Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

firecracker coredump #2393

Closed
magnate3 opened this issue Dec 25, 2020 · 29 comments · Fixed by #2404
Closed

firecracker coredump #2393

magnate3 opened this issue Dec 25, 2020 · 29 comments · Fixed by #2404
Labels
Type: Bug Indicates an unexpected problem or unintended behavior

Comments

@magnate3
Copy link

magnate3 commented Dec 25, 2020

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

@magnate3 magnate3 added the Type: Bug Indicates an unexpected problem or unintended behavior label Dec 25, 2020
@magnate3 magnate3 changed the title [Bug] Title firecracker coredump Dec 25, 2020
@gbionescu
Copy link

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
Copy link
Author

magnate3 commented Dec 30, 2020

@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
Copy link
Author

magnate3 commented Dec 30, 2020

@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
Copy link

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
Copy link
Author

magnate3 commented Jan 4, 2021

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
Copy link

gbionescu commented Jan 5, 2021

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
Copy link
Author

magnate3 commented Jan 6, 2021

@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
Copy link

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
Copy link
Author

magnate3 commented Jan 7, 2021

@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
Copy link

@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
Copy link
Author

magnate3 commented Jan 7, 2021

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
Copy link

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

@magnate3
Copy link
Author

magnate3 commented Jan 7, 2021

@gc-plp
git log -1
commit b092580 (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
Copy link

gbionescu commented Jan 7, 2021

@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
Copy link
Author

magnate3 commented Jan 7, 2021

@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
Copy link

@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
Copy link
Author

magnate3 commented Jan 8, 2021

@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 b092580 (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
b092580..364cf32 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
Copy link

gbionescu commented Jan 11, 2021

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
Copy link
Author

magnate3 commented Jan 11, 2021

@gc-plp hi, my branck is v0.24.0
root@ubuntu:~/myfirecracker/firecracker# git reset --hard v0.24.0
HEAD is now at 74a5731 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
Copy link

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

@magnate3
Copy link
Author

@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
Copy link
Contributor

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:

libc::CLOCK_PROCESS_CPUTIME_ID as u64

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
Copy link
Contributor

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
Copy link
Author

@alindima thanks,but there is still the same problem

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

  • master
    remotes/origin/HEAD -> origin/master
    remotes/origin/feature/aarch64_snapshot
    remotes/origin/feature/balloon
    remotes/origin/feature/diff-snapshot
    remotes/origin/feature/file_based_seccomp
    remotes/origin/feature/gdb_server
    remotes/origin/feature/macvtap
    remotes/origin/feature/seccomp_audit
    remotes/origin/fix-v0.18.1
    remotes/origin/fix-v0.19.1
    remotes/origin/fix-v0.20.1
    remotes/origin/fix-v0.21.1
    remotes/origin/fix-v0.21.2
    remotes/origin/fix-v0.21.3
    remotes/origin/fix-v0.22.1
    remotes/origin/gpl_snaps_sanity_checks
    remotes/origin/little_fixes_up
    remotes/origin/master
    remotes/origin/poc/cold-migration
    remotes/origin/v0.15.1
    remotes/origin/v0.15.2
    remotes/origin/v0.22.0
    remotes/origin/v0.22.2
    remotes/origin/v0.23.0
    remotes/origin/v0.23.1
    remotes/origin/v0.23.2
    remotes/origin/v0.24.0
    root@ubuntu:/myfirecracker/firecracker# git reset --hard master
    HEAD is now at 74a5731 Update cargo lock.
    root@ubuntu:
    /myfirecracker/firecracker# tools/devtool build
    [Firecracker devtool] Starting build (debug, musl) ...
    Compiling firecracker v0.24.0 (/firecracker/src/firecracker)
    Finished dev [unoptimized + debuginfo] target(s) in 4.14s
    Compiling jailer v0.24.0 (/firecracker/src/jailer)
    Finished dev [unoptimized + debuginfo] target(s) in 2.34s
    [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# rm /tmp/firecracker.socket
    root@ubuntu:
    /myfirecracker/firecracker# strace -f -o firecracker.output ./firecracker-v0.24.0-aarch64 --api-sock /tmp/firecracker.socket
    Bad system call

@alindima
Copy link
Contributor

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.

@alindima alindima reopened this Jan 12, 2021
@magnate3
Copy link
Author

magnate3 commented Jan 12, 2021

@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
364cf32..16af75a master -> origin/master

root@ubuntu:/myfirecracker/firecracker # git reset --hard origin/master
HEAD is now at 16af75a 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
Copy link
Contributor

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
Copy link
Author

@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
Copy link
Contributor

great to hear, thanks

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Type: Bug Indicates an unexpected problem or unintended behavior
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants