[Pkg-xen-devel] Bug#798510: 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 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>