Characterize eval plugin race leading to GetLinkable errors

ghcide/src/Development/IDE/Core/Compile.hs

@@ -529,7 +529,8 @@ mkHiFileResultCompile se session' tcm simplified_guts = catchErrs $ do
             core_file = codeGutsToCoreFile iface_hash guts
             iface_hash = getModuleHash final_iface
         core_hash1 <- atomicFileWrite se core_fp $ \fp ->
-          writeBinCoreFile fp core_file
+
+          trace ("TRACE: writeBinCoreFile: core_fp=" <> core_fp) $ writeBinCoreFile fp core_file
         -- We want to drop references to guts and read in a serialized, compact version
         -- of the core file from disk (as it is deserialised lazily)
         -- This is because we don't want to keep the guts in memory for every file in
@@ -1448,6 +1449,9 @@ instance NFData IdeLinkable where
 ml_core_file :: ModLocation -> FilePath
 ml_core_file ml = ml_hi_file ml <.> "core"
 
+ts :: Show a => String -> a -> a
+ts label x = trace ("TRACE: " <> label <> "=" <> show x) x
+
 -- | Returns an up-to-date module interface, regenerating if needed.
 --   Assumes file exists.
 --   Requires the 'HscEnv' to be set up with dependencies

ghcide/src/Development/IDE/Core/FileStore.hs

@@ -71,7 +71,7 @@ import           Language.LSP.VFS
 import           System.FilePath
 import           System.IO.Error
 import           System.IO.Unsafe
-
+import           Debug.Trace
 
 data Log
   = LogCouldNotIdentifyReverseDeps !NormalizedFilePath
@@ -250,7 +250,10 @@ setSomethingModified vfs state keys reason = do
     atomically $ do
         writeTQueue (indexQueue $ hiedbWriter $ shakeExtras state) (\withHieDb -> withHieDb deleteMissingRealFiles)
         modifyTVar' (dirtyKeys $ shakeExtras state) $ \x ->
-            foldl' (flip insertKeySet) x keys
+            foldl' (\xs k ->
+              --trace ("TRACE: insertDirkyKey: " <> show k) $
+
+             insertKeySet k xs) x keys
     void $ restartShakeSession (shakeExtras state) vfs reason []
 
 registerFileWatches :: [String] -> LSP.LspT Config IO Bool

ghcide/src/Development/IDE/Core/Rules.hs

@@ -181,7 +181,7 @@ import           GHC                                          (mgModSummaries)
 import qualified Data.IntMap                                  as IM
 #endif
 
-
+import           Debug.Trace
 
 data Log
   = LogShake Shake.Log
@@ -951,7 +951,7 @@ getModIfaceRule recorder = defineEarlyCutoff (cmapWithPrio LogShake recorder) $
       hsc <- hscEnv <$> use_ GhcSessionDeps f
       let compile = fmap ([],) $ use GenerateCore f
       se <- getShakeExtras
-      (diags, !mbHiFile) <- writeCoreFileIfNeeded se hsc linkableType compile tmr
+      (diags, !mbHiFile) <- writeCoreFileIfNeeded se hsc (ts2 "linkableType" f linkableType) compile tmr
       let fp = hiFileFingerPrint <$> mbHiFile
       hiDiags <- case mbHiFile of
         Just hiFile
@@ -980,6 +980,12 @@ incrementRebuildCount = do
   count <- getRebuildCountVar <$> getIdeGlobalAction
   liftIO $ atomically $ modifyTVar' count (+1)
 
+ts :: Show a => String -> a -> a
+ts label x = trace ("TRACE: " <> label <> "=" <> show x) x
+
+ts2 :: Show a => String -> NormalizedFilePath -> a -> a
+ts2 label nfp x = trace ("TRACE: " <> label <> "=" <> show x <> " (" <> show nfp <> ")") x
+
 -- | Also generates and indexes the `.hie` file, along with the `.o` file if needed
 -- Invariant maintained is that if the `.hi` file was successfully written, then the
 -- `.hie` and `.o` file (if needed) were also successfully written
@@ -1005,7 +1011,7 @@ regenerateHiFile sess f ms compNeeded = do
                 se <- getShakeExtras
 
                 -- Bang pattern is important to avoid leaking 'tmr'
-                (diags'', !res) <- writeCoreFileIfNeeded se hsc compNeeded compile tmr
+                (diags'', !res) <- writeCoreFileIfNeeded se hsc (ts2 "compNeeded" f compNeeded) compile tmr
 
                 -- Write hi file
                 hiDiags <- case res of

ghcide/src/Development/IDE/Core/Shake.hs

@@ -172,6 +172,7 @@ import qualified StmContainers.Map                      as STM
 import           System.FilePath                        hiding (makeRelative)
 import           System.IO.Unsafe                       (unsafePerformIO)
 import           System.Time.Extra
+import           Debug.Trace
 -- See Note [Guidelines For Using CPP In GHCIDE Import Statements]
 
 #if !MIN_VERSION_ghc(9,3,0)
@@ -1234,7 +1235,9 @@ defineEarlyCutoff' doDiagnostics cmp key file mbOld mode action = do
                     (if eq then ChangedRecomputeSame else ChangedRecomputeDiff)
                     (encodeShakeValue bs) $
                     A res
-        liftIO $ atomicallyNamed "define - dirtyKeys" $ modifyTVar' dirtyKeys (deleteKeySet $ toKey key file)
+        liftIO $ atomicallyNamed "define - dirtyKeys" $ modifyTVar' dirtyKeys (
+            trace ("TRACE: delete dirty key " <> show key <> " file " <> show file) $
+              deleteKeySet $ toKey key file)
         return res
   where
     -- Highly unsafe helper to compute the version of a file

plugins/hls-eval-plugin/src/Ide/Plugin/Eval/Rules.hs

@@ -41,7 +41,7 @@ import           GHC.Parser.Annotation
 import           Ide.Logger                           (Recorder, WithPriority,
                                                        cmapWithPrio)
 import           Ide.Plugin.Eval.Types
-
+import Debug.Trace
 
 rules :: Recorder (WithPriority Log) -> Rules ()
 rules recorder = do
@@ -56,13 +56,13 @@ instance IsIdeGlobal EvaluatingVar
 queueForEvaluation :: IdeState -> NormalizedFilePath -> IO ()
 queueForEvaluation ide nfp = do
     EvaluatingVar var <- getIdeGlobalState ide
-    atomicModifyIORef' var (\fs -> (Set.insert nfp fs, ()))
+    atomicModifyIORef' var (\fs -> (trace ("TRACE: queueForEvaluation: " <> show nfp ) $ Set.insert nfp fs, ()))
 
 unqueueForEvaluation :: IdeState -> NormalizedFilePath -> IO ()
 unqueueForEvaluation ide nfp = do
     EvaluatingVar var <- getIdeGlobalState ide
     -- remove the module from the Evaluating state, so that next time it won't evaluate to True
-    atomicModifyIORef' var $ \fs -> (Set.delete nfp fs, ())
+    atomicModifyIORef' var $ \fs -> (trace ("TRACE: unqueueForEvaluation: " <> show nfp ) $ Set.delete nfp fs, ())
 
 apiAnnComments' :: ParsedModule -> [SrcLoc.RealLocated EpaCommentTok]
 apiAnnComments' pm = do
@@ -110,7 +110,7 @@ isEvaluatingRule :: Recorder (WithPriority Log) -> Rules ()
 isEvaluatingRule recorder = defineEarlyCutoff (cmapWithPrio LogShake recorder) $ RuleNoDiagnostics $ \IsEvaluating f -> do
     alwaysRerun
     EvaluatingVar var <- getIdeGlobalAction
-    b <- liftIO $ (f `Set.member`) <$> readIORef var
+    b <- fmap (ts2 "isMemberEvaluatingVar" f) . liftIO $ (f `Set.member`) <$> readIORef var
     return (Just (if b then BS.singleton 1 else BS.empty), Just b)
 
 -- Redefine the NeedsCompilation rule to set the linkable type to Just _
@@ -120,12 +120,15 @@ isEvaluatingRule recorder = defineEarlyCutoff (cmapWithPrio LogShake recorder) $
 -- leading to much better performance of the evaluate code lens
 redefinedNeedsCompilation :: Recorder (WithPriority Log) -> Rules ()
 redefinedNeedsCompilation recorder = defineEarlyCutoff (cmapWithPrio LogShake recorder) $ RuleWithCustomNewnessCheck (<=) $ \NeedsCompilation f -> do
-    isEvaluating <- use_ IsEvaluating f
+    isEvaluating <- ts2 "isEvaluating" f  <$> use_ IsEvaluating f
 
     if not isEvaluating then needsCompilationRule f else do
         ms <- msrModSummary . fst <$> useWithStale_ GetModSummaryWithoutTimestamps f
         let df' = ms_hspp_opts ms
             linkableType = computeLinkableTypeForDynFlags df'
             fp = encodeLinkableType $ Just linkableType
 
-        pure (Just fp, Just (Just linkableType))
+        pure (Just fp, ts2 "redefinedNeedsCompilation" f $ Just (Just linkableType))
+
+ts2 :: Show a => String -> NormalizedFilePath -> a -> a
+ts2 label nfp x = trace ("TRACE: " <> label <> "=" <> show x <> "(" <> show nfp <> ")") x

tmp-notes.md

@@ -0,0 +1,33 @@
+HRK:|OK|FAIL|error
+
+OK|FAIL|error|isEvaluating|queueForEvaluation|unqueueForEvaluation|writeBinCoreFile
+
+
+(HRK: writeBinCoreFile)|(HRK: linkableType=Just BCOLinkable)|OK|FAIL|error
+
+Theory:
+
+Every test that succeeds has the following sequence:
+
+
+HRK: linkableType=Just BCOLinkable
+HRK: writeCoreFileIfNeeded: guts=modguts
+HRK: writeBinCoreFile /tmp/hls-test-root/.cache/ghcide/test-0.1.0.0-inplace-1af041e620a747f3eee9125b6968276b7bf496d0/extra-file-30552027971537-267991-12
+
+
+
+
+
+
+
+
+In order for `GetLinkable` rule to succeed, the
+
+The core file is written [here](https://github.com/haskell/haskell-language-server/blob/9593d04a76e024942981b1333bfb2558a6ae0dab/ghcide/src/Development/IDE/Core/Compile.hs#L532)
+
+But this core-file-writing code path is only triggered when  is called with `linkableType == Just BCOLinkable`.
+
+In the case when we get the `GetLinkable` error, the `linkableType` is always `Nothing`.
+
+
+