RE: Trivial patch to fix logging level output by XendCheckpoint.py

RE: Trivial patch to fix logging level output by XendCheckpoint.py

[Graham, Simon]

Well, I didn't expect this much discussion!!! I must admit I found it
hard to grok this code initially but I think the idea of exec'ing a
separate program is a good one to avoid the chance that xend can die
(especially since you don't currently seem to be able to restart xend
without rebooting Dom0).

Anyway - even if XendCheckpoint.py called xc_linux_save/restore
directly, you'd still have to deal with getting the output to the right
place since these APIs write their debug output directly to stderr so
I've got to believe you'd still fork a child that made the call and have
the parent slurp the contents of stderr and log them so the same issue
would exist...

Simon

> -----Original Message-----
> From: Daniel P. Berrange [mailto:berrange@redhat.com]
> Sent: Monday, November 20, 2006 4:56 PM
> To: Graham, Simon
> Cc: xen-devel@lists.xensource.com
> Subject: Re: [Xen-devel] Trivial patch to fix logging level output by
> XendCheckpoint.py
> 
> On Mon, Nov 20, 2006 at 04:34:25PM -0500, Graham, Simon wrote:
> > Signed-off by: Simon Graham <Simon.Graham@stratus.com>
> >
> > There is a somewhat trivial issue with XendCheckpoint.py right now
in
> > that it logs everything written to stderr by xc_save and xc_restore
> as
> > errors whereas in fact the vast majority of this output is
> > information/debug (and all actual errors are marked by the string
> ERROR:
> > at the start of the message) -- this is confusing to folks looking
at
> > the logs and makes automated log analysis tricky.
> >
> > Fix is to scan for the ERROR: string and log anything without it
> using
> > log.info instead.
> 
> This bit of XenD looks rather dubious to me. XenD spawns a background
> thread, which in turn forks the xc_save or xc_restore program, reading
> the stdout from this child process.
> 
> Aside from command line argument handling, the xc_save and xc_restore
> programs each only make *one* single function call to xc_linux_save or
> xc_linux_restore APIs in libxc.
> 
> But XenD already has libxc loaded & calls it directly for all other
> jobs
> its needs to do, including actually createing the domain in the first
> place.  So why is it going to all the trouble of fork'ing a child
> process
> rather than just calling  xc_linux_save/restore APIs directly ?  If it
> did this, we wouldn't need this loop to read, grok & log STDOUT from
> the
> child process at all - it would just end up in regular XenD logs.
> 
> And even more importantly, once we get the error reporting patches
> integrated
> into libxc, having the xc_linux_save/restore calls made by XenD
> directly
> would ensure we get reliable error handling for save/restore
> operations.
> 
> So, is there any good reason for xc_save & xc_restore to exist as
> separate
> processes - it just seems like a huge complication to me, increasing
> fragility of the system & reducing the quality of error reporting we
> can
> get
> 
> Regards,
> 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: Trivial patch to fix logging level output by XendCheckpoint.py

[Ewan Mellor]

On Mon, Nov 20, 2006 at 08:23:24PM -0500, Graham, Simon wrote:

> Well, I didn't expect this much discussion!!! I must admit I found it
> hard to grok this code initially but I think the idea of exec'ing a
> separate program is a good one to avoid the chance that xend can die
> (especially since you don't currently seem to be able to restart xend
> without rebooting Dom0).

That's not true -- Xend ought to be restarting itself (it forks itself so that
it has a monitor process) and even then "xend restart" ought to work.  Are you
having trouble with that?

The one process that we can't restart at the moment is xenstored.  Everything
else should be fine.

> Anyway - even if XendCheckpoint.py called xc_linux_save/restore
> directly, you'd still have to deal with getting the output to the right
> place since these APIs write their debug output directly to stderr so
> I've got to believe you'd still fork a child that made the call and have
> the parent slurp the contents of stderr and log them so the same issue
> would exist...

Yes, I think Daniel was proposing fixing all of that, too.

Ewan.

Re: Trivial patch to fix logging level output by XendCheckpoint.py

[Daniel P. Berrange]

