[PATCH] tools/xc: restore logging in xc_save

[PATCH] tools/xc: restore logging in xc_save

[Olaf Hering]

# HG changeset patch
# User Olaf Hering <olaf@aepfle.de>
# Date 1359745022 -3600
# Node ID d76b38b799293ff17fed8eaaac8fbbebced1b72f
# Parent  6d1d516ecaade56f796e3216e9931fdcc12282cd
tools/xc: restore logging in xc_save

Prior to xen-4.1 the helper xc_save would print some progress during
migration. With the new xc_interface_open API no more messages were
printed because no logger was configured.

Restore previous behaviour by providing a logger. The progress in
xc_domain_save will be disabled because its output lacks a linefeed
which makes xend.log look ugly.

Signed-off-by: Olaf Hering <olaf@aepfle.de>

diff -r 6d1d516ecaad -r d76b38b79929 tools/xcutils/xc_save.c
--- a/tools/xcutils/xc_save.c
+++ b/tools/xcutils/xc_save.c
@@ -166,17 +166,15 @@ static int switch_qemu_logdirty(int domi
 int
 main(int argc, char **argv)
 {
-    unsigned int maxit, max_f;
+    unsigned int maxit, max_f, lflags;
     int io_fd, ret, port;
     struct save_callbacks callbacks;
+    xentoollog_level lvl;
+    xentoollog_logger *l;
 
     if (argc != 6)
         errx(1, "usage: %s iofd domid maxit maxf flags", argv[0]);
 
-    si.xch = xc_interface_open(0,0,0);
-    if (!si.xch)
-        errx(1, "failed to open control interface");
-
     io_fd = atoi(argv[1]);
     si.domid = atoi(argv[2]);
     maxit = atoi(argv[3]);
@@ -185,6 +183,13 @@ main(int argc, char **argv)
 
     si.suspend_evtchn = -1;
 
+    lvl = si.flags & XCFLAGS_DEBUG ? XTL_DEBUG: XTL_DETAIL;
+    lflags = XTL_STDIOSTREAM_HIDE_PROGRESS;
+    l = (xentoollog_logger *)xtl_createlogger_stdiostream(stderr, lvl, lflags);
+    si.xch = xc_interface_open(l, 0, 0);
+    if (!si.xch)
+        errx(1, "failed to open control interface");
+
     si.xce = xc_evtchn_open(NULL, 0);
     if (si.xce == NULL)
         warnx("failed to open event channel handle");

Re: [PATCH] tools/xc: restore logging in xc_save

[Ian Campbell]

On Fri, 2013-02-01 at 18:58 +0000, Olaf Hering wrote:
> # HG changeset patch
> # User Olaf Hering <olaf@aepfle.de>
> # Date 1359745022 -3600
> # Node ID d76b38b799293ff17fed8eaaac8fbbebced1b72f
> # Parent  6d1d516ecaade56f796e3216e9931fdcc12282cd
> tools/xc: restore logging in xc_save
> 
> Prior to xen-4.1 the helper xc_save would print some progress during
> migration. With the new xc_interface_open API no more messages were
> printed because no logger was configured.
> 
> Restore previous behaviour by providing a logger. The progress in
> xc_domain_save will be disabled because its output lacks a linefeed
> which makes xend.log look ugly.
> 
> Signed-off-by: Olaf Hering <olaf@aepfle.de>
> 
> diff -r 6d1d516ecaad -r d76b38b79929 tools/xcutils/xc_save.c
> --- a/tools/xcutils/xc_save.c
> +++ b/tools/xcutils/xc_save.c
> @@ -166,17 +166,15 @@ static int switch_qemu_logdirty(int domi
>  int
>  main(int argc, char **argv)
>  {
> -    unsigned int maxit, max_f;
> +    unsigned int maxit, max_f, lflags;
>      int io_fd, ret, port;
>      struct save_callbacks callbacks;
> +    xentoollog_level lvl;
> +    xentoollog_logger *l;
>  
>      if (argc != 6)
>          errx(1, "usage: %s iofd domid maxit maxf flags", argv[0]);
>  
> -    si.xch = xc_interface_open(0,0,0);
> -    if (!si.xch)
> -        errx(1, "failed to open control interface");
> -
>      io_fd = atoi(argv[1]);
>      si.domid = atoi(argv[2]);
>      maxit = atoi(argv[3]);
> @@ -185,6 +183,13 @@ main(int argc, char **argv)
>  
>      si.suspend_evtchn = -1;
>  
> +    lvl = si.flags & XCFLAGS_DEBUG ? XTL_DEBUG: XTL_DETAIL;
> +    lflags = XTL_STDIOSTREAM_HIDE_PROGRESS;

Would it be useful (as an extension) to implement an XTL_STDIOSTREAM
flag which makes it output something more suitable for logging,
e.g. ...10%...20%...30%... 
(or perhaps automatic based on isatty(outputfd)?)

> +    l = (xentoollog_logger *)xtl_createlogger_stdiostream(stderr, lvl, lflags);

Might this fail and therefore require error handling?

The lvl and lflags variables seem a bit useless to me.

> +    si.xch = xc_interface_open(l, 0, 0);
> +    if (!si.xch)
> +        errx(1, "failed to open control interface");
> +
>      si.xce = xc_evtchn_open(NULL, 0);
>      if (si.xce == NULL)
>          warnx("failed to open event channel handle");
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

Re: [PATCH] tools/xc: restore logging in xc_save

[Olaf Hering]

On Mon, Feb 04, Ian Campbell wrote:

> On Fri, 2013-02-01 at 18:58 +0000, Olaf Hering wrote:
> > +    lvl = si.flags & XCFLAGS_DEBUG ? XTL_DEBUG: XTL_DETAIL;
> > +    lflags = XTL_STDIOSTREAM_HIDE_PROGRESS;
> 
> Would it be useful (as an extension) to implement an XTL_STDIOSTREAM
> flag which makes it output something more suitable for logging,
> e.g. ...10%...20%...30%... 
> (or perhaps automatic based on isatty(outputfd)?)

I was thinking about that, to extend the called progress functions. In
the case of xend.log it would produce many lines of progress.
Since the default xend logging is limited to 1MB, the xend.log file
would be rotated quickly and maybe useful logging output will be lost?

But for other callers of the progress functions it might be useful to
have a parsable output so that they dont have to jump through the hoops.
No idea if any caller makes use of the progress, given that it did not
work at all without the other patch I sent last Friday.

> > +    l = (xentoollog_logger *)xtl_createlogger_stdiostream(stderr, lvl, lflags);
> 
> Might this fail and therefore require error handling?

If it fails then no logging will happen.

> The lvl and lflags variables seem a bit useless to me.

They are there to keep the lines short.

Olaf

Re: [PATCH] tools/xc: restore logging in xc_save

[Ian Campbell]

On Mon, 2013-02-04 at 10:23 +0000, Olaf Hering wrote:
> On Mon, Feb 04, Ian Campbell wrote:
> 
> > On Fri, 2013-02-01 at 18:58 +0000, Olaf Hering wrote:
> > > +    lvl = si.flags & XCFLAGS_DEBUG ? XTL_DEBUG: XTL_DETAIL;
> > > +    lflags = XTL_STDIOSTREAM_HIDE_PROGRESS;
> > 
> > Would it be useful (as an extension) to implement an XTL_STDIOSTREAM
> > flag which makes it output something more suitable for logging,
> > e.g. ...10%...20%...30%... 
> > (or perhaps automatic based on isatty(outputfd)?)
> 
> I was thinking about that, to extend the called progress functions. In
> the case of xend.log it would produce many lines of progress.

How come many lines? I imaged the above as a single line.

> Since the default xend logging is limited to 1MB, the xend.log file
> would be rotated quickly and maybe useful logging output will be lost?
> 
> But for other callers of the progress functions it might be useful to
> have a parsable output so that they dont have to jump through the hoops.
> No idea if any caller makes use of the progress, given that it did not
> work at all without the other patch I sent last Friday.

xl migrate uses AFAIK, which isn't to say it wasn't broken ;-)

> 
> > > +    l = (xentoollog_logger *)xtl_createlogger_stdiostream(stderr, lvl, lflags);
> > 
> > Might this fail and therefore require error handling?
> 
> If it fails then no logging will happen.

Which I suppose is better than failing the migration altogether.

> 
> > The lvl and lflags variables seem a bit useless to me.
> 
> They are there to keep the lines short

I would have done:
    l = (xentoollog_logger *)xtl_createlogger_stdiostream(stderr,
                                        si.flags & XCFLAGS_DEBUG ? XTL_DEBUG: XTL_DETAIL,
                                        XTL_STDIOSTREAM_HIDE_PROGRESS);

But OK.

I think that addresses both of my questions, so
	Acked-by: Ian Campbell <ian.campbell@citrix.com>

Although I did mean to ask why the code had to move?

(I've been avoiding committing anything while we sort out the staging
backlog, and I seem to have a massive email backlog this morning to
boot, but this is in my queue)

Ian.

Re: [PATCH] tools/xc: restore logging in xc_save

[Olaf Hering]

On Mon, Feb 04, Ian Campbell wrote:

> On Mon, 2013-02-04 at 10:23 +0000, Olaf Hering wrote:
> > On Mon, Feb 04, Ian Campbell wrote:
> > 
> > > On Fri, 2013-02-01 at 18:58 +0000, Olaf Hering wrote:
> > > > +    lvl = si.flags & XCFLAGS_DEBUG ? XTL_DEBUG: XTL_DETAIL;
> > > > +    lflags = XTL_STDIOSTREAM_HIDE_PROGRESS;
> > > 
> > > Would it be useful (as an extension) to implement an XTL_STDIOSTREAM
> > > flag which makes it output something more suitable for logging,
> > > e.g. ...10%...20%...30%... 
> > > (or perhaps automatic based on isatty(outputfd)?)
> > 
> > I was thinking about that, to extend the called progress functions. In
> > the case of xend.log it would produce many lines of progress.
> 
> How come many lines? I imaged the above as a single line.

Oh, I did not realize that we did not talk about
XTL_STDIOSTREAM_HIDE_PROGRESS but about another new flag.


> > No idea if any caller makes use of the progress, given that it did not
> > work at all without the other patch I sent last Friday.
> 
> xl migrate uses AFAIK, which isn't to say it wasn't broken ;-)

For me it was not printed without the patch in
<6d1d516ecaade56f796e.1359738924@probook.site>

> Although I did mean to ask why the code had to move?

To get to si.flags.

Olaf

Re: [PATCH] tools/xc: restore logging in xc_save

[Ian Campbell]

On Mon, 2013-02-04 at 10:50 +0000, Olaf Hering wrote:
> On Mon, Feb 04, Ian Campbell wrote:
> 
> > On Mon, 2013-02-04 at 10:23 +0000, Olaf Hering wrote:
> > > On Mon, Feb 04, Ian Campbell wrote:
> > > 
> > > > On Fri, 2013-02-01 at 18:58 +0000, Olaf Hering wrote:
> > > > > +    lvl = si.flags & XCFLAGS_DEBUG ? XTL_DEBUG: XTL_DETAIL;
> > > > > +    lflags = XTL_STDIOSTREAM_HIDE_PROGRESS;
> > > > 
> > > > Would it be useful (as an extension) to implement an XTL_STDIOSTREAM
> > > > flag which makes it output something more suitable for logging,
> > > > e.g. ...10%...20%...30%... 
> > > > (or perhaps automatic based on isatty(outputfd)?)
> > > 
> > > I was thinking about that, to extend the called progress functions. In
> > > the case of xend.log it would produce many lines of progress.
> > 
> > How come many lines? I imaged the above as a single line.
> 
> Oh, I did not realize that we did not talk about
> XTL_STDIOSTREAM_HIDE_PROGRESS but about another new flag.

Right, or perhaps changing the behaviour of the !HIDE_PROGRESS flag
based on isatty, which would also perhaps fix the ugliness here:
http://www.chiark.greenend.org.uk/~xensrcts/logs/15367/test-amd64-amd64-xl/11.ts-guest-localmigrate.log
(not a big deal though)

> 
> 
> > > No idea if any caller makes use of the progress, given that it did not
> > > work at all without the other patch I sent last Friday.
> > 
> > xl migrate uses AFAIK, which isn't to say it wasn't broken ;-)
> 
> For me it was not printed without the patch in
> <6d1d516ecaade56f796e.1359738924@probook.site>

I guess this is in my queue somewhere, I'll take a look.

> > Although I did mean to ask why the code had to move?
> 
> To get to si.flags.

A-ha!

Thanks,
Ian.

Re: [PATCH] tools/xc: restore logging in xc_save

[Olaf Hering]

On Mon, Feb 04, Ian Campbell wrote:

> On Fri, 2013-02-01 at 18:58 +0000, Olaf Hering wrote:
> > # HG changeset patch
> > # User Olaf Hering <olaf@aepfle.de>
> > # Date 1359745022 -3600
> > # Node ID d76b38b799293ff17fed8eaaac8fbbebced1b72f
> > # Parent  6d1d516ecaade56f796e3216e9931fdcc12282cd
> > tools/xc: restore logging in xc_save
> > 
> > Prior to xen-4.1 the helper xc_save would print some progress during
> > migration. With the new xc_interface_open API no more messages were
> > printed because no logger was configured.
> > 
> > Restore previous behaviour by providing a logger. The progress in
> > xc_domain_save will be disabled because its output lacks a linefeed
> > which makes xend.log look ugly.
> > 
> > Signed-off-by: Olaf Hering <olaf@aepfle.de>
> > 
> > diff -r 6d1d516ecaad -r d76b38b79929 tools/xcutils/xc_save.c
> > --- a/tools/xcutils/xc_save.c
> > +++ b/tools/xcutils/xc_save.c
> > @@ -166,17 +166,15 @@ static int switch_qemu_logdirty(int domi
> >  int
> >  main(int argc, char **argv)
> >  {
> > -    unsigned int maxit, max_f;
> > +    unsigned int maxit, max_f, lflags;
> >      int io_fd, ret, port;
> >      struct save_callbacks callbacks;
> > +    xentoollog_level lvl;
> > +    xentoollog_logger *l;
> >  
> >      if (argc != 6)
> >          errx(1, "usage: %s iofd domid maxit maxf flags", argv[0]);
> >  
> > -    si.xch = xc_interface_open(0,0,0);
> > -    if (!si.xch)
> > -        errx(1, "failed to open control interface");
> > -
> >      io_fd = atoi(argv[1]);
> >      si.domid = atoi(argv[2]);
> >      maxit = atoi(argv[3]);
> > @@ -185,6 +183,13 @@ main(int argc, char **argv)
> >  
> >      si.suspend_evtchn = -1;
> >  
> > +    lvl = si.flags & XCFLAGS_DEBUG ? XTL_DEBUG: XTL_DETAIL;
> > +    lflags = XTL_STDIOSTREAM_HIDE_PROGRESS;
> 
> Would it be useful (as an extension) to implement an XTL_STDIOSTREAM
> flag which makes it output something more suitable for logging,
> e.g. ...10%...20%...30%... 
> (or perhaps automatic based on isatty(outputfd)?)

It could be as simple as this tested patch, if its a logfile always
write a new line.

What do you think about this approach?

Olaf

tools/xc: handle tty output differently in stdiostream_progress

Signed-off-by: Olaf Hering <olaf@aepfle.de>

diff -r d9b27c9c40a2 -r 5d7a62db6b3b tools/libxc/xtl_logger_stdio.c
--- a/tools/libxc/xtl_logger_stdio.c
+++ b/tools/libxc/xtl_logger_stdio.c
@@ -86,7 +86,7 @@ static void stdiostream_progress(struct 
                                  const char *doing_what, int percent,
                                  unsigned long done, unsigned long total) {
     xentoollog_logger_stdiostream *lg = (void*)logger_in;
-    int newpel, extra_erase;
+    int newpel, extra_erase, istty;
     xentoollog_level this_level;
 
     if (lg->flags & XTL_STDIOSTREAM_HIDE_PROGRESS)
@@ -105,7 +105,9 @@ static void stdiostream_progress(struct 
     if (this_level < lg->min_level)
         return;
 
-    if (lg->progress_erase_len)
+    istty = isatty(fileno(lg->f)) > 0;
+
+    if (istty && lg->progress_erase_len)
         putc('\r', lg->f);
 
     lg->progress_last_percent = percent;
@@ -113,10 +115,10 @@ static void stdiostream_progress(struct 
     newpel = fprintf(lg->f, "%s%s" "%s: %lu/%lu  %3d%%%s",
                      context?context:"", context?": ":"",
                      doing_what, done, total, percent,
-		     done == total ? "\n" : "");
+		     (done == total) || !istty ? "\n" : "");
 
     extra_erase = lg->progress_erase_len - newpel;
-    if (extra_erase > 0)
+    if (istty && extra_erase > 0)
         fprintf(lg->f, "%*s\r", extra_erase, "");
 
     lg->progress_erase_len = newpel;

Re: [PATCH] tools/xc: restore logging in xc_save

[Olaf Hering]

On Wed, Feb 13, Olaf Hering wrote:

> What do you think about this approach?

I think its not perfect. If XTL_STDIOSTREAM_SHOW_PID or
XTL_STDIOSTREAM_SHOW_DATE is requested, then both will not be printed. I
will let stdiostream_vmessage print the message if the output is not a
tty.

Olaf