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

concurrency issue / race condition #975

Open
Darkvater opened this issue Dec 21, 2023 · 4 comments
Open

concurrency issue / race condition #975

Darkvater opened this issue Dec 21, 2023 · 4 comments
Labels
BUG

Comments

@Darkvater
Copy link

Darkvater commented Dec 21, 2023 •
edited

Hi,

I've been investigating strange behaviour in wiremock (see wiremock/wiremock#706 (comment)) and over the course of several days narrowed the issue down to a race condition in json-path. While I am still trying to pin down the exact culprit please find my findings below. Maybe someone with intimate knowledge of the library can see immediately what is wrong which would save me a lot of time.

  • version used: json-path 2.8.0 (but json-path 2.7.0 exhibits the same behaviour)
  • issue: JsonPath.read(<<json>>, "concat($.keys())") returns the keys from a json called in a different thread

log and explanation

  • I have annotated certain classes with logging.
  • the log format is [<thread-id> - <class-instance-hash>] <class-name>::<method> ... parameters of interest]
  • I have simplified the log here a bit to give the same simple name to all objects that are the same. So everywhere you see <<BODY>> it means the same JSON payload; everywhere you see <<CONFIG>> it is the same object instance.
  • you can see from the log there is a recursive call here to evaluate $.keys and then concat()
  • somewhere after correctly evaluating $.keys to "transactionId-ZFOr/PRIIPS" the result of EvaluationContext::addResult on concat() is suddenly "transactionId-ZFOr/MIFID" which is another call. You can see this between the section highlighted in -----
  • EVALUATIONCONTEXTIMPL::addResult-1 is on calling addResult method
  • EVALUATIONCONTEXTIMPL::addResult-2 is after adding valueResult in addResult
  • EVALUATIONCONTEXTIMPL::addResult-3 is after adding pathResult in addResult

notes

  • I'm adding some more logging to check evaluation context's valueResult and indexes there, but each run takes a while as it really only happens occasionally, and even less so with the extra logging added
[qtp1615908941-218 - <<JSON_PATH_1>>]          JSONPATH::read jsonObject: <<BODY>>, configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>

