Fixes job cancellation bug hidden behind race condition

[izaaklauer]

Fixed the issue that caused these failures in CI:

• https://app.circleci.com/pipelines/github/hashicorp/waypoint/5710/workflows/1a5d72db-0c69-4873-b52b-9ba984ef6d03/jobs/43406
• https://app.circleci.com/pipelines/github/hashicorp/waypoint/4393/workflows/3c705bad-3280-4e46-91ab-9c22c1636ee5/jobs/31799

This was a tricky one to track down. From the failed tests, we can see that the client was receiving duplicate cancellation events. I was able to replicate the failed test by adding a sleep here.

Here’s what I think is happening:

There are three goroutines at play here. One watching for DB changes and adding them to a channel (A), one listening for client events and adding them to a channel (B), and a big one pulling off the channels and doing work (C).

In the final phase of this test, the client sends a completion event onto the stream. B gets it, and passes it to C synchronously via an unbuffered channel. C handles it, which eventually results in a DB update on the job (marking its state as Success), and then the race begins.

On one side, B is going to return, which will trigger its deferred cancel(), which will cause C to return and the test to pass. On the other side, the update that C just made to the job is going to get picked up by A’s watchset, which will result in one more job update for C to process before cancel() comes around, which will exercise the bug.

Generally, the memdb watchset path is slower than cancelling the context, so C never sees the final “Success” update to the job, and we don’t exercise the bug.

The bug is that we were treating the completion event as a cancellation event with an updated timestamp. It looks like *timestamppb.Timestamp’s aren’t nicely comparable with == - they return not equal even if they have the same underlying time values. Converting them to time.Time first does the trick.

Addresses one of the problems in #1521

[evanphx]

[krantzinator]

NICE

[briancain]

🔥 🐛