"Unexpected NTLM message Type 3 in new connection" Ubuntu 16.04 Apache 2.4

[peternewman]

apache2 2.4.18-2ubuntu3.1
libapache2-mod-python 3.3.1-11ubuntu2
python-pyauthenntlm2 2.2-300117

Similar to #12 I was seeing "Unexpected NTLM message Type 3 in new connection", the connection ID seemed to increment before the full NTLM handshake had completed. I've just realised I was using an internal redirect from / to /index.cgi, but this seems unlikely to have broken it.

Where PDC is 192.168.0.1 aka TESTDC.TESTDOMAIN.COM
BDC is 192.168.0.2 aka TESTDC2.TESTDOMAIN.COM

Client machine is 192.168.0.10

Apache config:

Alias /authtests /var/www/authtests

<Directory "/var/www/authtests/ntlm">
        Options +ExecCGI
        AddHandler cgi-script .cgi

				AuthName NTAuth
				AuthType NTLM
				PythonAuthenHandler pyntlm
				PythonOption Domain TESTDOMAIN.COM
				PythonOption PDC TESTDC.TESTDOMAIN.COM
				PythonOption BDC TESTDC2.TESTDOMAIN.COM
				require valid-user
				PythonOption Require valid-user

				LogLevel info
</Directory>

Before (with PDC deliberately misconfigured to see some logging):

[Sun Feb 19 10:16:22.098205 2017] [:info] [pid 12962:tid 140711507302144] [client 192.168.0.10:54022] PYNTLM: Handling connection 0x40 from address 192.168.0.10 for GET URI /authtests/ntlm/. 0 entries in connection cache.
[Sun Feb 19 10:16:22.125503 2017] [:info] [pid 12962:tid 140711498909440] [client 192.168.0.10:54025] PYNTLM: Handling connection 0x41 from address 192.168.0.10 for GET URI /authtests/ntlm/. 0 entries in connection cache.
[Sun Feb 19 10:16:22.125628 2017] [:info] [pid 12962:tid 140711498909440] [client 192.168.0.10:54025] PYTNLM: Initiating connection to Domain Controller server zzTESTDC.TESTDOMAIN.COM (domain TESTDOMAIN.COM).
[Sun Feb 19 10:16:22.127003 2017] [:crit] [pid 12962:tid 140711498909440] [client 192.168.0.10:54025] PYNTLM: Error when retrieving Type 2 message from server(zzTESTDC.TESTDOMAIN.COM) = [Errno -2] Name or service not known
[Sun Feb 19 10:16:22.127066 2017] [:info] [pid 12962:tid 140711498909440] [client 192.168.0.10:54025] PYTNLM: Initiating connection to Domain Controller server TESTDC2.TESTDOMAIN.COM (domain TESTDOMAIN.COM).
[Sun Feb 19 10:16:22.142896 2017] [:info] [pid 12962:tid 140711490516736] [client 192.168.0.10:54025] PYNTLM: Handling connection 0x42 from address 192.168.0.10 for GET URI /authtests/ntlm/. 1 entries in connection cache.
[Sun Feb 19 10:16:22.142976 2017] [:info] [pid 12962:tid 140711490516736] [client 192.168.0.10:54025] Unexpected NTLM message Type 3 in new connection from address 192.168.0.10 and URI /authtests/ntlm/

With more logging:

