My company started experimenting with Pact and Pact-Net a couple months ago. I am trying to finish up a POC I can share with the larger team but I have hit a wall with the provider tests.
I have both ends coded up (consumer and provider) and running but my provider tests continue to fail. I am running a .Net Core 7 web service inside of the provider test but it always fails and returns a 500 when I'm expecting a 200 with a good response body.
I've tried to debug the code but I can only step into Startup. After that, the code goes blackbox and I cannot debug the controller itself.
Questions:
- Does anyone know how to debug a web service running on Kestrel driven by Pact?
- Is the code on my consumer side good or am I missing something?
- Any recommendations for best practices, etc?
Thank you for any information you might have to share!!!!
Here is the provider code:
var host = Host.CreateDefaultBuilder()
.ConfigureWebHostDefaults(webBuilder =>
{
// Without setting to develop, you will not see binding issues coming from the web service itself
webBuilder.UseEnvironment("Local").CaptureStartupErrors(true);
webBuilder.ConfigureLogging(logging => logging.SetMinimumLevel(LogLevel.Trace));
webBuilder.UseKestrel();
webBuilder.UseStartup<Startup>();
})
.Build();
host.Start();
var pactConfig = new PactVerifierConfig
{
LogLevel = PactLogLevel.Debug,
Outputters = new List<IOutput>
{
new XunitOutput(_outputHelper),
new ConsoleOutput()
}
};
IPactVerifier pactVerifier = new PactVerifier(pactConfig);
pactVerifier
.ServiceProvider(providerName, new Uri(_fakeConsumerUri))
.WithFileSource(new FileInfo(pactFile))
/* TODO: Add this back when we have Pact Broker online */
//.WithProviderStateUrl(new Uri(_pactProvStatusUrl))
.Verify();
Additionally here's the sanitized log from the provider test (below). NOTE: I modified the expected response to accept a 500 otherwise the test would fail before it even gets to the response body.
Standard Output:
Starting verification...
Pact verification failed
Verifier Output
---------------
Verifying a pact between Consumer and Provider
MyTest
Given ProviderState_MyTest
returns a response which
has status code 500 (OK)
includes headers
"Content-Type" with value "application/problem+json" (OK)
has a matching body (FAILED)
Failures:
1) Verifying a pact between Consumer and Provider Given ProviderState_MyTest - MyTest
1.1) has a matching body
$ -> Actual map is missing the following keys: Key1, Key2, Key3
There were 1 pact failures
Verifier Logs
-------------
2023-12-11T15:16:45.893247Z WARN ThreadId(01) verify_interaction{interaction="MyTest"}: reqwest::async_impl::client: rustls failed to parse DER certificate UnsupportedCriticalExtension Certificate(b"0\x82\x03\xb30\x82\x02\x9b\xa0\x03\x02\x01\x02\x02\x10\x1d\0y\x8f\xfb\xaa\xee\xadCU!{\x0f\xa8r\xa60\r\x06\t*\x86H\x86\xf7\r\x01\x01\r\x05\00K1$0\"\x06\x03U\x04\x03\x13\x1bRazer Chroma SDK Local Cert1\x0f0\r\x06\x03U\x04\x0b\x13\x06Chroma1\x120\x10\x06\x03U\x04\n\x13\tRazer Inc0\x1e\x17\r230807132647Z\x17\r240807132647Z0K1$0\"\x06\x03U\x04\x03\x13\x1bRazer Chroma SDK Local Cert1\x0f0\r\x06\x03U\x04\x0b\x13\x06Chroma1\x120\x10\x06\x03U\x04\n\x13\tRazer Inc0\x82\x01\"0\r\x06\t*\x86H\x86\xf7\r\x01\x01\x01\x05\0\x03\x82\x01\x0f\00\x82\x01\n\x02\x82\x01\x01\0\xb0PC\x98}Ir!\xa9y0h\x9d\xea\xe4\x96t\xf5at\xcaYa\xe2\xbd\x0e\xea\xdc\0\xf7\xdf1\xe8\xb4?\xcd\x81\x91\xaf(P\x11Po\x87SZZ\x99\x03\x0e\x10ke\x16\\\xdc<^m&\xa7\xa1\xad#\tU*\x81_n\x8a\xc8S\xf4^g\x81g\xbeB\xc8\xd5_bB\x8c\x0b\xca6\xbd\xf8\xaa1=1:\x04q\xb2i?\xabC\xcc\"\x11\xa8\xa0GY\xc0A\xd7\x81\xd3\xa7\xe03\xd6g\xf1Wv9\\\xe7\xba\xca9]@\xe7?\xa1\xe1\xd3\x1fy\xf5\xc5{\x16\x86 \xfb@U\xd2o\xb9\x0b\xf33\xb7\xf9\xfd\x15\x12\xfe\x8c\x18>o\x1b\x01;u\x98\xcd0\xf0of\xc1\xf4\xe7\xea_\xe8\xff\xf3S\xc6\xaft\xf4\xc5Y\x97\xb3\xc80\xcd\xc7\xa5\xb0\x04V\xf4\x9d\xbc\x95UK&\x88YE\xe0\xcbw\xc1q \xc31\xbdV\x1e\xbaJ3\n\xb8$\xaf\xec\x9c*\x15+\x8c.\x9d\x14\x86\x0ep\x94L\x95.\x99\x848\xaa\x83r\x9aP\xda/\xad\xe6I\x02\x03\x01\0\x01\xa3\x81\x920\x81\x8f0\x1d\x06\x03U\x1d\x0e\x04\x16\x04\x14'\x02\xac\xe5R\xa7|\x80\xfb~~v/\xf25]\x0eN\xcfw0\x1f\x06\x03U\x1d#\x04\x180\x16\x80\x14'\x02\xac\xe5R\xa7|\x80\xfb~~v/\xf25]\x0eN\xcfw0\x0f\x06\x03U\x1d\x13\x01\x01\xff\x04\x050\x03\x01\x01\xff0\x0e\x06\x03U\x1d\x0f\x01\x01\xff\x04\x04\x03\x02\x01\x060\x14\x06\x03U\x1d\x04\x01\x01\xff\x04\n0\x080\x020\0\x03\x02\x02\x040\x16\x06\x03U\x1d%\x01\x01\xff\x04\x0c0\n\x06\x08+\x06\x01\x05\x05\x07\x03\x010\r\x06\t*\x86H\x86\xf7\r\x01\x01\r\x05\0\x03\x82\x01\x01\0\xa9\xf6\xb1l[\xf9\xf0\xca\x99\xd2\xe6R\xb1\xe3\x86\xa0\x8c\xcb\x81\xe170\xeb2\xb7l_\xf2\x8c\x90\xfcEE6\xb4\x08&mO\x1bY\xca\xc6Y\xf3\xa9O\x90\xc4\xbf\xdc\xb8;\xc6\xac\xc1,\x94\x19\xd0\xa4\x9e\x18>\xc06\xc8#\xc9\xbcs\x1a\x08\xb8\x01\xcb\x18\x1bG\xa6S\xd4U\x10C\xc0waq\x83}\xf3\x11*\xb8\xd8\xdf\x7f\x02UJ0\xde\n\xea\xbf\xa6\xb8N\x11\x8b4Bu\xe8\xc8\x8d\x8e\xac`\x96\x9d\xbd\x1c\xb9\x02\x9e\xf1\x86\xdc|y\xe8ep\xe8\xb6x}\xd5$n\x1e\x9e\xcc\x99:\xde\xbb\xa8S`o\x91M\xf0&C\x0e\\\x8e\x85\x1f\xb6\x95\x0f\x9a\xfe\xc6\x182\xe28g\xb7\xcd\x8a,c\x19\x1c\x97\xb4\xb2%\xb1\x0b*\x0c\x85(\xc9\xf9=\xa2\xf7\x17\xcd,%\xd3X\x8a\x92\x1e\xfaP\x9a\"\xdb\xaew\xaal\x81S\x9e\xe7KXA\x9c\x10D\xcbH\x8bA\x88\x16\xf8nOk=\xf7\x90\x83~;\x8c\xe9\xdd\x11>\xedD`\xd4\xa6E\xd2\x94L(:")
2023-12-11T15:16:45.893322Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier: Executing provider states
2023-12-11T15:16:45.893332Z INFO ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier: Running setup provider state change handler 'ProviderState_MyTest' for 'MyTest'
2023-12-11T15:16:45.893339Z WARN ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier::callback_executors: State Change ignored as there is no state change URL provided for interaction
2023-12-11T15:16:45.893342Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier: State Change: "ProviderState { name: "ProviderState_MyTest", params: {} }" -> Ok({})
2023-12-11T15:16:45.893351Z INFO ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier: Running provider verification for 'MyTest'
2023-12-11T15:16:45.893375Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier: Verifying a HTTP interaction
2023-12-11T15:16:45.893392Z INFO ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier::provider_client: Sending request to provider at http://127.0.0.1:59999/
2023-12-11T15:16:45.893394Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier::provider_client: Provider details = ProviderInfo { name: "Provider", protocol: "http", host: "127.0.0.1", port: Some(59999), path: "/", transports: [ProviderTransport { transport: "http", port: Some(59999), path: Some("/"), scheme: None }] }
2023-12-11T15:16:45.893401Z INFO ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier::provider_client: Sending request HTTP Request ( method: PUT, path: /my/path, query: None, headers: Some({"content-length": ["188"], "Content-Type": ["application/json; charset=utf-8"]}), body: Present(188 bytes) )
2023-12-11T15:16:45.893412Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier::provider_client: body:
7B22417474656D70744E756D626572223A312C2243616C6C6261636B54797065... (188 bytes)
2023-12-11T15:16:45.893511Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: reqwest::connect: starting new connection: http://127.0.0.1:59999/
2023-12-11T15:16:45.893542Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: hyper::client::connect::http: connecting to 127.0.0.1:59999
2023-12-11T15:16:45.893909Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: hyper::client::connect::http: connected to 127.0.0.1:59999
2023-12-11T15:16:45.968023Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier::provider_client: Received native response: Response { url: Url { scheme: "http", cannot_be_a_base: false, username: "", password: None, host: Some(Ipv4(127.0.0.1)), port: Some(59999), path: "/my/path", query: None, fragment: None }, status: 500, headers: {"content-type": "application/problem+json", "date": "Mon, 11 Dec 2023 15:16:45 GMT", "server": "Kestrel", "cache-control": "no-cache,no-store", "expires": "-1", "pragma": "no-cache", "transfer-encoding": "chunked"} }
2023-12-11T15:16:45.968165Z INFO ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier::provider_client: Received response: HTTP Response ( status: 500, headers: Some({"cache-control": ["no-cache", "no-store"], "content-type": ["application/problem+json"], "date": ["Mon", "11 Dec 2023 15:16:45 GMT"], "pragma": ["no-cache"], "expires": ["-1"], "transfer-encoding": ["chunked"], "server": ["Kestrel"]}), body: Present(207 bytes, application/problem+json) )
2023-12-11T15:16:45.968176Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_verifier::provider_client: body:
{
"status": 500,
"title": "InternalServerError",
"detail": "The operation has failed. Please try again later, and contact support if the problem persists.",
"traceId": "0HMVQBGO6CSRO:00000001"
}
2023-12-11T15:16:45.968186Z INFO ThreadId(01) verify_interaction{interaction="MyTest"}: pact_matching: comparing to expected response: HTTP Response ( status: 500, headers: Some({"Content-Type": ["application/problem+json"]}), body: Present(78 bytes) )
2023-12-11T15:16:45.968205Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_matching: expected content type = 'application/problem+json', actual content type = 'application/problem+json'
2023-12-11T15:16:45.968848Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_matching: content type header matcher = 'RuleList { rules: [], rule_logic: And, cascaded: false }'
2023-12-11T15:16:45.968862Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_plugin_driver::catalogue_manager: Looking for a content matcher for application/problem+json
2023-12-11T15:16:45.969069Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_matching: No content matcher defined for content type 'application/problem+json', using core matcher implementation
2023-12-11T15:16:45.969075Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_matching: Using body matcher for content type 'application/problem+json'
2023-12-11T15:16:45.969091Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_matching::json: compare: Comparing path $
2023-12-11T15:16:45.969095Z DEBUG ThreadId(01) verify_interaction{interaction="MyTest"}: pact_matching::json: compare_maps: Comparing maps at $: {"Key1": Number(1), "Key2": Object {"Prop1": String("stringValue")}, "Key3": String("stringValue")} -> {"detail": String("The operation has failed. Please try again later, and contact support if the problem persists."), "status": Number(500), "title": String("InternalServerError"), "traceId": String("0HMVQBGO6CSRO:00000001")}
Finally, here are the debug logs from Kestrel and .Net. I don't know what the expected log messages should be but I see a NullRefereneException after the routing was confirmed...
Microsoft.Extensions.Hosting.Internal.Host: Debug: Hosting starting
Microsoft.Hosting.Lifetime: Information: Now listening on: http://127.0.0.1:59999
Microsoft.AspNetCore.Hosting.Diagnostics: Debug: Loaded hosting startup assembly WebApi
Microsoft.Hosting.Lifetime: Information: Application started. Press Ctrl+C to shut down.
Microsoft.Hosting.Lifetime: Information: Hosting environment: Local
Microsoft.Hosting.Lifetime: Information: Content root path: C:\source\path\source\WebApi.Pact.Tests\bin\Debug\net7.0
Microsoft.Extensions.Hosting.Internal.Host: Debug: Hosting started
Microsoft.AspNetCore.Server.Kestrel.Connections: Debug: Connection id "0HMVRBISBFAHD" accepted.
Microsoft.AspNetCore.Server.Kestrel.Connections: Debug: Connection id "0HMVRBISBFAHD" started.
Microsoft.AspNetCore.Hosting.Diagnostics: Information: Request starting HTTP/1.1 PUT http://127.0.0.1:59999/my/path application/json;+charset=utf-8 188
Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware: Debug: Wildcard detected, all requests with hosts will be allowed.
Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware: Trace: All hosts are allowed.
Microsoft.AspNetCore.Routing.Matching.DfaMatcher: Debug: 1 candidate(s) found for the request path '/my/path'
Microsoft.AspNetCore.Routing.Matching.DfaMatcher: Debug: Endpoint 'WebApi.Controllers.Controller.PutAsync (WebApi)' with route pattern 'my/path' is valid for the request path '/my/path'
Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware: Debug: Request matched endpoint 'WebApi.Controllers.Controller.PutAsync (WebApi)'
Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware: Error: An unhandled exception has occurred while executing the request.
System.NullReferenceException: Object reference not set to an instance of an object.
at NWebsec.AspNetCore.Middleware.Middleware.CspMiddleware.SetCspHeaders(HttpContext context)
at NWebsec.AspNetCore.Middleware.Middleware.CspMiddleware.Invoke(HttpContext context)
at NWebsec.AspNetCore.Middleware.Middleware.MiddlewareBase.Invoke(HttpContext context)
at NWebsec.AspNetCore.Middleware.Middleware.MiddlewareBase.Invoke(HttpContext context)
at NWebsec.AspNetCore.Middleware.Middleware.MiddlewareBase.Invoke(HttpContext context)
at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.<Invoke>g__Awaited|8_0(ExceptionHandlerMiddlewareImpl middleware, HttpContext context, Task task)
Microsoft.AspNetCore.Server.Kestrel.Connections: Debug: Connection id "0HMVRBISBFAHD" completed keep alive response.
Microsoft.AspNetCore.Hosting.Diagnostics: Information: Request finished HTTP/1.1 PUT http://127.0.0.1:59999/my/path application/json;+charset=utf-8 188 - 500 - application/problem+json 61.4822ms
Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets: Debug: Connection id "0HMVRBISBFAHD" received FIN.
Microsoft.AspNetCore.Server.Kestrel: Debug: Connection id "0HMVRBISBFAHD", Request id "0HMVRBISBFAHD:00000001": started reading request body.
Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets: Debug: Connection id "0HMVRBISBFAHD" sending FIN because: "The Socket transport's send loop completed gracefully."
Microsoft.AspNetCore.Server.Kestrel.Connections: Debug: Connection id "0HMVRBISBFAHD" disconnecting.
Microsoft.AspNetCore.Server.Kestrel.BadRequests: Debug: Connection id "0HMVRBISBFAHD" bad request data: "Unexpected end of request content."
Microsoft.AspNetCore.Server.Kestrel.Core.BadHttpRequestException: Unexpected end of request content.
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1ContentLengthMessageBody.TryReadInternal(ReadResult& readResult)
at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.Http1MessageBody.OnConsumeAsync()
Microsoft.AspNetCore.Server.Kestrel: Debug: Connection id "0HMVRBISBFAHD", Request id "0HMVRBISBFAHD:00000001": done reading request body.
Microsoft.AspNetCore.Server.Kestrel.Connections: Debug: Connection id "0HMVRBISBFAHD" stopped.
Exception thrown: 'PactNet.Exceptions.PactFailureException' in PactNet.dll
Exception thrown: 'Xunit.Sdk.FailException' in xunit.assert.dll