Xen devel - Nov 2012 - Custom block script started twice for root block but only stopped once

Hi,

I''m using a custom block script in my xen setup and when started, it
creates a new device node pointing to some network resources.

Now I noticed that the script is called twice for the root block, the
first time for pygrub most likely, but is only stopped once ... I
don''t mind creating two devices node, but then I need to destroy both
...

Is this a known issue ?

 Cheers,

    Sylvain

On Fri, 2012-11-02 at 10:37 +0000, Sylvain Munaut wrote:
> Hi,
> 
> I''m using a custom block script in my xen setup and when started,
it
> creates a new device node pointing to some network resources.
> 
> Now I noticed that the script is called twice for the root block, the
> first time for pygrub most likely, but is only stopped once ... I
> don''t mind creating two devices node, but then I need to destroy
both
> ...
> 
> Is this a known issue ?
Not one I''ve heard. Running "xl -vvv create" might provide
some logs
which give an idea what is going on, likewise the logging
in /var/log/xen/...

Roger -- any ideas?

Ian.
> 
>  Cheers,
> 
>     Sylvain
> 
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xen.org
> http://lists.xen.org/xen-devel

On 08/11/12 09:26, Ian Campbell wrote:
> On Fri, 2012-11-02 at 10:37 +0000, Sylvain Munaut wrote:
>> Hi,
>>
>> I''m using a custom block script in my xen setup and when
started, it
>> creates a new device node pointing to some network resources.
>>
>> Now I noticed that the script is called twice for the root block, the
>> first time for pygrub most likely, but is only stopped once ... I
>> don''t mind creating two devices node, but then I need to
destroy both
>> ...
>>
>> Is this a known issue ?
> 
> Not one I''ve heard. Running "xl -vvv create" might
provide some logs
> which give an idea what is going on, likewise the logging
> in /var/log/xen/...
> 
> Roger -- any ideas?
Yes, I''ve been able to reproduce the error when using stubdoms,
I''m
currently working on a fix. Have you seen this when using stubdomains
Sylvain?

Also I''ve realized that when using stubdomains with disks that use file
based backends ("file:/") it doesn''t work, is this already
known, or a
regression?

Roger.

On Fri, 2012-11-09 at 15:36 +0000, Roger Pau Monne
wrote:
> Also I''ve realized that when using stubdomains with disks that use
> file based backends ("file:/") it doesn''t work, is this
already known,
> or a regression? 
It''s news to me... I don''t know if it is a regression, but it
seems like
it ought to work.

Ian.

On 09/11/12 16:36, Roger Pau Monné wrote:
> On 08/11/12 09:26, Ian Campbell wrote:
>> On Fri, 2012-11-02 at 10:37 +0000, Sylvain Munaut wrote:
>>> Hi,
>>>
>>> I''m using a custom block script in my xen setup and when
started, it
>>> creates a new device node pointing to some network resources.
>>>
>>> Now I noticed that the script is called twice for the root block,
the
>>> first time for pygrub most likely, but is only stopped once ... I
>>> don''t mind creating two devices node, but then I need to
destroy both
>>> ...
>>>
>>> Is this a known issue ?
>>
>> Not one I''ve heard. Running "xl -vvv create" might
provide some logs
>> which give an idea what is going on, likewise the logging
>> in /var/log/xen/...
>>
>> Roger -- any ideas?
> 
> Yes, I''ve been able to reproduce the error when using stubdoms,
I''m
> currently working on a fix. Have you seen this when using stubdomains
> Sylvain?
I''ve been thinking about this, and I think it''s the right
thing to do to
call hotplug scripts twice when using stubdomains. Each script gets
called for the corresponding PV interface of each guest. Here is a
stripped trace of the creation of a guest with a stubdomain:

[...]
libxl: debug: libxl_device.c:919:device_hotplug: for-domain: 46 - calling
hotplug script: /etc/xen/scripts/block add
[...]
libxl: debug: libxl_device.c:919:device_hotplug: for-domain: 47 - calling
hotplug script: /etc/xen/scripts/block add
[...]
libxl: debug: libxl_device.c:919:device_hotplug: for-domain: 47 - calling
hotplug script: /etc/xen/scripts/vif-bridge online
[...]
libxl: debug: libxl_device.c:919:device_hotplug: for-domain: 46 - calling
hotplug script: /etc/xen/scripts/vif-bridge online
[...]

And the destruction:

