From 0d85ef1655d9232e0bbae239a5f4f13e135cdf19 Mon Sep 17 00:00:00 2001 From: Patrick Date: Thu, 2 May 2024 22:47:42 +0800 Subject: [PATCH 01/11] swap shakeShut and stopReactor --- ghcide/src/Development/IDE/LSP/LanguageServer.hs | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/ghcide/src/Development/IDE/LSP/LanguageServer.hs b/ghcide/src/Development/IDE/LSP/LanguageServer.hs index e4493436cb..7521aed938 100644 --- a/ghcide/src/Development/IDE/LSP/LanguageServer.hs +++ b/ghcide/src/Development/IDE/LSP/LanguageServer.hs @@ -262,10 +262,13 @@ shutdownHandler :: Recorder (WithPriority Log) -> IO () -> LSP.Handlers (ServerM shutdownHandler recorder stopReactor = LSP.requestHandler SMethod_Shutdown $ \_ resp -> do (_, ide) <- ask liftIO $ logWith recorder Debug LogServerShutdownMessage - -- stop the reactor to free up the hiedb connection - liftIO stopReactor + -- we need to shut down the ide session before stopping the reactor + -- since SessionIO depends on the reactor, we may hang if we stop the reactor first + -- flush out the Shake session to record a Shake profile if applicable liftIO $ shakeShut ide + -- stop the reactor to free up the hiedb connection + liftIO stopReactor resp $ Right Null exitHandler :: IO () -> LSP.Handlers (ServerM c) From abf55389fab20ec0d1c554e8f800d5b3ee1d1b3c Mon Sep 17 00:00:00 2001 From: Patrick Date: Fri, 3 May 2024 05:20:36 +0800 Subject: [PATCH 02/11] take awasy the session in shutdown to prevent race condition --- ghcide/src/Development/IDE/Core/Shake.hs | 17 +++++++++-------- .../src/Development/IDE/LSP/LanguageServer.hs | 7 ++----- 2 files changed, 11 insertions(+), 13 deletions(-) diff --git a/ghcide/src/Development/IDE/Core/Shake.hs b/ghcide/src/Development/IDE/Core/Shake.hs index a215ee42ef..4d9bf88fed 100644 --- a/ghcide/src/Development/IDE/Core/Shake.hs +++ b/ghcide/src/Development/IDE/Core/Shake.hs @@ -75,6 +75,7 @@ module Development.IDE.Core.Shake( VFSModified(..), getClientConfigAction, ) where +import Control.Concurrent (withMVar) import Control.Concurrent.Async import Control.Concurrent.STM import Control.Concurrent.STM.Stats (atomicallyNamed) @@ -724,14 +725,14 @@ shakeSessionInit recorder ide@IdeState{..} = do logWith recorder Debug LogSessionInitialised shakeShut :: IdeState -> IO () -shakeShut IdeState{..} = do - runner <- tryReadMVar shakeSession - -- Shake gets unhappy if you try to close when there is a running - -- request so we first abort that. - for_ runner cancelShakeSession - void $ shakeDatabaseProfile shakeDb - progressStop $ progress shakeExtras - stopMonitoring +shakeShut IdeState{..} = + withMVar shakeSession $ \ runner -> do + -- Shake gets unhappy if you try to close when there is a running + -- request so we first abort that. + cancelShakeSession runner + void $ shakeDatabaseProfile shakeDb + progressStop $ progress shakeExtras + stopMonitoring -- | This is a variant of withMVar where the first argument is run unmasked and if it throws diff --git a/ghcide/src/Development/IDE/LSP/LanguageServer.hs b/ghcide/src/Development/IDE/LSP/LanguageServer.hs index 7521aed938..e4493436cb 100644 --- a/ghcide/src/Development/IDE/LSP/LanguageServer.hs +++ b/ghcide/src/Development/IDE/LSP/LanguageServer.hs @@ -262,13 +262,10 @@ shutdownHandler :: Recorder (WithPriority Log) -> IO () -> LSP.Handlers (ServerM shutdownHandler recorder stopReactor = LSP.requestHandler SMethod_Shutdown $ \_ resp -> do (_, ide) <- ask liftIO $ logWith recorder Debug LogServerShutdownMessage - -- we need to shut down the ide session before stopping the reactor - -- since SessionIO depends on the reactor, we may hang if we stop the reactor first - - -- flush out the Shake session to record a Shake profile if applicable - liftIO $ shakeShut ide -- stop the reactor to free up the hiedb connection liftIO stopReactor + -- flush out the Shake session to record a Shake profile if applicable + liftIO $ shakeShut ide resp $ Right Null exitHandler :: IO () -> LSP.Handlers (ServerM c) From 53ab0d5e19c03a0f6e43f26f5d31e58281946c27 Mon Sep 17 00:00:00 2001 From: Patrick Date: Fri, 3 May 2024 05:55:14 +0800 Subject: [PATCH 03/11] use try takeMVar --- ghcide/src/Development/IDE/Core/Shake.hs | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/ghcide/src/Development/IDE/Core/Shake.hs b/ghcide/src/Development/IDE/Core/Shake.hs index 4d9bf88fed..84c723fe74 100644 --- a/ghcide/src/Development/IDE/Core/Shake.hs +++ b/ghcide/src/Development/IDE/Core/Shake.hs @@ -725,14 +725,14 @@ shakeSessionInit recorder ide@IdeState{..} = do logWith recorder Debug LogSessionInitialised shakeShut :: IdeState -> IO () -shakeShut IdeState{..} = - withMVar shakeSession $ \ runner -> do - -- Shake gets unhappy if you try to close when there is a running - -- request so we first abort that. - cancelShakeSession runner - void $ shakeDatabaseProfile shakeDb - progressStop $ progress shakeExtras - stopMonitoring +shakeShut IdeState{..} = do + runner <- tryTakeMVar shakeSession + -- Shake gets unhappy if you try to close when there is a running + -- request so we first abort that. + for_ runner cancelShakeSession + void $ shakeDatabaseProfile shakeDb + progressStop $ progress shakeExtras + stopMonitoring -- | This is a variant of withMVar where the first argument is run unmasked and if it throws From ceb7020b3fddc322d70a728a092cbb3a8d653afe Mon Sep 17 00:00:00 2001 From: Patrick Date: Fri, 3 May 2024 09:40:27 +0800 Subject: [PATCH 04/11] time out the shakeShut --- ghcide/src/Development/IDE/Core/Shake.hs | 24 +++++++++++++++--------- 1 file changed, 15 insertions(+), 9 deletions(-) diff --git a/ghcide/src/Development/IDE/Core/Shake.hs b/ghcide/src/Development/IDE/Core/Shake.hs index 84c723fe74..c3fd797240 100644 --- a/ghcide/src/Development/IDE/Core/Shake.hs +++ b/ghcide/src/Development/IDE/Core/Shake.hs @@ -197,6 +197,7 @@ data Log | LogShakeGarbageCollection !T.Text !Int !Seconds -- * OfInterest Log messages | LogSetFilesOfInterest ![(NormalizedFilePath, FileOfInterestStatus)] + | LogTimeOutShuttingDownWaitForSessionVar !Seconds deriving Show instance Pretty Log where @@ -240,6 +241,8 @@ instance Pretty Log where LogSetFilesOfInterest ofInterest -> "Set files of interst to" <> Pretty.line <> indent 4 (pretty $ fmap (first fromNormalizedFilePath) ofInterest) + LogTimeOutShuttingDownWaitForSessionVar seconds -> + "Timed out waiting for session var after" <+> pretty seconds <+> "seconds" -- | We need to serialize writes to the database, so we send any function that -- needs to write to the database over the channel, where it will be picked up by @@ -724,15 +727,18 @@ shakeSessionInit recorder ide@IdeState{..} = do putMVar shakeSession initSession logWith recorder Debug LogSessionInitialised -shakeShut :: IdeState -> IO () -shakeShut IdeState{..} = do - runner <- tryTakeMVar shakeSession - -- Shake gets unhappy if you try to close when there is a running - -- request so we first abort that. - for_ runner cancelShakeSession - void $ shakeDatabaseProfile shakeDb - progressStop $ progress shakeExtras - stopMonitoring +shakeShut :: Recorder (WithPriority Log) -> IdeState -> IO () +shakeShut recorder IdeState{..} = do + res <- timeout 1 $ withMVar shakeSession $ \runner -> do + -- Shake gets unhappy if you try to close when there is a running + -- request so we first abort that. + cancelShakeSession runner + void $ shakeDatabaseProfile shakeDb + progressStop $ progress shakeExtras + stopMonitoring + case res of + Nothing -> logWith recorder Error $ LogTimeOutShuttingDownWaitForSessionVar 1 + Just _ -> pure () -- | This is a variant of withMVar where the first argument is run unmasked and if it throws From 84e673180ead20900de3adb2ce9c77a9af4532c4 Mon Sep 17 00:00:00 2001 From: Patrick Date: Fri, 3 May 2024 09:49:09 +0800 Subject: [PATCH 05/11] fix --- ghcide/src/Development/IDE/Core/Service.hs | 3 ++- ghcide/src/Development/IDE/LSP/LanguageServer.hs | 4 +++- 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/ghcide/src/Development/IDE/Core/Service.hs b/ghcide/src/Development/IDE/Core/Service.hs index cdb5ba72cb..80a44fd862 100644 --- a/ghcide/src/Development/IDE/Core/Service.hs +++ b/ghcide/src/Development/IDE/Core/Service.hs @@ -93,7 +93,8 @@ initialise recorder defaultConfig plugins mainRule lspEnv debouncer options with mainRule -- | Shutdown the Compiler Service. -shutdown :: IdeState -> IO () +-- shutdown :: Recorder (WithPriority Log) -> IdeState -> IO () +shutdown :: Recorder (WithPriority Shake.Log) -> IdeState -> IO () shutdown = shakeShut -- This will return as soon as the result of the action is diff --git a/ghcide/src/Development/IDE/LSP/LanguageServer.hs b/ghcide/src/Development/IDE/LSP/LanguageServer.hs index e4493436cb..f68568071a 100644 --- a/ghcide/src/Development/IDE/LSP/LanguageServer.hs +++ b/ghcide/src/Development/IDE/LSP/LanguageServer.hs @@ -35,6 +35,7 @@ import qualified Colog.Core as Colog import Control.Monad.IO.Unlift (MonadUnliftIO) import Development.IDE.Core.IdeConfiguration import Development.IDE.Core.Shake hiding (Log, Priority) +import qualified Development.IDE.Core.Shake as Shake import Development.IDE.Core.Tracing import qualified Development.IDE.Session as Session import Development.IDE.Types.Shake (WithHieDb) @@ -49,6 +50,7 @@ data Log | LogReactorThreadStopped | LogCancelledRequest !SomeLspId | LogSession Session.Log + | LogShake Shake.Log | LogLspServer LspServerLog | LogServerShutdownMessage deriving Show @@ -265,7 +267,7 @@ shutdownHandler recorder stopReactor = LSP.requestHandler SMethod_Shutdown $ \_ -- stop the reactor to free up the hiedb connection liftIO stopReactor -- flush out the Shake session to record a Shake profile if applicable - liftIO $ shakeShut ide + liftIO $ shakeShut (cmapWithPrio LogShake recorder) ide resp $ Right Null exitHandler :: IO () -> LSP.Handlers (ServerM c) From e4fd8531ea60364e77bcb655c126d48cc689e74d Mon Sep 17 00:00:00 2001 From: Patrick Date: Fri, 3 May 2024 09:59:18 +0800 Subject: [PATCH 06/11] use takeMVar --- ghcide/src/Development/IDE/Core/Shake.hs | 19 ++++++++++--------- 1 file changed, 10 insertions(+), 9 deletions(-) diff --git a/ghcide/src/Development/IDE/Core/Shake.hs b/ghcide/src/Development/IDE/Core/Shake.hs index c3fd797240..5cb2ea02ac 100644 --- a/ghcide/src/Development/IDE/Core/Shake.hs +++ b/ghcide/src/Development/IDE/Core/Shake.hs @@ -75,7 +75,7 @@ module Development.IDE.Core.Shake( VFSModified(..), getClientConfigAction, ) where -import Control.Concurrent (withMVar) +import Control.Concurrent (takeMVar, withMVar) import Control.Concurrent.Async import Control.Concurrent.STM import Control.Concurrent.STM.Stats (atomicallyNamed) @@ -729,16 +729,17 @@ shakeSessionInit recorder ide@IdeState{..} = do shakeShut :: Recorder (WithPriority Log) -> IdeState -> IO () shakeShut recorder IdeState{..} = do - res <- timeout 1 $ withMVar shakeSession $ \runner -> do - -- Shake gets unhappy if you try to close when there is a running - -- request so we first abort that. - cancelShakeSession runner - void $ shakeDatabaseProfile shakeDb - progressStop $ progress shakeExtras - stopMonitoring + res <- timeout 1 $ takeMVar shakeSession case res of + Just session -> do + -- Shake gets unhappy if you try to close when there is a running + -- request so we first abort that. + cancelShakeSession session + void $ shakeDatabaseProfile shakeDb + progressStop $ progress shakeExtras + stopMonitoring + case res of Nothing -> logWith recorder Error $ LogTimeOutShuttingDownWaitForSessionVar 1 - Just _ -> pure () -- | This is a variant of withMVar where the first argument is run unmasked and if it throws From 036ad1fa7d79a02083e6b3033d691034397c66aa Mon Sep 17 00:00:00 2001 From: Patrick Date: Fri, 3 May 2024 10:29:37 +0800 Subject: [PATCH 07/11] use withMVar to prevent stm dead lock --- ghcide/src/Development/IDE/Core/Shake.hs | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-) diff --git a/ghcide/src/Development/IDE/Core/Shake.hs b/ghcide/src/Development/IDE/Core/Shake.hs index 5cb2ea02ac..c3fd797240 100644 --- a/ghcide/src/Development/IDE/Core/Shake.hs +++ b/ghcide/src/Development/IDE/Core/Shake.hs @@ -75,7 +75,7 @@ module Development.IDE.Core.Shake( VFSModified(..), getClientConfigAction, ) where -import Control.Concurrent (takeMVar, withMVar) +import Control.Concurrent (withMVar) import Control.Concurrent.Async import Control.Concurrent.STM import Control.Concurrent.STM.Stats (atomicallyNamed) @@ -729,17 +729,16 @@ shakeSessionInit recorder ide@IdeState{..} = do shakeShut :: Recorder (WithPriority Log) -> IdeState -> IO () shakeShut recorder IdeState{..} = do - res <- timeout 1 $ takeMVar shakeSession + res <- timeout 1 $ withMVar shakeSession $ \runner -> do + -- Shake gets unhappy if you try to close when there is a running + -- request so we first abort that. + cancelShakeSession runner + void $ shakeDatabaseProfile shakeDb + progressStop $ progress shakeExtras + stopMonitoring case res of - Just session -> do - -- Shake gets unhappy if you try to close when there is a running - -- request so we first abort that. - cancelShakeSession session - void $ shakeDatabaseProfile shakeDb - progressStop $ progress shakeExtras - stopMonitoring - case res of Nothing -> logWith recorder Error $ LogTimeOutShuttingDownWaitForSessionVar 1 + Just _ -> pure () -- | This is a variant of withMVar where the first argument is run unmasked and if it throws From 9b8e966f07ce69ae58acbd2ef07a1c9d52b03523 Mon Sep 17 00:00:00 2001 From: Patrick Date: Sat, 4 May 2024 17:42:57 +0800 Subject: [PATCH 08/11] show error in test --- .github/workflows/test.yml | 2 ++ 1 file changed, 2 insertions(+) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index b86b6b8302..732cc86cd3 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -61,6 +61,8 @@ jobs: needs: - pre_job runs-on: ${{ matrix.os }} + env: + LSP_TEST_LOG_STDERR: 1 strategy: # We don't want to fail fast. # We used to fail fast, to avoid caches of failing PRs to overpopulate the CI From 335274bb3d003beddfcfc66b3b19bda1cdbb799d Mon Sep 17 00:00:00 2001 From: Patrick Date: Sat, 4 May 2024 17:50:03 +0800 Subject: [PATCH 09/11] stop the progress regardless but do profile if we can get the shake session --- ghcide/src/Development/IDE/Core/Shake.hs | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/ghcide/src/Development/IDE/Core/Shake.hs b/ghcide/src/Development/IDE/Core/Shake.hs index c3fd797240..7d0892de71 100644 --- a/ghcide/src/Development/IDE/Core/Shake.hs +++ b/ghcide/src/Development/IDE/Core/Shake.hs @@ -734,12 +734,11 @@ shakeShut recorder IdeState{..} = do -- request so we first abort that. cancelShakeSession runner void $ shakeDatabaseProfile shakeDb - progressStop $ progress shakeExtras - stopMonitoring case res of Nothing -> logWith recorder Error $ LogTimeOutShuttingDownWaitForSessionVar 1 Just _ -> pure () - + progressStop $ progress shakeExtras + stopMonitoring -- | This is a variant of withMVar where the first argument is run unmasked and if it throws -- an exception, the previous value is restored while the second argument is executed masked. From ced09a7456f2eea10dc19fc60e3d3d39315669ec Mon Sep 17 00:00:00 2001 From: soulomoon Date: Sat, 4 May 2024 19:39:12 +0800 Subject: [PATCH 10/11] Add thread id in ghcide tests log (#4204) * add threadId to ghcide test * add threadId to ghcide test * add thread id by default in ghcide-tests * remove redundant log --- ghcide/exe/Main.hs | 4 ++-- ghcide/test/exe/Main.hs | 3 ++- hls-test-utils/src/Test/Hls/FileSystem.hs | 1 - 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/ghcide/exe/Main.hs b/ghcide/exe/Main.hs index a38c5909f3..823d6faba6 100644 --- a/ghcide/exe/Main.hs +++ b/ghcide/exe/Main.hs @@ -21,7 +21,7 @@ import qualified Development.IDE.Main as IDEMain import qualified Development.IDE.Monitoring.OpenTelemetry as OpenTelemetry import qualified Development.IDE.Plugin.HLS.GhcIde as GhcIde import Development.IDE.Types.Options -import Ide.Logger (LoggingColumn (DataColumn, PriorityColumn), +import Ide.Logger (LoggingColumn (..), Pretty (pretty), Priority (Debug, Error, Info), WithPriority (WithPriority, priority), @@ -73,7 +73,7 @@ main = withTelemetryRecorder $ \telemetryRecorder -> do -- stderr recorder just for plugin cli commands pluginCliRecorder <- cmapWithPrio pretty - <$> makeDefaultStderrRecorder (Just [PriorityColumn, DataColumn]) + <$> makeDefaultStderrRecorder (Just [ThreadIdColumn, PriorityColumn, DataColumn]) let hlsPlugins = pluginDescToIdePlugins (GhcIde.descriptors (cmapWithPrio LogGhcIde pluginCliRecorder)) -- WARNING: If you write to stdout before runLanguageServer diff --git a/ghcide/test/exe/Main.hs b/ghcide/test/exe/Main.hs index 7031065aba..2dd21838cc 100644 --- a/ghcide/test/exe/Main.hs +++ b/ghcide/test/exe/Main.hs @@ -49,6 +49,7 @@ import CompletionTests import CPPTests import CradleTests import DependentFileTest +import Development.IDE (LoggingColumn (..)) import DiagnosticTests import ExceptionTests import FindDefinitionAndHoverTests @@ -74,7 +75,7 @@ import WatchedFileTests main :: IO () main = do - docWithPriorityRecorder <- makeDefaultStderrRecorder (Just [PriorityColumn, DataColumn]) + docWithPriorityRecorder <- makeDefaultStderrRecorder (Just [ThreadIdColumn, PriorityColumn, DataColumn]) let docWithFilteredPriorityRecorder = docWithPriorityRecorder diff --git a/hls-test-utils/src/Test/Hls/FileSystem.hs b/hls-test-utils/src/Test/Hls/FileSystem.hs index 1416564e38..c93643badd 100644 --- a/hls-test-utils/src/Test/Hls/FileSystem.hs +++ b/hls-test-utils/src/Test/Hls/FileSystem.hs @@ -115,7 +115,6 @@ materialise rootDir' fileTree testDataDir' = do copyDir' root dir = do files <- fmap FP.normalise . lines <$> withCurrentDirectory (testDataDir dir) (readProcess "git" ["ls-files", "--cached", "--modified", "--others"] "") mapM_ (createDirectoryIfMissing True . ((root ) . takeDirectory)) files - mapM_ (\f -> putStrLn $ (testDataDir dir f) <> ":" <> (root f) ) files mapM_ (\f -> copyFile (testDataDir dir f) (root f)) files return () From a3c86b09abc701818c533297eb43c5813dedd320 Mon Sep 17 00:00:00 2001 From: Patrick Date: Sun, 5 May 2024 00:52:46 +0800 Subject: [PATCH 11/11] do not use progressStop if shake could not be cancel yet --- ghcide/src/Development/IDE/Core/Shake.hs | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/ghcide/src/Development/IDE/Core/Shake.hs b/ghcide/src/Development/IDE/Core/Shake.hs index 7d0892de71..d192ed2f11 100644 --- a/ghcide/src/Development/IDE/Core/Shake.hs +++ b/ghcide/src/Development/IDE/Core/Shake.hs @@ -75,7 +75,7 @@ module Development.IDE.Core.Shake( VFSModified(..), getClientConfigAction, ) where -import Control.Concurrent (withMVar) +import Control.Concurrent (tryReadMVar, withMVar) import Control.Concurrent.Async import Control.Concurrent.STM import Control.Concurrent.STM.Stats (atomicallyNamed) @@ -734,11 +734,14 @@ shakeShut recorder IdeState{..} = do -- request so we first abort that. cancelShakeSession runner void $ shakeDatabaseProfile shakeDb + -- might hang if there are still running + progressStop $ progress shakeExtras + stopMonitoring case res of - Nothing -> logWith recorder Error $ LogTimeOutShuttingDownWaitForSessionVar 1 + Nothing -> do + logWith recorder Error $ LogTimeOutShuttingDownWaitForSessionVar 1 + stopMonitoring Just _ -> pure () - progressStop $ progress shakeExtras - stopMonitoring -- | This is a variant of withMVar where the first argument is run unmasked and if it throws -- an exception, the previous value is restored while the second argument is executed masked.