[Sun Feb 19 16:43:19.818869 2017] [:info] [pid 14897:tid 140451604592384] [client 192.168.0.10:51753] PYNTLM: Handling connection 0x0 from address 192.168.0.10 for GET URI /authtests/ntlm. 0 entries in connection cache.
[Sun Feb 19 16:43:19.818921 2017] [:info] [pid 14897:tid 140451604592384] [client 192.168.0.10:51753] PYNTLM: Cache: {}
[Sun Feb 19 16:43:19.818943 2017] [:info] [pid 14897:tid 140451604592384] [client 192.168.0.10:51753] PYNTLM: Con Notes: {}
[Sun Feb 19 16:43:19.872335 2017] [:info] [pid 14898:tid 140451604592384] [client 192.168.0.10:51756] PYNTLM: Handling connection 0x40 from address 192.168.0.10 for GET URI /authtests/ntlm. 0 entries in connection cache.
[Sun Feb 19 16:43:19.872383 2017] [:info] [pid 14898:tid 140451604592384] [client 192.168.0.10:51756] PYNTLM: Cache: {}
[Sun Feb 19 16:43:19.872407 2017] [:info] [pid 14898:tid 140451604592384] [client 192.168.0.10:51756] PYNTLM: Con Notes: {}
[Sun Feb 19 16:43:19.872440 2017] [:info] [pid 14898:tid 140451604592384] [client 192.168.0.10:51756] PYTNLM: Initiating connection to Domain Controller server TESTDC.TESTDOMAIN.COM (domain TESTDOMAIN.COM).
[Sun Feb 19 16:43:19.893372 2017] [:info] [pid 14898:tid 140451596199680] [client 192.168.0.10:51756] PYNTLM: Handling connection 0x41 from address 192.168.0.10 for GET URI /authtests/ntlm. 1 entries in connection cache.
[Sun Feb 19 16:43:19.893477 2017] [:info] [pid 14898:tid 140451596199680] [client 192.168.0.10:51756] PYNTLM: Cache: {64: (IP: TESTDC.TESTDOMAIN.COM:445 Domain: TESTDOMAIN.COM,\n      1487522599)}
[Sun Feb 19 16:43:19.893502 2017] [:info] [pid 14898:tid 140451596199680] [client 192.168.0.10:51756] PYNTLM: Con Notes: {}
[Sun Feb 19 16:43:19.893523 2017] [:info] [pid 14898:tid 140451596199680] [client 192.168.0.10:51756] Unexpected NTLM message Type 3 in new connection from address 192.168.0.10 and URI /authtests/ntlm from id 65

With even more logging:

[Sun Feb 19 18:56:05.543370 2017] [:info] [pid 16406:tid 139620972967680] [client 192.168.0.10:63534] PYNTLM: Handling connection 0x40 from address 192.168.0.10 for GET URI /authtests/ntlm/?1. 0 entries in connection cache.
[Sun Feb 19 18:56:05.543568 2017] [:info] [pid 16406:tid 139620972967680] [client 192.168.0.10:63534] authenhandler Connection (('192.168.0.10', 63534))->(('192.168.0.1', 80)) KA 0
[Sun Feb 19 18:56:05.545014 2017] [:info] [pid 16406:tid 139620972967680] [client 192.168.0.10:63534] PYNTLM: Cache: {}
[Sun Feb 19 18:56:05.545059 2017] [:info] [pid 16406:tid 139620972967680] [client 192.168.0.10:63534] PYNTLM: Con Notes: {}
[Sun Feb 19 18:56:05.545324 2017] [:info] [pid 16406:tid 139620972967680] [client 192.168.0.10:63534] Handle type 1 cache rm, Connection (('192.168.0.10', 63534))->(('192.168.0.1', 80)) KA 0
[Sun Feb 19 18:56:05.545362 2017] [:info] [pid 16406:tid 139620972967680] [client 192.168.0.10:63534] PYTNLM: Initiating connection to Domain Controller server TESTDC.TESTDOMAIN.COM (domain TESTDOMAIN.COM).
[Sun Feb 19 18:56:05.549161 2017] [:info] [pid 16406:tid 139620972967680] [client 192.168.0.10:63534] Handle type 1 cache add, Connection (('192.168.0.10', 63534))->(('192.168.0.1', 80)) KA 0
[Sun Feb 19 18:56:05.567635 2017] [:info] [pid 16406:tid 139620964574976] [client 192.168.0.10:63534] PYNTLM: Handling connection 0x41 from address 192.168.0.10 for GET URI /authtests/ntlm/?1. 1 entries in connection cache.
[Sun Feb 19 18:56:05.567928 2017] [:info] [pid 16406:tid 139620964574976] [client 192.168.0.10:63534] authenhandler Connection (('192.168.0.10', 63534))->(('192.168.0.1', 80)) KA 1
[Sun Feb 19 18:56:05.568094 2017] [:info] [pid 16406:tid 139620964574976] [client 192.168.0.10:63534] PYNTLM: Cache: {64: (IP: TESTDC.TESTDOMAIN.COM:445 Domain: TESTDOMAIN.COM,\n      1487530565)}
[Sun Feb 19 18:56:05.568177 2017] [:info] [pid 16406:tid 139620964574976] [client 192.168.0.10:63534] PYNTLM: Con Notes: {}
[Sun Feb 19 18:56:05.568364 2017] [:info] [pid 16406:tid 139620964574976] [client 192.168.0.10:63534] Authenhandler ntlm_version 3 Connection (('192.168.0.10', 63534))->(('192.168.0.1', 80)) KA 1
[Sun Feb 19 18:56:05.568488 2017] [:info] [pid 16406:tid 139620964574976] [client 192.168.0.10:63534] Unexpected NTLM message Type 3 in new connection from address 192.168.0.10 and URI /authtests/ntlm/?1 from id 65 (('192.168.0.10', 63534))
[Sun Feb 19 18:56:05.568665 2017] [:info] [pid 16406:tid 139620964574976] [client 192.168.0.10:63534] Connection (('192.168.0.10', 63534))->(('192.168.0.1', 80)) KA 1

