Pkg xen devel - Sep 2015 - Bug#798510: xen-utils-common: xendomains domU auto-starting fails after upgrade to Debian 8

Package: xen-utils-common
Version: 4.4.1-9+deb8u1
Severity: important

Dear Maintainer,

After upgrading to Debian 8, auto-starting of domUs via /etc/xen/auto
fails with errors like this

Sep 09 09:29:21 host xendomains[948]: Starting Xen domain domU (from
/etc/xen/auto/domU.cfg)...failed.
Sep 09 09:29:21 host xendomains[948]: libxl: error:
libxl_exec.c:129:libxl_report_child_exitstatus: /etc/xen/scripts/block add [-1]
died due to fatal signal Killed
Sep 09 09:29:21 host xendomains[948]: libxl: error:
libxl_exec.c:129:libxl_report_child_exitstatus: /etc/xen/scripts/block add [-1]
died due to fatal signal Killed
Sep 09 09:29:21 host xendomains[948]: libxl: error:
libxl_exec.c:129:libxl_report_child_exitstatus: /etc/xen/scripts/block add [-1]
died due to fatal signal Killed
Sep 09 09:29:21 host xendomains[948]: libxl: error:
libxl_create.c:1054:domcreate_launch_dm: unable to add disk devices

Services seem to get started in the correct order according to LSB
headers in the init scripts:

Sep  9 09:28:49 host systemd[1]: Starting LSB: Xen daemons...
Sep  9 09:28:49 host xenstored: Checking store ...
Sep  9 09:28:49 host xenstored: Checking store complete.
Sep  9 09:28:49 host xen[880]: Starting Xen daemons: xenfs xenstored xenconsoled
init-dom0.
Sep  9 09:28:49 host systemd[1]: Started LSB: Xen daemons.
Sep  9 09:28:49 host systemd[1]: Starting LSB: Start/stop secondary xen
domains...

Inserting a 'sleep 10' into /etc/defaults/xendomains solves the issue,
so it seems to be some timing problem.

Cheers
Wolfgang

On Thu, 2015-09-10 at 09:06 +0200, Wolfgang Karall-Ahlborn
wrote:
> After upgrading to Debian 8, auto-starting of domUs via /etc/xen/auto
> fails with errors like this
> 
> Sep 09 09:29:21 host xendomains[948]: Starting Xen domain domU (from
/etc/xen/auto/domU.cfg)...failed.
> Sep 09 09:29:21 host xendomains[948]: libxl: error:
libxl_exec.c:129:libxl_report_child_exitstatus: /etc/xen/scripts/block add [-1]
died due to fatal signal Killed
> Sep 09 09:29:21 host xendomains[948]: libxl: error:
libxl_exec.c:129:libxl_report_child_exitstatus: /etc/xen/scripts/block add [-1]
died due to fatal signal Killed
> Sep 09 09:29:21 host xendomains[948]: libxl: error:
libxl_exec.c:129:libxl_report_child_exitstatus: /etc/xen/scripts/block add [-1]
died due to fatal signal Killed
> Sep 09 09:29:21 host xendomains[948]: libxl: error:
libxl_create.c:1054:domcreate_launch_dm: unable to add disk devices
I suppose these domains all start just fine by hand, because the race
is well over by then...

Do you get anything further under /var/log/xen when this occurs? In
particular the xl files associated with the domain and
/var/log/xen/xen-hotplug.log

What does the disk configuration look like in domU.cfg?

It would also be useful to edit /etc/init.d/xendomains to change:
    out=$(xen create --quiet --defconfig "$file" 2>&1
1>/dev/null)
to?
    out=$(xen -vvv create --quiet --defconfig "$file" 2>&1
1>/dev/null)

(adding -vvv before create) and maybe replace /dev/null with something
like /tmp/xendomains.$(basename $file).log

Hopefully something in there will give us some clue what is not ready
yet.
> Services seem to get started in the correct order according to LSB
> headers in the init scripts:
> 
> Sep??9 09:28:49 host systemd[1]: Starting LSB: Xen daemons...
> Sep??9 09:28:49 host xenstored: Checking store ...
> Sep??9 09:28:49 host xenstored: Checking store complete.
> Sep??9 09:28:49 host xen[880]: Starting Xen daemons: xenfs xenstored
xenconsoled init-dom0.
> Sep??9 09:28:49 host systemd[1]: Started LSB: Xen daemons.
> Sep??9 09:28:49 host systemd[1]: Starting LSB: Start/stop secondary xen
domains...
> 
> Inserting a 'sleep 10' into /etc/defaults/xendomains solves the
issue,
> so it seems to be some timing problem.
Whereabouts? Near the start I guess.

Ian.
>

Hi Ian,

On 15-11-05 10:43:56, Ian Campbell wrote:
> I suppose these domains all start just fine by hand, because the race
> is well over by then...
Indeed they do.
> Do you get anything further under /var/log/xen when this occurs? In
> particular the xl files associated with the domain and
> /var/log/xen/xen-hotplug.log
Specifically xen-hotplug.log isn't modified at all, it's actually pretty
old while both the dom0 and also the domU were restarted a couple of
times today.

-rw-r--r-- 1 root adm    6735 Sep  9 10:13 xen-hotplug.log

