R4.0 - question about VM startup ordering during boot

[Ivan Mitev]

Hi,

IIRC in R3.2 VMs were started at boot time according to their dependency
on other VMs. Eg. - for a basic setup without whonix/tor/... - sys-net
would start first, then sys-firewall, and then other VMs configured to
start at boot time (in my case sys-usb, untrusted and work).

In R4.0 (rc3) I see that all the VMs start in parallel at boot time.
/usr/lib/systemd/system/qubes-vm@.service don't show any qubes specific
VM dependency mechanism, and neither do systemctl list-dependencies nor
systemd-analyze critical-chain qubes-vm@sys-firewall (for instance) show
a dependency on sys-net.

Q: is starting *all* the VMs in parallel the "new" way in R4.0 ?

I'm asking because each time I reboot, sys-net consistently fails with
the error message below so I'm wondering whether I'm hitting a totally
unrelated bug (in which case I'll open an issue) or if VMs in 4.0 have
to be started in a specific order but the mechanism isn't implemented
yet (or doesn't work in my case):

`Start failed: invalid argument: network device with mac [...] already
exists`

Note: sys-net has networking PCI devices assigned.

The odd thing is that sys-firewall always manages to start despite
sys-net's failure and other VMs "higher" in the dependency chain
(sys-usb, work, ...) also start successfully.

Starting sys-net manually fails with the same error as above. A helfpul
qubes-user list thread [1] hinted that sys-firewall had to be stopped
for sys-net to start successfully, so the workaround is to shutdown all
the VMs and start them manually according their dependency order - eg.
qvm-start sys-net, then sys-firewall, and then any of
sys-usb/work/untrusted/...


Ivan

PS: as always, kudos for the great work - I've switched to R4.0rc3 in
production with only very minimal issues so far in the past 2 weeks.

[1] https://groups.google.com/forum/#!topic/qubes-users/ta7yGkXoHYs

[Marek Marczykowski-Górecki]

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

On Thu, Jan 25, 2018 at 01:05:04PM +0200, Ivan Mitev wrote:
> Hi,
>
> IIRC in R3.2 VMs were started at boot time according to their dependency on
> other VMs. Eg. - for a basic setup without whonix/tor/... - sys-net would
> start first, then sys-firewall, and then other VMs configured to start at
> boot time (in my case sys-usb, untrusted and work).
>
> In R4.0 (rc3) I see that all the VMs start in parallel at boot time.
> /usr/lib/systemd/system/qubes-vm@.service don't show any qubes specific VM
> dependency mechanism, and neither do systemctl list-dependencies nor
> systemd-analyze critical-chain qubes-vm@sys-firewall (for instance) show a
> dependency on sys-net.
>
> Q: is starting *all* the VMs in parallel the "new" way in R4.0 ?

Yes. Starting a VM (same as in R3.2) implicitly start also its network
dependencies. What is improved in R4.0 that simultaneous requests for
starting the same VM (for example both work VM and personal VM require
starting sys-firewall) are queued and if VM is already running it
doesn't try to start it again.

> I'm asking because each time I reboot, sys-net consistently fails with the
> error message below so I'm wondering whether I'm hitting a totally unrelated
> bug (in which case I'll open an issue) or if VMs in 4.0 have to be started
> in a specific order but the mechanism isn't implemented yet (or doesn't work
> in my case):
>
> `Start failed: invalid argument: network device with mac [...] already
> exists`

This looks like the problem when sys-net is restarted while sys-firewall
was still running. See here:
https://github.com/QubesOS/qubes-issues/issues/3163
https://github.com/QubesOS/qubes-issues/issues/1426

I guess what happened is:
1. sys-net starts
2. sys-firewall starts
3. sys-net crashes
4. sys-net fails to start again

So, the question is why sys-net crashes. Take a look at
/var/log/xen/console/guest-sys-net.log and
/var/log/qubes/vm-sys-net.log.

- --
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-----

iQEzBAEBCAAdFiEEhrpukzGPukRmQqkK24/THMrX1ywFAlppvy0ACgkQ24/THMrX
1yy5+gf9E6n4lFQzh8T6wMmrfMdcGxKE7PHDvhRvgi434n6Ykv+2/SRDIQmqYimQ
XfAR2cHLfSVytopYO/P7EJl7bNqcsh1c4vI+RBShYy0UD8Lc4Vvq8lYxaTldIIz/
xiG+/wAhR4ealpmeSNWdFsL1ksQEItYzFtkUQIuKSNlUool9QHDnjTxbtWvq9sDL
weq2ELAtD9Z/K6QxZ4Vlol5ORxFd1NNPlPtxQZZmTBe2vKT14eEFcvq5JPfLubkJ
LRw1GG33g+V8KagdaRfgo6ZS70iOIX5anrh3pnsJtiTeZW89ClfGUMtt9ZhJuIZ0
n6zDAUy352Kt83pEGY/Nj5v6rga9rg==
=x2xp
-----END PGP SIGNATURE-----

[Ivan Mitev]

On 01/25/18 13:27, Marek Marczykowski-Górecki wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> On Thu, Jan 25, 2018 at 01:05:04PM +0200, Ivan Mitev wrote:
>> Hi,
>>
>> IIRC in R3.2 VMs were started at boot time according to their dependency on
>> other VMs. Eg. - for a basic setup without whonix/tor/... - sys-net would
>> start first, then sys-firewall, and then other VMs configured to start at
>> boot time (in my case sys-usb, untrusted and work).
>>
>> In R4.0 (rc3) I see that all the VMs start in parallel at boot time.
>> /usr/lib/systemd/system/qubes-vm@.service don't show any qubes specific VM
>> dependency mechanism, and neither do systemctl list-dependencies nor
>> systemd-analyze critical-chain qubes-vm@sys-firewall (for instance) show a
>> dependency on sys-net.
>>
>> Q: is starting *all* the VMs in parallel the "new" way in R4.0 ?
>
> Yes. Starting a VM (same as in R3.2) implicitly start also its network
> dependencies. What is improved in R4.0 that simultaneous requests for
> starting the same VM (for example both work VM and personal VM require
> starting sys-firewall) are queued and if VM is already running it
> doesn't try to start it again.

Thanks for the explanation...

>
>> I'm asking because each time I reboot, sys-net consistently fails with the
>> error message below so I'm wondering whether I'm hitting a totally unrelated
>> bug (in which case I'll open an issue) or if VMs in 4.0 have to be started
>> in a specific order but the mechanism isn't implemented yet (or doesn't work
>> in my case):
>>
>> `Start failed: invalid argument: network device with mac [...] already
>> exists`
>
> This looks like the problem when sys-net is restarted while sys-firewall
> was still running. See here:
> https://github.com/QubesOS/qubes-issues/issues/3163
> https://github.com/QubesOS/qubes-issues/issues/1426
>
> I guess what happened is:
> 1. sys-net starts
> 2. sys-firewall starts
> 3. sys-net crashes
> 4. sys-net fails to start again

Ah, I see...

I was 99% sure that the problem was startup concurrency because sys-net
would then start fine after all the other VMs were stopped. My bad :)

> So, the question is why sys-net crashes. Take a look at
> /var/log/xen/console/guest-sys-net.log and
> /var/log/qubes/vm-sys-net.log.

/var/log/qubes/vm-sys-net.log didn't have any helpful info, but I see
some panic logs in guest-sys-net.log ; I'll try to debug it when time
allows.

Thank you !
Ivan

[Marek Marczykowski-Górecki]

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

On Thu, Jan 25, 2018 at 02:21:35PM +0200, Ivan Mitev wrote:
> On 01/25/18 13:27, Marek Marczykowski-Górecki wrote:
> > So, the question is why sys-net crashes. Take a look at
> > /var/log/xen/console/guest-sys-net.log and
> > /var/log/qubes/vm-sys-net.log.
>
> /var/log/qubes/vm-sys-net.log didn't have any helpful info, but I see some
> panic logs in guest-sys-net.log ; I'll try to debug it when time allows.

Can you post this panic messages? I think I've hit exactly the same
problem once but mine logs didn't have any details on sys-net crash
(just cut during its startup). And I can't reproduce it again...

- --
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-----

iQEzBAEBCAAdFiEEhrpukzGPukRmQqkK24/THMrX1ywFAlptFl0ACgkQ24/THMrX
1yyz5gf+Mi2YbDmopIvlxANTP2aUgCaN9tgJt0pRqz6l6wuAqDFQRRbHB6BPnrI+
oRYc50jaIU+GSUcSCzGJfZwzHeuVDxhobKvz/JCyV3mOAJKGib+GDwx0ou6sE7BX
o46xoaK+kxMzTOzNu9YwNnEmJobadO1e3ElW+UGJkE1jYBmeDta1U/A75U+ywTv9
jjV5lFxDG9xGRwTV0rPwK58WhHOR+p/4MNU5sAQUOwLPzsWhTj1mUsQJi+1OxAw3
1OWlOvEPzq1K0J1IUK8d39TW+3WOBREs9460ducbYpSo7pgED2Aw6QPMDIAR4acL
v4ozBzCtz2cfErk4Dpe/0+KyOid8eA==
=wII/
-----END PGP SIGNATURE-----

[Ivan Mitev]

On 01/28/18 02:16, Marek Marczykowski-Górecki wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> On Thu, Jan 25, 2018 at 02:21:35PM +0200, Ivan Mitev wrote:
>> On 01/25/18 13:27, Marek Marczykowski-Górecki wrote:
>>> So, the question is why sys-net crashes. Take a look at
>>> /var/log/xen/console/guest-sys-net.log and
>>> /var/log/qubes/vm-sys-net.log.
>>
>> /var/log/qubes/vm-sys-net.log didn't have any helpful info, but I see some
>> panic logs in guest-sys-net.log ; I'll try to debug it when time allows.
>
> Can you post this panic messages? I think I've hit exactly the same
> problem once but mine logs didn't have any details on sys-net crash
> (just cut during its startup). And I can't reproduce it again...

[logs sent to your email address but feel free to publish them; the
panic message I saw was in guest-sys-net-dm.log]

After your reply to my original post I rebooted to see if I could notice
the timing you described (sys-net starting, then sys-firewall, and then
sys-net crashing). But go figure, while I had this sys-net startup
problem *each time* since installing 4.0rc3, this time sys-net started
successfully and since then I haven't been able to reproduce the problem
with the past 10+ reboots.

The *only* thing I remember that could be related to the problem was
updating sys-net's template a bit before my post (dnf update in
fedora-26). For info here's a list of the updated rpms on Jan 25:

