Where communities thrive


  • Join over 1.5M+ people
  • Join over 100K+ communities
  • Free without limits
  • Create your own community
People
Repo info
Activity
  • Aug 26 21:52
    ryandanthony synchronize #673
  • Aug 26 21:52
    ryandanthony synchronize #673
  • Aug 26 20:16
    ryandanthony synchronize #673
  • Aug 26 20:08
    ryandanthony synchronize #673
  • Aug 26 20:03
    ryandanthony synchronize #673
  • Aug 26 18:24
    ryandanthony opened #673
  • Jul 07 12:19
    jeremydmiller labeled #669
  • Jul 07 12:19
    jeremydmiller labeled #668
  • Jul 07 12:19
    jeremydmiller labeled #667
  • Jul 07 12:19
    jeremydmiller labeled #666
  • Jul 07 12:19
    jeremydmiller labeled #665
  • Jul 07 12:11
    jeremydmiller commented #668
  • Jul 07 12:02
    jeremydmiller demilestoned #644
  • Jul 07 12:02
    jeremydmiller demilestoned #629
  • Jul 07 12:02
    jeremydmiller demilestoned #627
  • Jul 07 12:02
    jeremydmiller demilestoned #618
  • Jul 07 12:02
    jeremydmiller demilestoned #617
  • Jul 07 12:02
    jeremydmiller demilestoned #616
  • Jul 07 12:02
    jeremydmiller demilestoned #612
  • Jul 07 12:02
    jeremydmiller demilestoned #610
Mark Warpool
@CodingGorilla
it doesn't only do it on the first message, but it does seem to stop running the message handlers twice "after a while"
Jeremy D. Miller
@jeremydmiller
The presence of the retry queue makes me wonder a bit
Mark Warpool
@CodingGorilla
if I put enough break points, everything just !@#$ing works... :rage:
It was pretty consistently running it twice the very first message it processed after I started the debugger, not it seems totally random
Almost like if I'm paused in the debugger long enough it starts a new one? But I can't quite nail down the pattern.
Mark Warpool
@CodingGorilla
Sorry, my gitter died or something I didn't see your responses

Even when it only runs one time it always says:

Jasper.Messages:Information: Successfully processed message UpdateFeatureSubscriptions#016cbb46-b9f5-433d-86d0-23eaedc9e5e9 from loopback://retries/