[...]
libxl: debug: libxl_device.c:919:device_hotplug: for-domain: 47 - calling
hotplug script: /etc/xen/scripts/block remove
[...]
libxl: debug: libxl_device.c:919:device_hotplug: for-domain: 47 - calling
hotplug script: /etc/xen/scripts/vif-bridge offline
[...]
libxl: debug: libxl_device.c:919:device_hotplug: for-domain: 46 - calling
hotplug script: /etc/xen/scripts/block remove
[...]
libxl: debug: libxl_device.c:919:device_hotplug: for-domain: 46 - calling
hotplug script: /etc/xen/scripts/vif-bridge offline
[...]

So hotplug script gets called twice for both creation and
destruction. Can you run a guest creation/destruction with
-vvv and provide the output?

Hi,

Sorry for the delayed response, I didn''t see anyone had answered ...
bad mail tagging rules.

For the moment I still have to use Xen 4.1.3 shipped with Debian, so
I''m still under the XM toolset and there is no -vvv AFAICT.

Cheers,

    Sylvain

A bit more info:

I tried using PV-GRUB and this doesn''t happen there, so it''s
only with PyGRUB.

AFAICT it happens in  tools/python/xen/xend/XendDomainInfo.py in the
_configureBootloader method.

_shouldMount will return true and so " dom0.create_vbd(vbd, disk)"
will be executed to allow access to the device to the host by
executing the block-script before the actuall booting.


[2012-11-26 13:40:44 3469] INFO (XendDomainInfo:3270) Mounting
192.168.2.201 name=rbd;key=rbd rbd-vm test on /dev/xvdp.
[2012-11-26 13:40:44 3469] DEBUG (DevController:95) DevController:
writing {''backend-id'': ''0'',
''virtual-device'': ''51952'',
''device-type'':
''disk'', ''state'': ''1'',
''backend'':
''/local/domain/0/backend/vbd/0/51952''} to
/local/domain/0/device/vbd/51952.
[2012-11-26 13:40:44 3469] DEBUG (DevController:97) DevController:
writing {''domain'': ''Domain-0'',
''frontend'':
''/local/domain/0/device/vbd/51952'', ''uuid'':
''1845bb27-97b5-ce21-348d-ade6e99829e9'',
''bootable'': ''0'', ''dev'':
''/dev/xvdp'', ''state'': ''1'',
''params'': ''192.168.2.201 name=rbd;key=rbd
rbd-vm test'', ''mode'': ''r'',
''online'': ''1'',
''frontend-id'': ''0'',
''type'':
''rbd''} to /local/domain/0/backend/vbd/0/51952.
[2012-11-26 13:40:44 3469] DEBUG (DevController:144) Waiting for 51952.
[2012-11-26 13:40:44 3469] DEBUG (DevController:628)
hotplugStatusCallback
/local/domain/0/backend/vbd/0/51952/hotplug-status.
[2012-11-26 13:40:45 3469] DEBUG (DevController:628)
hotplugStatusCallback
/local/domain/0/backend/vbd/0/51952/hotplug-status.
[2012-11-26 13:40:45 3469] DEBUG (DevController:642) hotplugStatusCallback 1.
[2012-11-26 13:40:45 3469] DEBUG (DevController:144) Waiting for 51952.
[2012-11-26 13:40:45 3469] DEBUG (DevController:628)
hotplugStatusCallback
/local/domain/0/backend/vbd/0/51952/hotplug-status.
[2012-11-26 13:40:45 3469] DEBUG (DevController:642) hotplugStatusCallback 1.
[2012-11-26 13:40:45 4455] DEBUG (XendBootloader:113) Launching
bootloader as [''/usr/lib/xen-4.1/bin/pygrub'',
''--args=console=hvc0
xencons=hvc0'',
''--output=/var/run/xend/boot/xenbl.7585'',
''-q'',
''/dev/xvdp''].
[2012-11-26 13:40:48 3469] INFO (XendDomainInfo:3289) Unmounting
/dev/xvdp from /dev/xvdp.
[2012-11-26 13:40:48 3469] DEBUG (XendDomainInfo:1276)
XendDomainInfo.destroyDevice: deviceClass = vbd, device = /dev/xvdp

Now in theory the destroyDevice call should have cleared up any
resources, but it seems it didn''t ...


Cheers,

    Sylvain

Actually I managed to trace it a bit further but here I''m kind of
stuck due to my lack of knowledge of "how it should work".

Basically it does try to destruct the device and the hotplug script
''/etc/xen/scripts/block'' is called with the command remove and
the
right device path. However by the time it''s called, the corresponding
subtree in the xenstore has been wiped it seems and so the hotplug
script fails, not knowing what to do ... and it does nothing.