glibc-common-2.25-13.fc26.x86_64
glibc-all-langpacks-2.25-13.fc26.x86_64
glibc-2.25-13.fc26.x86_64
ibus-libs-1.5.17-5.fc26.x86_64
libcrypt-nss-2.25-13.fc26.x86_64
system-python-libs-3.6.4-1.fc26.x86_64
kernel-core-4.14.14-200.fc26.x86_64
kernel-modules-4.14.14-200.fc26.x86_64
python3-libs-3.6.4-1.fc26.x86_64
python3-3.6.4-1.fc26.x86_64
ibus-gtk2-1.5.17-5.fc26.x86_64
ibus-gtk3-1.5.17-5.fc26.x86_64
ibus-wayland-1.5.17-5.fc26.x86_64
ibus-1.5.17-5.fc26.x86_64
ibus-setup-1.5.17-5.fc26.noarch
kernel-headers-4.14.14-200.fc26.x86_64
glibc-headers-2.25-13.fc26.x86_64
glibc-devel-2.25-13.fc26.x86_64
kernel-4.14.14-200.fc26.x86_64
system-python-3.6.4-1.fc26.x86_64
libassuan-2.5.1-1.fc26.x86_64
libgcrypt-1.8.2-1.fc26.x86_64
man-db-2.7.6.1-9.fc26.x86_64
sed-4.4-2.fc26.x86_64
publicsuffix-list-dafsa-20171228-1.fc26.noarch
kernel-devel-4.14.14-200.fc26.x86_64


