Fix and improve server logging

[jneira]

• hls architecture is complex, with many moving pieces (hie-bios, hiedb, ghcide, plugins, etc) and many points of failure so we need a good log setup allowing users and maintainers trace bug causes as fast as possible
• Now, afaics the logging system has some flaws:
  • It uses different logging frameworks, config options and criteria about what and where is the output
  • Logging levels are not consistent across components
  • And the worse thing, not always errors are reported in the log and users ends with a no working hls session with no clue about why is the cause

As @alanz suggested in this issue about harmonising logging :

• how and what are we going to log? Tapping into the LSP expectations makes sense, which seems to be to use stderr, which can then be managed per process and per client.
• Which logging framework will we use? In my mind this should be common across haskell-lsp, ghcide, and hls

I would add:

• ensure all errors even catastrophic ones are reported with the max info available
• use proper error levels setup with at least error, info and debug
• move all actual traces about rules to debug, as afaics the main information they give is what rule was fired and how many time it took, so useful for performance analysis (but only partially)
• expose all log level selection in all components and make it configurable up down from hls via cli arg and lsp config

[pepeiborra]

Sigma IDE uses a contra variant logger with support for tracing. It has the usual backends (console, event log) as well as an LSP backend.

Contra variant has these USPs:

1. error level is decided by caller (e.g. main function)
2. in-process tests can attach event handlers to log messages and use them to prove invariants

data LogMessage
  = LogRule LogRuleMessage
  | LogCore LogCoreMessage
  | LogCompile LogCompileMessage
  | LogOther LogOtherMessage

data LogRuleMessage
  = LogReindexingFile FilePath
  | LogRegeneratingInterface FilePath
  | ...

-- | A contravariant tracing abstraction
data Tracer msg = Tracer
  { logMsg_ :: forall m . (HasCallStack, MonadCatch m) => msg -> m ()
    -- ^ Log a message
  , traceMsg_ :: forall a m . (HasCallStack, MonadCatch m) => msg -> m a -> m a
    -- ^ Trace the begin and end of a computation
  }
instance Contravariant Tracer 
instance Monoid Tracer
instance Semigroup Tracer

[jneira]

Wow that sounds cool, any chance to use it in hls? i mean the source code is available to be copied or used via a public library

[pepeiborra]

This idea is implemented by logging libraries like co-log but Sigma IDE just rolls its own solution with the abstractions pasted above. There really isn't that much code.

-- Explicit record accessors to preserve call stacks

logMsg :: (HasCallStack, MonadTrace m) => Tracer msg -> msg -> m ()
logMsg logger msg = withFrozenCallStack $ logMsg_ logger msg

traceMsg :: (HasCallStack, MonadTrace m) => Tracer msg -> msg -> m a -> m a
traceMsg logger msg act = withFrozenCallStack $ traceMsg_ logger msg act

The only slightly tricky bit is the LSP backend, which involves registering a plugin to capture the LSPEnv in order to send SCustomMethod notifications in the logger.

Proving invariants in tests can be done by either parsing the LSP notifications sent by the LSP logger backend, or by creating new logger backends on the fly that do more complicated things

[michaelpj]

Why do you need a SCustomMethod? There's WindowLogMessage, right?

[michaelpj]

Also I'm very pro this, it would be very helpful.

The other component is just logging more. For example, we don't give users any logging about why we pick certain cradles, which is one of the things that we often end up helping people debug.

[jneira]

The other component is just logging more. For example, we don't give users any logging about why we pick certain cradles, which is one of the things that we often end up helping people debug.