The domU log files in /var/log/xen only seem to contain the shutdown
sequences, all start with lines like

Waiting for domain test-inetng1 (domid 1) to die [pid 1336]

but nothing related to the start of the domU.
> What does the disk configuration look like in domU.cfg?
$ sed -n '/^disk/,/]/p' /etc/xen/test-inetng1.cfg
disk        = [
                  'phy:/dev/inetng1/test-inetng1-disk,xvda2,w',
                  'phy:/dev/inetng1/test-inetng1-swap,xvda1,w',
                  'phy:/dev/inetng1/test-inetng1-data,xvdb,w',
              ]
> It would also be useful to edit /etc/init.d/xendomains to change:
>     out=$(xen create --quiet --defconfig "$file" 2>&1
1>/dev/null)
> to?
>     out=$(xen -vvv create --quiet --defconfig "$file" 2>&1
1>/dev/null)
> 
> (adding -vvv before create) and maybe replace /dev/null with something
> like /tmp/xendomains.$(basename $file).log
> 
> Hopefully something in there will give us some clue what is not ready
> yet.
I've changed it to

  out=$(xen -vvv create --quiet --defconfig "$file" 2>&1 | ts
"%b %d %H:%M:%.S" 1>/tmp/xendomains.$(basename $file).log)

to get some timestamps into the log with the help of moreutil's ts.

Also, I've added

  exec 5>> /tmp/xen-script-block-$1-$$.log
  BASH_XTRACEFD="5"
  PS4='+ \011$(date "+%b %d %H:%M:%S.%N"): $LINENO: '
  set -x

to the top of the helper script in /etc/xen/scripts/block.

With the additional timing information available, a colleague spotted
logger being late in the non-working case:

in the logs in /tmp/xen*:

  Nov 12 13:47:29.614355156: 21: logger -p daemon.debug --
/etc/xen/scripts/block: add XENBUS_PATH=backend/vbd/1/51728
  Nov 12 13:47:39.422965 libxl: debug:
libxl_device.c:1059:device_hotplug_timeout_cb: killing hotplug script
/etc/xen/scripts/block add because of timeout

in /var/log/syslog:

  Nov 12 13:47:41 inetng1 logger: /etc/xen/scripts/block: add
XENBUS_PATH=backend/vbd/1/51728

Disabling logger in /etc/xen/scripts/logging.sh made the problem go
away and the domU was started successfully at boot time.

But of course this is not a real solution but only a workaround, as much
as adding sleep to the default file.
> > Inserting a 'sleep 10' into /etc/defaults/xendomains solves
the issue,
> > so it seems to be some timing problem.
> 
> Whereabouts? Near the start I guess.
No, I've added it to the end of the file.

Cheers
Wolfgang

PS: My colleague also found this mailing list article
http://lists.freedesktop.org/archives/systemd-devel/2014-August/021767.html
mentioning the problem with logging being blocked at boot time with
systemd.

PPS: In case you need the full logs, I can attach them to the bug
report.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 836 bytes
Desc: Digital signature
URL:
<http://lists.alioth.debian.org/pipermail/pkg-xen-devel/attachments/20151112/6baddf9b/attachment.sig>

Hi,

Thanks for your report.

FYI Actually fixing this is on the TODO list for Buster:
https://salsa.debian.org/xen-team/debian-xen/issues/24

It's true that in order to have xendomains restore things after reboot,
the network bridge has to be functional, so it's clear that this has to
be fixed.

Hans

Your message dated Fri, 22 Feb 2019 16:37:31 +0000
with message-id <E1gxDpL-000AII-GM at fasolo.debian.org>
and subject line Bug#798510: fixed in xen 4.11.1+26-g87f51bf366-2
has caused the Debian Bug report #798510,
regarding xen-utils-common: xendomains domU auto-starting fails after upgrade to
Debian 8
to be marked as done.

This means that you claim that the problem has been dealt with.
If this is not the case it is now your responsibility to reopen the
Bug report if necessary, and/or fix the problem forthwith.

(NB: If you are a system administrator and have no idea what this
message is talking about, this may indicate a serious mail system
misconfiguration somewhere. Please contact owner at bugs.debian.org
immediately.)


-- 
798510: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=798510
Debian Bug Tracking System
Contact owner at bugs.debian.org with problems
-------------- next part --------------
An embedded message was scrubbed...
From: Wolfgang Karall-Ahlborn <lists+debian-bugs at karall-edv.at>
Subject: xen-utils-common: xendomains domU auto-starting fails after upgrade to
Debian 8
Date: Thu, 10 Sep 2015 09:06:51 +0200
Size: 4101
URL:
<http://alioth-lists.debian.net/pipermail/pkg-xen-devel/attachments/20190222/d6d23301/attachment.mht>
-------------- next part --------------
An embedded message was scrubbed...
From: Ian Jackson <ijackson at chiark.greenend.org.uk>
Subject: Bug#798510: fixed in xen 4.11.1+26-g87f51bf366-2
Date: Fri, 22 Feb 2019 16:37:31 +0000
Size: 19112
URL:
<http://alioth-lists.debian.net/pipermail/pkg-xen-devel/attachments/20190222/d6d23301/attachment-0001.mht>