PATCH: Add persistent guest & hv logging in xenconsoled

PATCH: Add persistent guest & hv logging in xenconsoled

[Daniel P. Berrange]

[-- Attachment #1: Type: text/plain, Size: 2655 bytes --]

The attached patch adds the persistent logging to the xenconsoled daemon.

  * The  --log  command line argument takes one of 4 values

      - none   - no logging   (the default)
      - hv     - log all hypervisor messages
      - guest  - log all guest messages
      - both   - log all guest & hypervisor messages

  * The --log-dir command line argument takes a path to specify where
    to store logfiles. If omitted it defaults to /var/log/xen/console

  * The hypervisor logfile is $LOGDIR/hypervisor.log

  * The guest logfile is  $LOGDIR/guest-[NAME].log

  * If receiving a SIGHUP it will close & re-open all log files to
    enable logrotate to do its magic

  * Fixes the permissions of /var/run/xenconsoled.pid

  * Adds a --pid-file command line argument to override the default
    location of pid file (this is not really related to logging, but
    since i was in that code...)


  Signed-off-by: Daniel P. Berrange <berrange@redhat.com>


The patch was done against 3.1.0  codebase, but applies against todays
xen-unstable.hg - though I see alot of stuff pending in the staging
tree, hopefully it won't break it.

There are 2 open questions....

The first is how to configure & pass the --log arg to xenconsoled. In the
upstream xen codebase the various daemons (xenstore, xenconsoled, etc)
are all forked by the tools/misc/xend script (typically in /usr/sbin/xend).
In Fedora we're intending to ditch this script & just start each daemon
directly from the init script & thus we can use /etc/sysconfig/xend to
configure the logging args. Solaris also doesn't use that tools/misc/xend
script IIRC, having their own scripts for stopping/starting distros. So
in this patch I've not made any attempt to provide a way to actually pass
the --log arg to xenconsoled, leaving such decisions upto the distro
packagers. Any alternate ideas are welcome...

When logging hypervisor data we call xc_readconsolering to fetch the data.
Since we don't want to log the same data over & over again we have to tell
it to clear the console. So if you enable hypervisor logging in xenconsoled,
then 'xm dmesg' will no longer show you any data. Personally I don't have
any problem with this, but if there's a way to reliably consume hypervisor 
logs in an incremental manner without having to clear the data I'm open
to suggestions...

Dan.
-- 
|=- Red Hat, Engineering, Emerging Technologies, Boston.  +1 978 392 2496 -=|
|=-           Perl modules: http://search.cpan.org/~danberr/              -=|
|=-               Projects: http://freshmeat.net/~danielpb/               -=|
|=-  GnuPG: 7D3B9505   F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505  -=| 

[-- Attachment #2: xen-console-log.patch --]
[-- Type: text/plain, Size: 9110 bytes --]

diff -rup xen-3.1.0-testing.hg-rc7.orig/tools/console/daemon/io.c xen-3.1.0-testing.hg-rc7.new/tools/console/daemon/io.c
--- xen-3.1.0-testing.hg-rc7.orig/tools/console/daemon/io.c	2007-05-03 12:49:28.000000000 -0400
+++ xen-3.1.0-testing.hg-rc7.new/tools/console/daemon/io.c	2007-05-31 16:42:18.000000000 -0400
@@ -44,6 +44,14 @@
 /* Each 10 bits takes ~ 3 digits, plus one, plus one for nul terminator. */
 #define MAX_STRLEN(x) ((sizeof(x) * CHAR_BIT + CHAR_BIT-1) / 10 * 3 + 2)
 
+extern int log_reload;
+extern int log_guest;
+extern int log_hv;
+extern char *log_dir;
+
+static int log_hv_fd = -1;
+static int xc_handle = -1;
+
 struct buffer
 {
 	char *data;
@@ -57,6 +65,7 @@ struct domain
 {
 	int domid;
 	int tty_fd;
+	int log_fd;
 	bool is_dead;
 	struct buffer buffer;
 	struct domain *next;
@@ -103,6 +112,19 @@ static void buffer_append(struct domain 
 	intf->out_cons = cons;
 	xc_evtchn_notify(dom->xce_handle, dom->local_port);
 
+	/* Get the data to the logfile as early as possible because if
+	 * no one is listening on the console pty then it will fill up
+	 * and handle_tty_write will stop being called.
+	 */
+	if (dom->log_fd != -1) {
+		int len = write(dom->log_fd,
+				buffer->data + buffer->size - size,
+				size);
+		if (len < 0)
+			dolog(LOG_ERR, "Write to log failed on domain %d: %d (%s)\n",
+			      dom->domid, errno, strerror(errno));
+	}
+
 	if (buffer->max_capacity &&
 	    buffer->size > buffer->max_capacity) {
 		/* Discard the middle of the data. */
@@ -144,6 +166,53 @@ static bool domain_is_valid(int domid)
 	return ret;
 }
 
+static int create_hv_log(void)
+{
+	char logfile[PATH_MAX];
+	int fd;
+	snprintf(logfile, PATH_MAX-1, "%s/hypervisor.log", log_dir);
+	logfile[PATH_MAX-1] = '\0';
+
+	fd = open(logfile, O_WRONLY|O_CREAT|O_APPEND, 0644);
+	if (fd == -1)
+		dolog(LOG_ERR, "Failed to open log %s: %d (%s)",
+		      logfile, errno, strerror(errno));
+	return fd;
+}
+
+static int create_domain_log(struct domain *dom)
+{
+	char logfile[PATH_MAX];
+	char *namepath, *data, *s;
+	int fd, len;
+
+	namepath = xs_get_domain_path(xs, dom->domid);
+	s = realloc(namepath, strlen(namepath) + 6);
+	if (s == NULL) {
+		free(namepath);
+		return -1;
+	}
+	strcat(namepath, "/name");
+	data = xs_read(xs, XBT_NULL, namepath, &len);
+	if (!data)
+		return -1;
+	if (!len) {
+		free(data);
+		return -1;
+	}
+
+	snprintf(logfile, PATH_MAX-1, "%s/guest-%s.log", log_dir, data);
+	free(data);
+	logfile[PATH_MAX-1] = '\0';
+
+	fd = open(logfile, O_WRONLY|O_CREAT|O_APPEND, 0644);
+	if (fd == -1)
+		dolog(LOG_ERR, "Failed to open log %s: %d (%s)",
+		      logfile, errno, strerror(errno));
+	return fd;
+}
+
+
 static int domain_create_tty(struct domain *dom)
 {
 	char *path;
@@ -325,6 +394,9 @@ static int domain_create_ring(struct dom
 		}
 	}
 
+	if (log_guest)
+		dom->log_fd = create_domain_log(dom);
+
  out:
 	return err;
 }
@@ -352,6 +424,7 @@ static bool watch_domain(struct domain *
 	return success;
 }
 
+
 static struct domain *create_domain(int domid)
 {
 	struct domain *dom;
@@ -383,6 +456,8 @@ static struct domain *create_domain(int 
 	strcat(dom->conspath, "/console");
 
 	dom->tty_fd = -1;
+	dom->log_fd = -1;
+
 	dom->is_dead = false;
 	dom->buffer.data = 0;
 	dom->buffer.consumed = 0;
@@ -444,6 +519,10 @@ static void cleanup_domain(struct domain
 		close(d->tty_fd);
 		d->tty_fd = -1;
 	}
+	if (d->log_fd != -1) {
+		close(d->log_fd);
+		d->log_fd = -1;
+	}
 
 	free(d->buffer.data);
 	d->buffer.data = NULL;
@@ -605,13 +684,54 @@ static void handle_xs(void)
 	free(vec);
 }
 
+static void handle_hv_logs(void)
+{
+	char buffer[1024*16];
+	char *bufptr = buffer;
+	unsigned int size = sizeof(buffer);
+	if (xc_readconsolering(xc_handle, &bufptr, &size, 1) == 0) {
+		int len = write(log_hv_fd, buffer, size);
+		if (len < 0)
+			dolog(LOG_ERR, "Failed to write hypervisor log: %d (%s)",
+			      errno, strerror(errno));
+	}
+}
+
+static void handle_log_reload(void)
+{
+	if (log_guest) {
+		struct domain *d;
+		for (d = dom_head; d; d = d->next) {
+			if (d->log_fd != -1)
+				close(d->log_fd);
+			d->log_fd = create_domain_log(d);
+		}
+	}
+
+	if (log_hv) {
+		if (log_hv_fd != -1)
+			close(log_hv_fd);
+		log_hv_fd = create_hv_log();
+	}
+}
+
 void handle_io(void)
 {
 	fd_set readfds, writefds;
 	int ret;
 
-	do {
+	if (log_hv) {
+		xc_handle = xc_interface_open();
+		if (xc_handle == -1)
+			dolog(LOG_ERR, "Failed to open xc handle: %d (%s)",
+			      errno, strerror(errno));
+		else
+			log_hv_fd = create_hv_log();
+	}
+
+	for (;;) {
 		struct domain *d, *n;
+		struct timeval timeout = { 1, 0 }; /* Read HV logs every 1 second */
 		int max_fd = -1;
 
 		FD_ZERO(&readfds);
@@ -637,7 +757,30 @@ void handle_io(void)
 			}
 		}
 
-		ret = select(max_fd + 1, &readfds, &writefds, 0, NULL);
+		/* XXX I wish we didn't have to busy wait for hypervisor logs
+		 * but there's no obvious way to get event channel notifications
+		 * for new HV log data as we can with guest */
+		ret = select(max_fd + 1, &readfds, &writefds, 0, log_hv_fd != -1 ? &timeout : NULL);
+
+		if (ret == -1) {
+			if (errno == EINTR) {
+				if (log_reload) {
+					handle_log_reload();
+					log_reload = 0;
+				}
+				continue;
+			}
+			dolog(LOG_ERR, "Failure in select: %d (%s)",
+			      errno, strerror(errno));
+			break;
+		}
+
+		/* Check for timeout */
+		if (ret == 0) {
+			if (log_hv_fd != -1)
+				handle_hv_logs();
+			continue;
+		}
 
 		if (FD_ISSET(xs_fileno(xs), &readfds))
 			handle_xs();
@@ -657,7 +800,12 @@ void handle_io(void)
 			if (d->is_dead)
 				cleanup_domain(d);
 		}
-	} while (ret > -1);
+	}
+
+	if (log_hv_fd != -1)
+		close(log_hv_fd);
+	if (xc_handle != -1)
+		xc_interface_close(xc_handle);
 }
 
 /*
diff -rup xen-3.1.0-testing.hg-rc7.orig/tools/console/daemon/main.c xen-3.1.0-testing.hg-rc7.new/tools/console/daemon/main.c
--- xen-3.1.0-testing.hg-rc7.orig/tools/console/daemon/main.c	2007-05-03 12:49:28.000000000 -0400
+++ xen-3.1.0-testing.hg-rc7.new/tools/console/daemon/main.c	2007-05-31 14:16:57.000000000 -0400
@@ -23,6 +23,8 @@
 #include <stdio.h>
 #include <errno.h>
 #include <unistd.h>
+#include <string.h>
+#include <signal.h>
 #include <sys/types.h>
 
 #include "xenctrl.h"
@@ -30,9 +32,19 @@
 #include "utils.h"
 #include "io.h"
 
+int log_reload = 0;
+int log_guest = 0;
+int log_hv = 0;
+char *log_dir = NULL;
+
+static void handle_hup(int sig)
+{
+        log_reload = 1;
+}
+
 static void usage(char *name)
 {
-	printf("Usage: %s [-h] [-V] [-v] [-i]\n", name);
+	printf("Usage: %s [-h] [-V] [-v] [-i] [--log=none|guest|hv|all] [--log-dir=DIR] [--pid-file=PATH]\n", name);
 }
 
 static void version(char *name)
@@ -48,6 +60,9 @@ int main(int argc, char **argv)
 		{ "version", 0, 0, 'V' },
 		{ "verbose", 0, 0, 'v' },
 		{ "interactive", 0, 0, 'i' },
+		{ "log", 1, 0, 'l' },
+		{ "log-dir", 1, 0, 'r' },
+		{ "pid-file", 1, 0, 'p' },
 		{ 0 },
 	};
 	bool is_interactive = false;
@@ -55,6 +70,7 @@ int main(int argc, char **argv)
 	int syslog_option = LOG_CONS;
 	int syslog_mask = LOG_WARNING;
 	int opt_ind = 0;
+	char *pidfile;
 
 	while ((ch = getopt_long(argc, argv, sopts, lopts, &opt_ind)) != -1) {
 		switch (ch) {
@@ -71,6 +87,22 @@ int main(int argc, char **argv)
 		case 'i':
 			is_interactive = true;
 			break;
+		case 'l':
+		        if (!strcmp(optarg, "all")) {
+			      log_hv = 1;
+			      log_guest = 1;
+			} else if (!strcmp(optarg, "hv")) {
+			      log_hv = 1;
+			} else if (!strcmp(optarg, "guest")) {
+			      log_guest = 1;
+			}
+			break;
+		case 'r':
+		        log_dir = strdup(optarg);
+			break;
+		case 'p':
+		        pidfile = strdup(optarg);
+			break;
 		case '?':
 			fprintf(stderr,
 				"Try `%s --help' for more information\n",
@@ -79,16 +111,22 @@ int main(int argc, char **argv)
 		}
 	}
 
+	if (!log_dir) {
+		log_dir = strdup("/var/log/xen/console");
+	}
+
 	if (geteuid() != 0) {
 		fprintf(stderr, "%s requires root to run.\n", argv[0]);
 		exit(EPERM);
 	}
 
+	signal(SIGHUP, handle_hup);
+
 	openlog("xenconsoled", syslog_option, LOG_DAEMON);
 	setlogmask(syslog_mask);
 
 	if (!is_interactive) {
-		daemonize("/var/run/xenconsoled.pid");
+		daemonize(pidfile ? pidfile : "/var/run/xenconsoled.pid");
 	}
 
 	if (!xen_setup())
@@ -99,6 +137,18 @@ int main(int argc, char **argv)
 	handle_io();
 
 	closelog();
+	free(log_dir);
+	free(pidfile);
 
 	return 0;
 }
+
+/*
+ * Local variables:
+ *  c-file-style: "linux"
+ *  indent-tabs-mode: t
+ *  c-indent-level: 8
+ *  c-basic-offset: 8
+ *  tab-width: 8
+ * End:
+ */
diff -rup xen-3.1.0-testing.hg-rc7.orig/tools/console/daemon/utils.c xen-3.1.0-testing.hg-rc7.new/tools/console/daemon/utils.c
--- xen-3.1.0-testing.hg-rc7.orig/tools/console/daemon/utils.c	2007-05-03 12:49:28.000000000 -0400
+++ xen-3.1.0-testing.hg-rc7.new/tools/console/daemon/utils.c	2007-05-31 14:49:32.000000000 -0400
@@ -86,7 +86,7 @@ void daemonize(const char *pidfile)
 	if (chdir("/") < 0)
 		exit (1);
 
-	fd = open(pidfile, O_RDWR | O_CREAT);
+	fd = open(pidfile, O_RDWR | O_CREAT, S_IRUSR|S_IWUSR);
 	if (fd == -1) {
 		exit(1);
 	}
Only in xen-3.1.0-testing.hg-rc7.new/tools/console/daemon: utils.c~

[-- Attachment #3: Type: text/plain, Size: 138 bytes --]

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel

Re: PATCH: Add persistent guest & hv logging in xenconsoled

[Keir Fraser]

On 31/5/07 22:32, "Daniel P. Berrange" <berrange@redhat.com> wrote:

> The first is how to configure & pass the --log arg to xenconsoled. In the
> upstream xen codebase the various daemons (xenstore, xenconsoled, etc)
> are all forked by the tools/misc/xend script (typically in /usr/sbin/xend).
> In Fedora we're intending to ditch this script & just start each daemon
> directly from the init script & thus we can use /etc/sysconfig/xend to
> configure the logging args. Solaris also doesn't use that tools/misc/xend
> script IIRC, having their own scripts for stopping/starting distros. So
> in this patch I've not made any attempt to provide a way to actually pass
> the --log arg to xenconsoled, leaving such decisions upto the distro
> packagers. Any alternate ideas are welcome...

For guest logging it'd be nice to have the option to specify via xenstore
where the log file should be written. Then it could be decided per guest by
xend, perhaps via a config file option. Having a blanket option on the
cmdline *as well* as a fallback is okay though. Other useful options would
be max log size (both in terms of max logging to a file, and max buffering
for the pty), again these could be read from xenstore per guest, with a
cmdline-specifiable fallback.

> When logging hypervisor data we call xc_readconsolering to fetch the data.
> Since we don't want to log the same data over & over again we have to tell
> it to clear the console. So if you enable hypervisor logging in xenconsoled,
> then 'xm dmesg' will no longer show you any data. Personally I don't have
> any problem with this, but if there's a way to reliably consume hypervisor
> logs in an incremental manner without having to clear the data I'm open
> to suggestions...

I thought I'd applied a patch to improve this interface, clearly I haven't
though. I'll look into it.

 -- Keir

Re: PATCH: Add persistent guest & hv logging in xenconsoled

[Daniel P. Berrange]

On Fri, Jun 01, 2007 at 09:10:36AM +0100, Keir Fraser wrote:
> On 31/5/07 22:32, "Daniel P. Berrange" <berrange@redhat.com> wrote:
> 
> > The first is how to configure & pass the --log arg to xenconsoled. In the
> > upstream xen codebase the various daemons (xenstore, xenconsoled, etc)
> > are all forked by the tools/misc/xend script (typically in /usr/sbin/xend).
> > In Fedora we're intending to ditch this script & just start each daemon
> > directly from the init script & thus we can use /etc/sysconfig/xend to
> > configure the logging args. Solaris also doesn't use that tools/misc/xend
> > script IIRC, having their own scripts for stopping/starting distros. So
> > in this patch I've not made any attempt to provide a way to actually pass
> > the --log arg to xenconsoled, leaving such decisions upto the distro
> > packagers. Any alternate ideas are welcome...
> 
> For guest logging it'd be nice to have the option to specify via xenstore
> where the log file should be written. Then it could be decided per guest by
> xend, perhaps via a config file option. Having a blanket option on the
> cmdline *as well* as a fallback is okay though. Other useful options would
> be max log size (both in terms of max logging to a file, and max buffering
> for the pty), again these could be read from xenstore per guest, with a
> cmdline-specifiable fallback.

IMHO getting Xenstore involved in this is needlessly complicating what
ultimately should be a simple problem - just need to decide how to make
XenD pass a suitable argument when starting the daemon.  I have posted
a separate mail describing changes we're doing in Fedora to the init 
scripts which allow the user to directly customize startup args for any
of the Xen related daemons.

Per guest log file names sounds like rather overkill IMHO and having max 
log sizes is unneccessary because logrotate is already capable of managing
the files being created. eg, a config like

 $ cat /etc/logrotate.d/xenconsoled
 /var/log/xen/console/* {
    notifempty
    missingok
    postrotate
        /bin/kill -HUP `cat /var/run/xenconsoled.pid 2>/dev/null` 1>/dev/null 2>&1 || true
    endscript
 }

> > When logging hypervisor data we call xc_readconsolering to fetch the data.
> > Since we don't want to log the same data over & over again we have to tell
> > it to clear the console. So if you enable hypervisor logging in xenconsoled,
> > then 'xm dmesg' will no longer show you any data. Personally I don't have
> > any problem with this, but if there's a way to reliably consume hypervisor
> > logs in an incremental manner without having to clear the data I'm open
> > to suggestions...
> 
> I thought I'd applied a patch to improve this interface, clearly I haven't
> though. I'll look into it.

I could be misunderstanding the interface - but it seems that if I don't
use the clear flag to xc_readconsolering i'd just get the same data over
and over.

Dan.
-- 
|=- Red Hat, Engineering, Emerging Technologies, Boston.  +1 978 392 2496 -=|
|=-           Perl modules: http://search.cpan.org/~danberr/              -=|
|=-               Projects: http://freshmeat.net/~danielpb/               -=|
|=-  GnuPG: 7D3B9505   F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505  -=| 

Re: PATCH: Add persistent guest & hv logging in xenconsoled

[Keir Fraser]

On 1/6/07 14:51, "Daniel P. Berrange" <berrange@redhat.com> wrote:

>> I thought I'd applied a patch to improve this interface, clearly I haven't
>> though. I'll look into it.
> 
> I could be misunderstanding the interface - but it seems that if I don't
> use the clear flag to xc_readconsolering i'd just get the same data over
> and over.

Yeah, the interface does need changing.

 -- Keir

Re: PATCH: Add persistent guest & hv logging in xenconsoled

[Keir Fraser]

On 31/5/07 22:32, "Daniel P. Berrange" <berrange@redhat.com> wrote:

>   * Adds a --pid-file command line argument to override the default
>     location of pid file (this is not really related to logging, but
>     since i was in that code...)

Applied, thanks. But...

Use of uninitialised local variable pidfile detected by gcc in this patch.
You guys really should consider using -Werror. It's great. :-)

Also, shouldn't the writes to log files be non-blocking, and those fds be
added to the select set when there is data waiting to be written?

 -- Keir

Re: PATCH: Add persistent guest & hv logging in xenconsoled

[Daniel P. Berrange]

On Mon, Jun 04, 2007 at 02:48:25PM +0100, Keir Fraser wrote:
> On 31/5/07 22:32, "Daniel P. Berrange" <berrange@redhat.com> wrote:
> 
> >   * Adds a --pid-file command line argument to override the default
> >     location of pid file (this is not really related to logging, but
> >     since i was in that code...)
> 
> Applied, thanks. But...
> 
> Use of uninitialised local variable pidfile detected by gcc in this patch.
> You guys really should consider using -Werror. It's great. :-)

Opps, we do use -Werror for all formal builds - dunno how that got missed.

> Also, shouldn't the writes to log files be non-blocking, and those fds be
> added to the select set when there is data waiting to be written?

IIRC, if you select() on a local file handle it'll always be shown writable
so I don't believe it'll be any use.

Dan.
-- 
|=- Red Hat, Engineering, Emerging Technologies, Boston.  +1 978 392 2496 -=|
|=-           Perl modules: http://search.cpan.org/~danberr/              -=|
|=-               Projects: http://freshmeat.net/~danielpb/               -=|
|=-  GnuPG: 7D3B9505   F3C9 553F A1DA 4AC2 5648 23C1 B3DF F742 7D3B 9505  -=| 

Re: PATCH: Add persistent guest & hv logging in xenconsoled

[Keir Fraser]

On 4/6/07 14:52, "Daniel P. Berrange" <berrange@redhat.com> wrote:

>> Also, shouldn't the writes to log files be non-blocking, and those fds be
>> added to the select set when there is data waiting to be written?
> 
> IIRC, if you select() on a local file handle it'll always be shown writable
> so I don't believe it'll be any use.

The kernel code appears to agree with you! Fair enough then.

 -- Keir