search

firecracker-microvm / firecracker

Secure and fast microVMs for serverless computing.
http://firecracker-microvm.io
Apache License 2.0
25.03k stars 1.75k forks source link

[Bug] Firecracker doesn't print anything to stdout after boot #3418

Closed dosisod closed 1 year ago

dosisod commented 1 year ago

Describe the bug

After setting up Firecracker (based off the getting started docs) Firecracker simply just hangs after the guest VM is started. There is nothing printed to stdout, no errors, no logs, etc.

This is the output I am getting:

$ sudo ./firecracker \
  --api-sock /tmp/firecracker.socket \
  --level Debug \
  --log-path /tmp/firelog \
  --show-level \
  --show-log-origin

[sudo] password for $USER:

And the logs from /tmp/firelog:

Running Firecracker v1.2.0-165-g81e771a2-dirty
2023-02-05T21:54:15.632444828 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:216] The API server received a Put request on "/boot-source" with body "{\n        \"kernel_image_path\": \"/home/loot/code/firecracker/hello-vmlinux.bin\",\n        \"boot_args\": \"console=ttyS0 reboot=k panic=1 pci=off\"\n   }".
2023-02-05T21:54:15.632752759 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:163] The request was executed successfully. Status code: 204 No Content.
2023-02-05T21:54:15.632795218 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:209] Total previous API call duration: 376 us.
2023-02-05T21:54:15.640348165 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:216] The API server received a Put request on "/drives/rootfs" with body "{\n        \"drive_id\": \"rootfs\",\n        \"path_on_host\": \"/home/loot/code/firecracker/hello-rootfs.ext4\",\n        \"is_root_device\": true,\n        \"is_read_only\": false\n }".
2023-02-05T21:54:15.640645294 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:163] The request was executed successfully. Status code: 204 No Content.
2023-02-05T21:54:15.640687379 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:209] Total previous API call duration: 366 us.
2023-02-05T21:54:15.646651325 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:216] The API server received a Put request on "/actions" with body "{\n      \"action_type\": \"InstanceStart\"\n   }".
2023-02-05T21:54:15.718916301 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:392] Artificially kick devices.
2023-02-05T21:54:15.719230860 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:163] The request was executed successfully. Status code: 204 No Content.
2023-02-05T21:54:15.719374100 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:209] Total previous API call duration: 72744 us.

To Reproduce

After starting Firecracker, I ran the following curl commands (still using the commands from the intro docs):

#!/bin/sh

kernel_path=$(pwd)"/hello-vmlinux.bin"
rootfs_path=$(pwd)"/hello-rootfs.ext4"

# configure guest
curl --unix-socket /tmp/firecracker.socket -i \
  -X PUT 'http://localhost/boot-source'   \
  -H 'Accept: application/json'           \
  -H 'Content-Type: application/json'     \
  -d "{
        \"kernel_image_path\": \"${kernel_path}\",
        \"boot_args\": \"console=ttyS0 reboot=k panic=1 pci=off\"
   }"

# configure rootfs
curl --unix-socket /tmp/firecracker.socket -i \
  -X PUT 'http://localhost/drives/rootfs' \
  -H 'Accept: application/json'           \
  -H 'Content-Type: application/json'     \
  -d "{
        \"drive_id\": \"rootfs\",
        \"path_on_host\": \"${rootfs_path}\",
        \"is_root_device\": true,
        \"is_read_only\": false
   }"

# start
curl --unix-socket /tmp/firecracker.socket -i \
  -X PUT 'http://localhost/actions'       \
  -H  'Accept: application/json'          \
  -H  'Content-Type: application/json'    \
  -d '{
      "action_type": "InstanceStart"
   }'

Running the above script as sudo produces the following:

$ sudo ./start.sh

HTTP/1.1 204
Server: Firecracker API
Connection: keep-alive

HTTP/1.1 204
Server: Firecracker API
Connection: keep-alive

HTTP/1.1 204
Server: Firecracker API
Connection: keep-alive

After that, the Firecracker instance in the other terminal still hasn't done anything.

Expected behaviour

I expect to see a login prompt.

Environment

Firecracker Version

I tried out both v1.2.0 and main (currently at 81e771a), neither worked for me.

Guest Version Info

I can't say for certain what version the guest kernel is using (since I cannot get it booted), but it is the same kernel used in the docs:

https://s3.amazonaws.com/spec.ccfc.min/img/quickstart_guide/x86_64/kernels/vmlinux.bin

Same goes for the rootfs:

https://s3.amazonaws.com/spec.ccfc.min/img/quickstart_guide/x86_64/rootfs/bionic.rootfs.ext4

Host Version Info

OS Info:

$ uname -a
Linux archer 6.1.9-arch1-1 #1 SMP PREEMPT_DYNAMIC Wed, 01 Feb 2023 17:07:39 +0000 x86_64 GNU/Linux

$ head -n 2 /etc/os-release
NAME="Arch Linux"
PRETTY_NAME="Arch Linux"

CPU info:

$ cat /proc/cpuinfo
processor       : 0
vendor_id       : AuthenticAMD
cpu family      : 21
model           : 2
model name      : AMD FX(tm)-8350 Eight-Core Processor
stepping        : 0
microcode       : 0x6000822
cpu MHz         : 4140.525
cache size      : 2048 KB
physical id     : 0
siblings        : 8
core id         : 0
cpu cores       : 4
apicid          : 16
initial apicid  : 0
fpu             : yes
fpu_exception   : yes
cpuid level     : 13
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm constant_tsc rep_good nopl nonstop_tsc cpuid extd_apicid aperfmperf pni pclmulqdq monitor ssse3 fma cx16 sse4_1 sse4_2 popcnt aes xsave avx f16c lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs xop skinit wdt lwp fma4 tce nodeid_msr tbm topoext perfctr_core perfctr_nb cpb hw_pstate ssbd vmmcall bmi1 arat npt lbrv svm_lock nrip_save tsc_scale vmcb_clean flushbyasid decodeassists pausefilter pfthreshold
bugs            : fxsave_leak sysret_ss_attrs null_seg spectre_v1 spectre_v2 spec_store_bypass retbleed
bogomips        : 8003.76
TLB size        : 1536 4K pages
clflush size    : 64
cache_alignment : 64
address sizes   : 48 bits physical, 48 bits virtual
power management: ts ttp tm 100mhzsteps hwpstate cpb eff_freq_ro

<snip>

KVM/Virtio related kernel modules:

$ lsmod | grep "^\S*\(kvm\|virtio\)"
kvmgt                 434176  0
vmw_vsock_virtio_transport    20480  0
vmw_vsock_virtio_transport_common    49152  1 vmw_vsock_virtio_transport
virtio_vdpa            16384  0
virtio_snd             40960  0
virtio_scsi            28672  0
virtio_rpmsg_bus       28672  0
virtio_rng             16384  0
virtio_pmem            16384  0
virtio_pci             24576  0
virtio_pci_legacy_dev    16384  1 virtio_pci
virtio_pci_modern_dev    20480  1 virtio_pci
virtio_net             77824  0
virtio_mmio            16384  0
virtio_mem             45056  0
virtio_iommu           28672  0
virtio_input           16384  0
virtio_gpu             86016  0
virtiofs               32768  0
virtio_dma_buf         16384  1 virtio_gpu
virtio_crypto          45056  0
virtio_console         45056  0
virtio_bt              16384  0
virtio_blk             28672  0
virtio_balloon         24576  0
nd_virtio              16384  1 virtio_pmem
i2c_virtio             16384  0
gpio_virtio            24576  0
9pnet_virtio           20480  0
kvm_amd               176128  1
kvm                  1146880  2 kvm_amd,kvmgt

I loaded every KVM/Virtio kernel module available on my system to see if that would fix anything to no avail.

Additional context

This issue is currently keeping me from using Firecracker on my dev machine. My inclination tells me that this is a KVM related issue (either with my host machine or in the way Firecracker is interfacing with the KVM), though I can't say for certain.

Things I have tried to do to fix/diagnose the issue:

I've done everything I can think of to diagnose it, but I still don't know what the issue might be, if it is something with my setup, or something with Firecracker itself I can't say. I don't see any crashes or error messages or anything which I find odd, it just isn't doing anything.

Checks

zulinx86 commented 1 year ago

Hello, thanks for opening an issue.

I cannot reproduce the issue on my side with the reproduction steps, so I'd like more information. Could you give me a strace result (strace.txt with the following command)?

$ sudo starce -f -o strace.txt \
  ./firecracker \
  --api-sock /tmp/firecracker.socket \
  --level Debug \
  --log-path /tmp/firelog \
  --show-level \
  --show-log-origin

Thanks,

dosisod commented 1 year ago

Here is the contents of strace.txt (using version v1.2.0 from the release page):

Click to expand