So whoever triggers the hotplug remove action should leave the xen
store tree in place until the hotplug script has run.

Cheers,

    Sylvain

On 04/12/12 15:21, Sylvain Munaut wrote:
> A bit more info:
> 
> I tried using PV-GRUB and this doesn''t happen there, so
it''s only with PyGRUB.
> 
> AFAICT it happens in  tools/python/xen/xend/XendDomainInfo.py in the
> _configureBootloader method.
> 
> _shouldMount will return true and so " dom0.create_vbd(vbd,
disk)"
> will be executed to allow access to the device to the host by
> executing the block-script before the actuall booting.
> 
> 
> [2012-11-26 13:40:44 3469] INFO (XendDomainInfo:3270) Mounting
> 192.168.2.201 name=rbd;key=rbd rbd-vm test on /dev/xvdp.
> [2012-11-26 13:40:44 3469] DEBUG (DevController:95) DevController:
> writing {''backend-id'': ''0'',
''virtual-device'': ''51952'',
''device-type'':
> ''disk'', ''state'': ''1'',
''backend'':
> ''/local/domain/0/backend/vbd/0/51952''} to
> /local/domain/0/device/vbd/51952.
> [2012-11-26 13:40:44 3469] DEBUG (DevController:97) DevController:
> writing {''domain'': ''Domain-0'',
''frontend'':
> ''/local/domain/0/device/vbd/51952'',
''uuid'':
> ''1845bb27-97b5-ce21-348d-ade6e99829e9'',
''bootable'': ''0'', ''dev'':
> ''/dev/xvdp'', ''state'':
''1'', ''params'': ''192.168.2.201
name=rbd;key=rbd
> rbd-vm test'', ''mode'': ''r'',
''online'': ''1'',
''frontend-id'': ''0'',
''type'':
> ''rbd''} to /local/domain/0/backend/vbd/0/51952.
> [2012-11-26 13:40:44 3469] DEBUG (DevController:144) Waiting for 51952.
> [2012-11-26 13:40:44 3469] DEBUG (DevController:628)
> hotplugStatusCallback
> /local/domain/0/backend/vbd/0/51952/hotplug-status.
> [2012-11-26 13:40:45 3469] DEBUG (DevController:628)
> hotplugStatusCallback
> /local/domain/0/backend/vbd/0/51952/hotplug-status.
> [2012-11-26 13:40:45 3469] DEBUG (DevController:642) hotplugStatusCallback
1.
> [2012-11-26 13:40:45 3469] DEBUG (DevController:144) Waiting for 51952.
> [2012-11-26 13:40:45 3469] DEBUG (DevController:628)
> hotplugStatusCallback
> /local/domain/0/backend/vbd/0/51952/hotplug-status.
> [2012-11-26 13:40:45 3469] DEBUG (DevController:642) hotplugStatusCallback
1.
> [2012-11-26 13:40:45 4455] DEBUG (XendBootloader:113) Launching
> bootloader as [''/usr/lib/xen-4.1/bin/pygrub'',
''--args=console=hvc0
> xencons=hvc0'',
''--output=/var/run/xend/boot/xenbl.7585'',
''-q'',
> ''/dev/xvdp''].
> [2012-11-26 13:40:48 3469] INFO (XendDomainInfo:3289) Unmounting
> /dev/xvdp from /dev/xvdp.
> [2012-11-26 13:40:48 3469] DEBUG (XendDomainInfo:1276)
> XendDomainInfo.destroyDevice: deviceClass = vbd, device = /dev/xvdp
> 
> Now in theory the destroyDevice call should have cleared up any
> resources, but it seems it didn''t ...
Could you give a try to xl in Xen 4.2?

On 04/12/12 16:23, Sylvain Munaut wrote:
> Actually I managed to trace it a bit further but here I''m kind of
> stuck due to my lack of knowledge of "how it should work".
> 
> Basically it does try to destruct the device and the hotplug script
> ''/etc/xen/scripts/block'' is called with the command
remove and the
> right device path. However by the time it''s called, the
corresponding
> subtree in the xenstore has been wiped it seems and so the hotplug
> script fails, not knowing what to do ... and it does nothing.
> 
> So whoever triggers the hotplug remove action should leave the xen
> store tree in place until the hotplug script has run.
This is one of the reasons we no longer launch hotplug scripts from udev
in xl, it is difficult to synchronize the process, and this kind of
races can happen easily, I guess the same can happen in xend. I think
the best way to fix this would be to switch to Xen 4.2 and the xl toolstack.