I assume this means that it's running the message out of the "retry queue"?
And for clarification, when the handler runs twice, I see that same message in the output twice, with the same id after the "UpdateFeatureSubscriptions"
Mark Warpool
@CodingGorilla
the handler handles all errors on it's own, so the Handle() method can never throw an exception, so Jasper should have no reason to put it into retry
Jeremy D. Miller
@jeremydmiller
It does. Makes me wonder if your message is getting routed to multiple queues. Not sure why anything would make it to the retries queue though
W/o it being a failure
Jeremy D. Miller
@jeremydmiller
You know you can let Jasper handle the errors, right? It’ll log and apply retry policies
Mark Warpool
@CodingGorilla
Yes, in this case I can't let it just fall and retry, I need to handle the failure gracefully and do a sort of rollback.
Mark Warpool
@CodingGorilla
It's handles keeping things in sync with a bunch of third party APIs for billing and such
Mark Warpool
@CodingGorilla
@jeremydmiller So I noticed that when I get this duplicate message running, I see jasper log the following
Jasper.Transports:Information: Recovered 1 incoming envelopes from storage
Does that indicate that it's seeing that message as previously failed?
Mark Warpool
@CodingGorilla
It seems like it's queuing up the message on the loopback, but then the durability agent sometimes kicks in and recovers the message while it's still running from the "local queue"
Jeremy D. Miller
@jeremydmiller
Which I’ve never, ever seen in any kind of testing on my own.
You’re using Postgres or Sql Server for the message persistence?
Mark Warpool
@CodingGorilla
Postgres via Jasper.Persistence.Marten
Jeremy D. Miller
@jeremydmiller
Can we do a zoom meeting or google hangout some day on this?
You’re running into a lot of things I don’t understand
Mark Warpool
@CodingGorilla
sure
I work from home, so I can make myself available whenever is good for you, except next thursday or friday
Jeremy D. Miller
@jeremydmiller
Monday afternoon work maybe?
Mark Warpool
@CodingGorilla
yea, that would be fine
Mark Warpool
@CodingGorilla
Man, I've been trying to figure this out all night, it has to be some weird sort of concurrency/timing issue, if I slow it down enough I can make it go away. But here is smidge of what I see in the Output when it actually happens
Processing: $Envelope #016cd0d2-9646-4d42-8579-f9c698867afb (UpdateFeatureSubscriptions) from Api@CGPC to loopback://durable/ on default
[... snipped noise ...]
Jasper.Transports:Information: Recovered 1 incoming envelopes from storage
Processing: $Envelope #016cd0d2-9646-4d42-8579-f9c698867afb from Api@CGPC to loopback://durable/ on default
[... snipped more noise ...]
Jasper.Messages:Information: Successfully processed message UpdateFeatureSubscriptions#016cd0d2-9646-4d42-8579-f9c698867afb from loopback://retries/
[... snipped more noise ...]
Jasper.Messages:Information: Successfully processed message UpdateFeatureSubscriptions#016cd0d2-9646-4d42-8579-f9c698867afb from loopback://retries/
Jay Stevens
@jediwarpraptor
This message was deleted
Mark Warpool
@CodingGorilla
The Processing: $Envelope #..." is a diagnostic log message I added to theWorkerQueue.AddQueue`ActionBlock<Envelop> anonymous method
Jay Stevens
@jediwarpraptor
This message was deleted
Mark Warpool
@CodingGorilla
So the one thing I noticed is that the first time I see the "Processing message", there is no other Jasper logging before it. But the second time you see the "Recovered 1 incoming envelopes from storage" message. This leads me to believe that it some how queues the job to run immediately, but then the RecoverIncomingMessages kicks in and grabs it also? But I'll be damned to hell if I can figure out where that's happening.
Jeremy D. Miller
@jeremydmiller
It it the same message Guid?
Mark Warpool
@CodingGorilla
yea, that sample I quoted above is real, the id is: 016cd0d2-9646-4d42-8579-f9c698867afb
Jeremy D. Miller
@jeremydmiller
It really shouldn’t be possible for it to be doing that if the same node is running the whole time
I’d love to see how you’re making that happen. This is all from posting to a local, persistent queue, right?
And you’re not stopping and starting anything in between somehow, right?
Mark Warpool
@CodingGorilla
This is all running on my local development machine. Yea, it's all from a call to ICommandBus.EnqueueDurably()
nope, like I said I have to remove all the breakpoints except inside the handler, or the behavior goes away
Jeremy D. Miller
@jeremydmiller
Is there something from the routing rules that’s routing it to both queues?
Hey, I’ve got to turn in, but I’ll check this when I can tomorrow.
Mark Warpool
@CodingGorilla
Not as far as I can tell, I really only have the local queue, I'll keep digging around until I'm ready to pass out myself. Good night :)
Jeremy D. Miller
@jeremydmiller
ttyl
Mark Warpool
@CodingGorilla
So a couple of observations:

First, this message:

Jasper.Messages:Information: Successfully processed message UpdateFeatureSubscriptions#016cd11a-6c35-483d-a028-fbfe4a5535f4 from loopback://retries/

Seems misleading, it seems like after a message is processed it always calls MessageLogger.MessageSucceeded() which is hard coded to report the "loopback://retries/" URL (which is called ReplyUri??), no matter what. The other logging I added seems to indicate it's actually coming from "loopback://durable/"
Second, I changed the JasperOptions.ScheduledJobs.FirstExecution and JasperOptions.ScheduledJobs.PollingTime, which seems to control the durability agent's queue processing. I set them both to 2 minutes (default of 0 seconds and 5 seconds respectively), and the problem seems to go away.
Mark Warpool
@CodingGorilla
But along with the problem going away, I also notice that the message is no longer being picked up by the RecoverIncomingMessages queue from the durability agent. But I still cannot figure out where the actual execution comes from.