/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

Qubes R4 sys-usb does not start - Start failed: internal error: Unable to reset PCI device 0000:00:14.0: no FLR, PM reset or bus reset available #3262

Closed
adrelanos opened this Issue Oct 30, 2017 · 3 comments

Comments

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
2 participants
@adrelanos @marmarek
@adrelanos
Member

adrelanos commented Oct 30, 2017

Qubes OS version:

R4

Affected TemplateVMs:

dom0

Steps to reproduce the behavior:

I wanted to get an USB device to work that didn't work for some reason (ledger nano s), wanted to try pci_strictreset true. So,

  • remove rd.qubes.hide_all_usb from grub so I won't lockout myself as long as I am learning about and experimenting with USB VMs
  • check qvm-pci and see all USB controllers were added with pci_strictreset true by default
    shut down sys-usb
  • detach all USB controllers from sys-usb
  • reattach all USB controllers to sys-sb with pci_strictreset true
  • restart
  • notice USB no longer works
  • delete sys-usb
  • recreate sys-usb
  • kernelopts nopat iommo=soft swiotlb=8192
  • reattach USB controllers without pci_strictreset setting (so should default to true

Expected behavior:

  • sys-usb functional,
  • or human readable error message.

Actual behavior:

  • sys-usb broken and
  • no user-useful error message

General notes:

With 2 of 3 usb controllers assigned to sys-usb.

[user@dom0 ~]$ qvm-start sys-usb
Start failed: internal error: libxenlight failed to create new domain 'sys-usb'

Oct 30 12:43:28 dom0 qubesd[10535]: Starting sys-usb
Oct 30 12:43:28 dom0 qmemman.systemstate[2430]: do_balloon(memsize=472907776)
Oct 30 12:43:28 dom0 qmemman.systemstate[2430]: xenfree=91067642
Oct 30 12:43:28 dom0 qmemman.daemon.algo[2430]: balloon: dom 2 has actual memory 4194304000
Oct 30 12:43:28 dom0 qmemman.daemon.algo[2430]: balloon: dom 6 has actual memory 4194332672
Oct 30 12:43:28 dom0 qmemman.daemon.algo[2430]: balloon: dom 0 has actual memory 24429662141
Oct 30 12:43:28 dom0 qmemman.daemon.algo[2430]: req=434268934 avail=29891021065.800003 donors=[('2', 3813820416.0), ('6', 3359047270.4), ('0', 22718153379.4)]
Oct 30 12:43:28 dom0 qmemman.daemon.algo[2430]: borrow 58179173.907166116 from 2
Oct 30 12:43:28 dom0 qmemman.daemon.algo[2430]: borrow 51241687.85901042 from 6
Oct 30 12:43:28 dom0 qmemman.daemon.algo[2430]: borrow 346561518.9338234 from 0
Oct 30 12:43:28 dom0 qmemman.systemstate[2430]: memset_reqs=[('2', 4136124826), ('6', 4143090984), ('0', 24083100622)]
Oct 30 12:43:28 dom0 qmemman.systemstate[2430]: mem-set domain 2 to 4136124826
Oct 30 12:43:28 dom0 qmemman.systemstate[2430]: mem-set domain 6 to 4143090984
Oct 30 12:43:28 dom0 qmemman.systemstate[2430]: mem-set domain 0 to 24083100622
Oct 30 12:43:28 dom0 qmemman.systemstate[2430]: xenfree=512041563
Oct 30 12:43:29 dom0 qubesd[10535]: b'  WARNING: Sum of all thin volume sizes (641.10 GiB) exceeds the size of thin pool qubes_dom0/pool00 and the size of whole volume group (446.12 GiB)!\n'
Oct 30 12:43:29 dom0 dmeventd[809]: No longer monitoring thin pool qubes_dom0-pool00-tpool.
Oct 30 12:43:29 dom0 lvm[809]: Monitoring thin pool qubes_dom0-pool00-tpool.
Oct 30 12:43:29 dom0 qubesd[10535]: b'  WARNING: Sum of all thin volume sizes (641.10 GiB) exceeds the size of thin pool qubes_dom0/pool00 and the size of whole volume group (446.12 GiB)!\n'
Oct 30 12:43:30 dom0 kernel: xen-blkback: backend/vbd/15/51712: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 30 12:43:30 dom0 kernel: xen-blkback: backend/vbd/15/51728: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 30 12:43:30 dom0 kernel: xen-blkback: backend/vbd/15/51744: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 30 12:43:30 dom0 kernel: xen-blkback: backend/vbd/15/51760: using 1 queues, protocol 1 (x86_64-abi) persistent grants
Oct 30 12:43:31 dom0 kernel: xen_pciback: vpci: 0000:00:1d.0: assign to virtual slot 0
Oct 30 12:43:31 dom0 kernel: pciback 0000:00:1d.0: registering for 15
Oct 30 12:43:31 dom0 kernel: pciback 0000:00:1d.0: enabling device (0000 -> 0002)
Oct 30 12:43:31 dom0 kernel: xen: registering gsi 23 triggering 0 polarity 1
Oct 30 12:43:31 dom0 kernel: Already setup the GSI :23
Oct 30 12:43:31 dom0 kernel: xen: registering gsi 23 triggering 0 polarity 1
Oct 30 12:43:31 dom0 kernel: Already setup the GSI :23
Oct 30 12:43:31 dom0 kernel: xen: registering gsi 23 triggering 0 polarity 1
Oct 30 12:43:31 dom0 kernel: Already setup the GSI :23
Oct 30 12:43:31 dom0 kernel: xen: registering gsi 23 triggering 0 polarity 1
Oct 30 12:43:31 dom0 kernel: Already setup the GSI :23
Oct 30 12:43:31 dom0 kernel: xen: registering gsi 23 triggering 0 polarity 1
Oct 30 12:43:31 dom0 kernel: Already setup the GSI :23
Oct 30 12:43:31 dom0 kernel: xen: registering gsi 23 triggering 0 polarity 1
Oct 30 12:43:31 dom0 kernel: Already setup the GSI :23
Oct 30 12:43:31 dom0 kernel: xen: registering gsi 23 triggering 0 polarity 1
Oct 30 12:43:31 dom0 kernel: Already setup the GSI :23
Oct 30 12:43:32 dom0 libvirtd[2350]: 2017-10-30 11:43:32.148+0000: 2379: error : libxlDomainStart:1320 : internal error: libxenlight failed to create new domain 'sys-usb'
Oct 30 12:43:32 dom0 qmemman.daemon.reqhandler[2430]: EOF
Oct 30 12:43:32 dom0 qubesd[10535]: QubesException("Start failed: internal error: libxenlight failed to create new domain 'sys-usb'",) while calling src=b'dom0' meth=b'admin.vm.Start' dest=b'sys-usb' arg=b'' len(untrusted_payload)=0
Oct 30 12:43:32 dom0 qmemman.daemon.algo[2430]: balance_when_enough_memory(xen_free_memory=459606223, total_mem_pref=2927277747.2, total_available_memory=29929088489.800003)
Oct 30 12:43:32 dom0 qmemman.daemon.algo[2430]: left_memory=5243786581 acceptors_count=1
Oct 30 12:43:32 dom0 qmemman.systemstate[2430]: stat: dom '2' act=4153348096 pref=380483584.0
Oct 30 12:43:32 dom0 qmemman.systemstate[2430]: stat: dom '6' act=4160311296 pref=835285401.6
Oct 30 12:43:32 dom0 qmemman.systemstate[2430]: stat: dom '0' act=24083100622 pref=1711508761.6000001
Oct 30 12:43:32 dom0 qmemman.systemstate[2430]: stat: xenfree=512035023 memset_reqs=[('6', 4194304000), ('0', 24429658083), ('2', 4194304000)]
Oct 30 12:43:32 dom0 qmemman.systemstate[2430]: mem-set domain 6 to 4194304000
Oct 30 12:43:32 dom0 qmemman.systemstate[2430]: mem-set domain 0 to 24429658083
Oct 30 12:43:32 dom0 qmemman.systemstate[2430]: mem-set domain 2 to 4194304000
Oct 30 12:43:32 dom0 qmemman.daemon.algo[2430]: balance_when_enough_memory(xen_free_memory=31845874, total_mem_pref=2927277747.2, total_available_memory=29922834209.800003)
Oct 30 12:43:32 dom0 qmemman.daemon.algo[2430]: left_memory=5241191625 acceptors_count=1
Oct 30 12:43:32 dom0 qmemman.daemon.algo[2430]: balance_when_enough_memory(xen_free_memory=33251369, total_mem_pref=2927277747.2, total_available_memory=29924239704.800003)
Oct 30 12:43:32 dom0 qmemman.daemon.algo[2430]: left_memory=5241774777 acceptors_count=1
Oct 30 12:43:32 dom0 qmemman.daemon.algo[2430]: balance_when_enough_memory(xen_free_memory=33953182, total_mem_pref=2927277747.2, total_available_memory=29924941517.800003)
Oct 30 12:43:32 dom0 qmemman.daemon.algo[2430]: left_memory=5242065965 acceptors_count=1

Somehow selective assignment of some but not all USB controllers is not possible, perhaps similar/duplicate of #1393?

With all 3 usb controllers assigned to sys-usb.

qvm-start sys-usb
Start failed: internal error: Unable to reset PCI device 0000:00:14.0: no FLR, PM reset or bus reset available

Oct 30 12:44:44 dom0 qubesd[10535]: Starting sys-usb
Oct 30 12:44:44 dom0 kernel: xhci_hcd 0000:00:14.0: remove, state 4
Oct 30 12:44:44 dom0 kernel: usb usb2: USB disconnect, device number 1
Oct 30 12:44:44 dom0 kernel: xhci_hcd 0000:00:14.0: USB bus 2 deregistered
Oct 30 12:44:44 dom0 kernel: xhci_hcd 0000:00:14.0: remove, state 1
Oct 30 12:44:44 dom0 kernel: usb usb1: USB disconnect, device number 1
Oct 30 12:44:44 dom0 kernel: usb 1-1: USB disconnect, device number 2
Oct 30 12:44:44 dom0 kernel: xhci_hcd 0000:00:14.0: Slot 2 endpoint 2 not removed from BW list!
Oct 30 12:44:44 dom0 kernel: xhci_hcd 0000:00:14.0: Slot 2 endpoint 4 not removed from BW list!
Oct 30 12:44:44 dom0 kernel: usb 1-2: USB disconnect, device number 3
Oct 30 12:44:44 dom0 kernel: xhci_hcd 0000:00:14.0: Slot 1 endpoint 2 not removed from BW list!
Oct 30 12:44:44 dom0 kernel: xhci_hcd 0000:00:14.0: USB bus 1 deregistered
Oct 30 12:44:44 dom0 kernel: pciback 0000:00:14.0: seizing device
Oct 30 12:44:44 dom0 kernel: xen: registering gsi 16 triggering 0 polarity 1
Oct 30 12:44:44 dom0 kernel: Already setup the GSI :16
Oct 30 12:44:44 dom0 qmemman.systemstate[2430]: do_balloon(memsize=472907776)
Oct 30 12:44:44 dom0 qmemman.systemstate[2430]: xenfree=91067636
Oct 30 12:44:44 dom0 qmemman.daemon.algo[2430]: balloon: dom 2 has actual memory 4194304000
Oct 30 12:44:44 dom0 qmemman.daemon.algo[2430]: balloon: dom 6 has actual memory 4194332672
Oct 30 12:44:44 dom0 qmemman.daemon.algo[2430]: balloon: dom 0 has actual memory 24429658083
Oct 30 12:44:44 dom0 qmemman.daemon.algo[2430]: req=434268940 avail=29891017007.800003 donors=[('2', 3813820416.0), ('6', 3359047270.4), ('0', 22718149321.4)]
Oct 30 12:44:44 dom0 qmemman.daemon.algo[2430]: borrow 58179182.60938446 from 2
Oct 30 12:44:44 dom0 qmemman.daemon.algo[2430]: borrow 51241695.52354612 from 6
Oct 30 12:44:44 dom0 qmemman.daemon.algo[2430]: borrow 346561508.86706936 from 0
Oct 30 12:44:44 dom0 qmemman.systemstate[2430]: memset_reqs=[('2', 4136124817), ('6', 4143090976), ('0', 24083096574)]
Oct 30 12:44:44 dom0 qmemman.systemstate[2430]: mem-set domain 2 to 4136124817
Oct 30 12:44:44 dom0 qmemman.systemstate[2430]: mem-set domain 6 to 4143090976
Oct 30 12:44:44 dom0 qmemman.systemstate[2430]: mem-set domain 0 to 24083096574
Oct 30 12:44:44 dom0 qmemman.systemstate[2430]: xenfree=512041547
Oct 30 12:44:45 dom0 qubesd[10535]: b'  WARNING: Sum of all thin volume sizes (641.10 GiB) exceeds the size of thin pool qubes_dom0/pool00 and the size of whole volume group (446.12 GiB)!\n'
Oct 30 12:44:45 dom0 dmeventd[809]: No longer monitoring thin pool qubes_dom0-pool00-tpool.
Oct 30 12:44:45 dom0 lvm[809]: Monitoring thin pool qubes_dom0-pool00-tpool.
Oct 30 12:44:45 dom0 qubesd[10535]: b'  WARNING: Sum of all thin volume sizes (641.10 GiB) exceeds the size of thin pool qubes_dom0/pool00 and the size of whole volume group (446.12 GiB)!\n'
Oct 30 12:44:45 dom0 libvirtd[2350]: 2017-10-30 11:44:45.528+0000: 2379: error : virPCIDeviceReset:1002 : internal error: Unable to reset PCI device 0000:00:14.0: no FLR, PM reset or bus reset available
Oct 30 12:44:45 dom0 qmemman.daemon.reqhandler[2430]: EOF
Oct 30 12:44:45 dom0 qubesd[10535]: QubesException('Start failed: internal error: Unable to reset PCI device 0000:00:14.0: no FLR, PM reset or bus reset available',) while calling src=b'dom0' meth=b'admin.vm.Start' dest=b'sys-usb' arg=b'' len(untrusted_payload)=0
Oct 30 12:45:46 dom0 sudo[4555]:     user : TTY=pts/6 ; PWD=/home/user ; USER=root ; COMMAND=/bin/journalctl -f -n 100
Oct 30 12:45:46 dom0 kernel: audit: type=1123 audit(1509363946.711:260): pid=4555 uid=1000 auid=1000 ses=1 msg='cwd="/home/user" cmd=6A6F75726E616C63746C202D66202D6E20313030 terminal=pts/6 res=success'
Oct 30 12:45:46 dom0 kernel: audit: type=1110 audit(1509363946.711:261): pid=4555 uid=0 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/6 res=success'
Oct 30 12:45:46 dom0 audit[4555]: USER_CMD pid=4555 uid=1000 auid=1000 ses=1 msg='cwd="/home/user" cmd=6A6F75726E616C63746C202D66202D6E20313030 terminal=pts/6 res=success'
Oct 30 12:45:46 dom0 audit[4555]: CRED_REFR pid=4555 uid=0 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/6 res=success'
Oct 30 12:45:46 dom0 sudo[4555]: pam_systemd(sudo:session): Cannot create session: Already running in a session
Oct 30 12:45:46 dom0 kernel: audit: type=1105 audit(1509363946.714:262): pid=4555 uid=0 auid=1000 ses=1 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/6 res=success'
Oct 30 12:45:46 dom0 audit[4555]: USER_START pid=4555 uid=0 auid=1000 ses=1 msg='op=PAM:session_open grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/6 res=success'
Oct 30 12:45:46 dom0 sudo[4555]: pam_unix(sudo:session): session opened for user root by (uid=0)
Oct 30 12:46:07 dom0 sudo[4555]: pam_unix(sudo:session): session closed for user root
Oct 30 12:46:07 dom0 kernel: audit: type=1106 audit(1509363967.057:263): pid=4555 uid=0 auid=1000 ses=1 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/6 res=success'
Oct 30 12:46:07 dom0 kernel: audit: type=1104 audit(1509363967.058:264): pid=4555 uid=0 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/6 res=success'
Oct 30 12:46:07 dom0 audit[4555]: USER_END pid=4555 uid=0 auid=1000 ses=1 msg='op=PAM:session_close grantors=pam_keyinit,pam_limits,pam_keyinit,pam_limits,pam_systemd,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/6 res=success'
Oct 30 12:46:07 dom0 audit[4555]: CRED_DISP pid=4555 uid=0 auid=1000 ses=1 msg='op=PAM:setcred grantors=pam_env,pam_unix acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/6 res=success'

Could removing rd.qubes.hide_all_usb from grub be the cause?

Since my sys-usb worked after installation, I must be missing some setting now? So this could also be a lack of my knoweldge on how to replicate the original setup. I tried sudo qubesctl state.sls qvm.sys-usb dom0, but it also does not fix my setup.

//cc @Rudd-O
@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Oct 30, 2017

Member

Are you sure you set no-strict-reset=True option properly? Your previous comment suggested opposite value (I've fixed it there).
Member

marmarek commented Oct 30, 2017

Are you sure you set no-strict-reset=True option properly? Your previous comment suggested opposite value (I've fixed it there).
@adrelanos

This comment has been minimized.

Show comment
Hide comment
@adrelanos

adrelanos Oct 30, 2017

Member

I might have confused these. What remains...

Could we have some better error messages for

Start failed: internal error: libxenlight failed to create new domain 'sys-usb'

and

Start failed: internal error: Unable to reset PCI device 0000:00:14.0: no FLR, PM reset or bus reset available

please?
Member

adrelanos commented Oct 30, 2017

I might have confused these. What remains...

Could we have some better error messages for

Start failed: internal error: libxenlight failed to create new domain 'sys-usb'

and

Start failed: internal error: Unable to reset PCI device 0000:00:14.0: no FLR, PM reset or bus reset available

please?
@marmarek

This comment has been minimized.

Show comment
Hide comment
@marmarek

marmarek Oct 30, 2017

Member

Yes, that would be duplicate of #3205 (especially #3205 (comment)). So, if you think that the only remaining part, lets close this one.
Member

marmarek commented Oct 30, 2017

Yes, that would be duplicate of #3205 (especially #3205 (comment)). So, if you think that the only remaining part, lets close this one.

@adrelanos adrelanos closed this Oct 30, 2017

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