On Tue, Nov 21, 2006 at 09:20:06AM +0000, Ewan Mellor wrote:
> On Mon, Nov 20, 2006 at 08:23:24PM -0500, Graham, Simon wrote:
> 
> > Well, I didn't expect this much discussion!!! I must admit I found it
> > hard to grok this code initially but I think the idea of exec'ing a
> > separate program is a good one to avoid the chance that xend can die
> > (especially since you don't currently seem to be able to restart xend
> > without rebooting Dom0).
> 
> That's not true -- Xend ought to be restarting itself (it forks itself so that
> it has a monitor process) and even then "xend restart" ought to work.  Are you
> having trouble with that?
> 
> The one process that we can't restart at the moment is xenstored.  Everything
> else should be fine.

While XenD itself can easily be restarted it does cause a few problems
if you have any HVM domains, or paravirt + blktap domains running. XenD
is the parent process for both qemu-dm and tapdisk helper processes. It
appears that these two are incapable of detecting shutdown of the guest
they are associated with themselves, and instead rely on XenD to tell
them when to exit / kill them. So the problem is, that if you restart
XenD these processes get re-parented to init, and then when you shutdown
the guest domain, the qemu-dm/tapdisk helpers stay around causing the
domain to linger in zombie state forever.

If we could figure out how to sort this, then XenD would be trivially
restartable without any ill effects.

> > Anyway - even if XendCheckpoint.py called xc_linux_save/restore
> > directly, you'd still have to deal with getting the output to the right
> > place since these APIs write their debug output directly to stderr so
> > I've got to believe you'd still fork a child that made the call and have
> > the parent slurp the contents of stderr and log them so the same issue
> > would exist...
> 
> Yes, I think Daniel was proposing fixing all of that, too.

Yes, the formalized libxc error handling patches would make that unncessary
if the calls were made in-process. Of course I still need to write another
iteration of those patches based on latest round of feedback, so we can put
this issue off to a later date.

Regards,
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: Trivial patch to fix logging level output by XendCheckpoint.py

[Graham, Simon]

> > > Well, I didn't expect this much discussion!!! I must admit I found
> it
> > > hard to grok this code initially but I think the idea of exec'ing
a
> > > separate program is a good one to avoid the chance that xend can
> die
> > > (especially since you don't currently seem to be able to restart
> xend
> > > without rebooting Dom0).
> >
> > That's not true -- Xend ought to be restarting itself (it forks
> itself so that
> > it has a monitor process) and even then "xend restart" ought to
work.
> Are you
> > having trouble with that?
> >
> > The one process that we can't restart at the moment is xenstored.
> Everything
> > else should be fine.
>

Yes we have had problems with this (in 3.0.2) -- however, we test this
with /etc/init.d/xend stop/start which will, I think, restart xenstored
as well, so I guess this still does not work. I will look into modifying
the test so it kills the main xend process instead to more accurately
test fault insertion in xend.

> While XenD itself can easily be restarted it does cause a few problems
> if you have any HVM domains, or paravirt + blktap domains running.
XenD
> is the parent process for both qemu-dm and tapdisk helper processes.
It
> appears that these two are incapable of detecting shutdown of the
guest
> they are associated with themselves, and instead rely on XenD to tell
> them when to exit / kill them. So the problem is, that if you restart
> XenD these processes get re-parented to init, and then when you
> shutdown
> the guest domain, the qemu-dm/tapdisk helpers stay around causing the
> domain to linger in zombie state forever.
> 
> If we could figure out how to sort this, then XenD would be trivially
> restartable without any ill effects.
> 

Ah - OK, well, we aren't testing HVM guests yet but we will be;
hopefully one of us can figure out how to solve this issue.

Simon

Re: Trivial patch to fix logging level output by XendCheckpoint.py

[Daniel P. Berrange]

