PyAuthenNTLM2
PyAuthenNTLM2 copied to clipboard
Legrandin
"Unexpected NTLM message Type 3 in new connection" Ubuntu 16.04 Apache 2.4
apache2 2.4.18-2ubuntu3.1 libapache2-mod-python 3.3.1-11ubuntu2 python-pyauthenntlm2 2.2-300117
Similar to https://github.com/Legrandin/PyAuthenNTLM2/issues/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>']
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.
What exactly you've to fix the problem for you? Could you post the config you've changed made this setup running? Thx!
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: https://github.com/Legrandin/PyAuthenNTLM2/compare/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.
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.
That sounds like a plausible explanation for the issues I was seeing and why it was only affecting some of us etc.