dovecot - Apr 2015 - userdb username change ignored when using (My)SQL was: Re: userdb username changed

Hi!

It works when using LDAP.
I've duplicated the "username change" debug line, just to see that
the
variables are really updated:

Apr 20 14:30:27 imap21 dovecot: auth-worker(27127): Debug:
sql(ppp at example.net): username changed ppp at example.net -> uppp
Apr 20 14:30:27 imap21 dovecot: auth-worker(27127): Debug: sql(uppp):
username changed uppp -> uppp
Apr 20 14:30:27 imap21 dovecot: auth: Debug: userdb out:
USER#0111#011ppp at
example.net#011home=/home/ppp#011uid=500#011gid=500#011quota_rule=*:storage=3100b:messages=1024

And the answer is of course yes. Just the userdb out string has the wrong value.
The right value is lost somewhere. But where?

Regards,

Peter


Log of the (for me unusable) LDAP query:

Apr 20 14:28:07 imap21 dovecot: auth: Debug: master in:
USER#0111#011m2500j6#011service=doveadm
Apr 20 14:28:07 imap21 dovecot: auth: Debug: ldap(m2500j6): user
search: base=ou=Users,ou=Mail,dc=bnet,dc=at scope=subtree
filter=(uid=m2500j6) fields=mailHost
Apr 20 14:28:07 imap21 dovecot: auth: Debug: ldap(m2500j6): result:
mailHost=localhost; mailHost unused
Apr 20 14:28:07 imap21 dovecot: auth: Debug: ldap(m2500j6): username
changed m2500j6 -> localhost
Apr 20 14:28:07 imap21 dovecot: auth: Debug: ldap(localhost): username
changed localhost -> localhost
Apr 20 14:28:07 imap21 dovecot: auth: Debug: ldap(localhost): result:
mailHost=localhost
Apr 20 14:28:07 imap21 dovecot: auth: Debug: userdb out:
USER#0111#011localhost#011

On 20-04-15 15:09, P?ter M?rton wrote:
> Hi!
> 
> It works when using LDAP.
> I've duplicated the "username change" debug line, just to see
that the
> variables are really updated:
> 
> Apr 20 14:30:27 imap21 dovecot: auth-worker(27127): Debug:
> sql(ppp at example.net): username changed ppp at example.net -> uppp
> Apr 20 14:30:27 imap21 dovecot: auth-worker(27127): Debug: sql(uppp):
> username changed uppp -> uppp
> Apr 20 14:30:27 imap21 dovecot: auth: Debug: userdb out:
> USER#0111#011ppp at
example.net#011home=/home/ppp#011uid=500#011gid=500#011quota_rule=*:storage=3100b:messages=1024
> 
> And the answer is of course yes. Just the userdb out string has the wrong
value.
> The right value is lost somewhere. But where?
Your messages to this list seem to miss a feature that is very welcome
on this kind of mailing lists: an actual problem or an issue you want to
fix.

When users can login and the username change is intended (as can be
concluded from your comments), then what is the problem you're reporting?

Are you trying to reporting the fact that the auth debug output has the
wrong username value? If not, what is it you're to tell us? :)
> 
> Regards,
> 
> Peter
> 
> 
> Log of the (for me unusable) LDAP query:
> 
> Apr 20 14:28:07 imap21 dovecot: auth: Debug: master in:
> USER#0111#011m2500j6#011service=doveadm
> Apr 20 14:28:07 imap21 dovecot: auth: Debug: ldap(m2500j6): user
> search: base=ou=Users,ou=Mail,dc=bnet,dc=at scope=subtree
> filter=(uid=m2500j6) fields=mailHost
> Apr 20 14:28:07 imap21 dovecot: auth: Debug: ldap(m2500j6): result:
> mailHost=localhost; mailHost unused
> Apr 20 14:28:07 imap21 dovecot: auth: Debug: ldap(m2500j6): username
> changed m2500j6 -> localhost
> Apr 20 14:28:07 imap21 dovecot: auth: Debug: ldap(localhost): username
> changed localhost -> localhost
> Apr 20 14:28:07 imap21 dovecot: auth: Debug: ldap(localhost): result:
> mailHost=localhost
> Apr 20 14:28:07 imap21 dovecot: auth: Debug: userdb out:
> USER#0111#011localhost#011
>

>> And the answer is of course yes. Just the userdb out string has the
wrong value.
>> The right value is lost somewhere. But where?
>
> Your messages to this list seem to miss a feature that is very welcome
> on this kind of mailing lists: an actual problem or an issue you want to
> fix.
I'm sorry that i wasn't able to formulate my problem correctly. :) I
try to elaborate:
If you read the config in my original message, and read the logs (line
by line), then you will notice the following facts:
1. The username change is intended.
2. The log says, that the username change is happening as it should.
3. The log says, that the "userdb out" contains the original (not
changed) username.
4. With passdb it works correctly: "passdb out" contains the right
(changed) username.

Outcome 1.: Fact 3 means, that any service which calls for userdb
lookup will get a wrong username. Wrong means here that it's not the
username intended for userdb lookup callers.

Outcome 2.: For me, fact 4 says that it was the developers intention
to be able to change the username. Eg.: to give *db lookup callers a
changed username, not the original as entered by the user.