```txt 373207 execve("./firecracker", ["./firecracker", "--api-sock", "/tmp/firecracker.socket", "--level", "Debug", "--log-path", "/tmp/firelog", "--show-level", "--show-log-origin"], 0x7ffc0eda09c8 /* 15 vars */) = 0 373207 mmap(NULL, 392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f580b059000 373207 arch_prctl(ARCH_SET_FS, 0x7f580b0590a8) = 0 373207 set_tid_address(0x81b7d8) = 373207 373207 poll([{fd=0, events=0}, {fd=1, events=0}, {fd=2, events=0}], 3, 0) = 0 (Timeout) 373207 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x5acb3b}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 373207 rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 373207 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 373207 rt_sigaction(SIGSEGV, {sa_handler=0x4d2a40, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 373207 rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 373207 rt_sigaction(SIGBUS, {sa_handler=0x4d2a40, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 373207 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 373207 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f580b056000 373207 mprotect(0x7f580b056000, 4096, PROT_NONE) = 0 373207 sigaltstack({ss_sp=0x7f580b057000, ss_flags=0, ss_size=8192}, NULL) = 0 373207 brk(NULL) = 0x1189000 373207 brk(0x118a000) = 0x118a000 373207 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 373207 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 373207 rt_sigaction(SIGSYS, {sa_handler=0x533540, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 373207 rt_sigaction(SIGBUS, {sa_handler=0x533b00, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 373207 rt_sigaction(SIGSEGV, {sa_handler=0x534100, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 373207 rt_sigaction(SIGXFSZ, {sa_handler=0x534700, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 373207 rt_sigaction(SIGXCPU, {sa_handler=0x534d00, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 373207 rt_sigaction(SIGPIPE, {sa_handler=0x535300, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 373207 rt_sigaction(SIGHUP, {sa_handler=0x535580, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 373207 rt_sigaction(SIGILL, {sa_handler=0x535b80, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 373207 brk(0x118d000) = 0x118d000 373207 open("/tmp/firelog", O_RDWR|O_NONBLOCK|O_CLOEXEC) = 3 373207 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 373207 write(3, "Running Firecracker v1.2.0\n", 27) = 27 373207 getrandom("\x76\x6a\xe3\x34\xb5\x95\xa4\x43\xb1\x4b\x7d\x3b\x5f\x70\x3b\xeb", 16, GRND_INSECURE) = 16 373207 brk(0x118e000) = 0x118e000 373207 brk(0x118f000) = 0x118f000 373207 eventfd2(0, 0) = 4 373207 dup(4) = 5 373207 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 373207 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f580ae53000 373207 mprotect(0x7f580ae55000, 2101248, PROT_READ|PROT_WRITE) = 0 373207 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 373207 clone(child_stack=0x7f580b055a48, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[373208], tls=0x7f580b055b20, child_tidptr=0x81b7d8) = 373208 373207 rt_sigprocmask(SIG_SETMASK, [], 373208 rt_sigprocmask(SIG_SETMASK, [], 373207 <... rt_sigprocmask resumed>NULL, 8) = 0 373207 epoll_create1(EPOLL_CLOEXEC) = 6 373207 brk(0x1190000 373208 <... rt_sigprocmask resumed>NULL, 8) = 0 373207 <... brk resumed>) = 0x1190000 373208 sigaltstack(NULL, 373207 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK 373208 <... sigaltstack resumed>{ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 373207 <... timerfd_create resumed>) = 7 373208 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0 373207 epoll_ctl(6, EPOLL_CTL_ADD, 7, {events=EPOLLIN, data={u32=7, u64=7}} 373208 <... mmap resumed>) = 0x7f580ae50000 373207 <... epoll_ctl resumed>) = 0 373208 mprotect(0x7f580ae50000, 4096, PROT_NONE 373207 futex(0x1189068, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 373208 <... mprotect resumed>) = 0 373208 sigaltstack({ss_sp=0x7f580ae51000, ss_flags=0, ss_size=8192}, NULL) = 0 373208 prctl(PR_SET_NAME, "fc_api") = 0 373208 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 8 373208 bind(8, {sa_family=AF_UNIX, sun_path="/tmp/firecracker.socket"}, 26) = 0 373208 listen(8, 128) = 0 373208 epoll_create1(EPOLL_CLOEXEC) = 9 373208 getrandom("\xc0\x73\xf0\xe2\x38\x57\x67\x16\x01\x34\x1c\xdf\x32\xc1\x38\x96", 16, GRND_INSECURE) = 16 373208 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0) = 0 373208 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=182, filter=0x118d800}) = 0 373208 epoll_ctl(9, EPOLL_CTL_ADD, 8, {events=EPOLLIN|EPOLLRDHUP, data={u32=8, u64=8}}) = 0 373208 epoll_pwait(9, [{events=EPOLLIN, data={u32=8, u64=8}}], 10, -1, NULL, 8) = 1 373208 accept4(8, {sa_family=AF_UNIX}, [110 => 2], SOCK_CLOEXEC) = 10 373208 ioctl(10, FIONBIO, [1]) = 0 373208 epoll_ctl(9, EPOLL_CTL_ADD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 373208 brk(0x1191000) = 0x1191000 373208 brk(0x1193000) = 0x1193000 373208 epoll_pwait(9, [{events=EPOLLIN, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 373208 recvmsg(10, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PUT /boot-source HTTP/1.1\r\nHost:"..., iov_len=1024}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 296 373208 open("/etc/localtime", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = 11 373208 fstat(11, {st_mode=S_IFREG|0644, st_size=2852, ...}) = 0 373208 mmap(NULL, 2852, PROT_READ, MAP_SHARED, 11, 0) = 0x7f580ae49000 373208 close(11) = 0 373208 write(3, "2023-02-08T20:05:28.889047591 [a"..., 331) = 331 373208 futex(0x1189068, FUTEX_WAKE_PRIVATE, 1 373207 <... futex resumed>) = 0 373208 <... futex resumed>) = 1 373207 read(4, 373208 write(5, "\1\0\0\0\0\0\0\0", 8 373207 <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8 373208 <... write resumed>) = 8 373207 open("/home/loot/code/firecracker/hello-vmlinux.bin", O_RDONLY|O_CLOEXEC 373208 futex(0x118e808, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 373207 <... open resumed>) = 11 373207 fcntl(11, F_SETFD, FD_CLOEXEC) = 0 373207 futex(0x118e808, FUTEX_WAKE_PRIVATE, 1) = 1 373208 <... futex resumed>) = 0 373207 futex(0x1189068, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 373208 write(3, "2023-02-08T20:05:28.889926455 [a"..., 172) = 172 373208 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLOUT|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 373208 write(3, "2023-02-08T20:05:28.890091431 [a"..., 137) = 137 373208 epoll_pwait(9, [{events=EPOLLOUT, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 373208 write(10, "HTTP/1.1 204 \r\nServer: Firecrack"..., 66) = 66 373208 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 373208 epoll_pwait(9, [{events=EPOLLIN|EPOLLHUP|EPOLLRDHUP, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 373208 epoll_ctl(9, EPOLL_CTL_DEL, 10, 0x7f580b055150) = 0 373208 close(10) = 0 373208 epoll_pwait(9, [{events=EPOLLIN, data={u32=8, u64=8}}], 10, -1, NULL, 8) = 1 373208 accept4(8, {sa_family=AF_UNIX}, [110 => 2], SOCK_CLOEXEC) = 10 373208 ioctl(10, FIONBIO, [1]) = 0 373208 epoll_ctl(9, EPOLL_CTL_ADD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 373208 epoll_pwait(9, [{events=EPOLLIN, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 373208 recvmsg(10, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PUT /drives/rootfs HTTP/1.1\r\nHos"..., iov_len=1024}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 323 373208 write(3, "2023-02-08T20:05:28.904788589 [a"..., 364) = 364 373208 futex(0x1189068, FUTEX_WAKE_PRIVATE, 1) = 1 373208 write(5, "\1\0\0\0\0\0\0\0", 8 373207 <... futex resumed>) = 0 373208 <... write resumed>) = 8 373207 read(4, 373208 futex(0x118e808, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 373207 <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8 373207 stat("/home/loot/code/firecracker/hello-rootfs.ext4", {st_mode=S_IFREG|0644, st_size=314572800, ...}) = 0 373207 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 12 373207 open("/home/loot/code/firecracker/hello-rootfs.ext4", O_RDWR|O_CLOEXEC) = 13 373207 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 373207 lseek(13, 0, SEEK_END) = 314572800 373207 fstat(13, {st_mode=S_IFREG|0644, st_size=314572800, ...}) = 0 373207 eventfd2(0, EFD_NONBLOCK) = 14 373207 eventfd2(0, EFD_NONBLOCK) = 15 373207 eventfd2(0, EFD_NONBLOCK) = 16 373207 futex(0x118e808, FUTEX_WAKE_PRIVATE, 1) = 1 373208 <... futex resumed>) = 0 373207 futex(0x1189068, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 373208 write(3, "2023-02-08T20:05:28.906205655 [a"..., 172) = 172 373208 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLOUT|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 373208 write(3, "2023-02-08T20:05:28.906358517 [a"..., 137) = 137 373208 epoll_pwait(9, [{events=EPOLLOUT, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 373208 write(10, "HTTP/1.1 204 \r\nServer: Firecrack"..., 66) = 66 373208 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 373208 epoll_pwait(9, [{events=EPOLLIN|EPOLLHUP|EPOLLRDHUP, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 373208 epoll_ctl(9, EPOLL_CTL_DEL, 10, 0x7f580b055150) = 0 373208 close(10) = 0 373208 epoll_pwait(9, [{events=EPOLLIN, data={u32=8, u64=8}}], 10, -1, NULL, 8) = 1 373208 accept4(8, {sa_family=AF_UNIX}, [110 => 2], SOCK_CLOEXEC) = 10 373208 ioctl(10, FIONBIO, [1]) = 0 373208 epoll_ctl(9, EPOLL_CTL_ADD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 373208 epoll_pwait(9, [{events=EPOLLIN, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 373208 recvmsg(10, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PUT /actions HTTP/1.1\r\nHost: loc"..., iov_len=1024}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 188 373208 write(3, "2023-02-08T20:05:28.913189658 [a"..., 219) = 219 373208 futex(0x1189068, FUTEX_WAKE_PRIVATE, 1 373207 <... futex resumed>) = 0 373208 <... futex resumed>) = 1 373207 read(4, 373208 write(5, "\1\0\0\0\0\0\0\0", 8) = 8 373208 futex(0x118e808, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 373207 <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8 373207 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=2752111}) = 0 373207 mmap(NULL, 134225920, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f5802e47000 373207 mmap(0x7f5802e48000, 134217728, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f5802e48000 373207 fcntl(11, F_DUPFD_CLOEXEC, 0) = 17 373207 fcntl(17, F_SETFD, FD_CLOEXEC) = 0 373207 lseek(17, 0, SEEK_SET) = 0 373207 read(17, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\2\0>\0\1\0\0\0\0\0\0\1\0\0\0\0"..., 64) = 64 373207 lseek(17, 64, SEEK_SET) = 64 373207 read(17, "\1\0\0\0\5\0\0\0\0\0 \0\0\0\0\0\0\0\0\201\377\377\377\377\0\0\0\1\0\0\0\0"..., 56) = 56 373207 read(17, "\1\0\0\0\6\0\0\0\0\0\340\0\0\0\0\0\0\0\300\201\377\377\377\377\0\0\300\1\0\0\0\0"..., 56) = 56 373207 read(17, "\1\0\0\0\6\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\313\1\0\0\0\0"..., 56) = 56 373207 read(17, "\1\0\0\0\7\0\0\0\0\0\r\1\0\0\0\0\0\0\315\201\377\377\377\377\0\0\315\1\0\0\0\0"..., 56) = 56 373207 read(17, "\4\0\0\0\0\0\0\0\3241\240\0\0\0\0\0\3241\200\201\377\377\377\377\3241\200\1\0\0\0\0"..., 56) = 56 373207 lseek(17, 2097152, SEEK_SET) = 2097152 373207 read(17, "H\215%Q?\300\0\350\324\0\0\0H\215=\355\377\377\377V\350\327\1\0\0^H\5\0\200\320\1"..., 12001280) = 12001280 373207 lseek(17, 14680064, SEEK_SET) = 14680064 373207 read(17, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 720896) = 720896 373207 lseek(17, 16777216, SEEK_SET) = 16777216 373207 read(17, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128600) = 128600 373207 lseek(17, 17629184, SEEK_SET) = 17629184 373207 read(17, "j\0j\0\351\27\1\0\0j\0j\1\351\16\1\0\0j\0j\2\351\5\1\0\0j\0j\3\351"..., 1257472) = 1257472 373207 lseek(17, 10498516, SEEK_SET) = 10498516 373207 read(17, "\4\0\0\0\24\0\0\0\3\0\0\0", 12) = 12 373207 lseek(17, 10498552, SEEK_SET) = 10498552 373207 close(17) = 0 373207 open("/dev/kvm", O_RDWR|O_CLOEXEC) = 17 373207 fcntl(17, F_SETFD, FD_CLOEXEC) = 0 373207 ioctl(17, KVM_GET_API_VERSION, 0) = 12 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_IRQCHIP) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_IOEVENTFD) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_IRQFD) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_USER_MEMORY) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_SET_TSS_ADDR) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_PIT2) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_PIT_STATE2) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_ADJUST_CLOCK) = 14 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_DEBUGREGS) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_MP_STATE) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_VCPU_EVENTS) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_XCRS) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_XSAVE) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_EXT_CPUID) = 1 373207 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_NR_MEMSLOTS) = 32764 373207 ioctl(17, KVM_CREATE_VM, 0) = 18 373207 ioctl(17, KVM_GET_VCPU_MMAP_SIZE, 0) = 12288 373207 brk(0x1194000) = 0x1194000 373207 ioctl(17, KVM_GET_SUPPORTED_CPUID, {nent=56, entries=[...]}) = 0 373207 ioctl(17, KVM_GET_MSR_INDEX_LIST, 0x11933e0) = 0 373207 ioctl(18, KVM_SET_USER_MEMORY_REGION, {slot=0, flags=0, guest_phys_addr=0, memory_size=134217728, userspace_addr=0x7f5802e48000}) = 0 373207 ioctl(18, KVM_SET_TSS_ADDR, 0xfffbd000) = 0 373207 close(17) = 0 373207 eventfd2(0, EFD_NONBLOCK) = 17 373207 ioctl(18, KVM_CREATE_IRQCHIP, 0) = 0 373207 ioctl(18, KVM_CREATE_PIT2, 0x7ffda2e63cb8) = 0 373207 dup(17) = 19 373207 ioctl(18, KVM_CREATE_VCPU, 0) = 20 373207 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_SHARED, 20, 0) = 0x7f5802e41000 373207 fcntl(1, F_GETFL) = 0x2 (flags O_RDWR) 373207 fcntl(1, F_SETFL, O_RDWR|O_NONBLOCK) = 0 373207 eventfd2(0, EFD_NONBLOCK) = 21 373207 eventfd2(0, EFD_NONBLOCK) = 22 373207 epoll_ctl(6, EPOLL_CTL_ADD, 0, {events=EPOLLIN, data={u32=0, u64=0}}) = 0 373207 epoll_ctl(6, EPOLL_CTL_ADD, 22, {events=EPOLLIN, data={u32=22, u64=22}}) = 0 373207 dup(17) = 23 373207 dup(21) = 24 373207 eventfd2(0, EFD_NONBLOCK) = 25 373207 eventfd2(0, EFD_NONBLOCK) = 26 373207 dup(26) = 27 373207 dup(25) = 28 373207 dup(28) = 29 373207 close(28) = 0 373207 dup(24) = 28 373207 dup(28) = 30 373207 close(28) = 0 373207 ioctl(18, KVM_IRQFD, 0x7ffda2e63c30) = 0 373207 ioctl(18, KVM_IRQFD, 0x7ffda2e63c30) = 0 373207 ioctl(18, KVM_IRQFD, 0x7ffda2e63c30) = 0 373207 epoll_ctl(6, EPOLL_CTL_ADD, 16, {events=EPOLLIN, data={u32=16, u64=16}}) = 0 373207 ioctl(18, KVM_IOEVENTFD, 0x7ffda2e63d00) = 0 373207 ioctl(18, KVM_IRQFD, 0x7ffda2e63c50) = 0 373207 brk(0x1195000) = 0x1195000 373207 brk(0x1197000) = 0x1197000 373207 ioctl(20, KVM_SET_CPUID2, {nent=54, entries=[...]}) = 0 373207 ioctl(20, KVM_SET_MSRS, 0x1194300) = 10 373207 ioctl(20, KVM_SET_REGS, {rax=0, ..., rsp=0x8ff0, rbp=0x8ff0, ..., rip=0x1000000, rflags=0x2}) = 0 373207 ioctl(20, KVM_SET_FPU, 0x7ffda2e63060) = 0 373207 ioctl(20, KVM_GET_SREGS, {cs={base=0xffff0000, limit=65535, selector=61440, type=10, present=1, dpl=0, db=0, s=1, l=0, g=0, avl=0}, ...}) = 0 373207 ioctl(20, KVM_SET_SREGS, {cs={base=0, limit=1048575, selector=8, type=11, present=1, dpl=0, db=0, s=1, l=1, g=1, avl=0}, ...}) = 0 373207 ioctl(20, KVM_GET_LAPIC, 0x7ffda2e62180) = 0 373207 ioctl(20, KVM_SET_LAPIC, 0x7ffda2e62580) = 0 373207 ioctl(0, TIOCGWINSZ, {ws_row=52, ws_col=212, ws_xpixel=1908, ws_ypixel=1040}) = 0 373207 ioctl(0, TCGETS, {c_iflag=ICRNL, c_oflag=NL0|CR0|TAB0|BS0|VT0|FF0|OPOST|ONLCR, c_cflag=B38400|CS8|CREAD, c_lflag=ISIG|ICANON|ECHO|ECHOE|ECHOK|IEXTEN|ECHOCTL|ECHOKE, ...}) = 0 373207 ioctl(0, SNDCTL_TMR_START or TCSETS, {c_iflag=ICRNL, c_oflag=NL0|CR0|TAB0|BS0|VT0|FF0|OPOST|ONLCR, c_cflag=B38400|CS8|CREAD, c_lflag=ECHOE|ECHOK|IEXTEN|ECHOCTL|ECHOKE, ...}) = 0 373207 fcntl(0, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) 373207 rt_sigaction(SIGRT_3, {sa_handler=0x50d6e0, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 373207 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5802c3e000 373207 mprotect(0x7f5802c40000, 2101248, PROT_READ|PROT_WRITE) = 0 373207 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 373207 clone(child_stack=0x7f5802e40a48, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[373533], tls=0x7f5802e40b20, child_tidptr=0x81b7d8) = 373533 373207 rt_sigprocmask(SIG_SETMASK, [], 373533 rt_sigprocmask(SIG_SETMASK, [], 373207 <... rt_sigprocmask resumed>NULL, 8) = 0 373533 <... rt_sigprocmask resumed>NULL, 8) = 0 373207 futex(0x1193cd0, FUTEX_WAIT_BITSET_PRIVATE, 0, NULL, FUTEX_BITSET_MATCH_ANY 373533 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 373533 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f580ae4d000 373533 mprotect(0x7f580ae4d000, 4096, PROT_NONE) = 0 373533 sigaltstack({ss_sp=0x7f580ae4e000, ss_flags=0, ss_size=8192}, NULL) = 0 373533 prctl(PR_SET_NAME, "fc_vcpu 0") = 0 373533 futex(0x1193cd0, FUTEX_WAKE_PRIVATE, 2147483647 373207 <... futex resumed>) = 0 373533 <... futex resumed>) = 1 373207 futex(0x1193cb0, FUTEX_WAIT_BITSET_PRIVATE, 2, NULL, FUTEX_BITSET_MATCH_ANY 373533 futex(0x1193cb0, FUTEX_WAKE_PRIVATE, 1 373207 <... futex resumed>) = -1 EAGAIN (Resource temporarily unavailable) 373533 <... futex resumed>) = 0 373207 futex(0x1193cb0, FUTEX_WAKE_PRIVATE, 1 373533 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0 373207 <... futex resumed>) = 0 373533 <... prctl resumed>) = 0 373207 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0 373533 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=254, filter=0x118ddc0} 373207 <... prctl resumed>) = 0 373207 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=286, filter=0x118cf00}) = 0 373533 <... prctl resumed>) = 0 373207 write(3, "2023-02-08T20:05:28.991391247 [a"..., 127) = 127 373533 futex(0x1194548, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 373207 futex(0x1194548, FUTEX_WAKE_PRIVATE, 1 373533 <... futex resumed>) = -1 EAGAIN (Resource temporarily unavailable) 373207 <... futex resumed>) = 0 373207 tkill(373533, SIGRT_3 373533 ioctl(20, KVM_RUN 373207 <... tkill resumed>) = 0 373207 epoll_ctl(6, EPOLL_CTL_ADD, 17, {events=EPOLLIN, data={u32=17, u64=17}}) = 0 373207 futex(0x118e808, FUTEX_WAKE_PRIVATE, 1 373533 <... ioctl resumed>, 0) = -1 EINTR (Interrupted system call) 373207 <... futex resumed>) = 1 373208 <... futex resumed>) = 0 373207 timerfd_settime(7, 0, {it_interval={tv_sec=60, tv_nsec=0}, it_value={tv_sec=60, tv_nsec=0}}, 373533 --- SIGRT_3 {si_signo=SIGRT_3, si_code=SI_TKILL, si_pid=373207, si_uid=0} --- 373207 <... timerfd_settime resumed>{it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}}) = 0 373208 write(3, "2023-02-08T20:05:28.991879719 [a"..., 172 373207 epoll_ctl(6, EPOLL_CTL_ADD, 4, {events=EPOLLIN, data={u32=4, u64=4}} 373533 rt_sigreturn({mask=[]} 373207 <... epoll_ctl resumed>) = 0 373208 <... write resumed>) = 172 373207 epoll_pwait(6, 373533 <... rt_sigreturn resumed>) = -1 EINTR (Interrupted system call) 373208 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLOUT|EPOLLRDHUP, data={u32=10, u64=10}} 373533 ioctl(20, KVM_RUN 373208 <... epoll_ctl resumed>) = 0 373208 write(3, "2023-02-08T20:05:28.992201201 [a"..., 138) = 138 373208 epoll_pwait(9, [{events=EPOLLOUT, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 373208 write(10, "HTTP/1.1 204 \r\nServer: Firecrack"..., 66) = 66 373208 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 373208 epoll_pwait(9, [{events=EPOLLIN|EPOLLHUP|EPOLLRDHUP, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 373208 epoll_ctl(9, EPOLL_CTL_DEL, 10, 0x7f580b055150) = 0 373208 close(10) = 0 373208 epoll_pwait(9, 373207 <... epoll_pwait resumed>0x118e920, 256, -1, NULL, 8) = -1 EINTR (Interrupted system call) 373207 --- SIGTERM {si_signo=SIGTERM, si_code=SI_USER, si_pid=373835, si_uid=0} --- 373208 <... epoll_pwait resumed> ) = ? 373533 <... ioctl resumed> ) = ? 373533 +++ killed by SIGTERM +++ 373208 +++ killed by SIGTERM +++ 373207 +++ killed by SIGTERM +++ ```

