Re: [MirageOS-devel] test, quality, tcpip

[Thomas Leonard <talex5@xxxxxxxxx>]

On 12 May 2015 at 22:54, Thomas Gazagnaire <thomas@xxxxxxxxxxxxxx> wrote:
>>
>> An other point which is cruelly missing is a proper logging system - which
>> is central when debugging runtime errors.
>
>
> Thomas, do you have any thoughts about what a proper logging system would
> look like? What features it would provide? I'm experimenting a little with
> this already, making a logger that can write messages to the console and
> also send as syslog. I'd be interested in trying to expand this and make it
> into something generally useful for Mirage but would probably need a bit of
> guidance to begin with.
>
> I'm aware of https://github.com/UnixJunkie/dolog and wondering whether this
> is a good starting point, if it were functorized to accept the Mirage
> console signature?
>
>
> As Anil said, I don't thing re-using dolog is a good idea (dolog serves its
> purposes nicely but it is not what we want as a general logging library for
> MirageOS). I have not yet a very clear idea of what we should do, but I plan
> to spend some time soon to come up with a more concrete proposal.

I spent a few years using log4j. I actually thought it was pretty
good, especially for larger systems. The only real problem with
logging in Java is that there are multiple systems in widespread use
and figuring out which logging system to configure to get messages
from a particular component is a nightmare.

Each component creates a Logger object and logs messages against it,
with a level. e.g.

package com.example;
class Foo {
  static Logger log = Logger.getLogger(Foo.class.getName());
  ...
  public void bar() {
    log.info("Hello");
  }
}

Using Foo.class.getName() rather than "com.example.Foo" avoids typos
in the logger name, and means it can't get out of date if the package
changes.

Introspection lets it discover the method name and line number
automatically. This can slow down the logging, but it's configurable
at runtime.

One hugely useful feature is being able to attach exceptions to log
messages. e.g.

  try { ... }
  catch (Exception ex) {
    log.warn("Problem doing X", ex);
  }

In the configuration file, you can specific a filter level for each
component (e.g. "Log everything under com.example at INFO level or
higher by default, but log com.example.Foo at DEBUG"):

log4j.logger.com.example=INFO
log4j.logger.com.example.Foo=DEBUG

This is especially useful when you have components written by
different people, because they tend to have different opinions about
how verbose to be. It's also very useful when trying to track down a
problem without getting DEBUG output from everything.

Once a message has passed its component filter, it is then distributed
to various configured "appenders" (backends), and these also have
filters. For example, you could log everything to a file, but only
warnings and higher to the console.

> Few remarks:
>
> - I'm in favour of designing something from scratch

The critical thing is how components generate messages. It would be
*really* useful to have a single API, so every OCaml library can use
"the OCaml log API" and it's up to the final link which concrete
library to use. It might be worth talking to the authors of the other
systems to see if there's any possibilty of agreement here.

In particular, the API for generating logging events should be
separate from the API for configuring logging output (which depends on
the specific system being used).

> - I also don't particularly like the usual warn/debug/info/error stuff (I
> tend to use debug/error only anyway)

I think INFO is very useful. For example, a web-server would log
requests at INFO level. There are lots of other non-debug, non-warning
events like this you want (startup complete, new IP address assigned,
etc).

> - Using Irmin is a good idea if it's available but I'd like to not enforce
> it as a dependency if possible

Yes. To get widespread use, the logging API should have no dependencies itself.

Another useful optional backend would be the tracing system, so that
log messages appear in the trace, attached to the Lwt thread that
generated them.

> - I'm not a big fan of passing the logging function as an argument as this
> means you need to thread it everywhere (and if you want to add some logging
> to a function, you'll need to change its type) so the design of Lwt_log is
> compelling - but need to thing a bit more about that

I'm undecided about this. It is annoying when you want to log
something and you have to thread a logger all though the code to do
it. However, there are some useful benefits to passing it:

- You can run two largely independent applications in a single
unikernel, with separate logging for each.

- You could run two IP stacks, and log each interface to its own file.

- main.ml can choose the top-level names for each logger, and then
each module can create a child logger for sub-components it creates,
forming a tree. This makes it easy to see where a message is coming
from, which isn't always obvious if modules choose their own names.

Having it on every function might be too much, but perhaps a functor
argument would do? Or perhaps have both options, Irmin-style.

> - I quite like the "with-trace" function of bigloo[1] and I found it quite
> useful in practice (although I would replace the trace level by some section
> names that you could turn-off/on dynamically and/or statically)
> - It is always hard to find the right balance of things to log or to not log
> and I'm not sure how we can have a general solution for this without runtime
> control. Spamming the log traces is very useful when you debug and or when
> you try to fix a weird production issue, but you also want to be fast and
> avoid DoS ...
> - I also quite liked reading stuff about Finagle/Zipkin[2] (although I never
> used it in practice) and that would be quite nice if we had a similar
> logging story for MirageOS
> - If anyone knows a good existing logging library that they used in other
> languages, I'm keen to have a look.


-- 
Dr Thomas Leonard        http://roscidus.com/blog/
GPG: DA98 25AE CAD0 8975 7CDA  BD8E 0713 3F96 CA74 D8BA

_______________________________________________
MirageOS-devel mailing list
MirageOS-devel@xxxxxxxxxxxxxxxxxxxx
http://lists.xenproject.org/cgi-bin/mailman/listinfo/mirageos-devel