Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
bcmills opened this issue Mar 8, 2022 · 8 comments
Assignees
Labels
gopls Issues related to the Go language server, gopls. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Testing An issue that has been verified to require only test changes, not just a test failure. Tools This label describes issues relating to any tools in the x/tools repository.
Milestone

Comments

@bcmills
Copy link
Contributor

bcmills commented Mar 8, 2022

--- 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 bcmills added NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. gopls Issues related to the Go language server, gopls. labels Mar 8, 2022
@gopherbot gopherbot added the Tools This label describes issues relating to any tools in the x/tools repository. label Mar 8, 2022
@gopherbot gopherbot added this to the Unreleased milestone Mar 8, 2022
@bcmills
Copy link
Contributor Author

bcmills commented Mar 8, 2022

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
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor Author

bcmills commented Apr 12, 2022

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.)

@bcmills bcmills added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Apr 12, 2022
@findleyr findleyr added Testing An issue that has been verified to require only test changes, not just a test failure. and removed gopls/testing labels May 10, 2022
@gopherbot
Copy link

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
Copy link
Contributor Author

bcmills commented May 12, 2022

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

@bcmills bcmills reopened this May 12, 2022
@bcmills bcmills removed the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label May 12, 2022
@bcmills bcmills reopened this May 12, 2022
@findleyr
Copy link
Contributor

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

@gopherbot
Copy link

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
gopls Issues related to the Go language server, gopls. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. Testing An issue that has been verified to require only test changes, not just a test failure. Tools This label describes issues relating to any tools in the x/tools repository.
Projects
None yet
Development

No branches or pull requests

4 participants