On Tue, Nov 21, 2006 at 09:58:33AM -0500, Graham, Simon wrote:
> > > > Well, I didn't expect this much discussion!!! I must admit I found
> > it
> > > > hard to grok this code initially but I think the idea of exec'ing
> a
> > > > separate program is a good one to avoid the chance that xend can
> > die
> > > > (especially since you don't currently seem to be able to restart
> > xend
> > > > without rebooting Dom0).
> > >
> > > That's not true -- Xend ought to be restarting itself (it forks
> > itself so that
> > > it has a monitor process) and even then "xend restart" ought to
> work.
> > Are you
> > > having trouble with that?
> > >
> > > The one process that we can't restart at the moment is xenstored.
> > Everything
> > > else should be fine.
> >
> 
> Yes we have had problems with this (in 3.0.2) -- however, we test this
> with /etc/init.d/xend stop/start which will, I think, restart xenstored
> as well, so I guess this still does not work. I will look into modifying
> the test so it kills the main xend process instead to more accurately
> test fault insertion in xend.

The init script doesn't stop or start xenstored itself. The init script
merely starts up XenD. XenD then checks to see if xenstored is already
running, and if not starts it. When you do 'service xend stop' to shutdown
XenD it will leave xenstored running.

> > While XenD itself can easily be restarted it does cause a few problems
> > if you have any HVM domains, or paravirt + blktap domains running.
> XenD
> > is the parent process for both qemu-dm and tapdisk helper processes.
> It
> > appears that these two are incapable of detecting shutdown of the
> guest
> > they are associated with themselves, and instead rely on XenD to tell
> > them when to exit / kill them. So the problem is, that if you restart
> > XenD these processes get re-parented to init, and then when you
> > shutdown
> > the guest domain, the qemu-dm/tapdisk helpers stay around causing the
> > domain to linger in zombie state forever.
> > 
> > If we could figure out how to sort this, then XenD would be trivially
> > restartable without any ill effects.
> > 
> 
> Ah - OK, well, we aren't testing HVM guests yet but we will be;
> hopefully one of us can figure out how to solve this issue.

This isn't only an issue with HVM - the tapdisk process is used by paravirt
guests when blktap is used for file backed virtual disks.

Regards,
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: Trivial patch to fix logging level output by XendCheckpoint.py

[Ewan Mellor]

On Tue, Nov 21, 2006 at 09:58:33AM -0500, Graham, Simon wrote:

> > > > Well, I didn't expect this much discussion!!! I must admit I found
> > it
> > > > hard to grok this code initially but I think the idea of exec'ing
> a
> > > > separate program is a good one to avoid the chance that xend can
> > die
> > > > (especially since you don't currently seem to be able to restart
> > xend
> > > > without rebooting Dom0).
> > >
> > > That's not true -- Xend ought to be restarting itself (it forks
> > itself so that
> > > it has a monitor process) and even then "xend restart" ought to
> work.
> > Are you
> > > having trouble with that?
> > >
> > > The one process that we can't restart at the moment is xenstored.
> > Everything
> > > else should be fine.
> >
> 
> Yes we have had problems with this (in 3.0.2) -- however, we test this
> with /etc/init.d/xend stop/start which will, I think, restart xenstored
> as well, so I guess this still does not work.

No, /etc/init.d/xend stop doesn't (shouldn't) stop xenstored.

Ewan.

Trivial patch to fix logging level output by XendCheckpoint.py

[Graham, Simon]

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

Signed-off by: Simon Graham <Simon.Graham@stratus.com>

There is a somewhat trivial issue with XendCheckpoint.py right now in
that it logs everything written to stderr by xc_save and xc_restore as
errors whereas in fact the vast majority of this output is
information/debug (and all actual errors are marked by the string ERROR:
at the start of the message) -- this is confusing to folks looking at
the logs and makes automated log analysis tricky.

Fix is to scan for the ERROR: string and log anything without it using
log.info instead.

Regards,
Simon


