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

[Francois Lesueur]

Hi,

I face a very similar bug since I upgraded to stretch, but related to
network bridges :

xendomains[1361]: libxl: error:
libxl_device.c:1225:device_hotplug_child_death_cb: script: Could not
find bridge device brdmz

It of course works well when I launch domus after boot. Seems that
networking bridges are not up when xendomains start.

In my case, adding a dependency on $network in /etc/init.d/xendomains
seems to solve this issue. Should this dependency be added in the
package or do you think it will introduce other problems ?

Cheers,
Francois



On Thu, 12 Nov 2015 18:10:26 +0100 Wolfgang Karall-Ahlborn
 wrote:
> 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 adm6735 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.
> 

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

[Wolfgang Karall-Ahlborn]

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 adm6735 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.


signature.asc
Description: Digital signature

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

[Ian Campbell]

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.
>