ghcid sometimes fails to parse valid source file

[rcook]

On saving a valid source file from VSCode, sometimes ghcid will fail to interpret the code. The most common error I have seen is the following:

<interactive>:68:53-56: error:
    • Variable not in scope: main :: IO a0
    • Perhaps you meant ‘min’ (imported from Prelude)

...done

This suggests that the source file is temporarily empty or something. I've not seen this happen much (if at all) on macOS. I wonder if there is some kind of race condition in the file watcher employed by ghcid. Alternatively, this could be some strange behaviour exclusive to VSCode and/or an interaction between the Haskero plugin and VSCode. I'll report back with more information as I get it.

Environment:

• Ubuntu Desktop 18.04
• VSCode 1.28.2 (with Haskero plugin)
• Haskell Stack 1.9.1

Repro:

1. Create new, empty project using Haskell Stack:

   stack new ghcid-demo simple
   cd ghcid-demo
   mv \{\{name\}\}.cabal ghcid-demo.cabal
   echo resolver: lts-12.16 >> stack.yaml
   echo packages: [.] >> stack.yaml

2. From newly created project directory, start VSCode with code .
3. Open integrated terminal in VSCode
4. Inside integrated terminal, start ghcid with stack exec ghcid
5. Make edits to src/Main.hs and save a few times

Approximately every other time I save, ghcid will fail to typecheck the source file with the error above regardless of whether the source file is valid Haskell or not.

Update (1): I experimented using Vim instead of VSCode. I ran tmux to split my terminal with Vim in one split and stack exec ghcid in the other. I cannot reproduce the failure with this configuration.

Update (2): Back in VSCode, I tried repeating the scenario with Haskero both enabled and disabled. This seems to make no difference: I still see invalid parses from ghcid from time to time.

This suggests that there might be something fishy about how VSCode saves files.

[ndmitchell]

Weird. I use vs code on Mac and Windows and it's rock solid there. Some editors (Vim) do weird delete, rename, recreate tricks and ghcid works around them. Any idea why it says line 68 of interactive? That strikes me as odd. The --verbose output of ghcid might help shed some light, it's pretty explicit about all the steps it takes.

[rcook]

Sample program Main.hs (the content doesn't matter - as long as it's valid Haskell):