I'm kind of lucky, most of issues magically disappear at some point :)

Cheers,
Ivan

[awokd]

On Sun, January 28, 2018 8:44 am, Ivan Mitev wrote:

> I'm kind of lucky, most of [my] issues magically disappear at some point :)

Remind me to stay on your good side!

[Ivan Mitev]

aha - will do :)

[Tom Zander]

On Thursday, 25 January 2018 12:05:04 CET Ivan Mitev wrote:
> Q: is starting *all* the VMs in parallel the "new" way in R4.0 ?

To avoid stressing qubesd, which may cause the issue you suffered from, I
suggest you unset the 'start VM automatically at boot' in the config for sys-
net. Just having it for sys-firewall is enough (although I heard too many
scary stories of not being presented with a login promt if either fails so I
just disable all autostart).

Important to realize is that the autostart is implemented as a systemd
service, as such this works too (although it leaves qubes confused);

systemctl disable qube...@sys-net.service

I had to do this because I had to move my sys-net to a different pool and
delete the original VM. Unfortunately qubes never removed the service file.
--
Tom Zander
Blog: https://zander.github.io
Vlog: https://vimeo.com/channels/tomscryptochannel

[Marek Marczykowski-Górecki]

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

On Sun, Jan 28, 2018 at 10:44:37AM +0200, Ivan Mitev wrote:
> On 01/28/18 02:16, Marek Marczykowski-Górecki wrote:
> > On Thu, Jan 25, 2018 at 02:21:35PM +0200, Ivan Mitev wrote:
> > > On 01/25/18 13:27, Marek Marczykowski-Górecki wrote:
> > > > So, the question is why sys-net crashes. Take a look at
> > > > /var/log/xen/console/guest-sys-net.log and
> > > > /var/log/qubes/vm-sys-net.log.
> > >
> > > /var/log/qubes/vm-sys-net.log didn't have any helpful info, but I see some
> > > panic logs in guest-sys-net.log ; I'll try to debug it when time allows.
> >
> > Can you post this panic messages? I think I've hit exactly the same
> > problem once but mine logs didn't have any details on sys-net crash
> > (just cut during its startup). And I can't reproduce it again...
>
> [logs sent to your email address but feel free to publish them; the panic
> message I saw was in guest-sys-net-dm.log]

