First hover differs from subsequent hovers

[evenbrenden]

When opening a file, the first hover request is missing some information (like description and documentation links) compared to later requests. This happens for each file opened for the first time during an HLS session. The RPC requests appears to be identical (except for the id field), so I'm ruling out the client as a source of the issue.

hover.mp4

Your environment

Which OS do you use?

NixOS

Which version of GHC do you use and how did you install it?

9.0.2 from Nix

How is your project built (alternative: link to the project)?

I can reproduce this issue with both Cabal and standalone modules/files.

Which LSP client (editor/plugin) do you use?

Neovim LSP client

Which version of HLS do you use and how did you install it?

1.7.0.0 from Nix

Have you configured HLS in any way (especially: a hie.yaml file)?

Using implicit-hie for Cabal projects, no configuration for standalone modules/files.

Steps to reproduce

1. Open a file.
2. Hover on a non-local symbol.
3. Close the preview.
4. Hover on the same symbol again.

Expected behaviour

First hover should give the same information as the second hover.

Actual behaviour

First hover is missing information like description and documentation links.

Debug information

LSP logs for the first hover:

[DEBUG][2022-07-21 22:16:15] .../lua/vim/lsp.lua:1023	"LSP[hls]"	"client.request"	1	"textDocument/hover"	{  position = {    character = 7,    line = 3  },  textDocument = {    uri = "file:///home/evenbrenden/Downloads/Main.hs"  }}	<function 1>	1
[DEBUG][2022-07-21 22:16:15] .../vim/lsp/rpc.lua:347	"rpc.send"	{  id = 2,  jsonrpc = "2.0",  method = "textDocument/hover",  params = {    position = {      character = 7,      line = 3    },    textDocument = {      uri = "file:///home/evenbrenden/Downloads/Main.hs"    }  }}
[ERROR][2022-07-21 22:16:15] .../vim/lsp/rpc.lua:420	"rpc"	"haskell-language-server-wrapper"	"stderr"	"2022-07-21T20:16:15.387204Z | Debug | GhcIde.hover entered (ideLogger)\n2022-07-21T20:16:15.387370Z | Debug | Hover request at position 4:8 in file: /home/evenbrenden/Downloads/Main.hs\n2022-07-21T20:16:15.387562Z | Debug | LOOKUP UP PERSISTENT FOR: GetDocMap\n2022-07-21T20:16:15.387647Z | Debug | Finished: C:GetHieAst:/home/evenbrenden/Downloads/Main.hs Took: 0.00s\n2022-07-21T20:16:15.387647Z | Debug | Finished: C:GhcSession:/home/evenbrenden/Downloads/Main.hs Took: 0.00s\n"
[DEBUG][2022-07-21 22:16:15] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  jsonrpc = "2.0",  method = "window/logMessage",  params = {    message = "GhcIde.hover entered (ideLogger)",    type = 4  }}
[DEBUG][2022-07-21 22:16:15] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  jsonrpc = "2.0",  method = "window/logMessage",  params = {    message = "Hover request at position 4:8 in file: /home/evenbrenden/Downloads/Main.hs",    type = 4  }}
[DEBUG][2022-07-21 22:16:15] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  jsonrpc = "2.0",  method = "window/logMessage",  params = {    message = "LOOKUP UP PERSISTENT FOR: GetDocMap",    type = 4  }}
[DEBUG][2022-07-21 22:16:15] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  id = 2,  jsonrpc = "2.0",  result = {    contents = {      kind = "markdown",      value = "\n```haskell\nreturn :: forall (m :: * -> *) a. Monad m => a -> m a\n```\n\n*Defined in ‘GHC.Base’*\n *(base-4.15.1.0)*\n* * *\n\n```haskell\n$dMonad :: Monad IO\n```\n\n* * *\n\n```haskell\n_ :: () -> IO ()\n```\n* * *\n\n```haskell\n_ :: forall (m :: * -> *) a. Monad m => a -> m a\n```\n"    },    range = {      end = {        character = 13,        line = 3      },      start = {        character = 7,        line = 3      }    }  }}
[ERROR][2022-07-21 22:16:15] .../vim/lsp/rpc.lua:420	"rpc"	"haskell-language-server-wrapper"	"stderr"	"2022-07-21T20:16:15.390021Z | Debug | Finished: C:GetDocMap:/home/evenbrenden/Downloads/Main.hs Took: 0.00s\n"
[DEBUG][2022-07-21 22:16:15] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  jsonrpc = "2.0",  method = "window/logMessage",  params = {    message = "Finished: C:GetHieAst:/home/evenbrenden/Downloads/Main.hs Took: 0.00s",    type = 4  }}
[DEBUG][2022-07-21 22:16:15] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  jsonrpc = "2.0",  method = "window/logMessage",  params = {    message = "Finished: C:GhcSession:/home/evenbrenden/Downloads/Main.hs Took: 0.00s",    type = 4  }}
[DEBUG][2022-07-21 22:16:15] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  jsonrpc = "2.0",  method = "window/logMessage",  params = {    message = "Finished: C:GetDocMap:/home/evenbrenden/Downloads/Main.hs Took: 0.00s",    type = 4  }}
[INFO][2022-07-21 22:16:15] ...lsp/handlers.lua:458	"GhcIde.hover entered (ideLogger)"
[INFO][2022-07-21 22:16:15] ...lsp/handlers.lua:458	"Hover request at position 4:8 in file: /home/evenbrenden/Downloads/Main.hs"
[INFO][2022-07-21 22:16:15] ...lsp/handlers.lua:458	"LOOKUP UP PERSISTENT FOR: GetDocMap"
[INFO][2022-07-21 22:16:15] ...lsp/handlers.lua:458	"Finished: C:GetHieAst:/home/evenbrenden/Downloads/Main.hs Took: 0.00s"
[INFO][2022-07-21 22:16:15] ...lsp/handlers.lua:458	"Finished: C:GhcSession:/home/evenbrenden/Downloads/Main.hs Took: 0.00s"
[INFO][2022-07-21 22:16:15] ...lsp/handlers.lua:458	"Finished: C:GetDocMap:/home/evenbrenden/Downloads/Main.hs Took: 0.00s"

LSP log for the second hover:

[DEBUG][2022-07-21 22:16:18] .../lua/vim/lsp.lua:1023	"LSP[hls]"	"client.request"	1	"textDocument/hover"	{  position = {    character = 7,    line = 3  },  textDocument = {    uri = "file:///home/evenbrenden/Downloads/Main.hs"  }}	<function 1>	1
[DEBUG][2022-07-21 22:16:18] .../vim/lsp/rpc.lua:347	"rpc.send"	{  id = 3,  jsonrpc = "2.0",  method = "textDocument/hover",  params = {    position = {      character = 7,      line = 3    },    textDocument = {      uri = "file:///home/evenbrenden/Downloads/Main.hs"    }  }}
[ERROR][2022-07-21 22:16:18] .../vim/lsp/rpc.lua:420	"rpc"	"haskell-language-server-wrapper"	"stderr"	"2022-07-21T20:16:18.184501Z | Debug | GhcIde.hover entered (ideLogger)\n2022-07-21T20:16:18.184760Z | Debug | Hover request at position 4:8 in file: /home/evenbrenden/Downloads/Main.hs\n2022-07-21T20:16:18.185066Z | Debug | Finished: C:GhcSession:/home/evenbrenden/Downloads/Main.hs Took: 0.00s\n2022-07-21T20:16:18.185068Z | Debug | Finished: C:GetHieAst:/home/evenbrenden/Downloads/Main.hs Took: 0.00s\n2022-07-21T20:16:18.186434Z | Debug | Finished: C:GetDocMap:/home/evenbrenden/Downloads/Main.hs Took: 0.00s\n"
[DEBUG][2022-07-21 22:16:18] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  jsonrpc = "2.0",  method = "window/logMessage",  params = {    message = "GhcIde.hover entered (ideLogger)",    type = 4  }}
[DEBUG][2022-07-21 22:16:18] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  jsonrpc = "2.0",  method = "window/logMessage",  params = {    message = "Hover request at position 4:8 in file: /home/evenbrenden/Downloads/Main.hs",    type = 4  }}
[DEBUG][2022-07-21 22:16:18] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  id = 3,  jsonrpc = "2.0",  result = {    contents = {      kind = "markdown",      value = "\n```haskell\nreturn :: forall (m :: * -> *) a. Monad m => a -> m a\n```\n\n*Defined in ‘GHC.Base’*\n *(base-4.15.1.0)*\n\n\nInject a value into the monadic type.\n\n[Documentation](file:///nix/store/5xxas1y13lirgyb67g22j38fvnbsvrrb-ghc-9.0.2-doc/share/doc/ghc/html/libraries/base-4.15.1.0/GHC-Base.html#v:return)\n\n[Source](file:///nix/store/5xxas1y13lirgyb67g22j38fvnbsvrrb-ghc-9.0.2-doc/share/doc/ghc/html/libraries/base-4.15.1.0/src/GHC-Base.html#return)\n\n\n* * *\n\n```haskell\n$dMonad :: Monad IO\n```\n\n* * *\n\n```haskell\n_ :: () -> IO ()\n```\n* * *\n\n```haskell\n_ :: forall (m :: * -> *) a. Monad m => a -> m a\n```\n"    },    range = {      end = {        character = 13,        line = 3      },      start = {        character = 7,        line = 3      }    }  }}
[DEBUG][2022-07-21 22:16:18] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  jsonrpc = "2.0",  method = "window/logMessage",  params = {    message = "Finished: C:GhcSession:/home/evenbrenden/Downloads/Main.hs Took: 0.00s",    type = 4  }}
[DEBUG][2022-07-21 22:16:18] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  jsonrpc = "2.0",  method = "window/logMessage",  params = {    message = "Finished: C:GetHieAst:/home/evenbrenden/Downloads/Main.hs Took: 0.00s",    type = 4  }}
[DEBUG][2022-07-21 22:16:18] .../vim/lsp/rpc.lua:454	"rpc.receive"	{  jsonrpc = "2.0",  method = "window/logMessage",  params = {    message = "Finished: C:GetDocMap:/home/evenbrenden/Downloads/Main.hs Took: 0.00s",    type = 4  }}
[INFO][2022-07-21 22:16:18] ...lsp/handlers.lua:458	"GhcIde.hover entered (ideLogger)"
[INFO][2022-07-21 22:16:18] ...lsp/handlers.lua:458	"Hover request at position 4:8 in file: /home/evenbrenden/Downloads/Main.hs"
[INFO][2022-07-21 22:16:18] ...lsp/handlers.lua:458	"Finished: C:GhcSession:/home/evenbrenden/Downloads/Main.hs Took: 0.00s"
[INFO][2022-07-21 22:16:18] ...lsp/handlers.lua:458	"Finished: C:GetHieAst:/home/evenbrenden/Downloads/Main.hs Took: 0.00s"
[INFO][2022-07-21 22:16:18] ...lsp/handlers.lua:458	"Finished: C:GetDocMap:/home/evenbrenden/Downloads/Main.hs Took: 0.00s"

