[libvirt] [PATCH 00/12] Structured syslog (Lumberjack/CEE) support

Tue Oct 9 09:47:04 UTC 2012

On Mon, Oct 08, 2012 at 02:44:04PM -0400, Miloslav Trmac wrote:
> Hello,
> Thanks for the review, and I'm sorry about the late response.
> 
> ----- Original Message -----
> > While I agree with the effort to try to standardize on metadata to
> > be collected with log messages, I can't say I like the Lumberjack
> > design, or this proposed usage in libvirt.
> > 
> > First it is not possible for libvirt to detect whether messages it
> > sends to syslog() are going to be processed by a syslog daemon which
> > actually understands the JSON format. This means we can't turn on
> > use of this JSON format automatically, without causing all existing
> > distros to get their logs filled with JSON data.
> 
> True, but that's an inevitable consequence of being compatible
> with the syslog protocol.[1]

IMHO this is the first of many design flaws in - given that you have
to write all this new code in applications to support the structured
logging, and ideally want new syslog server to get tools to process
the data, it would have been easy to also define a new protocol to
send the data, isntead of trying to hang onto the syslog() API call
or protocol.

> Yes, it does make the question of a default awkward.  However,
> considering that journal has been switched on by default, and
> MESSAGE= of everything sent to journal goes to syslog, is there
> still a chance of enabling a syslog output by default at the same
> time?  Doing so would cause each message to appear in syslog twice
> on systems that have journald.

Given systemd's fast adoption across a wide range of Linux distros,
in particular the enterprise distros from Red Hat & SUSE, we're
going to have journald support in places where structured logging
really matters, likely expanding to all Linux distros in a reasonably
short period. As such I don't really have a desire to also support
Lumberjack format in libvirt natively. IMHO, system services should
just log to journald and either journald can forward plain messages
to syslog, or a tool can be created which pulls structured log data
out of the journal and formats it in Lumberjack format.

> > I also don't like the use of JSON for this purpose in the first place.
>
> I'm afraid this is not really open to a change, however I'll try to
> explain why I don't see JSON as a problem.
> 
> > Application logging facilities really need to be simple, reliable, and
> > safe to use in any context. For example in between a fork() and execve()
> > where POSIX requires only use of async signal safe functions. Now I know
> > that technically speaking syslog() itself is not async signal safe in
> > general, but the way libvirt uses it for logging makes it safe(ish) in
> > our case. We can not, however, imagine that JSON (or really any general
> > JSON library) is going to be async signal safe.
> 
> You can also view JSON syntax as a sequence of (fixed field identifier string, field value with some characters escaped) pairs, which is pretty much the minimum standard for _any_ representation of data in a text format.  Choosing JSON was just simpler than trying to committee-invent something new.[2]
> 
> The journal protocol has a similarly inconvenient case of handling \n 
> it's only not as noticeable because there are fewer characters to escape,
> and \n is rarer.

Actually the difference is more significant than that. While, \n is special,
you do not actually have todo any escaping of the \n when sending the data
to the journald. The wire protocol has special handling where you just
specify the length of the string to be sent, and any newlines in it will be
ignored for the purposes of identifying structured field boundaries. Not
having todo any escaping in this way is very good because it means you do
not need to further copy the data to be logged - you can just fill out the
iovec structs in the write way and get zero-copy logging.

> Re: async-signal-safe use: Yes, using a JSON library is more convenien
>  and generally preferred to writing a yet another JSON encoder, and yes,
> a typical JSON library will not be async-signal-safe.  However,
> applications are not required to use all JSON facilities.  An application
> that wants to log a static string between fork() and execve() can just as
> easily log a static JSON string.

I don't really see logging preformatted static JSON strings as a
satisfactory approach, especially when compared to the way you can
use journald.

> Regarding libvirt specifically, virLogVMessage is rather far from
> async-signal-safe (e.g. virVasprintf(), virLogLock()), so this doesn't
> seem to be a concern for libvirt.

It actually *is* very much a concern for libvirt.

The virLogLock() is in fact designed so that we can safely use it in
between fork+exec(). ALl our code which runs external programs uses our
virCommand/virRun wrappers which synchronize on the logging mutex, so we
can avoid the deadlock issues with mutexes here. Before we did this we
did indeed have problems with deadlocks in our logging code.

We also have also hit problems with the locatime() function not being
async signal safe, so we had to re-write our log message formatting code
to avoid using gmtime/localtime, to avoid deadlocks.

While there are some functions still used which are not technically
async signal safe, this does not mean we don't care. In practice the
reason by asprintf() and friends are not declared safe by POSIX is
that they can malloc() and malloc() is not declared safe. We are
however fortunate that GLibc's malloc is safe. We do still, however,
have a goal to eliminate use of these unsafe functions in the future,
but it is not immediately pressing.

We certainly do *not* want to introduce new code that causes us
further complication in this area.

> > By way of comparison the systemd journal APIs deal with all theses
> > issues.
> > 
> > The actual journald client side logging API is possible to implement
> > and use without doing any memory allocation at all,
> 
> virLogOutputToJournald can be implemented like that, but not the
> libsystemd-journal API: you'll find a fairly liberal use of alloca()
> in journal-send.c.  If alloca() is allowed, a JSON formatting API
> can be implemented without "memory allocation" as well.

Yes, that is one of the reasons I ended up writing to the journald
protocol directly. While the current APIs in libsystemd-journal
do require alloca(), it would actually be possible to make add some
functions which avoided this need. This is something I intend to
pursue with systemd devs when I have more free time.

> > in a completely
> > async signal safe manner, using only socket() + sendmsg() with a
> > stack allocated iovec[] for storing individual metadata fields to be
> > sent.
> 
> Looking at how libvirt currently sends journal data, is the
> /run/systemd/journal/socket protocol a stable ABI?  I can't
> find anything documenting it within the systemd git tree, and
> it is not mentioned at http://www.freedesktop.org/wiki/Software/systemd/InterfaceStabilityPromise .

Hmm, that's a good point actually, I must confirm that.

> > The API is soooo simple to use too, for example, a traditional
> > syslog() call, can be replaced with something like:
> > 
> >     sd_journal_send("MESSAGE=%s", str,
> >                     "PRIORITY=%d", prio,
> >                     "CODE_LINE=%lld", linenr,
> >                     "CODE_FUNC=%s", funcname,
> >                     ...arbirary other key=value metadata...
> >                     NULL);
> 
> There actually is a library (libumberlog) providing just such a simple API.  A corresponding call is
> > ul_syslog(prio, str,
> >           "code_line", "%s", service,
> >           "code_func", "%s", auth_method,
> >           ... arbitrary other metadata...
> >           NULL);
> 
> However, I thought that libvirt would prefer not adding yet
> another dependency, especially when the extensions for
> virRaiseErrorFull require a per-field data structure in any
> case.[3]

Mostly I'd want to avoid external libraries here due to the async signal
safety issues.

Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|