The node.js http-server package does not run correctly #2451
Description
The http-server package is a popular Node.js package for running a simple http server. It does not seem to run correctly in shadow. The simulation completes successfully, but curl never is able to connect to the server. The server seems to get stuck just after starting when the main thread exits. From the shimlog, it appears that the main thread causes a segfault which is caught by a signal handler, but the thread is later killed with tgkill().
general:
stop_time: 10s
model_unblocked_syscall_latency: true
network:
graph:
type: 1_gbit_switch
hosts:
server:
network_node_id: 0
processes:
- path: /usr/bin/node
args: /usr/local/bin/http-server -p 80 -d
start_time: 3s
client:
network_node_id: 0
processes:
- path: /usr/bin/curl
args: -s server
start_time: 5sapt install npm
npm install http-server -g
rm -rf shadow.data && ../shadow/build/src/main/shadow --strace-logging-mode standard --log-level trace shadow.yaml > shadow.logLast server strace commands:
00:00:03.001 [tid 1000] close(17) = 0
00:00:03.001 [tid 1000] ioctl(2, 21505) = -25 (ENOTTY: Not a typewriter)
00:00:03.001 [tid 1000] fstat(...) = 0
00:00:03.001 [tid 1000] ioctl(2, 21505) = -25 (ENOTTY: Not a typewriter)
00:00:03.001 [tid 1000] fstat(...) = 0
00:00:03.001 [tid 1000] ioctl(2, 21505) = -25 (ENOTTY: Not a typewriter)
00:00:03.001 [tid 1000] fstat(...) = 0
00:00:03.001 [tid 1000] ioctl(2, 21505) = -25 (ENOTTY: Not a typewriter)
00:00:03.001 [tid 1000] fstat(...) = 0
00:00:03.001 [tid 1000] uname(...) = 0
00:00:03.001 [tid 1000] shadow_hostname_to_addr_ipv4(...) = 0
Shadow log around when the server last runs:
00:00:04.854050 [29191:shadow-worker] 00:00:03.001645710 [TRACE] [server:11.0.0.2] [syscall_handler.c:200] [_syscallhandler_post_syscall] SYSCALL_HANDLER_POST(node,pid=1000): syscall 1003 shadow_hostname_to_addr_ipv4 result: state=DONE val=0(n/a)
00:00:04.854063 [29191:shadow-worker] 00:00:03.001645710 [TRACE] [server:11.0.0.2] [syscall_handler.c:617] [syscallhandler_make_syscall] Unapplied CPU latencyamt=0 max=1000
00:00:05.443290 [29191:shadow-worker] 00:00:03.001645710 [TRACE] [server:11.0.0.2] [managed_thread.c:242] [_managedthread_waitForNextEvent] received shim_event 2
00:00:05.443324 [29191:shadow-worker] 00:00:03.001645710 [TRACE] [server:11.0.0.2] [managed_thread.c:175] [_managedthread_cleanup] child 29193 exited
00:00:05.443332 [29191:shadow-worker] 00:00:03.001645710 [INFO] [server:11.0.0.2] [syscall_handler.c:102] [_syscallhandler_free] handled 1501 syscalls
00:00:05.443450 [29191:shadow-worker] 00:00:03.001645710 [INFO] [server:11.0.0.2] [syscall_handler.c:108] [_syscallhandler_free] Thread 1000 (node) syscall counts: {statx:515, open:134, close:117, brk:116, mprotect:111, futex:93, read:86, mmap:49, munmap:44, newfstatat:42, openat:42, pread64:34, ioctl:26, shadow_yield:20, rt_sigprocmask:17, fstat:12, getpid:8, clone:6, prlimit64:5, rt_sigaction:5, fcntl:3, pipe2:3, epoll_create1:2, eventfd2:2, getrandom:2, uname:2, write:2, shadow_hostname_to_addr_ipv4:1, shadow_init_memory_manager:1, sysinfo:1}
00:00:05.443642 [29191:shadow-worker] 00:00:03.001645710 [TRACE] [server:11.0.0.2] [descriptor.c:84] [legacyfile_unref] Descriptor 0x7f15200047e0 strong_ref-- to 0 (weak_ref=0)
00:00:05.443655 [29191:shadow-worker] 00:00:03.001645710 [TRACE] [server:11.0.0.2] [descriptor.c:61] [_legacyfile_free] Descriptor 0x7f15200047e0 calling vtable free now
00:00:05.443679 [29191:shadow-worker] 00:00:03.001645710 [DEBUG] [server:11.0.0.2] [process.c:704] [process_continue] process 'server.node.1000' done continuing
00:00:05.443685 [29191:shadow-worker] 00:00:03.001645710 [DEBUG] [server:11.0.0.2] [process.c:490] [_process_check_thread] thread 1000 in process 'server.node.1000' exited with code 0
00:00:05.443831 [29174:shadow] n/a [DEBUG] [n/a] [manager.rs:437] [shadow_rs::core::manager] Finished execution window [3001000050--3002000050], next event at 3002344000
00:00:05.443884 [29191:shadow-worker] 00:00:03.002344000 [TRACE] [server:11.0.0.2] [timer.rs:113] [shadow_rs::host::timer] Expired Timer no longer exists.
00:00:05.443905 [29191:shadow-worker] 00:00:03.002545000 [TRACE] [server:11.0.0.2] [timer.rs:113] [shadow_rs::host::timer] Expired Timer no longer exists.
00:00:05.443918 [29191:shadow-worker] 00:00:03.002549000 [TRACE] [server:11.0.0.2] [timer.rs:113] [shadow_rs::host::timer] Expired Timer no longer exists.
00:00:05.444004 [29174:shadow] n/a [DEBUG] [n/a] [manager.rs:437] [shadow_rs::core::manager] Finished execution window [3002344000--3003344000], next event at 3003479000
00:00:05.444042 [29191:shadow-worker] 00:00:03.003479000 [TRACE] [server:11.0.0.2] [timer.rs:113] [shadow_rs::host::timer] Expired Timer no longer exists.
00:00:05.444058 [29191:shadow-worker] 00:00:03.003483000 [TRACE] [server:11.0.0.2] [timer.rs:113] [shadow_rs::host::timer] Expired Timer no longer exists.
00:00:05.444142 [29174:shadow] n/a [DEBUG] [n/a] [manager.rs:437] [shadow_rs::core::manager] Finished execution window [3003479000--3004479000], next event at 5000000000
Shim log:
00:00:00.954492 [00:00:03.001665710] [shd-shim] [trace] [shim_api_addrinfo.c:247] [_shim_api_hostname_to_addr_ipv4] SYS_shadow_hostname_to_addr_ipv4 returned addr 11.0.0.2 for name server
00:00:00.954504 [00:00:03.001665710] [shd-shim] [trace] [shim_rdtsc.c:44] [_shim_rdtsc_handle_sigsegv] Trapped sigsegv
00:00:00.954508 [00:00:03.001665710] [shd-shim] [trace] [shim_rdtsc.c:48] [_shim_rdtsc_handle_sigsegv] Initializing tsc
00:00:00.954520 [00:00:03.001665710] [shd-shim] [trace] [shim_rdtsc.c:104] [_shim_rdtsc_handle_sigsegv] SIGSEGV not recognized as rdtsc; handling as error
00:00:00.954555 [00:00:03.001665710] [shd-shim] [trace] [shim_seccomp.c:52] [_shim_seccomp_handle_sigsys] Trapped syscall 13
00:00:00.954560 [00:00:03.001665710] [shd-shim] [trace] [shim_syscall.c:277] [shim_syscallv] Making syscall 13 directly; we expect ptrace or seccomp will interpose it, or it will be handled natively by the kernel.
00:00:00.954564 [00:00:03.001665710] [shd-shim] [trace] [shim_seccomp.c:65] [_shim_seccomp_handle_sigsys] Trapped syscall 13 returning 0
00:00:00.954570 [00:00:03.001665710] [shd-shim] [trace] [shim_seccomp.c:52] [_shim_seccomp_handle_sigsys] Trapped syscall 186
00:00:00.954574 [00:00:03.001665710] [shd-shim] [trace] [shim_syscall.c:277] [shim_syscallv] Making syscall 186 directly; we expect ptrace or seccomp will interpose it, or it will be handled natively by the kernel.
00:00:00.954578 [00:00:03.001665710] [shd-shim] [trace] [shim_seccomp.c:65] [_shim_seccomp_handle_sigsys] Trapped syscall 186 returning 45957
00:00:00.954583 [00:00:03.001665710] [shd-shim] [trace] [shim_seccomp.c:52] [_shim_seccomp_handle_sigsys] Trapped syscall 39
00:00:00.954586 [00:00:03.001665710] [shd-shim] [trace] [shim_syscall.c:277] [shim_syscallv] Making syscall 39 directly; we expect ptrace or seccomp will interpose it, or it will be handled natively by the kernel.
00:00:00.954590 [00:00:03.001665710] [shd-shim] [trace] [shim_seccomp.c:65] [_shim_seccomp_handle_sigsys] Trapped syscall 39 returning 45957
00:00:00.954595 [00:00:03.001665710] [shd-shim] [trace] [shim_seccomp.c:52] [_shim_seccomp_handle_sigsys] Trapped syscall 234
00:00:00.954598 [00:00:03.001665710] [shd-shim] [trace] [shim_syscall.c:277] [shim_syscallv] Making syscall 234 directly; we expect ptrace or seccomp will interpose it, or it will be handled natively by the kernel.