Hi Robert (and list),
See my response below,
On 27/05/14 23:05, dovecot-request(a)dovecot.org wrote:
> Message: 4 Date: Mon, 26 May 2014 19:50:01 -0700 From: Robert L
> Mathews <lists(a)tigertech.com> To: Dovecot Mailing List
> <dovecot(a)dovecot.org> Subject: Re: [Dovecot] Odd ownership of the
> dovecot-uidlist file Message-ID: <5383FD59.9050809(a)tigertech.com>
> Content-Type: text/plain; charset=UTF-8 On 5/26/14, 6:06 PM,
> dclist.hook(a)hook.net.nz 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
> 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