And here are the accompanying logs from /tmp/firelog for reference:

Running Firecracker v1.2.0
2023-02-08T20:05:28.889047591 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:216] The API server received a Put request on "/boot-source" with body "{\n        \"kernel_image_path\": \"/home/loot/code/firecracker/hello-vmlinux.bin\",\n        \"boot_args\": \"console=ttyS0 reboot=k panic=1 pci=off\"\n   }".
2023-02-08T20:05:28.889926455 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:163] The request was executed successfully. Status code: 204 No Content.
2023-02-08T20:05:28.890091431 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:211] Total previous API call duration: 1055 us.
2023-02-08T20:05:28.904788589 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:216] The API server received a Put request on "/drives/rootfs" with body "{\n        \"drive_id\": \"rootfs\",\n        \"path_on_host\": \"/home/loot/code/firecracker/hello-rootfs.ext4\",\n        \"is_root_device\": true,\n        \"is_read_only\": false\n   }".
2023-02-08T20:05:28.906205655 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:163] The request was executed successfully. Status code: 204 No Content.
2023-02-08T20:05:28.906358517 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:211] Total previous API call duration: 1578 us.
2023-02-08T20:05:28.913189658 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:216] The API server received a Put request on "/actions" with body "{\n      \"action_type\": \"InstanceStart\"\n   }".
2023-02-08T20:05:28.991391247 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:408] Artificially kick devices.
2023-02-08T20:05:28.991879719 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:163] The request was executed successfully. Status code: 204 No Content.
2023-02-08T20:05:28.992201201 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:211] Total previous API call duration: 79015 us.

I ran it using the same procedure as above, and after about 30 seconds I killed it.

Thank you for the response, hopefully this info is helpful!

zulinx86 commented 1 year ago

Thanks for giving logs quickly!

As far as I see your strace log, it reached KVM_RUN call and appears to start a guest VM. Please give me more time to dive deep into this.

Let me share a log on my side:

Click to expand ```txt 12493 execve("./firecracker", ["./firecracker", "--api-sock", "/tmp/firecracker.socket", "--level", "Debug", "--log-path", "/tmp/firelog", "--show-level", "--show-log-origin"], 0x7ffc934d3d38 /* 17 vars */) = 0 12493 mmap(NULL, 392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2ed03e6000 12493 arch_prctl(ARCH_SET_FS, 0x7f2ed03e60a8) = 0 12493 set_tid_address(0x81b7d8) = 12493 12493 poll([{fd=0, events=0}, {fd=1, events=0}, {fd=2, events=0}], 3, 0) = 0 (Timeout) 12493 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x5acb3b}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 12493 rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 12493 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 12493 rt_sigaction(SIGSEGV, {sa_handler=0x4d2a40, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 12493 rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 12493 rt_sigaction(SIGBUS, {sa_handler=0x4d2a40, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 12493 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 12493 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f2ed03e3000 12493 mprotect(0x7f2ed03e3000, 4096, PROT_NONE) = 0 12493 sigaltstack({ss_sp=0x7f2ed03e4000, ss_flags=0, ss_size=8192}, NULL) = 0 12493 brk(NULL) = 0x9f4000 12493 brk(0x9f5000) = 0x9f5000 12493 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 12493 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 12493 rt_sigaction(SIGSYS, {sa_handler=0x533540, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 12493 rt_sigaction(SIGBUS, {sa_handler=0x533b00, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 12493 rt_sigaction(SIGSEGV, {sa_handler=0x534100, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 12493 rt_sigaction(SIGXFSZ, {sa_handler=0x534700, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 12493 rt_sigaction(SIGXCPU, {sa_handler=0x534d00, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 12493 rt_sigaction(SIGPIPE, {sa_handler=0x535300, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 12493 rt_sigaction(SIGHUP, {sa_handler=0x535580, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 12493 rt_sigaction(SIGILL, {sa_handler=0x535b80, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 12493 brk(0x9f8000) = 0x9f8000 12493 open("/tmp/firelog", O_RDWR|O_NONBLOCK|O_CLOEXEC) = 3 12493 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 12493 write(3, "Running Firecracker v1.2.0\n", 27) = 27 12493 getrandom("\x6e\x94\x6d\xac\x73\xb7\xc4\x69\xba\x53\x40\x3f\x59\x1e\xea\xd5", 16, 0x4 /* GRND_??? */) = 16 12493 brk(0x9f9000) = 0x9f9000 12493 brk(0x9fa000) = 0x9fa000 12493 eventfd2(0, 0) = 4 12493 dup(4) = 5 12493 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 12493 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2ed01e0000 12493 mprotect(0x7f2ed01e2000, 2101248, PROT_READ|PROT_WRITE) = 0 12493 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 12493 clone(child_stack=0x7f2ed03e2a48, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tidptr=0x7f2ed03e2b58, tls=0x7f2ed03e2b20, child_tidptr=0x81b7d8) = 12494 12493 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 12494 rt_sigprocmask(SIG_SETMASK, [], 12493 epoll_create1(EPOLL_CLOEXEC) = 6 12494 <... rt_sigprocmask resumed> NULL, 8) = 0 12493 brk(0x9fb000 12494 sigaltstack(NULL, 12493 <... brk resumed> ) = 0x9fb000 12494 <... sigaltstack resumed> {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 12493 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK 12494 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0 12493 <... timerfd_create resumed> ) = 7 12493 epoll_ctl(6, EPOLL_CTL_ADD, 7, {EPOLLIN, {u32=7, u64=7}} 12494 <... mmap resumed> ) = 0x7f2ed01dd000 12493 <... epoll_ctl resumed> ) = 0 12494 mprotect(0x7f2ed01dd000, 4096, PROT_NONE) = 0 12493 futex(0x9f4068, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 12494 sigaltstack({ss_sp=0x7f2ed01de000, ss_flags=0, ss_size=8192}, NULL) = 0 12494 prctl(PR_SET_NAME, "fc_api") = 0 12494 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 8 12494 bind(8, {sa_family=AF_UNIX, sun_path="/tmp/firecracker.socket"}, 26) = 0 12494 listen(8, 128) = 0 12494 epoll_create1(EPOLL_CLOEXEC) = 9 12494 getrandom("\xe4\xb2\x5d\x36\x8a\xce\xcc\x75\xfd\x7e\x20\x04\x2d\xd4\x48\x63", 16, 0x4 /* GRND_??? */) = 16 12494 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0) = 0 12494 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=182, filter=0x9f8800}) = 0 12494 epoll_ctl(9, EPOLL_CTL_ADD, 8, {EPOLLIN|EPOLLRDHUP, {u32=8, u64=8}}) = 0 12494 epoll_pwait(9, 12493 <... futex resumed> ) = ? ERESTARTSYS (To be restarted if SA_RESTART is set) 12493 --- SIGWINCH {si_signo=SIGWINCH, si_code=SI_KERNEL} --- 12493 futex(0x9f4068, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 12494 <... epoll_pwait resumed> [{EPOLLIN, {u32=8, u64=8}}], 10, -1, NULL, 8) = 1 12494 accept4(8, {sa_family=AF_UNIX}, [110->2], SOCK_CLOEXEC) = 10 12494 ioctl(10, FIONBIO, [1]) = 0 12494 epoll_ctl(9, EPOLL_CTL_ADD, 10, {EPOLLIN|EPOLLRDHUP, {u32=10, u64=10}}) = 0 12494 epoll_pwait(9, 12493 <... futex resumed> ) = ? ERESTARTSYS (To be restarted if SA_RESTART is set) 12493 --- SIGWINCH {si_signo=SIGWINCH, si_code=SI_KERNEL} --- 12493 futex(0x9f4068, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 12494 <... epoll_pwait resumed> [{EPOLLIN, {u32=8, u64=8}}], 10, -1, NULL, 8) = 1 12494 accept4(8, {sa_family=AF_UNIX}, [110->2], SOCK_CLOEXEC) = 10 12494 ioctl(10, FIONBIO, [1]) = 0 12494 epoll_ctl(9, EPOLL_CTL_ADD, 10, {EPOLLIN|EPOLLRDHUP, {u32=10, u64=10}}) = 0 12494 brk(0x9fc000) = 0x9fc000 12494 brk(0x9fe000) = 0x9fe000 12494 epoll_pwait(9, [{EPOLLIN, {u32=10, u64=10}}], 10, -1, NULL, 8) = 1 12494 recvmsg(10, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PUT /boot-source HTTP/1.1\r\nHost:"..., iov_len=1024}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 283 12494 open("/etc/localtime", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = 11 12494 fstat(11, {st_mode=S_IFREG|0644, st_size=127, ...}) = 0 12494 mmap(NULL, 127, PROT_READ, MAP_SHARED, 11, 0) = 0x7f2ed01dc000 12494 close(11) = 0 12494 write(3, "2023-02-09T18:02:02.759235866 [a"..., 318) = 318 12494 futex(0x9f4068, FUTEX_WAKE_PRIVATE, 1) = 1 12494 write(5, "\1\0\0\0\0\0\0\0", 8) = 8 12493 <... futex resumed> ) = 0 12494 futex(0x9f9808, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 12493 read(4, "\1\0\0\0\0\0\0\0", 8) = 8 12493 open("/home/ec2-user/hello-vmlinux.bin", O_RDONLY|O_CLOEXEC) = 11 12493 fcntl(11, F_SETFD, FD_CLOEXEC) = 0 12493 futex(0x9f9808, FUTEX_WAKE_PRIVATE, 1) = 1 12494 <... futex resumed> ) = 0 12493 futex(0x9f4068, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 12494 write(3, "2023-02-09T18:02:02.760161026 [a"..., 172) = 172 12494 epoll_ctl(9, EPOLL_CTL_MOD, 10, {EPOLLOUT|EPOLLRDHUP, {u32=10, u64=10}}) = 0 12494 write(3, "2023-02-09T18:02:02.760198676 [a"..., 136) = 136 12494 epoll_pwait(9, [{EPOLLOUT, {u32=10, u64=10}}], 10, -1, NULL, 8) = 1 12494 write(10, "HTTP/1.1 204 \r\nServer: Firecrack"..., 66) = 66 12494 epoll_ctl(9, EPOLL_CTL_MOD, 10, {EPOLLIN|EPOLLRDHUP, {u32=10, u64=10}}) = 0 12494 epoll_pwait(9, [{EPOLLIN|EPOLLHUP|EPOLLRDHUP, {u32=10, u64=10}}], 10, -1, NULL, 8) = 1 12494 epoll_ctl(9, EPOLL_CTL_DEL, 10, 0x7f2ed03e2150) = 0 12494 close(10) = 0 12494 epoll_pwait(9, [{EPOLLIN, {u32=8, u64=8}}], 10, -1, NULL, 8) = 1 12494 accept4(8, {sa_family=AF_UNIX}, [110->2], SOCK_CLOEXEC) = 10 12494 ioctl(10, FIONBIO, [1]) = 0 12494 epoll_ctl(9, EPOLL_CTL_ADD, 10, {EPOLLIN|EPOLLRDHUP, {u32=10, u64=10}}) = 0 12494 epoll_pwait(9, [{EPOLLIN, {u32=10, u64=10}}], 10, -1, NULL, 8) = 1 12494 recvmsg(10, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PUT /drives/rootfs HTTP/1.1\r\nHos"..., iov_len=1024}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 310 12494 write(3, "2023-02-09T18:02:03.911623990 [a"..., 351) = 351 12494 futex(0x9f4068, FUTEX_WAKE_PRIVATE, 1) = 1 12494 write(5, "\1\0\0\0\0\0\0\0", 8) = 8 12493 <... futex resumed> ) = 0 12494 futex(0x9f9808, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 12493 read(4, "\1\0\0\0\0\0\0\0", 8) = 8 12493 stat("/home/ec2-user/hello-rootfs.ext4", {st_mode=S_IFREG|0664, st_size=314572800, ...}) = 0 12493 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 12 12493 open("/home/ec2-user/hello-rootfs.ext4", O_RDWR|O_CLOEXEC) = 13 12493 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 12493 lseek(13, 0, SEEK_END) = 314572800 12493 fstat(13, {st_mode=S_IFREG|0664, st_size=314572800, ...}) = 0 12493 eventfd2(0, EFD_NONBLOCK) = 14 12493 eventfd2(0, EFD_NONBLOCK) = 15 12493 eventfd2(0, EFD_NONBLOCK) = 16 12493 futex(0x9f9808, FUTEX_WAKE_PRIVATE, 1) = 1 12494 <... futex resumed> ) = 0 12493 futex(0x9f4068, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 12494 write(3, "2023-02-09T18:02:03.912070754 [a"..., 172) = 172 12494 epoll_ctl(9, EPOLL_CTL_MOD, 10, {EPOLLOUT|EPOLLRDHUP, {u32=10, u64=10}}) = 0 12494 write(3, "2023-02-09T18:02:03.912183785 [a"..., 136) = 136 12494 epoll_pwait(9, [{EPOLLOUT, {u32=10, u64=10}}], 10, -1, NULL, 8) = 1 12494 write(10, "HTTP/1.1 204 \r\nServer: Firecrack"..., 66) = 66 12494 epoll_ctl(9, EPOLL_CTL_MOD, 10, {EPOLLIN|EPOLLRDHUP, {u32=10, u64=10}}) = 0 12494 epoll_pwait(9, [{EPOLLIN|EPOLLHUP|EPOLLRDHUP, {u32=10, u64=10}}], 10, -1, NULL, 8) = 1 12494 epoll_ctl(9, EPOLL_CTL_DEL, 10, 0x7f2ed03e2150) = 0 12494 close(10) = 0 12494 epoll_pwait(9, [{EPOLLIN, {u32=8, u64=8}}], 10, -1, NULL, 8) = 1 12494 accept4(8, {sa_family=AF_UNIX}, [110->2], SOCK_CLOEXEC) = 10 12494 ioctl(10, FIONBIO, [1]) = 0 12494 epoll_ctl(9, EPOLL_CTL_ADD, 10, {EPOLLIN|EPOLLRDHUP, {u32=10, u64=10}}) = 0 12494 epoll_pwait(9, [{EPOLLIN, {u32=10, u64=10}}], 10, -1, NULL, 8) = 1 12494 recvmsg(10, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PUT /actions HTTP/1.1\r\nHost: loc"..., iov_len=1024}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 188 12494 write(3, "2023-02-09T18:02:48.598344735 [a"..., 219) = 219 12494 futex(0x9f4068, FUTEX_WAKE_PRIVATE, 1) = 1 12494 write(5, "\1\0\0\0\0\0\0\0", 8) = 8 12493 <... futex resumed> ) = 0 12494 futex(0x9f9808, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 12493 read(4, "\1\0\0\0\0\0\0\0", 8) = 8 12493 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=3035102}) = 0 12493 mmap(NULL, 134225920, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2ec81da000 12493 mmap(0x7f2ec81db000, 134217728, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7f2ec81db000 12493 fcntl(11, F_DUPFD_CLOEXEC, 0) = 17 12493 fcntl(17, F_SETFD, FD_CLOEXEC) = 0 12493 lseek(17, 0, SEEK_SET) = 0 12493 read(17, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\2\0>\0\1\0\0\0\0\0\0\1\0\0\0\0"..., 64) = 64 12493 lseek(17, 64, SEEK_SET) = 64 12493 read(17, "\1\0\0\0\5\0\0\0\0\0 \0\0\0\0\0\0\0\0\201\377\377\377\377\0\0\0\1\0\0\0\0"..., 56) = 56 12493 read(17, "\1\0\0\0\6\0\0\0\0\0\340\0\0\0\0\0\0\0\300\201\377\377\377\377\0\0\300\1\0\0\0\0"..., 56) = 56 12493 read(17, "\1\0\0\0\6\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\313\1\0\0\0\0"..., 56) = 56 12493 read(17, "\1\0\0\0\7\0\0\0\0\0\r\1\0\0\0\0\0\0\315\201\377\377\377\377\0\0\315\1\0\0\0\0"..., 56) = 56 12493 read(17, "\4\0\0\0\0\0\0\0\3241\240\0\0\0\0\0\3241\200\201\377\377\377\377\3241\200\1\0\0\0\0"..., 56) = 56 12493 lseek(17, 2097152, SEEK_SET) = 2097152 12493 read(17, "H\215%Q?\300\0\350\324\0\0\0H\215=\355\377\377\377V\350\327\1\0\0^H\5\0\200\320\1"..., 12001280) = 12001280 12493 lseek(17, 14680064, SEEK_SET) = 14680064 12493 read(17, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 720896) = 720896 12493 lseek(17, 16777216, SEEK_SET) = 16777216 12493 read(17, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128600) = 128600 12493 lseek(17, 17629184, SEEK_SET) = 17629184 12493 read(17, "j\0j\0\351\27\1\0\0j\0j\1\351\16\1\0\0j\0j\2\351\5\1\0\0j\0j\3\351"..., 1257472) = 1257472 12493 lseek(17, 10498516, SEEK_SET) = 10498516 12493 read(17, "\4\0\0\0\24\0\0\0\3\0\0\0", 12) = 12 12493 lseek(17, 10498552, SEEK_SET) = 10498552 12493 close(17) = 0 12493 open("/dev/kvm", O_RDWR|O_CLOEXEC) = 17 12493 fcntl(17, F_SETFD, FD_CLOEXEC) = 0 12493 ioctl(17, KVM_GET_API_VERSION, 0) = 12 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_IRQCHIP) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_IOEVENTFD) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_IRQFD) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_USER_MEMORY) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_SET_TSS_ADDR) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_PIT2) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_PIT_STATE2) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_ADJUST_CLOCK) = 2 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_DEBUGREGS) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_MP_STATE) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_VCPU_EVENTS) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_XCRS) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_XSAVE) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_EXT_CPUID) = 1 12493 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_NR_MEMSLOTS) = 509 12493 ioctl(17, KVM_CREATE_VM, 0) = 18 12493 ioctl(17, KVM_GET_VCPU_MMAP_SIZE, 0) = 12288 12493 brk(0x9ff000) = 0x9ff000 12493 ioctl(17, KVM_GET_SUPPORTED_CPUID, {nent=60, entries=[...]}) = 0 12493 ioctl(17, KVM_GET_MSR_INDEX_LIST, 0x9fe3e0) = 0 12493 ioctl(18, KVM_SET_USER_MEMORY_REGION, {slot=0, flags=0, guest_phys_addr=0, memory_size=134217728, userspace_addr=0x7f2ec81db000}) = 0 12493 ioctl(18, KVM_SET_TSS_ADDR, 0xfffbd000) = 0 12493 close(17) = 0 12493 eventfd2(0, EFD_NONBLOCK) = 17 12493 ioctl(18, KVM_CREATE_IRQCHIP, 0) = 0 12493 ioctl(18, KVM_CREATE_PIT2, 0x7ffd83d86678) = 0 12493 dup(17) = 19 12493 ioctl(18, KVM_CREATE_VCPU, 0) = 20 12493 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_SHARED, 20, 0) = 0x7f2ec81d7000 12493 fcntl(1, F_GETFL) = 0x8402 (flags O_RDWR|O_APPEND|O_LARGEFILE) 12493 fcntl(1, F_SETFL, O_RDWR|O_APPEND|O_NONBLOCK|O_LARGEFILE) = 0 12493 eventfd2(0, EFD_NONBLOCK) = 21 12493 eventfd2(0, EFD_NONBLOCK) = 22 12493 epoll_ctl(6, EPOLL_CTL_ADD, 0, {EPOLLIN, {u32=0, u64=0}}) = 0 12493 epoll_ctl(6, EPOLL_CTL_ADD, 22, {EPOLLIN, {u32=22, u64=22}}) = 0 12493 dup(17) = 23 12493 dup(21) = 24 12493 eventfd2(0, EFD_NONBLOCK) = 25 12493 eventfd2(0, EFD_NONBLOCK) = 26 12493 dup(26) = 27 12493 dup(25) = 28 12493 dup(28) = 29 12493 close(28) = 0 12493 dup(24) = 28 12493 dup(28) = 30 12493 close(28) = 0 12493 ioctl(18, KVM_IRQFD, 0x7ffd83d865f0) = 0 12493 ioctl(18, KVM_IRQFD, 0x7ffd83d865f0) = 0 12493 ioctl(18, KVM_IRQFD, 0x7ffd83d865f0) = 0 12493 epoll_ctl(6, EPOLL_CTL_ADD, 16, {EPOLLIN, {u32=16, u64=16}}) = 0 12493 ioctl(18, KVM_IOEVENTFD, 0x7ffd83d866c0) = 0 12493 ioctl(18, KVM_IRQFD, 0x7ffd83d86610) = 0 12493 brk(0xa00000) = 0xa00000 12493 brk(0xa02000) = 0xa02000 12493 ioctl(20, KVM_SET_CPUID2, {nent=56, entries=[...]}) = 0 12493 ioctl(20, KVM_SET_MSRS, 0x9ff300) = 10 12493 ioctl(20, KVM_SET_REGS, {rax=0, ..., rsp=0x8ff0, rbp=0x8ff0, ..., rip=0x1000000, rflags=0x2}) = 0 12493 ioctl(20, KVM_SET_FPU, 0x7ffd83d85a20) = 0 12493 ioctl(20, KVM_GET_SREGS, {cs={base=0xffff0000, limit=65535, selector=61440, type=10, present=1, dpl=0, db=0, s=1, l=0, g=0, avl=0}, ...}) = 0 12493 ioctl(20, KVM_SET_SREGS, {cs={base=0, limit=1048575, selector=8, type=11, present=1, dpl=0, db=0, s=1, l=1, g=1, avl=0}, ...}) = 0 12493 ioctl(20, KVM_GET_LAPIC, 0x7ffd83d84b40) = 0 12493 ioctl(20, KVM_SET_LAPIC, 0x7ffd83d84f40) = 0 12493 ioctl(0, TIOCGWINSZ, {ws_row=79, ws_col=181, ws_xpixel=2534, ws_ypixel=2686}) = 0 12493 ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0 12493 ioctl(0, SNDCTL_TMR_START or TCSETS, {B38400 opost -isig -icanon -echo ...}) = 0 12493 fcntl(0, F_GETFL) = 0x8c02 (flags O_RDWR|O_APPEND|O_NONBLOCK|O_LARGEFILE) 12493 rt_sigaction(SIGRT_3, {sa_handler=0x50d6e0, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 12493 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2ec7fd4000 12493 mprotect(0x7f2ec7fd6000, 2101248, PROT_READ|PROT_WRITE) = 0 12493 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 12493 clone(child_stack=0x7f2ec81d6a48, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tidptr=0x7f2ec81d6b58, tls=0x7f2ec81d6b20, child_tidptr=0x81b7d8) = 12614 12493 rt_sigprocmask(SIG_SETMASK, [], 12614 rt_sigprocmask(SIG_SETMASK, [], 12493 <... rt_sigprocmask resumed> NULL, 8) = 0 12614 <... rt_sigprocmask resumed> NULL, 8) = 0 12493 futex(0x9fecd0, FUTEX_WAIT_BITSET_PRIVATE, 0, NULL, FUTEX_BITSET_MATCH_ANY 12614 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 12614 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f2ec7fd1000 12614 mprotect(0x7f2ec7fd1000, 4096, PROT_NONE) = 0 12614 sigaltstack({ss_sp=0x7f2ec7fd2000, ss_flags=0, ss_size=8192}, NULL) = 0 12614 prctl(PR_SET_NAME, "fc_vcpu 0") = 0 12614 futex(0x9fecd0, FUTEX_WAKE_PRIVATE, 2147483647 12493 <... futex resumed> ) = 0 12614 <... futex resumed> ) = 1 12493 futex(0x9fecb0, FUTEX_WAIT_BITSET_PRIVATE, 2, NULL, FUTEX_BITSET_MATCH_ANY 12614 futex(0x9fecb0, FUTEX_WAKE_PRIVATE, 1 12493 <... futex resumed> ) = -1 EAGAIN (Resource temporarily unavailable) 12614 <... futex resumed> ) = 0 12493 futex(0x9fecb0, FUTEX_WAKE_PRIVATE, 1 12614 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0 12493 <... futex resumed> ) = 0 12614 <... prctl resumed> ) = 0 12614 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=254, filter=0x9f8dc0} 12493 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0) = 0 12493 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=286, filter=0x9f7f00} 12614 <... prctl resumed> ) = 0 12614 futex(0x9ff548, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 12493 <... prctl resumed> ) = 0 12493 write(3, "2023-02-09T18:02:48.606931359 [a"..., 127) = 127 12493 futex(0x9ff548, FUTEX_WAKE_PRIVATE, 1) = 1 12614 <... futex resumed> ) = 0 12493 tkill(12614, SIGRT_3) = 0 12614 ioctl(20, KVM_RUN 12493 epoll_ctl(6, EPOLL_CTL_ADD, 17, {EPOLLIN, {u32=17, u64=17}}) = 0 12493 futex(0x9f9808, FUTEX_WAKE_PRIVATE, 1) = 1 12493 timerfd_settime(7, 0, {it_interval={tv_sec=60, tv_nsec=0}, it_value={tv_sec=60, tv_nsec=0}}, 12494 <... futex resumed> ) = 0 12493 <... timerfd_settime resumed> {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}}) = 0 12493 epoll_ctl(6, EPOLL_CTL_ADD, 4, {EPOLLIN, {u32=4, u64=4}} 12614 <... ioctl resumed> , 0) = -1 EINTR (Interrupted system call) 12493 <... epoll_ctl resumed> ) = 0 12614 --- SIGRT_3 {si_signo=SIGRT_3, si_code=SI_TKILL, si_pid=12493, si_uid=0} --- 12493 epoll_pwait(6, 12494 write(3, "2023-02-09T18:02:48.607035940 [a"..., 172 12614 rt_sigreturn({mask=[]} 12494 <... write resumed> ) = 172 12614 <... rt_sigreturn resumed> ) = -1 EINTR (Interrupted system call) 12614 ioctl(20, KVM_RUN 12494 epoll_ctl(9, EPOLL_CTL_MOD, 10, {EPOLLOUT|EPOLLRDHUP, {u32=10, u64=10}}) = 0 12494 write(3, "2023-02-09T18:02:48.607115751 [a"..., 137) = 137 12494 epoll_pwait(9, [{EPOLLOUT, {u32=10, u64=10}}], 10, -1, NULL, 8) = 1 12494 write(10, "HTTP/1.1 204 \r\nServer: Firecrack"..., 66) = 66 12494 epoll_ctl(9, EPOLL_CTL_MOD, 10, {EPOLLIN|EPOLLRDHUP, {u32=10, u64=10}}) = 0 12494 epoll_pwait(9, [{EPOLLIN|EPOLLHUP|EPOLLRDHUP, {u32=10, u64=10}}], 10, -1, NULL, 8) = 1 12494 epoll_ctl(9, EPOLL_CTL_DEL, 10, 0x7f2ed03e2150) = 0 12494 close(10) = 0 12494 epoll_pwait(9, 12614 <... ioctl resumed> , 0) = 0 12614 ioctl(20, KVM_RUN, 0) = 0 12614 ioctl(20, KVM_RUN, 0) = 0 12614 ioctl(20, KVM_RUN, 0) = 0 12614 ioctl(20, KVM_RUN, 0) = 0 // multiple KVM_RUN calls continue... ```

