x/tools/gopls/internal/regtest/diagnostics: TestNoReinitialize failures with "condition has final verdict Unmeetable"

[bcmills]

--- FAIL: TestNoReinitialize (1.81s)
    --- FAIL: TestNoReinitialize/singleton (1.00s)
        diagnostics_test.go:1976: waiting on:
            	Unmeetable: once "completed work \"diagnosing opened files\" at least 1 time(s)" is met, must have "log message matching \".*query=\\\\[builtin mod.com/...\\\\].*\" expected 1 times"
            
            err:condition has final verdict Unmeetable
            
            state:
            #### log messages (see RPC logs for full text):
            	Info: "2022/03/04 18:52:45 go env for /tmp/workdir-host-f...
            
            #### diagnostics:
            
            #### outstanding work:
            #### completed work:
            	Setting up workspace: 1
            	diagnosing initial workspace load: 1
            	diagnosing opened files: 1
            	Load: 1
FAIL
FAIL	golang.org/x/tools/gopls/internal/regtest/diagnostics	221.910s

From the gopls logs, it seems that the $/progress notification replied with Done. about 100ms after diagnosing opened files began, and the completed work "diagnosing opened files" even really is missing. Maybe a synchronization bug in the progress notification?

greplogs --dashboard -md -l -e 'FAIL: TestNoReinitialize'

2022-03-04T18:29:58-121d1e4-ca384f7/freebsd-arm64-dmgk

(CC @findleyr)

[bcmills]

Hmm, in the trace I see:

[Trace - 18:52:44.913 PM] Received notification '$/progress'.
Params: {"token":"833170555986271453","value":{"kind":"begin","title":"Load","message":"Loading query=[builtin mod.com/...]"}}

Up to what looks like maybe a double-escaping bug in the test failure message, this looks like exactly the log message that the test is claiming is “unmeetable”.

[findleyr]

Up to what looks like maybe a double-escaping bug in the test failure message, this looks like exactly the log message that the test is claiming is “unmeetable”.

That's a progress notification. We're missing the log message that the load has actually been performed.

[findleyr]

After looking at this briefly I have no idea how it is possible: the load completed successfully and so should have generated a log message. Yet it seems unlikely that we're dropping logs.

Unfortunately/fortunately it has not reoccurred in the last month, so I am disinclined to spend too much time investigating right now.

[bcmills]

Unfortunately/fortunately it has not reoccurred in the last month, so I am disinclined to spend too much time investigating right now.

That seems reasonable to me. (With only one example in the logs, there's no pattern we can follow to help identify the root cause.)

[gopherbot]

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

[bcmills]

greplogs -l -e 'FAIL: TestNoReinitialize' --since=2022-03-05
2022-04-04T06:48:45-153e30b-492c85a/windows-amd64-race

[findleyr]

We recently realized that log messages are not ordered with respect to other LSP events. That would explain this failure (and others).

[gopherbot]

Change https://go.dev/cl/513097 mentions this issue: gopls: fix tests that depend on log sequencing