But outcome 1. and 2. contradicts each other. That gave me three
possible conclusions:
a. I made some mistake
b. my assumption(s) was/were wrong
c. Someone else made a mistake (it's a bug)

But i couldn't find out which is the correct, soooo i sent my original
message to the list.

And while i tried to confute "conclusion b." i tried the whole process
with LDAP. With success. LDAP userdb lookup returns the changed
username.
Here we are now. :)

Thank you, if you read it until here. My only excuse for not writing
all that in my original message is that i wanted to keep my problem
description clean and simple. In my 23 years of history on technical
electronic messaging boards, i've been told many many times that i
write irrelevant informations in my messages. (like this) :) And i
assumed i couldn't change... :)
>
> When users can login and the username change is intended (as can be
> concluded from your comments), then what is the problem you're
reporting?
>
> Are you trying to reporting the fact that the auth debug output has the
> wrong username value? If not, what is it you're to tell us? :)
I hope that the debug output is a trustful source of information. But
who knows? It would be my third assumption proved wrong - today.

And all my struggle just to be able to use quota-status service with
postfix. With unauthenticated senders, postfix only sends the
recipient address (beside many irrelevant data) to the policy service
(quota-status). So userdb has to use the email address to lookup up
the quota rule, and to give a username to quota-dict for lookup. My
usernames are sadly not email addresses, thats why i had to make query
which resolves addresses to usernames. The whole problem started here.


Regards,

Peter

Hi!

Can someone please tell me what is the difference between "auth" and
"auth-worker"? I mean the entries in the log.
For me it looks like "auth" would be a master process for authdb and
userdb lookups. But quota-status, and even lmtp are calling
auth-worker directly. Or?

Imap auth with mysql:
Apr 22 12:35:16 imap21 dovecot: auth-worker(21529): Debug:
sql(ppp at example.net,195.202.128.25): username changed ppp at example.net
-> uppp
Apr 22 12:35:16 imap21 dovecot: auth: Debug:
sql(ppp at example.net,195.202.128.25,<jp8LuE0UXADDyoAZ>): username
changed ppp at example.net -> uppp
Both processes(?) loop through the returned variables (with request.c
auth_request_set_userdb_field) , but only "auth" sets the
"username"
successfully.

Imap auth with ldap:
Apr 22 13:17:55 imap21 dovecot: auth: Debug:
ldap(m2500j6,127.0.0.1,<WYiTUE4UngB/AAAB>): username changed m2500j6
-> uppp
Apr 22 13:17:55 imap21 dovecot: auth: Debug:
ldap(uppp,127.0.0.1,<WYiTUE4UngB/AAAB>): result: gidNumber=168
homeDirectory=/tmp mailHost=uppp
Only "auth", and username is successfully changed.

quota-status with mysql:
Apr 22 12:35:59 imap21 dovecot: auth-worker(21529): Debug:
sql(ppp at kabsi.at): username changed ppp at kabsi.at -> uppp
Apr 22 12:35:59 imap21 dovecot: auth: Debug: userdb out:
USER#0111#011ppp at
kabsi.at#011home=/home/ppp#011uid=500#011gid=500#011quota_rule=*:storage=3100b:messages=1024#011login_user=uppp
Apr 22 12:35:59 imap21 dovecot: quota-status(ppp at kabsi.at): Debug:
auth input: ppp at kabsi.at home=/home/ppp uid=500 gid=500
quota_rule=*:storage=3100b:messages=1024 login_user=uppp
Only auth-worker is looping through the returned fields (single
"username changed" entry), and the username isn't changed.

quota-status with ldap:
Apr 22 13:25:14 imap21 dovecot: auth: Debug: ldap(m2500j6): user
search: base=ou=Users,ou=Mail,dc=bnet,dc=at scope=subtree
filter=(uid=m2500j6) fields=mailHost,gidNumber,homeDirectory
Apr 22 13:25:14 imap21 dovecot: auth: Debug: ldap(m2500j6): result:
gidNumber=168 homeDirectory=/tmp mailHost=uppp;
homeDirectory,mailHost,gidNumber unused
Apr 22 13:25:14 imap21 dovecot: auth: Debug: ldap(m2500j6): username
changed m2500j6 -> uppp
Apr 22 13:25:14 imap21 dovecot: auth: Debug: ldap(localhost): result:
gidNumber=168 homeDirectory=/tmp mailHost=uppp
Apr 22 13:25:14 imap21 dovecot: auth: Debug: userdb out:
USER#0111#011localhost#011gid=168#011home=/tmp
Apr 22 13:25:14 imap21 dovecot: quota-status(m2500j6): Debug: auth
input: uppp gid=168 home=/tmp
Apr 22 13:25:14 imap21 dovecot: quota-status(m2500j6): Debug: changed
username to uppp

Again! Only "auth", but username is changed. Even quota-status logs
the username change.


Thanks!

Peter

On Mon, Dec 7, 2015 at 8:13 PM, Timo Sirainen <tss at iki.fi> wrote:
> http://dovecot.org/releases/2.2/dovecot-2.2.20.tar.gz
> http://dovecot.org/releases/2.2/dovecot-2.2.20.tar.gz.sig
>
> This could be (one of) the last v2.2.x release. We're starting v2.3
> development soon.
> (...)
- auth: userdb lookups via auth-worker couldn't change
username
> (...)

Thanks for that Timo! I will test it.

Regards,

Peter