HIE doesn't respond to request when error occurs

[noughtmare]

See https://github.com/noughtmare/haskell-lsp-client/pull/7#issuecomment-393547576.

No response is send to my completion request after "Got error while processing diagnostics: : cannot satisfy -package-id haskell-lsp-types-0.2.2.0-3h9qH2UuBHb4YGz8RPTqBe\n (use -v for more information)".

In the JSON RPC specification it says: "When a rpc call is made, the Server MUST reply with a Response", that doesn't happen in this case.

PS: I have found the cause of this error, but that is not relevant to this more fundamental issue.

[alanz]

@noughtmare can you redo this with current hie master, we have improved the logging, so it is clearer what is happening.

Or can you provide a reproducable test case I can run on my side.

[noughtmare]

with hie from github master:

2018-06-04 00:03:34.666719201 [ThreadId 4] - run entered for HIE(hie) Version 0.2.0.0, Git revision a4e21f43c94dfc253d07614e781347d657c86b9b (dirty) (1448 commits) x86_64 ghc-8.2.2
2018-06-04 00:03:34.666886986 [ThreadId 4] - Current directory:/home/jaro/Data/haskell/haskell-lsp-client
2018-06-04 00:03:34.666938906 [ThreadId 4] - 

haskell-lsp:Starting up server ...
2018-06-04 00:03:34.667418495 [ThreadId 4] - ---> {"jsonrpc":"2.0","id":0,"method":"initialize","params":{"processId":17703,"capabilities":{"workspace":{"applyEdit":false,"workspaceEdit":{"documentChanges":false},"didChangeConfiguration":{"dynamicRegistration":false},"didChangeWatchedFiles":{"dynamicRegistration":false},"symbol":{"dynamicRegistration":false},"executeCommand":{"dynamicRegistration":false}},"textDocument":{"synchronization":{"dynamicRegistration":false,"willSave":false,"willSaveWaitUntil":false,"didSave":false},"completion":{"dynamicRegistration":false,"completionItem":{"snippetSupport":false}},"hover":{"dynamicRegistration":false},"signatureHelp":{"dynamicRegistration":false},"references":{"dynamicRegistration":false},"documentHighlight":{"dynamicRegistration":false},"documentSymbol":{"dynamicRegistration":false},"formatting":{"dynamicRegistration":false},"rangeFormatting":{"dynamicRegistration":false},"onTypeFormatting":{"dynamicRegistration":false},"definition":{"dynamicRegistration":false},"codeAction":{"dynamicRegistration":false},"codeLens":{"dynamicRegistration":false},"documentLink":{"dynamicRegistration":false},"rename":{"dynamicRegistration":false}}}}}
2018-06-04 00:03:34.66863301 [ThreadId 5] - <--2--{"result":{"capabilities":{"textDocumentSync":{"openClose":true,"change":2,"willSave":false,"willSaveWaitUntil":false,"save":{"includeText":false}},"hoverProvider":true,"completionProvider":{"resolveProvider":true,"triggerCharacters":["."]},"definitionProvider":true,"referencesProvider":true,"documentHighlightProvider":true,"documentSymbolProvider":true,"codeActionProvider":true,"documentFormattingProvider":true,"documentRangeFormattingProvider":true,"renameProvider":true,"executeCommandProvider":{"commands":["applyrefact:applyOne","hare:demote"]}}},"jsonrpc":"2.0","id":0}
2018-06-04 00:03:34.685003065 [ThreadId 4] - ---> {"jsonrpc":"2.0","method":"initialized","params":{}}
2018-06-04 00:03:34.685218563 [ThreadId 4] - ---> {"jsonrpc":"2.0","method":"textDocument/didOpen","params":{"textDocument":{"uri":"file:///home/jaro/Data/haskell/haskell-lsp-client/Test.hs","languageId":"haskell","version":1,"text":"main = put\n"}}}
2018-06-04 00:03:34.685355194 [ThreadId 4] - ---> {"jsonrpc":"2.0","id":1,"method":"textDocument/documentSymbol","params":{"textDocument":{"uri":"file:///home/jaro/Data/haskell/haskell-lsp-client/Test.hs"}}}
2018-06-04 00:03:34.68546411 [ThreadId 10] - ideDispatcher: top of loop
2018-06-04 00:03:34.685512226 [ThreadId 7] - ghcDispatcher: top of loop
2018-06-04 00:03:34.685572532 [ThreadId 8] - ****** reactor: got message number:0
2018-06-04 00:03:34.685613883 [ThreadId 8] - ****** reactor: processing Initialized Notification
2018-06-04 00:03:34.68563984 [ThreadId 8] - ****** reactor: got message number:1
2018-06-04 00:03:34.685660723 [ThreadId 8] - ****** reactor: processing NotDidOpenTextDocument
2018-06-04 00:03:34.68572262 [ThreadId 8] - ****** reactor: got message number:2
2018-06-04 00:03:34.685750335 [ThreadId 8] - reactor:got Document symbol request:RequestMessage {_jsonrpc = "2.0", _id = IdInt 1, _method = TextDocumentDocumentSymbol, _params = DocumentSymbolParams {_textDocument = TextDocumentIdentifier {_uri = Uri {getUri = "file:///home/jaro/Data/haskell/haskell-lsp-client/Test.hs"}}}}
2018-06-04 00:03:34.685995348 [ThreadId 5] - <--2--{"jsonrpc":"2.0","method":"window/logMessage","params":{"type":4,"message":"Using hie version: Version 0.2.0.0, Git revision a4e21f43c94dfc253d07614e781347d657c86b9b (dirty) (1448 commits) x86_64 ghc-8.2.2"}}
2018-06-04 00:03:34.686131748 [ThreadId 7] - ghcDispatcher:got request 0 with id: Nothing
2018-06-04 00:03:34.686260822 [ThreadId 7] - ghcDispatcher: top of loop
2018-06-04 00:03:34.686297341 [ThreadId 7] - ghcDispatcher:got request 1 with id: Nothing
2018-06-04 00:03:34.686773957 [ThreadId 10] - ideDispatcher:got request 2 with id: IdInt 1
2018-06-04 00:03:34.686925589 [ThreadId 10] - ideDispatcher: top of loop
2018-06-04 00:03:34.687135864 [ThreadId 5] - <--2--{"jsonrpc":"2.0","method":"window/logMessage","params":{"type":4,"message":"Using hoogle db at: /home/jaro/.hoogle/default-haskell-5.0.17.hoo"}}
2018-06-04 00:03:34.687624709 [ThreadId 7] - file mapping state is: fromList [("/home/jaro/Data/haskell/haskell-lsp-client/Test.hs",FileMapping {fmPath = "/tmp/ghc-mod17705/Test17704-0.hs", fmTemp = True})]
2018-06-04 00:03:34.687701518 [ThreadId 7] - ghcDispatcher: top of loop
2018-06-04 00:03:34.687737275 [ThreadId 7] - ghcDispatcher:got request 1 with id: Nothing
2018-06-04 00:03:34.687769851 [ThreadId 7] - ghcDispatcher:Processing request as version matches
2018-06-04 00:03:34.747488464 [ThreadId 7] - ghcDispatcher: top of loop
2018-06-04 00:03:34.747578248 [ThreadId 7] - ghcDispatcher:got request 1 with id: Nothing
2018-06-04 00:03:34.747618144 [ThreadId 7] - ghcDispatcher:Processing request as version matches
2018-06-04 00:03:34.747759015 [ThreadId 7] - setTypecheckedModule: file mapping state is: fromList [("/home/jaro/Data/haskell/haskell-lsp-client/Test.hs",FileMapping {fmPath = "/tmp/ghc-mod17705/Test17704-0.hs", fmTemp = True})]
2018-06-04 00:03:34.747800438 [ThreadId 7] - setTypecheckedModule: before ghc-mod
2018-06-04 00:03:34.83004969 [ThreadId 5] - <--2--{"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///home/jaro/Data/haskell/haskell-lsp-client/Test.hs","diagnostics":[]}}
2018-06-04 00:03:34.867734736 [ThreadId 7] - setTypecheckedModule: after ghc-mod
2018-06-04 00:03:34.867912222 [ThreadId 7] - setTypecheckedModule: Didn't get typechecked module for: "/home/jaro/Data/haskell/haskell-lsp-client/Test.hs"
2018-06-04 00:03:34.867980546 [ThreadId 7] - ghcDispatcher: top of loop
2018-06-04 00:03:34.868163802 [ThreadId 5] - <--2--{"jsonrpc":"2.0","method":"window/showMessage","params":{"type":1,"message":"Got error while processing diagnostics: readCreateProcess: /home/jaro/haskell-ide-engine/.stack-work/install/x86_64-linux-nix/lts-11.9/8.2.2/libexec/x86_64-linux-ghc-8.2.2/cabal-helper-0.8.0.3/cabal-helper-wrapper \"--with-ghc=ghc\" \"--with-ghc-pkg=ghc-pkg\" \"--with-cabal=cabal\" \"/home/jaro/Data/haskell/haskell-lsp-client\" \"/home/jaro/Data/haskell/haskell-lsp-client/dist\" \"package-db-stack\" \"flags\" \"compiler-version\" \"ghc-merged-pkg-options\" \"config-flags\" \"non-default-config-flags\" \"ghc-src-options\" \"ghc-pkg-options\" \"ghc-lang-options\" \"ghc-options\" \"source-dirs\" \"entrypoints\" \"needs-build-output\" (exit 1): failed"}}
2018-06-04 00:03:34.868327669 [ThreadId 5] - <--2--{"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///home/jaro/Data/haskell/haskell-lsp-client/Test.hs","diagnostics":[]}}

Then it hangs, while it should send some sort of error as response to the documentSymbol request.

[alanz]

Ok, I think the problem is that the processing is suspended (using IdeResponseDeferred), but when the module loading fails the deferred processing is not triggered.

cc @wz1000 , @Bubba

[lukel97]

@alanz I have a branch for this https://github.com/Bubba/haskell-ide-engine/tree/deferred-response-failures I need to test it a bit more before I make a PR

[alanz]

ok, thanks. If you like I can take it forward too, as I want to wrap my brain around the processing.

To me it looks like deleteCachedModule and markCacheStale need to flush the cache, and we need to call deleteCachedModule on load error, or at least flush the pending deferreds.

[lukel97]

Sure, that branch only adds the sending back of a ModuleFailed result whenever setTypecheckModule fails, we probably need to do that cache flushing stuff as well.

On 4 Jun 2018, at 09:56, Alan Zimmerman notifications@github.com wrote:

ok, thanks. If you like I can take it forward too, as I want to wrap my brain around the processing.

To me it looks like deleteCachedModule and markCacheStale need to flush the cache, and we need to call deleteCachedModule on load error, or at least flush the pending deferreds.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/haskell/haskell-ide-engine/issues/619#issuecomment-394363540, or mute the thread https://github.com/notifications/unsubscribe-auth/ACX4jLGQx1nLkZ7BogQScnk6VzmjHQ5Qks5t5TycgaJpZM4UYOuM.

[alanz]

@noughtmare can you try this again using https://github.com/alanz/haskell-ide-engine/tree/deferred-response-failures-rebased?

I think it is going to give you an error rather than an empty list, but at least it should respond.

[alanz]

Turned into a PR at https://github.com/haskell/haskell-ide-engine/pull/621

[noughtmare]

Yes, that fixes it.