Skip to content

"Unable to edit document because the file was not previously opened" when using "dart.onlyAnalyzeProjectsWithOpenFiles":true (and plugins) #4862

Closed

Description

@DanTup

Splitting this from #4740 since it's not the same as the original issue and I'm not yet certain that it's plugin-related at all.

To reproduce:

  • Create a simple empty project that references an analyzer plugin (like custom_lint)
    I'm not sure the plugin is relevant yet, but it seems to repro pretty reliably with and I couldn't repro without
  • Ensure "dart.onlyAnalyzeProjectsWithOpenFiles":true is set for the workspace and that no files are open
  • Run the Developer: Reload Window command to get a clean analyzer with no open files
  • Open analysis_options.yaml and press Save
  • Close analysis_options.yaml
    Modifying analysis_options may or may not be relevant
  • Open a .dart file
  • Make some changes to the file

This open results in an error like:

image

Opening the file triggers rebuilding of analysis roots, but it also seems to remove the overlay:

1701185971585:Req:{"jsonrpc"::"2.0","method"::"textDocument/didOpen","params"::{"textDocument"::{"uri"::"file::///C%3A/Dev/Test%20Projects/dartcode_4740_repro/lib/dartcode_4740_repro.dart","languageId"::"dart","version"::1,"text"::"int calculate() {\n  return 6 * 7;\n}\n"}},"clientRequestTime"::1701185971583}
1701185971585:Info:Setting overlay for C::\Dev\Test Projects\dartcode_4740_repro\lib\dartcode_4740_repro.dart
1701185971587:Info:Setting roots
1701185971588:Info:Done setting roots
1701185971588:Info:Done setting roots
1701185971588:Info:Removing overlay for C::\Dev\Test Projects\dartcode_4740_repro\lib\dartcode_4740_repro.dart
1701185972690:Req:{"jsonrpc"::"2.0","method"::"textDocument/didChange","params"::{"textDocument"::{"uri"::"file::///C%3A/Dev/Test%20Projects/dartcode_4740_repro/lib/dartcode_4740_repro.dart","version"::2},"contentChanges"::[{"range"::{"start"::{"line"::3,"character"::0},"end"::{"line"::3,"character"::0}},"rangeLength"::0,"text"::"d"}]},"clientRequestTime"::1701185972204}
1701185972690:Res:{"jsonrpc"::"2.0","method"::"window/showMessage","params"::{"message"::"Unable to edit document because the file was not previously opened:: C::\\Dev\\Test Projects\\dartcode_4740_repro\\lib\\dartcode_4740_repro.dart","type"::1}}
1701185972690:Res:{"jsonrpc"::"2.0","method"::"window/logMessage","params"::{"message"::"An unrecoverable error occurred.\n\nUnable to edit document because the file was not previously opened:: C::\\Dev\\Test Projects\\dartcode_4740_repro\\lib\\dartcode_4740_repro.dart\n\n-32099\n\nnull","type"::1}}

We always verify we have an overlay before processing a textDocument/didChange event so this results in us throwing.

