[libvirt] [PATCH v2 03/13] logging: introduce log handling protocol

[John Ferlan]

On 11/12/2015 12:19 PM, Daniel P. Berrange wrote:
> Define a new RPC protocol for the virtlogd daemon that provides
> for handling of logs. The initial RPC method defined allows a
> client to obtain a file handle to use for writing to a log
> file for a guest domain. The file handle passed back will not
> actually refer to the log file, but rather an anonymous pipe.
> The virtlogd daemon will forward I/O between them, ensuring
> file rotation happens when required.
> 
> Initially the log setup is hardcoded to cap log files at
> 128 KB, and keep 2 backups when rolling over.
> 
> Signed-off-by: Daniel P. Berrange <berrange at redhat.com>
> ---
>  po/POTFILES.in                    |   1 +
>  src/Makefile.am                   |   4 +
>  src/logging/log_daemon.c          |  30 +++
>  src/logging/log_daemon.h          |   3 +
>  src/logging/log_daemon_dispatch.c | 101 +++++++-
>  src/logging/log_handler.c         | 521 ++++++++++++++++++++++++++++++++++++++
>  src/logging/log_handler.h         |  63 +++++
>  src/logging/log_protocol.x        |  94 ++++++-
>  8 files changed, 815 insertions(+), 2 deletions(-)
>  create mode 100644 src/logging/log_handler.c
>  create mode 100644 src/logging/log_handler.h
> 

As I was thinking about the "view of a client" - I began to wonder if
the logic in virRotatingFileReaderSeek which doesn't find the
inode/offset should perhaps return a failure instead of the offset of
the oldest file (especially if maxbackup == 0)?  Is it possible to have
a case where there are two backups and enough time has passed such that
we've rotated more than once (or is that an Amsterdam moment ;-))?

Shouldn't perhaps the client be able to handle whether the file it was
looking at has rotated out of existence and then decide what to do
rather than assuming that the client would want the offset of the most
recent rotated file (if of course it even exists)?


Another thought I had - within this new model might it be reasonable to
allow a client to set the logging level desired for a connection rather
than using the same logging level for all virtlogd connections? I know
I've found use in the past of raising and lowering logging levels for
debugging libvirtd, but I have to turn off all domains if I want more;
otherwise, the log file is overwhelmed.  But I could certainly see need
if I were debugging to 'enable' or 'disable' specific logging "on the
fly"...  Different problem!

Anyway...

[...]

>
> diff --git a/src/logging/log_daemon.c b/src/logging/log_daemon.c
> index 184076c..bc13257 100644
> --- a/src/logging/log_daemon.c
> +++ b/src/logging/log_daemon.c

[...]

> @@ -157,6 +162,12 @@ virLogDaemonNew(virLogDaemonConfigPtr config, bool privileged)
>  }
>  
>  
> +virLogHandlerPtr virLogDaemonGetHandler(virLogDaemonPtr daemon)

NIT: Two lines
virLogHandlerPtr
virLogDaemon...

> +{
> +    return daemon->handler;
> +}
> +
> +

[...]

