Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

usePreemptiveAuthentication doesn't work as expected #1764

Open
misko321 opened this issue Jan 26, 2024 · 4 comments
Open

usePreemptiveAuthentication doesn't work as expected #1764

misko321 opened this issue Jan 26, 2024 · 4 comments
Labels
bug Indicates an unexpected problem or unintended behavior smartbear-supported SmartBear engineering team will support this issue. See https://docs.pact.io/help/smartbear

Comments

@misko321
Copy link

misko321 commented Jan 26, 2024 •
edited

usePreemptiveAuthentication property doesn't work as expected

Steps to reproduce:

  • set the system property: pact.pactbroker.httpclient.usePreemptiveAuthentication="true"
  • run the provider tests pointing to a Pact Broker with Basic Auth enabled

Results:

  • Expected: the very first request to Pact Broker contains the Authorization header with Basic Auth credentials; no 401 Unauthorized ever appears in the response
  • Actual: the first request to Pact Broker doesn't contain the Authorization header with Basic Auth credentials; 401 Unauthorized is returned in the response, which Pact doesn't expect and fails later on

I think the crucial logs are:

2024-01-26 08:35:45.005 WARN [Test worker] au.com.dius.pact.core.pactbroker.HalClient$Companion.setupHttpClient: Using preemptive basic authentication with the pact broker at http://localhost:9292

which confirms, that the property was read correctly and:

2024-01-26 08:57:54.705 ERROR [Test worker] org.apache.hc.client5.http.impl.auth.HttpAuthenticator.addAuthResponse: ex-0000000001 Basic{} authentication error: User credentials not set

which tells that the underlying Apache HTTP client doesn't use the username and password set in Pact config (or it expects to find the credentials for this particular thing in other place than Pact sets).

Same thing happens if I use a remotely deployed Pact Broker and not the one running on a localhost, so that's not the reason here.

If the property is set to false, then the non-preemptive flow is executed correctly and the username and password are used just fine in the second try, so they are loaded correctly.

Dependency used: au.com.dius.pact.provider:junit5spring:4.6.5 (the latest as of today)

Excerpt from logs:

2024-01-26 08:35:44.885 DEBUG [Test worker] au.com.dius.pact.provider.junitsupport.loader.PactBrokerLoader$Companion.newPactBrokerClient: Authentication: Basic
2024-01-26 08:35:44.902 DEBUG [Test worker] au.com.dius.pact.core.pactbroker.HalClient$Companion.fetch: Fetching: /
2024-01-26 08:35:45.005 WARN  [Test worker] au.com.dius.pact.core.pactbroker.HalClient$Companion.setupHttpClient: Using preemptive basic authentication with the pact broker at http://localhost:9292
2024-01-26 08:35:45.023 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.InternalHttpClient.doExecute: ex-0000000001 preparing request execution
2024-01-26 08:35:45.032 DEBUG [Test worker] org.apache.hc.client5.http.impl.auth.AuthCacheKeeper.loadFromCache: ex-0000000001 Re-using cached 'Basic' auth scheme for http://localhost:9292
2024-01-26 08:35:45.032 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.ProtocolExec.execute: ex-0000000001 target auth state: UNCHALLENGED
2024-01-26 08:35:45.033 ERROR [Test worker] org.apache.hc.client5.http.impl.auth.HttpAuthenticator.addAuthResponse: ex-0000000001 Basic{} authentication error: User credentials not set
2024-01-26 08:35:45.033 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.ProtocolExec.execute: ex-0000000001 proxy auth state: UNCHALLENGED
2024-01-26 08:35:45.034 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.ConnectExec.execute: ex-0000000001 acquiring connection with route {}->http://localhost:9292
2024-01-26 08:35:45.034 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.InternalHttpClient.acquireEndpoint: ex-0000000001 acquiring endpoint (3 MINUTES)
2024-01-26 08:35:45.036 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager.lease: ex-0000000001 endpoint lease request (3 MINUTES) [route: {}->http://localhost:9292][total available: 0; route allocated: 0 of 5; total allocated: 0 of 25]
2024-01-26 08:35:45.040 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager.get: ex-0000000001 endpoint leased [route: {}->http://localhost:9292][total available: 0; route allocated: 1 of 5; total allocated: 1 of 25]
2024-01-26 08:35:45.054 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager.get: ex-0000000001 acquired ep-0000000001
2024-01-26 08:35:45.055 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.InternalHttpClient.acquireEndpoint: ex-0000000001 acquired endpoint ep-0000000001
2024-01-26 08:35:45.055 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.ConnectExec.execute: ex-0000000001 opening connection {}->http://localhost:9292
2024-01-26 08:35:45.056 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.InternalHttpClient.connectEndpoint: ep-0000000001 connecting endpoint (null)
2024-01-26 08:35:45.058 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager.connect: ep-0000000001 connecting endpoint to http://localhost:9292 (3 MINUTES)
2024-01-26 08:35:45.058 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator.connect: localhost resolving remote address
2024-01-26 08:35:45.059 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator.connect: localhost resolved to [localhost/127.0.0.1]
2024-01-26 08:35:45.061 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator.connect: localhost:9292 connecting null->localhost/127.0.0.1:9292 (3 MINUTES)
2024-01-26 08:35:45.061 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.DefaultManagedHttpClientConnection.setSocketTimeout: http-outgoing-0 set socket timeout to 3 MINUTES
2024-01-26 08:35:45.062 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.DefaultHttpClientConnectionOperator.connect: localhost:9292 connected null->localhost/127.0.0.1:9292 as http-outgoing-0
2024-01-26 08:35:45.062 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager.connect: ep-0000000001 connected http-outgoing-0
2024-01-26 08:35:45.062 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.InternalHttpClient.connectEndpoint: ep-0000000001 endpoint connected
2024-01-26 08:35:45.063 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.MainClientExec.execute: ex-0000000001 executing GET / HTTP/1.1
2024-01-26 08:35:45.063 DEBUG [Test worker] org.apache.hc.client5.http.protocol.RequestAddCookies.process: ex-0000000001 Cookie spec selected: strict
2024-01-26 08:35:45.070 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.InternalHttpClient.execute: ep-0000000001 start execution ex-0000000001
2024-01-26 08:35:45.071 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager.execute: ep-0000000001 executing exchange ex-0000000001 over http-outgoing-0
2024-01-26 08:35:45.072 DEBUG [Test worker] org.apache.hc.client5.http.headers.onRequestSubmitted: http-outgoing-0 >> GET / HTTP/1.1
2024-01-26 08:35:45.072 DEBUG [Test worker] org.apache.hc.client5.http.headers.onRequestSubmitted: http-outgoing-0 >> Content-Type: application/json
2024-01-26 08:35:45.072 DEBUG [Test worker] org.apache.hc.client5.http.headers.onRequestSubmitted: http-outgoing-0 >> Accept: application/hal+json, application/json
2024-01-26 08:35:45.072 DEBUG [Test worker] org.apache.hc.client5.http.headers.onRequestSubmitted: http-outgoing-0 >> Accept-Encoding: gzip, x-gzip, deflate
2024-01-26 08:35:45.072 DEBUG [Test worker] org.apache.hc.client5.http.headers.onRequestSubmitted: http-outgoing-0 >> Host: localhost:9292
2024-01-26 08:35:45.073 DEBUG [Test worker] org.apache.hc.client5.http.headers.onRequestSubmitted: http-outgoing-0 >> Connection: keep-alive
2024-01-26 08:35:45.073 DEBUG [Test worker] org.apache.hc.client5.http.headers.onRequestSubmitted: http-outgoing-0 >> User-Agent: Apache-HttpClient/5.2.1 (Java/17.0.7)
2024-01-26 08:35:45.073 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 >> "GET / HTTP/1.1[\r][\n]"
2024-01-26 08:35:45.073 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 >> "Content-Type: application/json[\r][\n]"
2024-01-26 08:35:45.073 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 >> "Accept: application/hal+json, application/json[\r][\n]"
2024-01-26 08:35:45.074 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 >> "Accept-Encoding: gzip, x-gzip, deflate[\r][\n]"
2024-01-26 08:35:45.074 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 >> "Host: localhost:9292[\r][\n]"
2024-01-26 08:35:45.074 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 >> "Connection: keep-alive[\r][\n]"
2024-01-26 08:35:45.074 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 >> "User-Agent: Apache-HttpClient/5.2.1 (Java/17.0.7)[\r][\n]"
2024-01-26 08:35:45.074 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 >> "[\r][\n]"
2024-01-26 08:35:45.075 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 << "HTTP/1.1 401 Unauthorized[\r][\n]"
2024-01-26 08:35:45.076 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 << "Content-Type: text/plain[\r][\n]"
2024-01-26 08:35:45.076 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 << "WWW-Authenticate: Basic realm="Restricted area"[\r][\n]"
2024-01-26 08:35:45.076 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 << "Content-Length: 0[\r][\n]"
2024-01-26 08:35:45.076 DEBUG [Test worker] org.apache.hc.client5.http.wire.wire: http-outgoing-0 << "[\r][\n]"
2024-01-26 08:35:45.078 DEBUG [Test worker] org.apache.hc.client5.http.headers.onResponseReceived: http-outgoing-0 << HTTP/1.1 401 Unauthorized
2024-01-26 08:35:45.079 DEBUG [Test worker] org.apache.hc.client5.http.headers.onResponseReceived: http-outgoing-0 << Content-Type: text/plain
2024-01-26 08:35:45.079 DEBUG [Test worker] org.apache.hc.client5.http.headers.onResponseReceived: http-outgoing-0 << WWW-Authenticate: Basic realm="Restricted area"
2024-01-26 08:35:45.079 DEBUG [Test worker] org.apache.hc.client5.http.headers.onResponseReceived: http-outgoing-0 << Content-Length: 0
2024-01-26 08:35:45.082 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.MainClientExec.execute: ex-0000000001 connection can be kept alive for 3 MINUTES
2024-01-26 08:35:45.082 DEBUG [Test worker] org.apache.hc.client5.http.impl.classic.InternalHttpClient.releaseEndpoint: ep-0000000001 releasing valid endpoint
2024-01-26 08:35:45.082 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager.release: ep-0000000001 releasing endpoint
2024-01-26 08:35:45.082 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager.release: ep-0000000001 connection http-outgoing-0 can be kept alive for 3 MINUTES
2024-01-26 08:35:45.083 DEBUG [Test worker] org.apache.hc.client5.http.impl.io.PoolingHttpClientConnectionManager.release: ep-0000000001 connection released [route: {}->http://localhost:9292][total available: 1; route allocated: 1 of 5; total allocated: 1 of 25]
2024-01-26 08:35:45.084 DEBUG [Test worker] org.apache.hc.client5.http.impl.auth.HttpAuthenticator.isChallenged: ex-0000000001 Authentication required
2024-01-26 08:35:45.084 DEBUG [Test worker] org.apache.hc.client5.http.impl.auth.AuthCacheKeeper.clearCache: ex-0000000001 Clearing cached auth scheme for http://localhost:9292/
2024-01-26 08:35:45.084 DEBUG [Test worker] org.apache.hc.client5.http.impl.auth.HttpAuthenticator.updateAuthState: ex-0000000001 localhost:9292 requested authentication
2024-01-26 08:35:45.085 DEBUG [Test worker] org.apache.hc.client5.http.impl.auth.HttpAuthenticator.updateAuthState: ex-0000000001 Authorization challenge processed
2024-01-26 08:35:45.086 DEBUG [Test worker] org.apache.hc.client5.http.impl.auth.HttpAuthenticator.updateAuthState: ex-0000000001 Authentication failed
2024-01-26 08:35:45.086 DEBUG [Test worker] org.apache.hc.client5.http.impl.auth.AuthCacheKeeper.clearCache: ex-0000000001 Clearing cached auth scheme for http://localhost:9292/
2024-01-26 08:35:45.094 WARN  [Test worker] au.com.dius.pact.core.pactbroker.HalClient$Companion.navigate: Failed to fetch the root HAL document

au.com.dius.pact.core.pactbroker.InvalidNavigationRequest: Failed to fetch the root HAL document
	at au.com.dius.pact.core.pactbroker.HalClient.navigate(HalClient.kt:253)
	...
Caused by: au.com.dius.pact.core.pactbroker.RequestFailedException: Request to path '/' failed with response 401
	at au.com.dius.pact.core.pactbroker.HalClient.handleHalResponse(HalClient.kt:345)
	...
@rholshausen rholshausen added the bug Indicates an unexpected problem or unintended behavior label Jan 30, 2024
@rholshausen
Copy link
Contributor

How are you setting the username and password?

rholshausen added a commit that referenced this issue Jan 30, 2024
@rholshausen
fix: when Preemptive Authentication is enabled, basic auth creds were…
01058b3 
… not being set correctly #1764
@rholshausen rholshausen added the smartbear-supported SmartBear engineering team will support this issue. See https://docs.pact.io/help/smartbear label Jan 31, 2024
@github-actions GitHub Actions
Copy link

🤖 Great news! We've labeled this issue as smartbear-supported and created a tracking ticket in PactFlow's Jira (PACT-1754). We'll keep work public and post updates here. Meanwhile, feel free to check out our docs. Thanks for your patience!

@misko321
Copy link
Author

How are you setting the username and password?

I'm running tests with Spring, so in the test I have:

@ExtendWith(SpringExtension.class)
@SpringBootTest(webEnvironment = SpringBootTest.WebEnvironment.DEFINED_PORT)
@Provider("some-provider-name")
@PactBroker
class ClassUnderTest {
  ...
}

and the properties for the @PactBroker annotation are read from application.yaml:

pactbroker:
  url: ${PACT_BROKER_URL:http://localhost:9292}
  auth:
    username: ${PACT_BROKER_USERNAME:pact}
    password: ${PACT_BROKER_PASSWORD:pact}

Nothing more. All these properties are read fine and everything works okay when usePreemptiveAuthentication=false.

@rholshausen
Copy link
Contributor

4.6.6 has been released with a fix for this

rholshausen added a commit that referenced this issue Apr 22, 2024
@rholshausen
fix: when Preemptive Authentication is enabled, basic auth creds were…
ac328e2 
… not being set correctly #1764
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Indicates an unexpected problem or unintended behavior smartbear-supported SmartBear engineering team will support this issue. See https://docs.pact.io/help/smartbear
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@misko321 @rholshausen