Bug 20481 - xend.err 'Device 768 (vbd) could not be connected. Hotplug scripts not working.
xend.err 'Device 768 (vbd) could not be connected. Hotplug scripts not working.
Status: CLOSED FIXED
Product: UCS
Classification: Unclassified
Component: Virtualization - Xen
UCS 3.2
Other Linux
: P5 normal (vote)
: UCS 3.2-0-errata
Assigned To: Philipp Hahn
Erik Damrose
:
Depends on: 33924
Blocks: 35531
  Show dependency treegraph
 
Reported: 2010-10-22 09:56 CEST by Arvid Requate
Modified: 2014-07-31 09:22 CEST (History)
6 users (show)

See Also:
What kind of report is it?: ---
What type of bug is this?: ---
Who will be affected by this bug?: ---
How will those affected feel about the bug?: ---
User Pain:
Enterprise Customer affected?:
School Customer affected?:
ISV affected?:
Waiting Support:
Ticket number:
Bug group (optional):
Max CVSS v3 score:


Attachments
/var/log/xen/qemu-dm-winxp-test001.log (875 bytes, text/plain)
2010-10-22 09:59 CEST, Arvid Requate
Details
/var/log/xen/xen-hotplug.log (36 bytes, text/plain)
2010-10-22 10:01 CEST, Arvid Requate
Details
/var/log/xen/xend.log (31.90 KB, text/plain)
2010-10-22 10:01 CEST, Arvid Requate
Details
Debug logs von libvirt und xend (539.49 KB, application/x-gtar)
2010-10-22 12:38 CEST, Arvid Requate
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Arvid Requate univentionstaff 2010-10-22 09:56:48 CEST
Beim Starten eines frisch kopieren XP-Images im UMC Modul UVMM erschien das Popup:

Error managing domain "bdb3a479-6e16-7427-09d3-f88271d29bcd": POST operation failed: xend_post: error from xen daemon: (xend.err 'Device 768 (vbd) could not be connected. Hotplug scripts not working.')

Nach einem erneuten Startversuch der VM blieb das UMC Modul im Reload hängen. Nach erneutem Einloggen in die UMC wurde die VM nicht mehr im UVMM Modul angezeigt. Ein restart von uvmm-daemon und uvmm-node-common hat daran nichts geändert.

UCS 2.4 mit Scope uvmm:
python-univention-virtual-machine-manager   0.10.4-5.97.201010191625
univention-virtual-machine-manager-daemon    0.9.106-1.92.201008230911
univention-virtual-machine-manager-node-common 0.1.13-1.14.201008261605
univention-virtual-machine-manager-node-xen  0.1.13-1.14.201008261605
univention-virtual-machine-manager-schema    1.0.18-1.17.201008161111
Comment 1 Arvid Requate univentionstaff 2010-10-22 09:59:17 CEST
Created attachment 2772 [details]
/var/log/xen/qemu-dm-winxp-test001.log
Comment 2 Arvid Requate univentionstaff 2010-10-22 10:01:04 CEST
Created attachment 2773 [details]
/var/log/xen/xen-hotplug.log
Comment 3 Arvid Requate univentionstaff 2010-10-22 10:01:20 CEST
Created attachment 2774 [details]
/var/log/xen/xend.log
Comment 4 Arvid Requate univentionstaff 2010-10-22 10:21:03 CEST
Nach Reboot des UVMM Nodes (xen5) wird der Node selbst im UMC-Modul UVMM auf dem Host selbst als unfunktional angezeigt. Auf einem zweiten UVMM-Node wird er hingegen mit der fraglichen VM normal angezeigt, allerdings lässt sich die VM auch dort nicht starten.

root@xen5:/var/lib/libvirt/images# xm list
Name                                        ID   Mem VCPUs      State   Time(s)
Domain-0                                     0  3259     2     r-----     90.3
winxp-test001                                    512     1                 0.0

root@xen5:/var/lib/libvirt/images# virsh -c xen://xen5.ucsdvs.qa/ list
 Id Name                 State
----------------------------------
  0 Domain-0             running

root@xen5:/var/lib/libvirt/images# virsh -c xen+unix://xen5.ucsdvs.qa/ list
 Id Name                 State
----------------------------------
  0 Domain-0             running
