Misbehaving QubesDB VM daemon isn't properly handled in dom0

[marmarek]

https://groups.google.com/d/msgid/qubes-users/378c2d08-f02a-4d78-89d5-cf82fd0f2528%40googlegroups.com

I've just added some initial QubesDB support (to get the IP address). It
took me a while to get it working because initially I didn't spot that the
C struct requires some padding before data_len. This worked:

cstruct msg_header {
uint8_t ty;
uint8_t path[64];
uint8_t padding[3];
uint32_t data_len;
(* rest of message is data *)
} as little_endian

My first attempts at sending the initial MULTIREAD without this padding
caused dom0 to get into a bad state (qubes-manager wouldn't run, etc) and I
had to reboot the laptop a couple of times.

[talex5]

Nothing interesting in the logs:

[tal@dom0 ~]$ cat /var/log/qubes/qubesdb.mirage-test.log 
vchan closed
reconnecting
terminating

I've uploaded the test kernel I was using here if you want to recreate it:

http://test.roscidus.com/static/qubes/mir-break-db.xen

Just create an AppVM and set that as the kernel. It doesn't care about disk or network or initrd.

Each time I restart it, there's a pause of a few seconds at "Starting Qubes DB", and I get two new qubesdb processes:

[tal@dom0 ~]$ qvm-kill mirage-test && qvm-start mirage-test && (ps axu|grep 'qubesdb.*mirage-test'|wc)
--> Creating volatile image: /var/lib/qubes/appvms/mirage-test/volatile.img...
--> Loading the VM (type = AppVM)...
--> Starting Qubes DB...
--> Setting Qubes DB info for the VM...
--> Updating firewall rules...
--> Starting the VM...
--> Starting the qrexec daemon...
Waiting for VM's qrexec agent.connected
--> Starting Qubes GUId...
Connecting to VM's GUI agent: .connected
--> Sending monitor layout...
--> Waiting for qubes-session...
 43    1063    9728
[tal@dom0 ~]$ qvm-kill mirage-test && qvm-start mirage-test && (ps axu|grep 'qubesdb.*mirage-test'|wc)
--> Creating volatile image: /var/lib/qubes/appvms/mirage-test/volatile.img...
--> Loading the VM (type = AppVM)...
--> Starting Qubes DB...
--> Setting Qubes DB info for the VM...
--> Updating firewall rules...
--> Starting the VM...
--> Starting the qrexec daemon...
Waiting for VM's qrexec agent.connected
--> Starting Qubes GUId...
Connecting to VM's GUI agent: .connected
--> Sending monitor layout...
--> Waiting for qubes-session...
 45    1113   10187

xl list shows many nulls:

[tal@dom0 ~]$ xl list
Name                                        ID   Mem VCPUs      State   Time(s)
dom0                                         0  3911     4     r-----   12827.9
sys-net                                     47   294     4     -b----     504.1
sys-firewall                                48   497     4     -b----     308.2
dev                                         71   747     4     r-----    3018.9
mirage-firewall                             75    32     1     -b----       0.1
(null)                                      85     0     1     -bp--d       0.0
(null)                                      86     0     1     -bp--d       0.0
(null)                                      87     0     1     -bp--d       0.0
(null)                                      88     0     1     -bp--d       0.0
(null)                                      89     0     1     -bp--d       0.0
(null)                                      90     0     1     -bp--d       0.0
(null)                                      91     0     1     -bp--d       0.0
(null)                                      92     0     1     -bp--d       0.0
(null)                                      93     0     1     -bp--d       0.0
(null)                                      94     0     1     -bp--d       0.0
(null)                                      95     0     1     -bp--d       0.0
(null)                                      96     0     1     -bp--d       0.0
(null)                                      97     0     1     -bp--d       0.0
(null)                                      98     0     1     -bp--d       0.0
(null)                                      99     0     1     -bp--d       0.0
(null)                                     100     0     1     -bp--d       0.0
(null)                                     101     0     1     -bp--d       0.0
(null)                                     102     0     1     -bp--d       0.0
(null)                                     103     0     1     -bp--d       0.0
(null)                                     104     0     1     -bp--d       0.0
(null)                                     105     0     1     -bp--d       0.0
mirage-test                                106    40     1     -b----       0.0
comms                                      107  2164     4     -b----     164.5

qubes-manager doesn't start.

[talex5]

Nothing interesting in the logs:

[tal@dom0 ~]$ cat /var/log/qubes/qubesdb.mirage-test.log 
vchan closed
reconnecting
terminating

I've uploaded the test kernel I was using here if you want to recreate it:

http://test.roscidus.com/static/qubes/mir-break-db.xen

Just create an AppVM and set that as the kernel. It doesn't care about disk or network or initrd.

Each time I restart it, there's a pause of a few seconds at "Starting Qubes DB", and I get two new qubesdb processes:

[tal@dom0 ~]$ qvm-kill mirage-test && qvm-start mirage-test && (ps axu|grep 'qubesdb.*mirage-test'|wc)
--> Creating volatile image: /var/lib/qubes/appvms/mirage-test/volatile.img...
--> Loading the VM (type = AppVM)...
--> Starting Qubes DB...
--> Setting Qubes DB info for the VM...
--> Updating firewall rules...
--> Starting the VM...
--> Starting the qrexec daemon...
Waiting for VM's qrexec agent.connected
--> Starting Qubes GUId...
Connecting to VM's GUI agent: .connected
--> Sending monitor layout...
--> Waiting for qubes-session...
 43    1063    9728
[tal@dom0 ~]$ qvm-kill mirage-test && qvm-start mirage-test && (ps axu|grep 'qubesdb.*mirage-test'|wc)
--> Creating volatile image: /var/lib/qubes/appvms/mirage-test/volatile.img...
--> Loading the VM (type = AppVM)...
--> Starting Qubes DB...
--> Setting Qubes DB info for the VM...
--> Updating firewall rules...
--> Starting the VM...
--> Starting the qrexec daemon...
Waiting for VM's qrexec agent.connected
--> Starting Qubes GUId...
Connecting to VM's GUI agent: .connected
--> Sending monitor layout...
--> Waiting for qubes-session...
 45    1113   10187

xl list shows many nulls:

[tal@dom0 ~]$ xl list
Name                                        ID   Mem VCPUs      State   Time(s)
dom0                                         0  3911     4     r-----   12827.9
sys-net                                     47   294     4     -b----     504.1
sys-firewall                                48   497     4     -b----     308.2
dev                                         71   747     4     r-----    3018.9
mirage-firewall                             75    32     1     -b----       0.1
(null)                                      85     0     1     -bp--d       0.0
(null)                                      86     0     1     -bp--d       0.0
(null)                                      87     0     1     -bp--d       0.0
(null)                                      88     0     1     -bp--d       0.0
(null)                                      89     0     1     -bp--d       0.0
(null)                                      90     0     1     -bp--d       0.0
(null)                                      91     0     1     -bp--d       0.0
(null)                                      92     0     1     -bp--d       0.0
(null)                                      93     0     1     -bp--d       0.0
(null)                                      94     0     1     -bp--d       0.0
(null)                                      95     0     1     -bp--d       0.0
(null)                                      96     0     1     -bp--d       0.0
(null)                                      97     0     1     -bp--d       0.0
(null)                                      98     0     1     -bp--d       0.0
(null)                                      99     0     1     -bp--d       0.0
(null)                                     100     0     1     -bp--d       0.0
(null)                                     101     0     1     -bp--d       0.0
(null)                                     102     0     1     -bp--d       0.0
(null)                                     103     0     1     -bp--d       0.0
(null)                                     104     0     1     -bp--d       0.0
(null)                                     105     0     1     -bp--d       0.0
mirage-test                                106    40     1     -b----       0.0
comms                                      107  2164     4     -b----     164.5

qubes-manager doesn't start.

[marmarek]

Can you strace some of those qubesdb processes (strace -p PID)? In worst
case, there should be timeout of 60s (on select syscall), after which
process should exit.

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?

[marmarek]

Can you strace some of those qubesdb processes (strace -p PID)? In worst
case, there should be timeout of 60s (on select syscall), after which
process should exit.

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?

[marmarek]

And check also /var/log/qubes/qubesdb.mirage-test.log.old.

[marmarek]

And check also /var/log/qubes/qubesdb.mirage-test.log.old.