bug: launch failed: xencall issue encountered: kernel error: EINVAL: Invalid argument

[gthvn1]

What happened?

Hello,

I followed the Development Guide and when I tried to launch the guest I got a failure.
I launched the guest using: RUST_LOG=debug ./hack/debug/kratactl.sh launch --attach alpine:latest
And I got:

[2024-05-10T16:09:49Z ERROR kratactl::cli::launch] launch failed: xencall issue encountered: kernel error: EINVAL: Invalid argument

I pasted the full output in relevant log output.
I also started kratad.sh with debug log and I can see the warning:

[2024-05-10T16:09:49Z WARN  kratad::reconcile::guest] failed to start guest 595ceded-da16-4b28-a430-1b77267acb3f: xencall issue encountered: kernel error: EINVAL: Invalid argument

I have updated my debian stable and cleanup my working directory.

I will test if I can find the commit that generates the issue because I tested it maybe two weeks ago and it worked.

Version / Commit

09ee251

Relevant log output

[2024-05-10T16:09:48Z DEBUG h2::client] binding client connection
[2024-05-10T16:09:48Z DEBUG h2::client] client connection bound
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-05-10T16:09:48Z DEBUG h2::proto::connection] Connection; peer=Client
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_read] received frame=Settings { flags: (0x0), initial_window_size: 1048576, max_frame_size: 16384, max_header_list_size: 16777216 }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Settings { flags: (0x1: ACK) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=WindowUpdate { stream_id: StreamId(0), size_increment: 5177345 }
[2024-05-10T16:09:48Z DEBUG tower::buffer::worker] service.ready=true message=processing request
[2024-05-10T16:09:48Z DEBUG tower::buffer::worker] service.ready=true message=processing request
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_read] received frame=Settings { flags: (0x1: ACK) }
[2024-05-10T16:09:48Z DEBUG h2::proto::settings] received settings ACK; applying Settings { flags: (0x0), enable_push: 0, initial_window_size: 2097152, max_frame_size: 16384 }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_read] received frame=WindowUpdate { stream_id: StreamId(0), size_increment: 983041 }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Headers { stream_id: StreamId(3), flags: (0x4: END_HEADERS) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Data { stream_id: StreamId(1) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Data { stream_id: StreamId(3) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Data { stream_id: StreamId(1), flags: (0x1: END_STREAM) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Data { stream_id: StreamId(3), flags: (0x1: END_STREAM) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_read] received frame=Headers { stream_id: StreamId(3), flags: (0x4: END_HEADERS) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_read] received frame=Headers { stream_id: StreamId(1), flags: (0x4: END_HEADERS) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_read] received frame=Data { stream_id: StreamId(1) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_read] received frame=Headers { stream_id: StreamId(1), flags: (0x5: END_HEADERS | END_STREAM) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Reset { stream_id: StreamId(1), error_code: CANCEL }
[2024-05-10T16:09:48Z DEBUG tower::buffer::worker] service.ready=true message=processing request
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Headers { stream_id: StreamId(5), flags: (0x4: END_HEADERS) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Data { stream_id: StreamId(5) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_write] send frame=Data { stream_id: StreamId(5), flags: (0x1: END_STREAM) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_read] received frame=Headers { stream_id: StreamId(5), flags: (0x4: END_HEADERS) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_read] received frame=Data { stream_id: StreamId(5) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_read] received frame=Headers { stream_id: StreamId(5), flags: (0x5: END_HEADERS | END_STREAM) }
[2024-05-10T16:09:48Z DEBUG h2::codec::framed_read] received frame=Data { stream_id: StreamId(3) }
[2024-05-10T16:09:49Z DEBUG h2::codec::framed_read] received frame=Data { stream_id: StreamId(3) }
[2024-05-10T16:09:49Z ERROR kratactl::cli::launch] launch failed: xencall issue encountered: kernel error: EINVAL: Invalid argument

[azenla]

Interesting, what Xen version was this on? Also, can you run with RUST_LOG="TRACE", it will be very verbose but will pinpoint where the issue is.

Thanks!

[gthvn1]

I'm running Xen version 4.17.4-pre

(XEN) Xen version 4.17.4-pre (Debian 4.17.3+10-g091466ba55-1~deb12u1) ([email protected]) (x86_64-linux-gnu-gcc (Debian 12.2.0-14) 12.2.0) debug=n Sun Feb  4 15:31:59 UTC 2024
(XEN) Bootloader: GRUB 2.06-13+deb12u1
(XEN) Command line: placeholder dom0_mem=4G,max:4G

I added trace and I see this:

[2024-05-14T17:02:48Z TRACE xencall] domctl fd=22 create_domain create_domain=CreateDomain { ssidref: 12, handle: [1, 241, 53, 24, 131, 81, 78, 236, 181, 189, 5, 31, 25, 5, 136, 118], flags: 32, iommu_opts: 0, max_vcpus: 1, max_evtchn_port: 1023, max_grant_frames: -1, max
_maptrack_frames: -1, grant_opts: 2, vmtrace_size: 0, cpupool_id: 0, arch_domain_config: ArchDomainConfig { emulation_flags: 0, misc_flags: 0 } }
[2024-05-14T17:02:48Z TRACE xencall] call fd=22 hypercall op=0x24 arg=[139641399339192, 0, 0, 0, 0]
[2024-05-14T17:02:49Z WARN  kratad::reconcile::guest] failed to start guest 6f97c8c2-bc08-4bd8-b8fa-314ce177ad07: xencall issue encountered: kernel error: EINVAL: Invalid argument
[2024-05-14T17:02:49Z INFO  kratad::reconcile::guest] reconciled guest 6f97c8c2-bc08-4bd8-b8fa-314ce177ad07

I have full log that I can copy/paste somewhere if needed ;)

[azenla]

That's odd. It's failing at create_domain. I've never seen that be a problem, but what that probably means is the struct passed to create domain has an invalid value. I will peek into xen to see if I can figure out the reason.