Host info:

Click to expand ``` # uname -a Linux ip-172-31-7-104.us-west-2.compute.internal 5.10.162-141.675.amzn2.x86_64 #1 SMP Mon Jan 9 22:45:11 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux # cat /etc/os-release NAME="Amazon Linux" VERSION="2" ID="amzn" ID_LIKE="centos rhel fedora" VERSION_ID="2" PRETTY_NAME="Amazon Linux 2" ANSI_COLOR="0;33" CPE_NAME="cpe:2.3:o:amazon:amazon_linux:2" HOME_URL="https://amazonlinux.com/" # lscpu Architecture: x86_64 CPU op-mode(s): 32-bit, 64-bit Byte Order: Little Endian CPU(s): 192 On-line CPU(s) list: 0-95 Off-line CPU(s) list: 96-191 Thread(s) per core: 1 Core(s) per socket: 48 Socket(s): 2 NUMA node(s): 4 Vendor ID: AuthenticAMD CPU family: 25 Model: 1 Model name: AMD EPYC 7R13 48-Core Processor Stepping: 1 CPU MHz: 1796.994 CPU max MHz: 3731.7380 CPU min MHz: 1500.0000 BogoMIPS: 5299.98 Virtualization: AMD-V L1d cache: 32K L1i cache: 32K L2 cache: 512K L3 cache: 32768K NUMA node0 CPU(s): 0-23 NUMA node1 CPU(s): 24-47 NUMA node2 CPU(s): 48-71 NUMA node3 CPU(s): 72-95 Flags: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm constant_tsc rep_good nopl nonstop_tsc cpuid extd_apicid aperfmperf pni pclmulqdq monitor ssse3 fma cx16 pcid sse4_1 sse4_2 movbe popcnt aes xsave avx f16c rdrand lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt tce topoext perfctr_core perfctr_nb bpext perfctr_llc mwaitx cpb cat_l3 cdp_l3 invpcid_single hw_pstate sme ssbd mba sev ibrs ibpb stibp vmmcall sev_es fsgsbase bmi1 avx2 smep bmi2 erms invpcid cqm rdt_a rdseed adx smap clflushopt clwb sha_ni xsaveopt xsavec xgetbv1 xsaves cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local clzero irperf xsaveerptr rdpru wbnoinvd amd_ppin arat npt lbrv svm_lock nrip_save tsc_scale vmcb_clean flushbyasid decodeassists pausefilter pfthreshold v_vmsave_vmload vgif umip pku ospke vaes vpclmulqdq rdpid overflow_recov succor smca fsrm ```

