Our new/fresh dovecot imap installation on CentOS (latest from yum repository,
which is 2.2.10) is locking up with a panic on a consistent basis and denying
service to subsequent clients. The behavior is repeatable. Have spent weeks
debugging and trying different configurations with no success.
Specific /var/log/maillog error messages are:
12:06:54 dovecot: auth: Error: talloc: access after free error - first free may
be at ../auth/ntlmssp/ntlmssp_server.c:457
12:06:54 dovecot: auth: Error: Bad talloc magic value - access after free
12:06:54 dovecot: auth: Error: PANIC (pid 2570): Bad talloc magic value - access
after free
Our configuration is based on the instructions for NTLM authentication with our
Windows 2012R2 AD/Domain server:
http://wiki2.dovecot.org/HowTo/ActiveDirectoryNtlm
<http://wiki2.dovecot.org/HowTo/ActiveDirectoryNtlm>
Here are the steps to reproduce:
1. Fresh boot of CentOS server, only configured for postfix/dovecot
2. Connect with Outlook 2016 12.0.4312.1000 32bit on Win7 via IMAP to this
dovecot server
3. Any existing and new mail loads in OK to inbox - so authentication is working
OK to AD domain server
4. Send an email to someone from Outlook
5. SMTP process completes, message is delivered -
6. dovecot immediately panics on servers, Authentication to dovecot no longer
works
7. <systemctl restart dovecot> will hang until a <kill -9> on the
?dovecot/auth? PID is performed
The issue is with steps 6/7 immediately after 4/5- and is intermittent.
Steps 1-3 always work OK, as do 4-5.
Further, inbound emails received on this server when no IMAP client is running
are always received just fine and dovecot doesn?t hang.
Sometimes I have to send a few email messages with steps 4/5 before the issue
with 6/7 happens.
If I tail -f /var/log/maillog on the server, I can usually determine when 6/7
will fail because there is a line or two with:
"dovecot: map: Disconnected: logged out message?
being shown, even though the Outlook client is still open.
After I see that Outlook closed an IMAP session, even though outlook is still
running, I can send a message from Outlook and after it appears in my inbox,
dovecot panics/hangs immediately
Authentication is otherwise working, e.g. test with:
/usr/bin/ntlm_auth ?username=alice
occasionally takes several seconds to respond, but is usually immediate
response is always NT_STATUS_OK: Success (0x0)
(I welcome tips to make ntlm_auth always respond more quickly!)
I have tried adding lines to smb.conf like:
win bind cache time = 300
win bind offline login = true
No success
I have also looked further into the detailed debugging logs and there is:
dovecot: auth: Error: Go user=[alice] domain=[OFFICE] workstation=[pc1] len1=24
len2=290
dovecot: auth: error: login for user [OFFICE]\[alice]@[pc1] failed due to [Wrong
Password]
dovecot: auth: Error: GENSEC login failed: NT_STATUS_LOGON_FAILURE
dovecot: auth: winbind(?,x.x.x.x,<XXX>): user not authetnicated:
NT_STATUS_LOGON_FAILURE
But I am not sure why there would be that error, since earlier IMAP sessions are
working just fine with the same exact domain/username and password.
It seems to be something about Outlook quickly opening up new simultaneous IMAP
sessions with a CONT command, and NTLM authentication somehow fails with one of
them, and panics. It always seems to be when sending an email. Like the
process of either receiving a new msg in the inbox and/or also posting the just
sent message into the Sent Items folder via IMAP (perhaps when it happens
simultaneously, as in a message you cc yourself on) is somehow triggering this.
Here is more detailed information that can hopefully help track this down.
Thank you!
dovecot -n
# 2.2.10: /etc/dovecot/dovecot.conf
CentOS 7.2.1511
auth_mechanisms = ntlm
auth_use_winbind = yes
auth_username_format = %n
mbox_write_locks = fcntl
passdb {
drive = pam
}
protocols = imap
service auth {
user = root
}
userdb {
driver = passwd
}
/etc/samba/smb.conf
workgroup = OFFICE
realm = OFFICE.LOCAL
security = ADS
local master = no
preferred master = no
dns proxy = no
idmap uid = 10000-20000
idmap gid = 10000-20000
password server = win2012r2
encrypt passwords = no
kerberos method = system keytab
winbind use_default_domain = yes
winbind offline login = true
winbind separator = +
ERROR MESSAGE
12:00:10 dovecot: imap(alice): Disconnected: logged out in=398 out=4368
12:05:52 postfix/smtpd: connect from pc1
12:05:52 postfix/smtpd: client=pc1
12:05:52 postfix/cleanu: message-id=<XXX>
12:05:52 postfix/qmgr: from=alice, size=5925, nrcpt=1 (queue active)
12:05:53 postfix/smtp: to=bob, relay=mailserver, delay=0.93, dsn=2.0.0,
status=send (250 ok: Message accepted)
12:06:53 postfix/qmgr: removed
12:06:54 dovecot: auth: Debug: Loading modules from directory:
/usr/lib64/dovecot/auth
12:06:54 dovecot: auth: Debug: Module loaded:
/usr/lib64/dovecot/auth/libdriver_sqlite.so
12:06:54 dovecot: auth: Debug: Read auth token secret from
/var/run/dovecot/auth-token-secret.dat
12:06:54 dovecot: auth: Debug: auth client connected (pid=2565)
12:06:54 dovecot: auth: Debug: auth client connected (pid=2568)
12:06:54 dovecot: auth: Debug: auth client connected (pid=2569)
12:06:54 dovecot: auth: Debug: client in:
AUTH#0111#011NTLM#011service=imap#011session=XXXip=X.X.X.X#011rip=X.X.X.X#011lport=143#011rport=61072
12:06:54 dovecot: auth: Debug: client in:
AUTH#0111#011NTLM#011service=imap#011session=XXXip=X.X.X.X#011rip=X.X.X.X#011lport=143#011rport_61061
12:06:54 dovecot: auth: Debug: client in:
AUTH#0111#011NTLM#011service=imap#011sessoin=XXXip=x.x.x.x#011lip=X.X.X.X#011lport=143#011rport=61073
12:06:54 dovecot: auth: Debug: client passdb out: CONT#0111
12:06:54 dovecot: auth: Debug: client passdb out: CONT#0111
12:06:54 dovecot: auth: Debug: client passdb out: CONT#0111
12:06:54 dovecot: auth: Debug: client in: CONT<hidden>
12:06:54 dovecot: auth: Debug: client passdb out: CONT#0111#011XXX
12:06:54 dovecot: auth: Debug: client in: CONT<hidden>
12:06:54 dovecot: auth: Debug: client passdb out; CONT#0111#011XXX
12:06:54 dovecot: auth: Debug: client passdb out: CONT#0111#011XXX
12:06:54 dovecot: auth: Debug: client in CONT<hidden>
12:06:54 dovecot: auth: winbind(?X.X.X.X,<XXX>): user not authenticated:
NT_STATUS_LOGON_FAILURE
12:06:54 dovecot: auth: Debug: client in: CONT<hidden>
12:06:54 dovecot: auth: Error: talloc: access after free error - first free may
be at ../auth/ntlmssp/ntlmssp_server.c:457
12:06:54 dovecot: auth: Error: Bad talloc magic value - access after free
12:06:54 dovecot: auth: Error: PANIC (pid 2570): Bad talloc magic value - access
after free
12:06:54 dovecot: auth: Error: BACKTRACE: 15 stack frames:
12:06:54 dovecot: auth: Error: #0 /lib64/libsmbconf.so.0(log_stack_trace+0x1a)
12:06:54 dovecot: auth: Error: #1 /lib64/libsmbconf.so.0(smb_panic_s3+0x20)
12:06:54 dovecot: auth: error: #2 /lib53/libsamba-util.so.0(smb_panic+0x2f)
12:06:54 dovecot: auth: Error: #3 /lib64/libtalloc.so.2(+0x20af)
12:06:54 dovecot: auth: Error: #4 /lib64/libtalloc.so.2(_talloc_free+0x545)
12:06:54 dovecot: auth: Error: #5 /lib64/libsamba-util.so.0(data_blob_free+0x18)
12:06:54 dovecot: auth: Error: #6
/lib64/libgensec.so.0(gensec_ntlmssp_server_auth+0xdf)
12:06:54 dovecot: auth: Error: #7
/lib64/libgensec.so.0(gensec_ntlmssp_update+0x253)
12:06:54 dovecot: auth: Error: #8 /lib64/libgensec.so.0(gensec_update_ev+0x232)
12:06:54 dovecot: auth: Error: #9 /lib64/libgensec.so.0(gensec_update+0x17)
12:06:54 dovecot: auth: Error: #10 /usr/bin/ntlm_auth(+0x92df)
12:06:54 dovecot: auth: Error: #11 /usr/bin/ntlm_auth(+0x587f)
12:06:54 dovecot: auth: Error: #12 /usr/bin/ntlm_auth(main+0xc3b)
12:06:54 dovecot: auth: Error: #13 /lib64/libc.so.6(__libc_start_main+0xf5)
12:06:54 dovecot: auth: Error: #14 /usr/bin/ntlm_auth(+0x535d)
12:06:54 dovecot: auth: Error: Can not dump core: corepath not set up
12:06:55 postfix/smtp[2560]: disconnect from pc1
12:09:54 dovecot: imap-login: Disconnected: Inactivity during authentication
(disconnected while authenticating, waited 180 secs): user =<>,
method=NTLM, rip=x.x.x.x, lip=x.x.x.x, session=<XXX>
The last line ends up repeating as clients continue to try to connect.