> diff --git a/src/logging/log_daemon_dispatch.c b/src/logging/log_daemon_dispatch.c
> index 98df178..f612be1 100644
> --- a/src/logging/log_daemon_dispatch.c
> +++ b/src/logging/log_daemon_dispatch.c
> @@ -1,7 +1,7 @@
>  /*
>   * log_daemon_dispatch.c: log management daemon dispatch
>   *
> - * Copyright (C) 2006-2015 Red Hat, Inc.
> + * Copyright (C) 2015 Red Hat, Inc.

Probably should have been something in patch 2...  I didn't mention it
there mainly because I read your comment to Peter...

>   *
>   * This library is free software; you can redistribute it and/or
>   * modify it under the terms of the GNU Lesser General Public

[...]

> diff --git a/src/logging/log_handler.c b/src/logging/log_handler.c
> new file mode 100644
> index 0000000..8853fd0

[...]

> +
> +static void
> +virLogHandlerDomainLogFileEvent(int watch,
> +                                int fd,
> +                                int events,
> +                                void *opaque)
> +{
> +    virLogHandlerPtr handler = opaque;
> +    virLogHandlerLogFilePtr logfile;
> +    char buf[1024];
> +    ssize_t len;
> +
> +    virObjectLock(handler);
> +    logfile = virLogHandlerGetLogFileFromWatch(handler, watch);
> +    if (!logfile || logfile->pipefd != fd) {
> +        virEventRemoveHandle(watch);

handler is still locked

> +        return;
> +    }
> +
> + reread:
> +    len = read(fd, buf, sizeof(buf));
> +    if (len < 0) {
> +        if (errno == EINTR)
> +            goto reread;
> +
> +        virReportSystemError(errno, "%s",
> +                             _("Unable to read from log pipe"));
> +        goto error;
> +    }
> +
> +    if (virRotatingFileWriterAppend(logfile->file, buf, len) != len)
> +        goto error;
> +
> +    if (events & VIR_EVENT_HANDLE_HANGUP)
> +        goto error;
> +
> +    virObjectUnlock(handler);
> +    return;
> +
> + error:
> +    virLogHandlerLogFileClose(handler, logfile);
> +    virObjectUnlock(handler);
> +}
> +
> +

[...]

> +
> +
> +static virLogHandlerLogFilePtr virLogHandlerLogFilePostExecRestart(virJSONValuePtr object)
> +{
> +    virLogHandlerLogFilePtr file;
> +    const char *path;
> +
> +    if (VIR_ALLOC(file) < 0)
> +        return NULL;
> +
> +    if ((path = virJSONValueObjectGetString(object, "path")) == NULL) {
> +        virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> +                       _("Missing file path in JSON document"));
> +        goto error;
> +    }
> +
> +    if ((file->file = virRotatingFileWriterNew(path, 128 * 1024, 2, false, 0600)) == NULL)

magic numbers (used more than once)

#define DEFAULT_FILE_SIZE 128 * 1024
#define DEFAULT_MAXBACKUP 2
#define DEFAULT_MODE 0600

> +        goto error;
> +
> +    if (virJSONValueObjectGetNumberInt(object, "pipefd", &file->pipefd) < 0) {
> +        virReportError(VIR_ERR_INTERNAL_ERROR, "%s",
> +                       _("Missing file pipefd in JSON document"));
> +        goto error;
> +    }
> +    if (virSetInherit(file->pipefd, false) < 0) {
> +        virReportSystemError(errno, "%s",
> +                             _("Cannot enable close-on-exec flag"));
> +        goto error;
> +    }
> +
> +    return file;
> +
> + error:
> +    virLogHandlerLogFileFree(file);
> +    return NULL;
> +}
> +

[...]

> +
> +char *virLogHandlerDomainReadLogFile(virLogHandlerPtr handler,
> +                                     const char *driver,
> +                                     const unsigned char *domuuid,
> +                                     const char *domname,
> +                                     ino_t inode,
> +                                     off_t offset,
> +                                     size_t maxlen)
> +{
> +    char *path;
> +    virRotatingFileReaderPtr file = NULL;
> +    char *data = NULL;

Why no locking of handler?

> +
> +    if (!(path = virLogHandlerGetLogFilePathForDomain(handler,
> +                                                      driver,
> +                                                      domuuid,
> +                                                      domname)))
> +        goto error;
> +
> +    if (!(file = virRotatingFileReaderNew(path, 2)))
> +        goto error;
> +
> +    if (virRotatingFileReaderSeek(file, inode, offset) < 0)
> +        goto error;
> +
> +    if (VIR_ALLOC_N(data, maxlen) < 0)
> +        goto error;
> +

What happens if by the time we get here the file was rotated?  Although
the current default is 2 backups, if there were 0 backups, then what?

> +    if (virRotatingFileReaderConsume(file, data, maxlen) < 0)
> +        goto error;
> +
> +    virRotatingFileReaderFree(file);
> +    return data;

path is leaked (both regular and error)

> +
> + error:
> +    VIR_FREE(data);
> +    virRotatingFileReaderFree(file);
> +    return NULL;
> +}
> +
> +

[...]

That's what I found - I don't think there's anything that I found that
would prevent an ACK, although perhaps depending on the answer to the
question posed at the top regarding the view of the client more changes
would be required in this code to handle the case(s) where the client
couldn't find the file it "had" been reading (by inode and offset).

John