-
-
Notifications
You must be signed in to change notification settings - Fork 389
Improve logging #2558
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Improve logging #2558
Conversation
This is an example of a custom logger used in an in-process test:
|
This is an example of a test that parses (strongly typed) log messages to prove invariants:
|
…ded log file to see it side by side with original logging
84afa80
to
671211e
Compare
Just wanted to say that this is going in the right direction and very impressively so, in case you still had any doubts. And a suggestion - instead of a Big Bang, try to land it incrementally. Don't make any more changes, polish what you have and land it before converting any more modules and plugins. |
… to same log file
I think this may become unwieldy.
|
Yeah I was thinking with the various So like you said the easiest thing would to have each module know how to convert its However, in the Duncan Coutts video, the impression I got was they already have a log value data type that is independent of the module structure. If that's the case then centralization is a lot easier. That's technically possible... I just look at every module that logs stuff and gather all the logging types in one place. It would still mimic the module structure but not literally needing to import each module aliased. It's also more flexible because well a module doesn't actually have to use a |
…er and hls-plugin-api dependencies
…have default logger be mutex stderr or file handle, use stderr if failing to open log file
Can we re-export |
Yeah that sounds like a good idea. Gonna do that. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Reading the PR description, this is pretty much what Sigma IDE does as described in #2492. Approving early as I don't want to hold back the PR leading to inevitable merge conflicts.
For future work, we should have a logging backend that forwards some LSP messages (encoded as JSON values) to the LSP stream for testing invariants.
defaultArguments :: Priority -> Arguments | ||
defaultArguments priority = Arguments | ||
defaultArguments :: Recorder (WithPriority Log) -> Logger -> Arguments | ||
defaultArguments recorder logger = Arguments |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Did you consider adding an argsRecorder
field to store the recorder
argument?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I thought about it briefly but wasn't sure how it would play out. The recorder would be for the Log
type at the point it gets passed to Argument
, and then it gets put into a ShakeExtras
. When we want to use it we'd take it out and contramap it right there? I think that would mean each module would need to import the Log
of the recorder when it was put into the Argument
or ShakeExtras
. It seemed messy but maybe my mental simulation was just wrong.
Other ways is that existential-ish typeclass method?
{ argsProjectRoot = Nothing | ||
, argsOTMemoryProfiling = False | ||
, argCommand = LSP | ||
, argsLogger = stderrLogger priority | ||
, argsRules = mainRule def >> action kick | ||
, argsLogger = pure logger |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
What is the old Logger
type used for now? If it is still being used, can it be subsumed with a LogLegacy Priority
recorder?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The old logger type is still being used, it's just being initialized at various entry points and passed in.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Not exactly sure what the LogLegacy Priority
means, but the original plan was to remove argsLogger
completely eventually.
import qualified System.Log.Formatter as HSL | ||
import qualified System.Log.Handler as HSL | ||
import qualified System.Log.Handler.Simple as HSL | ||
import qualified System.Log.Logger as HsLogger |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is a significant change in behaviour. Switching to HsLogger seems unrelated to the contravariant logging changes, and better left for another PR
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The only reason for the hslogger stuff is so we can still see them in the logs because hie-bios and a few other places in the code base haven't been converted to the contravariant logging system.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I don't follow this. Are you saying that the old stderr logger implementation didn't work with the contravariant system?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Although now that I look, it seems the only place in hls that uses hslogger is the Hlint plugin, but I'm pretty sure I need the hslogger stuff to get the hiebios output for log files. The reason to copypaste the hslogger stuff from lsp
was so the outputs wouldn't interleave improperly when we write to the handle.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
But the old stderr logger was already using locking to prevent undesired interleaving. I'm not keen on adding a new dependency in ghcide, specially as @michaelpj is planning to drop the hslogger dependency in lsp
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Oh OK didn't see the newer message.
Previously HLS used both hslogger, and a plain stderr logger depending on the entry point. If ghcide
process was run it would use stderr logger, and otherwise I think it would overwrite the default stderr logger with the hslogger logger.
Additionally hie-bios
uses hslogger to write compilation logs to output. The hslogger was initialized by calling setupLogger
from lsp
. If I kept using the setupLogger
from lsp
then the logs would get interleaved weirdly because they don't have access to the lock
, and so I decided to copy-paste that code with some modifications so we could still get any logs written to some handle using hslogger, but also not have them displayed weirdly.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Maybe the confusion is thinking that we're using hslogger as the console/file backend. We're not... we're using just hslogger to setup a hslogger so we can pick up hie-bios
logs to the right handle, and give it a lock so it doesn't do funny things with messages we write to the actual handle backend.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
So, if I understand your analysis right, the hie-bios
logs were actually broken for ghcide
, since hie-bios
unconditionally uses hslogger
, and the ghcide
entry point wasn't setting it up? That would also be true for the logs from lsp
, which currently use hslogger
(although I'm getting rid of it).
I'm okay with putting this in there as a temporary measure until we can get rid of hslogger
in our dependencies. We should just clearly explain why we're doing it.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Yes, I'll add a better comment.
… on prettyprinter and hslogger
This comment was marked as resolved.
This comment was marked as resolved.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
idk what's going on but lgtm!
This comment was marked as outdated.
This comment was marked as outdated.
This isn't so bad, right? Typically this means writing a
I think the advantage is rather locality of reasoning: you can see in that module what logs it emits and they're just there. We could imagine instead having a This makes me think that there are 3 (?) reasonable points on the spectrum:
I think 3 would actually be quite annoying if we ever do want to emit a different type. The most practical example I can think of is providing a Maybe we should consider 2 instead? It's a little ugly, but given the number of packages we have, perhaps things still get scoped somewhat reasonably? |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think this is great, and we should merge it soon and iterate from there.
cmapWithPrio :: (a -> b) -> Recorder (WithPriority b) -> Recorder (WithPriority a) | ||
cmapWithPrio f = cmap (fmap f) | ||
|
||
cmapIO :: (a -> IO b) -> Recorder b -> Recorder a |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I'd probably call this cmapM
(to match co-log
), with the implicit constraint that we fix m ~ IO
in our recorder. This is also fine though.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I think in order to get cmapM
working with the rank N type of logger_
in Recorder
I'd need an UnliftIO
or MonadBaseControl
constraint, and I remember having some issue there too.
I'm not sure if the rank N type of the logger_
field is worth, but it does save carrying around a type parameter. Without the logger_
having rank N type then using co-log
directly would probably be better, although Pepe's initial example had a tracer_
field bundled in which would be different from co-log
.
{ logger_ :: forall m. (HasCallStack, MonadIO m) => msg -> m () } | ||
|
||
logWith :: (HasCallStack, MonadIO m) => Recorder (WithPriority msg) -> Priority -> msg -> m () | ||
logWith recorder priority msg = withFrozenCallStack $ logger_ recorder (WithPriority priority msg) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
If you switch the order of the constructors of WithPriority
then you could just make this
logWith :: ... => Recorder msg -> msg -> m ()
and have the call sites do this
logWith logger $ "hello" `WithPriority` Info
which is a bit more verbose but kind of cute :) Probably this is better, given this gets called a lot.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It is cooler to have logWith
not know anything about Priority
. I think in the end going back to
logDebug logger log = logWith logger $ WithPriority Debug log
will be better since I expect everything to use priorities/severities
= LogSession Session.Log | ||
deriving Show | ||
|
||
makeLogger :: Var [Log] -> Recorder (WithPriority Log) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Probably not for this PR to keep it minimal, but there's a nice generic version of this backed by a TQueue
or something, so you could have
mkTQueueLogger :: IO (Recorder msg, TQueue msg)
or something.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
That's more convenient. It never occurred to me that the recorder is kind of like the in pipe so you can create them both at same time.
Ignore my previous message, it was in fact just wrong! 🙈 |
This comment was marked as resolved.
This comment was marked as resolved.
Option 3 defeats the point of contra variant logging, doesn't it? You can no longer use the trick to test invariants as in #2558 (comment) |
This started as an attempt to bubble up errors from the VFS as actual errors and return them to the user via the LSP response. However, in fact VFS operations occur in response to notifications, which don't have responses. So all we can do is log the error and drop the change, which is okay. However, that made me look at how the logging works. At the moment we use `hslogger`, which is fine, but isn't so great when it's plugging into part of a larger system. For example, we might want to have a global log handler that sends error-level logs to the client as messages, or uses the `logMessage` method of the LSP spec. But there's no way to intercept the messages sent by the VFS currently. So I switched over to using `co-log-core`, which is also the direction that [HLS is going](haskell/haskell-language-server#2558). `co-log-core` is also a lightweight dependency. It's suboptimal for `lsp-types` to depend on a logging library, however, but that should be fixed when we do haskell#394.
…explaining hslogger setup existence
👋 I'm returning to the |
This started as an attempt to bubble up errors from the VFS as actual errors and return them to the user via the LSP response. However, in fact VFS operations occur in response to notifications, which don't have responses. So all we can do is log the error and drop the change, which is okay. However, that made me look at how the logging works. At the moment we use `hslogger`, which is fine, but isn't so great when it's plugging into part of a larger system. For example, we might want to have a global log handler that sends error-level logs to the client as messages, or uses the `logMessage` method of the LSP spec. But there's no way to intercept the messages sent by the VFS currently. So I switched over to using `co-log-core`, which is also the direction that [HLS is going](haskell/haskell-language-server#2558). `co-log-core` is also a lightweight dependency. It's suboptimal for `lsp-types` to depend on a logging library, however, but that should be fixed when we do haskell#394.
Fixed conflicts and if tests are good then I think this can be merged then can iterate |
Failure is just some warnings from building with |
Okay, let's do this. Reading back, I see this from @pepeiborra
I'm not sure I quite understood this, could you make an issue so we don't forget? |
* convert to contravariant logging style part 1, uses additional hardcoded log file to see it side by side with original logging * convert Session to contravariant logging style * convert Plugin/HLS and FireStore to contravariant logging style * convert Rules (and most of the universe) to contravariant logging style * fix tests, allow old style logging and contravariant logging to write to same log file * fix import inside wrong CPP * add CPP for LogTactic constructor * remove redundant import * fix ghcide tests * remove unused import * fix plugin tests * LSP_TEST_STDERR should apply to contra logger as well * fix tactic plugin test * use CPP for Log datatype plugin constructors, remove unused imports * add a few Pretty instances, add prettyprinter to haskell-language-sever and hls-plugin-api dependencies * add Pretty Log instances for Session, FileStore, Notifications * add remaining Pretty Log instances * add logToPriorities * fix slight interleaving issue with hslogger and logger both logging, have default logger be mutex stderr or file handle, use stderr if failing to open log file * forgot to add .cabal files with hslogger dep * dont use UnliftIO file IO helpers because they are too new * remove log helper comments, use Doc instead of Text as final console/file logger input, renaming, export Log constructors * remove accidentally added useless file, removed prettyprinter dep from hls-plugin-api because stack ghc8.6.5 doesnt have it? * use deprecated prettyprint modules import for the sake of circleci ghc-8.6.5 * use dummy stderr logger for plugin cli commands, use priorityToHsLoggerPriority function instead of manual mapping * remove old plugin detritus that somehow got committed * fix prettyprinter imports for 8.6.5 * try enforcing prettyprinter bounds? * enforcing bound makes no sense * maybe changing stack yamls does trick * filter out warnings when their diags are empty to more closely match original * add ability to select wanted logging columns, match prev ghcide exe logging behaviour * dont log anything when diags are empty in some defineEarlyCutoff versions * use non-deprecated prettyprinter imports * fix ghcide test module * change logWith to accept priority at call site, remove all logToPriority functions, add cmapWithPrio that contramaps through WithPriority * remove useless hiding import list, add comments to default recorder makers * make cradleToOptsAndLibDir take concrete cradle to remove existential type var in Log constructor * Types.Logger now re-exports prettyprinter, remove unused dependencies on prettyprinter and hslogger * existential type var to remove boilerplate in Plugins.hs, remove a few Show instances * add SourceLoc logging column, inline logToDoc functions, add comment explaining hslogger setup existence * qualify a name to match original source * fix -WError
* First go * Match against specific error message. * Basic Change Type Signature implementation. This implementation only matches a single GHC Error message: ``` • Couldn't match type ‘Int’ with ‘Data.HashSet.Internal.HashSet Int’ Expected type: Int -> Int Actual type: Data.HashSet.Internal.HashSet Int -> Int • In the expression: head . toList In an equation for ‘test’: test = head . toList ``` Specifically on `Expected type: ...`, `Actual type:...` and `In an equation ...`. There are plenty of error messages that match this format but aren't actually valid. * GHC 9.2.0 compat change * Lift expectedError message into a separate binding * Move ChangeTypeAction into it's own plugin * Add New Error Message parsing. - Add new regex for matching extra errors message types - Revamp original regex to match more. - Add basic test suite. - Begin adding `tidyActualType` semantics to provide slightly prettier TyVars * Added Error Message Validation to ignore bad Messages. - Add Pretty Printing for Types - Added a few test scenarios * Miscellaneous Cleanup. * Update Tide Type Signature logic. - Be able to tidy signatures with operators in it - Use T.words instead of regex matching to split tyVars * Remove locA (defaults to id in 8.10) to satisfy 9.0+ * Touch up 9.2.1 * Clean up review notes * Update stack.yamls * Fix copy-paste error * Fix Local Signature resolution * Improve logging (#2558) * convert to contravariant logging style part 1, uses additional hardcoded log file to see it side by side with original logging * convert Session to contravariant logging style * convert Plugin/HLS and FireStore to contravariant logging style * convert Rules (and most of the universe) to contravariant logging style * fix tests, allow old style logging and contravariant logging to write to same log file * fix import inside wrong CPP * add CPP for LogTactic constructor * remove redundant import * fix ghcide tests * remove unused import * fix plugin tests * LSP_TEST_STDERR should apply to contra logger as well * fix tactic plugin test * use CPP for Log datatype plugin constructors, remove unused imports * add a few Pretty instances, add prettyprinter to haskell-language-sever and hls-plugin-api dependencies * add Pretty Log instances for Session, FileStore, Notifications * add remaining Pretty Log instances * add logToPriorities * fix slight interleaving issue with hslogger and logger both logging, have default logger be mutex stderr or file handle, use stderr if failing to open log file * forgot to add .cabal files with hslogger dep * dont use UnliftIO file IO helpers because they are too new * remove log helper comments, use Doc instead of Text as final console/file logger input, renaming, export Log constructors * remove accidentally added useless file, removed prettyprinter dep from hls-plugin-api because stack ghc8.6.5 doesnt have it? * use deprecated prettyprint modules import for the sake of circleci ghc-8.6.5 * use dummy stderr logger for plugin cli commands, use priorityToHsLoggerPriority function instead of manual mapping * remove old plugin detritus that somehow got committed * fix prettyprinter imports for 8.6.5 * try enforcing prettyprinter bounds? * enforcing bound makes no sense * maybe changing stack yamls does trick * filter out warnings when their diags are empty to more closely match original * add ability to select wanted logging columns, match prev ghcide exe logging behaviour * dont log anything when diags are empty in some defineEarlyCutoff versions * use non-deprecated prettyprinter imports * fix ghcide test module * change logWith to accept priority at call site, remove all logToPriority functions, add cmapWithPrio that contramaps through WithPriority * remove useless hiding import list, add comments to default recorder makers * make cradleToOptsAndLibDir take concrete cradle to remove existential type var in Log constructor * Types.Logger now re-exports prettyprinter, remove unused dependencies on prettyprinter and hslogger * existential type var to remove boilerplate in Plugins.hs, remove a few Show instances * add SourceLoc logging column, inline logToDoc functions, add comment explaining hslogger setup existence * qualify a name to match original source * fix -WError * Delete the Telemetry log level (#2727) It's a bit non-standard, and moreover it's entirely dead. * Wall and 9.2 fix * Remove unneeded comments/code Co-authored-by: J. S <[email protected]> Co-authored-by: Michael Peyton Jones <[email protected]> Co-authored-by: Pepe Iborra <[email protected]>
This PR tries to implement the contravariant logging/tracing library described by #2492 (comment)
Currently the most straightforward way of contravariant logging that this PR does:
Log
datatype then add oneLog
datatype taking the values you want to loglogWith recorder Warning $ LogConstructorName value1 value2
Log
type of that module e.g.Log
datatypes.e.g.
Log
value toDoc
s by aPretty Log
instance defined in it. The final log value is converted to aDoc
by that module'sPretty Log
instance which delegates to otherPretty Log
instances if necessary.Log
values to priorities. Instead they are specified at the log call site (like how every other log framework does it), and stored alongside the log value usingWithPriority a
. The "first/final" logger is aRecorder (WithPriority (Doc ann))
. This allows us to more easily alter priorities when contramapping the logger which is more flexible than converting a log value to a priority.Cons
LogOther Text
constructor to theLog
type of the current module, but if you are logging "for real" then you invent a constructor that takes the values you want to log, and then add to thePretty Log
instance (add a pattern matching branch) to convert theLog
to aDoc
exe/Plugins.hs
, aLog
constructor should be added to the existingLog
datatype for the plugin if it doesn't exist, and a contramapped recorder should be passed to the plugin's descriptor function. Additionally, you need to add entries for thepretty
pattern match. This pattern matching needsCPP
like everything else in that module. This should be simple to do by following the existing example, but still an extra step.contramap
Pros
Questions (for the future):
Log
data type. In that case the single logger decides how to interpret the message later.Log
values. Maybe generic programming or TH can be useful here.Todo:
WithPriority (Doc a)
instead ofWithPriority Text
since we're using prettyprinterlogToPriority
functionTodo in other PRs:
logInfo
,logDebug
, etc, tologWith