WIP: qemu: randomly choose vsock port on the host side

[vikanezrimaya]

Prevents conflicts between MicroVMs.

Somehow doesn't work first try; VM might timeout a few times before it starts working. The problem is most likely between socat and systemd. More debug logging is needed. (Adding it here would be trivial, actually.)

[astro]

How about creating the port number from bash $RANDOM instead of reading it back from socat's log?

[vikanezrimaya]

1. With VMADDR_PORT_ANY, the kernel can handle collisions for us and transparently rebind. If we choose the port ourselves, we'll have to handle binding collisions ourselves, increasing complexity of the code.
2. Potential port range is smaller, $RANDOM gives half of a u16 (0-32767) while VMADDR_PORT_ANY uses all 32 bits of the port.

[astro]

Alternatively, microvm.vsock.cid should be unique per VM. Let's just add that to an offset.

[astro]

Are you going to work on this on the next few days, or may I roll back the qemu change?

[vikanezrimaya]

Are you going to work on this on the next few days, or may I roll back the qemu change?

I originally planned to work on this this week, but more important concerns arose at work. I will be able to pick this up this Monday.

…

-- Sincerely, Vika <3

[vikanezrimaya]

socat -d -d -d -d log from a run that fails to send notifications to systemd

2024/12/24 22:46:35 socat[692485] I just born: child process 692485
2024/12/24 22:46:35 socat[692485] D setenv("SOCAT_PID", "692485", 1)
2024/12/24 22:46:35 socat[692485] D setenv() -> 0
2024/12/24 22:46:35 socat[692485] I close(5)
2024/12/24 22:46:35 socat[692485] D close()  -> 0
2024/12/24 22:46:35 socat[692485] D setenv("SOCAT_SOCKADDR", "2", 1)
2024/12/24 22:46:35 socat[692485] D setenv() -> 0
2024/12/24 22:46:35 socat[692485] D setenv("SOCAT_SOCKPORT", "600003", 1)
2024/12/24 22:46:35 socat[692485] D setenv() -> 0
2024/12/24 22:46:35 socat[692485] D setenv("SOCAT_PEERADDR", "3", 1)
2024/12/24 22:46:35 socat[692485] D setenv() -> 0
2024/12/24 22:46:35 socat[692485] D setenv("SOCAT_PEERPORT", "1023", 1)
2024/12/24 22:46:35 socat[692485] D setenv() -> 0
2024/12/24 22:46:35 socat[692485] D xioopen("UNIX-SENDTO:/run/systemd/notify")
2024/12/24 22:46:35 socat[692485] D calloc(1, 928)
2024/12/24 22:46:35 socat[692485] D calloc() -> 0x5642edd24850
2024/12/24 22:46:35 socat[692485] D malloc(448)
2024/12/24 22:46:35 socat[692485] D malloc() -> 0x5642edd24180
2024/12/24 22:46:35 socat[692485] D socket(1, 2, 0)
2024/12/24 22:46:35 socat[692485] I socket(1, 2, 0) -> 5
2024/12/24 22:46:35 socat[692485] D fcntl(5, 2, 0x1)
2024/12/24 22:46:35 socat[692485] D fcntl() -> 0x0
2024/12/24 22:46:35 socat[692485] D getsockname(5, 0x7ffdcc1ebb80, 0x7ffdcc1ebb7c{112})
2024/12/24 22:46:35 socat[692485] D getsockname(, {AF=1 "<anon>"}, {2}) -> 0
2024/12/24 22:46:35 socat[692485] N successfully prepared local socket AF=1 "<anon>"
2024/12/24 22:46:35 socat[692485] I resolved and opened all sock addresses
2024/12/24 22:46:35 socat[692485] D posix_memalign(0x7ffdcc1eb0b8, 4096, 16385)
2024/12/24 22:46:35 socat[692485] D posix_memalign(...) -> 0
2024/12/24 22:46:35 socat[692485] N starting data transfer loop with FDs [6,6] and [5,5]
2024/12/24 22:46:35 socat[692485] D data loop: sock1->eof=0, sock2->eof=0, closing=0, wasaction=1, total_to={0.1000000}
2024/12/24 22:46:35 socat[692485] D select(7, &0x60, &0x60, &0x0, NULL/0.000000)
2024/12/24 22:46:35 socat[692485] D select -> (, 0x40, 0x60, 0x0, NULL/0.000000), 3
2024/12/24 22:46:35 socat[692485] D read(6, 0x5642edd25000, 8192)
2024/12/24 22:46:35 socat[692485] D read -> 0
2024/12/24 22:46:35 socat[692485] N socket 1 (fd 6) is at EOF
2024/12/24 22:46:35 socat[692485] I shutdown(5, 1)
2024/12/24 22:46:35 socat[692485] D shutdown()  -> 0
2024/12/24 22:46:35 socat[692485] D data loop: sock1->eof=3, sock2->eof=0, closing=1, wasaction=1, total_to={0.1000000}
2024/12/24 22:46:35 socat[692485] D select(6, &0x20, &0x0, &0x0, &0.500000)
2024/12/24 22:46:35 socat[692485] D select -> (, 0x0, 0x0, 0x0, &0.000000), 0
2024/12/24 22:46:35 socat[692485] I poll timed out (no data within 0.500000 seconds)
2024/12/24 22:46:35 socat[692485] I shutdown(6, 2)
2024/12/24 22:46:35 socat[692485] D shutdown()  -> 0
2024/12/24 22:46:35 socat[692485] I shutdown(5, 2)
2024/12/24 22:46:35 socat[692485] D shutdown()  -> 0
2024/12/24 22:46:35 socat[692485] N exiting with status 0
2024/12/24 22:46:35 socat[692485] D exit(0)
2024/12/24 22:46:35 socat[692485] D starting xioexit()
2024/12/24 22:46:35 socat[692485] D finished xioexit()
2024/12/24 22:46:35 socat[691825] N childdied(): handling signal 17
2024/12/24 22:46:35 socat[691825] I childdied(signum=17)
2024/12/24 22:46:35 socat[691825] D waitpid(-1, 0x7ffdcc1ea374, 1)
2024/12/24 22:46:35 socat[691825] D waitpid(, {0}, ) -> 692485
2024/12/24 22:46:35 socat[691825] I number of children decreased to 0

In particular, it seems we are dealing with spurious EOF errors, as evidenced by the following line from above: (socket 6 seems to be the vsock that QEMU opens)

2024/12/24 22:46:35 socat[692485] N socket 1 (fd 6) is at EOF

I advise reverting the initial commits to support vsock notifications until we manage to figure out why (supposedly) QEMU is prematurely sending EOF before we are able to read any data from the socket. I don't think it is socat's fault, I suspect it may be QEMU or guest systemd's fault. More data is required, though I am unsure how to get it besides sticking QEMU in gdb and trying to set a breakpoint on vsock-related functions. (Perhaps QEMU can also do debug logging to shed more light on this issue?)