Working hotplug, but still timing out waiting for vbd device ("changing physical-device not supported"?)

Working hotplug, but still timing out waiting for vbd device ("changing physical-device not supported"?)

[Charles Duffy]

This has previously been posted to xen-users, but not seen any response 
as of yet. (Granted, it's a weekend and only 15 hours since my initial 
post; I hope I'm not being excessively impatient).

I'm running Xen3 7775 with udev 073. My dom0 is Gentoo-based. When I try 
to start a DomU, it times out waiting for hotplug-based notification, as 
per the following:

DEBUG (DevController:69) Waiting for devices vif.
DEBUG (DevController:75) Waiting for 0.
DEBUG (DevController:69) Waiting for devices usb.
DEBUG (DevController:69) Waiting for devices vbd.
DEBUG (DevController:75) Waiting for 769.
ERROR (SrvBase:87) Request wait_for_devices failed.
Traceback (most recent call last):
   File 
"/usr/src/xen-unstable.hg/dist/install/usr/lib64/python/xen/web/SrvBase.py", 
line 85, in perform
     return op_method(op, req)
   File 
"/usr/src/xen-unstable.hg/dist/install/usr/lib64/python/xen/xend/server/SrvDomain.py", 
line 68, in op_wait_for_devices
     return self.dom.waitForDevices()
   File 
"/usr/src/xen-unstable.hg/dist/install/usr/lib64/python/xen/xend/XendDomainInfo.py", 
line 1200, in waitForDevices
     self.waitForDevices_(c)
   File 
"/usr/src/xen-unstable.hg/dist/install/usr/lib64/python/xen/xend/XendDomainInfo.py", 
line 856, in waitForDevices_
     return self.getDeviceController(deviceClass).waitForDevices()
   File 
"/usr/src/xen-unstable.hg/dist/install/usr/lib64/python/xen/xend/server/DevController.py", 
line 71, in waitForDevices
     return map(self.waitForDevice, self.deviceIDs())
   File 
"/usr/src/xen-unstable.hg/dist/install/usr/lib64/python/xen/xend/server/DevController.py", 
line 80, in waitForDevice
     raise VmError( ("Device %s (%s) could not be connected. "
VmError: Device 769 (vbd) could not be connected. Hotplug scripts not 
working

However, based on the following passage from /var/log/messages, the 
relevant vbd backend *really did* start up and try to provide 
notification of its new state:

logger: /etc/xen/scripts/block: bind XENBUS_PATH=backend/vbd/1/769
logger: /etc/xen/scripts/block: bind XENBUS_PATH=backend/vbd/1/770
logger: /etc/xen/scripts/block: Writing 
backend/vbd/1/770/physical-device 0xfd04 backend/vbd/1/770/node 
/dev/data/demo-1-swap to xenstore.
changing physical-device not supported
changing physical-device not supported
logger: /etc/xen/scripts/block: Writing backend/vbd/1/770/hotplug-status 
connected to xenstore.
changing physical-device not supported
logger: /etc/xen/scripts/block: Writing 
backend/vbd/1/769/physical-device 0xfd03 backend/vbd/1/769/node 
/dev/data/demo-1 to xenstore.
logger: /etc/xen/scripts/vif-bridge: bridge=xenbr0 up 
XENBUS_PATH=backend/vif/1/0
logger: /etc/xen/scripts/block: Writing backend/vbd/1/769/hotplug-status 
connected to xenstore.
changing physical-device not supported
changing physical-device not supported
changing physical-device not supported
device vif1.0 entered promiscuous mode
xenbr0: port 3(vif1.0) entering learning state
logger: /etc/xen/scripts/vif-bridge: Writing 
backend/vif/1/0/hotplug-status connected to xenstore.
xenbr0: topology change detected, propagating
xenbr0: port 3(vif1.0) entering forwarding state
logger: /etc/xen/scripts/vif-bridge: Successful vif-bridge operation for 
vif1.0, bridge xenbr0.

Note the "changing physical-device not supported" messages. My disks are 
indeed specified as phy devices, as per the following:

disk = [ 'phy:data/demo-1,hda1,w', 'phy:data/demo-1-swap,hda2,w' ]

However, I'd hope that being specified as physical devices wouldn't 
impede hotplug notification.


Running diagnose.py on the relevant domain yields the following output:

Domain ID is 2.
Domain name is demo-1.
Found 2 device classes in use.
Found 1 vbd devices.
Found device vbd, 770.
Backend is stuck waiting for frontend for device vbd, 770.
Device vbd, 770 hotplugging has completed successfully.
Found 1 vif devices.
Found device vif, 0.
Backend is stuck waiting for frontend for device vif, 0.

Notably, this identifies the backend as blocking on vif,0; whereas the 
message log indicates "Successful vif-bridge operation for vif1.0, 
bridge xenbr0".


Any suggestions as to why I would be seeing the present behaviour?

[FIXED] Re: Working hotplug, but still timing out waiting for vbd device

[Charles Duffy]

For whatever reason, running install.sh wasn't installing 
/etc/hotplug/xen-backend.agent. Put it in place manually, and all is well.

Sorry for the noise.

[FIXED - NOT!] Re: Working hotplug, but still timing out waiting for vbd device

[Charles Duffy]

So it worked for me... once. Not happening again.

Oddly enough, though, I manually ran "xm unpause" on one of the domains 
which was paused on account of devices not being detected as 
available... and it came up perfectly happily. I've verified that both 
network and block device access function.

Timing out waiting for vbd device *only when xend started with trace_start*

[Charles Duffy]

Since this issue was obviously happening only for me, I went looking for 
potential causes specific to my configuration.

My init scripts start xend with trace_start.

I backed this out (to just use "start"), rebooted, and everything came 
up normally. Rebooted again, likewise. Changed it back to trace_start, 
rebooted again, same failure as described in the thread this should be 
attached to. Changed it to start again, works.

So -- for the initial issue, I have a workaround by way of avoiding 
trace_start, but I'd argue that it's quite certainly a bug that 
trace_start has side effects of this variety. Should I file a bug, or 
does someone else have it?

Re: Timing out waiting for vbd device *only when xend started with trace_start*

[Ewan Mellor]

On Mon, Nov 14, 2005 at 05:31:00AM -0600, Charles Duffy wrote:

> Since this issue was obviously happening only for me, I went looking for 
> potential causes specific to my configuration.
> 
> My init scripts start xend with trace_start.
> 
> I backed this out (to just use "start"), rebooted, and everything came 
> up normally. Rebooted again, likewise. Changed it back to trace_start, 
> rebooted again, same failure as described in the thread this should be 
> attached to. Changed it to start again, works.
> 
> So -- for the initial issue, I have a workaround by way of avoiding 
> trace_start, but I'd argue that it's quite certainly a bug that 
> trace_start has side effects of this variety. Should I file a bug, or 
> does someone else have it?

This is showing up intermittently with our regression tests.  It seems to be a
race of some sort, which would be consistent with it going away or coming back
when you fiddle with the logging -- all you are doing is changing the timing
of things so that it appears or does not appear.

If you export XENSTORED_TRACE=1 before starting Xend and Xenstored, then you
will get a log file in /var/log/xenstored-trace.log.  This information is
interesting to me, because it shows the ordering over time of the store
events, which makes it easier to piece together what's going on.

Also, could you put a line in
/usr/lib/python/xen/xend/server/DevController.py, to log entry into the
hotplugStatus function (the syntax is log.debug("hotplugStatus entered"), and
it goes below the def hotplugStatus(): line).

With these two things together, if you could reproduce the problem and then
send me /var/log/xend.log and /var/log/xenstored-trace.log, this will help me
to track down the problem.

Unfortunately, I cannot reproduce this myself at the moment, so this will be
the quickest way for you to get the problem diagnosed.

Thanks a lot for your help,

Ewan.

Re: Timing out waiting for vbd device *only when xend started with trace_start*

[Charles Duffy]

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

Ewan Mellor wrote:
> This is showing up intermittently with our regression tests.  It seems to be a
> race of some sort, which would be consistent with it going away or coming back
> when you fiddle with the logging -- all you are doing is changing the timing
> of things so that it appears or does not appear.
> 
> If you export XENSTORED_TRACE=1 before starting Xend and Xenstored, then you
> will get a log file in /var/log/xenstored-trace.log.  This information is
> interesting to me, because it shows the ordering over time of the store
> events, which makes it easier to piece together what's going on.

It does indeed feel like a race condition. Unfortunetly, setting 
XENSTORED_TRACE impacts the timing such as to make it nonreproducible.

> Also, could you put a line in
> /usr/lib/python/xen/xend/server/DevController.py, to log entry into the
> hotplugStatus function (the syntax is log.debug("hotplugStatus entered"), and
> it goes below the def hotplugStatus(): line).

Done; xend.log attached. No xenstored.trace yet for the reason described 
above.

Since the issue appears to be happening when xend is running below full 
speed but xenstored is not, I'm wondering if some mechanism to 
artificially slow xend (running it in valgrind?) would be effective in 
permitting the issue to be reproduced with tracing in place on both 
processes. I'll look into it, unless you have other suggestions.

[-- Attachment #2: xend.log.bz2 --]
[-- Type: application/x-bzip2, Size: 2293 bytes --]

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

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

Re: Timing out waiting for vbd device *only when xend started with trace_start*

[Charles Duffy]

Ewan Mellor wrote:
> Thanks for that.  Both you and Friedmund Lassmann are seeing the same bug.  If
> you look, you have a line from xenstored-trace.log:
> 
> OUT 0x1208c548 02:29:59 WATCH_EVENT (/local/domain/0/backend/vif/1/0 363717120 )
> 
> which is the firing of the watch, but the line from xend.log:
> 
> [2005-11-14 02:31:59 xend] DEBUG (DevController:286) hotplugStatus entered
> 
> doesn't execute until 2 minutes later, when the other thread times out.  In
> other words, I think that the waiting thread has hold of a lock, and so the
> thread waiting to deliver the watch is locked out.  I can't find that lock
> though, and I still can't reproduce this!  If either of you can get a hold on
> the problem, then that would be great.

Hmmm.

It might be nice if the xend trace handler were expanded to print both 
current PID (or thread name) and timestamp when indicating that a line 
is being executed. Not something I have time to do right now -- and 
other people are prone to using the host in question during business 
hours -- but I'll take a shot at it tomorrow morning if time permits and 
nobody else has beat me to it.

That said, the only lock I see being handled closely prior to this 
occurance is xslock in xenstore/xswatch.py:watchStart.

Re: Timing out waiting for vbd device *only when xend started with trace_start*

[Ewan Mellor]

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

On Mon, Nov 14, 2005 at 10:11:27AM -0600, Charles Duffy wrote:

> It might be nice if the xend trace handler were expanded to print both 
> current PID (or thread name) and timestamp when indicating that a line 
> is being executed.

Ask and ye shall receive an attachment.

Ewan.

[-- Attachment #2: logging-thread.patch --]
[-- Type: text/plain, Size: 556 bytes --]

diff -r 6d981d34cf52 tools/python/xen/xend/XendLogging.py
--- a/tools/python/xen/xend/XendLogging.py	Mon Nov 14 11:28:47 2005
+++ b/tools/python/xen/xend/XendLogging.py	Mon Nov 14 16:30:29 2005
@@ -42,7 +42,7 @@
 DEFAULT_BACKUP_COUNT = 5
 
 STDERR_FORMAT = "[%(name)s] %(levelname)s (%(module)s:%(lineno)d) %(message)s"
-LOGFILE_FORMAT = "[%(asctime)s %(name)s] %(levelname)s (%(module)s:%(lineno)d) %(message)s"
+LOGFILE_FORMAT = "[%(asctime)s %(name)s %(thread)d] %(levelname)s (%(module)s:%(lineno)d) %(message)s"
 DATE_FORMAT = "%Y-%m-%d %H:%M:%S"
 
 

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

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

Re: Timing out waiting for vbd device *only when xend started with trace_start*

[Charles Duffy]

Ewan Mellor wrote:
> On Mon, Nov 14, 2005 at 10:11:27AM -0600, Charles Duffy wrote:
> 
>>It might be nice if the xend trace handler were expanded to print both 
>>current PID (or thread name) and timestamp when indicating that a line 
>>is being executed.
> 
> Ask and ye shall receive an attachment.

Nifty -- but not quite what I had in mind.

I was thinking about modifying the *tracing*, not the *logging*; thus, 
it would be the code in xend/server/SrvDaemon.py:trace that would be 
impacted.

This would allow for a substantially higher granularity -- seeing where 
we are not just on every log statement, but on every line executed by 
the interpreter.

Re: Timing out waiting for vbd device *only when xend started with trace_start*

[Ewan Mellor]

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

On Mon, Nov 14, 2005 at 10:40:58AM -0600, Charles Duffy wrote:

> Ewan Mellor wrote:
> >On Mon, Nov 14, 2005 at 10:11:27AM -0600, Charles Duffy wrote:
> >
> >>It might be nice if the xend trace handler were expanded to print both 
> >>current PID (or thread name) and timestamp when indicating that a line 
> >>is being executed.
> >
> >Ask and ye shall receive an attachment.
> 
> Nifty -- but not quite what I had in mind.
> 
> I was thinking about modifying the *tracing*, not the *logging*; thus, 
> it would be the code in xend/server/SrvDaemon.py:trace that would be 
> impacted.

You'll be after this one then!

I don't think I'll check this in just yet, as it may significantly affect
performance.  If someone wanted to make this configurable in a way that didn't
hurt tracing performance too much, that would be good.

Ewan.

[-- Attachment #2: trace-thread.patch --]
[-- Type: text/plain, Size: 646 bytes --]

diff -r 6d981d34cf52 tools/python/xen/xend/server/SrvDaemon.py
--- a/tools/python/xen/xend/server/SrvDaemon.py	Mon Nov 14 11:28:47 2005
+++ b/tools/python/xen/xend/server/SrvDaemon.py	Mon Nov 14 17:19:07 2005
@@ -8,7 +8,9 @@
 import os
 import signal
 import sys
+import thread
 import threading
+import time
 import linecache
 import pwd
 import re
@@ -201,6 +203,8 @@
                 pass
 
     def print_trace(self, string):
+        self.tracefile.write(time.strftime("%Y-%m-%d %H:%M:%S "))
+        self.tracefile.write("%10x" % thread.get_ident())
         for i in range(self.traceindent):
             ch = " "
             if (i % 5):

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

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

Re: Timing out waiting for vbd device *only when xend started with trace_start*

[Ewan Mellor]

On Mon, Nov 14, 2005 at 11:51:08AM +0000, Ewan Mellor wrote:

> On Mon, Nov 14, 2005 at 05:31:00AM -0600, Charles Duffy wrote:
> 
> > Since this issue was obviously happening only for me, I went looking for 
> > potential causes specific to my configuration.
> > 
> > My init scripts start xend with trace_start.
> > 
> > I backed this out (to just use "start"), rebooted, and everything came 
> > up normally. Rebooted again, likewise. Changed it back to trace_start, 
> > rebooted again, same failure as described in the thread this should be 
> > attached to. Changed it to start again, works.
> > 
> > So -- for the initial issue, I have a workaround by way of avoiding 
> > trace_start, but I'd argue that it's quite certainly a bug that 
> > trace_start has side effects of this variety. Should I file a bug, or 
> > does someone else have it?
> 
> This is showing up intermittently with our regression tests.  It seems to be
> a race of some sort, which would be consistent with it going away or coming
> back when you fiddle with the logging -- all you are doing is changing the
> timing of things so that it appears or does not appear.

I found it.  xs_watch is racing with xs_read_watch, meaning that the watch can
fire before xs_watch has put the appropriate entry in its internal lists.
A patch is being tested at the moment, and will push today.

This is the bug affecting Charles Duffy, Friedmund Lassmann, and Hien Nguyen
(bug #392).

This has been in the code since early September -- it is only now that we are
using watches in Xend to check for hotplug success or failure that it has
become apparent.

Ewan.

Re: Working hotplug, but still timing out waiting for vbd device ("changing physical-device not supported"?)

[Ewan Mellor]

On Sun, Nov 13, 2005 at 11:37:06AM -0600, Charles Duffy wrote:

> changing physical-device not supported

Actually Charles, I've just noticed this in your earlier mail, and this
suggests something a little more serious going on than I first thought
(actually you might have two problems, so if you could still address the
potential race, that would be good).

Does this happen immediately after a reboot?

Are you using NFS anywhere, say as your dom 0 root fs?

Ewan.

Re: Working hotplug, but still timing out waiting for vbd device ("changing physical-device not supported"?)

[Charles Duffy]

Ewan Mellor wrote:
> On Sun, Nov 13, 2005 at 11:37:06AM -0600, Charles Duffy wrote:
> 
>>changing physical-device not supported
> 
> Actually Charles, I've just noticed this in your earlier mail, and this
> suggests something a little more serious going on than I first thought
> (actually you might have two problems, so if you could still address the
> potential race, that would be good).

Yes; I'll get you feedback on the other item within the next few hours.

> Does this happen immediately after a reboot?

Let's see... I have it happening on the first DomU startups after one 
boot... and don't see it anywhere else in my logs, particularly 
including my more recent test boots.

On the occasion when it *did* happen (that's still covered in the 
available logs), logs were as follows:

Nov 12 15:03:34 demo-xen net.agent[8280]: add event not handled
Nov 12 15:03:35 demo-xen logger: /etc/xen/scripts/block: bind 
XENBUS_PATH=backend/vbd/1/769
Nov 12 15:03:35 demo-xen logger: /etc/xen/scripts/block: bind 
XENBUS_PATH=backend/vbd/1/770
Nov 12 15:03:35 demo-xen logger: /etc/xen/scripts/block: Writing 
backend/vbd/1/770/physical-device 0xfd04 backend/vbd/1/770/node 
/dev/data/demo-1-swap to xenstore.
Nov 12 15:03:35 demo-xen changing physical-device not supported
Nov 12 15:03:35 demo-xen changing physical-device not supported
Nov 12 15:03:35 demo-xen logger: /etc/xen/scripts/block: Writing 
backend/vbd/1/770/hotplug-status connected to xenstore.
Nov 12 15:03:35 demo-xen changing physical-device not supported
Nov 12 15:03:35 demo-xen logger: /etc/xen/scripts/block: Writing 
backend/vbd/1/769/physical-device 0xfd03 backend/vbd/1/769/node 
/dev/data/demo-1 to xenstore.
Nov 12 15:03:35 demo-xen logger: /etc/xen/scripts/vif-bridge: 
bridge=xenbr0 up XENBUS_PATH=backend/vif/1/0
Nov 12 15:03:35 demo-xen logger: /etc/xen/scripts/block: Writing 
backend/vbd/1/769/hotplug-status connected to xenstore.
Nov 12 15:03:35 demo-xen changing physical-device not supported
Nov 12 15:03:35 demo-xen changing physical-device not supported
Nov 12 15:03:35 demo-xen changing physical-device not supported

> Are you using NFS anywhere, say as your dom 0 root fs?

No NFS. My root is LVM over local drives only (and likewise, my DomUs' 
block devices all are phy: pointing at logical volumes).

Re: Working hotplug, but still timing out waiting for vbd device ("changing physical-device not supported"?)

[Ewan Mellor]

On Mon, Nov 14, 2005 at 06:10:39AM -0600, Charles Duffy wrote:

> Ewan Mellor wrote:
> >On Sun, Nov 13, 2005 at 11:37:06AM -0600, Charles Duffy wrote:
> >
> >>changing physical-device not supported
> >
> >Actually Charles, I've just noticed this in your earlier mail, and this
> >suggests something a little more serious going on than I first thought
> >(actually you might have two problems, so if you could still address the
> >potential race, that would be good).
> 
> Yes; I'll get you feedback on the other item within the next few hours.
> 
> >Does this happen immediately after a reboot?
> 
> Let's see... I have it happening on the first DomU startups after one 
> boot... and don't see it anywhere else in my logs, particularly 
> including my more recent test boots.

Hmm.  There's a possibility that stale state in the store would cause this.
It's convoluted, but I think it's possible.  If you see it again, then

xenstore-rm /local
xenstore-rm /vm
reboot

would be a good idea (assuming that this is a test box and you don't care
about what's on it!).  If it's gone away, then let's focus on the hotplug
script problem.

There is a patch coming through soon that should help with the "changing
physical-device" problem, assuming that it _is_ stale state that's causing it.

Cheers,

Ewan.