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:
Fresh boot of CentOS server, only configured for postfix/dovecot
Connect with Outlook 2016 12.0.4312.1000 32bit on Win7 via IMAP to this dovecot server
Any existing and new mail loads in OK to inbox - so authentication is working OK to AD domain server
Send an email to someone from Outlook
SMTP process completes, message is delivered -
dovecot immediately panics on servers, Authentication to dovecot no longer works
<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.