Similar requests are not matched

[dzyanis]

I use WireMock c 2.6.0 and I get this strange exception all the time:

com.github.tomakehurst.wiremock.client.VerificationException:`
No requests exactly matched. Most similar request was: expected:<
DELETE
/foo/bar?name=Dan&id=uniqId> but was:<
DELETE
/foo/bar?name=Dan&id=uniqId>

I've checked a lot of ways but nothing helps.
My code looks like:

stubFor(delete(urlMatching(".")))
executeRequest()
verify(deleteRequestedFor(urlMatching(s"/foo/bar.")))

And I suppose that it's a bug.
Correct me if I'm wrong

[tomakehurst]

Could you post the details of the request you're making in executeRequest()?

[jsalinaspolo]

@dzyanis I think you were trying to verify with the wrong regular expression.

I suppose executeRequest is calling "/foo/bar?name=Dan&id=uniqId"

and the verify is only accepting a character but not any character. Should be "." instead of ".*"
verify(deleteRequestedFor(urlMatching(s"/foo/bar.")))
so the verify should looks like
verify(deleteRequestedFor(urlMatching(s"/foo/bar.*")))

[gustavotemple]

Today I had this error, in my case it was because I am using cache (akka.http.caching), therefore, instead of my GET request being completed, the value came from the cache and the error occurred. To fix it, I cleared the cache before testing.

[L-G-v1]

I have exactly the same error: https://stackoverflow.com/questions/59768415/wiremock-behaves-weird-sometime . Is there any kind of update here ?

[Amitercse]

@tomakehurst Any update on this issue. I am also facing similar issue and more surprisingly same code is working on different machine but not on my machine.

[dzyanis]

totally forgot about this issue and I don't remember how I fixed that. By the way, there is no bug. It was something wrong or with the version or with the order.

[L-G-v1]

By the way, this is totally a BUG(we've tried it with multiple WireMock solutions)! My team has struggle with it for months..Our investigations leads to the fact that the tests run before the stubs register. So the only solution was to wait for that registering, but definitely there should something out there that handle these things behind the scene. Here you can check what we did: https://stackoverflow.com/questions/59768415/wiremock-behaves-weird-sometime . It's hacky , but at least we're all having green builds

[tomakehurst]

I don't think this is a WireMock bug. Stubs are registered synchronously so there shouldn't ever be a need to wait for them to become registered unless your app or framework is introducing its own asynchronicity.

What I suggest is that you try to replicate this in a test case that uses WireMock directly, removing Spring etc. and if the problem persists then open a new issue and share the full details of how to reproduce.

[L-G-v1]

Yeah, I guess you're right about introducing its own asynchronicity. We're also using spring-react, so probably this adds it. So in our case it was really interesting, the Integration tests pack increase with time and everything worked as expected but starting with a point, some integration tests failed randomly. So this was ultimately our last solutions to wait for those subs.

You can imagine that from a point in which the service has hundreds of integration tests it's really painful to investigate or to get rid of some spring dependencies..

Anyway thanks for your support, I didn't have these kinds of problem when I used it in the past with a spring-mvc framework integrated. Cheers

[r00ta]

@tomakehurst @brebDevv
We faced the same issue and we found it was a concurrency problem in our test. You can have a look here if you like 5733d9e2be6485d52ffa08870cabdee0/sandbox#64 . To keep it short:

1. we had a service that was making 4 async PUT requests to a server
2. the test was only waiting for 2 PUT requests to be received before asserting that a particular PUT request was made
3. If the expected request was not within the first two and it was not received by the mock before the verify, it was failing
4. the misleding thing is that the expected request was received by the mock before the new VerificationException was build, so in the error message we had a perfect match between the expected payload and the received one.

[rob-h-w]

Bumping this because I see the same issue. The verification message is effectively expected: "X", but was: "X". It's pretty confusing.

[tomakehurst]

@rob-h-w please could you provide full details of how to replicate the issue you've seen?

[L-G-v1]

Hi all. It's quite hard to replicate the issue, especially since it was failing randomly in our case(especially if your testing an asynchronous environment, as ours ). The only solution found by our team was this one: https://stackoverflow.com/questions/59768415/wiremock-behaves-weird-sometime

@rob-h-w Please take a look at the solution comment.

[Darkvater]

This is definitely an issue and I am quite certain it is a bug too. We are struggling with exactly the same thing and I've spent the last few days trying to pin it down. Acceptance tests fail occasionally, for example running 3.2k tests 150 times fails about 6 tests. So not very often, but it's definitely there.

This is what I have found so far, hopefully someone more knowledgeable than me on Wiremock can use these hints.

• version used: 2.35.0, 2.35.1 (com.github.tomakehurst:wiremock-jre8) but also 3.3.1 (org.wiremock:wiremock)
• app server: Quarkus 3.1.0.Final with vertx reactive webclient
• jvm: kotlin 1.8.10

I've logged the be-jezus out of wiremock, overriding custom matchers to be able to log, and can see that sometimes the wrong body is passed to the request matchers. I am expecting to match a certain JSON pattern from the body against the setup stubs. That stub - which exists - is never executed against the request sent down (transactionId-LS63/FIDLEG) but against another request (some-ska/SOS); highlighted between >>>> x <<<<.

The request body is read in RequestPattern::allBodyPatternsMatch and consumed by WireMockHttpServletRequestAdapter::getBody where I think some concurrency issues exist that sometimes provide the wrong (cached?) body.

Now the most interesting bit is that if in BEFORE_MATCH event I filter the stubs and actually log the relevant ones, the test is rock-stable. Obviously the timings have changed, or something has been triggered.

I hope this helps!

The relevant logs are below.

[qtp723166096-180 com.github.tomakehurst.wiremock.stubbing.ServeEvent@1bde2db0/BEFORE_MATCH] request: {
  "url" : "/api/calculate",
  "absoluteUrl" : http://localhost:8988/api/calculate,
  "method" : "POST",
  "clientIp" : "127.0.0.1",
  "headers" : {
    "User-Agent" : "Vert.x-WebClient/4.4.2",
    "Content-Type" : "application/json",
    "Content-Length" : "457",
    "Host" : "localhost:8988",
    "traceparent" : "00-d60401f12ad30a6fa207c68d5ccc1d32-e3bd53b23b717514-01",
    "X-B3-TraceId" : "d60401f12ad30a6fa207c68d5ccc1d32",
    "X-B3-SpanId" : "e3bd53b23b717514",
    "X-B3-Sampled" : "1"
  },
  "cookies" : { },
  "browserProxyRequest" : false,
  "loggedDate" : 1702659310937,
  "bodyAsBase64" : "",
  "body" : "{\"transactionId-LS63/FIDLEG\":{\"requestId\":\"bfd3b2bc-a57d-41a4-8ab5-94bc8ea1f13b}}",
  "protocol" : "HTTP/1.1",
  "scheme" : "http",
  "host" : "localhost",
  "port" : 8988,
  "loggedDateString" : "2023-12-15T16:55:10.937Z",
  "queryParams" : { },
  "formParams" : { }
} / response: null / stubMapping: null
>>>>> [qtp723166096-180] PATTERN match (com.csg.cs.gts.compliance.documents.calculation.FetchListedRegulatoryDocumentCalculation$FIDLEG@2636bb7c - 180b3cd5-4936-4698-b659-80ab0599913d): (FIDLEG): [some-ska/SOS] <<<<<
[qtp723166096-180] PATTERN match (com.csg.cs.gts.compliance.documents.calculation.FetchListedRegulatoryDocumentCalculation$UCITS_UK@30ec45e9 - 6596e589-b955-4aca-a2ea-26c64cf37b8e): (UCITS_UK): [transactionId-LS63/FIDLEG]
[qtp723166096-180] PATTERN match (com.csg.cs.gts.compliance.documents.calculation.FetchListedRegulatoryDocumentCalculation$UCITS_PRO@6fae9f39 - b855f9e8-b3ba-412b-beae-33446595485f): (UCITS): [transactionId-LS63/FIDLEG]
[qtp723166096-180] PATTERN match (com.csg.cs.gts.compliance.documents.calculation.FetchListedRegulatoryDocumentCalculation$UCITS_EU@699148d7 - d2ac5e39-39ba-454b-be3c-7a229e5817ce): (UCITS): [transactionId-LS63/FIDLEG]
[qtp723166096-180] PATTERN match (com.csg.cs.gts.compliance.documents.calculation.FetchListedRegulatoryDocumentCalculation$PRIIPS_UK@7861b7e0 - 312259ae-3374-4826-a3e7-c086ccefed2c): (PRIIPS_UK): [transactionId-LS63/FIDLEG]
[qtp723166096-180] PATTERN match (com.csg.cs.gts.compliance.documents.calculation.FetchListedRegulatoryDocumentCalculation$PRIIPS_EU@3d7abcbd - ecf1c26a-f984-457e-8284-8b160d420e43): (PRIIPS): [transactionId-LS63/FIDLEG]
[qtp723166096-180 com.github.tomakehurst.wiremock.stubbing.ServeEvent@57822f50/AFTER_MATCH] request: {
  "url" : "/api/calculate",
 "absoluteUrl" : http://localhost:8988/api/calculate,
  "method" : "POST",
  "clientIp" : "127.0.0.1",
  "headers" : {
    "User-Agent" : "Vert.x-WebClient/4.4.2",
    "Content-Type" : "application/json",
    "Content-Length" : "457",
    "Host" : "localhost:8988",
    "traceparent" : "00-d60401f12ad30a6fa207c68d5ccc1d32-e3bd53b23b717514-01",
    "X-B3-TraceId" : "d60401f12ad30a6fa207c68d5ccc1d32",
    "X-B3-SpanId" : "e3bd53b23b717514",
    "X-B3-Sampled" : "1"
  },
  "cookies" : { },
  "browserProxyRequest" : false,
  "loggedDate" : 1702659310937,
  "bodyAsBase64" : "xxx",
  "body" : "{\"transactionId-LS63/FIDLEG\":{\"requestId\":\"bfd3b2bc-a57d-41a4-8ab5-94bc8ea1f13b}}",
  "protocol" : "HTTP/1.1",
  "scheme" : "http",
  "host" : "localhost",
  "port" : 8988,
  "loggedDateString" : "2023-12-15T16:55:10.937Z",
  "queryParams" : { },
  "formParams" : { }
} / response: (no response definition configured) / stubMapping: {
  "id" : "4df86ac9-3c39-402f-b69c-40fc46e6b6d4",
  "request" : {
    "method" : "ANY"
  },
  "response" : {
    "status" : 404,
    "fromConfiguredStub" : false
  },
  "uuid" : "4df86ac9-3c39-402f-b69c-40fc46e6b6d4"
}
[qtp723166096-180] console notification logger (# of mappings: 22 (-1014077506) Request received:
127.0.0.1 - POST /api/calculate
User-Agent: [Vert.x-WebClient/4.4.2]
Content-Type: [application/json]
Content-Length: [457]
Host: [localhost:8988]
traceparent: [00-d60401f12ad30a6fa207c68d5ccc1d32-e3bd53b23b717514-01]
X-B3-TraceId: [d60401f12ad30a6fa207c68d5ccc1d32]
X-B3-SpanId: [e3bd53b23b717514]
X-B3-Sampled: [1]
{"transactionId-LS63/FIDLEG":{"requestId":"bfd3b2bc-a57d-41a4-8ab5-94bc8ea1f13b"}}

Matched response definition:
(no response definition configured)

Response:
HTTP/1.1 404
(no headers)

[tomakehurst]

Thanks for reporting @Darkvater, but I don't think there's much we can do without a bit more information. Please could you share a repro project and your full startup/config settings?

[Darkvater]

Sorry, can't as it's an internal project. There is nothing special in the server setup; global transformer.is enabled, that's it. I'll try and investigate a bit more around the reading of the response body.

[Darkvater]

Okay, I have found the culprit, at least in my case. It's json-path or its json provider having a concurrency issue.
The logs show that for the same json body JsonPath.read(value, expectedValue) in MatchesJsonPathPattern::getExpressionResult returns a wrong value (MIFID) while it should return PRIIPS as returned by Jackson objectmapper (which I hacked into the code as reference). Looks like it might be due to something in json-path-(2.8.0)

[qtp1597441511-250 - 909308825] MATCH body: <some-body>
[qtp1597441511-250 - 909308825] ISADVANCEDMATCH body: <some-body>
[qtp1597441511-250 - 909308825] GETEXPRESSIONRESULT expectedValue: concat($.keys()), body: <some-body>
[qtp1597441511-250 - 909308825] - GETEXPRESSIONRESULT objectmapper: [transactionId-Lr27/PRIIPS]
----------------------------------------------------------------------------------------------------------------
[qtp1597441511-250 - 909308825] - GETEXPRESSIONRESULT obj: [transactionId-Lr27/MIFID], expectedValue: concat($.keys()), value: <some-body>
[qtp1597441511-250 - 909308825] - GETEXPRESSIONRESULT obj(string): [transactionId-Lr27/MIFID], expectedValue: concat($.keys()), value: <some-body>
[qtp1597441511-250 - 709664492] PATTERN (PRIIPS): [transactionId-Lr27/MIFID]
----------------------------------------------------------------------------------------------------------------
[qtp1597441511-250 - 709664492] PATTERN is-match false
[qtp1597441511-250 - 909308825] ISADVANCEDMATCH result: false, body: <some-body>
[qtp1597441511-250 - 909308825] MATCH result: false, body: <some-body>

in the logs the first value is the thread id, the second is the object hash code.

[tomakehurst]

Thanks for sharing this discovery @Darkvater !

[Darkvater]

For anyone having an issue with wiremock flakyness and using json matchers (at least up to and including json-path-2.8.0): turn off JSONPath cache which will "solve" the problem at least until a proper solution is in place. You can do this by adding the below code in some static initialiser: com.jayway.jsonpath.spi.cache.CacheProvider.setCache(new NOOPCache());

See json-path/JsonPath#975 (comment) for details.

[tomakehurst]

@Darkvater would you mind raising a PR to turn this off in WireMock (at least until it gets fixed upstream)?

[tomakehurst]

@Darkvater JSONPath caching disabled in 0be7371