Xen devel - Nov 2005 - Working hotplug, but still timing out waiting for vbd device

I''m running Xen3 7775 with udev 073 (which was a PITA to get working,
as
the initrd I''ve been running for quite some time uses an older one -- 
but that''s an entirely different story). 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.

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


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

Apologies for not including this last time.

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.

Per the log in the quoted message below, vif-bridge *is* called and 
claims that it completed successfully, which implies that it went 
through the success call at line 61 and thus should have updated 
xenstore to provide notification of its functioning state.

Obviously, there''s a step somewhere in the initialization process that
I
don''t fully understand. Anyone?

Charles Duffy wrote:
> I''m running Xen3 7775 with udev 073 (which was a PITA to get
working, as
> the initrd I''ve been running for quite some time uses an older one
--
> but that''s an entirely different story). 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.
> 
> Any suggestions as to why I would be seeing the present behaviour?

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

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?


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

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.


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

For whatever reason, /etc/hotplug/xen-backend.agent didn''t get 
installed. Put it in place manually, and all is well.


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

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.


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

Worked once, not happening again.

I''ve noticed, however, that manually running "xm unpause" on
the
impacted domains causes them to come up perfectly happily, including 
network, block devices, &c.


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

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?


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

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.

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

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.

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

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

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

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.

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

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.


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

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.


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

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.


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

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.

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

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.


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

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.

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