Warning at arch/x86/xen/apic.c in sys-net-dm is safe to ignore. It's a
side effect of our memory optimizations there (aggressively disabling
not needed kernel features).

Other than that, I see some hardware initialization problems related to
Intel Wifi interface:

[ 6.028035] WARNING: CPU: 1 PID: 567 at /home/user/rpmbuild/BUILD/kernel-4.9.56/linux-4.9.56/drivers/net/wireless/intel/iwlwifi/pcie/trans.c:1860 iwl_trans_pcie_grab_nic_access+0xeb/0xf0 [iwlwifi]
[ 6.028035] Timeout waiting for hardware access (CSR_GP_CNTRL 0xffffffff)

That might result in hanging sys-net during startup, and consequently
startup timeout. According to the log qrexec was started before that
("Started Qubes remote exec agent" message), so it isn't exactly the
timeout defined by qrexec_timeout property. But maybe about something
else, like connecting network to sys-firewall. Or a crash related to
above, but not logged for some reason...

> After your reply to my original post I rebooted to see if I could notice the
> timing you described (sys-net starting, then sys-firewall, and then sys-net
> crashing). But go figure, while I had this sys-net startup problem *each
> time* since installing 4.0rc3, this time sys-net started successfully and
> since then I haven't been able to reproduce the problem with the past 10+
> reboots.

Ok, so keep trying to notice that timing, this will ensure it will
keep working ;)

> The *only* thing I remember that could be related to the problem was
> updating sys-net's template a bit before my post (dnf update in fedora-26).
> For info here's a list of the updated rpms on Jan 25:

(...)

I don't see anything that could directly affect startup crash...

- --
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-----

iQEzBAEBCAAdFiEEhrpukzGPukRmQqkK24/THMrX1ywFAlpt3DgACgkQ24/THMrX
1ywIdQgAi/SKEQzSDQ+xv8K1yVDyv3fDeqyGKq/M1XNo133d3vNKg3KCm8+3OKWd
jXcYcUIxIEZCD1T0rmfl2eDXn+Gk4rwqFdQZBstuWwzGJoG+JNOU4M++ORgDlxzc
3T3wMrEDlAKv9nop6+R6zecNPxtEIqwR7Qa7Ddk4ApGcVB/kHjwtdNef6w3MTmir
KUV5ilqCBAZcUk8Jxh33wN+HNB5g6Z4b0/WYU9Bio/mpPW2LDI0W2gqeGjivjPjL
f5pLgpoJvOvcmdjhK+0NJgOksHvr+dS4o+iht6S6gKTvAplKymmAEaiZjR3Y5j6K
VQAMcO+ZlhJXyQxnzmx4/NxfRQ5shw==
=hcjO
-----END PGP SIGNATURE-----