search

JasperFx / wolverine

Supercharged .NET server side development!
https://wolverinefx.net
MIT License
1.18k stars 130 forks source link

In Memory Queues don't seem to work when IDocumentSession is injected into EndPoint's method #536

Closed JoshuaNitschke closed 10 months ago

JoshuaNitschke commented 11 months ago

STEPS TO REPRODUCE 1) Clone https://github.com/JoshuaNitschke/wolverine-issue-reproduction 2) Add postgres database as a user secret 2) Start the web api 3) Use the swagger page to execute all four end points

RESULT The handlers for the first two endpoints will not execute (as determined by the handlers never firing logs nor hitting break points when running in debug mode). However, the second two endpoints work just fine. The only difference between the first set of endpoints and the second is that the first two have an unused dependency injected IDocumentSession session, which I wouldn't expect to affect the message bus behavior.

No Wolverine extensions are detected
info: Wolverine.Runtime.WolverineRuntime[0]
      Exporting Open Telemetry metrics from Wolverine with name Wolverine:WolverineIssueReproduction.WebApi, version 1.6.1.0

info: Wolverine.Runtime.WolverineRuntime[0]
      Starting Wolverine messaging for application assembly WolverineIssueReproduction.Application, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
info: Wolverine.Configuration.HandlerDiscovery[0]
      Searching assembly WolverineIssueReproduction.WebApi, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null for Wolverine message handlers
info: Wolverine.Configuration.HandlerDiscovery[0]
      Searching assembly WolverineIssueReproduction.Application, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null for Wolverine message handlers
info: Wolverine.Transports.ListeningAgent[0]
      Started message listening at dbcontrol://76b2943d-c3ab-437d-89d6-e0b21b42203a/
info: Wolverine.Runtime.Agents.NodeAgentController[0]
      Starting agents for Node 76b2943d-c3ab-437d-89d6-e0b21b42203a with assigned node id 45
info: Wolverine.Runtime.Agents.NodeAgentController[0]
      Found no elected leader on node startup, requesting node 7395fdbe-ea92-410c-952d-0c77c493ad39 to be the new leader
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: http://localhost:5210
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: D:\GIT\wolverine-issue-reproduction\src\WolverineIssueReproduction.WebApi
info: WolverineIssueReproduction.Application.LogCommandHandler[0]
      I always log!
info: WolverineIssueReproduction.Application.LogCommand[104]
      Successfully processed message WolverineIssueReproduction.Application.LogCommand#018a7647-7979-441c-ae40-4d9faede113e from local://wolverineissuereproduction.application.logcommand/
info: WolverineIssueReproduction.Application.Sagas.TestSaga[0]
      Got a new request with id 99f4c065-a617-4ea2-88a0-6a69d939b2c1 and I always start
info: WolverineIssueReproduction.Application.Sagas.StartTest[104]
      Successfully processed message WolverineIssueReproduction.Application.Sagas.StartTest#018a7647-8aa7-4bfd-94cb-91d0436d6808 from local://wolverineissuereproduction.application.sagas.starttest/
info: WolverineIssueReproduction.Application.Sagas.TestSaga[0]
      Saga 99f4c065-a617-4ea2-88a0-6a69d939b2c1 TIMEOUT OUT - MARKING COMPLETE
info: WolverineIssueReproduction.Application.Sagas.TestTimeout[104]
      Successfully processed message WolverineIssueReproduction.Application.Sagas.TestTimeout#018a7647-8b91-4c40-8f54-a0c0611ea433 from local://wolverineissuereproduction.application.sagas.testtimeout/

EXPECTED RESULT: 1) The first two endpoints should behave exactly the same as the last two endpoints with log messages showing messages received, and handled as they do when opts.Policies.UseDurableLocalQueues() is set (output when enabled pictured below)

Now, uncomment opts.Policies.UseDurableLocalQueues(); and verify that logs show the handlers execute all four times - I would expect the same result for the in memory bus.

No Wolverine extensions are detected
info: Wolverine.Runtime.WolverineRuntime[0]
      Exporting Open Telemetry metrics from Wolverine with name Wolverine:WolverineIssueReproduction.WebApi, version 1.6.1.0

info: Wolverine.Runtime.WolverineRuntime[0]
      Starting Wolverine messaging for application assembly WolverineIssueReproduction.Application, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
info: Wolverine.Configuration.HandlerDiscovery[0]
      Searching assembly WolverineIssueReproduction.WebApi, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null for Wolverine message handlers
