Re: [Dovecot] Odd ownership of the dovecot-uidlist file
Hi,
Please see my responses below,
On 04/06/14 01:35, dovecot-request@dovecot.org wrote:
Message: 4 Date: Tue, 3 Jun 2014 09:33:48 +0200 (CEST) From: Steffen Kaiser
Jun 3 11:38:51 brio dovecot: Dovecot postlogin.sh running as hamish@XXXXX (/mnt/spool/keepers/h/XXXXX/hamish) userid = 7053 (7053) - uidlist = 26624 Jun 3 11:38:51 brio dovecot: Dovecot for hamish@XXXXX finished, uidlist now = 26624 who is user 26624? Is the uid valid at all? If it is invalid, are there other files owned by this uid? Maybe only one of your NFS server has this uid in its /etc/passwd? Is user "hamish" shared to another user somehow, either via symlinks, ACLs, ...? UID 26624 is a valid user ('info' of domain14552) but under a compleltly different domain name (hamish is under domain25367). However that user has also not logged in around the time the ownership was changed. There is no relevance to the two users, except that they exist on the system and for some reason this issue happened to the hamish user.
The NFS server does not know about the UIDs, it just provides the numeric IDs which is translated on the dovecot/exim servers by NSS and Dovecotr using the replicated MySQL database. Additionally both users have existed for some time and the databases are in sync. Customers also do not have any access to the file system so there will be no symlinks in place.
Its also not a single server that we are seeing the issue on, it maybe one Dovecot server accessing one NFS server. Then the next time its a different Dovecot server accessing a different NFS server.
the logs for that time which is abnormal (a whole bunch of other logins from other customers but nothing from those two users and no errors) What about cron jobs, message delivery, backups, ... anything that possibly can alter that file. I don't think, it's a Dovecot issue, unless the uid 26624 is valid and hamish is shared with that user. Nothing besides Courier being replaced by Dovecot has changed in the server setup (although I could be wrong there, but we are going through one component at a time and until this issue is resolved we are not moving onto the next), and the only file which is being modified is a file which only Dovecot maintains.
There are hourly backups which do an rsync to another server in case of hardware failure, there are scripts which move mailboxes between NFS servers but they show up in logs. Exim has no need to touch a dovecot controlled file, and when it writes mail into the maildir its writing as the correct user.
It also seem odd that one login is fine then randomly the next login the file ownership has changed, nothing happens in between the two logins which are in some cases only 5 to 10 minutes apart.
All I am really looking for is ideas on where to look, as it seems odd that nobody else is reporting this, and since its a reasonably new setup its possibly something we have done in the config (which I posted in my first email). Is there a reliable way to run a script directly when a dovecot session starts and finishes so we could output the ownership before and after which may also help eliminate the session itself.
Cheers, Bruce
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Wed, 4 Jun 2014, Bruce wrote:
Please see my responses below,
I dislike top posting anyway :-)
On 04/06/14 01:35, dovecot-request@dovecot.org wrote:
Message: 4 Date: Tue, 3 Jun 2014 09:33:48 +0200 (CEST) From: Steffen Kaiser
Jun 3 11:38:51 brio dovecot: Dovecot postlogin.sh running as hamish@XXXXX (/mnt/spool/keepers/h/XXXXX/hamish) userid = 7053 (7053) - uidlist = 26624 Jun 3 11:38:51 brio dovecot: Dovecot for hamish@XXXXX finished, uidlist now = 26624 who is user 26624? Is the uid valid at all? If it is invalid, are there other files owned by this uid? Maybe only one of your NFS server has this uid in its /etc/passwd? Is user "hamish" shared to another user somehow, either via symlinks, ACLs, ...? UID 26624 is a valid user ('info' of domain14552) but under a compleltly different domain name (hamish is under domain25367). However that user has also not logged in around the time the ownership was changed. There is no relevance to the two users, except that they exist on the system and for some reason this issue happened to the hamish user.
That means: no sharing, right ?
The NFS server does not know about the UIDs, it just provides the numeric IDs which is translated on the dovecot/exim servers by NSS and Dovecotr using the replicated MySQL database. Additionally both users have existed for some time and the databases are in sync. Customers also do not have any access to the file system so there will be no symlinks in place.
Its also not a single server that we are seeing the issue on, it maybe one Dovecot server accessing one NFS server. Then the next time its a different Dovecot server accessing a different NFS server.
Because it's NFS, any server accessing this NFS export may alter the ownership, because I still do not believe it's a Dovecot IMAP/POP issue ;-)
the logs for that time which is abnormal (a whole bunch of other logins from other customers but nothing from those two users and no errors) What about cron jobs, message delivery, backups, ... anything that possibly can alter that file. I don't think, it's a Dovecot issue, unless the uid 26624 is valid and hamish is shared with that user. Nothing besides Courier being replaced by Dovecot has changed in the server setup (although I could be wrong there, but we are going through one component at a time and until this issue is resolved we are not moving onto the next), and the only file which is being modified is a file which only Dovecot maintains.
Could there be Courier-related left-over scripts running?
There are hourly backups which do an rsync to another server in case of hardware failure, there are scripts which move mailboxes between NFS servers but they show up in logs. Exim has no need to touch a dovecot controlled file, and when it writes mail into the maildir its writing as the correct user.
How does exim deliver the messages to the user storage? Via Dovecot-Deliver or directly. I interprete your sentence, that the messages are dropped directly. 00
It also seem odd that one login is fine then randomly the next login the file ownership has changed, nothing happens in between the two logins which are in some cases only 5 to 10 minutes apart.
All I am really looking for is ideas on where to look, as it seems odd that nobody else is reporting this, and since its a reasonably new setup its
That's why I point to non-Dovecot things.
possibly something we have done in the config (which I posted in my first email). Is there a reliable way to run a script directly when a dovecot session starts and finishes so we could output the ownership before and after which may also help eliminate the session itself.
Your post-login script does exactly that. That leaves the message delivery, if you do so via Dovecot deliver. LMTP seems to be off.
I'm not sure if inotify works via NFS as Peter suggested, but that would my next idea as well. Let inotify wait for changes on that file, then fire up a script to capture "ps gaux" and maybe more.
If you have SELinux running, maybe you can trigger a warning there? I don't know much about SELinux.
Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux)
iQEVAwUBU47CQ3z1H7kL/d9rAQI3CAgAiXImeQ8nJcLkgEY+2Y8eOIWoNEOmPhMY yFaAYHoFnoQx8XJnlL9A0OY/L2INGdBN2ia1lUu8CkLbpfgCHY+MHuargFp6oUiP oCVhKbl4fjwk7T1Sm7tYDenW2zuBcF2kWSy3seROJYn5SUnKem4W4TRDnM/qheTg TR9pygp+1u3k6gq54Zni8JMY/m/9+8FtAHwWhkrY6LFXcdPT56q1+h2HNW2T/VVp g2GG7jKMKDl+VDxidDV/8obKQWWpgW4qO+aUwx+vxfud5GbXf0gL+PHtnf12XPHK /B/099fa8HiIpEWwqt3I5RTE1LrAsxJSwnWYfnEkqeTQrc9U7PVK7A== =NotM -----END PGP SIGNATURE-----
Hi Steffen,
See my responses below,
On 04/06/14 18:52, Steffen Kaiser wrote:
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
On Wed, 4 Jun 2014, Bruce wrote:
Please see my responses below, I dislike top posting anyway :-)
Yeah, its habit as I deal with people who top post and reply with 'Your email had nothing in it' if I don't say there is more below.
Jun 3 11:38:51 brio dovecot: Dovecot postlogin.sh running as hamish@XXXXX
(/mnt/spool/keepers/h/XXXXX/hamish) userid = 7053 (7053) - uidlist = 26624 Jun 3 11:38:51 brio dovecot: Dovecot for hamish@XXXXX finished, uidlist now = 26624 who is user 26624? Is the uid valid at all? If it is invalid, are there other files owned by this uid? Maybe only one of your NFS server has this uid in its /etc/passwd? Is user "hamish" shared to another user somehow, either via symlinks, ACLs, ...? UID 26624 is a valid user ('info' of domain14552) but under a compleltly different domain name (hamish is under domain25367). However that user has also not logged in around the time the ownership was changed. There is no relevance to the two users, except that they exist on the system and for some reason this issue happened to the hamish user. That means: no sharing, right ?
Correct.
The NFS server does not know about the UIDs, it just provides the numeric IDs which is translated on the dovecot/exim servers by NSS and Dovecotr using the replicated MySQL database. Additionally both users have existed for some time and the databases are in sync. Customers also do not have any access to the file system so there will be no symlinks in place.
Its also not a single server that we are seeing the issue on, it maybe one Dovecot server accessing one NFS server. Then the next time its a different Dovecot server accessing a different NFS server. Because it's NFS, any server accessing this NFS export may alter the ownership, because I still do not believe it's a Dovecot IMAP/POP issue ;-)
But we would see this with any application and file that is on NFS, in this case it is only ever one particular file, and only happened after changing to Dovecot (Previous to that we have had this NFS set up in place for 7 years).
Nothing besides Courier being replaced by Dovecot has changed in the server setup (although I could be wrong there, but we are going through one component at a time and until this issue is resolved we are not moving onto the next), and the only file which is being modified is a file which only Dovecot maintains. Could there be Courier-related left-over scripts running?
Its highly unlikely, and why would a courier script want to modify the ownership of a Dovecot file.
There are hourly backups which do an rsync to another server in case of hardware failure, there are scripts which move mailboxes between NFS servers but they show up in logs. Exim has no need to touch a dovecot controlled file, and when it writes mail into the maildir its writing as the correct user. How does exim deliver the messages to the user storage? Via Dovecot-Deliver or directly. I interprete your sentence, that the messages are dropped directly. 00
Exim does it directly, once again no need for it to touch a file which Dovecot creates and maintains.
possibly something we have done in the config (which I posted in my first email). Is there a reliable way to run a script directly when a dovecot session starts and finishes so we could output the ownership before and after which may also help eliminate the session itself. Your post-login script does exactly that. That leaves the message delivery, if you do so via Dovecot deliver. LMTP seems to be off.
I thought that's what should happen but looking at timestamps of the logins after the change, the permission denied always comes after the postlogin script completes, which means something happens after then.
Jun 3 12:56:31 gettas dovecot: pop3(celia@xxx): Mailbox init failed top=0 (0 b), retr=0 (0 b), messages=0 (0 b), del=0 Jun 3 12:56:32 gettas dovecot: pop3-login: Login: user=<celia@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=19655, TLS, session=<r2qX++P6gAB6PWyl> Jun 3 12:56:32 gettas dovecot: Dovecot postlogin.sh running as celia@xxx/celia) userid = 41410 (41410) - uidlist = 7903 Jun 3 12:56:32 gettas dovecot: Dovecot for celia@xxx finished, uidlist now = 7903 <---- POSTLOGIN.SH ENDS HERE Jun 3 12:56:32 gettas dovecot: pop3(celia@xxx/celia/Maildir/dovecot-uidlist) failed: Permission denied Jun 3 12:56:32 gettas dovecot: pop3(celia@xxx/celia/Maildir/dovecot-uidlist) failed: Permission denied Jun 3 12:56:32 gettas dovecot: pop3(celia@xxx): Error: Couldn't init INBOX: Internal error occurred. Refer to server log for more information. [2014-06-03 12:56:32] Jun 3 12:56:32 gettas dovecot: pop3(celia@xxx): Mailbox init failed top=0 (0 b), retr=0 (0 b), messages=0 (0 b), del=0
I could put this down to same microsecond and syslog recording in a different order, but its consistently in this order.
I'm not sure if inotify works via NFS as Peter suggested, but that would my next idea as well. Let inotify wait for changes on that file, then fire up a script to capture "ps gaux" and maybe more.
If you have SELinux running, maybe you can trigger a warning there? I don't know much about SELinux.
We don't have SELinux running, and unfortunately we are talking over 400,000 mailboxes (200,000 domains) which this could happen randomly too and adding inotify requires a file handle to be opened per file, which would make the servers unstable.
I have found a piece of code in the Dovecot source which I'm wondering about, so I am going to compile up a custom version and see if it continues to happen. Of course with it happening randomly being able to confirm its still happening is going to take time. So if anyone has any other ideas where to look I would be appreciative.
Cheers, Bruce
participants (3)
-
Bruce
-
Peter Chiochetti
-
Steffen Kaiser