feat(logging): easier logging

[ulugbekna]

• Logging without passing down loggers across call hierarchy as Log is available globally with cleanup (log file is closed unlike previously)
• Logging for merlin

All logging enabled by env vars.

vscode redirects all stderr to output panel.

[rgrinberg]

Is there no way to have merlin write the ocamllsp log? It seems annoying to have to check two different files for this.

[ulugbekna]

Is there no way to have merlin write the ocamllsp log?

Not without making changes to merlin, but, currently, we can pass - to both LOG variables to redirect logs to stderr; then we can have them in one place.

From my experience, I found having separate log files quite convenient because of merlin log buffering and how much logs it can produce. We can evolve our logging as the need rises.

--

Also, merlin's buffering is a bit of annoyance for debugging; it would be great to possible flush the buffer after each Document.dispatch call. Wdyt?

[rgrinberg]

If you don't want merlin's log, can't you just disable it? Or add a marker that distinguishes the two types of logs and then filter in your log viewer? One of the most useful things about logs is the linearized output. Seeing it in a different file is going to reduce the ability to debug anything.

Also, merlin's buffering is a bit of annoyance for debugging; it would be great to possible flush the buffer after each Document.dispatch call. Wdyt?

Sure, that sounds reasonable.

[ulugbekna]

But the issue with merlin not exposing its logging internals remains, so we can’t have merlin and olsp use the same file for logging except for stderr, which allows to have a single log. I can send a patch to merlin to fix this, but doesn’t have to stop this PR; shall a user like merlin and olsp to use the same file, they can pass the same file path as both env vars. Does this make sense?

[rgrinberg]

It doesn't make sense to me yet. How would you prevent from the logs from overwriting each other?

Merlin already logs to stderr if the value is set to -. So might as well only stick to that for now. To be clear, here are the properties of a logging we're looking for:

1. A single environment variable to tweak the various settings.
2. Messages are written atomically. That is, they should never appear interleaved.
3. However, messages are still written to a linear log so we can easily see temporal relationships.
4. We can filter the logs by the "source" or other various useful properties.

I'd like to move forward towards these properties, not away from them.

[ulugbekna]

How would you prevent from the logs from overwriting each other?

olsp and merlin loggers can share a single out_channel if both env vars point to the same file.

I propose adding Logger.with_outchan : out_channel -> ?sections:'a list -> (unit -> 'b) -> 'b to merlin's logger. Then we can pass our own out_channel to merlin's logger. Wdyt?

1. A single environment variable to tweak the various settings.

The idea behind having two environment variables was

1. Be able to enable/disable only one of olsp and merlin logs
2. Point them to different files (eg to inspect merlin logs for single merlin command in olsp tests)
3. Respect merlin's env var MERLIN_LOG - the same env var for debugging both olsp's merlin and ordinary merlin

and most importantly avoid a complex env var - how will a single env for both logging systems look like? if we permit only a single output file, then ",[olsp_log_section];[merlin_log_section]"?

---

Ideally, we should also be able to replace merlin's log printing. Then we would be able to prepend a prefix with the source and time, eg [merlin][xx:xx:xx] ...

[rgrinberg]

olsp and merlin loggers can share a single out_channel if both env vars point to the same file.

Since olsp and merlin run in separate threads (at least for now), how do you propose they synchronize their access to this out_channel?

Be able to enable/disable only one of olsp and merlin logs

Here's a value that would set one or the other: sources=olsp or sources=merlin

Point them to different files (eg to inspect merlin logs for single merlin command in olsp tests)

That's not useful. If anything, without linearizing messages, you will have a hard time correlating the two streams to get any meaning out.

Respect merlin's env var MERLIN_LOG - the same env var for debugging both olsp's merlin and ordinary merlin

Why do we need that? We should be ignoring merlin's configuration files rather than respecting them. Our programs should co-exist as much as possible without stepping on each other.

[ulugbekna]

Since olsp and merlin run in separate threads (at least for now), how do you propose they synchronize their access to this out_channel?

Doesn't ocaml runtime synchronize access to a single variable from different threads?

[rgrinberg]

Doesn't ocaml runtime synchronize access to a single variable from different threads?

A single variable, yes. Whole operations like writing a log, no. Luckily out channels have a lock so we just need to make sure that an entire message is written with a single output_string call.

Converting this to a draft until all the issues are fixed.