Weird crash on a module importing th definitions that runs IO

[maksbotan]

hie works fine on all modules in my project except one. I see this in logs (--debug --vomit):

2019-12-12 22:46:12.402861 [ThreadId 4] - ---> {"jsonrpc":"2.0","method":"textDocument/didOpen","params":{"textDocument":{ **MY MODULE HERE**
2019-12-12 22:46:12.404909 [ThreadId 10] - ****** reactor: got message number:8
2019-12-12 22:46:12.404973 [ThreadId 10] - ****** reactor: processing NotDidOpenTextDocument
2019-12-12 22:46:12.405081 [ThreadId 10] - requestDiagnostics: no diagFunc for:DiagnosticOnOpen
2019-12-12 22:46:12.405115 [ThreadId 10] - ****** reactor: top of loop
2019-12-12 22:46:12.405152 [ThreadId 12] - ghcDispatcher:got request 8 with id: Nothing
2019-12-12 22:46:12.406491 [ThreadId 12] - file mapping state is: fromList **MY FILES**
2019-12-12 22:46:12.406616 [ThreadId 12] - ghcDispatcher: top of loop
2019-12-12 22:46:12.406647 [ThreadId 12] - ghcDispatcher:got request 8 with id: Nothing
2019-12-12 22:46:12.406678 [ThreadId 12] - ghcDispatcher:Processing request as version matches
2019-12-12 22:46:12.447532 [ThreadId 12] - ghcDispatcher: top of loop
2019-12-12 22:46:12.447631 [ThreadId 12] - ghcDispatcher:got request 8 with id: Nothing
2019-12-12 22:46:12.447662 [ThreadId 12] - ghcDispatcher:Processing request as version matches
2019-12-12 22:46:12.44801 [ThreadId 12] - setTypecheckedModule: file mapping state is: fromList **MY FILES**
2019-12-12 22:46:12.448073 [ThreadId 12] - setTypecheckedModule: before ghc-mod
2019-12-12 22:46:12.487182 [ThreadId 6] - <--2--{"jsonrpc":"2.0","params":{"uri":"THAT MODULE","diagnostics":[]},"method":"textDocument/publishDiagnostics"}
2019-12-12 22:46:13.185014 [ThreadId 4] - ---> {"jsonrpc":"2.0","id":4,"method":"textDocument/documentHighlight","params":{"textDocument":{"uri":"THAT MODULE"},"position":{"line":0,"character":0}}}
2019-12-12 22:46:13.185177 [ThreadId 10] - ****** reactor: got message number:9
2019-12-12 22:46:13.185214 [ThreadId 10] - reactor:got DocumentHighlightsRequest:RequestMessage {_jsonrpc = "2.0", _id = IdInt 4, _method = TextDocumentDocumentHighlight, _params = TextDocumentPositionParams {_textDocument = TextDocumentIdentifier {_uri = Uri {getUri = "fTHAT FILE"}}, _position = Position {_line = 0, _character = 0}, _workDoneToken = Nothing}}
2019-12-12 22:46:13.185264 [ThreadId 10] - ****** reactor: top of loop
2019-12-12 22:46:13.185894 [ThreadId 13] - ideDispatcher: got request 9 with id: IdInt 4
2019-12-12 22:46:13.186077 [ThreadId 13] - ideDispatcher: top of loop
2019-12-12 22:46:15.043613 [ThreadId 4] - run entered for hie-wrapper(hie-wrapper) Version 0.14.0.0, Git revision f7e0db0e10317a85f18a81bb5bb31bbba4d2804b (dirty) (3127 commits) x86_64 ghc-8.6.3
2019-12-12 22:46:15.04459 [ThreadId 4] - Current directory:/Users/maksbotan/...
2019-12-12 22:46:15.044633 [ThreadId 4] - Operating system:darwin
2019-12-12 22:46:15.462198 [ThreadId 4] - Cradle directory:/Users/maksbotan/...
2019-12-12 22:46:15.46241 [ThreadId 4] - Using stack GHC version
2019-12-12 22:46:15.738918 [ThreadId 4] - Project GHC version:8.6.3
2019-12-12 22:46:15.739005 [ThreadId 4] - hie exe candidates :["hie-8.6.3","hie-8.6","hie"]
2019-12-12 22:46:15.739514 [ThreadId 4] - found hie exe at:/Users/maksbotan/.local/bin/hie
2019-12-12 22:46:15.739556 [ThreadId 4] - args:["-d","-l","/tmp/hie.log","--vomit"]
2019-12-12 22:46:15.739584 [ThreadId 4] - launching ....



2019-12-12 22:46:15.81211 [ThreadId 4] - Using stack GHC version
2019-12-12 22:46:16.08133 [ThreadId 4] - Run entered for HIE(hie) Version 0.14.0.0, Git revision f7e0db0e10317a85f18a81bb5bb31bbba4d2804b (dirty) (3127 commits) x86_64 ghc-8.6.3

As you can see, hie (ghc-mod?) just dies without printing any logs. Unfortunately, I can't share my code as this is a private project at my job. Can you give any hints on how to get more info from hie?

I tried removing some code from the module, but wasn't able to find minimal offending piece...

I'm on latest master (f7e0db0e10) with GHC-8.6.3, my project uses LTS-13.6 from stack. I use nvim with coc.nvim.

[jneira]

Weird indeed! Maybe it is making stabs in the dark, but maybe starting with an empty module (with all defs to undefined?) and adding code in little steps could drive to catch the offending fragment

[maksbotan]

Hmm, I found what breaks it. Here's how to reproduce:

module TH.hs:

module TH where

import           Data.Aeson                 (Value)
import           Data.Yaml                  (decodeFileThrow)
import           Language.Haskell.TH        (Exp, Q, runIO)
import           Language.Haskell.TH.Syntax (addDependentFile, lift)

loadEnum :: FilePath -> Q Exp
loadEnum path = do
  val <- runIO $ decodeFileThrow path :: Q Value
  lift ([] :: [String])

module Exp.hs:

{-# LANGUAGE TemplateHaskell #-}

module Exp where

import TH

list :: [String]
list = $(loadEnum "test.txt")

file test.txt (this is valid yaml):

123
456

With this I get the same behavior on Exp.hs. If I comment the line with runIO in TH.hs, the problem is gone.

[maksbotan]

Maybe it's worth noting that I first observed this on a module that just imports list defined in Exp.hs, therefore I had no idea that the problem is in TH.

[jneira]

Thanks for investigating and minimize the reproduction case. For completeness: the crash is triggered when hie tries to load a module that imports, even transitively, TemplateHaskell definitions that runs IO.

[maksbotan]

Yes, looks like that. Where do you think the problem is -- in hie, ghc-mod or maybe ghc itself?

[alanz]

I think the problem is that we work with a copy of the file in a temporary directory. I suspect it is not able to find the file "test.txt".

[maksbotan]

@alanz sadly, it's probably more complicated than that.

Here's what I checked:

• Use absolute path -- crash
• Use absolute path and readFile instead of decodeFileThrow from Data.Yaml -- works
• Use relative path and readFile -- works
• Use relative path and val <- runIO $ (decodeStrict <$> BS.readFile path) :: Q (Maybe Value) (decodeStrict from aeson) -- still works
• Both decodeFileEither and decodeFileThrow from Data.Yaml -- crash
• BS.readFile path >>= decodeThrow -- crash
• decodeEither <$> BS.readFile path -- also crash

So probably the problem is somewhere in that module: http://hackage.haskell.org/package/yaml-0.11.2.0/docs/src/Data.Yaml.html

That's totally crazy.

[maksbotan]

I checked if i fails with latest snoyberg/yaml@d0a2ba62a (yaml-0.11.2.0) -- it does.

I tried with system-libyaml -- fails as well.

I was able to find a place in yaml that breaks:

https://github.com/snoyberg/yaml/blob/d0a2ba62ab48e01eedfc9989a4b5ff6021b337aa/libyaml/src/Text/Libyaml.hs#L666-L672

If I change the function to:

runParser parser = do
    let mark = YamlMark 0 0 0
    yield $ MarkedEvent EventStreamStart mark mark
    yield $ MarkedEvent EventDocumentStart mark mark
    yield $ MarkedEvent (EventScalar (B8.pack "!!!!") NoTag Plain Nothing) mark mark
    yield $ MarkedEvent EventDocumentEnd mark mark
    yield $ MarkedEvent EventStreamEnd mark mark
    return ()

-- i.e. return constant yaml without actually parsing file (but still with opening, initing C library and freeing it afterwards). And in this case, HIE does not crash. @snoyberg, maybe you can debug this problem on yaml's side?

Is there any option or patch to make HIE output when or how exactly does ghc-mod fail?

[maksbotan]

Hello.

FYI, this still happens on latest master (92ac896029a5ba5f740ebca168533c83848548c6).

Now HIE does not crash, it just doesn't work.

There is this line in the log:

2020-01-13 18:38:37.500783 [ThreadId 28] - Scheduler thread exited unexpectedly: loadObj "/private/var/folders/xm/wymzs8212vd2z4w239yz0kxr0000gn/T/ghc98091_0/ghc_4.o": failed

After that, judging by the log, it gets my commands like "hover", but does not answer.

Full log with --debug --vomit: hie.log

How can I debug this further/

[fendor]

The issue you are encountering looks like https://github.com/haskell/haskell-ide-engine/issues/1520 and currently, there is not much to debug it. The problem might occur on Modules that import Paths_*.

[maksbotan]

Well, I don't know if the two are related.

I found out that my issue is related to using "yaml" package - see above for proof. It is some weird interaction between yaml, its ffi stuff, TH and hie.

[jneira]

The error also reminds me #1207

[jneira]

• When trying to open the project in vscode if got this error in the log:

2020-01-14 18:58:50.5547596 [ThreadId 4] - <--2--{"jsonrpc":"2.0","params":{"value":{"kind":"report","percentage":0.9629629629629629,"message":"Haskell.Ide.Engine.Version"},"token":0},"method":"$/progress"}
2020-01-14 18:58:51.8267596 [ThreadId 25] - Scheduler thread exited unexpectedly: loadObj "C:\\TEMP\\ghc11780_0\\ghc_20.o": failed

The cabal project loading stops in Haskell.Ide.Engine.Version that suspiciously uses TemplateHaskell, using a definition that runs IO (to call the git program and get the last commit hash)

[ProofOfKeags]

Just ran into this in a Yesod Application. The standard Model.hs gets stuck because of PersistEntitySyntax.

[AshtonKem]

I too am having issues on a Yesod Application, but I can't tell which file it's crashing on based on the log output.

[maksbotan]

Sadly, this still happens with latest master (35f62cffb6bae6c3f86113cb0c55f52b7192689d), LTS-15.5 and GHC-8.8.3.

[useronym]

I am also experiencing this issue with some TH code that performs IO. I managed to get 2 different crash messages:

hie-8.4.4: loadObj: /tmp/ghc88723_0/ghc_145.o: file doesn't exist
2020-05-01 11:29:20.322143244 [ThreadId 28] - Scheduler thread exited unexpectedly: loadObj "/tmp/ghc88723_0/ghc_145.o": failed

2020-05-01 11:10:31.876190063 [ThreadId 29] - Scheduler thread exited unexpectedly: expectJust getLinkDeps
CallStack (from HasCallStack):
  error, called at compiler/utils/Maybes.hs:55:27 in ghc:Maybes
  expectJust, called at compiler/ghci/Linker.hs:710:28 in ghc:Linker

[Ptival]

Well, at least I don't feel alone, as I am also experiencing the expectJust getLinkDeps on some Template Haskell code! :-(