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.