Worker: sometimes sends events without a step id

[josephjclark]

Strange sequence of events in worker logs:

[SRV] ✘ cf698f95-4b16-4a75-9ac4-98e1729f7017 :: step:complete :: ERR: [step:complete] {"step_id":["This field can't be blank."]}
[SRV] ℹ cf698f95-4b16-4a75-9ac4-98e1729f7017 :: run:log :: OK
[SRV] ✘ cf698f95-4b16-4a75-9ac4-98e1729f7017 :: step:start :: ERR: [step:start] {"job_id":["does not exist"]}
[SRV] ✘ cf698f95-4b16-4a75-9ac4-98e1729f7017 :: run:log :: ERR: [run:log] {"step_id":["must be associated with the run"]}

How is step_id blank?

This should lead to lost. I think this run might recover, but interestingly there is a lost run (ea330df2-6b88-4cb3-84b9-4619e5d3c319) at almost the same time as this. Coincidence?

GCP logs for the run

[josephjclark]

Seen another one of these today GCP

This lead to lost - because step:complete was rejected the following step:start was also rejected and the whole thing goes sideways.

What's also weird is we seem to get two event responses to step complete:

[SRV] ℹ ce11dd61-952f-408f-a7ff-b580d642d72e :: sent step:complete :: OK :: 602ms
[SRV] ✘ ce11dd61-952f-408f-a7ff-b580d642d72e :: step:complete :: ERR: [step:complete] {"step_id":["This field can't be blank."]}

We get an OK response but then an error? That's odd. Did it send twice? Is it bad logging code?

The other thing about this is: the moment the step complete was rejected, we know that run is dead. It should't be lost

I've raised out OpenFn/lightning#4355 so that we can handle this better lightning side

At some stage I'll try and work out a repro Worker-side.

[josephjclark]

Seen two on Eswatini: eg https://app.openfn.org/projects/da257e6e-4adf-4ac1-8f04-f5ac815499a0/runs/851848f2-f695-412e-b70f-ab163f72bdf6

[josephjclark]

A quick search suggests this is coming up quite a bit - I'm scanning the logs but something in the order of 20 in the last 30 days

[josephjclark]

I think I'm going to add some dedicated debugging around this, see what I can work out