Expected to find job with key, but no job found

[deepthidevaki]

Describe the bug

E 2020-12-14T19:08:36.656982Z Expected to find job with key 2251799821310810, but no job found 
E 2020-12-14T19:08:36.662935Z Expected to find job with key 2251799821310836, but no job found 
E 2020-12-14T19:08:36.663326Z Expected to find job with key 2251799821310837, but no job found 
E 2020-12-14T19:08:36.663534Z Expected to find job with key 2251799821310838, but no job found 
E 2020-12-14T19:08:36.663810Z Expected to find job with key 2251799821310839, but no job found 
E 2020-12-14T19:08:36.664011Z Expected to find job with key 2251799821310840, but no job found 
E 2020-12-14T19:08:36.664190Z Expected to find job with key 2251799821310841, but no job found 
E 2020-12-14T19:08:36.664447Z Expected to find job with key 2251799821310842, but no job found 
E 2020-12-14T19:08:36.664742Z Expected to find job with key 2251799821310843, but no job found 
E 2020-12-14T19:08:36.664946Z Expected to find job with key 2251799821310844, but no job found 
E 2020-12-14T19:08:36.665131Z Expected to find job with key 2251799821310810, but no job found 
E 2020-12-14T19:08:36.665295Z Expected to find job with key 2251799821310836, but no job found 
E 2020-12-14T19:08:36.665451Z Expected to find job with key 2251799821310837, but no job found 
E 2020-12-14T19:08:36.665643Z Expected to find job with key 2251799821310838, but no job found 
E 2020-12-14T19:08:36.665880Z Expected to find job with key 2251799821310839, but no job found 
E 2020-12-14T19:08:36.666101Z Expected to find job with key 2251799821310840, but no job found 
E 2020-12-14T19:08:36.667479Z Expected to find job with key 2251799821310841, but no job found 
E 2020-12-14T19:08:36.668035Z Expected to find job with key 2251799821310842, but no job found 
E 2020-12-14T19:08:36.668297Z Expected to find job with key 2251799821310843, but no job found 
E 2020-12-14T19:08:36.668501Z Expected to find job with key 2251799821310844, but no job found 

Version 0.25.3
Report location: visitJob (JobState.java:257)

logs

Environment:

• Camunda cloud
• Zeebe Version: 0.25.3

[deepthidevaki]

On a first look, this looks like a bug. If it is not, then we should lower the log level.

[Zelldon]

Duplicate of #3765

[deepthidevaki]

I don't think this is duplicate of #3765.
This log occurs when iterating over jobs. This happens when activating the jobs (JobState#forEachActivatableJobs )or when timing out jobs after deadline (JobState#forEachTimedOutEntry). When a job is completed, as far as I know, we don't iterate over the jobs.

[deepthidevaki]

I would categorize it as a bug. I couldn't find a case where this is expected to happen. But I would assign severity low as the error went away shortly and we did not observe any other issues related to it.

[npepinpe]

This occurred on the gameday cluster, so postponed until tomorrow after the game day in case it's related. Let's not solve the incident before the gameday occurs 😅

[pihme]

Not sure it is related to the game day. It is not deliberate. I can tell that much

Please wait for Game Day. After Game Day I can also give full sources, which might help in diagnosing the problem

[pihme]

So from the client side there is nothing out of the ordinary. I think this is a Zeebe-internal phenomenon. Would be interesting to see a stack trace, in particular whether it is called from forEachTimedOutEntry or forEachActivateableJob.

[npepinpe]

Please verify whether we're creating garbage (i.e. leaving dangling references) or we're actually "losing" jobs or inserting the wrong references. The latter is high priority, but the former isn't. In case of doubt I would assume the worst, and then we can verify and reprioritize (or just fix it if the cause is obvious at that point).

[deepthidevaki]

So from the client side there is nothing out of the ordinary. I think this is a Zeebe-internal phenomenon. Would be interesting to see a stack trace, in particular whether it is called from forEachTimedOutEntry or forEachActivateableJob.

Unfortunately there is not stack trace available to determine if it is called from forEachTimedOutEntry or forEachActivateableJob.

[deepthidevaki]

As a user, Peter did not observe any issues. We also don't see any stuck workflows in Operate. So I think we can safely assume that the severity is low.

[npepinpe]

Occurred in the last CW09 benchmark: https://console.cloud.google.com/errors/CKe9pf-Tqe-ZZw?service=zeebe-broker&version=medic-cw-09-cf1627167-benchmark&time=P1D&project=zeebe-io

Seems to occur in bursts, but the cluster seems healthy and the workers aren't reporting any errors.

[npepinpe]

I'm closing for now as we haven't noticed any negative effects, so I wouldn't invest time here at the moment.

[namero999]

We are experiencing this on 8.3.3

Was it ever discovered what this is about? Should we be worried (as in silent job loss)?

[npepinpe]

This can happen normally if your jobs time out while another worker is working on them. So for example, I have a job of type A, and two different workers foo and bar subscribed to receive jobs of type A. The job has an activation timeout of 5 seconds. Zeebe sends the job to worker foo. That worker is slow for some reason, and takes more than 5 seconds to complete the job. After 5 seconds, Zeebe assumes worker foo timed out, and sends the job to worker bar. But maybe worker foo completes the job after 5.5 seconds! So now the job is completed and effectively doesn't exist anymore in Zeebe. But worker bar has received it, and completes it after 7 seconds. Then you get the NOT_FOUND error.

This is not an error from Zeebe's point of view because Zeebe is an at-least-once system.

[namero999]

I see, thank you. It might be consistent with the fact that we have attempted to run some tests with a high value for max-jobs-active. Currently the pod is outputting lots of logs about these jobs being not found. While it's clear that this is not an issue, should we expect the logs to stop once all the jobs have exhausted the retries?