/qubes-issues

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cannot start templates VMs after system update #3549

Closed
kototama opened this Issue Feb 7, 2018 · 8 comments

Comments

Assignees
No one assigned
Labels
Projects
None yet
Milestone
  Release 4.0
5 participants
@kototama @donob4n @marmarek @lvh @andrewdavidwong
@kototama

kototama commented Feb 7, 2018

Qubes OS version:

4RC3

Affected TemplateVMs:

All.

Steps to reproduce the behavior:

qvm-start fedora-26
qvm-start debian-9
qvm-start debian-8
qvm-run --dispvm fedora-26-dvm gnome-terminal

Expected behavior:

VMs and DispVM start.

Actual behavior:

Got error:
Start failed: internal error: libxenlight failed to create new domain 'debian-8', see /var/log/libvirt/libxl/libxl-driver.log for details

For DispVM:

qvm-run --dispvm fedora-26-dvm gnome-terminal
Running 'gnome-terminal' on $dispvm:fedora-26-dvm
$dispvm:fedora-26-dvm: Start failed: internal error: libxenlight failed to create new domain 'disp9978', see /var/log/libvirt/libxl/libxl-driver.log for details
Traceback (most recent call last):
  File "/usr/bin/qvm-run", line 5, in <module>
    sys.exit(main())
  File "/usr/lib/python3.5/site-packages/qubesadmin/tools/qvm_run.py", line 238, in main
    dispvm.cleanup()
  File "/usr/lib/python3.5/site-packages/qubesadmin/vm/__init__.py", line 365, in cleanup
    self.kill()
  File "/usr/lib/python3.5/site-packages/qubesadmin/vm/__init__.py", line 119, in kill
    self.qubesd_call(self._method_dest, 'admin.vm.Kill')
  File "/usr/lib/python3.5/site-packages/qubesadmin/base.py", line 68, in qubesd_call
    payload_stream)
  File "/usr/lib/python3.5/site-packages/qubesadmin/app.py", line 483, in qubesd_call
    return self._parse_qubesd_response(return_data)
  File "/usr/lib/python3.5/site-packages/qubesadmin/base.py", line 81, in _parse_qubesd_response
    'Got empty response from qubesd. See journalctl in dom0 for '
qubesadmin.exc.QubesDaemonNoResponseError: Got empty response from qubesd. See journalctl in dom0 for details.

General notes:

This is incapacitating my work and I will have to abandon Qubes if there are no fixes or workarounds very soon.

Log of libxl-driver.log:

2018-02-01 08:40:40.188+0000: libxl: libxl.c:1857:libxl_console_get_tty: unable to read console tty path `/local/domain/1/console/tty': Resource temporarily unavailable
2018-02-01 08:40:44.959+0000: libxl: libxl_pci.c:1174:libxl__device_pci_reset: The kernel doesn't support reset from sysfs for PCI device 0000:00:14.0
2018-02-01 08:41:19.568+0000: libxl: libxl.c:1601:libxl__destroy_domid: non-existant domain -1
2018-02-01 08:41:19.568+0000: libxl: libxl.c:1560:domain_destroy_callback: unable to destroy guest with domid 4294967295
2018-02-01 08:41:19.568+0000: libxl: libxl.c:1489:domain_destroy_cb: destruction of domain 4294967295 failed
2018-02-01 08:41:54.373+0000: libxl: libxl.c:1601:libxl__destroy_domid: non-existant domain -1
2018-02-01 08:41:54.373+0000: libxl: libxl.c:1560:domain_destroy_callback: unable to destroy guest with domid 4294967295
2018-02-01 08:41:54.373+0000: libxl: libxl.c:1489:domain_destroy_cb: destruction of domain 4294967295 failed
2018-02-01 08:42:10.662+0000: libxl: libxl.c:1601:libxl__destroy_domid: non-existant domain -1
2018-02-01 08:42:10.662+0000: libxl: libxl.c:1560:domain_destroy_callback: unable to destroy guest with domid 4294967295
2018-02-01 08:42:10.662+0000: libxl: libxl.c:1489:domain_destroy_cb: destruction of domain 4294967295 failed
2018-02-01 08:42:25.089+0000: libxl: libxl.c:1601:libxl__destroy_domid: non-existant domain -1
2018-02-01 08:42:25.089+0000: libxl: libxl.c:1560:domain_destroy_callback: unable to destroy guest with domid 4294967295
2018-02-01 08:42:25.089+0000: libxl: libxl.c:1489:domain_destroy_cb: destruction of domain 4294967295 failed
2018-02-01 08:43:28.871+0000: libxl: libxl.c:1601:libxl__destroy_domid: non-existant domain -1
2018-02-01 08:43:28.871+0000: libxl: libxl.c:1560:domain_destroy_callback: unable to destroy guest with domid 4294967295
2018-02-01 08:43:28.871+0000: libxl: libxl.c:1489:domain_destroy_cb: destruction of domain 4294967295 failed
2018-02-01 08:45:12.927+0000: libxl: libxl_pci.c:1174:libxl__device_pci_reset: The kernel doesn't support reset from sysfs for PCI device 0000:00:14.0
2018-02-01 16:07:13.047+0000: libxl: libxl.c:1857:libxl_console_get_tty: unable to read console tty path `/local/domain/17/console/tty': Resource temporarily unavailable
2018-02-01 17:41:31.096+0000: libxl: libxl_device.c:1074:device_backend_callback: unable to remove device with path /local/domain/6/backend/vif/14/0
2018-02-01 17:41:31.099+0000: libxl: libxl.c:1673:devices_destroy_cb: libxl__devices_destroy failed for 14
2018-02-01 17:41:31.595+0000: libxl: libxl_device.c:1074:device_backend_callback: unable to remove device with path /local/domain/6/backend/vif/12/0
2018-02-01 17:41:31.599+0000: libxl: libxl.c:1673:devices_destroy_cb: libxl__devices_destroy failed for 12
2018-02-01 17:41:31.902+0000: libxl: libxl_pci.c:1174:libxl__device_pci_reset: The kernel doesn't support reset from sysfs for PCI device 0000:00:14.0
2018-02-01 17:41:49.808+0000: libxl: libxl_device.c:1074:device_backend_callback: unable to remove device with path /local/domain/2/backend/vif/7/0
2018-02-01 17:41:49.811+0000: libxl: libxl.c:1673:devices_destroy_cb: libxl__devices_destroy failed for 7
2018-02-01 17:42:00.012+0000: libxl: libxl_linux.c:155:libxl__loopdev_cleanup: unable to release device /dev/loop0: No such device or address
2018-02-01 17:42:00.070+0000: libxl: libxl_linux.c:155:libxl__loopdev_cleanup: unable to release device /dev/loop0: No such device or address
2018-02-05 08:18:55.033+0000: libxl: libxl.c:1857:libxl_console_get_tty: unable to read console tty path `/local/domain/1/console/tty': Resource temporarily unavailable
2018-02-05 08:18:56.629+0000: libxl: libxl_pci.c:1174:libxl__device_pci_reset: The kernel doesn't support reset from sysfs for PCI device 0000:00:14.0
2018-02-05 09:34:06.636+0000: libxl: libxl.c:1857:libxl_console_get_tty: unable to read console tty path `/local/domain/17/console/tty': Resource temporarily unavailable
2018-02-05 16:32:56.191+0000: libxl: libxl_pci.c:1174:libxl__device_pci_reset: The kernel doesn't support reset from sysfs for PCI device 0000:00:14.0
2018-02-05 16:32:57.705+0000: libxl: libxl_device.c:1074:device_backend_callback: unable to remove device with path /local/domain/7/backend/vif/11/0
2018-02-05 16:32:57.709+0000: libxl: libxl.c:1673:devices_destroy_cb: libxl__devices_destroy failed for 11
2018-02-05 16:32:57.817+0000: libxl: libxl_device.c:1074:device_backend_callback: unable to remove device with path /local/domain/6/backend/vif/10/0
2018-02-05 16:32:57.824+0000: libxl: libxl.c:1673:devices_destroy_cb: libxl__devices_destroy failed for 10
2018-02-05 16:33:14.358+0000: libxl: libxl_device.c:1074:device_backend_callback: unable to remove device with path /local/domain/4/backend/vif/13/0
2018-02-05 16:33:14.361+0000: libxl: libxl.c:1673:devices_destroy_cb: libxl__devices_destroy failed for 13
2018-02-05 16:33:22.519+0000: libxl: libxl_linux.c:155:libxl__loopdev_cleanup: unable to release device /dev/loop0: No such device or address
2018-02-05 16:33:22.568+0000: libxl: libxl_linux.c:155:libxl__loopdev_cleanup: unable to release device /dev/loop0: No such device or address
2018-02-06 08:30:01.088+0000: libxl: libxl_pci.c:1174:libxl__device_pci_reset: The kernel doesn't support reset from sysfs for PCI device 0000:00:14.0
2018-02-06 08:30:03.532+0000: libxl: libxl.c:1857:libxl_console_get_tty: unable to read console tty path `/local/domain/5/console/tty': Resource temporarily unavailable

journalctl | tail -100:


Feb 07 11:05:39 dom0 qubesd[12566]: Creating directory: /var/lib/qubes/appvms/disp5089
Feb 07 11:05:39 dom0 qubesd[12566]: Creating icon symlink: /var/lib/qubes/appvms/disp5089/icon.png -> /usr/share/icons/hicolor/128x128/devices/appvm-red.png
Feb 07 11:05:39 dom0 kernel: audit_printk_skb: 6 callbacks suppressed
Feb 07 11:05:39 dom0 kernel: audit: type=1103 audit(1517997939.119:222): pid=30225 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 kernel: audit: type=1105 audit(1517997939.120:223): pid=30225 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 audit[30225]: CRED_ACQ pid=30225 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 audit[30225]: USER_START pid=30225 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 runuser[30225]: pam_unix(runuser:session): session opened for user user by (uid=0)
Feb 07 11:05:39 dom0 audit[30227]: CRED_ACQ pid=30227 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 kernel: audit: type=1103 audit(1517997939.147:224): pid=30227 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 runuser[30227]: pam_unix(runuser:session): session opened for user user by (uid=0)
Feb 07 11:05:39 dom0 audit[30227]: USER_START pid=30227 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 kernel: audit: type=1105 audit(1517997939.148:225): pid=30227 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: balance_when_enough_memory(xen_free_memory=25243689, total_mem_pref=4094174425.6000004, total_available_memory=15834798866.400002)
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: left_memory=3749999199 acceptors_count=3
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: left_memory=722828959 acceptors_count=2
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: stat: dom '10' act=4126146560 pref=1619681689.6000001 last_target=4126146560
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: stat: dom '0' act=9936847293 pref=1728797094.4 last_target=9936847293
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: stat: dom '6' act=2097152000 pref=323114188.8 last_target=2097152000
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: stat: dom '3' act=3743583750 pref=422581452.8 last_target=3743583750
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: stat: xenfree=77672489 memset_reqs=[('3', 3664720834), ('10', 4126146560), ('0', 10016552094), ('6', 2097152000)]
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: mem-set domain 3 to 3664720834
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: mem-set domain 10 to 4126146560
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: mem-set domain 0 to 10016552094
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: mem-set domain 6 to 2097152000
Feb 07 11:05:39 dom0 runuser[30227]: pam_unix(runuser:session): session closed for user user
Feb 07 11:05:39 dom0 audit[30227]: USER_END pid=30227 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 audit[30227]: CRED_DISP pid=30227 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 kernel: audit: type=1106 audit(1517997939.576:226): pid=30227 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 kernel: audit: type=1104 audit(1517997939.576:227): pid=30227 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 qubesd[12566]: Starting disp5089
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: do_balloon(memsize=426770432)
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: xenfree=76219478
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: balloon: dom 10 has actual memory 4126146560
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: balloon: dom 0 has actual memory 10016552094
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: balloon: dom 6 has actual memory 2097152000
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: balloon: dom 3 has actual memory 3664720834
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: req=402979754 avail=15810397062.400002 donors=[('10', 2506464870.3999996), ('0', 8287754999.6), ('6', 1774037811.2), ('3', 3242139381.2)]
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: borrow 67079740.157178186 from 10
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: borrow 221802610.6908099 from 0
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: borrow 47478022.45690918 from 6
Feb 07 11:05:39 dom0 qmemman.daemon.algo[12565]: borrow 86768368.39510268 from 3
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: memset_reqs=[('10', 4059066819), ('0', 9794749483), ('6', 2049673977), ('3', 3577952465)]
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: mem-set domain 10 to 4059066819
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: mem-set domain 0 to 9794749483
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: mem-set domain 6 to 2049673977
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: mem-set domain 3 to 3577952465
Feb 07 11:05:39 dom0 qmemman.systemstate[12565]: xenfree=497788015
Feb 07 11:05:39 dom0 audit[30225]: USER_END pid=30225 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 audit[30225]: CRED_DISP pid=30225 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 runuser[30225]: pam_unix(runuser:session): session closed for user user
Feb 07 11:05:39 dom0 kernel: audit: type=1106 audit(1517997939.962:228): pid=30225 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:39 dom0 kernel: audit: type=1104 audit(1517997939.962:229): pid=30225 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:40 dom0 qubesd[12566]: b'  WARNING: Sum of all thin volume sizes (910.64 GiB) exceeds the size of thin pool qubes_dom0/pool00 and the size of whole volume group (476.74 GiB)!\n'
Feb 07 11:05:40 dom0 dmeventd[875]: No longer monitoring thin pool qubes_dom0-pool00-tpool.
Feb 07 11:05:40 dom0 lvm[875]: Monitoring thin pool qubes_dom0-pool00-tpool.
Feb 07 11:05:40 dom0 qubesd[12566]: b'  WARNING: Sum of all thin volume sizes (912.64 GiB) exceeds the size of thin pool qubes_dom0/pool00 and the size of whole volume group (476.74 GiB)!\n'
Feb 07 11:05:40 dom0 dmeventd[875]: No longer monitoring thin pool qubes_dom0-pool00-tpool.
Feb 07 11:05:40 dom0 lvm[875]: Monitoring thin pool qubes_dom0-pool00-tpool.
Feb 07 11:05:41 dom0 qubesd[12566]: b'  WARNING: Sum of all thin volume sizes (922.64 GiB) exceeds the size of thin pool qubes_dom0/pool00 and the size of whole volume group (476.74 GiB)!\n'
Feb 07 11:05:42 dom0 libvirtd[12593]: 2018-02-07 10:05:42.052+0000: 12613: error : libxlDomainStart:1308 : internal error: libxenlight failed to create new domain 'disp5089'
Feb 07 11:05:42 dom0 qubesd[12566]: Start failed: internal error: libxenlight failed to create new domain 'disp5089'
Feb 07 11:05:43 dom0 qmemman.daemon.reqhandler[12565]: EOF
Feb 07 11:05:43 dom0 qmemman.daemon.algo[12565]: balance_when_enough_memory(xen_free_memory=445359215, total_mem_pref=4053200089.6000004, total_available_memory=15873601869.400002)
Feb 07 11:05:43 dom0 qmemman.daemon.algo[12565]: left_memory=3828753389 acceptors_count=3
Feb 07 11:05:43 dom0 qmemman.daemon.algo[12565]: left_memory=764764967 acceptors_count=2
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '10' act=4059066819 pref=1619681689.6000001 last_target=4059066819
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '0' act=9794749483 pref=1687822758.4 last_target=9794749483
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '6' act=2049673977 pref=323114188.8 last_target=2049673977
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '3' act=3577952465 pref=422581452.8 last_target=3577952465
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: xenfree=497788015 memset_reqs=[('10', 4126146560), ('3', 3732440299), ('0', 9946542776), ('6', 2097152000)]
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 10 to 4126146560
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 3 to 3732440299
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 0 to 9946542776
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 6 to 2097152000
Feb 07 11:05:43 dom0 qmemman.daemon.algo[12565]: balance_when_enough_memory(xen_free_memory=20407279, total_mem_pref=4095415104.0000005, total_available_memory=15827273810.0)
Feb 07 11:05:43 dom0 qmemman.daemon.algo[12565]: left_memory=3745130272 acceptors_count=3
Feb 07 11:05:43 dom0 qmemman.daemon.algo[12565]: left_memory=720236292 acceptors_count=2
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '10' act=4126146560 pref=1619681689.6000001 last_target=4126146560
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '0' act=9946542776 pref=1730037772.8 last_target=9946542776
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '6' act=2097152000 pref=323114188.8 last_target=2097152000
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '3' act=3732440299 pref=422581452.8 last_target=3732440299
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: xenfree=72836079 memset_reqs=[('3', 3660534120), ('10', 4126146560), ('0', 10014468173), ('6', 2097152000)]
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 3 to 3660534120
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 10 to 4126146560
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 0 to 10014468173
Feb 07 11:05:43 dom0 audit[32142]: CRED_ACQ pid=32142 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 6 to 2097152000
Feb 07 11:05:43 dom0 kernel: audit: type=1103 audit(1517997943.052:230): pid=32142 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:43 dom0 kernel: audit: type=1105 audit(1517997943.054:231): pid=32142 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:43 dom0 audit[32142]: USER_START pid=32142 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:43 dom0 runuser[32142]: pam_unix(runuser:session): session opened for user user by (uid=0)
Feb 07 11:05:43 dom0 audit[32142]: USER_END pid=32142 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_unix acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:43 dom0 audit[32142]: CRED_DISP pid=32142 uid=0 auid=4294967295 ses=4294967295 msg='op=PAM:setcred grantors=pam_rootok acct="user" exe="/usr/sbin/runuser" hostname=? addr=? terminal=? res=success'
Feb 07 11:05:43 dom0 runuser[32142]: pam_unix(runuser:session): session closed for user user
Feb 07 11:05:43 dom0 qubesd[12566]: Removing volume volatile: qubes_dom0/vm-disp5089-volatile
Feb 07 11:05:43 dom0 qubesd[12566]: Removing volume private: qubes_dom0/vm-disp5089-private
Feb 07 11:05:43 dom0 qubesd[12566]: Removing volume root: qubes_dom0/vm-disp5089-root
Feb 07 11:05:43 dom0 qubesd[12566]: Removing volume kernel: 4.9.56-21
Feb 07 11:05:43 dom0 qubesd[12566]: unhandled exception while calling src=b'dom0' meth=b'admin.vm.Kill' dest=b'disp5089' arg=b'' len(untrusted_payload)=0
Feb 07 11:05:43 dom0 qubesd[12566]: Traceback (most recent call last):
Feb 07 11:05:43 dom0 qubesd[12566]:   File "/usr/lib/python3.5/site-packages/qubes/api/__init__.py", line 260, in respond
Feb 07 11:05:43 dom0 qubesd[12566]:     self.send_event)
Feb 07 11:05:43 dom0 qubesd[12566]:   File "/usr/lib/python3.5/site-packages/qubes/api/__init__.py", line 127, in __init__
Feb 07 11:05:43 dom0 qubesd[12566]:     self.dest = self.app.domains[dest.decode('ascii')]
Feb 07 11:05:43 dom0 qubesd[12566]:   File "/usr/lib/python3.5/site-packages/qubes/app.py", line 467, in __getitem__
Feb 07 11:05:43 dom0 qubesd[12566]:     raise KeyError(key)
Feb 07 11:05:43 dom0 qubesd[12566]: KeyError: 'disp5089'
Feb 07 11:05:43 dom0 qmemman.daemon.algo[12565]: balance_when_enough_memory(xen_free_memory=30028873, total_mem_pref=4047688921.6000004, total_available_memory=15880640804.400002)
Feb 07 11:05:43 dom0 qmemman.daemon.algo[12565]: left_memory=3840195181 acceptors_count=3
Feb 07 11:05:43 dom0 qmemman.daemon.algo[12565]: left_memory=770857634 acceptors_count=2
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '10' act=4126146560 pref=1619681689.6000001 last_target=4126146560
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '0' act=10014468173 pref=1682311590.4 last_target=10014468173
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '6' act=2097152000 pref=323114188.8 last_target=2097152000
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: dom '3' act=3660534120 pref=422581452.8 last_target=3660534120
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: stat: xenfree=82457673 memset_reqs=[('0', 9938212868), ('10', 4126146560), ('3', 3742278913), ('6', 2097152000)]
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 0 to 9938212868
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 10 to 4126146560
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 3 to 3742278913
Feb 07 11:05:43 dom0 qmemman.systemstate[12565]: mem-set domain 6 to 2097152000
@donob4n

This comment has been minimized.

Show comment
Hide comment
@donob4n

donob4n Feb 7, 2018

@kototama

This is incapacitating my work and I will have to abandon Qubes if there are no fixes or workarounds very soon.

You are using RC3, why don't try a fresh RC4? And if you use Qubes for everyday work, can't you use 3.2 instead?

donob4n commented Feb 7, 2018

@kototama

This is incapacitating my work and I will have to abandon Qubes if there are no fixes or workarounds very soon.

You are using RC3, why don't try a fresh RC4? And if you use Qubes for everyday work, can't you use 3.2 instead?
@kototama

This comment has been minimized.

Show comment
Hide comment
@kototama

kototama Feb 7, 2018

I cannot loose so much time fresh installing RC4.

3.2 does not work on recent hardware, the kernel is too old.

kototama commented Feb 7, 2018

I cannot loose so much time fresh installing RC4.

3.2 does not work on recent hardware, the kernel is too old.
@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Feb 7, 2018

Member

In libxl-driver.log listing I don't see messages from the time of your failed DispVM start (according to journalctl). See last few lines just after failed start attempt.
Member

marmarek commented Feb 7, 2018

In libxl-driver.log listing I don't see messages from the time of your failed DispVM start (according to journalctl). See last few lines just after failed start attempt.
@lvh

This comment has been minimized.

Show comment
Hide comment
@lvh

lvh Feb 7, 2018

Check your kernel version. Likely <4.11. Means PVH won't work, HVM does. That's why sys-net and sys-usb work. Suggested fix:

  1. Change sys-firewall to hvm (qvm-prefs sys-firewall virt_mode hvm) or change updatevm to sys-net temporarily (qubes-prefs updatevm sys-net)
  2. qubes-dom0-update, hope you get a 4.14 kernel
  3. undo what you did in step 1

lvh commented Feb 7, 2018

Check your kernel version. Likely <4.11. Means PVH won't work, HVM does. That's why sys-net and sys-usb work. Suggested fix:

  1. Change sys-firewall to hvm (qvm-prefs sys-firewall virt_mode hvm) or change updatevm to sys-net temporarily (qubes-prefs updatevm sys-net)
  2. qubes-dom0-update, hope you get a 4.14 kernel
  3. undo what you did in step 1

@andrewdavidwong andrewdavidwong added the bug label Feb 8, 2018

@andrewdavidwong andrewdavidwong added this to the Release 4.0 milestone Feb 8, 2018

@kototama

This comment has been minimized.

Show comment
Hide comment
@kototama

kototama Feb 8, 2018

@marmarek I may have wrongly copied the log? The content is:

2018-02-08 08:38:56.023+0000: xc: panic: xc_dom_elfloader.c:66: xc_dom_guest_type: image not capable of booting inside a HVM container: Invalid kernel
2018-02-08 08:38:56.023+0000: libxl: libxl_dom.c:677:libxl__build_dom: xc_dom_parse_image failed: Invalid argument
2018-02-08 08:38:56.040+0000: libxl: libxl_create.c:1284:domcreate_rebuild_done: cannot (re-)build domain: -3

Thanks to @lvh tips, I was able to upgrade the kernel with this command:

sudo qubes-dom0-update --enablerepo=qubes-dom0-current-testing --action=install kernel-qubes-vm.x86_64 --best --allowerasing

I can now start the Template VMs. I upgrade fedora-26-dvm (dnf update) [not sure if it makes sense] and the fedora-26 template.

However I cannot start a DispVM. Running:

qvm-run --dispvm fedora-26-dvm gnome-terminal results in the terminal being launched and the VM suddenly being killed.

Log:
2018-02-08 09:20:25.616+0000: libxl: libxl_device.c:1081:device_backend_callback: unable to remove device with path /local/domain/4/backend/vif/20/0 2018-02-08 09:20:25.624+0000: libxl: libxl.c:1669:devices_destroy_cb: libxl__devices_destroy failed for 20 2018-02-08 09:20:25.732+0000: libxl: libxl_linux.c:155:libxl__loopdev_cleanup: unable to release device /dev/loop1: No such device or address 2018-02-08 09:20:25.752+0000: libxl: libxl_device.c:1081:device_backend_callback: unable to remove device with path /local/domain/4/backend/vif/19/0 2018-02-08 09:20:25.758+0000: libxl: libxl.c:1669:devices_destroy_cb: libxl__devices_destroy failed for 19

How can I fix the DispVM problem?

kototama commented Feb 8, 2018 •
edited
Edited 1 time
  • @kototama kototama edited Feb 8, 2018 (most recent)

@marmarek I may have wrongly copied the log? The content is:

2018-02-08 08:38:56.023+0000: xc: panic: xc_dom_elfloader.c:66: xc_dom_guest_type: image not capable of booting inside a HVM container: Invalid kernel
2018-02-08 08:38:56.023+0000: libxl: libxl_dom.c:677:libxl__build_dom: xc_dom_parse_image failed: Invalid argument
2018-02-08 08:38:56.040+0000: libxl: libxl_create.c:1284:domcreate_rebuild_done: cannot (re-)build domain: -3

Thanks to @lvh tips, I was able to upgrade the kernel with this command:

sudo qubes-dom0-update --enablerepo=qubes-dom0-current-testing --action=install kernel-qubes-vm.x86_64 --best --allowerasing

I can now start the Template VMs. I upgrade fedora-26-dvm (dnf update) [not sure if it makes sense] and the fedora-26 template.

However I cannot start a DispVM. Running:

qvm-run --dispvm fedora-26-dvm gnome-terminal results in the terminal being launched and the VM suddenly being killed.

Log:
2018-02-08 09:20:25.616+0000: libxl: libxl_device.c:1081:device_backend_callback: unable to remove device with path /local/domain/4/backend/vif/20/0 2018-02-08 09:20:25.624+0000: libxl: libxl.c:1669:devices_destroy_cb: libxl__devices_destroy failed for 20 2018-02-08 09:20:25.732+0000: libxl: libxl_linux.c:155:libxl__loopdev_cleanup: unable to release device /dev/loop1: No such device or address 2018-02-08 09:20:25.752+0000: libxl: libxl_device.c:1081:device_backend_callback: unable to remove device with path /local/domain/4/backend/vif/19/0 2018-02-08 09:20:25.758+0000: libxl: libxl.c:1669:devices_destroy_cb: libxl__devices_destroy failed for 19

How can I fix the DispVM problem?
@kototama

This comment has been minimized.

Show comment
Hide comment
@kototama

kototama Feb 8, 2018

Running qvm-run --dispvm fedora-26-dvm xterm and qvm-run --dispvm fedora-26-dvm firefox works. Only gnome-terminal causes problem!

kototama commented Feb 8, 2018 •
edited
Edited 1 time
  • @kototama kototama edited Feb 8, 2018 (most recent)

Running qvm-run --dispvm fedora-26-dvm xterm and qvm-run --dispvm fedora-26-dvm firefox works. Only gnome-terminal causes problem!
@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Feb 8, 2018

Member

That's a different issue. gnome-terminal is incompatible with DispVM. Related documentation for this is discussed here:
QubesOS/qubes-doc#543
Member

marmarek commented Feb 8, 2018

That's a different issue. gnome-terminal is incompatible with DispVM. Related documentation for this is discussed here:
QubesOS/qubes-doc#543
@kototama

This comment has been minimized.

Show comment
Hide comment
@kototama

kototama Feb 8, 2018

I see. Thank you Marek.

kototama commented Feb 8, 2018

I see. Thank you Marek.

@marmarek marmarek closed this Feb 27, 2018

@andrewdavidwong andrewdavidwong added the resolved label Feb 28, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment