Investigating the failing formatter tests.

Conclusion is that getDocumentContents is returning junk, doing the idempotent
test manually on vscode works as expected, but ends up with junk at the end of
the file in the test.

2020-03-12 21:11:05.79062259 [ThreadId 38] - Formatter.doFormatting: contents=
"{-# LANGUAGE NoImplicitPrelude #-}
module    Format where
foo   :: Int ->  Int
foo  3 = 2
foo    x  = x
bar   :: String ->   IO String
bar s =  do
      x <- return \"hello\"
      return \"asdf\"
"

2020-03-12 21:11:07.896114974 [ThreadId 7] - <--2--{"result":[{"range":{"start":{"line":0,"character":0},"end":{"line":9,"character":0}},"newText":
"{-# LANGUAGE NoImplicitPrelude #-}

module Format where

foo :: Int -> Int
foo 3 = 2
foo x = x

bar :: String -> IO String
bar s = do
  x <- return \"hello\"
  return \"asdf\"
"}],"jsonrpc":"2.0","id":1}

2020-03-12 21:11:07.897123428 [ThreadId 5] - ---> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"version":0,"uri":"file:///home/alanz/mysrc/github/alanz/haskell-language-server/test/testdata/Format.hs"},"contentChanges":[{"text":
"{-# LANGUAGE NoImplicitPrelude #-}

module Format where

foo :: Int -> Int
foo 3 = 2
foo x = x

bar :: String -> IO String
bar s = do
  x <- return \"hello\"
  return \"asdf\"
","range":{"start":{"line":0,"character":0},"end":{"line":9,"character":0}}}]}}

-------------------------------------------------------

2020-03-12 21:11:07.899375044 [ThreadId 213] - Formatter.doFormatting: contents="{-# LANGUAGE NoImplicitPrelude #-}
module    Format where
foo   :: Int ->  Int
foo  3 = 2
foo    x  = x
bar   :: String ->   IO String
bar s =  do
      x <- return \"hello\"
      return \"asdf\"
"

2020-03-12 21:11:07.902320214 [ThreadId 7] - <--2--{"result":[{"range":{"start":{"line":0,"character":0},"end":{"line":9,"character":0}},"newText":"{-# LANGUAGE NoImplicitPrelude #-}

module Format where

foo :: Int -> Int
foo 3 = 2
foo x = x

bar :: String -> IO String
bar s = do
  x <- return \"hello\"
  return \"asdf\"
"}],"jsonrpc":"2.0","id":2}

2020-03-12 21:11:07.902812215 [ThreadId 5] - ---> {"jsonrpc":"2.0","method":"textDocument/didChange","params":{"textDocument":{"version":0,"uri":"file:///home/alanz/mysrc/github/alanz/haskell-language-server/test/testdata/Format.hs"},"contentChanges":[{"text":
"{-# LANGUAGE NoImplicitPrelude #-}

module Format where

foo :: Int -> Int
foo 3 = 2
foo x = x

bar :: String -> IO String
bar s = do
  x <- return \"hello\"
  return \"asdf\"
","range":{"start":{"line":0,"character":0},"end":{"line":9,"character":0}}}]}}

--------------------------------

hieCommand: haskell-language-server --lsp -d -l test-logs/hie-stack-8.6.5.yaml.log
HIE cache is warmed up

Format
  formatting provider
    formatting is idempotent FAILED [1]

Failures:

  test/functional/FormatSpec.hs:64:42:
  1) Format, formatting provider, formatting is idempotent
       expected: "{-# LANGUAGE NoImplicitPrelude #-}\n\nmodule Format where\n\nfoo :: Int -> Int\nfoo 3 = 2\nfoo x = x\n\nbar :: String -> IO String\nbar s = do\n  x <- return \"hello\"\n  return \"asdf\"\n"
        but got: "{-# LANGUAGE NoImplicitPrelude #-}\n\nmodule Format where\n\nfoo :: Int -> Int\nfoo 3 = 2\nfoo x = x\n\nbar :: String -> IO String\nbar s = do\n  x <- return \"hello\"\n  return \"asdf\"\nbar s = do\n  x <- return \"hello\"\n  return \"asdf\"\n"

  To rerun use: --match "/Format/formatting provider/formatting is idempotent/"

Randomized with seed 1814425400

Author: alanz

exe/Arguments.hs

@@ -32,6 +32,11 @@ data Arguments = Arguments
     ,argsShakeProfiling :: Maybe FilePath
     ,argsTesting :: Bool
     ,argsExamplePlugin :: Bool
+    -- These next two are for compatibility with existing hie clients, allowing
+    -- them to just change the name of the exe and still work.
+    , argsDebugOn       :: Bool
+    , argsLogFile       :: Maybe String
+
     }
 
 getArguments :: String -> IO Arguments
@@ -57,6 +62,18 @@ arguments exeName = Arguments
       <*> switch (long "example"
                   <> help "Include the Example Plugin. For Plugin devs only")
 
+      <*> switch
+           ( long "debug"
+          <> short 'd'
+          <> help "Generate debug output"
+           )
+      <*> optional (strOption
+           ( long "logfile"
+          <> short 'l'
+          <> metavar "LOGFILE"
+          <> help "File to log to, defaults to stdout"
+           ))
+
 -- ---------------------------------------------------------------------
 -- Set the GHC libdir to the nix libdir if it's present.
 getLibdir :: IO FilePath

exe/Main.hs

@@ -128,8 +128,8 @@ main = do
 
     -- LSP.setupLogger (optLogFile opts) ["hie", "hie-bios"]
     --   $ if optDebugOn opts then L.DEBUG else L.INFO
-    LSP.setupLogger argsShakeProfiling ["hie", "hie-bios"]
-      $ if argsTesting then L.DEBUG else L.INFO
+    LSP.setupLogger argsLogFile ["hie", "hie-bios"]
+      $ if argsDebugOn then L.DEBUG else L.INFO
 
     -- lock to avoid overlapping output on stdout
     lock <- newLock

src/Ide/Plugin/Formatter.hs

@@ -20,12 +20,15 @@ import qualified Data.Map  as Map
 import qualified Data.Text as T
 import           Development.IDE.Core.FileStore
 import           Development.IDE.Core.Rules
+import           Development.IDE.Core.Shake
 -- import           Development.IDE.LSP.Server
 -- import           Development.IDE.Plugin
 import           Development.IDE.Types.Diagnostics as D
 import           Development.IDE.Types.Location
 -- import           Development.Shake hiding ( Diagnostic )
+-- import           Ide.Logger
 import           Ide.Types
+import           Development.IDE.Types.Logger
 import           Ide.Plugin.Config
 import qualified Language.Haskell.LSP.Core as LSP
 -- import           Language.Haskell.LSP.Messages
@@ -64,7 +67,10 @@ doFormatting lf providers ideState ft uri params = do
           Just (toNormalizedFilePath -> fp) -> do
             (_, mb_contents) <- runAction ideState $ getFileContents fp
             case mb_contents of
-              Just contents -> provider ideState ft contents fp params
+              Just contents -> do
+                  logDebug (ideLogger ideState) $ T.pack $
+                      "Formatter.doFormatting: contents=" ++ show contents -- AZ
+                  provider ideState ft contents fp params
               Nothing -> return $ Left $ responseError $ T.pack $ "Formatter plugin: could not get file contents for " ++ show uri
           Nothing -> return $ Left $ responseError $ T.pack $ "Formatter plugin: uriToFilePath failed for: " ++ show uri
       Nothing -> return $ Left $ responseError $ T.pack $ "Formatter plugin: no formatter found for:[" ++ T.unpack mf ++ "]"

test/functional/FormatSpec.hs

@@ -50,6 +50,20 @@ spec = do
       formatRange doc (FormattingOptions 2 True) (Range (Position 2 0) (Position 4 10))
       documentContents doc >>= liftIO . (`shouldBe` orig)
 
+    -- ---------------------------------
+
+    it "formatting is idempotent" $ runSession hieCommand fullCaps "test/testdata" $ do
+      doc <- openDoc "Format.hs" "haskell"
+
+      sendNotification WorkspaceDidChangeConfiguration (DidChangeConfigurationParams (formatLspConfig "ormolu"))
+      formatDoc doc (FormattingOptions 2 True)
+      documentContents doc >>= liftIO . (`shouldBe` formattedDocOrmolu)
+
+      formatDoc doc (FormattingOptions 2 True)
+      documentContents doc >>= liftIO . (`shouldBe` formattedDocOrmolu)
+
+    -- ---------------------------------
+
     it "can change on the fly" $ runSession hieCommand fullCaps "test/testdata" $ do
       doc <- openDoc "Format.hs" "haskell"
 
@@ -99,6 +113,8 @@ spec = do
   --     liftIO $ edits `shouldBe` [TextEdit (Range (Position 1 0) (Position 3 0))
   --                                   "foo x y = do\n    print x\n    return 42\n"]
 
+    -- ---------------------------------
+
   describe "ormolu" $ do
     let formatLspConfig provider =
           object [ "languageServerHaskell" .= object ["formattingProvider" .= (provider :: Value)] ]
@@ -114,6 +130,8 @@ spec = do
         GHC86 -> formatted
         _ -> liftIO $ docContent `shouldBe` unchangedOrmolu
 
+-- ---------------------------------------------------------------------
+
 formattedDocOrmolu :: T.Text
 formattedDocOrmolu =
   "{-# LANGUAGE NoImplicitPrelude #-}\n\n\
@@ -204,7 +222,6 @@ formattedFloskellPostBrittany =
   \bar s = do\n\
   \  x <- return \"hello\"\n\
   \  return \"asdf\"\n\
-  \  return \"asdf\"\n\
   \"
 
 formattedBrittanyPostFloskell :: T.Text

test/utils/TestUtils.hs

@@ -207,7 +207,8 @@ logFilePath = "hie-" ++ stackYaml ++ ".log"
 hieCommand :: String
 -- hieCommand = "hie --lsp --bios-verbose -d -l test-logs/" ++ logFilePath
 -- hieCommand = "haskell-language-server --lsp"
-hieCommand = "haskell-language-server --lsp --test --shake-profiling=test-logs/" ++ logFilePath
+-- hieCommand = "haskell-language-server --lsp --test --shake-profiling=test-logs/" ++ logFilePath
+hieCommand = "haskell-language-server --lsp -d -l test-logs/" ++ logFilePath
 
 hieCommandVomit :: String
 hieCommandVomit = hieCommand ++ " --vomit"