{-# LANGUAGE DataKinds #-}
{-# LANGUAGE GADTs #-}
{-# LANGUAGE KindSignatures #-}
{-# LANGUAGE TypeFamilies #-}
{-# LANGUAGE UndecidableInstances #-}

module Main (main) where

data Nat = Zero | Succ Nat

data Vector (n :: Nat) (a :: *) where
    VNil :: Vector 'Zero a
    VCons :: a -> Vector n a -> Vector ('Succ n) a

instance Show a => Show (Vector n a) where
    show VNil = "VNil"
    show (VCons a as) = "VCons " ++ show a ++ " (" ++ show as ++ ")"

add :: Nat -> Nat -> Nat
add Zero n = n
add (Succ n) m = add n (Succ m)

type family Add n m where
    Add 'Zero n = n
    Add ('Succ n) m = Add n ('Succ m)

main :: IO ()
main = do
    putStrLn "Hello"

Here's the output of running stack exec ghcid -- --verbose 2>&1 | tee ../out.txt in response to typing extra spaces at the end of the file and saving from VSCode repeatedly:

%STDIN: :reload
%STDIN: INTERNAL_GHCID.putStrLn ['#','~','G','H','C','I','D','-','F','I','N','I','S','H','-','1','7','~','#']
INTERNAL_GHCID.hPutStrLn INTERNAL_GHCID.stderr ['#','~','G','H','C','I','D','-','F','I','N','I','S','H','-','1','7','~','#']
%NOTIFY: Modified "/home/rcook/src/tlph/src/Main.hs" 2018-11-23 17:31:01.557799827 UTC False
%STDOUT: #~GHCID-START~##~GHCID-START~#[1 of 1] Compiling Main             ( /home/rcook/src/tlph/src/Main.hs, nothing )
%STDOUT: Ok, one module loaded.
%STDOUT: #~GHCID-START~##~GHCID-FINISH-17~#
%STDERR: #~GHCID-FINISH-17~#
%STDIN: :show modules
%STDIN: INTERNAL_GHCID.putStrLn ['#','~','G','H','C','I','D','-','F','I','N','I','S','H','-','1','8','~','#']
INTERNAL_GHCID.hPutStrLn INTERNAL_GHCID.stderr ['#','~','G','H','C','I','D','-','F','I','N','I','S','H','-','1','8','~','#']
%STDOUT: #~GHCID-START~##~GHCID-START~#Main             ( /home/rcook/src/tlph/src/Main.hs, nothing )
%STDOUT: #~GHCID-START~##~GHCID-FINISH-18~#
%STDERR: #~GHCID-FINISH-18~#
%MESSAGES: [Loading {loadModule = "Main", loadFile = "/home/rcook/src/tlph/src/Main.hs"}]
%LOADED: ["/home/rcook/src/tlph/src/Main.hs"]
]0;All good, at 09:31:01 - tlph
All good (1 module, at 09:31:01)

%WAITING: /home/rcook/src/tlph/.ghcid ./stack.yaml /home/rcook/src/tlph/tlph.cabal /home/rcook/.ghc/ghci.conf /tmp/haskell-stack-ghci/57f1a991/ghci-script /home/rcook/src/tlph/src/Main.hs
%WAITING: /home/rcook/.ghc /home/rcook/src/tlph /home/rcook/src/tlph/src /tmp/haskell-stack-ghci/57f1a991
%NOTIFY: Modified "/home/rcook/src/tlph/src/Main.hs" 2018-11-23 17:31:29.740270498 UTC False
%WAITING: Notify signaled
%RELOADING: /home/rcook/src/tlph/src/Main.hs

Reloading...
  /home/rcook/src/tlph/src/Main.hs

%STDIN: :reload
%STDIN: INTERNAL_GHCID.putStrLn ['#','~','G','H','C','I','D','-','F','I','N','I','S','H','-','1','9','~','#']
INTERNAL_GHCID.hPutStrLn INTERNAL_GHCID.stderr ['#','~','G','H','C','I','D','-','F','I','N','I','S','H','-','1','9','~','#']
%NOTIFY: Modified "/home/rcook/src/tlph/src/Main.hs" 2018-11-23 17:31:29.745815983 UTC False
%STDOUT: #~GHCID-START~##~GHCID-START~#[1 of 1] Compiling Main             ( /home/rcook/src/tlph/src/Main.hs, nothing )
%STDERR: 
%STDERR: /home/rcook/src/tlph/src/Main.hs:1:1: error:
%STDERR:     The IO action ‘main’ is not defined in module ‘Main’
%STDERR:   |
%STDERR: 1 | {-# LANGUAGE DataKinds #-}
%STDERR:   | ^
%STDOUT: Failed, no modules loaded.
%STDOUT: #~GHCID-START~##~GHCID-FINISH-19~#
%STDERR: #~GHCID-FINISH-19~#
%STDIN: :show modules
%STDIN: INTERNAL_GHCID.putStrLn ['#','~','G','H','C','I','D','-','F','I','N','I','S','H','-','2','0','~','#']
INTERNAL_GHCID.hPutStrLn INTERNAL_GHCID.stderr ['#','~','G','H','C','I','D','-','F','I','N','I','S','H','-','2','0','~','#']
%STDOUT: #~GHCID-START~##~GHCID-START~##~GHCID-START~##~GHCID-FINISH-20~#
%STDERR: #~GHCID-FINISH-20~#
%MESSAGES: [Loading {loadModule = "Main", loadFile = "/home/rcook/src/tlph/src/Main.hs"},Message {loadSeverity = Error, loadFile = "/home/rcook/src/tlph/src/Main.hs", loadFilePos = (1,1), loadFilePosEnd = (1,1), loadMessage = ["\ESC[;1m/home/rcook/src/tlph/src/Main.hs:1:1: \ESC[;1m\ESC[31merror:\ESC[0m\ESC[0m\ESC[;1m\ESC[0m\ESC[0m\ESC[;1m","    The IO action \8216main\8217 is not defined in module \8216Main\8217\ESC[0m\ESC[0m","\ESC[;1m\ESC[34m  |\ESC[0m\ESC[0m","\ESC[;1m\ESC[34m1 |\ESC[0m\ESC[0m \ESC[;1m\ESC[31m{\ESC[0m\ESC[0m-# LANGUAGE DataKinds #-}","\ESC[;1m\ESC[34m  |\ESC[0m\ESC[0m\ESC[;1m\ESC[31m ^\ESC[0m\ESC[0m"]}]
%LOADED: ["/home/rcook/src/tlph/src/Main.hs"]
]0;1 error - tlph
/home/rcook/src/tlph/src/Main.hs:1:1: error:
    The IO action ‘main’ is not defined in module ‘Main’
  |
1 | {-# LANGUAGE DataKinds #-}
  | ^

%WAITING: /home/rcook/src/tlph/.ghcid ./stack.yaml /home/rcook/src/tlph/tlph.cabal /home/rcook/.ghc/ghci.conf /tmp/haskell-stack-ghci/57f1a991/ghci-script /home/rcook/src/tlph/src/Main.hs
%WAITING: /home/rcook/.ghc /home/rcook/src/tlph /home/rcook/src/tlph/src /tmp/haskell-stack-ghci/57f1a991

[ndmitchell]

That's not something I've seen before - it looks like ghci has seen the file half written which an editor should never do. Are you using an up to date vs code and ghcid? Is there some kind of overwrite in place option enabled?

[rcook]

$ uname -a
Linux mymachine 4.15.0-38-generic #41-Ubuntu SMP Wed Oct 10 10:59:38 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
$ code --version
1.29.1
bc24f98b5f70467bc689abf41cc5550ca637088e
x64
$ stack --version
Version 1.9.1, Git revision f9d0042c141660e1d38f797e1d426be4a99b2a3c (6168 commits) x86_64 hpack-0.31.0
$ stack exec ghcid -- --version
Auto reloading GHCi daemon v0.7.1

[rcook]

I've disabled all Haskell-related extensions in VSCode (using --disable-extensions) and reset all settings to default (by deleting settings.json etc.) and the problem persists.

[rcook]

I just did some experimentation with inotifywait:

#!/bin/bash
while inotifywait -e modify src/Main.hs; do
  stat src/Main.hs
done

This will occasionally report a zero-length file size. I think it's safe to say that this behaviour is unrelated to ghcid. It looks like some VSCode weirdness.

I'll close this issue. Thanks for your time!

[rcook]

I created a VSCode issue: https://github.com/Microsoft/vscode/issues/63720. I think that this issue might be an interaction between Git, VSCode and inotify.

[ndmitchell]

Thanks! That does seem like a VS Code bug, and one I've never seen on my machines.

[ndmitchell]

I think I do a very brief sleep after I detect a change, so would be weird that writing doesn't complete in that window. I should take a look.

[anka-213]

I have the same issue with (g)vim on Arch. About once in every 10 saves, ghcid sees a partial file.

[ndmitchell]

Does ghcid then quickly soon after spot the full file? As in you only see the partial file for a fraction of a second? It's meant to immediately rerun if it detects a file changed while it was loading.

Does adding a sleep before https://github.com/ndmitchell/ghcid/blob/master/src/Wait.hs#L108 help?

[nkpart]

I've been seeing this error about 9 times out of every 10 saves when using VSCode and the remote extensions (the remote end is an Ubuntu 19.04 box).

Adding sleep 0.05 as suggested in Wait.hs seems to fix the problem.

[ndmitchell]

If this is an issue that keeps cropping up then perhaps adding the sleep always isn't a bad idea. 0.05s is small enough that it's probably not perceptibly slower (although always sad to think of those 0.05s adding up 😢). Anyone want to whip up a PR, given that I can't test it as it works robustly for me.