info: Wolverine.Configuration.HandlerDiscovery[0]
      Searching assembly WolverineIssueReproduction.Application, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null for Wolverine message handlers
info: Wolverine.Transports.ListeningAgent[0]
      Started message listening at dbcontrol://4b00e0db-a488-4033-a744-87531ccdd41f/
info: Wolverine.Runtime.Agents.NodeAgentController[0]
      Starting agents for Node 4b00e0db-a488-4033-a744-87531ccdd41f with assigned node id 44
info: Wolverine.Runtime.Agents.NodeAgentController[0]
      Found no elected leader on node startup, requesting node 7395fdbe-ea92-410c-952d-0c77c493ad39 to be the new leader
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: http://localhost:5210
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: D:\GIT\wolverine-issue-reproduction\src\WolverineIssueReproduction.WebApi
info: WolverineIssueReproduction.Application.LogCommandHandler[0]
      I won't log without durable queues!
info: WolverineIssueReproduction.Application.LogCommand[104]
      Successfully processed message WolverineIssueReproduction.Application.LogCommand#018a7642-f6e0-428d-a5a0-633ac533a8a2 from local://wolverineissuereproduction.application.logcommand/
info: WolverineIssueReproduction.Application.Sagas.TestSaga[0]
      Got a new request with id 1b834c19-3934-4079-9789-6eabe09cf2ac and I won't start without a durable queue
info: WolverineIssueReproduction.Application.Sagas.StartTest[104]
      Successfully processed message WolverineIssueReproduction.Application.Sagas.StartTest#018a7643-08a6-4fa3-bd6d-33b39dfc95fb from local://wolverineissuereproduction.application.sagas.starttest/
info: Wolverine.Runtime.WolverineRuntime[0]
      Locally enqueuing scheduled message 018a7643-0a36-48f7-a66d-77b54846acf7 of type WolverineIssueReproduction.Application.Sagas.TestTimeout
info: WolverineIssueReproduction.Application.Sagas.TestSaga[0]
      Saga 1b834c19-3934-4079-9789-6eabe09cf2ac TIMEOUT OUT - MARKING COMPLETE
info: WolverineIssueReproduction.Application.Sagas.TestTimeout[104]
      Successfully processed message WolverineIssueReproduction.Application.Sagas.TestTimeout#018a7643-0a36-48f7-a66d-77b54846acf7 from local://wolverineissuereproduction.application.sagas.testtimeout/
info: WolverineIssueReproduction.Application.LogCommandHandler[0]
      I always log!
info: WolverineIssueReproduction.Application.LogCommand[104]
      Successfully processed message WolverineIssueReproduction.Application.LogCommand#018a7643-345c-43a3-854a-797a93ea8d0f from local://wolverineissuereproduction.application.logcommand/
info: WolverineIssueReproduction.Application.Sagas.TestSaga[0]
      Got a new request with id 83c3d69c-38b6-411d-95a4-e452c524b45a and I always start
info: WolverineIssueReproduction.Application.Sagas.StartTest[104]
      Successfully processed message WolverineIssueReproduction.Application.Sagas.StartTest#018a7643-4b7e-4c7a-8c67-a94fc4821362 from local://wolverineissuereproduction.application.sagas.starttest/
info: Wolverine.Runtime.WolverineRuntime[0]
      Locally enqueuing scheduled message 018a7643-4b9a-411a-b8bf-f217e80d50f2 of type WolverineIssueReproduction.Application.Sagas.TestTimeout
info: WolverineIssueReproduction.Application.Sagas.TestSaga[0]
      Saga 83c3d69c-38b6-411d-95a4-e452c524b45a TIMEOUT OUT - MARKING COMPLETE
info: WolverineIssueReproduction.Application.Sagas.TestTimeout[104]
      Successfully processed message WolverineIssueReproduction.Application.Sagas.TestTimeout#018a7643-4b9a-411a-b8bf-f217e80d50f2 from local://wolverineissuereproduction.application.sagas.testtimeout/
JoshuaNitschke commented 11 months ago

I added unit tests to verify my swagger experience. I would expect all the tests to pass

image image
jeremydmiller commented 10 months ago

That was unpleasant to debug.

It's a combinatorial bug that's specific to the usage of Marten + doing no actual persistence

JoshuaNitschke commented 10 months ago

@jeremydmiller thank you!