With workaround:

[Sun Feb 19 19:03:05.519408 2017] [:info] [pid 16518:tid 139972984174336] [client 192.168.0.10:56376] PYNTLM: Handling connection 0x47 from address 192.168.0.10 for GET URI /authtests/ntlm/?1dsdsdsdsds. 0 entries in connection cache.
[Sun Feb 19 19:03:05.519718 2017] [:info] [pid 16518:tid 139972984174336] [client 192.168.0.10:56376] authenhandler Connection (('192.168.0.10', 56376))->(('192.168.0.1', 80)) KA 0
[Sun Feb 19 19:03:05.519767 2017] [:info] [pid 16518:tid 139972984174336] [client 192.168.0.10:56376] PYNTLM: Cache: {}
[Sun Feb 19 19:03:05.519921 2017] [:info] [pid 16518:tid 139972984174336] [client 192.168.0.10:56376] PYNTLM: Con Notes: {}
[Sun Feb 19 19:03:05.534815 2017] [:info] [pid 16518:tid 139972975781632] [client 192.168.0.10:56379] PYNTLM: Handling connection 0x48 from address 192.168.0.10 for GET URI /authtests/ntlm/?1dsdsdsdsds. 0 entries in connection cache.
[Sun Feb 19 19:03:05.535048 2017] [:info] [pid 16518:tid 139972975781632] [client 192.168.0.10:56379] authenhandler Connection (('192.168.0.10', 56379))->(('192.168.0.1', 80)) KA 0
[Sun Feb 19 19:03:05.535094 2017] [:info] [pid 16518:tid 139972975781632] [client 192.168.0.10:56379] PYNTLM: Cache: {}
[Sun Feb 19 19:03:05.535189 2017] [:info] [pid 16518:tid 139972975781632] [client 192.168.0.10:56379] PYNTLM: Con Notes: {}
[Sun Feb 19 19:03:05.535388 2017] [:info] [pid 16518:tid 139972975781632] [client 192.168.0.10:56379] Handle type 1 cache rm, Connection (('192.168.0.10', 56379))->(('192.168.0.1', 80)) KA 0
[Sun Feb 19 19:03:05.535482 2017] [:info] [pid 16518:tid 139972975781632] [client 192.168.0.10:56379] PYTNLM: Initiating connection to Domain Controller server TESTDC.TESTDOMAIN.COM (domain TESTDOMAIN.COM).
[Sun Feb 19 19:03:05.539073 2017] [:info] [pid 16518:tid 139972975781632] [client 192.168.0.10:56379] Handle type 1 cache add, Connection (('192.168.0.10', 56379))->(('192.168.0.1', 80)) KA 0
[Sun Feb 19 19:03:05.544361 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] PYNTLM: Handling connection 0x49 from address 192.168.0.10 for GET URI /authtests/ntlm/?1dsdsdsdsds. 1 entries in connection cache.
[Sun Feb 19 19:03:05.544527 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] authenhandler Connection (('192.168.0.10', 56379))->(('192.168.0.1', 80)) KA 1
[Sun Feb 19 19:03:05.544711 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] PYNTLM: Cache: {'192.168.0.10-56379': (IP: TESTDC.TESTDOMAIN.COM:445 Domain: TESTDOMAIN.COM,\n                        1487530985)}
[Sun Feb 19 19:03:05.544743 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] PYNTLM: Con Notes: {}
[Sun Feb 19 19:03:05.544868 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] Authenhandler ntlm_version 3 Connection (('192.168.0.10', 56379))->(('192.168.0.1', 80)) KA 1
[Sun Feb 19 19:03:05.544984 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] Handle type 3 Connection (('192.168.0.10', 56379))->(('192.168.0.1', 80)) KA 1
[Sun Feb 19 19:03:05.545020 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] PYNTLM: Proxy: IP: TESTDC.TESTDOMAIN.COM:445 Domain: TESTDOMAIN.COM
[Sun Feb 19 19:03:05.557399 2017] [:notice] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] PYNTLM: User testuser/TESTDOMAIN has been authenticated to access URI /authtests/ntlm/?1dsdsdsdsds
[Sun Feb 19 19:03:05.557559 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] Handle type 3 cache rm Connection (('192.168.0.10', 56379))->(('192.168.0.1', 80)) KA 1
[Sun Feb 19 19:03:05.557818 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] PYNTLM: Handling connection 0x49 from address 192.168.0.10 for GET URI /authtests/ntlm/index.html?1dsdsdsdsds. 0 entries in connection cache.
[Sun Feb 19 19:03:05.557945 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] authenhandler Connection (('192.168.0.10', 56379))->(('192.168.0.1', 80)) KA 1
[Sun Feb 19 19:03:05.557971 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] PYNTLM: Cache: {}
[Sun Feb 19 19:03:05.557994 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] PYNTLM: Con Notes: {'NTLM_AUTHORIZED': 'testuser'}
[Sun Feb 19 19:03:05.558017 2017] [:info] [pid 16518:tid 139972967388928] [client 192.168.0.10:56379] PYTNLM: Spurious authentication request on connection 0x49. Method = GET. Content-Length = 0. Headers = ['NTLM <256 base64 characters removed>']

[peternewman]

My workaround was to switch from using the connection IDs, which appear to be changing during the connection (note how they are getting reused KA=KeepAlive count, but they aren't being kept alive for long enough).

Instead I switched to the remote IP and remote port and used these as the cache key instead, which should only exist for a similar length of time to the connection ID I'd believe and should still be unique to that machine/connection.

I don't really understand why the connection ID isn't working, although I half wonder if it's something up with my Apache config or Ubuntu's version of Apache 2.4.

[prodigy7]

What exactly you've to fix the problem for you? Could you post the config you've changed made this setup running? Thx!

[peternewman]

Hi @prodigy7 ,

So did you hit the same issue? What OS, Apache version etc were you using?

Sorry, I thought I'd committed my changes. I've just done so here:
master...peternewman:apache2.4-fix

When I get a chance I'll try and gather together all the other Apache 2.4 fixes I'm using and open a PR.

[stroobl]

In our setup (Apache 2.4.25 on Debian Stretch) I was able to fix this error by switching Apache from mpm_event to mpm_worker. So without @peternewman 's fix.

[peternewman]

That sounds like a plausible explanation for the issues I was seeing and why it was only affecting some of us etc.