[qtp1615908941-218 - <<COMPILED_PATH_1>>]      COMPILEDPATH::evaluate-1.0 document: <<BODY>>, rootDocument: <<BODY>>, configuration: <<CONFIG>>
[qtp1615908941-218 - <<COMPILED_PATH_1>>]      COMPILEDPATH::evaluate-2.0 path: $.concat(...), document: <<BODY>>, rootDocument: <<BODY>>, configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<COMPILED_PATH_1>>]      COMPILEDPATH::evaluate-2.1 ctx: <<EVALUATIONCTX>>, path: $.concat(...), configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<COMPILED_PATH_2>>]      COMPILEDPATH::evaluate-1.0 document: <<BODY>>, rootDocument: <<BODY>>, configuration: <<CONFIG>>
[qtp1615908941-218 - <<COMPILED_PATH_2>>]      COMPILEDPATH::evaluate-2.0 path: $.keys(), document: <<BODY>>, rootDocument: <<BODY>>, configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<COMPILED_PATH_2>>]      COMPILEDPATH::evaluate-2.1 ctx: <<EVALUATIONCTX_2>>, path: $.keys(), configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<EVALUATION_CONTEXT_1>>] EVALUATIONCONTEXTIMPL::addResult-1 path: $.keys, model: [transactionId-ZFOr/PRIIPS], configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<EVALUATION_CONTEXT_1>>] EVALUATIONCONTEXTIMPL::addResult-2 valueResult: [[transactionId-ZFOr/PRIIPS]], resultIndex: 0, configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<EVALUATION_CONTEXT_1>>] EVALUATIONCONTEXTIMPL::addResult-3 valueResult: [[transactionId-ZFOr/PRIIPS]], resultIndex: 0, configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<COMPILED_PATH_2>>]      COMPILEDPATH::evaluate-2.2 ctx: <<EVALUATIONCTX_2>>, path: $.keys(), configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<COMPILED_PATH_2>>]      COMPILEDPATH::evaluate-2.4 ctx: <<EVALUATIONCTX_2>>, path: $.keys(), configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<COMPILED_PATH_2>>]      COMPILEDPATH::evaluate-1.1 result: <<EVALUATIONCTX_2>>, document: <<BODY>>, rootDocument: <<BODY>>, configuration: <<CONFIG>>
[qtp1615908941-218 - <<EVALUATION_CONTEXT_1>>] EVALUATIONCONTEXTIMPL::getValue-1.1 value: [transactionId-ZFOr/PRIIPS], unwrap: true
[qtp1615908941-218 - <<EVALUATION_CONTEXT_1>>] EVALUATIONCONTEXTIMPL::getValue-1.2 result: [transactionId-ZFOr/PRIIPS], unwrap: true
--------------------------------------------------------------------------------------------------------------------------------------------
[qtp1615908941-218 - <<EVALUATION_CONTEXT_2>>] EVALUATIONCONTEXTIMPL::addResult-1 path: $.concat, model: [transactionId-ZFOr/MIFID], configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<EVALUATION_CONTEXT_2>>] EVALUATIONCONTEXTIMPL::addResult-2 valueResult: [[transactionId-ZFOr/MIFID]], resultIndex: 0, configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<EVALUATION_CONTEXT_2>>] EVALUATIONCONTEXTIMPL::addResult-3 valueResult: [[transactionId-ZFOr/MIFID]], resultIndex: 0, configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<COMPILED_PATH_1>>]      COMPILEDPATH::evaluate-2.2 ctx: <<EVALUATIONCTX>>, path: $.concat(...), configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<COMPILED_PATH_1>>]      COMPILEDPATH::evaluate-2.4 ctx: <<EVALUATIONCTX>>, path: $.concat(...), configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - <<COMPILED_PATH_1>>]      COMPILEDPATH::evaluate-1.1 result: <<EVALUATIONCTX>>, document: <<BODY>>, rootDocument: <<BODY>>, configuration: <<CONFIG>>
[qtp1615908941-218 - <<EVALUATION_CONTEXT_2>>] EVALUATIONCONTEXTIMPL::getValue-1.1 value: [transactionId-ZFOr/MIFID], unwrap: true
[qtp1615908941-218 - <<EVALUATION_CONTEXT_2>>] EVALUATIONCONTEXTIMPL::getValue-1.2 result: [transactionId-ZFOr/MIFID], unwrap: true
 --------------------------------------------------------------------------------------------------------------------------------------------

[qtp1615908941-218 - <<JSON_PATH_1>>]          JSONPATH::read-3 result: [transactionId-ZFOr/MIFID], jsonObject: <<BODY>>, configuration: <<CONFIG>>, jsonProvider: <<JSONPROVIDER>>
[qtp1615908941-218 - 1482307509] JSONPROVIDER::parse json: <<BODY>>
@Darkvater
Copy link
Author

I did more investigation today and can quite confidently say that the problem is caused by the LRUCache used for the paths. It's not really the cache which is at fault but CompiledPath which has volatile state.

When the cache value is reused between threads it means you have the same CompiledPath but also the same FunctionPathToken which contains the parameters that holds the state of the current evaluation. You cannot share this between threads.

The issue is resolved when cache is turned off (with NOOPCache).
I can provide logs that prove this. Unfortunately I have no solution for the fix as it's very deep and complex within the library. I think the fix should be to just pass everything around and remove the state.

@Darkvater Darkvater mentioned this issue Dec 22, 2023
Closed
@dlehammer
Copy link

Seems related to #974 🤔

@He-Pin
Copy link

He-Pin commented Apr 28, 2024 •
edited

@Darkvater How about replacing the Cache with one backing by guava/caffeine?

@Darkvater
Copy link
Author

The problem is not with the caching library but the way it is used. No other cache engine can help here, the problem is a lot deeper.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
BUG
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@kallestenflo @He-Pin @Darkvater @dlehammer