The main difference is host kernel version (5.10 vs. 6.1). If you have kernel 5.10 machine, I'd appreciate it if you could give it a try.

Thanks,

zulinx86 commented 1 year ago

I tried on Arch Linux with kernel 6.1 (AMI from here), but I couldn't reproduce that.

Host info:

Click to expand ``` # uname -a Linux ip-172-31-14-56 6.1.8-1-ec2 #1 SMP PREEMPT_DYNAMIC Tue, 31 Jan 2023 13:06:12 +0000 x86_64 GNU/Linux # cat /etc/os-release NAME="Arch Linux" PRETTY_NAME="Arch Linux" ID=arch BUILD_ID=rolling ANSI_COLOR="38;2;23;147;209" HOME_URL="https://archlinux.org/" DOCUMENTATION_URL="https://wiki.archlinux.org/" SUPPORT_URL="https://bbs.archlinux.org/" BUG_REPORT_URL="https://bugs.archlinux.org/" PRIVACY_POLICY_URL="https://terms.archlinux.org/docs/privacy-policy/" LOGO=archlinux-logo # lscpu Architecture: x86_64 CPU op-mode(s): 32-bit, 64-bit Address sizes: 43 bits physical, 48 bits virtual Byte Order: Little Endian CPU(s): 192 On-line CPU(s) list: 0-191 Vendor ID: AuthenticAMD BIOS Vendor ID: Advanced Micro Devices, Inc. Model name: AMD EPYC 7R13 48-Core Processor BIOS Model name: AMD EPYC 7R13 48-Core Processor Unknown CPU @ 2.6GHz BIOS CPU family: 107 CPU family: 25 Model: 1 Thread(s) per core: 2 Core(s) per socket: 48 Socket(s): 2 Stepping: 1 Frequency boost: enabled CPU(s) scaling MHz: 71% CPU max MHz: 3731.7380 CPU min MHz: 1500.0000 BogoMIPS: 5300.09 Flags: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm constant_t sc rep_good nopl nonstop_tsc cpuid extd_apicid aperfmperf rapl pni pclmulqdq monitor ssse3 fma cx16 pcid sse4_1 sse4_2 movbe popcnt aes xsave avx f16c rdran d lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt tce topoext perfctr_core perfctr_nb bpext perfctr_llc mw aitx cpb cat_l3 cdp_l3 invpcid_single hw_pstate ssbd mba ibrs ibpb stibp vmmcall fsgsbase bmi1 avx2 smep bmi2 erms invpcid cqm rdt_a rdseed adx smap clflush opt clwb sha_ni xsaveopt xsavec xgetbv1 xsaves cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local clzero irperf xsaveerptr rdpru wbnoinvd amd_ppin brs arat n pt lbrv svm_lock nrip_save tsc_scale vmcb_clean flushbyasid decodeassists pausefilter pfthreshold v_vmsave_vmload vgif v_spec_ctrl umip pku ospke vaes vpclm ulqdq rdpid overflow_recov succor smca fsrm sev sev_es Virtualization features: Virtualization: AMD-V Caches (sum of all): L1d: 3 MiB (96 instances) L1i: 3 MiB (96 instances) L2: 48 MiB (96 instances) L3: 384 MiB (12 instances) NUMA: NUMA node(s): 4 NUMA node0 CPU(s): 0-23,96-119 NUMA node1 CPU(s): 24-47,120-143 NUMA node2 CPU(s): 48-71,144-167 NUMA node3 CPU(s): 72-95,168-191 Vulnerabilities: Itlb multihit: Not affected L1tf: Not affected Mds: Not affected Meltdown: Not affected Mmio stale data: Not affected Retbleed: Not affected Spec store bypass: Mitigation; Speculative Store Bypass disabled via prctl Spectre v1: Mitigation; usercopy/swapgs barriers and __user pointer sanitization Spectre v2: Vulnerable, IBPB: conditional, IBRS_FW, STIBP: always-on, RSB filling, PBRSB-eIBRS: Not affected Srbds: Not affected Tsx async abort: Not affected ```

Logs

/tmp/firelog:

Click to expand ``` Running Firecracker v1.2.0 2023-02-09T19:06:54.272317920 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:216] The API server received a Put request on "/boot-source" with body "{\n \"kernel_image_path\": \"/home/arch/hello-vmlinux.bin\",\n \"boot_args\": \"console=ttyS0 reboot=k panic=1 pci=off\"\n }". 2023-02-09T19:06:54.272835464 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:163] The request was executed successfully. Status code: 204 No Content. 2023-02-09T19:06:54.272918775 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:211] Total previous API call duration: 610 us. 2023-02-09T19:06:54.278114897 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:216] The API server received a Put request on "/drives/rootfs" with body "{\n \"drive_id\": \"rootfs\",\n \"path_on_host\": \"/home/arch/hello-rootfs.ext4\",\n \"is_root_device\": true,\n \"is_read_only\": false\n }". 2023-02-09T19:06:54.278652721 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:163] The request was executed successfully. Status code: 204 No Content. 2023-02-09T19:06:54.278722171 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:211] Total previous API call duration: 616 us. 2023-02-09T19:06:54.283136057 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:216] The API server received a Put request on "/actions" with body "{\n \"action_type\": \"InstanceStart\"\n }". 2023-02-09T19:06:54.336982032 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:408] Artificially kick devices. 2023-02-09T19:06:54.337196183 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:163] The request was executed successfully. Status code: 204 No Content. 2023-02-09T19:06:54.337351964 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:211] Total previous API call duration: 54219 us. 2023-02-09T19:06:54.793095553 [anonymous-instance:main:DEBUG:src/devices/src/virtio/block/event_handler.rs:35] block: activate event 2023-02-09T19:06:54.803906000 [anonymous-instance:fc_vcpu 0:WARN:src/devices/src/legacy/i8042.rs:132] Failed to trigger i8042 kbd interrupt (disabled by guest OS) 2023-02-09T19:06:54.827304439 [anonymous-instance:fc_vcpu 0:WARN:src/devices/src/legacy/i8042.rs:132] Failed to trigger i8042 kbd interrupt (disabled by guest OS) 2023-02-09T19:06:55.643743207 [anonymous-instance:fc_vcpu 0:WARN:src/devices/src/virtio/mmio.rs:318] invalid virtio mmio write: 0x0:0x1 ```

strace.txt

