[Dovecot] Odd ownership of the dovecot-uidlist file

Bruce dclist.hook at hook.net.nz
Tue Jun 3 02:01:49 UTC 2014


Hi Robert (and list),

See my response below,

On 27/05/14 23:05, dovecot-request at dovecot.org wrote:
> Message: 4 Date: Mon, 26 May 2014 19:50:01 -0700 From: Robert L 
> Mathews <lists at tigertech.com> To: Dovecot Mailing List 
> <dovecot at dovecot.org> Subject: Re: [Dovecot] Odd ownership of the 
> dovecot-uidlist file Message-ID: <5383FD59.9050809 at tigertech.com> 
> Content-Type: text/plain; charset=UTF-8 On 5/26/14, 6:06 PM, 
> dclist.hook at 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 at 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 at XXXXX (/mnt/spool/keepers/h/XXXXX/hamish) userid = 7053 (7053) - 
uidlist = 7053
Jun 3 11:18:13 brio dovecot: Dovecot for hamish at XXXXX finished, uidlist 
now = 7053
Jun 3 11:28:13 brio dovecot: pop3(hamish at 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 at 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 at XXXXX (/mnt/spool/keepers/h/XXXXX/hamish) userid = 7053 (7053) - 
uidlist = 26624
Jun 3 11:38:51 brio dovecot: Dovecot for hamish at XXXXX finished, uidlist 
now = 26624
Jun 3 11:38:51 brio dovecot: pop3(hamish at XXXXX): Error: 
open(/mnt/spool/keepers/h/XXXXX/hamish/Maildir/dovecot-uidlist) failed: 
Permission denied
Jun 3 11:38:51 brio dovecot: pop3(hamish at XXXXX): Error: 
open(/mnt/spool/keepers/h/XXXXX/hamish/Maildir/dovecot-uidlist) failed: 
Permission denied
Jun 3 11:38:51 brio dovecot: pop3(hamish at 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 at 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 at 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 at 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 at 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 at xxx/test) userid = 1667 (1667) - uidlist = 1667
Jun 3 11:18:32 brio dovecot: pop3-login: Login: user=<test at 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 at xxx): Disconnected: Logged out 
bytes=9/360
Jun 3 11:18:32 brio dovecot: pop3(haidee.b at 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 at xxx finished, uidlist now 
= 1667
Jun 3 11:18:32 brio dovecot: Dovecot postlogin.sh running as 
test at xxx/test) userid = 1667 (1667) - uidlist = 1667
Jun 3 11:18:32 brio dovecot: Dovecot for test at xxx finished, uidlist now 
= 1667
Jun 3 11:18:32 brio dovecot: pop3(test at 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 at 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 at 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 at xxx/manager) userid = 12397 (12397) - uidlist = 12397
Jun 3 11:18:32 brio dovecot: Dovecot for manager at xxx finished, uidlist 
now = 12397
Jun 3 11:18:32 brio dovecot: imap(manager at xxx): Disconnected: Logged out 
bytes=91/873
Jun 3 11:18:32 brio dovecot: pop3-login: Login: user=<amanda at 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 at xxx/amanda) userid = 24293 (24293) - uidlist = 24293
Jun 3 11:18:32 brio dovecot: Dovecot for amanda at xxx finished, uidlist 
now = 24293
Jun 3 11:18:32 brio dovecot: pop3(anton at 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 at 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 at xxx/admin) userid = 25119 (25119) - uidlist = 25119
Jun 3 11:18:32 brio dovecot: Dovecot for admin at xxx finished, uidlist now 
= 25119
Jun 3 11:18:32 brio dovecot: pop3-login: Login: user=<info at 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 at 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 at xxx/info) userid = 13732 (13732) - uidlist = 13732
Jun 3 11:18:32 brio dovecot: Dovecot for info at xxx finished, uidlist now 
= 13732
Jun 3 11:18:32 brio dovecot: Dovecot postlogin.sh running as 
robb at xxx/robb) userid = 21760 (21760) - uidlist = 21760
Jun 3 11:18:32 brio dovecot: Dovecot for robb at xxx finished, uidlist now 
= 21760
Jun 3 11:18:33 brio dovecot: pop3(number5 at 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 at 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 at 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 at 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 at 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 at xxx/sbreed) userid = 21761 (21761) - uidlist = 21761
Jun 3 11:18:33 brio dovecot: Dovecot for sbreed at xxx finished, uidlist 
now = 21761
Jun 3 11:18:33 brio dovecot: pop3(robb at 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 at 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 at xxx/gary) userid = 26671 (26671) - uidlist = 26671
Jun 3 11:18:33 brio dovecot: Dovecot for gary at xxx finished, uidlist now 
= 26671
Jun 3 11:18:33 brio dovecot: imap(gary at xxx): Disconnected: Logged out 
bytes=394/10899
Jun 3 11:18:34 brio dovecot: imap-login: Login: user=<sales at 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 at xxx/sales) userid = 16696 (16696) - uidlist = 16696
Jun 3 11:18:34 brio dovecot: Dovecot for sales at xxx finished, uidlist now 
= 16696
Jun 3 11:18:34 brio dovecot: pop3-login: Login: user=<tmeha at 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 at xxx/tmeha) userid = 4338 (4338) - uidlist = 4338
Jun 3 11:18:34 brio dovecot: Dovecot for tmeha at xxx finished, uidlist now 
= 4338
Jun 3 11:18:34 brio dovecot: imap(sales at xxx): Disconnected: Logged out 
bytes=467/14224
Jun 3 11:18:34 brio dovecot: pop3-login: Login: user=<christine at 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 at 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 at xxx/christine) userid = 29127 (29127) - uidlist = 29127
Jun 3 11:18:34 brio dovecot: Dovecot for christine at xxx finished, uidlist 
now = 29127
Jun 3 11:18:34 brio dovecot: Dovecot postlogin.sh running as 
john at xxx/john) userid = 15027 (15027) - uidlist = 15027
Jun 3 11:18:34 brio dovecot: Dovecot for john at xxx finished, uidlist now 
= 15027
Jun 3 11:18:34 brio dovecot: pop3-login: Login: user=<res at 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 at xxx/res) userid = 35375 (35375) - uidlist = 35375
Jun 3 11:18:34 brio dovecot: Dovecot for res at xxx finished, uidlist now = 
35375
Jun 3 11:18:34 brio dovecot: pop3(res at 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 at 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 at 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 at xxx/test) userid = 1667 (1667) - uidlist = 1667
Jun 3 11:18:34 brio dovecot: Dovecot for test at xxx finished, uidlist now 
= 1667
Jun 3 11:18:34 brio dovecot: imap(test at xxx): Disconnected: Logged out 
bytes=9/360
Jun 3 11:18:34 brio dovecot: imap-login: Login: user=<priestley at 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



More information about the dovecot mailing list