Closed gabi-dobritescu closed 3 years ago
Hi @gabi-dobritescu - thanks for the detailed issue report!
Indeed, the proxy should respond try to authenticate when a 401 appears, even if a successful auth handshake has been performed on the same connection before. I have fixed a similar issue quite some time ago, and was under the impression that this already was in place. Maybe something is different for Negotiate. I'll look into it shortly.
Ok, after looking through this again I think the code should be correct as is.
The purpose of isNewOrAuthenticated
is to check if the current connection is new (= authentication not started yet) or authenticated (in which case authentication may be restarted on request by the server). If the state is something in between, authentication is ongoing and a new response should not reach the onResponse method. While authentication handshake is ongoing, the code stays within this method:
https://github.com/bjowes/cypress-ntlm-auth/blob/2d18b1b842e4b77ef8c24527d335b6010926a0b0/src/proxy/negotiate.manager.ts#L20
until authentication is successful or fails.
A 401 should not reach the onReponse callback during that phase, since it is handled inside the NegotiateManager.
However, since you have a use case where this is an issue, there must be something more to it. Could you provide some debug logs so I can follow the flow?
Hi Bjorn,
First of all, thank you for looking into this issue. Much appreciated.
Otherwise, here's an excerpt of debug messages from a run with 3 API calls to the same endpoint. I've enabled debugging for the plugin and debug headers too. I've redacted the url that the requests are targeting, but it's the same url for all 3 requests.
cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:30417 to target http://127.0.0.1:29570/ +7m cypress:plugin:ntlm-auth Request to config API +2ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:29570/ +1ms cypress:plugin:ntlm-auth Received valid NTLM SSO config +3ms cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:30419 to target http://
/ +42ms cypress:plugin:ntlm-auth Request to http:// / in registered NTLM Hosts (using SSO) +1ms cypress:plugin:ntlm-auth Received 401 with Negotiate in www-authenticate header. Starting handshake. +221ms cypress:plugin:ntlm-auth Sending Negotiate message token request +2ms cypress:plugin:ntlm-auth [Negotiate YHoGBisGAQUFAqBwMG6gMDAuBgorBgEEAYI3AgIKBgkqhkiC9xIBAgIGCSqGSIb3EgECAgYKKwYBBAGCNwICHqI6BDhOVExNU1NQAAEAAACXsgjiAgACADYAAAAOAA4AKAAAAAoAY0UAAAAPVE9MT05BRDY1MEJaSjRFVQ==] +1ms cypress:plugin:ntlm-auth Sending Negotiate message token response with initial client request +109ms cypress:plugin:ntlm-auth [Negotiate oYHqMIHnoAMKAQGigcsEgchOVExNU1NQAAMAAAAYABgAiAAAABgAGACgAAAABAAEAFgAAAAQABAAXAAAABwAHABsAAAAEAAQALgAAAAVgojiCgBjRQAAAA9cwR0SiY0smbEzj6J/WkJsRQBVAEQAbwBiAHIAaQB0AGUAcwBUAE8ATABPAE4AQQBEADYANQAwAEIAWgBKADQAyfrgQbz4y/QAAAAAAAAAAAAAAAAAAAAAr4c7E8KNO0fxvP3dtX+zVsNCMUVQgd58+ycWVMbR/DwVAUbMQfJ1zqMSBBABAAAAIOXYnBBYfJkAAAAA] +1ms cypress:plugin:ntlm-auth Removed agent for 127.0.0.1:30417 due to socket.close +5s cypress:plugin:ntlm-auth Negotiate authentication failed (www-authenticate with Negotiate not found in server response) with host http:// / +278ms cypress:plugin:ntlm-auth Cannot perform handshake. +1ms cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:30425 to target http://127.0.0.1:29570/ +109ms cypress:plugin:ntlm-auth Request to config API +1ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:29570/ +1ms cypress:plugin:ntlm-auth Received valid NTLM SSO config +3ms cypress:plugin:ntlm-auth Request to http:// / in registered NTLM Hosts (using SSO) +29ms cypress:plugin:ntlm-auth Request to config API +175ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:29570/ +2ms cypress:plugin:ntlm-auth Received valid NTLM SSO config +2ms cypress:plugin:ntlm-auth Request to http:// / in registered NTLM Hosts (using SSO) +29ms cypress:plugin:ntlm-auth Removed agent for 127.0.0.1:30425 due to socket.close +5s cypress:plugin:ntlm-auth Removed agent for 127.0.0.1:30419 due to socket.close +135ms
As you can see from the output above, the handshake is initiated only for the first request.
The handshake fails at the end because our server replies with "www-authenticate": "
Here's an example of what the server responds with for the last 2 requests:
Status: 401 - Unauthorized Headers: { "content-length": "61", "content-type": "application/json; charset=utf-8", "server": "Microsoft-HTTPAPI/2.0", "www-authenticate": "Negotiate", "date": "Fri, 12 Feb 2021 15:07:36 GMT", "connection": "keep-alive", "keep-alive": "timeout=5" } Body: { "Message": "Authorization has been denied for this request." }
I hope these additional details help with the investigation. I'll continue investigating on my end as well, focusing more on the handshake() method.
Thanks - still not able to see how it occurs, need to spend some more time on it. However, you should be able to work around it by calling cy.ntlmReset() at the beginning of each test. Then the connection will be removed so you have a clean slate for each test.
I've added a few logging statements of my own to better understand the flow of execution. Here's how it looks:
cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: /ntlm-sso +31s cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:33879 to target http://127.0.0.1:33624/ +1ms cypress:plugin:ntlm-auth Request to config API +1ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:33624/ +1ms cypress:plugin:ntlm-auth Received valid NTLM SSO config +2ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: /ntlm-sso +2ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for:
+37ms cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:33881 to target http:// +1ms cypress:plugin:ntlm-auth Request to http:// in registered NTLM Hosts (using SSO) +1ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: +342ms cypress:plugin:ntlm-auth Received 401 with Negotiate in www-authenticate header. Starting handshake. +1ms cypress:plugin:ntlm-auth ##### DEBUG handshake() invoked! +1ms cypress:plugin:ntlm-auth Sending Negotiate message token request +1ms cypress:plugin:ntlm-auth [Negotiate YHoGBisGAQUFAqBwMG6gMDAuBgorBgEEAYI3AgIKBgkqhkiC9xIBAgIGCSqGSIb3EgECAgYKKwYBBAGCNwICHqI6BDhOVExNU1NQAAEAAACXsgjiAgACADYAAAAOAA4AKAAAAAoAY0UAAAAPVE9MT05BRDY1MEJaSjRFVQ==] +1ms cypress:plugin:ntlm-auth ##### DEBUG handshakeResponse() invoked! +108ms cypress:plugin:ntlm-auth Sending Negotiate message token response with initial client request +2ms cypress:plugin:ntlm-auth [Negotiate oYHqMIHnoAMKAQGigcsEgchOVExNU1NQAAMAAAAYABgAiAAAABgAGACgAAAABAAEAFgAAAAQABAAXAAAABwAHABsAAAAEAAQALgAAAAVgojiCgBjRQAAAA+rTIz8fUdre5XK1X70ehhQRQBVAEQAbwBiAHIAaQB0AGUAcwBUAE8ATABPAE4AQQBEADYANQAwAEIAWgBKADQASQkcg0hclGUAAAAAAAAAAAAAAAAAAAAAgs+jhSMepY6yfwoRvbepAJKRWzvVehyW6j+PyREVqNeE3LWa52wX5aMSBBABAAAAeIGx6uKXQuUAAAAA] +1ms cypress:plugin:ntlm-auth Removed agent for 127.0.0.1:33879 due to socket.close +5s cypress:plugin:ntlm-auth ##### DEBUG handshakeResponse() invoked! +7s cypress:plugin:ntlm-auth Negotiate authentication failed (www-authenticate with Negotiate not found in server response) with host http:// +1ms cypress:plugin:ntlm-auth ##### DEBUG handshakeCallback() invoked! +1ms cypress:plugin:ntlm-auth Cannot perform handshake. +1ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: /ntlm-sso +384ms cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:33894 to target http://127.0.0.1:33624/ +1ms cypress:plugin:ntlm-auth Request to config API +2ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:33624/ +1ms cypress:plugin:ntlm-auth Received valid NTLM SSO config +3ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: /ntlm-sso +1ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: +28ms cypress:plugin:ntlm-auth Request to http:// in registered NTLM Hosts (using SSO) +1ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: +216ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: /ntlm-sso +58ms cypress:plugin:ntlm-auth Request to config API +1ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:33624/ +1ms cypress:plugin:ntlm-auth Received valid NTLM SSO config +3ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: /ntlm-sso +1ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: +31ms cypress:plugin:ntlm-auth Request to http:// in registered NTLM Hosts (using SSO) +1ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: +155ms cypress:plugin:ntlm-auth Removed agent for 127.0.0.1:33894 due to socket.close +5s cypress:plugin:ntlm-auth Removed agent for 127.0.0.1:33881 due to socket.close +190ms
The logging statements are the first statements in the methods they reference. I think this clearly shows that the handshake() method is not invoked at all for the 2nd and 3rd request.
Your suggestion with invoking cy.ntlmReset() before running each test did the trick - my tests are passing now.
This is how the debug output looks like after adding the reset statement:
cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: /reset +1m cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:34874 to target http://127.0.0.1:33624/ +2ms cypress:plugin:ntlm-auth Request to config API +1ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:33624/ +1ms cypress:plugin:ntlm-auth Received reset +3ms cypress:plugin:ntlm-auth Removed all agents due to reset +1ms cypress:plugin:ntlm-auth Removed and closed all tunnels due to reset +1ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: /reset +2ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: /ntlm-sso +11ms cypress:plugin:ntlm-auth Request to config API +1ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:33624/ +1ms cypress:plugin:ntlm-auth Received valid NTLM SSO config +3ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: /ntlm-sso +1ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: /
+37ms cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:34877 to target http:// / +1ms cypress:plugin:ntlm-auth Request to http:// / in registered NTLM Hosts (using SSO) +1ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: / +224ms cypress:plugin:ntlm-auth Received 401 with Negotiate in www-authenticate header. Starting handshake. +1ms cypress:plugin:ntlm-auth ##### DEBUG handshake() invoked! +1ms cypress:plugin:ntlm-auth Sending Negotiate message token request +2ms cypress:plugin:ntlm-auth [Negotiate YHoGBisGAQUFAqBwMG6gMDAuBgorBgEEAYI3AgIKBgkqhkiC9xIBAgIGCSqGSIb3EgECAgYKKwYBBAGCNwICHqI6BDhOVExNU1NQAAEAAACXsgjiAgACADYAAAAOAA4AKAAAAAoAY0UAAAAPVE9MT05BRDY1MEJaSjRFVQ==] +1ms cypress:plugin:ntlm-auth ##### DEBUG handshakeResponse() invoked! +107ms cypress:plugin:ntlm-auth Sending Negotiate message token response with initial client request +2ms cypress:plugin:ntlm-auth [Negotiate oYHqMIHnoAMKAQGigcsEgchOVExNU1NQAAMAAAAYABgAiAAAABgAGACgAAAABAAEAFgAAAAQABAAXAAAABwAHABsAAAAEAAQALgAAAAVgojiCgBjRQAAAA+xGzT0Amr+RHNFZ2N+UjivRQBVAEQAbwBiAHIAaQB0AGUAcwBUAE8ATABPAE4AQQBEADYANQAwAEIAWgBKADQA5AaV7q87B4EAAAAAAAAAAAAAAAAAAAAAfbuK75Lqiq/aMJ977TIC7Qr3pT9ygDDokSQJLZDu9JbdCv8hPlyeFqMSBBABAAAAJ78Y4br1MzUAAAAA] +1ms cypress:plugin:ntlm-auth Removed agent for 127.0.0.1:34874 due to socket.close +5s cypress:plugin:ntlm-auth ##### DEBUG handshakeResponse() invoked! +6s cypress:plugin:ntlm-auth Negotiate authentication failed (www-authenticate with Negotiate not found in server response) with host http:// / +1ms cypress:plugin:ntlm-auth ##### DEBUG handshakeCallback() invoked! +2ms cypress:plugin:ntlm-auth Cannot perform handshake. +1ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: /reset +314ms cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:34889 to target http://127.0.0.1:33624/ +2ms cypress:plugin:ntlm-auth Request to config API +1ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:33624/ +0ms cypress:plugin:ntlm-auth Received reset +3ms cypress:plugin:ntlm-auth Destroying context for 127.0.0.1:34877 +1ms cypress:plugin:ntlm-auth Removed all agents due to reset +1ms cypress:plugin:ntlm-auth Removed and closed all tunnels due to reset +1ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: /reset +2ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: /ntlm-sso +11ms cypress:plugin:ntlm-auth Request to config API +1ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:33624/ +1ms cypress:plugin:ntlm-auth Received valid NTLM SSO config +2ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: /ntlm-sso +2ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: / +28ms cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:34892 to target http:// / +1ms cypress:plugin:ntlm-auth Request to http:// / in registered NTLM Hosts (using SSO) +2ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: / +216ms cypress:plugin:ntlm-auth Received 401 with Negotiate in www-authenticate header. Starting handshake. +1ms cypress:plugin:ntlm-auth ##### DEBUG handshake() invoked! +2ms cypress:plugin:ntlm-auth Sending Negotiate message token request +1ms cypress:plugin:ntlm-auth [Negotiate YHoGBisGAQUFAqBwMG6gMDAuBgorBgEEAYI3AgIKBgkqhkiC9xIBAgIGCSqGSIb3EgECAgYKKwYBBAGCNwICHqI6BDhOVExNU1NQAAEAAACXsgjiAgACADYAAAAOAA4AKAAAAAoAY0UAAAAPVE9MT05BRDY1MEJaSjRFVQ==] +1ms cypress:plugin:ntlm-auth ##### DEBUG handshakeResponse() invoked! +107ms cypress:plugin:ntlm-auth Sending Negotiate message token response with initial client request +2ms cypress:plugin:ntlm-auth [Negotiate oYHqMIHnoAMKAQGigcsEgchOVExNU1NQAAMAAAAYABgAiAAAABgAGACgAAAABAAEAFgAAAAQABAAXAAAABwAHABsAAAAEAAQALgAAAAVgojiCgBjRQAAAA9qyJMka+3SGGA8yZ5PsPm2RQBVAEQAbwBiAHIAaQB0AGUAcwBUAE8ATABPAE4AQQBEADYANQAwAEIAWgBKADQAXLLmbpFF7F8AAAAAAAAAAAAAAAAAAAAAjuSh/6FkiCd6/JLjMe+DG2aiqRJ/TYSp+ePi2EHKUpfE15Qif46gwqMSBBABAAAApyrJ/koLkbkAAAAA] +1ms cypress:plugin:ntlm-auth Removed agent for 127.0.0.1:34889 due to socket.close +5s cypress:plugin:ntlm-auth ##### DEBUG handshakeResponse() invoked! +7s cypress:plugin:ntlm-auth Negotiate authentication failed (www-authenticate with Negotiate not found in server response) with host http:// / +1ms cypress:plugin:ntlm-auth ##### DEBUG handshakeCallback() invoked! +2ms cypress:plugin:ntlm-auth Cannot perform handshake. +1ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: /reset +319ms cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:34905 to target http://127.0.0.1:33624/ +2ms cypress:plugin:ntlm-auth Request to config API +1ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:33624/ +1ms cypress:plugin:ntlm-auth Received reset +3ms cypress:plugin:ntlm-auth Destroying context for 127.0.0.1:34892 +1ms cypress:plugin:ntlm-auth Removed all agents due to reset +1ms cypress:plugin:ntlm-auth Removed and closed all tunnels due to reset +1ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: /reset +2ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: /ntlm-sso +11ms cypress:plugin:ntlm-auth Request to config API +1ms cypress:plugin:ntlm-auth Created untracked agent for target http://127.0.0.1:33624/ +1ms cypress:plugin:ntlm-auth Received valid NTLM SSO config +3ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: /ntlm-sso +1ms cypress:plugin:ntlm-auth ##### DEBUG onRequest() invoked for: / +30ms cypress:plugin:ntlm-auth Created agent for client 127.0.0.1:34908 to target http:// / +1ms cypress:plugin:ntlm-auth Request to http:// / in registered NTLM Hosts (using SSO) +1ms cypress:plugin:ntlm-auth ##### DEBUG onResponse() invoked for: / +219ms cypress:plugin:ntlm-auth Received 401 with Negotiate in www-authenticate header. Starting handshake. +2ms cypress:plugin:ntlm-auth ##### DEBUG handshake() invoked! +1ms cypress:plugin:ntlm-auth Sending Negotiate message token request +2ms cypress:plugin:ntlm-auth [Negotiate YHoGBisGAQUFAqBwMG6gMDAuBgorBgEEAYI3AgIKBgkqhkiC9xIBAgIGCSqGSIb3EgECAgYKKwYBBAGCNwICHqI6BDhOVExNU1NQAAEAAACXsgjiAgACADYAAAAOAA4AKAAAAAoAY0UAAAAPVE9MT05BRDY1MEJaSjRFVQ==] +1ms cypress:plugin:ntlm-auth ##### DEBUG handshakeResponse() invoked! +108ms cypress:plugin:ntlm-auth Sending Negotiate message token response with initial client request +2ms cypress:plugin:ntlm-auth [Negotiate oYHqMIHnoAMKAQGigcsEgchOVExNU1NQAAMAAAAYABgAiAAAABgAGACgAAAABAAEAFgAAAAQABAAXAAAABwAHABsAAAAEAAQALgAAAAVgojiCgBjRQAAAA/yZGXyR/nYuScJO6akHsyzRQBVAEQAbwBiAHIAaQB0AGUAcwBUAE8ATABPAE4AQQBEADYANQAwAEIAWgBKADQA4hRJwcuU/s0AAAAAAAAAAAAAAAAAAAAA69LX/HCoucwKzUYNTEVddM5kdkPhLF+P7BzA4yzZrd0tBspOJc0TlKMSBBABAAAAYEM6hW9woMMAAAAA] +1ms cypress:plugin:ntlm-auth Removed agent for 127.0.0.1:34905 due to socket.close +5s cypress:plugin:ntlm-auth ##### DEBUG handshakeResponse() invoked! +7s cypress:plugin:ntlm-auth Negotiate authentication failed (www-authenticate with Negotiate not found in server response) with host http:// / +2ms cypress:plugin:ntlm-auth ##### DEBUG handshakeCallback() invoked! +1ms cypress:plugin:ntlm-auth Cannot perform handshake. +1ms cypress:plugin:ntlm-auth Removed agent for 127.0.0.1:34908 due to socket.close +5s
Please let me know what other debug info I can provide to assist with investigating the issue.
Ok, I figured it out. There were actually three cases where a new handshake should be attempted
I'm preparing a new release where this will be handled.
Secondly, I think your server implementation seems faulty. It really shouldn't return an empty Negotiate header if the authentication was successful, it should return a proper Negotiate token.
Thank you for putting in the fix. I've picked up the latest version and now the tests are passing just fine.
And I agree with you, it looks like our server side implementation of the authentication handshake is not 100% compliant with the protocol. I'll talk to the dev team to see if it can be improved.
I'm doing some API testing with Cypress where I'm sending multiple requests to the same endpoint that is protected with the Negotiate authentication scheme.
When I run my tests only the first test succeeds, all the subsequent ones fail with 401 Unauthorized errors.
After some debugging I realised that the authentication handshake happens only for the first request. On subsequent requests, the handshake does not get triggered although the server responds with the appropriate authentication request header.
I believe I've tracked down the source of the error to this line of code: https://github.com/bjowes/cypress-ntlm-auth/blob/2d18b1b842e4b77ef8c24527d335b6010926a0b0/src/proxy/ntlm.proxy.mitm.ts#L241
Based on my understanding of the code I believe this code should read: if (context && context.isNewOrUnauthenticated(targetHost))
and the isNewOrAuthenticated() from here: https://github.com/bjowes/cypress-ntlm-auth/blob/2d18b1b842e4b77ef8c24527d335b6010926a0b0/src/proxy/connection.context.ts#L74
should be changed to:
isNewOrUnauthenticated(ntlmHostUrl) { const auth = this._ntlmHost === undefined || (this._ntlmHost !== undefined && this._ntlmHost.href === ntlmHostUrl.href && this._ntlmState !== 4) /* Authenticated */; return auth; }
With these changes I got my tests to pass.
Please note, that I'm using this package quite a bit, with no issues at all. The only scenario where I've run into this issue is in my API test suites, where I only make requests to the same endpoint, multiple times in a row.
I'm using version 3.1.5 of the library.