Full LSP log for the session: lsp.log

[evenbrenden]

Actually, this happens for each symbol for each file. For example, if I add an expression with print to the example file above, I need to hover over that symbol twice too to get all the available information.

[July541]

If I understand correctly, hover behavior is designed to respond to necessary info asap, here we respond to type info first and attach other comments while available.

To verify this, you can open a project and wait for some while, hover on print will show all info we have even if it is the first time.

[evenbrenden]

To verify this, you can open a project and wait for some while, hover on print will show all info we have even if it is the first time.

I tried waiting 60+ seconds and the behaviour is the same. So I don't think this depends on any timing.

From what I gather, the LOOKUP UP PERSISTENT FOR log statements are what separates the first hover from the second one.

[lordmilko]

The same behavior occurs on Windows with vscode. The following science experiment shows it doesn't seem to have anything to do with the amount of time being waited

1. Hover over a function containing a comment
2. Dismiss the hover
3. Add an exclamation point to the comment. A flurry of LSP events are generated as the server is notified of the change of text
4. Wait 5 seconds
5. Hover over the function. The previous comment is still displayed
6. Dismiss the hover and quickly re-hover
7. The new comment is now displayed

This would appear to demonstrate that the act of demanding a hover in step 5 results in a change in state that is only then accessible when you re-request a hover in step 7. In the event a hover event is going to trigger a time consuming operation, it would make sense to me to make a best-effort and at least give it a second or two before timing out and defaulting to a more basic response

[expipiplus1]

hover behavior is designed to respond to necessary info asap

I would gladly suffer a delay to get this more reliably as it's pretty much the only thing I use the hover for (or better yet maybe some dedicated call for getting these links)

For any neovim users, here's a workaround which calls hover twice in quick succession to get and open the link: mrcjkb/haskell-tools.nvim#395 (comment)