Comment 5 Arvid Requate univentionstaff 2010-10-22 10:32:54 CEST
Nach zweitem Reboot ist der Node wieder erreichbar und die VM wird als ausgeschaltet angezeigt. Nach Starten der VM hängt das UMC Modul wieder im Reload, aber xm list zeigt die VM schmal als pausiert an. Erneutes einloggen in das UMC-Modul: VM wird korrekt als pausiert angezeigt und lässt sich dann auch starten.
Comment 6 Arvid Requate univentionstaff 2010-10-22 12:38:12 CEST
Created attachment 2775 [details]
Debug logs von libvirt und xend

Neuinstallation (das ist hier alles amd64) zeigt das gleiche Problem, auch mit einem anderen Image (OpenDVDI/Windows-XP-SP3-vor-Versiegelung/hdimage_1.0.gz statt vorher winxp-sp3-gplpv/hdimage_xen_3.4.3_neu_aktiviert_gplpv_maerz.gz).

Windows sagt bei Starten (vnc), dass ein Problem mit der Maschine vorliegt, versucht dann irgendwas zu retten und dann ist die VM wieder aus. Starten versetzt die Maschine zuverlässig in den pausierten Zustand, unpausieren provoziert beim Start wieder den Windows Crash.
Comment 7 Stefan Gohmann univentionstaff 2010-10-22 19:58:37 CEST
Problem war hier, dass "/etc/xen/scripts/block" nicht vorhanden war. Arvid bei der Installation die folgende Nachfrage bekommen (ohne univention-install):

Richte univention-dvs-node ein (1.0.30-10.27.201010202011) ...

Konfigurationsdatei »/etc/xen/scripts/block«
 ==> Gelöscht (von Ihnen oder einem Skript) seit der Installation.
 ==> Paketverteiler hat eine aktualisierte Version herausgegeben.
   Was möchten Sie damit machen? Ihre Wahlmöglichkeiten sind:
    Y oder I : Die Version des Paket-Betreuers installieren
    N oder O : Die momentan installierte Version beibehalten
       D     : Die Unterschiede zwischen den Versionen anzeigen
       Z     : Prozess in den Hintergrund, um die Situation zu begutachten
 Der Standardweg ist das Beibehalten der momentanen Version.
*** block (Y/I/N/O/D/Z) [Vorgabe=N] ?

Für den Prototypen wird das Verhalten zunächst im Wiki dokumentiert.
Comment 8 Arvid Requate univentionstaff 2010-10-27 10:11:29 CEST
Das Problem wurde wohl dadurch ausgelöst, dass xen-3.4 schon bei der Installation ausgewählt wurde (ggf. per uvmm-node-xen) und dann kommt der divert in univention-dvs-node preinst zu spät. Man sollte entweder die Anpassungen am hook-Skript "block" entweder nach xen-3.4 übernehmen, oder samt divert in ein höhergelegenes Metapaket (uvmm-node-xen?) verschieben, wenn das in xen-3.4 schwer zu pflegen ist.
Comment 9 Erik Damrose univentionstaff 2013-11-05 14:21:30 CET
Reoccured during UCS 3.2 product tests.
Comment 10 Philipp Hahn univentionstaff 2013-11-07 15:38:13 CET
Happened during PT for UCS-3.2:
1. Happens mostly after a reboot; a 2nd try normally succeeds.
2. Was no longer reproducible after several more reboots
3. Running "xend trace_start" didn't show anything suspect.
4. Seems to be loopback related.
5. Might be AMD related.
6. Looks like a timing issue.
Comment 11 Janek Walkenhorst univentionstaff 2013-11-07 16:00:24 CET
(In reply to Philipp Hahn from comment #10)
> Happened during PT for UCS-3.2:
> 5. Might be AMD related.
Also happened consistently after the first reboot (after the installation of u-virt-node-xen) on Intel CPUs (FSC TX150, TX200, TX300)
Comment 12 Erik Damrose univentionstaff 2013-11-08 14:56:12 CET
UCS 3.2 UVMM Product tests showed that this occurs on Intel and AMD platforms. The error prevents the first VM from properly starting on a XEN machine. The subsequent start requests works without error.
Comment 13 Philipp Hahn univentionstaff 2013-11-29 18:24:09 CET
I get the slightly different message:

VmError: Device 51728 (vbd) could not be connected. Path closed or removed during hotplug add: backend/vbd/1/51728 state: 1
[2013-11-29 05:17:45 2153] DEBUG (DevController:649) deviceDestroyCallback /local/domain/0/backend/vbd/1/51712/hotplug-status.

# printf "%04x\n" 51728
ca10
# echo $((0xca))
202
# grep 202 /proc/devices 
202 xvd

The message is from tools/hotplug/Linux/block.
Comment 14 Philipp Hahn univentionstaff 2013-12-02 13:30:49 CET
(In reply to Philipp Hahn from comment #13)
> VmError: Device 51728 (vbd) could not be connected. Path closed or removed
> during hotplug add: backend/vbd/1/51728 state: 1

According to <http://wiki.xen.org/wiki/XenStore_Reference> and to <file:xen/tools/python/xen/xend/server/DevConstants.py>:
xenbusState = {
    'Unknown'       : 0,
    'Initialising'  : 1,
    'InitWait'      : 2,
    'Initialised'   : 3,
    'Connected'     : 4,
    'Closing'       : 5,
    'Closed'        : 6,
    'Reconfiguring' : 7,
    'Reconfigured'  : 8,
    }
The state-mechanism is described on <http://www.informit.com/articles/article.aspx?p=1160234&seqNum=4>.

On the other hand /etc/xen/scripts/block already expects the device to be in state 2=InitWait, while it actually is still in state 1=Initialising:

> xenbus_state=$(xenstore_read_default "$XENBUS_PATH/state" 'unknown')
> if [ "$xenbus_state" != '2' ]
...
>   fatal "Path closed or removed during hotplug add: $XENBUS_PATH state: $xenbus_state"

In my limited tests last Friday the bug only manifested sometimes, most likely just after a reboot and most reliably only then, when the host was still busy completing other init-scripts.
To me is looks like a race condition, where the block-hot-plug script is launched too early in the back-end domain while the front-end domain has not yet acknowledged the probe drivers/block/xen-blkback/xenbus.c#xen_blkbk_probe .


The failing code in the block-script was added in <http://xenbits.xen.org/gitweb/?p=xen.git;a=commitdiff;h=92e6cb5673b37bd883bdef0d0e83faf000edf61d>.

A work-around might be as simple as adding a delay if the state is still 1.
diff --git a/tools/hotplug/Linux/block b/tools/hotplug/Linux/block
index 06de5c9..cbf2af3 100644
--- a/tools/hotplug/Linux/block
+++ b/tools/hotplug/Linux/block
@@ -255,12 +255,16 @@ case "$command" in
 
         # Avoid a race with the remove if the path has been deleted, or
 	# otherwise changed from "InitWait" state e.g. due to a timeout
-        xenbus_state=$(xenstore_read_default "$XENBUS_PATH/state" 'unknown')
-        if [ "$xenbus_state" != '2' ]
-        then
+        while true
+        do
+          xenbus_state=$(xenstore_read_default "$XENBUS_PATH/state" 'unknown')
+          case "$xenbus_state" in
+          1) sleep 1 ; continue ;;
+          2) break ;;
+          esac
           release_lock "block"
           fatal "Path closed or removed during hotplug add: $XENBUS_PATH state: $xenbus_state"
-        fi
+        done
 
         if [ "$mode" = 'w' ] && ! stat "$file" -c %A | grep -q w
         then

Das ganze ist derzeit ungetestet, weil gerade xen16 gerade kaputt gegangen ist.
Comment 15 Philipp Hahn univentionstaff 2014-01-13 16:29:56 CET
(In reply to Philipp Hahn from comment #14)
...
> +++ b/tools/hotplug/Linux/block
...
> +          1) sleep 1 ; continue ;;
...
> Das ganze ist derzeit ungetestet, weil gerade xen16 gerade kaputt gegangen
> ist.

Test was successful: The case triggered and after a delay of 1 second the VM was started successfully.
I'll apply the patch.
Comment 16 Philipp Hahn univentionstaff 2014-01-14 20:31:38 CET
r47146 | Bug #20481: Fix race condition in Xen hotplug script

Build is waiting for Bug #33924 to be fixed...
Comment 17 Erik Damrose univentionstaff 2014-01-20 12:25:38 CET
OK: The patch waits for the device to leave the state "Initializing". After that, the VM is started without problems. This MAY lead to the first VM to be started with a great delay:
- UCS was rebooted and it was tried to start a VM immediately: It took 1:45 minutes for the initialization to finish (syslog entry every second).
- When the system is left idling for about 5 minutes, the initialization is finished in 1 second.

I could not reproduce the behaviour reported at this bug with the patch applied.

OK: 2014-01-14-xen-4.1.yaml. I added the current build version (r47248).
Comment 18 Moritz Muehlenhoff univentionstaff 2014-01-29 11:17:56 CET
http://errata.univention.de/ucs/3.2/33.html