Activity

  1. added this to the v3.78.0 milestone on Nov 28, 2023
  2. DanTup commented on Nov 28, 2023

    @DanTup
    MemberAuthor

    This looks like a race condition and it may be caused by plugins.

    When there are changes to plugins, we end up re-computing our capabilities and call client/unregisterCapability and client/registerCapability. It appears that this causes VS Code to tell us that the open files have been closed and then re-opened:

    1701186529088:Res:{"id"::5,"jsonrpc"::"2.0","method"::"client/unregisterCapability","params"::{"unregisterations"::[{"id"::"181","method"::"textDocument/codeAction"},{"id"::"184","method"::"textDocument/definition"},{"id"::"187","method"::"textDocument/formatting"},{"id"::"188","method"::"textDocument/implementation"},{"id"::"189","method"::"textDocument/references"},{"id"::"190","method"::"textDocument/rename"},{"id"::"192","method"::"textDocument/signatureHelp"},{"id"::"193","method"::"textDocument/didOpen"},{"id"::"194","method"::"textDocument/didClose"},{"id"::"195","method"::"textDocument/didChange"}]}}
    1701186529089:Res:{"id"::6,"jsonrpc"::"2.0","method"::"client/registerCapability","params"::{"registrations"::[{"id"::"221","method"::"textDocument/codeAction","registerOptions"::{"codeActionKinds"::["source","source.organizeImports","source.fixAll","source.sortMembers","quickfix","refactor"],"documentSelector"::[{"language"::"dart","scheme"::"file"}]}},{"id"::"224","method"::"textDocument/definition","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}]}},{"id"::"227","method"::"textDocument/formatting","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}]}},{"id"::"228","method"::"textDocument/implementation","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}]}},{"id"::"229","method"::"textDocument/references","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}]}},{"id"::"230","method"::"textDocument/rename","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}],"prepareProvider"::true}},{"id"::"232","method"::"textDocument/signatureHelp","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"}],"retriggerCharacters"::[","],"triggerCharacters"::["("]}},{"id"::"233","method"::"textDocument/didOpen","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"},{"language"::"yaml","pattern"::"**/pubspec.yaml","scheme"::"file"},{"language"::"yaml","pattern"::"**/analysis_options.yaml","scheme"::"file"},{"language"::"yaml","pattern"::"**/lib/{fix_data.yaml,fix_data/**.yaml}","scheme"::"file"}]}},{"id"::"234","method"::"textDocument/didClose","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"},{"language"::"yaml","pattern"::"**/pubspec.yaml","scheme"::"file"},{"language"::"yaml","pattern"::"**/analysis_options.yaml","scheme"::"file"},{"language"::"yaml","pattern"::"**/lib/{fix_data.yaml,fix_data/**.yaml}","scheme"::"file"}]}},{"id"::"235","method"::"textDocument/didChange","registerOptions"::{"documentSelector"::[{"language"::"dart","scheme"::"file"},{"language"::"yaml","pattern"::"**/pubspec.yaml","scheme"::"file"},{"language"::"yaml","pattern"::"**/analysis_options.yaml","scheme"::"file"},{"language"::"yaml","pattern"::"**/lib/{fix_data.yaml,fix_data/**.yaml}","scheme"::"file"}],"syncKind"::2}}]}}
    1701186530038:Req:{"jsonrpc"::"2.0","method"::"textDocument/didClose","params"::{"textDocument"::{"uri"::"file::///C%3A/Dev/Test%20Projects/dartcode_4740_repro/lib/dartcode_4740_repro.dart"}},"clientRequestTime"::1701186530034}
    1701186530042:Req:{"jsonrpc"::"2.0","method"::"textDocument/didOpen","params"::{"textDocument"::{"uri"::"file::///C%3A/Dev/Test%20Projects/dartcode_4740_repro/lib/dartcode_4740_repro.dart","languageId"::"dart","version"::2,"text"::"int calculate() {\n  return 6 * 7;\n}\nd"}},"clientRequestTime"::1701186530038}
    

    But it appears that we process the close/open in the wrong order, so we first update the overlay and then remove it:

    CLOSE    -> 1701186530038:Req:{"jsonrpc"::"2.0","method"::"textDocument/didClose","params"::{"textDocument"::{"uri"::"file::///C%3A/Dev/Test%20Projects/dartcode_4740_repro/lib/dartcode_4740_repro.dart"}},"clientRequestTime"::1701186530034}
                1701186530039:Info:Setting roots
                1701186530039:Req:{"jsonrpc"::"2.0","method"::"$/cancelRequest","params"::{"id"::6},"clientRequestTime"::1701186530035}
                1701186530042:Req:{"jsonrpc"::"2.0","id"::6,"result"::null,"clientRequestTime"::1701186530038}
    OPEN     -> 1701186530042:Req:{"jsonrpc"::"2.0","method"::"textDocument/didOpen","params"::{"textDocument"::{"uri"::"file::///C%3A/Dev/Test%20Projects/dartcode_4740_repro/lib/dartcode_4740_repro.dart","languageId"::"dart","version"::2,"text"::"int calculate() {\n  return 6 * 7;\n}\nd"}},"clientRequestTime"::1701186530038}
    +OVERLAY -> 1701186530042:Info:Setting overlay for C::\Dev\Test Projects\dartcode_4740_repro\lib\dartcode_4740_repro.dart
                1701186530044:Info:Setting roots
                1701186530045:Req:{"jsonrpc"::"2.0","id"::8,"method"::"textDocument/codeAction","params"::{"textDocument"::{"uri"::"file::///C%3A/Dev/Test%20Projects/dartcode_4740_repro/lib/dartcode_4740_repro.dart"},"range"::{"start"::{"line"::3,"character"::1},"end"::{"line"::3,"character"::1}},"context"::{"diagnostics"::[],"triggerKind"::2}},"clientRequestTime"::1701186530039}
                1701186530046:Res:{"id"::8,"jsonrpc"::"2.0","error"::{"code"::-32801,"message"::"Document was modified before operation completed"}}
                1701186530046:Info:Done setting roots
    -OVERLAY -> 1701186530046:Info:Removing overlay for C::\Dev\Test Projects\dartcode_4740_repro\lib\dartcode_4740_repro.dart
    

    So it appears that there is a bug in the processing of closed files - they must be applied immediately and synchronously.

    
    #0      OverlayResourceProvider.removeOverlay (package::analyzer/file_system/overlay_file_system.dart::68::62)
    #1      LspAnalysisServer.onOverlayDestroyed (package::analysis_server/src/lsp/lsp_analysis_server.dart::603::22)
    #2      TextDocumentCloseHandler.handle.<anonymous closure> (package::analysis_server/src/lsp/handlers/handler_text_document_changes.dart::76::14)
    <asynchronous suspension>
    #3      LspAnalysisServer._handleNotificationMessage (package::analysis_server/src/lsp/lsp_analysis_server.dart::991::20)
    <asynchronous suspension>
    #4      LspAnalysisServer.handleMessage.<anonymous closure>.<anonymous closure> (package::analysis_server/src/lsp/lsp_analysis_server.dart::458::15)
    <asynchronous suspension>
    #5      OperationPerformanceImpl.runAsync (package::analyzer/src/util/performance/operation_performance.dart::172::14)
    <asynchronous suspension>
    #6      LspAnalysisServer.handleMessage.<anonymous closure> (package::analysis_server/src/lsp/lsp_analysis_server.dart::439::11)
    <asynchronous suspension>
    
  3. DanTup commented on Nov 28, 2023

    @DanTup
    MemberAuthor

    The issue is a bug in handling of closed files. There is an await that meant if a client closed and re-opened a file very close together, the close could be processed after the open, leaving the file in a "closed" state (which produces this error on the next change).

    It isn't directly related to plugins or onlyAnalyzeProjectsWithOpenFiles, however using plugins can result in us re-registering capabilities with the client when analysis roots change (which results in VS Code's LSP client closing and re-opening all files since those events are tied to the capabilities) and using onlyAnalyzeProjectsWithOpenFiles causes additional work when files are opening/closing which makes it more likely for the bad await to cause the work to be re-ordered.

    I have a fix open at https://dart-review.googlesource.com/c/sdk/+/338660 but since it'll only ship in a future SDK release my recommendation is to disable onlyAnalyzeProjectsWithOpenFiles as a workaround (I'd generally recommend not using that at all, but if you do feel you need it for some projects, set it only on those projects rather than in your global user settings).

  4. DanTup commented on Nov 28, 2023

    @DanTup
    MemberAuthor
  5. added
    relies on sdk changesSomething that requires changes in the Dart/Flutter SDK to ship before it will become available
    in editorRelates to code editing or language features
    on Nov 28, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    in editorRelates to code editing or language featuresin lsp/analysis serverSomething to be fixed in the Dart analysis serveris bugrelies on sdk changesSomething that requires changes in the Dart/Flutter SDK to ship before it will become available

    Type

    No type

    Projects

    No projects

      Milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions