'Failed to connect to qmemman' after failed HVM start (qubes-dom0-current-testing)

[sudod...@gmail.com]

I did an update from qubes-dom0-current-testing. There seems to be a problem with HVMs. When trying to start Windows I get this:

--> Loading the VM (type = TemplateHVM)...
Traceback (most recent call last):
File "/usr/bin/qvm-start", line 131, in <module>
main()
File "/usr/bin/qvm-start", line 115, in main
xid = vm.start(verbose=options.verbose, preparing_dvm=options.preparing_dvm, start_guid=not options.noguid, notify_function=tray_notify_generic if options.tray else None)
File "/usr/lib64/python2.7/site-packages/qubes/modules/02QubesTemplateHVm.py", line 94, in start
return super(QubesTemplateHVm, self).start(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/qubes/modules/01QubesHVm.py", line 326, in start
return super(QubesHVm, self).start(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/qubes/modules/000QubesVm.py", line 1876, in start
self.libvirt_domain.createWithFlags(libvirt.VIR_DOMAIN_START_PAUSED)
File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1059, in createWithFlags
if ret == -1: raise libvirtError ('virDomainCreateWithFlags() failed', dom=self)
libvirt.libvirtError: internal error: libxenlight failed to create new domain 'win7-x64'

After that I can't start ANY VM without first rebooting Qubes:
Starting a HVM template:
--> Loading the VM (type = TemplateHVM)...
ERROR: ERROR: Failed to connect to qmemman: [Errno 111] Connection refused

Starting a PV template:
--> Loading the VM (type = TemplateVM)...
ERROR: ERROR: Failed to connect to qmemman: [Errno 111] Connection refused

Starting a normal VM:
--> Creating volatile image: /var/lib/qubes/appvms/untrusted/volatile.img...
--> Loading the VM (type = AppVM)...
ERROR: ERROR: Failed to connect to qmemman: [Errno 111] Connection refused

[Marek Marczykowski-Górecki]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

On Sun, Jan 10, 2016 at 05:48:47AM -0800, sudod...@gmail.com wrote:
> I did an update from qubes-dom0-current-testing. There seems to be a problem with HVMs. When trying to start Windows I get this:
>
> --> Loading the VM (type = TemplateHVM)...
> Traceback (most recent call last):
> File "/usr/bin/qvm-start", line 131, in <module>
> main()
> File "/usr/bin/qvm-start", line 115, in main
> xid = vm.start(verbose=options.verbose, preparing_dvm=options.preparing_dvm, start_guid=not options.noguid, notify_function=tray_notify_generic if options.tray else None)
> File "/usr/lib64/python2.7/site-packages/qubes/modules/02QubesTemplateHVm.py", line 94, in start
> return super(QubesTemplateHVm, self).start(*args, **kwargs)
> File "/usr/lib64/python2.7/site-packages/qubes/modules/01QubesHVm.py", line 326, in start
> return super(QubesHVm, self).start(*args, **kwargs)
> File "/usr/lib64/python2.7/site-packages/qubes/modules/000QubesVm.py", line 1876, in start
> self.libvirt_domain.createWithFlags(libvirt.VIR_DOMAIN_START_PAUSED)
> File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1059, in createWithFlags
> if ret == -1: raise libvirtError ('virDomainCreateWithFlags() failed', dom=self)
> libvirt.libvirtError: internal error: libxenlight failed to create new domain 'win7-x64'

Check /var/log/libvirt/libxl-driver.log for detailed error message.

> After that I can't start ANY VM without first rebooting Qubes:
> Starting a HVM template:
> --> Loading the VM (type = TemplateHVM)...
> ERROR: ERROR: Failed to connect to qmemman: [Errno 111] Connection refused

(...)

Please check "sudo systemctl status qubes-qmemman", or better "sudo
journalctl -u qubes-qmemman" for error messages. Then you can restart
the service with "sudo systemctl restart qubes-qmemman".

- --
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab
A: Because it messes up the order in which people normally read text.
Q: Why is top-posting such a bad thing?
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2

iQEcBAEBCAAGBQJWknbPAAoJENuP0xzK19csR0MH+gLFe3Ib3b1UScBJOmP9pZ4u
7rTzAxxWcEa/0ftML2iG1Swca2mJtyD9LTPPfOFbYcEEO5RnofQHl/aLUXLLdoxr
QpecWLW6uCm7Aey8N76RfI4/Kgvv0IViUD9hXAdmqLTZxJt8vpfpmZMjNghnB4y9
0/3Hc2uzb14RwdmeURkq+2J40HDaQH7ZwdYt1RZc+Q8PiL+Nq1rHQrNFAfdZH4LK
vHhPCxHGhX0l6Du6J2fWz4bx84gzliGqrqyU4DDU02zRnTU58DlWkXE215oPBF66
o/sVNETkMR35yK5rWKai4qmvoem2GWfHxXIReGURvUxWmtFKhQdXIWJTzKf3b9E=
=jwDQ
-----END PGP SIGNATURE-----

[sudod...@gmail.com]

I noticed that root-cow.img is missing in the template directory, no idea how it got lost. It's probably me doing stupid things, not Qubes :)
I'm assuming root-cow.img (a LVM snapshot partition) contains the changes made to root.img while running the template the last time such that 'qvm-revert-template-changes' can do its job. Is this right?
Can I fix this somehow without re-installing the template? Create an empty root-cow.img?

By the way this are the log files:

libxl-driver.log:
2016-01-10 16:39:25 CET libxl: error: libxl_exec.c:118:libxl_report_child_exitstatus: /etc/xen/scripts/block-origin add [6265] exited with error status 1
2016-01-10 16:39:25 CET libxl: error: libxl_device.c:1084:device_hotplug_child_death_cb: script: /var/lib/qubes/vm-templates/win7-x64/root-cow.img does not exist.
2016-01-10 16:39:25 CET libxl: error: libxl_create.c:1177:domcreate_launch_dm: unable to add disk devices
2016-01-10 16:39:25 CET libxl: error: libxl_dm.c:2031:libxl__destroy_device_model: xs_rm failed for /local/domain/0/device-model/14
2016-01-10 16:39:25 CET libxl: error: libxl_dm.c:1983:kill_device_model: unable to find device model pid in /local/domain/14/image/device-model-pid
2016-01-10 16:39:25 CET libxl: error: libxl.c:1643:libxl__destroy_domid: libxl__destroy_device_model failed for 14
2016-01-10 16:39:25 CET libxl: error: libxl_exec.c:118:libxl_report_child_exitstatus: /etc/xen/scripts/block-origin remove [6356] exited with error status 1
2016-01-10 16:39:25 CET libxl: error: libxl_device.c:1084:device_hotplug_child_death_cb: script: /etc/xen/scripts/block-origin failed; error detected.

journalctl -u qubes-qmemman:

Jan 10 16:33:36 dom0 systemd[1]: Started Qubes memory management daemon.
Jan 10 16:33:42 dom0 systemd[1]: qubes-qmemman.service: main process exited, code=exited, status=1/FAILURE
Jan 10 16:33:42 dom0 systemd[1]: Unit qubes-qmemman.service entered failed state.

[sudod...@gmail.com]

I figured out a solution myself. It's that simple:
truncate -s 20G root-cow.img

But anyway: Thanks Marek for always being that patient!

[Marek Marczykowski-Górecki]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

On Sun, Jan 10, 2016 at 07:55:59AM -0800, sudod...@gmail.com wrote:
> I noticed that root-cow.img is missing in the template directory, no idea how it got lost. It's probably me doing stupid things, not Qubes :)
> I'm assuming root-cow.img (a LVM snapshot partition) contains the changes made to root.img while running the template the last time such that 'qvm-revert-template-changes' can do its job. Is this right?

Yes.

> Can I fix this somehow without re-installing the template? Create an empty root-cow.img?

Try with qvm-template-commit. It will create empty sparse file with
appropriate size. As you've already figured out.

And I think it isn't your error, recently there were some changes in
this part of the code and it looks like it doesn't handle upgrade
well...

https://github.com/QubesOS/qubes-issues/issues/1602

> By the way this are the log files:
>
> libxl-driver.log:
> 2016-01-10 16:39:25 CET libxl: error: libxl_exec.c:118:libxl_report_child_exitstatus: /etc/xen/scripts/block-origin add [6265] exited with error status 1
> 2016-01-10 16:39:25 CET libxl: error: libxl_device.c:1084:device_hotplug_child_death_cb: script: /var/lib/qubes/vm-templates/win7-x64/root-cow.img does not exist.
> 2016-01-10 16:39:25 CET libxl: error: libxl_create.c:1177:domcreate_launch_dm: unable to add disk devices
> 2016-01-10 16:39:25 CET libxl: error: libxl_dm.c:2031:libxl__destroy_device_model: xs_rm failed for /local/domain/0/device-model/14
> 2016-01-10 16:39:25 CET libxl: error: libxl_dm.c:1983:kill_device_model: unable to find device model pid in /local/domain/14/image/device-model-pid
> 2016-01-10 16:39:25 CET libxl: error: libxl.c:1643:libxl__destroy_domid: libxl__destroy_device_model failed for 14
> 2016-01-10 16:39:25 CET libxl: error: libxl_exec.c:118:libxl_report_child_exitstatus: /etc/xen/scripts/block-origin remove [6356] exited with error status 1
> 2016-01-10 16:39:25 CET libxl: error: libxl_device.c:1084:device_hotplug_child_death_cb: script: /etc/xen/scripts/block-origin failed; error detected.
>
>
>
> journalctl -u qubes-qmemman:
>
> Jan 10 16:33:36 dom0 systemd[1]: Started Qubes memory management daemon.
> Jan 10 16:33:42 dom0 systemd[1]: qubes-qmemman.service: main process exited, code=exited, status=1/FAILURE
> Jan 10 16:33:42 dom0 systemd[1]: Unit qubes-qmemman.service entered failed state.

Qmemman should be totally unrelated to root-cow.img problem... Maybe
there is something more in /var/log/qubes/qmemman.log regarding that
failure? That file is probably quite long, but search for entries about
the time of the failure.

- --
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab
A: Because it messes up the order in which people normally read text.
Q: Why is top-posting such a bad thing?
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2

iQEcBAEBCAAGBQJWkodkAAoJENuP0xzK19cs87sH/iYRvljw8Oj0vUWoRWqn8rtd
ZgY1KCSib0Ye0v08gHNmjafXCK+R6dJY2g+vKexON21QfBrwpYjsQ2PTNeGhC+2U
UM1XfExjn2JMZyfkt4yZhyfSiFwJ02Vn+rBtVYca7VkMdsESgF3eNWU7x4zVEHiz
SIOWSaoXywARp3SUKq7iFHNGZysFhmcHq4N3bq8S+eXQIvTAlTy0t+4zmmdL6k72
jid4B0oMTNPjImYtHW+Nwm3TkdqzNeoLbmKtCWO/HYWkAo4qRunULgOAD6qB+nPI
V2Jc370HxutrXtT3NtTSHzb9O0PK6mTJxdjs2X1ECthJJF7W3FCJiBt3fK5GzoA=
=quqG
-----END PGP SIGNATURE-----

[sudod...@gmail.com]

Well it's not that unrelated as it can be triggered by the root-cow.img problem. Here is how I can reproduce the bug in 3.1 R1 (I get the error only with a HVM template):

cd /var/lib/qubes/vm-templates/win7-x64
rm root-cow.img
qvm-start win7-x64

--> Loading the VM (type = TemplateHVM)...
Traceback (most recent call last):
File "/usr/bin/qvm-start", line 131, in <module>
main()
File "/usr/bin/qvm-start", line 115, in main
xid = vm.start(verbose=options.verbose, preparing_dvm=options.preparing_dvm, start_guid=not options.noguid, notify_function=tray_notify_generic if options.tray else None)
File "/usr/lib64/python2.7/site-packages/qubes/modules/02QubesTemplateHVm.py", line 94, in start
return super(QubesTemplateHVm, self).start(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/qubes/modules/01QubesHVm.py", line 326, in start
return super(QubesHVm, self).start(*args, **kwargs)
File "/usr/lib64/python2.7/site-packages/qubes/modules/000QubesVm.py", line 1876, in start
self.libvirt_domain.createWithFlags(libvirt.VIR_DOMAIN_START_PAUSED)
File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1059, in createWithFlags
if ret == -1: raise libvirtError ('virDomainCreateWithFlags() failed', dom=self)
libvirt.libvirtError: internal error: libxenlight failed to create new domain 'win7-x64'

Again:
qvm-start win7-x64

--> Loading the VM (type = TemplateHVM)...
ERROR: ERROR: Failed to connect to qmemman: [Errno 111] Connection refused

Obviously qmemman crashes.
tail -f /var/log/qubes/qmemman.log tells me that nothing gets written to the log on failure.