talloc access after free error ntlmssp_server.c:457
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
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.
On 16 Mar 2016, at 22:38, J Landwehr jlandwehr@icloud.com wrote:
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
Looks like a bug in the winbind code.
Do you think it’s a bug in the dovecot code that calls winbind? Or in the samba based winbind code?
We have a fully patched CentOS system.
This case is definitely triggered as follows: Connect with Outlook Outlook brings in any new mail After maybe 30 seconds there are IMAP disconnect messages in maillog Then send a message to yourself. The message is sent and received, but the dovecot server crashes/panics Appears to be related to the CONT command And receiving NT_STATUS_WRONG_PASSWORD / NT_STATUS_LOGON_FAILURE
What I can’t figure out is that ntlm_auth always works from the command line, and IMAP is otherwise working to bring in new mail (so authenticating is working) - but it’s like a certain condition of sync’ing perhaps the Sent folder with the Inbox folder having two authentication events simultaneously is the issue, and the second one fails?
auth client connected auth client conencted client in: AUTH client in: AUTH client passdb out: CONT#0111 client passdb out: CONT#0111 client in: CONT<hidden> Got 'YR ..." from squid (length: 59). Starting GENSEC mechanism ntlmssp Starting GENSEC mechanism ntlmssp
Login for user [domain]\[user]@[workstation] failed due to [Wrong Password] ../auth/ntlmssp/ntlmssp_server.c:455: checking NTLMSSP password for domain/user failed: NT_STATUS_WRONG_PASSWORD GENSEC login failed: NT_STATUS_LOGON_FAILURE winbind(?,IP,<...>): user not authenticated: NT_STATUS_LOGON_FAILURE client in: CONT got 'KK ......' from squid . talloc: access after free error - first free may be at ../auth/ntlmssp/ntlmssp_server.c:457 Bad talloc magic value - access after free PANIC (pid ....): Bad talloc magic value - access after free Definitely welcome any debugging ideas and workarounds, because we have had to shut off IMAP and only use POP.
On Mar 29, 2016, at 1:46 PM, Timo Sirainen tss@iki.fi wrote:
On 16 Mar 2016, at 22:38, J Landwehr jlandwehr@icloud.com wrote:
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
Looks like a bug in the winbind code.
participants (2)
-
J Landwehr
-
Timo Sirainen