[-- Attachment #2: xendcheckpoint.patch --]
[-- Type: application/octet-stream, Size: 584 bytes --]

Index: trunk/tools/python/xen/xend/XendCheckpoint.py
===================================================================
--- trunk/tools/python/xen/xend/XendCheckpoint.py	(revision 6921)
+++ trunk/tools/python/xen/xend/XendCheckpoint.py	(working copy)
@@ -234,4 +234,9 @@
         if line == "":
             break
         else:
-            log.error('%s', line.strip())
+            line = line.strip()
+            m = re.match(r"^ERROR: (.*)", line)
+            if m is None:
+                log.info('%s', line)
+            else:
+                log.error('%s', m.group(1))

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

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

Re: Trivial patch to fix logging level output by XendCheckpoint.py

[Daniel P. Berrange]

On Mon, Nov 20, 2006 at 04:34:25PM -0500, Graham, Simon wrote:
> Signed-off by: Simon Graham <Simon.Graham@stratus.com>
> 
> There is a somewhat trivial issue with XendCheckpoint.py right now in
> that it logs everything written to stderr by xc_save and xc_restore as
> errors whereas in fact the vast majority of this output is
> information/debug (and all actual errors are marked by the string ERROR:
> at the start of the message) -- this is confusing to folks looking at
> the logs and makes automated log analysis tricky.
> 
> Fix is to scan for the ERROR: string and log anything without it using
> log.info instead.

This bit of XenD looks rather dubious to me. XenD spawns a background
thread, which in turn forks the xc_save or xc_restore program, reading
the stdout from this child process.

Aside from command line argument handling, the xc_save and xc_restore
programs each only make *one* single function call to xc_linux_save or 
xc_linux_restore APIs in libxc.

But XenD already has libxc loaded & calls it directly for all other jobs
its needs to do, including actually createing the domain in the first
place.  So why is it going to all the trouble of fork'ing a child process
rather than just calling  xc_linux_save/restore APIs directly ?  If it
did this, we wouldn't need this loop to read, grok & log STDOUT from the
child process at all - it would just end up in regular XenD logs. 

And even more importantly, once we get the error reporting patches integrated
into libxc, having the xc_linux_save/restore calls made by XenD directly
would ensure we get reliable error handling for save/restore operations.

So, is there any good reason for xc_save & xc_restore to exist as separate
processes - it just seems like a huge complication to me, increasing
fragility of the system & reducing the quality of error reporting we can
get

Regards,
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: Trivial patch to fix logging level output by XendCheckpoint.py

[Anthony Liguori]

Daniel P. Berrange wrote:
> On Mon, Nov 20, 2006 at 04:34:25PM -0500, Graham, Simon wrote:
>> Signed-off by: Simon Graham <Simon.Graham@stratus.com>

> And even more importantly, once we get the error reporting patches integrated
> into libxc, having the xc_linux_save/restore calls made by XenD directly
> would ensure we get reliable error handling for save/restore operations.

It used to work that way.  xc_linux_save/restore were factored out of 
Xend late in the 3.0 dev process.  I believe the idea was that they 
should be executed with lower privileges (which is why they take file 
descriptors as command line arguments instead of just calling 
xc_interface_open() like you would expect).

I believe it was Christian who was driving this.  Perhaps he has a few 
more details?

Regards,

Anthony Liguori

> So, is there any good reason for xc_save & xc_restore to exist as separate
> processes - it just seems like a huge complication to me, increasing
> fragility of the system & reducing the quality of error reporting we can
> get
> 
> Regards,
> Dan.

Re: Trivial patch to fix logging level output by XendCheckpoint.py

[Daniel P. Berrange]

On Mon, Nov 20, 2006 at 04:34:22PM -0600, Anthony Liguori wrote:
> Daniel P. Berrange wrote:
> >On Mon, Nov 20, 2006 at 04:34:25PM -0500, Graham, Simon wrote:
> >>Signed-off by: Simon Graham <Simon.Graham@stratus.com>
> 
> >And even more importantly, once we get the error reporting patches 
> >integrated
> >into libxc, having the xc_linux_save/restore calls made by XenD directly
> >would ensure we get reliable error handling for save/restore operations.
> 
> It used to work that way.  xc_linux_save/restore were factored out of 
> Xend late in the 3.0 dev process.  I believe the idea was that they 
> should be executed with lower privileges (which is why they take file 
> descriptors as command line arguments instead of just calling 
> xc_interface_open() like you would expect).
>
> I believe it was Christian who was driving this.  Perhaps he has a few 
> more details?

Ok, looking back at the HG logs it appears  # 5099 

 "Execute xc_linux_restore in a seperate process so that it can't
  crash xend.  Also handle errors passed from xc_linux_restore and
  log info messages from xc_linux_restore."

and # 5121:

 "Implement the parts of vm save which need interaction with xend
  as part of xend, instead of using xfrd.
  Execute xc_linux_save in a seperate process so that it can't
  crash xend. Also handle errors passed from xc_linux_save.

are where these programs came into existance.

Regards,
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: Trivial patch to fix logging level output by XendCheckpoint.py

[Ewan Mellor]

On Mon, Nov 20, 2006 at 09:56:00PM +0000, Daniel P. Berrange wrote:

> On Mon, Nov 20, 2006 at 04:34:25PM -0500, Graham, Simon wrote:
> > Signed-off by: Simon Graham <Simon.Graham@stratus.com>
> > 
> > There is a somewhat trivial issue with XendCheckpoint.py right now in
> > that it logs everything written to stderr by xc_save and xc_restore as
> > errors whereas in fact the vast majority of this output is
> > information/debug (and all actual errors are marked by the string ERROR:
> > at the start of the message) -- this is confusing to folks looking at
> > the logs and makes automated log analysis tricky.
> > 
> > Fix is to scan for the ERROR: string and log anything without it using
> > log.info instead.
> 
> This bit of XenD looks rather dubious to me. XenD spawns a background
> thread, which in turn forks the xc_save or xc_restore program, reading
> the stdout from this child process.
> 
> Aside from command line argument handling, the xc_save and xc_restore
> programs each only make *one* single function call to xc_linux_save or 
> xc_linux_restore APIs in libxc.
> 
> But XenD already has libxc loaded & calls it directly for all other jobs
> its needs to do, including actually createing the domain in the first
> place.  So why is it going to all the trouble of fork'ing a child process
> rather than just calling  xc_linux_save/restore APIs directly ?  If it
> did this, we wouldn't need this loop to read, grok & log STDOUT from the
> child process at all - it would just end up in regular XenD logs. 
> 
> And even more importantly, once we get the error reporting patches integrated
> into libxc, having the xc_linux_save/restore calls made by XenD directly
> would ensure we get reliable error handling for save/restore operations.
> 
> So, is there any good reason for xc_save & xc_restore to exist as separate
> processes - it just seems like a huge complication to me, increasing
> fragility of the system & reducing the quality of error reporting we can
> get

It was done because, in the past, we didn't trust the stability of the
save and restore code, and didn't want it taking down the whole of Xend.
You could argue that that code is much more reliable now, and so we
don't need all this complexity.  Then again, with HVM live migration
work upcoming, maybe we'll come appreciate the isolation again.

Ewan.

Re: Trivial patch to fix logging level output by XendCheckpoint.py

[John Levon]

On Mon, Nov 20, 2006 at 10:40:44PM +0000, Ewan Mellor wrote:

> It was done because, in the past, we didn't trust the stability of the
> save and restore code, and didn't want it taking down the whole of Xend.

One could argue that this would be a good thing!

Having the separate programs makes debugging quite a bit more
difficult as well...

regards
john

Re: Trivial patch to fix logging level output by XendCheckpoint.py

[Ewan Mellor]

On Mon, Nov 20, 2006 at 04:34:25PM -0500, Graham, Simon wrote:

> Signed-off by: Simon Graham <Simon.Graham@stratus.com>
> 
> There is a somewhat trivial issue with XendCheckpoint.py right now in
> that it logs everything written to stderr by xc_save and xc_restore as
> errors whereas in fact the vast majority of this output is
> information/debug (and all actual errors are marked by the string ERROR:
> at the start of the message) -- this is confusing to folks looking at
> the logs and makes automated log analysis tricky.
> 
> Fix is to scan for the ERROR: string and log anything without it using
> log.info instead.

Applied, thanks.  We can continue to discuss wider improvements in this area,
but there's nothing wrong with this patch for now.

Cheers,

Ewan.