talloc access after free error ntlmssp_server.c:457

[J Landwehr]

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.