[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