Click to expand ``` 3376 execve("./firecracker", ["./firecracker", "--api-sock", "/tmp/firecracker.socket", "--level", "Debug", "--log-path", "/tmp/firelog", "--show-level", "--show-log-origin"], 0x7fffee134638 /* 12 vars */) = 0 3376 mmap(NULL, 392, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc8f23cc000 3376 arch_prctl(ARCH_SET_FS, 0x7fc8f23cc0a8) = 0 3376 set_tid_address(0x81b7d8) = 3376 3376 poll([{fd=0, events=0}, {fd=1, events=0}, {fd=2, events=0}], 3, 0) = 0 (Timeout) 3376 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x5acb3b}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 3376 rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 3376 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 3376 rt_sigaction(SIGSEGV, {sa_handler=0x4d2a40, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 3376 rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 3376 rt_sigaction(SIGBUS, {sa_handler=0x4d2a40, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 3376 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 3376 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fc8f23c9000 3376 mprotect(0x7fc8f23c9000, 4096, PROT_NONE) = 0 3376 sigaltstack({ss_sp=0x7fc8f23ca000, ss_flags=0, ss_size=8192}, NULL) = 0 3376 brk(NULL) = 0x1bf0000 3376 brk(0x1bf1000) = 0x1bf1000 3376 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 3376 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 3376 rt_sigaction(SIGSYS, {sa_handler=0x533540, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 3376 rt_sigaction(SIGBUS, {sa_handler=0x533b00, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 3376 rt_sigaction(SIGSEGV, {sa_handler=0x534100, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 3376 rt_sigaction(SIGXFSZ, {sa_handler=0x534700, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 3376 rt_sigaction(SIGXCPU, {sa_handler=0x534d00, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 3376 rt_sigaction(SIGPIPE, {sa_handler=0x535300, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 3376 rt_sigaction(SIGHUP, {sa_handler=0x535580, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 3376 rt_sigaction(SIGILL, {sa_handler=0x535b80, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 3376 brk(0x1bf4000) = 0x1bf4000 3376 open("/tmp/firelog", O_RDWR|O_NONBLOCK|O_CLOEXEC) = 3 3376 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 3376 write(3, "Running Firecracker v1.2.0\n", 27) = 27 3376 getrandom("\x2a\x9f\x56\xe3\x05\x3c\xf8\xd2\x99\x04\xca\x33\xab\xb4\x2c\x79", 16, GRND_INSECURE) = 16 3376 brk(0x1bf5000) = 0x1bf5000 3376 brk(0x1bf6000) = 0x1bf6000 3376 eventfd2(0, 0) = 4 3376 dup(4) = 5 3376 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 3376 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc8f21c6000 3376 mprotect(0x7fc8f21c8000, 2101248, PROT_READ|PROT_WRITE) = 0 3376 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 3376 clone(child_stack=0x7fc8f23c8a48, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[3377], tls=0x7fc8f23c8b20, child_tidptr=0x81b7d8) = 3377 3376 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 3377 rt_sigprocmask(SIG_SETMASK, [], 3376 epoll_create1(EPOLL_CLOEXEC) = 6 3377 <... rt_sigprocmask resumed>NULL, 8) = 0 3376 brk(0x1bf7000) = 0x1bf7000 3377 sigaltstack(NULL, 3376 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK 3377 <... sigaltstack resumed>{ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 3376 <... timerfd_create resumed>) = 7 3377 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0 3376 epoll_ctl(6, EPOLL_CTL_ADD, 7, {events=EPOLLIN, data={u32=7, u64=7}} 3377 <... mmap resumed>) = 0x7fc8f21c3000 3376 <... epoll_ctl resumed>) = 0 3377 mprotect(0x7fc8f21c3000, 4096, PROT_NONE) = 0 3377 sigaltstack({ss_sp=0x7fc8f21c4000, ss_flags=0, ss_size=8192}, 3376 futex(0x1bf0068, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 3377 <... sigaltstack resumed>NULL) = 0 3377 prctl(PR_SET_NAME, "fc_api") = 0 3377 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 8 3377 bind(8, {sa_family=AF_UNIX, sun_path="/tmp/firecracker.socket"}, 26) = 0 3377 listen(8, 128) = 0 3377 epoll_create1(EPOLL_CLOEXEC) = 9 3377 getrandom("\x23\xce\x11\xe5\x12\x4c\xae\xf6\x62\x02\x26\x15\x20\xcf\xfc\x7f", 16, GRND_INSECURE) = 16 3377 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0) = 0 3377 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=182, filter=0x1bf4800}) = 0 3377 epoll_ctl(9, EPOLL_CTL_ADD, 8, {events=EPOLLIN|EPOLLRDHUP, data={u32=8, u64=8}}) = 0 3377 epoll_pwait(9, [{events=EPOLLIN, data={u32=8, u64=8}}], 10, -1, NULL, 8) = 1 3377 accept4(8, {sa_family=AF_UNIX}, [110 => 2], SOCK_CLOEXEC) = 10 3377 ioctl(10, FIONBIO, [1]) = 0 3377 epoll_ctl(9, EPOLL_CTL_ADD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 3377 brk(0x1bf8000) = 0x1bf8000 3377 brk(0x1bfa000) = 0x1bfa000 3377 epoll_pwait(9, [{events=EPOLLIN, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 3377 recvmsg(10, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PUT /boot-source HTTP/1.1\r\nHost:"..., iov_len=1024}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 279 3377 open("/etc/localtime", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = 11 3377 fstat(11, {st_mode=S_IFREG|0644, st_size=114, ...}) = 0 3377 mmap(NULL, 114, PROT_READ, MAP_SHARED, 11, 0) = 0x7fc8f21c2000 3377 close(11) = 0 3377 write(3, "2023-02-09T19:06:54.272317920 [a"..., 314) = 314 3377 futex(0x1bf0068, FUTEX_WAKE_PRIVATE, 1) = 1 3377 write(5, "\1\0\0\0\0\0\0\0", 8) = 8 3376 <... futex resumed>) = 0 3377 futex(0x1bf5808, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 3376 read(4, "\1\0\0\0\0\0\0\0", 8) = 8 3376 open("/home/arch/hello-vmlinux.bin", O_RDONLY|O_CLOEXEC) = 11 3376 fcntl(11, F_SETFD, FD_CLOEXEC) = 0 3376 futex(0x1bf5808, FUTEX_WAKE_PRIVATE, 1) = 1 3377 <... futex resumed>) = 0 3376 futex(0x1bf0068, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 3377 write(3, "2023-02-09T19:06:54.272835464 [a"..., 172) = 172 3377 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLOUT|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 3377 write(3, "2023-02-09T19:06:54.272918775 [a"..., 136) = 136 3377 epoll_pwait(9, [{events=EPOLLOUT, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 3377 write(10, "HTTP/1.1 204 \r\nServer: Firecrack"..., 66) = 66 3377 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 3377 epoll_pwait(9, [{events=EPOLLIN|EPOLLHUP|EPOLLRDHUP, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 3377 epoll_ctl(9, EPOLL_CTL_DEL, 10, 0x7fc8f23c8150) = 0 3377 close(10) = 0 3377 epoll_pwait(9, [{events=EPOLLIN, data={u32=8, u64=8}}], 10, -1, NULL, 8) = 1 3377 accept4(8, {sa_family=AF_UNIX}, [110 => 2], SOCK_CLOEXEC) = 10 3377 ioctl(10, FIONBIO, [1]) = 0 3377 epoll_ctl(9, EPOLL_CTL_ADD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 3377 epoll_pwait(9, [{events=EPOLLIN, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 3377 recvmsg(10, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PUT /drives/rootfs HTTP/1.1\r\nHos"..., iov_len=1024}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 306 3377 write(3, "2023-02-09T19:06:54.278114897 [a"..., 347) = 347 3377 futex(0x1bf0068, FUTEX_WAKE_PRIVATE, 1) = 1 3376 <... futex resumed>) = 0 3377 write(5, "\1\0\0\0\0\0\0\0", 8 3376 read(4, 3377 <... write resumed>) = 8 3376 <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8 3377 futex(0x1bf5808, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 3376 stat("/home/arch/hello-rootfs.ext4", {st_mode=S_IFREG|0644, st_size=314572800, ...}) = 0 3376 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 12 3376 open("/home/arch/hello-rootfs.ext4", O_RDWR|O_CLOEXEC) = 13 3376 fcntl(13, F_SETFD, FD_CLOEXEC) = 0 3376 lseek(13, 0, SEEK_END) = 314572800 3376 fstat(13, {st_mode=S_IFREG|0644, st_size=314572800, ...}) = 0 3376 eventfd2(0, EFD_NONBLOCK) = 14 3376 eventfd2(0, EFD_NONBLOCK) = 15 3376 eventfd2(0, EFD_NONBLOCK) = 16 3376 futex(0x1bf5808, FUTEX_WAKE_PRIVATE, 1) = 1 3377 <... futex resumed>) = 0 3376 futex(0x1bf0068, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 3377 write(3, "2023-02-09T19:06:54.278652721 [a"..., 172) = 172 3377 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLOUT|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 3377 write(3, "2023-02-09T19:06:54.278722171 [a"..., 136) = 136 3377 epoll_pwait(9, [{events=EPOLLOUT, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 3377 write(10, "HTTP/1.1 204 \r\nServer: Firecrack"..., 66) = 66 3377 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 3377 epoll_pwait(9, [{events=EPOLLIN|EPOLLHUP|EPOLLRDHUP, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 3377 epoll_ctl(9, EPOLL_CTL_DEL, 10, 0x7fc8f23c8150) = 0 3377 close(10) = 0 3377 epoll_pwait(9, [{events=EPOLLIN, data={u32=8, u64=8}}], 10, -1, NULL, 8) = 1 3377 accept4(8, {sa_family=AF_UNIX}, [110 => 2], SOCK_CLOEXEC) = 10 3377 ioctl(10, FIONBIO, [1]) = 0 3377 epoll_ctl(9, EPOLL_CTL_ADD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 3377 epoll_pwait(9, [{events=EPOLLIN, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 3377 recvmsg(10, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="PUT /actions HTTP/1.1\r\nHost: loc"..., iov_len=1024}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 188 3377 write(3, "2023-02-09T19:06:54.283136057 [a"..., 219) = 219 3377 futex(0x1bf0068, FUTEX_WAKE_PRIVATE, 1) = 1 3376 <... futex resumed>) = 0 3377 write(5, "\1\0\0\0\0\0\0\0", 8 3376 read(4, 3377 <... write resumed>) = 8 3376 <... read resumed>"\1\0\0\0\0\0\0\0", 8) = 8 3377 futex(0x1bf5808, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 3376 clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=0, tv_nsec=2007093}) = 0 3376 mmap(NULL, 134225920, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7fc8ea1c0000 3376 mmap(0x7fc8ea1c1000, 134217728, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x7fc8ea1c1000 3376 fcntl(11, F_DUPFD_CLOEXEC, 0) = 17 3376 fcntl(17, F_SETFD, FD_CLOEXEC) = 0 3376 lseek(17, 0, SEEK_SET) = 0 3376 read(17, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\2\0>\0\1\0\0\0\0\0\0\1\0\0\0\0"..., 64) = 64 3376 lseek(17, 64, SEEK_SET) = 64 3376 read(17, "\1\0\0\0\5\0\0\0\0\0 \0\0\0\0\0\0\0\0\201\377\377\377\377\0\0\0\1\0\0\0\0"..., 56) = 56 3376 read(17, "\1\0\0\0\6\0\0\0\0\0\340\0\0\0\0\0\0\0\300\201\377\377\377\377\0\0\300\1\0\0\0\0"..., 56) = 56 3376 read(17, "\1\0\0\0\6\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\313\1\0\0\0\0"..., 56) = 56 3376 read(17, "\1\0\0\0\7\0\0\0\0\0\r\1\0\0\0\0\0\0\315\201\377\377\377\377\0\0\315\1\0\0\0\0"..., 56) = 56 3376 read(17, "\4\0\0\0\0\0\0\0\3241\240\0\0\0\0\0\3241\200\201\377\377\377\377\3241\200\1\0\0\0\0"..., 56) = 56 3376 lseek(17, 2097152, SEEK_SET) = 2097152 3376 read(17, "H\215%Q?\300\0\350\324\0\0\0H\215=\355\377\377\377V\350\327\1\0\0^H\5\0\200\320\1"..., 12001280) = 12001280 3376 lseek(17, 14680064, SEEK_SET) = 14680064 3376 read(17, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 720896) = 720896 3376 lseek(17, 16777216, SEEK_SET) = 16777216 3376 read(17, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 128600) = 128600 3376 lseek(17, 17629184, SEEK_SET) = 17629184 3376 read(17, "j\0j\0\351\27\1\0\0j\0j\1\351\16\1\0\0j\0j\2\351\5\1\0\0j\0j\3\351"..., 1257472) = 1257472 3376 lseek(17, 10498516, SEEK_SET) = 10498516 3376 read(17, "\4\0\0\0\24\0\0\0\3\0\0\0", 12) = 12 3376 lseek(17, 10498552, SEEK_SET) = 10498552 3376 close(17) = 0 3376 open("/dev/kvm", O_RDWR|O_CLOEXEC) = 17 3376 fcntl(17, F_SETFD, FD_CLOEXEC) = 0 3376 ioctl(17, KVM_GET_API_VERSION, 0) = 12 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_IRQCHIP) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_IOEVENTFD) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_IRQFD) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_USER_MEMORY) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_SET_TSS_ADDR) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_PIT2) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_PIT_STATE2) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_ADJUST_CLOCK) = 14 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_DEBUGREGS) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_MP_STATE) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_VCPU_EVENTS) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_XCRS) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_XSAVE) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_EXT_CPUID) = 1 3376 ioctl(17, KVM_CHECK_EXTENSION, KVM_CAP_NR_MEMSLOTS) = 32764 3376 ioctl(17, KVM_CREATE_VM, 0) = 18 3376 ioctl(17, KVM_GET_VCPU_MMAP_SIZE, 0) = 12288 3376 brk(0x1bfb000) = 0x1bfb000 3376 ioctl(17, KVM_GET_SUPPORTED_CPUID, {nent=60, entries=[...]}) = 0 3376 ioctl(17, KVM_GET_MSR_INDEX_LIST, 0x1bfa3e0) = 0 3376 ioctl(18, KVM_SET_USER_MEMORY_REGION, {slot=0, flags=0, guest_phys_addr=0, memory_size=134217728, userspace_addr=0x7fc8ea1c1000}) = 0 3376 ioctl(18, KVM_SET_TSS_ADDR, 0xfffbd000) = 0 3376 close(17) = 0 3376 eventfd2(0, EFD_NONBLOCK) = 17 3376 ioctl(18, KVM_CREATE_IRQCHIP, 0) = 0 3376 ioctl(18, KVM_CREATE_PIT2, 0x7ffc2f999258) = 0 3376 dup(17) = 19 3376 ioctl(18, KVM_CREATE_VCPU, 0) = 20 3376 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_SHARED, 20, 0) = 0x7fc8ea1bd000 3376 fcntl(1, F_GETFL) = 0x2 (flags O_RDWR) 3376 fcntl(1, F_SETFL, O_RDWR|O_NONBLOCK) = 0 3376 eventfd2(0, EFD_NONBLOCK) = 21 3376 eventfd2(0, EFD_NONBLOCK) = 22 3376 epoll_ctl(6, EPOLL_CTL_ADD, 0, {events=EPOLLIN, data={u32=0, u64=0}}) = 0 3376 epoll_ctl(6, EPOLL_CTL_ADD, 22, {events=EPOLLIN, data={u32=22, u64=22}}) = 0 3376 dup(17) = 23 3376 dup(21) = 24 3376 eventfd2(0, EFD_NONBLOCK) = 25 3376 eventfd2(0, EFD_NONBLOCK) = 26 3376 dup(26) = 27 3376 dup(25) = 28 3376 dup(28) = 29 3376 close(28) = 0 3376 dup(24) = 28 3376 dup(28) = 30 3376 close(28) = 0 3376 ioctl(18, KVM_IRQFD, 0x7ffc2f9991d0) = 0 3376 ioctl(18, KVM_IRQFD, 0x7ffc2f9991d0) = 0 3376 ioctl(18, KVM_IRQFD, 0x7ffc2f9991d0) = 0 3376 epoll_ctl(6, EPOLL_CTL_ADD, 16, {events=EPOLLIN, data={u32=16, u64=16}}) = 0 3376 ioctl(18, KVM_IOEVENTFD, 0x7ffc2f9992a0) = 0 3376 ioctl(18, KVM_IRQFD, 0x7ffc2f9991f0) = 0 3376 brk(0x1bfc000) = 0x1bfc000 3376 brk(0x1bfe000) = 0x1bfe000 3376 ioctl(20, KVM_SET_CPUID2, {nent=58, entries=[...]}) = 0 3376 ioctl(20, KVM_SET_MSRS, 0x1bfb300) = 10 3376 ioctl(20, KVM_SET_REGS, {rax=0, ..., rsp=0x8ff0, rbp=0x8ff0, ..., rip=0x1000000, rflags=0x2}) = 0 3376 ioctl(20, KVM_SET_FPU, 0x7ffc2f998600) = 0 3376 ioctl(20, KVM_GET_SREGS, {cs={base=0xffff0000, limit=65535, selector=61440, type=10, present=1, dpl=0, db=0, s=1, l=0, g=0, avl=0}, ...}) = 0 3376 ioctl(20, KVM_SET_SREGS, {cs={base=0, limit=1048575, selector=8, type=11, present=1, dpl=0, db=0, s=1, l=1, g=1, avl=0}, ...}) = 0 3376 ioctl(20, KVM_GET_LAPIC, 0x7ffc2f997720) = 0 3376 ioctl(20, KVM_SET_LAPIC, 0x7ffc2f997b20) = 0 3376 ioctl(0, TIOCGWINSZ, {ws_row=79, ws_col=181, ws_xpixel=2534, ws_ypixel=2686}) = 0 3376 ioctl(0, TCGETS, {c_iflag=ICRNL|IXON|IXANY|IMAXBEL|IUTF8, c_oflag=NL0|CR0|TAB0|BS0|VT0|FF0|OPOST|ONLCR, c_cflag=B38400|CS8|CREAD, c_lflag=ISIG|ICANON|ECHO|ECHOE|ECHOK|IEXTEN|E CHOCTL|ECHOKE|PENDIN, ...}) = 0 3376 ioctl(0, SNDCTL_TMR_START or TCSETS, {c_iflag=ICRNL|IXON|IXANY|IMAXBEL|IUTF8, c_oflag=NL0|CR0|TAB0|BS0|VT0|FF0|OPOST|ONLCR, c_cflag=B38400|CS8|CREAD, c_lflag=ECHOE|ECHOK|IEXTE N|ECHOCTL|ECHOKE|PENDIN, ...}) = 0 3376 fcntl(0, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) 3376 rt_sigaction(SIGRT_3, {sa_handler=0x50d6e0, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x5acb3b}, NULL, 8) = 0 3376 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc8e9fba000 3376 mprotect(0x7fc8e9fbc000, 2101248, PROT_READ|PROT_WRITE) = 0 3376 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 3376 clone(child_stack=0x7fc8ea1bca48, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tid=[3388], tls=0x7fc8ea1bcb20, child_tidptr=0x81b7d8) = 3388 3376 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 3376 futex(0x1bfacd0, FUTEX_WAIT_BITSET_PRIVATE, 0, NULL, FUTEX_BITSET_MATCH_ANY 3388 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 3388 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 3388 mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fc8e9fb7000 3388 mprotect(0x7fc8e9fb7000, 4096, PROT_NONE) = 0 3388 sigaltstack({ss_sp=0x7fc8e9fb8000, ss_flags=0, ss_size=8192}, NULL) = 0 3388 prctl(PR_SET_NAME, "fc_vcpu 0") = 0 3388 futex(0x1bfacd0, FUTEX_WAKE_PRIVATE, 2147483647) = 1 3376 <... futex resumed>) = 0 3388 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0 3376 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0 3388 <... prctl resumed>) = 0 3376 <... prctl resumed>) = 0 3388 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=254, filter=0x1bf4dc0} 3376 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=286, filter=0x1bf3f00}) = 0 3388 <... prctl resumed>) = 0 3376 write(3, "2023-02-09T19:06:54.336982032 [a"..., 127) = 127 3388 futex(0x1bfb548, FUTEX_WAIT_BITSET_PRIVATE, 4294967295, NULL, FUTEX_BITSET_MATCH_ANY 3376 futex(0x1bfb548, FUTEX_WAKE_PRIVATE, 1 3388 <... futex resumed>) = -1 EAGAIN (Resource temporarily unavailable) 3376 <... futex resumed>) = 0 3376 tkill(3388, SIGRT_3 3388 ioctl(20, KVM_RUN 3376 <... tkill resumed>) = 0 3376 epoll_ctl(6, EPOLL_CTL_ADD, 17, {events=EPOLLIN, data={u32=17, u64=17}}) = 0 3376 futex(0x1bf5808, FUTEX_WAKE_PRIVATE, 1) = 1 3376 timerfd_settime(7, 0, {it_interval={tv_sec=60, tv_nsec=0}, it_value={tv_sec=60, tv_nsec=0}}, {it_interval={tv_sec=0, tv_nsec=0}, it_value={tv_sec=0, tv_nsec=0}}) = 0 3376 epoll_ctl(6, EPOLL_CTL_ADD, 4, {events=EPOLLIN, data={u32=4, u64=4}} 3388 <... ioctl resumed>, 0) = -1 EINTR (Interrupted system call) 3377 <... futex resumed>) = 0 3376 <... epoll_ctl resumed>) = 0 3388 --- SIGRT_3 {si_signo=SIGRT_3, si_code=SI_TKILL, si_pid=3376, si_uid=0} --- 3376 epoll_pwait(6, 3388 rt_sigreturn({mask=[]} 3377 write(3, "2023-02-09T19:06:54.337196183 [a"..., 172 3388 <... rt_sigreturn resumed>) = -1 EINTR (Interrupted system call) 3388 ioctl(20, KVM_RUN 3377 <... write resumed>) = 172 3377 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLOUT|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 3377 write(3, "2023-02-09T19:06:54.337351964 [a"..., 138) = 138 3377 epoll_pwait(9, [{events=EPOLLOUT, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 3377 write(10, "HTTP/1.1 204 \r\nServer: Firecrack"..., 66) = 66 3377 epoll_ctl(9, EPOLL_CTL_MOD, 10, {events=EPOLLIN|EPOLLRDHUP, data={u32=10, u64=10}}) = 0 3377 epoll_pwait(9, [{events=EPOLLIN|EPOLLHUP|EPOLLRDHUP, data={u32=10, u64=10}}], 10, -1, NULL, 8) = 1 3377 epoll_ctl(9, EPOLL_CTL_DEL, 10, 0x7fc8f23c8150) = 0 3377 close(10) = 0 3377 epoll_pwait(9, 3388 <... ioctl resumed>, 0) = 0 3388 ioctl(20, KVM_RUN, 0) = 0 3388 ioctl(20, KVM_RUN, 0) = 0 3388 ioctl(20, KVM_RUN, 0) = 0 // multiple KVM_RUN calls continues... ```
zulinx86 commented 1 year ago

