Hi Robert (and list),
See my response below,
On 27/05/14 23:05, dovecot-request@dovecot.org wrote:
It would be great if someone can give us some hints where the problem maybe as this has us stumped. Have you tried "stat dovecot-uidlist" after it's changed to look at all
Message: 4 Date: Mon, 26 May 2014 19:50:01 -0700 From: Robert L Mathews <lists@tigertech.com> To: Dovecot Mailing List <dovecot@dovecot.org> Subject: Re: [Dovecot] Odd ownership of the dovecot-uidlist file Message-ID: <5383FD59.9050809@tigertech.com> Content-Type: text/plain; charset=UTF-8 On 5/26/14, 6:06 PM, dclist.hook@hook.net.nz wrote: three times of the file?
The "Change" time is probably more interesting than the modification time. It should show the time that the ownership was altered or the file recreated, and maybe you can look at the logs to see what happened then.
Thanks for the suggestion, we have had another occurrence of the wrong ownership on the dovecot-uid today. And we took a stat of the file but the logs around the time dont give any indication of the incorrect user logging in, a dovecot error or anything helpful.
This is the log entry for the user as the issue started occurring: Jun 3 11:18:13 brio dovecot: pop3-login: Login: user=<hamish@XXXXX>, method=APOP, rip=x.x.x.x, lip=x.x.x.x, mpid=31874, TLS, session=<Cfr6m+L6bgB2lKNI> Jun 3 11:18:13 brio dovecot: Dovecot postlogin.sh running as hamish@XXXXX (/mnt/spool/keepers/h/XXXXX/hamish) userid = 7053 (7053) - uidlist = 7053 Jun 3 11:18:13 brio dovecot: Dovecot for hamish@XXXXX finished, uidlist now = 7053 Jun 3 11:28:13 brio dovecot: pop3(hamish@XXXXX): Disconnected for inactivity top=0 (0 b), retr=0 (0 b), messages=380 (41770867 b), del=0 Jun 3 11:38:51 brio dovecot: pop3-login: Login: user=<hamish@XXXXX>, method=APOP, rip=x.x.x.x, lip=x.x.x.x, mpid=16538, TLS, session=<EyrJ5eL6eAB2lKNI> 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 Jun 3 11:38:51 brio dovecot: pop3(hamish@XXXXX): Error: open(/mnt/spool/keepers/h/XXXXX/hamish/Maildir/dovecot-uidlist) failed: Permission denied Jun 3 11:38:51 brio dovecot: pop3(hamish@XXXXX): Error: open(/mnt/spool/keepers/h/XXXXX/hamish/Maildir/dovecot-uidlist) failed: Permission denied Jun 3 11:38:51 brio dovecot: pop3(hamish@XXXXX): Error: Couldn't init INBOX: Internal error occurred. Refer to server log for more information. [2014-06-03 11:38:51] Jun 3 11:38:51 brio dovecot: pop3(hamish@XXXXX): Mailbox init failed top=0 (0 b), retr=0 (0 b), messages=0 (0 b), del=0
You will notice our postlogin script spits out some information about
the uidlist file both before it starts and after it finishes which shows
uid it as running as and the owner of the uidlist file. For reference
this is the current script (we have pulled a lot of the extra stuff we
were doing out for testing):
-- 8<--
#!/bin/bash
# WARNING: Be sure to use mail_drop_priv_before_exec=yes, otherwise the
files are created as root!
logger -t dovecot -p mail.info "Dovecot postlogin.sh running as $USER
($HOME) userid = $EUID ($UID) - uidlist = stat $HOME/Maildir/dovecot-uidlist -c %u"
# Removed the exec so we can run something after the login. Once the uid list issue is fixed this should be set back #exec "$1" "$1"
logger -t dovecot -p mail.info "Dovecot for $USER finished, uidlist now
= stat $HOME/Maildir/dovecot-uidlist -c %u"
-- 8<--
root@brio:/mnt/spool/keepers/h/XXXXXXX/hamish/Maildir# stat dovecot-uidlist File: `dovecot-uidlist' Size: 26819 Blocks: 56 IO Block: 1048576 regular file Device: 1ah/26d Inode: 9424182 Links: 3 Access: (0600/-rw-------) Uid: (26624/info-14552) Gid: (11307/domain14552) Access: 2014-06-03 11:18:05.000000000 +1200 Modify: 2014-06-03 01:55:19.000000000 +1200 Change: 2014-06-03 11:18:33.000000000 +1200 Birth: -
The stat says the change happened at 11:18:33, so we looked at the logs around that time: Jun 3 11:18:32 brio dovecot: imap-login: Login: user=<test@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=647, session=<Y6oZneL6vwDSMGzL> Jun 3 11:18:32 brio dovecot: pop3(enquiry@xxx): Disconnected: Logged out top=0 (0 b), retr=0 (0 b), messages=64 (7363643 b), del=0 Jun 3 11:18:32 brio dovecot: Dovecot postlogin.sh running as test@xxx/test) userid = 1667 (1667) - uidlist = 1667 Jun 3 11:18:32 brio dovecot: pop3-login: Login: user=<test@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=652, session=<GDsaneL6nwDSMGzL> Jun 3 11:18:32 brio dovecot: imap(test@xxx): Disconnected: Logged out bytes=9/360 Jun 3 11:18:32 brio dovecot: pop3(haidee.b@xxx): Disconnected: Logged out top=0 (0 b), retr=0 (0 b), messages=81 (17665182 b), del=0 Jun 3 11:18:32 brio dovecot: Dovecot for test@xxx finished, uidlist now = 1667 Jun 3 11:18:32 brio dovecot: Dovecot postlogin.sh running as test@xxx/test) userid = 1667 (1667) - uidlist = 1667 Jun 3 11:18:32 brio dovecot: Dovecot for test@xxx finished, uidlist now = 1667 Jun 3 11:18:32 brio dovecot: pop3(test@xxx): Disconnected: Logged out top=0 (0 b), retr=0 (0 b), messages=1 (1756 b), del=0 Jun 3 11:18:32 brio dovecot: pop3(nz@xxx): Disconnected: Logged out top=0 (0 b), retr=0 (0 b), messages=0 (0 b), del=0 Jun 3 11:18:32 brio dovecot: imap-login: Login: user=<manager@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=667, session=<hCUeneL6sADAqMjK> Jun 3 11:18:32 brio dovecot: Dovecot postlogin.sh running as manager@xxx/manager) userid = 12397 (12397) - uidlist = 12397 Jun 3 11:18:32 brio dovecot: Dovecot for manager@xxx finished, uidlist now = 12397 Jun 3 11:18:32 brio dovecot: imap(manager@xxx): Disconnected: Logged out bytes=91/873 Jun 3 11:18:32 brio dovecot: pop3-login: Login: user=<amanda@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=675, session=<NeMeneL6rgDLraCP> Jun 3 11:18:32 brio dovecot: Dovecot postlogin.sh running as amanda@xxx/amanda) userid = 24293 (24293) - uidlist = 24293 Jun 3 11:18:32 brio dovecot: Dovecot for amanda@xxx finished, uidlist now = 24293 Jun 3 11:18:32 brio dovecot: pop3(anton@xxx): Disconnected: Logged out top=0 (0 b), retr=0 (0 b), messages=603 (57517089 b), del=0 Jun 3 11:18:32 brio dovecot: pop3-login: Login: user=<admin@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=685, TLS, session=<hiAjneL6vgDemmai> Jun 3 11:18:32 brio dovecot: Dovecot postlogin.sh running as admin@xxx/admin) userid = 25119 (25119) - uidlist = 25119 Jun 3 11:18:32 brio dovecot: Dovecot for admin@xxx finished, uidlist now = 25119 Jun 3 11:18:32 brio dovecot: pop3-login: Login: user=<info@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=691, session=<ZJQkneL6SgB97OUI> Jun 3 11:18:32 brio dovecot: pop3-login: Login: user=<robb@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=695, session=<7MskneL6TAB97O9T> Jun 3 11:18:32 brio dovecot: Dovecot postlogin.sh running as info@xxx/info) userid = 13732 (13732) - uidlist = 13732 Jun 3 11:18:32 brio dovecot: Dovecot for info@xxx finished, uidlist now = 13732 Jun 3 11:18:32 brio dovecot: Dovecot postlogin.sh running as robb@xxx/robb) userid = 21760 (21760) - uidlist = 21760 Jun 3 11:18:32 brio dovecot: Dovecot for robb@xxx finished, uidlist now = 21760 Jun 3 11:18:33 brio dovecot: pop3(number5@xxx): Disconnected: Logged out top=0 (0 b), retr=0 (0 b), messages=19 (422734 b), del=0 Jun 3 11:18:33 brio dovecot: pop3(admin@xxx): Disconnected: Logged out top=0 (0 b), retr=0 (0 b), messages=256 (8614214 b), del=0 Jun 3 11:18:33 brio dovecot: pop3(info@xxx): Disconnected: Logged out top=0 (0 b), retr=0 (0 b), messages=227 (56540919 b), del=0 Jun 3 11:18:33 brio dovecot: pop3(amanda@xxx): Disconnected: Logged out top=0 (0 b), retr=1 (20185 b), messages=69 (5243134 b), del=0 Jun 3 11:18:33 brio dovecot: pop3-login: Login: user=<sbreed@xxx>, method=APOP, rip=x.x.x.x, lip=x.x.x.x, mpid=712, session=<brAtneL6LgBuiOW3> Jun 3 11:18:33 brio dovecot: Dovecot postlogin.sh running as sbreed@xxx/sbreed) userid = 21761 (21761) - uidlist = 21761 Jun 3 11:18:33 brio dovecot: Dovecot for sbreed@xxx finished, uidlist now = 21761 Jun 3 11:18:33 brio dovecot: pop3(robb@xxx): Disconnected: Logged out top=0 (0 b), retr=0 (0 b), messages=0 (0 b), del=0 Jun 3 11:18:33 brio dovecot: imap-login: Login: user=<gary@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=721, session=<z0MvneL6swDAqMjK> Jun 3 11:18:33 brio dovecot: Dovecot postlogin.sh running as gary@xxx/gary) userid = 26671 (26671) - uidlist = 26671 Jun 3 11:18:33 brio dovecot: Dovecot for gary@xxx finished, uidlist now = 26671 Jun 3 11:18:33 brio dovecot: imap(gary@xxx): Disconnected: Logged out bytes=394/10899 Jun 3 11:18:34 brio dovecot: imap-login: Login: user=<sales@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=733, session=<0kc2neL6tgDAqMjK> Jun 3 11:18:34 brio dovecot: Dovecot postlogin.sh running as sales@xxx/sales) userid = 16696 (16696) - uidlist = 16696 Jun 3 11:18:34 brio dovecot: Dovecot for sales@xxx finished, uidlist now = 16696 Jun 3 11:18:34 brio dovecot: pop3-login: Login: user=<tmeha@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=741, session=<OKg4neL69gB97O9T> Jun 3 11:18:34 brio dovecot: Dovecot postlogin.sh running as tmeha@xxx/tmeha) userid = 4338 (4338) - uidlist = 4338 Jun 3 11:18:34 brio dovecot: Dovecot for tmeha@xxx finished, uidlist now = 4338 Jun 3 11:18:34 brio dovecot: imap(sales@xxx): Disconnected: Logged out bytes=467/14224 Jun 3 11:18:34 brio dovecot: pop3-login: Login: user=<christine@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=753, session=<yrM9neL6xgDbWELK> Jun 3 11:18:34 brio dovecot: pop3-login: Login: user=<john@xxx>, method=APOP, rip=x.x.x.x, lip=x.x.x.x, mpid=754, session=<w7I9neL6JAB5SN1a> Jun 3 11:18:34 brio dovecot: Dovecot postlogin.sh running as christine@xxx/christine) userid = 29127 (29127) - uidlist = 29127 Jun 3 11:18:34 brio dovecot: Dovecot for christine@xxx finished, uidlist now = 29127 Jun 3 11:18:34 brio dovecot: Dovecot postlogin.sh running as john@xxx/john) userid = 15027 (15027) - uidlist = 15027 Jun 3 11:18:34 brio dovecot: Dovecot for john@xxx finished, uidlist now = 15027 Jun 3 11:18:34 brio dovecot: pop3-login: Login: user=<res@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=769, TLS, session=<0oM/neL6YwB97a8j> Jun 3 11:18:34 brio dovecot: Dovecot postlogin.sh running as res@xxx/res) userid = 35375 (35375) - uidlist = 35375 Jun 3 11:18:34 brio dovecot: Dovecot for res@xxx finished, uidlist now = 35375 Jun 3 11:18:34 brio dovecot: pop3(res@xxx): Disconnected: Logged out top=0 (0 b), retr=0 (0 b), messages=0 (0 b), del=0 Jun 3 11:18:34 brio dovecot: pop3(tmeha@xxx): Disconnected: Logged out top=0 (0 b), retr=0 (0 b), messages=0 (0 b), del=0 Jun 3 11:18:34 brio dovecot: imap-login: Login: user=<test@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=781, session=<bRREneL6PgDSMGx8> Jun 3 11:18:34 brio dovecot: Dovecot postlogin.sh running as test@xxx/test) userid = 1667 (1667) - uidlist = 1667 Jun 3 11:18:34 brio dovecot: Dovecot for test@xxx finished, uidlist now = 1667 Jun 3 11:18:34 brio dovecot: imap(test@xxx): Disconnected: Logged out bytes=9/360 Jun 3 11:18:34 brio dovecot: imap-login: Login: user=<priestley@xxx>, method=PLAIN, rip=x.x.x.x, lip=x.x.x.x, mpid=792, session=<aX1FneL6OADAqMjL>
There is nothing there which indicates anything happened at 11:18:33 which would have gone anywhere near the uidlist file or even from the user that the file changed to (remembering that the directory permission would prevent them writing to the file anyway)
The stat also says the change happened at 11:18:33, and there is nothing in 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)
Any further suggestions?
Cheers, James