yep, this is a implicit-hie thing, which has not log output at all afaik :-(

[michaelpj]

I might make a gentle attempt to use co-log-core or something in HLS, but that shouldn't stop anyone else from doing something on this.

[jneira]

One of the aspects of server logging which could be improved is the log of lsp messages, see #1904

[michaelpj]

Adding some TODOS for after #2558 lands (cc @eddiemundo )

• Move hie-bios to a similar kind of structured logging
• Purge hslogger (requires the previous step)
• Integrate new lsp with structured logging
• Add log handler that uses LSP showMessage/logMessage notifications

[eddiemundo]

More TODOs that #2558 didn't complete

• Convert all instances of logInfo, logDebug, etc, to logWith (or convert logInfo, logDebug to use logWith, and convert all logWiths back to logInfo, logDebug, etc.). Not sure how many are left maybe roughly 10-20 calls?
• Eliminate all places where exceptions can be swallowed. I think a few places run stuff async and aren't waited on.
• Add more logging, including returning user suggestions. Not sure about the what needs more logging.
• For things that can't be handled let them go to a top level handler which can then send messages to user? I saw some places that handle unhandleable errors locally which make things inconsistent.
• Implement/use tracing functionality where appropriate. I think from the examples tracing is used to measure before and afters, but if using it to print things may have to change the console backend to do something different than a simple lock because deadlocks.
• documentation explaining how to use contravariant logging
• Improve ergonomics somehow? Generics, TH. edit: probably don't do this - and considering putting the "recorder" inside ShakeExtras like before.
  I don't think putting in ShakeExtras is free because naively have to fix message type, then when you get it out of ShakeExtras have to contramap it to the modules Log type? This requires importing Log constructors of the recorder message type that is fixed in the ShakeExtras. I haven't tried it, however I guess if there are no problems with importing Log constructors from elsewhere when doing the logging, or there is another way, we can save passing a Recorder type to a lot of places.

[michaelpj]

considering putting the "recorder" inside ShakeExtras like before

I'm not sure how I feel about this. It depends on whether we want to do much in the way of "local" logging control. For example, if we wanted to have the ability to turn off plugin logs or something,, we'd want to make sure they were being passed the logger that we had modified, not taking one from the global environment.

[eddiemundo]

Nice that's another disadvantage. It's just an idea that Pepe asked if I thought about that I reflexively didn't like, but couldn't really articulate why beyond it being uglier. I'll edit the comment.

[pepeiborra]

The recorder should be an input to defaultMain and therefore under your full control, regardless of whether it is stored in ShakeExtras or not.

My suggestion was to add a field argsRecorder to the Arguments value taken by defaultMain, iirc, not to add it to ShakeExtras. Or maybe I suggested both?

[eddiemundo]

You're right my brain failed and now I see my reply makes no sense. My train of thought was previous logger in Arguments goes into ShakeExtras, therefore adding recorder to Arguments is for going into ShakeExtras.

[michaelpj]

A few more:

• Murder hls-plugin-api/src/Ide/Logger, which uses hslogger
• Murder Logger in favour of Recorder (I guess it's still there due to it being what's stored in ShakeExtras?)

[eddiemundo]

With #2750 we can send messages to window by setting priority of message to Error. If that goes through the places that still use SWindowMessages directly instead of the recorder afaik are:
splice plugin
tactics plugin
fourmolu plugin
retrie plugin
extendImportHandler plugin in Completions.hs
displayTHWarning in Rules.hs

Maybe setting message to Error isn't appropriate for all like displayTHWarning since that will also come with a report this to issue tracker when using the hls exe which we probably don't want.

[xsebek]

As a side question, is there a place where the new loggers get their format string?

There seem to be four formats*:

2022-05-30 23:01:33.8870000 [client] INFO Finding haskell-language-server
2022-05-30T23:01:34.751639Z | Info | Starting (haskell-language-server) LSP server...
[Info  - 1:01:36 AM] Starting (haskell-language-server) LSP server...
2022-05-31 01:01:38.501386828 [ThreadId 155] INFO hie-bios:	Build profile: -w ghc-8.10.7 -O1

I was thinking about adding the thread id to debug one issue but could not find where the new structured logs are formatted with time, level and stuff. 😕

^{*) Funny that each time format is different too, with the first two ignoring time zones I guess?}

[drsooch]

As a side question, is there a place where the new loggers get their format string?

There seem to be four formats*:

2022-05-30 23:01:33.8870000 [client] INFO Finding haskell-language-server
2022-05-30T23:01:34.751639Z | Info | Starting (haskell-language-server) LSP server...
[Info  - 1:01:36 AM] Starting (haskell-language-server) LSP server...
2022-05-31 01:01:38.501386828 [ThreadId 155] INFO hie-bios:	Build profile: -w ghc-8.10.7 -O1

I was thinking about adding the thread id to debug one issue but could not find where the new structured logs are formatted with time, level and stuff. confused

*) Funny that each time format is different too, with the first two ignoring time zones I guess?

I believe the first one is the old legacy logging format. Otherwise, checkout ghcide/src/Development/IDE/Types/Logger.hs search for defaultLoggingColumns and add ThreadIdColumn you should get the Thread IDs

[drsooch]

Here's another thought:

• Context aware logging. For example, knowing that a certain message came from plugin 'x' or from ghcide itself. There are a considerable amount of moving parts I think, for example, when runAction called it would be nice to know where it came from (most plugins attach a descriptive action name such as "alternateNumberFormat.TypeCheck", but it would be nice for it to be automatic.

[michaelpj]

There seem to be four formats

Yeah, there's still a mess here:

1. I don't know what this is
2. This is the "new" log format that stuff should mostly be using
3. This is the same log as the previous one, but sent to the client, so vscode displays it. It's not ideal that it displays the logs sent to the client and stdout interleaved, maybe we shouldn't send all our logs to vscode if it's going to do that?
4. This is hslogger, which is on its way out. I recently purged it from hie-bios, so once we get a new hie-bios that should be gone.

Context aware logging.

I think this shouldn't be too bad? It could be another field in our message type, of type [Context], and then you could write withContext :: Context -> Recorder ... -> Recorder ... fairly easily I think?