Hi @dosisod , I tried to reproduce the issue, but I couldn't. Is there anything else that you have noticed on your side?

dosisod commented 1 year ago

I have yet to test my Arch build on a different computer, or test a different OS on my current computer. Given that you have tested this on an Arch 6.1 kernel I suspect it is either something wrong with my OS configuration, or something wrong with my physical hardware.

I will see what I can do about narrowing this down and get back to you when I have some more info.

xmarcalx commented 1 year ago

Hi @dosisod ,

Thanks for reporting the issue. We were not able to reproduce this issue in our testing with host kernel 6.1. At the same time, we have further improved Firecracker and our testing methods for kernel 6.1 since the issue was opened. We are closing this issue and we suggest to try to boot a microVM using newer Firecracker version. Please feel free to reopen this issue, if you will still experiencing problems.

dosisod commented 1 year ago

@xmarcalx I just tested this again and it works. I'm on kernel version 6.4.10 now, so perhaps something since then fixed it. I tried bisecting Firecracker to see if it was Firecracker related, but I cannot build 81e771a (commit when I opened this), v1.2.0 or v1.3.0 due to some vmm-related build errors (I could post the build errors if you like). The earliest version I could find that actually compiled was v1.4.0, and that one works.

Thanks for bringing this up again, I suspect this was a kernel/CPU bug and/or computer issues on my end.