search

firecracker-microvm / firecracker

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

firecracker coredump #2393

Closed magnate3 closed 3 years ago

magnate3 commented 3 years ago

Describe the bug

[Author TODO: A clear and concise description of what the bug is.]

root@ubuntu:~/myfirecracker/firecracker# firecracker --api-sock /tmp/firecracker.socket Bad system call (core dumped)

To Reproduce

1、 start firecrakcer: firecracker --api-sock /tmp/firecracker.socket 2、 send curl request 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\": \"keep_bootcon console=ttyS0 reboot=k panic=1 pci=off\" }" curl: (52) Empty reply from server curl: (7) Couldn't connect to server curl: (7) Couldn't connect to server

Environment

uname -a Linux ubuntu 5.0.0-23-generic #24~18.04.1-Ubuntu SMP Mon Jul 29 16:10:24 UTC 2019 aarch64 aarch64 aarch64 GNU/Linux

the firecrakcer is builded as following: root@ubuntu:~/myfirecracker# git clone https://github.com/firecracker-microvm/firecracker.git Cloning into 'firecracker'... remote: Enumerating objects: 82, done. remote: Counting objects: 100% (82/82), done. remote: Compressing objects: 100% (69/69), done. remote: Total 25405 (delta 31), reused 25 (delta 12), pack-reused 25323 Receiving objects: 100% (25405/25405), 17.58 MiB | 5.38 MiB/s, done. Resolving deltas: 100% (15370/15370), done. root@ubuntu:~/myfirecracker# cd firecracker root@ubuntu:~/myfirecracker/firecracker# tools/devtool build

gbionescu commented 3 years ago

Hi @magnate3

It seems that the built-in seccomp filters are stopping the Firecracker process when the kernel is loaded. The seccomp filters can be disabled by passing the --seccomp-level 0 parameters to Firecracker.

Could you give us more details on what happens on your host? I did not manage to reproduce this on one of our machines.

You can start the firecracker process using strace:

strace -o firecracker.output firecracker --api-sock /tmp/firecracker.socket

Run the curl request and check paste the last 100-200 lines from the firecracker.output file.

magnate3 commented 3 years ago

@gc-plp @gc-plp thanks, root@ubuntu:~# strace -o firecracker.output firecracker --api-sock /tmp/firecracker.socket Bad system call root@ubuntu:~# cat firecracker.output execve("/usr/local/bin/firecracker", ["firecracker", "--api-sock", "/tmp/firecracker.socket"], 0xffffe47a1bc0 / 22 vars /) = 0 mmap(NULL, 592, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffab4bf000 set_tid_address(0x7e5870) = 29954 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x712414}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 rt_sigaction(SIGSEGV, {sa_handler=0x6ec69c, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 rt_sigaction(SIGBUS, {sa_handler=0x6ec69c, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffab4bb000 mprotect(0xffffab4bb000, 4096, PROT_NONE) = 0 sigaltstack({ss_sp=0xffffab4bc000, ss_flags=0, ss_size=12288}, NULL) = 0 brk(NULL) = 0x371db000 brk(0x371dc000) = 0x371dc000 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 rt_sigaction(SIGSYS, {sa_handler=0x4679bc, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGBUS, {sa_handler=0x466ccc, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGSEGV, {sa_handler=0x46711c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGXFSZ, {sa_handler=0x46642c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGXCPU, {sa_handler=0x46687c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGPIPE, {sa_handler=0x46756c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGHUP, {sa_handler=0x467e0c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGILL, {sa_handler=0x46825c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 brk(0x371df000) = 0x371df000 brk(0x371e0000) = 0x371e0000 brk(0x371e1000) = 0x371e1000 eventfd2(0, 0) = 3 dup(3) = 4 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffab2b8000 mprotect(0xffffab2ba000, 2101248, PROT_READ|PROT_WRITE) = 0 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 clone(child_stack=0xffffab4ba980, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tidptr=0xffffab4ba9f8, tls=0xffffab4baaa0, child_tidptr=0x7e5870) = 29955 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 epoll_create1(EPOLL_CLOEXEC) = 6 getrandom("\x6c\x66\x9b\x7b\x52\x23\x06\x5e\xab\xeb\xec\x3c\x25\x5b\xa4\xf2", 16, GRND_NONBLOCK) = 16 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 8 epoll_ctl(6, EPOLL_CTL_ADD, 8, {EPOLLIN, {u32=8, u64=8}}) = 0 futex(0xffffdfd56ad4, FUTEX_WAIT_PRIVATE, 2, NULL) = ? +++ killed by SIGSYS +++

the curl request is : root@ubuntu:~# ls $(pwd)"/rootfs/vmlinux.bin" /root/rootfs/vmlinux.bin root@ubuntu:~# ls $(pwd)"/rootfs/xenial.rootfs.ext4" /root/rootfs/xenial.rootfs.ext4 kernel_path=$(pwd)"/rootfs/vmlinux.bin" rootfs_path=$(pwd)"/rootfs/xenial.rootfs.ext4"

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\": \"keep_bootcon console=ttyS0 reboot=k panic=1 pci=off\" }"

magnate3 commented 3 years ago

