Enhance tracking of idempotent jobs in repository callbacks

[adeutscher]

Summary

When I enhanced the applied execution arbiter that supports the monitor worker threads to be more aware of the process being shut down, I noted an issue I had with some of the phrasing.

In comments, I mentioned how tracking the number of jobs in a given state had complications, and that the cure might be worse than the disease. It was absolutely more trouble than it was worth for the branch that I was working on at the time.

Since then, #84 has seen me take aim at trace log noise a bit, leading me to think that it would absolutely be worth it to adjust this. Marking a ToDo for later.

Main Objectives

Goals:

• Main goal is to have the idempotency monitor only stop waiting when there are specifically blocked jobs to be followed up on. The main benefit to this is to further reduce unnecessary log noise, even if it is trace-level.
• Once we actually are tracking the state:
  • Consider having Inactive jobs tracked under the same system
  • Remove the comment talking about how we couldn't possibly implement the tracking system that we just implemented.

Implementation Idea

• Update job repository to be aware of when the number of items that are blocked because the idempotency system has detected that they were running elsewhere.
  • This could probably involve giving job repository entries a link back to their repository.
  • Alternatively, the job repository could itself be a subscriber on the event of its entries. Would probably be more secure than adding a reporting method on the IJobRepository interface.
  • Ideally, this system would also maintain a watch on the inactive jobs tally, possibly replacing some of our current implementation for inactive jobs.
• Add to the job repository another subscribe callback that calls when the idempotency-blocked tally is updated.
• Duplicate the applied execution arbiter's delay to have specialized versions for the heartbeat monitor and the maintainer monitor.

[adeutscher]

While we're at it, also tidying up IJobRepositoryEntry in general, replacing the setter methods with set properties. They're all async, but there's nothing in them that requires async. That earns this issue a cleanup tag as well.

[adeutscher]

Trying to do this enhanced tracking in the one AppliedExecutionEndArbiter ended up being a completely confusing ball of string, so moved responsibilities into 3 separate classes. Even if we have some duplication, it's worth it for the readability.

[adeutscher]

Local testing is looking good:

SQS-based example (idempotency enabled but not likely to be triggered):

worker-1  | DBG Hosting starting
worker-1  | INF Found credentials using the AWS SDK's default credential search
worker-1  | INF Found credentials using the AWS SDK's default credential search
worker-1  | DBG Hosting started
worker-1  | VRB Idempotency Monitor: Waiting for watchable events
worker-1  | VRB Heartbeat Monitor: Waiting for watchable events
worker-1  | VRB Worker thread for JobSubscriberManager done. Response: NotEnabled
worker-1  | INF Health listening on port 8081
worker-1  | VRB Fetched 1 jobs in 00:00:00.1211307
worker-1  | VRB Executor 0 received message 5bbe12ad-41a3-41a7-9743-103b4b9472c9
worker-1  | VRB Heartbeat Monitor: 00:03:44.9959925 until next heartbeat check
worker-1  | INF Sleeping for 2 seconds
worker-1  | VRB Executor 0 finished processing message 5bbe12ad-41a3-41a7-9743-103b4b9472c9. Result: Success
worker-1  | VRB Fetched 0 jobs in 00:00:00.0015125
worker-1  | VRB Waiting before pulling more jobs, retrying in 2 s
< Job loader noise >
worker-1  | VRB Heartbeat Monitor: Waiting for watchable events

Next is a RabbitMQ example (idempotency enabled and likely to be triggered), using loader mode for async loading. There's still some points that need addressing. As with the first test, the idempotency monitor doesn't keep looping after it announces that it's waiting for events. When a job is deferred to the idempotency monitor, the system starts looping. The problem is, after it starts looping it doesn't stop:

worker-1  | VRB Executor 1 was unable to obtain a lock on message demo , deferring to Idempotency Monitor
worker-1  | VRB Idempotency Monitor: 00:00:30 until next follow-up check
worker-1  | VRB Fetching up to 10 messages from RabbitMQ Queue: RabbitQueue
< Noise >
worker-1  | VRB Waiting before pulling more jobs, retrying in 30 s
worker-1  | VRB Idempotency Monitor has attempted to acknowledge message demo . Success: True
worker-1  | VRB Idempotency Monitor: 00:00:30 until next follow-up check
worker-1  | VRB Fetching up to 10 messages from RabbitMQ Queue: RabbitQueue
worker-1  | VRB Fetched 0 jobs in 00:00:00.0006693
worker-1  | VRB Waiting before pulling more jobs, retrying in 30 s
worker-1  | VRB Idempotency Monitor: 00:00:30 until next follow-up check

What should be happening is that the idempotency monitor should report 'Waiting for watchable events' again.

This is drifting more into the idempotency system's mechanics, but getting the thought out while I have it: Current perma-looping in the branch aside, we can't rely on any internal signal within the job worker to speed up this 30s loop because we cannot assume with our current logic that this is the only instance of the JobWorker that is running. Adding a configuration option attesting that there's only one job worker instance would only support a very niche case that I don't think would bring any benefit. But if I did choose to do that in the future, then I'd do it with a third cancellation token source on the delay. When idempotency-blocked jobs hit zero and the configuration option is enabled, then the CTS is cancelled and rotated out for a fresh one.

[adeutscher]

Found the problem. It wasn't anything wrong with this branch's new logic, it's that the existing idempotency monitor logic directly removes the job from the running without bothering to set it to Complete.

Right this moment, my favoured way to solve this would to to update RemoveJobAsync. It would be a good catch-all if I ever added some new avenue to remove a job that wasn't previously marked, and it's a good thing I double-checked too because there were some old-style subscriber-notifiers there. They weren't breaking anything, but they're redundant now.

[adeutscher]

It's 1:20 AM, so I'm leaving a few final items until tomorrow:

• Confirm that the logic actually works.
• Commit the solution-wide code cleanup that I set in motion before I left my desk.
• Update Complete documentation to confirm that every job entry should flow into complete before removal.

I considered that a better fundamental fix for the tracking issue might be to make the job entry disposable and have the callback newState be nullable and do it on dispose, but I'd rather be specific about it than leave it up to disposal.

[adeutscher]

• Success:

  worker-1  | VRB Idempotency Monitor has attempted to acknowledge message test2 . Success: True
  worker-1  | VRB Idempotency Monitor: Waiting for watchable events
  

• Cleanup sweep uncovered no changes.

• On second thought lets give the dispose idea a spin. The worst it can do is not be commit-worthy.

[adeutscher]

The thing that I was worried about happened. Something must still be holding onto a reference to the entry, because Dispose isn't called in a snappy manner automatically when it goes out of scope.

Takeaways:

• Call dispose explicitly
• Suggests a possible memory leak? Doing a quick inspection.