@gc-plp thank you very much, I follow you advice and try like following and the firecracker start successfully strace -o firecracker.output firecracker --api-sock /tmp/firecracker.socket --seccomp-level 0**** [ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Linux version 4.14.138 (sandreim@firecracker-arm-ci) (gcc version 7.4.0 (Ubuntu/Linaro 7.4.0-1ubuntu1~18.04.1)) #1 SMP Tue Sep 10 12:26:05 UTC 2019 [ 0.000000] Boot CPU: AArch64 Processor [410fd082] [ 0.000000] Machine model: linux,dummy-virt [ 0.000000] debug: skip boot console de-registration. [ 0.000000] earlycon: uart0 at MMIO 0x0000000040002000 (options '') [ 0.000000] bootconsole [uart0] enabled [ 0.000000] efi: Getting EFI parameters from FDT: [ 0.000000] efi: UEFI not found. [ 0.000000] NUMA: No NUMA configuration found [ 0.000000] NUMA: Faking a node at [mem 0x0000000000000000-0x0000000087ffffff] [ 0.000000] NUMA: NODE_DATA [mem 0x87edac80-0x87ef3fff] [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000080000000-0x0000000087ffffff] [ 0.000000] Normal empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000080000000-0x0000000087ffffff] [ 0.000000] Initmem setup node 0 [mem 0x0000000080000000-0x0000000087ffffff] [ 0.000000] psci: probing for conduit method from DT.

gbionescu commented 3 years ago

Hi @magnate3. You don't need to run Firecracker with strace. You can just do firecracker --api-sock /tmp/firecracker.socket --seccomp-level 0.

I took a quick look at the first strace log and it looks similar to what I can see on my machine. Could you also paste the strace output when using --seccomp-level 0, please? The actual boot log is not needed, only what happens during the curl request.

magnate3 commented 3 years ago

ok，I understand what you say. thank you. when execute the cmd : strace -o firecracker.output firecracker --api-sock /tmp/firecracker.socket --seccomp-level 0,the output is :

execve("/usr/local/bin/firecracker", ["firecracker", "--api-sock", "/tmp/firecracker.socket", "--seccomp-level", "0"], 0xffffe84883d0 / 22 vars /) = 0 mmap(NULL, 592, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffff9d68f000 set_tid_address(0x7e5870) = 48729 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x712414}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 rt_sigaction(SIGSEGV, {sa_handler=0x6ec69c, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 rt_sigaction(SIGBUS, {sa_handler=0x6ec69c, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffff9d68b000 mprotect(0xffff9d68b000, 4096, PROT_NONE) = 0 sigaltstack({ss_sp=0xffff9d68c000, ss_flags=0, ss_size=12288}, NULL) = 0 brk(NULL) = 0x132d5000 brk(0x132d6000) = 0x132d6000 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 rt_sigaction(SIGSYS, {sa_handler=0x4679bc, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGBUS, {sa_handler=0x466ccc, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGSEGV, {sa_handler=0x46711c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGXFSZ, {sa_handler=0x46642c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGXCPU, {sa_handler=0x46687c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGPIPE, {sa_handler=0x46756c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGHUP, {sa_handler=0x467e0c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 rt_sigaction(SIGILL, {sa_handler=0x46825c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 brk(0x132d9000) = 0x132d9000 eventfd2(0, 0) = 3 dup(3) = 4 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffff9d488000 mprotect(0xffff9d48a000, 2101248, PROT_READ|PROT_WRITE) = 0 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 clone(child_stack=0xffff9d68a980, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tidptr=0xffff9d68a9f8, tls=0xffff9d68aaa0, child_tidptr=0x7e5870) = 48 730 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 epoll_create1(EPOLL_CLOEXEC) = 6 getrandom("\xd5\xf6\xb5\x4f\xac\xac\x7c\x62\xc2\x9e\x58\xe2\xa1\xdc\x3b\x97", 16, GRND_NONBLOCK) = 16 brk(0x132da000) = 0x132da000 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 8 epoll_ctl(6, EPOLL_CTL_ADD, 8, {EPOLLIN, {u32=8, u64=8}}) = 0 futex(0xffffd27068c4, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 read(3, "\1\0\0\0\0\0\0\0", 8) = 8 openat(AT_FDCWD, "/root/rootfs/vmlinux.bin", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 10 fcntl(10, F_SETFD, FD_CLOEXEC) = 0 fcntl(10, F_GETFD) = 0x1 (flags FD_CLOEXEC) brk(0x132dc000) = 0x132dc000 futex(0xffff9d688544, FUTEX_WAKE_PRIVATE, 1) = 1 futex(0xffffd27068c4, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 read(3, "\1\0\0\0\0\0\0\0", 8) = 8 newfstatat(AT_FDCWD, "/root/rootfs/xenial.rootfs.ext4", {st_mode=S_IFREG|0644, st_size=209715200, ...}, 0) = 0 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 11 openat(AT_FDCWD, "/root/rootfs/xenial.rootfs.ext4", O_RDWR|O_LARGEFILE|O_CLOEXEC) = 12 fcntl(12, F_SETFD, FD_CLOEXEC) = 0 lseek(12, 0, SEEK_END) = 209715200 fstat(12, {st_mode=S_IFREG|0644, st_size=209715200, ...}) = 0 eventfd2(0, EFD_NONBLOCK) = 13 eventfd2(0, EFD_NONBLOCK) = 14 eventfd2(0, EFD_NONBLOCK) = 15 futex(0xffff9d688544, FUTEX_WAKE_PRIVATE, 1) = 1 futex(0xffffd2706834, FUTEX_WAIT_PRIVATE, 2, NULL) = 0 read(3, "\1\0\0\0\0\0\0\0", 8) = 8 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 16 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK) = 17 openat(AT_FDCWD, "/dev/net/tun", O_RDWR|O_NONBLOCK|O_LARGEFILE|O_CLOEXEC) = 18 fcntl(18, F_SETFD, FD_CLOEXEC) = 0 ioctl(18, TUNSETIFF, 0xffffd2602fd8) = 0 ioctl(18, TUNSETOFFLOAD, 0x17)

gbionescu commented 3 years ago

Hi @magnate3,

I took another look at the output and don't find an obvious reason for the failure just from the logs.

I also tried reproducing it with different kernels on an aarch64 machine but it doesn't trigger on our side, which could indicate that the kernel that you are using is somehow different from the one that I used, which is 5.4.0, based on an Ubuntu 20.04.

Could you give us a few details on the environment you are running on? Information on the processor model and overall environment would be useful. I also noticed that you're running Ubuntu with a 5.0.0 kernel. Is this the vanilla version of the kernel? What Ubuntu version are you using?

You might also see valuable information by enabling the logging feature. Just add --log-path logs.fifo --level Debug --show-level --show-log-origin to the Firecracker parameter list. Make sure that an empty file called logs.fifo exists first by running touch logs.fifo.

Thanks!

magnate3 commented 3 years ago

@gc-plp thanks for you detail response.

root@ubuntu:~# uname -a Linux ubuntu 5.0.0-23-generic #24~18.04.1-Ubuntu SMP Mon Jul 29 16:10:24 UTC 2019 aarch64 aarch64 aarch64 GNU/Linux root@ubuntu:~# cat /etc/os-release NAME="Ubuntu" VERSION="18.04.3 LTS (Bionic Beaver)" ID=ubuntu ID_LIKE=debian PRETTY_NAME="Ubuntu 18.04.3 LTS" VERSION_ID="18.04" HOME_URL="https://www.ubuntu.com/" SUPPORT_URL="https://help.ubuntu.com/" BUG_REPORT_URL="https://bugs.launchpad.net/ubuntu/" PRIVACY_POLICY_URL="https://www.ubuntu.com/legal/terms-and-policies/privacy-policy" VERSION_CODENAME=bionic UBUNTU_CODENAME=bionic root@ubuntu:~# lscpu Architecture: aarch64 Byte Order: Little Endian CPU(s): 64 On-line CPU(s) list: 0-63 Thread(s) per core: 1 Core(s) per socket: 32 Socket(s): 2 NUMA node(s): 4 Vendor ID: ARM Model: 2 Model name: Cortex-A72 Stepping: r0p2 BogoMIPS: 100.00 L1d cache: 32K L1i cache: 48K L2 cache: 1024K L3 cache: 16384K NUMA node0 CPU(s): 0-15 NUMA node1 CPU(s): 16-31 NUMA node2 CPU(s): 32-47 NUMA node3 CPU(s): 48-63 Flags: fp asimd evtstrm aes pmull sha1 sha2 crc32 cpuid root@ubuntu:~#

root@ubuntu:~# cat logs.fifo Running Firecracker v0.21.0-838-gb0925803 2021-01-06T08:51:18.250088413 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:146] The API server received a Put request on "/boot-source" with body "{\n \"kernel_image_path\": \"/root/rootfs/vmlinux.bin\",\n \"boot_args\": \"keep_bootcon console=ttyS0 reboot=k panic=1 pci=off\"\n }". 2021-01-06T08:51:18.250405095 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:99] The request was executed successfully. Status code: 204 No Content. 2021-01-06T08:51:18.250467995 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:153] Total previous API call duration: 402 us. 2021-01-06T08:51:18.262568993 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:146] The API server received a Put request on "/drives/rootfs" with body "{\n \"drive_id\": \"rootfs\",\n \"path_on_host\": \"/root/rootfs/xenial.rootfs.ext4\",\n \"is_root_device\": true,\n \"is_read_only\": false\n }". 2021-01-06T08:51:18.262852614 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:99] The request was executed successfully. Status code: 204 No Content. 2021-01-06T08:51:18.262922154 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:153] Total previous API call duration: 370 us. 2021-01-06T08:51:18.274666190 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:146] The API server received a Put request on "/network-interfaces/eth0" with body "{\n \"iface_id\": \"eth0\",\n \"guest_mac\": \"AA:FC:00:00:00:AB\",\n \"host_dev_name\": \"ftap0\"\n }". 2021-01-06T08:51:18.276220198 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:99] The request was executed successfully. Status code: 204 No Content. 2021-01-06T08:51:18.276285398 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:153] Total previous API call duration: 1633 us. 2021-01-06T08:51:18.288182575 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:146] The API server received a Put request on "/actions" with body "{\n \"action_type\": \"InstanceStart\"\n }". 2021-01-06T08:51:18.319801646 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:394] Artificially kick devices. 2021-01-06T08:51:18.319912386 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:425] kick net eth0. 2021-01-06T08:51:18.319969446 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:414] kick block rootfs. 2021-01-06T08:51:18.320142147 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:99] The request was executed successfully. Status code: 204 No Content. 2021-01-06T08:51:18.320222008 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:153] Total previous API call duration: 32052 us. 2021-01-06T08:51:18.572132269 [anonymous-instance:main:DEBUG:src/devices/src/virtio/block/event_handler.rs:14] block: activate event 2021-01-06T08:51:18.575952207 [anonymous-instance:main:DEBUG:src/devices/src/virtio/net/event_handler.rs:15] net: activate event

gbionescu commented 3 years ago

The logs.fifo output seems to be captured from a run that's using --seccomp-filter 0 I assume. Could you also paste the output when running without --seccomp-filter 0?

Regarding the firecracker binary, I wanted to confirm with you that you're running ./tools/devtool build --release. Is this correct?

Could you also try running the prebuilt binary on our release page?

magnate3 commented 3 years ago

@gc-plp hello, if I run the prebuilt binary,there is no problem.

the following test is exected by my own firecracker root@ubuntu:~# firecracker --api-sock /tmp/firecracker.socket --log-path logs.fifo --level Debug --show-level --show-log-origin Bad system call root@ubuntu:~# cat logs.fifo Running Firecracker v0.21.0-838-gb0925803 2021-01-06T08:51:18.250088413 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:146] The API server received a Put request on "/boot-source" with body "{\n \"kernel_image_path\": \"/root/rootfs/vmlinux.bin\",\n \"boot_args\": \"keep_bootcon console=ttyS0 reboot=k panic=1 pci=off\"\n }". 2021-01-06T08:51:18.250405095 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:99] The request was executed successfully. Status code: 204 No Content. 2021-01-06T08:51:18.250467995 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:153] Total previous API call duration: 402 us. 2021-01-06T08:51:18.262568993 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:146] The API server received a Put request on "/drives/rootfs" with body "{\n \"drive_id\": \"rootfs\",\n \"path_on_host\": \"/root/rootfs/xenial.rootfs.ext4\",\n \"is_root_device\": true,\n \"is_read_only\": false\n }". 2021-01-06T08:51:18.262852614 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:99] The request was executed successfully. Status code: 204 No Content. 2021-01-06T08:51:18.262922154 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:153] Total previous API call duration: 370 us. 2021-01-06T08:51:18.274666190 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:146] The API server received a Put request on "/network-interfaces/eth0" with body "{\n \"iface_id\": \"eth0\",\n \"guest_mac\": \"AA:FC:00:00:00:AB\",\n \"host_dev_name\": \"ftap0\"\n }". 2021-01-06T08:51:18.276220198 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:99] The request was executed successfully. Status code: 204 No Content. 2021-01-06T08:51:18.276285398 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:153] Total previous API call duration: 1633 us. 2021-01-06T08:51:18.288182575 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:146] The API server received a Put request on "/actions" with body "{\n \"action_type\": \"InstanceStart\"\n }". 2021-01-06T08:51:18.319801646 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:394] Artificially kick devices. 2021-01-06T08:51:18.319912386 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:425] kick net eth0. 2021-01-06T08:51:18.319969446 [anonymous-instance:main:INFO:src/vmm/src/device_manager/mmio.rs:414] kick block rootfs. 2021-01-06T08:51:18.320142147 [anonymous-instance:fc_api:INFO:src/api_server/src/parsed_request.rs:99] The request was executed successfully. Status code: 204 No Content. 2021-01-06T08:51:18.320222008 [anonymous-instance:fc_api:DEBUG:src/api_server/src/lib.rs:153] Total previous API call duration: 32052 us. 2021-01-06T08:51:18.572132269 [anonymous-instance:main:DEBUG:src/devices/src/virtio/block/event_handler.rs:14] block: activate event 2021-01-06T08:51:18.575952207 [anonymous-instance:main:DEBUG:src/devices/src/virtio/net/event_handler.rs:15] net: activate event 2021-01-06T11:19:12.478710783 [anonymous-instance:main:WARN:src/devices/src/legacy/serial.rs:434] Detached the serial input due to peer close/error. 2021-01-06T11:19:12.479307246 [anonymous-instance:main:ERROR:src/vmm/src/signal_handler.rs:124] Shutting down VM after intercepting signal 1, code 0.

gbionescu commented 3 years ago

@magnate3 in the tests that you did before, are you using the binary built using devtool?

If not, are you by any chance running cargo build?

magnate3 commented 3 years ago

I build like this : root@ubuntu:~/myfirecracker/firecracker# tools/devtool build [Firecracker devtool] About to pull docker image fcuvm/dev:v25 [Firecracker devtool] Continue? (y/n) y

gbionescu commented 3 years ago

@magnate3 what commit ID are you basing your build on? What's the output of git log -1?

magnate3 commented 3 years ago

@gc-plp git log -1 commit b0925803c3c34223d717514da959a07a12ab0e27 (HEAD -> master, origin/master, origin/HEAD) Author: Diana Popa dpopa@amazon.com Date: Tue Dec 22 10:44:16 2020 +0200

CI: add git commit message linter

Fixes #1231

Signed-off-by: Diana Popa <dpopa@amazon.com>
gbionescu commented 3 years ago

@magnate3 I'd like to go back a bit to running strace if possible, I seem to have missed a parameter.

Could you add the -f parameter to strace for both runs and run the API call again? Basically we'd need the output for the following two runs:

  1. strace -f -o firecracker.output firecracker --api-sock /tmp/firecracker.socket

  2. strace -f -o firecracker.output firecracker --api-sock /tmp/firecracker.socket --seccomp-level 0

magnate3 commented 3 years ago

@gc-plp root@ubuntu:~/myfirecracker# strace -f -o firecracker.output firecracker --api-sock /tmp/firecracker.socket Bad system call root@ubuntu:~/myfirecracker# cat firecracker.output 10624 execve("/usr/local/bin/firecracker", ["firecracker", "--api-sock", "/tmp/firecracker.socket"], 0xffffe3682448 / 23 vars /) = 0 10624 mmap(NULL, 592, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffff7ffe3000 10624 set_tid_address(0x7e5870) = 10624 10624 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x712414}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 10624 rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 10624 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 10624 rt_sigaction(SIGSEGV, {sa_handler=0x6ec69c, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 10624 rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 10624 rt_sigaction(SIGBUS, {sa_handler=0x6ec69c, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 10624 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 10624 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffff7ffdf000 10624 mprotect(0xffff7ffdf000, 4096, PROT_NONE) = 0 10624 sigaltstack({ss_sp=0xffff7ffe0000, ss_flags=0, ss_size=12288}, NULL) = 0 10624 brk(NULL) = 0x27da0000 10624 brk(0x27da1000) = 0x27da1000 10624 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 10624 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 10624 rt_sigaction(SIGSYS, {sa_handler=0x4679bc, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 10624 rt_sigaction(SIGBUS, {sa_handler=0x466ccc, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 10624 rt_sigaction(SIGSEGV, {sa_handler=0x46711c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 10624 rt_sigaction(SIGXFSZ, {sa_handler=0x46642c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 10624 rt_sigaction(SIGXCPU, {sa_handler=0x46687c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 10624 rt_sigaction(SIGPIPE, {sa_handler=0x46756c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 10624 rt_sigaction(SIGHUP, {sa_handler=0x467e0c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 10624 rt_sigaction(SIGILL, {sa_handler=0x46825c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 10624 brk(0x27da4000) = 0x27da4000 10624 brk(0x27da5000) = 0x27da5000 10624 brk(0x27da6000) = 0x27da6000 10624 eventfd2(0, 0) = 3 10624 dup(3) = 4 10624 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 10624 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffff7fddc000 10624 mprotect(0xffff7fdde000, 2101248, PROT_READ|PROT_WRITE) = 0 10624 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 10624 clone(child_stack=0xffff7ffde980, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tidptr=0xffff7ffde9f8, tls=0xffff7ffdeaa0, child_tidptr=0x7e5870) = 10625 10625 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...> 10624 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...> 10625 <... rt_sigprocmask resumed> NULL, 8) = 0 10624 <... rt_sigprocmask resumed> NULL, 8) = 0 10625 sigaltstack(NULL, <unfinished ...> 10624 epoll_create1(EPOLL_CLOEXEC <unfinished ...> 10625 <... sigaltstack resumed> {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 10624 <... epoll_create1 resumed> ) = 5 10625 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...> 10624 getrandom( <unfinished ...> 10625 <... mmap resumed> ) = 0xffff7fdd8000 10624 <... getrandom resumed> "\xaa\x1a\xd6\xeb\xee\xec\x5b\xab\x13\x4b\x8b\x73\x77\x38\x03\xc8", 16, GRND_NONBLOCK) = 16 10625 mprotect(0xffff7fdd8000, 4096, PROT_NONE <unfinished ...> 10624 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK <unfinished ...> 10625 <... mprotect resumed> ) = 0 10624 <... timerfd_create resumed> ) = 6 10625 sigaltstack({ss_sp=0xffff7fdd9000, ss_flags=0, ss_size=12288}, NULL) = 0 10624 epoll_ctl(5, EPOLL_CTL_ADD, 6, {EPOLLIN, {u32=6, u64=6}} <unfinished ...> 10625 prctl(PR_SET_NAME, "fc_api" <unfinished ...> 10624 <... epoll_ctl resumed> ) = 0 10625 <... prctl resumed> ) = 0 10624 futex(0xffffe1e50ef4, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> 10625 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 7 10625 bind(7, {sa_family=AF_UNIX, sun_path="/tmp/firecracker.socket"}, 26) = 0 10625 listen(7, 128) = 0 10625 epoll_create1(EPOLL_CLOEXEC) = 8 10625 getrandom("\x84\xea\x4d\xcb\x6a\xba\x93\xfe\x64\x86\xd2\x27\x12\xac\xbb\x50", 16, GRND_NONBLOCK) = 16 10625 brk(0x27da7000) = 0x27da7000 10625 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0) = 0 10625 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=270, filter=0x27da6000}) = 0 10625 epoll_ctl(8, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLRDHUP, {u32=7, u64=7}}) = 0 10625 epoll_pwait(8, [{EPOLLIN, {u32=7, u64=7}}], 10, -1, NULL, 8) = 1 10625 accept4(7, {sa_family=AF_UNIX}, [110->2], SOCK_CLOEXEC) = 9 10625 ioctl(9, FIONBIO, [1]) = 0 10625 epoll_ctl(8, EPOLL_CTL_ADD, 9, {EPOLLIN|EPOLLRDHUP, {u32=9, u64=9}}) = 0 10625 epoll_pwait(8, [{EPOLLIN, {u32=9, u64=9}}], 10, -1, NULL, 8) = 1 10625 recvfrom(9, "PUT /boot-source HTTP/1.1\r\nHost:"..., 1024, 0, NULL, NULL) = 303 10625 clock_gettime(CLOCK_MONOTONIC, {tv_sec=0, tv_nsec=0}) = 1 10625 --- SIGSYS {si_signo=SIGSYS, si_code=SYS_SECCOMP, si_call_addr=0xffff7ffe5620, si_syscall=__NR_clock_gettime, si_arch=AUDIT_ARCH_AARCH64} --- 10625 clock_gettime(CLOCK_REALTIME, {tv_sec=0, tv_nsec=0}) = 0 10625 --- SIGSYS {si_signo=SIGSYS, si_code=SYS_SECCOMP, si_call_addr=0xffff7ffe5620, si_syscall=__NR_clock_gettime, si_arch=AUDIT_ARCH_AARCH64} --- 10624 <... futex resumed>) = ? 10625 +++ killed by SIGSYS +++ 10624 +++ killed by SIGSYS +++ strace -f -o firecracker.output firecracker --api-sock /tmp/firecracker.socket --seccomp-level 0

11428 execve("/usr/local/bin/firecracker", ["firecracker", "--api-sock", "/tmp/firecracker.socket", "--seccomp-level", "0"], 0xffffea55b7a8 / 23 vars /) = 0 11428 mmap(NULL, 592, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffb7016000 11428 set_tid_address(0x7e5870) = 11428 11428 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x712414}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 11428 rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 11428 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 11428 rt_sigaction(SIGSEGV, {sa_handler=0x6ec69c, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 11428 rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 11428 rt_sigaction(SIGBUS, {sa_handler=0x6ec69c, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 11428 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 11428 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffb7012000 11428 mprotect(0xffffb7012000, 4096, PROT_NONE) = 0 11428 sigaltstack({ss_sp=0xffffb7013000, ss_flags=0, ss_size=12288}, NULL) = 0 11428 brk(NULL) = 0x36702000 11428 brk(0x36703000) = 0x36703000 11428 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 11428 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 11428 rt_sigaction(SIGSYS, {sa_handler=0x4679bc, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 11428 rt_sigaction(SIGBUS, {sa_handler=0x466ccc, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 11428 rt_sigaction(SIGSEGV, {sa_handler=0x46711c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 11428 rt_sigaction(SIGXFSZ, {sa_handler=0x46642c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 11428 rt_sigaction(SIGXCPU, {sa_handler=0x46687c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 11428 rt_sigaction(SIGPIPE, {sa_handler=0x46756c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 11428 rt_sigaction(SIGHUP, {sa_handler=0x467e0c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 11428 rt_sigaction(SIGILL, {sa_handler=0x46825c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x712414}, NULL, 8) = 0 11428 brk(0x36706000) = 0x36706000 11428 eventfd2(0, 0) = 3 11428 dup(3) = 4 11428 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 11428 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffb6e0f000 11428 mprotect(0xffffb6e11000, 2101248, PROT_READ|PROT_WRITE) = 0 11428 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 11428 clone(child_stack=0xffffb7011980, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tidptr =0xffffb70119f8, tls=0xffffb7011aa0, child_tidptr=0x7e5870) = 11429 11429 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...> 11428 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...> 11429 <... rt_sigprocmask resumed> NULL, 8) = 0 11428 <... rt_sigprocmask resumed> NULL, 8) = 0 11429 sigaltstack(NULL, <unfinished ...> 11428 epoll_create1(EPOLL_CLOEXEC <unfinished ...> 11429 <... sigaltstack resumed> {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 11428 <... epoll_create1 resumed> ) = 5 11429 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...> 11428 getrandom( <unfinished ...> 11429 <... mmap resumed> ) = 0xffffb6e0b000 11428 <... getrandom resumed> "\x0a\x23\x1b\x39\x8e\x0f\xc0\x5e\xcb\x8a\x19\x01\x8b\x5a\x1e\x0e", 16, GRND_NONBLOCK) = 16 11429 mprotect(0xffffb6e0b000, 4096, PROT_NONE <unfinished ...> 11428 brk(0x36707000 <unfinished ...>

gbionescu commented 3 years ago

@magnate3, what's the output of cat /sys/devices/system/clocksource/clocksource0/current_clocksource on your system?

Also, could you update to the latest commit ID and rebuild?

magnate3 commented 3 years ago

@gc-plp cat /sys/devices/system/clocksource/clocksource0/current_clocksource arch_sys_counter And, my firecracker branch is the master branch. I will take you advice and execute git fetch git log -1 commit b0925803c3c34223d717514da959a07a12ab0e27 (HEAD -> master, origin/master, origin/HEAD) Author: Diana Popa dpopa@amazon.com Date: Tue Dec 22 10:44:16 2020 +0200

CI: add git commit message linter

Fixes #1231

Signed-off-by: Diana Popa <dpopa@amazon.com>

root@ubuntu:~/myfirecracker/firecracker# git status On branch master Your branch is up to date with 'origin/master'.

nothing to commit, working tree clean

firecracker# git fetch remote: Enumerating objects: 106, done. remote: Counting objects: 100% (106/106), done. remote: Compressing objects: 100% (15/15), done. remote: Total 132 (delta 93), reused 94 (delta 91), pack-reused 26 Receiving objects: 100% (132/132), 25.72 KiB | 145.00 KiB/s, done. Resolving deltas: 100% (95/95), completed with 59 local objects. From https://github.com/firecracker-microvm/firecracker b0925803..364cf32b master -> origin/master

buf,after I execute fit fetch and tools/devtool build, the firecracker still has the same bug.

cp ./build/cargo_target/aarch64-unknown-linux-musl/debug/firecracker /usr/local/bin/ root@ubuntu:~/myfirecracker/firecracker# firecracker --api-sock /tmp/firecracker.socket Bad system call

gbionescu commented 3 years ago

Hi @magnate3. Thanks for all the info! It's been very useful so far.

I do have a few more requests:

Can you run strace -f -o firecracker.output firecracker --api-sock /tmp/firecracker.socket on our 0.24 release and again on the binary that you've built locally?

Before building the binary on your machine, please make sure that you're checking out the corresponding 0.24 tag by running git reset --hard v0.24.

magnate3 commented 3 years ago

@gc-plp hi， my branck is v0.24.0 root@ubuntu:~/myfirecracker/firecracker# git reset --hard v0.24.0 HEAD is now at 74a5731f Update cargo lock.

after run tools/devtool build

root@ubuntu:~/myfirecracker/firecracker# strace -f -o firecracker.output firecracker --api-sock /tmp/firecracker.socket Bad system call root@ubuntu:~/myfirecracker/firecracker# cat firecracker.output 25219 execve("/usr/local/bin/firecracker", ["firecracker", "--api-sock", "/tmp/firecracker.socket"], 0xffffc8904278 / 23 vars /) = 0 25219 mmap(NULL, 592, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffacbeb000 25219 set_tid_address(0x7e5870) = 25219 25219 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7129b4}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 25219 rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 25219 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 25219 rt_sigaction(SIGSEGV, {sa_handler=0x6ecc38, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7129b4}, NULL, 8) = 0 25219 rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 25219 rt_sigaction(SIGBUS, {sa_handler=0x6ecc38, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x7129b4}, NULL, 8) = 0 25219 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 25219 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffacbe7000 25219 mprotect(0xffffacbe7000, 4096, PROT_NONE) = 0 25219 sigaltstack({ss_sp=0xffffacbe8000, ss_flags=0, ss_size=12288}, NULL) = 0 25219 brk(NULL) = 0x279a000 25219 brk(0x279b000) = 0x279b000 25219 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 25219 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 25219 rt_sigaction(SIGSYS, {sa_handler=0x4b7d40, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7129b4}, NULL, 8) = 0 25219 rt_sigaction(SIGBUS, {sa_handler=0x4b7050, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7129b4}, NULL, 8) = 0 25219 rt_sigaction(SIGSEGV, {sa_handler=0x4b74a0, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7129b4}, NULL, 8) = 0 25219 rt_sigaction(SIGXFSZ, {sa_handler=0x4b67b0, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7129b4}, NULL, 8) = 0 25219 rt_sigaction(SIGXCPU, {sa_handler=0x4b6c00, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7129b4}, NULL, 8) = 0 25219 rt_sigaction(SIGPIPE, {sa_handler=0x4b78f0, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7129b4}, NULL, 8) = 0 25219 rt_sigaction(SIGHUP, {sa_handler=0x4b8190, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7129b4}, NULL, 8) = 0 25219 rt_sigaction(SIGILL, {sa_handler=0x4b85e0, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7129b4}, NULL, 8) = 0 25219 brk(0x279e000) = 0x279e000 25219 brk(0x279f000) = 0x279f000 25219 brk(0x27a0000) = 0x27a0000 25219 eventfd2(0, 0) = 3 25219 dup(3) = 4 25219 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 25219 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffac9e4000 25219 mprotect(0xffffac9e6000, 2101248, PROT_READ|PROT_WRITE) = 0 25219 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 25219 clone(child_stack=0xffffacbe6980, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tidptr=0xffffacbe69f8, tls=0xffffacbe6aa0, child_tidptr=0x7e5870) = 25220 25220 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...> 25219 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...> 25220 <... rt_sigprocmask resumed> NULL, 8) = 0 25219 <... rt_sigprocmask resumed> NULL, 8) = 0 25220 sigaltstack(NULL, <unfinished ...> 25219 epoll_create1(EPOLL_CLOEXEC <unfinished ...> 25220 <... sigaltstack resumed> {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 25219 <... epoll_create1 resumed> ) = 5 25220 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...> 25219 getrandom( <unfinished ...> 25220 <... mmap resumed> ) = 0xffffac9e0000 25219 <... getrandom resumed> "\x53\x4d\x44\x1c\xc7\x98\x81\x0c\x4e\x96\x74\x3c\x0f\x99\x4b\xe1", 16, GRND_NONBLOCK) = 16 25220 mprotect(0xffffac9e0000, 4096, PROT_NONE <unfinished ...> 25219 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK <unfinished ...> 25220 <... mprotect resumed> ) = 0 25219 <... timerfd_create resumed> ) = 6 25220 sigaltstack({ss_sp=0xffffac9e1000, ss_flags=0, ss_size=12288}, NULL) = 0 25220 prctl(PR_SET_NAME, "fc_api") = 0 25220 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 7 25220 bind(7, {sa_family=AF_UNIX, sun_path="/tmp/firecracker.socket"}, 26) = 0 25220 listen(7, 128) = 0 25220 epoll_create1(EPOLL_CLOEXEC) = 8 25220 getrandom("\x70\x19\x64\x02\x1d\x7e\x1e\x51\x1b\xb0\xd3\x84\x3c\x8d\x7d\xf4", 16, GRND_NONBLOCK) = 16 25219 epoll_ctl(5, EPOLL_CTL_ADD, 6, {EPOLLIN, {u32=6, u64=6}} <unfinished ...> 25220 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0 <unfinished ...> 25219 <... epoll_ctl resumed> ) = 0 25220 <... prctl resumed> ) = 0 25220 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=270, filter=0x279ec40} <unfinished ...> 25219 futex(0xffffe45a93a4, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> 25220 <... prctl resumed> ) = 0 25220 epoll_ctl(8, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLRDHUP, {u32=7, u64=7}}) = 0 25220 epoll_pwait(8, [{EPOLLIN, {u32=7, u64=7}}], 10, -1, NULL, 8) = 1 25220 accept4(7, {sa_family=AF_UNIX}, [110->2], SOCK_CLOEXEC) = 9 25220 ioctl(9, FIONBIO, [1]) = 0 25220 epoll_ctl(8, EPOLL_CTL_ADD, 9, {EPOLLIN|EPOLLRDHUP, {u32=9, u64=9}}) = 0 25220 brk(0x27a1000) = 0x27a1000 25220 epoll_pwait(8, [{EPOLLIN, {u32=9, u64=9}}], 10, -1, NULL, 8) = 1 25220 recvfrom(9, "PUT /boot-source HTTP/1.1\r\nHost:"..., 1024, 0, NULL, NULL) = 303 25220 clock_gettime(CLOCK_MONOTONIC, {tv_sec=0, tv_nsec=0}) = 1 25220 --- SIGSYS {si_signo=SIGSYS, si_code=SYS_SECCOMP, si_call_addr=0xffffacbed620, si_syscall=__NR_clock_gettime, si_arch=AUDIT_ARCH_AARCH64} --- 25220 clock_gettime(CLOCK_REALTIME, {tv_sec=0, tv_nsec=0}) = 0 25220 --- SIGSYS {si_signo=SIGSYS, si_code=SYS_SECCOMP, si_call_addr=0xffffacbed620, si_syscall=__NR_clock_gettime, si_arch=AUDIT_ARCH_AARCH64} --- 25219 <... futex resumed>) = ? 25220 +++ killed by SIGSYS +++ 25219 +++ killed by SIGSYS +++

gbionescu commented 3 years ago

@magnate3 could also run the same strace test with the prebuilt 0.24 release?

magnate3 commented 3 years ago

@gc-plp ok, strace -f -o firecracker.output ./firecracker-v0.24.0-aarch64 --api-sock /tmp/firecracker.socket Bad system call

cat firecracker.output 35538 execve("./firecracker-v0.24.0-aarch64", ["./firecracker-v0.24.0-aarch64", "--api-sock", "/tmp/firecracker.socket"], 0xffffde786688 / 23 vars /) = 0 35538 mmap(NULL, 592, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffa5271000 35538 set_tid_address(0x594868) = 35538 35538 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x53fee4}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 35538 rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 35538 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 35538 rt_sigaction(SIGSEGV, {sa_handler=0x4a59b8, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 35538 rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 35538 rt_sigaction(SIGBUS, {sa_handler=0x4a59b8, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 35538 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 35538 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffa526d000 35538 mprotect(0xffffa526d000, 4096, PROT_NONE) = 0 35538 sigaltstack({ss_sp=0xffffa526e000, ss_flags=0, ss_size=12288}, NULL) = 0 35538 brk(NULL) = 0x2adfa000 35538 brk(0x2adfb000) = 0x2adfb000 35538 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 35538 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 35538 rt_sigaction(SIGSYS, {sa_handler=0x502ce8, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 35538 rt_sigaction(SIGBUS, {sa_handler=0x503078, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 35538 rt_sigaction(SIGSEGV, {sa_handler=0x503384, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 35538 rt_sigaction(SIGXFSZ, {sa_handler=0x503690, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 35538 rt_sigaction(SIGXCPU, {sa_handler=0x50399c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 35538 rt_sigaction(SIGPIPE, {sa_handler=0x503ca8, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 35538 rt_sigaction(SIGHUP, {sa_handler=0x503fb4, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 35538 rt_sigaction(SIGILL, {sa_handler=0x5042c0, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 35538 brk(0x2adfe000) = 0x2adfe000 35538 brk(0x2adff000) = 0x2adff000 35538 brk(0x2ae00000) = 0x2ae00000 35538 eventfd2(0, 0) = 3 35538 dup(3) = 4 35538 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 35538 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffa506a000 35538 mprotect(0xffffa506c000, 2101248, PROT_READ|PROT_WRITE) = 0 35538 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 35538 clone(child_stack=0xffffa526c980, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tidptr=0xffffa526c9f8, tls=0xffffa526caa0, child_tidptr=0x594868) = 35539 35539 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...> 35538 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...> 35539 <... rt_sigprocmask resumed> NULL, 8) = 0 35538 <... rt_sigprocmask resumed> NULL, 8) = 0 35539 sigaltstack(NULL, <unfinished ...> 35538 epoll_create1(EPOLL_CLOEXEC <unfinished ...> 35539 <... sigaltstack resumed> {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 35538 <... epoll_create1 resumed> ) = 5 35539 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...> 35538 getrandom( <unfinished ...> 35539 <... mmap resumed> ) = 0xffffa5066000 35538 <... getrandom resumed> "\x75\x5c\x3c\xaa\xda\xb7\x55\xf4\x5c\xd8\xf5\x44\x19\x90\x50\x0f", 16, GRND_NONBLOCK) = 16 35539 mprotect(0xffffa5066000, 4096, PROT_NONE <unfinished ...> 35538 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK <unfinished ...> 35539 <... mprotect resumed> ) = 0 35538 <... timerfd_create resumed> ) = 6 35539 sigaltstack({ss_sp=0xffffa5067000, ss_flags=0, ss_size=12288}, <unfinished ...> 35538 epoll_ctl(5, EPOLL_CTL_ADD, 6, {EPOLLIN, {u32=6, u64=6}} <unfinished ...> 35539 <... sigaltstack resumed> NULL) = 0 35538 <... epoll_ctl resumed> ) = 0 35539 prctl(PR_SET_NAME, "fc_api" <unfinished ...> 35538 futex(0xffffe7f7c5c4, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> 35539 <... prctl resumed> ) = 0 35539 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 7 35539 bind(7, {sa_family=AF_UNIX, sun_path="/tmp/firecracker.socket"}, 26) = 0 35539 listen(7, 128) = 0 35539 epoll_create1(EPOLL_CLOEXEC) = 8 35539 getrandom("\xf0\xe9\x9f\x13\x9b\x94\x17\x97\xc9\xa9\xd8\x80\x7d\x40\xf8\x55", 16, GRND_NONBLOCK) = 16 35539 brk(0x2ae01000) = 0x2ae01000 35539 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0) = 0 35539 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=270, filter=0x2ae00000}) = 0 35539 epoll_ctl(8, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLRDHUP, {u32=7, u64=7}}) = 0 35539 epoll_pwait(8, [{EPOLLIN, {u32=7, u64=7}}], 10, -1, NULL, 8) = 1 35539 accept4(7, {sa_family=AF_UNIX}, [110->2], SOCK_CLOEXEC) = 9 35539 ioctl(9, FIONBIO, [1]) = 0 35539 epoll_ctl(8, EPOLL_CTL_ADD, 9, {EPOLLIN|EPOLLRDHUP, {u32=9, u64=9}}) = 0 35539 epoll_pwait(8, [{EPOLLIN, {u32=9, u64=9}}], 10, -1, NULL, 8) = 1 35539 recvfrom(9, "PUT /boot-source HTTP/1.1\r\nHost:"..., 1024, 0, NULL, NULL) = 303 35539 clock_gettime(CLOCK_MONOTONIC, {tv_sec=0, tv_nsec=0}) = 1 35539 --- SIGSYS {si_signo=SIGSYS, si_code=SYS_SECCOMP, si_call_addr=0xffffa5273620, si_syscall=__NR_clock_gettime, si_arch=AUDIT_ARCH_AARCH64} --- 35539 clock_gettime(CLOCK_REALTIME, {tv_sec=0, tv_nsec=0}) = 0 35539 --- SIGSYS {si_signo=SIGSYS, si_code=SYS_SECCOMP, si_call_addr=0xffffa5273620, si_syscall=__NR_clock_gettime, si_arch=AUDIT_ARCH_AARCH64} --- 35538 <... futex resumed>) = ? 35539 +++ killed by SIGSYS +++ 35538 +++ killed by SIGSYS +++

alindima commented 3 years ago

Thanks @magnate3 for reporting this issue and giving us all the requested information.

The Firecracker process is terminated by the clock_gettime syscall, which is called with CLOCK_MONOTONIC and then with CLOCK_REALTIME. As of Firecracker v0.24.0, the default seccomp allowlist only allows clock_gettime with the CLOCK_PROCESS_CPUTIME_ID option: https://github.com/firecracker-microvm/firecracker/blob/b75fc9dc94a004ab3498fb2f3cb87b0f8e5bfaf8/src/vmm/src/default_syscalls/filters.rs#L43

This issue is not reproduced on all platforms and environments because of vdso. Vdso is a linux shared library that implements a couple of frequently used syscalls in user space, to improve application performance.

For example, for aarch64, these are:

       __kernel_gettimeofday
       __kernel_clock_gettime
       __kernel_clock_getres

Calling a system call through vdso, in userspace, essentially bypasses seccomp filters. This is a long-known problem of seccomp: https://lwn.net/Articles/795128/.

Musl, the default libc implementation that Firecracker uses, first tries to find the according symbol in the vdso library. If it doesn't exist there, it falls back to calling the actual clock_gettime system call.

It would be interesting to see what platform are you testing on (CPU model, etc.) and whether you have any special configuration that disables vdso.

We are going to shortly publish a fix for your issue.

Thank you again for reporting this and all your cooperation.

alindima commented 3 years ago

The PR addressing this issue is merged, please confirm that it fixes your problem. Run a git reset --hard upstream/master and rerun the reproduction scenario.

magnate3 commented 3 years ago

@alindima thanks,but there is still the same problem

root@ubuntu:~/myfirecracker/firecracker# git branch --all all

alindima commented 3 years ago

Can you please first run a git fetch --all and git reset --hard upstream/master. If the issue persists, please run Firecracker with strace, like so: strace -f -o firecracker.output firecracker --api-sock /tmp/firecracker.socket, to see what the faulty syscall is now.

magnate3 commented 3 years ago

@alindima thanks, but the problem still exist

root@ubuntu:~/myfirecracker/firecracker# git fetch --all Fetching origin remote: Enumerating objects: 95, done. remote: Counting objects: 100% (95/95), done. remote: Compressing objects: 100% (49/49), done. remote: Total 98 (delta 60), reused 76 (delta 46), pack-reused 3 Unpacking objects: 100% (98/98), done. From https://github.com/firecracker-microvm/firecracker 364cf32b..16af75a4 master -> origin/master

root@ubuntu:~/myfirecracker/firecracker # git reset --hard origin/master HEAD is now at 16af75a4 Removed sysconf dependency root@ubuntu:~/myfirecracker/firecracker#

root@ubuntu:~/myfirecracker/firecracker# tools/devtool build [Firecracker devtool] About to pull docker image public.ecr.aws/firecracker/fcuvm:v27 [Firecracker devtool] Continue? (y/n) y v27: Pulling from firecracker/fcuvm Digest: sha256:18a213f6f567221fe68ea176e18d4a1562523f997ce6e1791c2715cabea1e75f Status: Downloaded newer image for public.ecr.aws/firecracker/fcuvm:v27 public.ecr.aws/firecracker/fcuvm:v27 [Firecracker devtool] Starting build (debug, musl) ... Compiling firecracker v0.24.0 (/firecracker/src/firecracker) Compiling vm-memory v0.1.0 (/firecracker/src/vm-memory) Compiling utils v0.1.0 (/firecracker/src/utils) Compiling logger v0.1.0 (/firecracker/src/logger) Compiling polly v0.0.1 (/firecracker/src/polly) Compiling arch v0.1.0 (/firecracker/src/arch) Compiling kernel v0.1.0 (/firecracker/src/kernel) Compiling micro_http v0.1.0 (/firecracker/src/micro_http) Compiling rate_limiter v0.1.0 (/firecracker/src/rate_limiter) Compiling dumbo v0.1.0 (/firecracker/src/dumbo) Compiling mmds v0.1.0 (/firecracker/src/mmds) Compiling devices v0.1.0 (/firecracker/src/devices) Compiling vmm v0.1.0 (/firecracker/src/vmm) Compiling api_server v0.1.0 (/firecracker/src/api_server) Finished dev [unoptimized + debuginfo] target(s) in 22.24s Compiling jailer v0.24.0 (/firecracker/src/jailer) Compiling utils v0.1.0 (/firecracker/src/utils) Finished dev [unoptimized + debuginfo] target(s) in 3.75s [Firecracker devtool] Build successful. [Firecracker devtool] Binaries placed under /root/myfirecracker/firecracker/build/cargo_target/aarch64-unknown-linux-musl/debug root@ubuntu:~/myfirecracker/firecracker# ls /root/myfirecracker/firecracker/build/cargo_target/aarch64-unknown-linux-musl/debug build deps examples firecracker firecracker.d incremental jailer jailer.d root@ubuntu:~/myfirecracker/firecracker# cp /root/myfirecracker/firecracker/build/cargo_target/aarch64-unknown-linux-musl/debug/firecracker /usr/local/bin/

root@ubuntu:~/myfirecracker/firecracker# strace -f -o firecracker.output ./firecracker-v0.24.0-aarch64 --api-sock /tmp/firecracker.socket Bad system call root@ubuntu:~/myfirecracker/firecracker# cat firecracker.output 63779 execve("./firecracker-v0.24.0-aarch64", ["./firecracker-v0.24.0-aarch64", "--api-sock", "/tmp/firecracker.socket"], 0xffffc8630758 / 23 vars /) = 0 63779 mmap(NULL, 592, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffb62c7000 63779 set_tid_address(0x594868) = 63779 63779 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x53fee4}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 63779 rt_sigaction(SIGSEGV, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 63779 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 63779 rt_sigaction(SIGSEGV, {sa_handler=0x4a59b8, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 63779 rt_sigaction(SIGBUS, NULL, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0 63779 rt_sigaction(SIGBUS, {sa_handler=0x4a59b8, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 63779 sigaltstack(NULL, {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 63779 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffb62c3000 63779 mprotect(0xffffb62c3000, 4096, PROT_NONE) = 0 63779 sigaltstack({ss_sp=0xffffb62c4000, ss_flags=0, ss_size=12288}, NULL) = 0 63779 brk(NULL) = 0x16551000 63779 brk(0x16552000) = 0x16552000 63779 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 63779 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 63779 rt_sigaction(SIGSYS, {sa_handler=0x502ce8, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 63779 rt_sigaction(SIGBUS, {sa_handler=0x503078, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 63779 rt_sigaction(SIGSEGV, {sa_handler=0x503384, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 63779 rt_sigaction(SIGXFSZ, {sa_handler=0x503690, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 63779 rt_sigaction(SIGXCPU, {sa_handler=0x50399c, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 63779 rt_sigaction(SIGPIPE, {sa_handler=0x503ca8, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 63779 rt_sigaction(SIGHUP, {sa_handler=0x503fb4, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 63779 rt_sigaction(SIGILL, {sa_handler=0x5042c0, sa_mask=~[RTMIN RT_1 RT_2], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x53fee4}, NULL, 8) = 0 63779 brk(0x16555000) = 0x16555000 63779 brk(0x16556000) = 0x16556000 63779 brk(0x16557000) = 0x16557000 63779 eventfd2(0, 0) = 3 63779 dup(3) = 4 63779 rt_sigprocmask(SIG_UNBLOCK, [RT_1 RT_2], NULL, 8) = 0 63779 mmap(NULL, 2109440, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xffffb60c0000 63779 mprotect(0xffffb60c2000, 2101248, PROT_READ|PROT_WRITE) = 0 63779 rt_sigprocmask(SIG_BLOCK, ~[RTMIN RT_1 RT_2], [], 8) = 0 63779 clone(child_stack=0xffffb62c2980, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID|0x400000, parent_tidptr=0xffffb62c29f8, tls=0xffffb62c2aa0, child_tidptr=0x594868) = 63780 63780 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...> 63779 rt_sigprocmask(SIG_SETMASK, [], <unfinished ...> 63780 <... rt_sigprocmask resumed> NULL, 8) = 0 63779 <... rt_sigprocmask resumed> NULL, 8) = 0 63780 sigaltstack(NULL, <unfinished ...> 63779 epoll_create1(EPOLL_CLOEXEC <unfinished ...> 63780 <... sigaltstack resumed> {ss_sp=NULL, ss_flags=SS_DISABLE, ss_size=0}) = 0 63779 <... epoll_create1 resumed> ) = 5 63780 mmap(NULL, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0 <unfinished ...> 63779 getrandom( <unfinished ...> 63780 <... mmap resumed> ) = 0xffffb60bc000 63779 <... getrandom resumed> "\x55\x25\x70\x1d\xb4\xb8\x1c\x52\x62\x3b\xfe\x12\x47\xec\x31\x53", 16, GRND_NONBLOCK) = 16 63780 mprotect(0xffffb60bc000, 4096, PROT_NONE <unfinished ...> 63779 timerfd_create(CLOCK_MONOTONIC, TFD_CLOEXEC|TFD_NONBLOCK <unfinished ...> 63780 <... mprotect resumed> ) = 0 63779 <... timerfd_create resumed> ) = 6 63780 sigaltstack({ss_sp=0xffffb60bd000, ss_flags=0, ss_size=12288}, <unfinished ...> 63779 epoll_ctl(5, EPOLL_CTL_ADD, 6, {EPOLLIN, {u32=6, u64=6}} <unfinished ...> 63780 <... sigaltstack resumed> NULL) = 0 63779 <... epoll_ctl resumed> ) = 0 63780 prctl(PR_SET_NAME, "fc_api" <unfinished ...> 63779 futex(0xfffffeba8f44, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> 63780 <... prctl resumed> ) = 0 63780 socket(AF_UNIX, SOCK_STREAM|SOCK_CLOEXEC, 0) = 7 63780 bind(7, {sa_family=AF_UNIX, sun_path="/tmp/firecracker.socket"}, 26) = 0 63780 listen(7, 128) = 0 63780 epoll_create1(EPOLL_CLOEXEC) = 8 63780 getrandom("\xca\xb5\x4c\x30\x85\xf8\x4c\x95\xa2\x39\x06\x70\xf9\xfd\x9f\x1b", 16, GRND_NONBLOCK) = 16 63780 brk(0x16558000) = 0x16558000 63780 prctl(PR_SET_NO_NEW_PRIVS, 1, 0, 0, 0) = 0 63780 prctl(PR_SET_SECCOMP, SECCOMP_MODE_FILTER, {len=270, filter=0x16557000}) = 0 63780 epoll_ctl(8, EPOLL_CTL_ADD, 7, {EPOLLIN|EPOLLRDHUP, {u32=7, u64=7}}) = 0 63780 epoll_pwait(8, [{EPOLLIN, {u32=7, u64=7}}], 10, -1, NULL, 8) = 1 63780 accept4(7, {sa_family=AF_UNIX}, [110->2], SOCK_CLOEXEC) = 9 63780 ioctl(9, FIONBIO, [1]) = 0 63780 epoll_ctl(8, EPOLL_CTL_ADD, 9, {EPOLLIN|EPOLLRDHUP, {u32=9, u64=9}}) = 0 63780 epoll_pwait(8, [{EPOLLIN, {u32=9, u64=9}}], 10, -1, NULL, 8) = 1 63780 recvfrom(9, "PUT /boot-source HTTP/1.1\r\nHost:"..., 1024, 0, NULL, NULL) = 303 63780 clock_gettime(CLOCK_MONOTONIC, {tv_sec=0, tv_nsec=0}) = 1 63780 --- SIGSYS {si_signo=SIGSYS, si_code=SYS_SECCOMP, si_call_addr=0xffffb62c9620, si_syscall=__NR_clock_gettime, si_arch=AUDIT_ARCH_AARCH64} --- 63780 clock_gettime(CLOCK_REALTIME, {tv_sec=0, tv_nsec=0}) = 0 63780 --- SIGSYS {si_signo=SIGSYS, si_code=SYS_SECCOMP, si_call_addr=0xffffb62c9620, si_syscall=__NR_clock_gettime, si_arch=AUDIT_ARCH_AARCH64} --- 63779 <... futex resumed>) = ? 63780 +++ killed by SIGSYS +++ 63779 +++ killed by SIGSYS +++

alindima commented 3 years ago

Looking into the log you pasted, you are running firecracker v0.24, not the latest Firecracker: strace -f -o firecracker.output ./firecracker-v0.24.0-aarch64 --api-sock /tmp/firecracker.socket

You copied the latest binary into /usr/local/bin, but then used firecracker-v0.24.0-aarch64. Try executing firecracker instead of firecracker-v0.24.0-aarch64 in the strace command

magnate3 commented 3 years ago

@alindima nice,thank you .This is caused by my carelessness.now, the problem is solved. Starting Daily apt download activities... [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Discard unused blocks. [ OK ] Started fcnet.service. [ OK ] Started OpenBSD Secure Shell server. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. [ OK ] Started Daily apt download activities. Starting Daily apt upgrade and clean activities... [ OK ] Started Daily apt upgrade and clean activities.

Ubuntu 18.04.2 LTS fadfdd4af58a ttyS0

fadfdd4af58a login:

alindima commented 3 years ago

great to hear, thanks