Simulating JVM #2084

bentoumia · 2022-04-25T11:12:49Z

bentoumia
Apr 25, 2022

Hello,

so i am currently working on simulating BFT-SMaRt(https://github.com/bft-smart/library) in Shadow as part of my Bachelor's thesis. Strangely, the simulation works and completes successfully with ptrace but not with LD_PRELOAD. I also tried to simulate just the command
java --version in Shadow and also this does not work with preload. It seems as if it is related to the JVM.

is this maybe related to this(#1549)?

Im very curious to know why this fails in preload and i would be very thankful can explain to me why this happens.

Shadow also never terminates, it just hangs in this state indefinitely, shimlog also shows a SegFault happening:
00:00:00.037584 [00:00:00.000000001] [shd-shim] [error] [shim.c:548] [_handle_sigsegv] Unhandled sigsegv

Here are my logs:

00:00:00.000006 [shadow] n/a [INFO] [n/a] [main.c:68] [main_logBuildInfo] Starting Shadow v2.0.0-pre.4-244-g46437ab1 2021-09-23--18:21:32 with GLib v2.66.1
** Starting Shadow v2.0.0-pre.4-244-g46437ab1 2021-09-23--18:21:32 with GLib v2.66.1
00:00:00.000392 [shadow] n/a [INFO] [n/a] [main.c:72] [main_logBuildInfo] Shadow was built from branch main on 2022-04-21--13:34:53 in Release mode with compile options: -ggdb;-fno-omit-frame-pointer;-Wreturn-type;-Wswitch;-O3 and link options: -Wl,--no-as-needed
00:00:00.000403 [shadow] n/a [INFO] [n/a] [main.c:73] [main_logBuildInfo] For more information, visit https://shadow.github.io or https://github.com/shadow
00:00:00.000404 [shadow] n/a [INFO] [n/a] [main.c:74] [main_logBuildInfo] Logging current startup arguments and environment
00:00:00.000407 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: /root/.local/bin/shadow
00:00:00.000408 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: --parallelism=4
00:00:00.000410 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: shadow.yaml
00:00:00.000428 [shadow] n/a [INFO] [n/a] [controller.c:103] [controller_new] simulation controller created
00:00:00.000430 [shadow] n/a [INFO] [n/a] [controller.c:425] [controller_run] loading and initializing simulation data
00:00:00.000910 [shadow] n/a [INFO] [n/a] [manager.c:210] [manager_new] found required preload library libshadow-shim.so at path /root/.local/lib/libshadow-shim.so
00:00:00.000966 [shadow] n/a [INFO] [n/a] [manager.c:219] [manager_new] found optional preload library libshadow_openssl_rng.so at path /root/.local/lib/libshadow_openssl_rng.so
00:00:00.001534 [shadow] n/a [INFO] [n/a] [scheduler.c:179] [scheduler_new] main scheduler thread will operate with 5 worker threads
00:00:00.001748 [shadow] n/a [INFO] [n/a] [controller.c:445] [controller_run] registering plugins and hosts
00:00:00.001769 [shadow] n/a [INFO] [n/a] [host.c:131] [host_new] Created host id '2' name 'h1'
00:00:00.001827 [shadow] n/a [WARN] [n/a] [tsc.c:192] [Tsc_nativeCyclesPerSecond] Couldn't get CPU TSC frequency
00:00:00.001830 [shadow] n/a [WARN] [n/a] [host.c:177] [host_setup] Couldn't find TSC frequency. rdtsc emulation won't scale accurately wrt simulation time. For most applications this shouldn't matter.
00:00:00.001848 [shadow] n/a [INFO] [n/a] [host.c:222] [host_setup] Setup host id '2' name 'h1' with seed 1105148392, ip 11.0.0.1, 122070 bwUpKiBps, 122070 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.001921 [shadow] n/a [INFO] [n/a] [host.c:131] [host_new] Created host id '3' name 'h2'
00:00:00.001954 [shadow] n/a [WARN] [n/a] [tsc.c:192] [Tsc_nativeCyclesPerSecond] Couldn't get CPU TSC frequency
00:00:00.001956 [shadow] n/a [WARN] [n/a] [host.c:177] [host_setup] Couldn't find TSC frequency. rdtsc emulation won't scale accurately wrt simulation time. For most applications this shouldn't matter.
00:00:00.001964 [shadow] n/a [INFO] [n/a] [host.c:222] [host_setup] Setup host id '3' name 'h2' with seed 2853875478, ip 11.0.0.2, 122070 bwUpKiBps, 122070 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.002006 [shadow] n/a [INFO] [n/a] [host.c:131] [host_new] Created host id '4' name 'h3'
00:00:00.002040 [shadow] n/a [WARN] [n/a] [tsc.c:192] [Tsc_nativeCyclesPerSecond] Couldn't get CPU TSC frequency
00:00:00.002042 [shadow] n/a [WARN] [n/a] [host.c:177] [host_setup] Couldn't find TSC frequency. rdtsc emulation won't scale accurately wrt simulation time. For most applications this shouldn't matter.
00:00:00.002048 [shadow] n/a [INFO] [n/a] [host.c:222] [host_setup] Setup host id '4' name 'h3' with seed 645940202, ip 11.0.0.3, 122070 bwUpKiBps, 122070 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.002089 [shadow] n/a [INFO] [n/a] [host.c:131] [host_new] Created host id '5' name 'h4'
00:00:00.002119 [shadow] n/a [WARN] [n/a] [tsc.c:192] [Tsc_nativeCyclesPerSecond] Couldn't get CPU TSC frequency
00:00:00.002122 [shadow] n/a [WARN] [n/a] [host.c:177] [host_setup] Couldn't find TSC frequency. rdtsc emulation won't scale accurately wrt simulation time. For most applications this shouldn't matter.
00:00:00.002134 [shadow] n/a [INFO] [n/a] [host.c:222] [host_setup] Setup host id '5' name 'h4' with seed 2059732742, ip 11.0.0.4, 122070 bwUpKiBps, 122070 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.002180 [shadow] n/a [INFO] [n/a] [host.c:131] [host_new] Created host id '6' name 'h5'
00:00:00.002212 [shadow] n/a [WARN] [n/a] [tsc.c:192] [Tsc_nativeCyclesPerSecond] Couldn't get CPU TSC frequency
00:00:00.002213 [shadow] n/a [WARN] [n/a] [host.c:177] [host_setup] Couldn't find TSC frequency. rdtsc emulation won't scale accurately wrt simulation time. For most applications this shouldn't matter.
00:00:00.002220 [shadow] n/a [INFO] [n/a] [host.c:222] [host_setup] Setup host id '6' name 'h5' with seed 663466108, ip 11.0.0.5, 122070 bwUpKiBps, 122070 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.002751 [shadow] n/a [INFO] [n/a] [controller.c:470] [controller_run] running simulation
00:00:00.002753 [shadow] n/a [INFO] [n/a] [controller.c:474] [controller_run] log message buffering is enabled for efficiency
00:00:00.002814 [worker-3] n/a [INFO] [n/a] [scheduler.c:70] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.002835 [worker-3] 00:00:00.000000000 [INFO] [h3:11.0.0.3] [tracker.c:430] [_tracker_logNode] [shadow-heartbeat] [node-header] interval-seconds,recv-bytes,send-bytes,cpu-percent,delayed-count,avgdelay-milliseconds;inbound-localhost-counters;outbound-localhost-counters;inbound-remote-counters;outbound-remote-counters where counters are: packets-total,bytes-total,packets-control,bytes-control-header,packets-control-retrans,bytes-control-header-retrans,packets-data,bytes-data-header,bytes-data-payload,packets-data-retrans,bytes-data-header-retrans,bytes-data-payload-retrans
00:00:00.002848 [worker-3] 00:00:00.000000000 [INFO] [h3:11.0.0.3] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.002847 [worker-1] n/a [INFO] [n/a] [scheduler.c:70] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.002858 [worker-3] n/a [INFO] [n/a] [scheduler.c:72] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.002877 [worker-4] n/a [INFO] [n/a] [scheduler.c:70] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.002870 [worker-2] n/a [INFO] [n/a] [scheduler.c:70] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.002890 [worker-1] 00:00:00.000000000 [INFO] [h2:11.0.0.2] [tracker.c:430] [_tracker_logNode] [shadow-heartbeat] [node-header] interval-seconds,recv-bytes,send-bytes,cpu-percent,delayed-count,avgdelay-milliseconds;inbound-localhost-counters;outbound-localhost-counters;inbound-remote-counters;outbound-remote-counters where counters are: packets-total,bytes-total,packets-control,bytes-control-header,packets-control-retrans,bytes-control-header-retrans,packets-data,bytes-data-header,bytes-data-payload,packets-data-retrans,bytes-data-header-retrans,bytes-data-payload-retrans
00:00:00.002892 [worker-4] 00:00:00.000000000 [INFO] [h5:11.0.0.5] [tracker.c:430] [_tracker_logNode] [shadow-heartbeat] [node-header] interval-seconds,recv-bytes,send-bytes,cpu-percent,delayed-count,avgdelay-milliseconds;inbound-localhost-counters;outbound-localhost-counters;inbound-remote-counters;outbound-remote-counters where counters are: packets-total,bytes-total,packets-control,bytes-control-header,packets-control-retrans,bytes-control-header-retrans,packets-data,bytes-data-header,bytes-data-payload,packets-data-retrans,bytes-data-header-retrans,bytes-data-payload-retrans
00:00:00.002900 [worker-4] 00:00:00.000000000 [INFO] [h5:11.0.0.5] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.002905 [worker-4] n/a [INFO] [n/a] [scheduler.c:72] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.002921 [worker-1] 00:00:00.000000000 [INFO] [h2:11.0.0.2] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.002950 [worker-1] n/a [INFO] [n/a] [scheduler.c:72] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.002956 [worker-2] 00:00:00.000000000 [INFO] [h1:11.0.0.1] [tracker.c:430] [_tracker_logNode] [shadow-heartbeat] [node-header] interval-seconds,recv-bytes,send-bytes,cpu-percent,delayed-count,avgdelay-milliseconds;inbound-localhost-counters;outbound-localhost-counters;inbound-remote-counters;outbound-remote-counters where counters are: packets-total,bytes-total,packets-control,bytes-control-header,packets-control-retrans,bytes-control-header-retrans,packets-data,bytes-data-header,bytes-data-payload,packets-data-retrans,bytes-data-header-retrans,bytes-data-payload-retrans
00:00:00.002989 [worker-2] 00:00:00.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.003031 [worker-2] n/a [INFO] [n/a] [scheduler.c:72] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.006217 [worker-0] n/a [INFO] [n/a] [scheduler.c:70] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.006253 [worker-0] 00:00:00.000000000 [INFO] [h4:11.0.0.4] [tracker.c:430] [_tracker_logNode] [shadow-heartbeat] [node-header] interval-seconds,recv-bytes,send-bytes,cpu-percent,delayed-count,avgdelay-milliseconds;inbound-localhost-counters;outbound-localhost-counters;inbound-remote-counters;outbound-remote-counters where counters are: packets-total,bytes-total,packets-control,bytes-control-header,packets-control-retrans,bytes-control-header-retrans,packets-data,bytes-data-header,bytes-data-payload,packets-data-retrans,bytes-data-header-retrans,bytes-data-payload-retrans
00:00:00.006272 [worker-0] 00:00:00.000000000 [INFO] [h4:11.0.0.4] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.006291 [worker-0] n/a [INFO] [n/a] [scheduler.c:72] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.006975 [worker-2] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [process.c:497] [_process_start] starting process 'h1.java.1000'
00:00:00.007356 [worker-2] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [thread_preload.c:200] [threadpreload_run] forking new thread with environment 'SHADOW_SPAWNED=TRUE SHADOW_LOG_START_TIME=759003507831 SHADOW_LOG_LEVEL=3 SHADOW_INTERPOSE_METHOD=PRELOAD LD_PRELOAD=/root/.local/lib/libshadow-shim.so:/root/.local/lib/libshadow_openssl_rng.so SHADOW_LOG_FILE=/root/library/build/install/library/shadow.data/hosts/h1/h1.java.1000.shimlog SHADOW_IPC_BLK=8,134217728,648,/shadow_shmemfile_759003.514841085-32699 SHADOW_USE_SECCOMP= SHADOW_PID=32699 SHADOW_TSC_HZ=2500000', arguments '/usr/lib/jvm/java-11-openjdk-amd64/bin/java -Djava.security.properties=./config/java.security -Dhttps.protocols=TLSv1.2,TLSv1.1,TLSv1 -Dlogback.configurationFile=./config/logback.xml -cp ./lib/* bftsmart.demo.counter.CounterServer 0', and working directory '/root/library/build/install/library'
00:00:00.007601 [worker-2] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [process.c:519] [_process_start] process 'h1.java.1000' started
00:00:00.030042 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:492] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.030046 [worker-2] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:496] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.031816 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:492] [syscallhandler_make_syscall] Detected unsupported syscall 229 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.031818 [worker-2] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:496] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 229, which may result in unusual behavior
00:00:00.032204 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [signal.c:214] [_rt_sigaction] Ignoring `sigaction` for signal 11
00:00:00.032900 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [socket.c:1222] [syscallhandler_socket] unsupported socket domain "1", we only support AF_INET
00:00:00.032911 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [socket.c:1222] [syscallhandler_socket] unsupported socket domain "1", we only support AF_INET
00:00:00.033941 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:492] [syscallhandler_make_syscall] Detected unsupported syscall 81 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.033944 [worker-2] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:496] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 81, which may result in unusual behavior
00:00:00.034665 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:492] [syscallhandler_make_syscall] Detected unsupported syscall 81 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.034667 [worker-2] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:496] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 81, which may result in unusual behavior
00:00:00.035125 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:492] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.035126 [worker-2] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:496] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.035445 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:492] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.035447 [worker-2] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:496] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior

stevenengler · 2022-04-25T15:06:57Z

stevenengler
Apr 25, 2022
Collaborator

I don't think we've done any testing of a JRE within Shadow. Which JRE are you using (OpenJDK, HotSpot, etc), and what version? How did you install it? And what OS are you using?

1 reply

bentoumia Apr 26, 2022
Author

Hello @stevenengler and thank you for the fast reply! i tried this with OpenJDK 11, 16 and 17 and i observed the same behavior on all 3 versions. Packages were installed using apt on Ubuntu 20.10.

sporksmith · 2022-04-25T16:05:46Z

sporksmith
Apr 25, 2022
Collaborator

00:00:00.037584 [00:00:00.000000001] [shd-shim] [error] [shim.c:548] [_handle_sigsegv] Unhandled sigsegv

A backtrace of this segv would also be helpful. There are some instructions for getting them here: https://shadow.github.io/docs/guide/developer_guide.html#debugging-virtual-processes

3 replies

bentoumia Apr 26, 2022
Author

Hello @sporksmith and thank you for the fast reply and the instructions! Here is the backtrace:

(gdb) thread apply all bt

Thread 3 (Thread 0x7fffee0e3640 (LWP 1001)):
warning: Couldn't find general-purpose registers in core file.
#0  <unavailable> in ?? ()
Backtrace stopped: not enough registers or memory available to unwind further

Thread 2 (Thread 0x7ffff7451740 (LWP 54534)):
#0  0x00007ffff7bbaed0 in shadow_vreal_raw_syscall (n=n@entry=202, args=args@entry=0x7ffff7bce2b0 <_tlss+40016>) at /root/shadow/src/lib/shim/preload_syscall.c:73
#1  0x00007ffff7bbb376 in shadow_vraw_syscall (n=202, args=args@entry=0x7ffff7bce2b0 <_tlss+40016>) at /root/shadow/src/lib/shim/preload_syscall.c:251
#2  0x00007ffff7bbb536 in syscall (n=n@entry=202) at /root/shadow/src/lib/shim/preload_syscall.c:280
#3  0x00007ffff7bbc9ea in _futex_wait_abs (timeout=0x0, s=0x7fffef451268) at /root/shadow/src/lib/shim/shadow_sem.c:130
#4  _shadow_sem_timedwait (abs_timeout=0x0, sem=0x7fffef451268) at /root/shadow/src/lib/shim/shadow_sem.c:130
#5  shadow_sem_wait (sem=sem@entry=0x7fffef451268) at /root/shadow/src/lib/shim/shadow_sem.c:155
#6  0x00007ffff7bbcc68 in BinarySpinningSem::wait (this=this@entry=0x7fffef451268, spin=<optimized out>) at /root/shadow/src/lib/shim/binary_spinning_sem.cc:34
#7  0x00007ffff7bbc650 in shimevent_recvEventFromShadow (data=data@entry=0x7fffef451008, e=e@entry=0x7ffff7bce410 <_tlss+40368>, spin=<optimized out>) at /root/shadow/src/lib/shim/ipc.cc:69
#8  0x00007ffff7bbb10f in _shadow_raw_syscall_event (syscall_event=0x7fffffff9890) at /root/shadow/src/lib/shim/preload_syscall.c:107
#9  0x00007ffff7bbacae in _vshadow_raw_syscall (n=<optimized out>, args=0x7fffffff9890) at /root/shadow/src/lib/shim/preload_syscall.c:206
#10 0x00007ffff7bbb3a7 in shadow_vraw_syscall (n=202, args=args@entry=0x7fffffff9a30) at /root/shadow/src/lib/shim/preload_syscall.c:245
#11 0x00007ffff7bbb471 in shadow_raw_syscall (n=<optimized out>) at /root/shadow/src/lib/shim/preload_syscall.c:260
#12 0x00007ffff7bbb7c9 in _handle_sigsys (sig=<optimized out>, info=<optimized out>, voidUcontext=0x7fffffff9b40) at /root/shadow/src/lib/shim/shim.c:386
#13 <signal handler called>
#14 __pthread_clockjoin_ex (threadid=140737187296832, thread_return=0x7fffffffa8b8, clockid=<optimized out>, abstime=<optimized out>, block=<optimized out>) at pthread_join_common.c:145
#15 0x00007ffff7ba304f in ?? () from /usr/lib/jvm/java-16-openjdk-amd64/bin/../lib/libjli.so
#16 0x00007ffff7b9fd81 in ?? () from /usr/lib/jvm/java-16-openjdk-amd64/bin/../lib/libjli.so
#17 0x00007ffff7ba16d5 in JLI_Launch () from /usr/lib/jvm/java-16-openjdk-amd64/bin/../lib/libjli.so
#18 0x00005555555552b3 in ?? ()
#19 0x00007ffff79cecb2 in __libc_start_main (main=0x555555555180, argc=2, argv=0x7fffffffec28, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffec18) at ../csu/libc-start.c:314
#20 0x000055555555535e in ?? ()

Thread 1 (LWP 54535):
#0  0x00007ffff7bbaed0 in shadow_vreal_raw_syscall (n=234, args=args@entry=0x7ffff7bd8720 <_tlss+82112>) at /root/shadow/src/lib/shim/preload_syscall.c:73
#1  0x00007ffff7bbb081 in shadow_real_raw_syscall (n=<optimized out>) at /root/shadow/src/lib/shim/preload_syscall.c:85
#2  0x00007ffff7bbb28b in _shadow_raw_syscall_event (syscall_event=0x7fffee0e0390) at /root/shadow/src/lib/shim/preload_syscall.c:140
#3  0x00007ffff7bbacae in _vshadow_raw_syscall (n=<optimized out>, args=0x7fffee0e0390) at /root/shadow/src/lib/shim/preload_syscall.c:206
Backtrace stopped: previous frame inner to this frame (corrupt stack?)
(gdb)

sporksmith Apr 26, 2022
Collaborator

It looks like the the "Thread 1" backtrace may be truncated?

bentoumia Apr 26, 2022
Author

Whoops, very sorry about that. I updated it :)

sporksmith · 2022-04-25T16:28:13Z

sporksmith
Apr 25, 2022
Collaborator

00:00:00.030042 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:492] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1

sched_getaffinity. So far we haven't seen anything react badly due to not supporting it, but maybe the JVM does. It might be worth trying adding NATIVE(sched_getaffinity) in syscallhandler_make_syscall, which will cause the syscall to be executed natively. This isn't ideal for a real fix, but would let us know whether this is part of the problem.

00:00:00.031816 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:492] [syscallhandler_make_syscall] Detected unsupported syscall 229 called from thread 1001 in process h1.java.1000 on host h1

clock_getres. This shouldn't be too difficult to support, but from context it doesn't seem likely to be the problem. Might be worth trying a NATIVE(clock_getres) as above.

00:00:00.032204 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [signal.c:214] [_rt_sigaction] Ignoring `sigaction` for signal 11

This might be a hint that the JVM is trying to do its own paging, which would probably take some work to support. OTOH it might just be trying to install a handler that dumps debug info before exiting with a segv.

00:00:00.033941 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:492] [syscallhandler_make_syscall] Detected unsupported syscall 81 called from thread 1001 in process h1.java.1000 on host h1

fchdir. This doesn't look like it'd be difficult to support, and shadow returning an error for it in the current sim seems likely to cause trouble. A NATIVE wouldn't work here; we'd need to properly emulate it.

00:00:00.035125 [worker-2] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:492] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1

sched_getaffinity again. Given that it's the last thing in the log before it hangs, adding the NATIVE(sched_getaffinity) as described above might be worth trying.

1 reply

bentoumia Apr 26, 2022
Author

Hello again and thank you for the tips! I added the NATIVE() and rebuilt Shadow the SegFault still occurs however. Note i am only calling java --version here.

** Starting Shadow v2.0.0-pre.4-244-g46437ab1-dirty 2021-09-23--18:21:32 with GLib v2.66.1
00:00:00.000002 [shadow] n/a [INFO] [n/a] [main.c:68] [main_logBuildInfo] Starting Shadow v2.0.0-pre.4-244-g46437ab1-dirty 2021-09-23--18:21:32 with GLib v2.66.1
00:00:00.000123 [shadow] n/a [INFO] [n/a] [main.c:72] [main_logBuildInfo] Shadow was built from branch main on 2022-04-26--00:24:11 in Release mode with compile options: -ggdb;-fno-omit-frame-pointer;-Wreturn-type;-Wswitch;-O3 and link options: -Wl,--no-as-needed
00:00:00.000125 [shadow] n/a [INFO] [n/a] [main.c:73] [main_logBuildInfo] For more information, visit https://shadow.github.io or https://github.com/shadow
00:00:00.000127 [shadow] n/a [INFO] [n/a] [main.c:74] [main_logBuildInfo] Logging current startup arguments and environment
00:00:00.000129 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: /root/.local/bin/shadow
00:00:00.000131 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: --parallelism=4
00:00:00.000132 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: shadow.yaml
00:00:00.000147 [shadow] n/a [INFO] [n/a] [controller.c:103] [controller_new] simulation controller created
00:00:00.000148 [shadow] n/a [INFO] [n/a] [controller.c:425] [controller_run] loading and initializing simulation data
00:00:00.000545 [shadow] n/a [INFO] [n/a] [manager.c:210] [manager_new] found required preload library libshadow-shim.so at path /root/.local/lib/libshadow-shim.so
00:00:00.000561 [shadow] n/a [INFO] [n/a] [manager.c:219] [manager_new] found optional preload library libshadow_openssl_rng.so at path /root/.local/lib/libshadow_openssl_rng.so
00:00:00.000998 [shadow] n/a [INFO] [n/a] [scheduler.c:179] [scheduler_new] main scheduler thread will operate with 1 worker threads
00:00:00.001138 [shadow] n/a [INFO] [n/a] [controller.c:445] [controller_run] registering plugins and hosts
00:00:00.001167 [shadow] n/a [INFO] [n/a] [host.c:131] [host_new] Created host id '2' name 'h1'
00:00:00.001215 [shadow] n/a [WARN] [n/a] [tsc.c:192] [Tsc_nativeCyclesPerSecond] Couldn't get CPU TSC frequency
00:00:00.001218 [shadow] n/a [WARN] [n/a] [host.c:177] [host_setup] Couldn't find TSC frequency. rdtsc emulation won't scale accurately wrt simulation time. For most applications this shouldn't matter.
00:00:00.001242 [shadow] n/a [INFO] [n/a] [host.c:222] [host_setup] Setup host id '2' name 'h1' with seed 1105148392, ip 11.0.0.1, 122070 bwUpKiBps, 122070 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.001801 [shadow] n/a [INFO] [n/a] [controller.c:470] [controller_run] running simulation
00:00:00.001813 [shadow] n/a [INFO] [n/a] [controller.c:474] [controller_run] log message buffering is enabled for efficiency
00:00:00.002053 [worker-0] n/a [INFO] [n/a] [scheduler.c:70] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.002118 [worker-0] 00:00:00.000000000 [INFO] [h1:11.0.0.1] [tracker.c:430] [_tracker_logNode] [shadow-heartbeat] [node-header] interval-seconds,recv-bytes,send-bytes,cpu-percent,delayed-count,avgdelay-milliseconds;inbound-localhost-counters;outbound-localhost-counters;inbound-remote-counters;outbound-remote-counters where counters are: packets-total,bytes-total,packets-control,bytes-control-header,packets-control-retrans,bytes-control-header-retrans,packets-data,bytes-data-header,bytes-data-payload,packets-data-retrans,bytes-data-header-retrans,bytes-data-payload-retrans
00:00:00.002152 [worker-0] 00:00:00.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.002189 [worker-0] n/a [INFO] [n/a] [scheduler.c:72] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.002532 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [process.c:497] [_process_start] starting process 'h1.java.1000'
00:00:00.002853 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [thread_preload.c:200] [threadpreload_run] forking new thread with environment 'SHADOW_SPAWNED=TRUE SHADOW_LOG_START_TIME=807376524517 SHADOW_LOG_LEVEL=3 SHADOW_INTERPOSE_METHOD=PRELOAD LD_PRELOAD=/root/.local/lib/libshadow-shim.so:/root/.local/lib/libshadow_openssl_rng.so SHADOW_LOG_FILE=/root/library/build/install/library/shadow.data/hosts/h1/h1.java.1000.shimlog SHADOW_IPC_BLK=8,134217728,648,/shadow_shmemfile_807376.527070271-44106 SHADOW_USE_SECCOMP= SHADOW_PID=44106 SHADOW_TSC_HZ=2500000', arguments '/usr/lib/jvm/java-11-openjdk-amd64/bin/java --version', and working directory '/root/library/build/install/library'
00:00:00.003155 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [process.c:519] [_process_start] process 'h1.java.1000' started
00:00:00.027624 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [signal.c:214] [_rt_sigaction] Ignoring `sigaction` for signal 11
00:00:00.028291 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [socket.c:1222] [syscallhandler_socket] unsupported socket domain "1", we only support AF_INET
00:00:00.028301 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [socket.c:1222] [syscallhandler_socket] unsupported socket domain "1", we only support AF_INET
00:00:00.029989 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 81 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.029992 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 81, which may result in unusual behavior
00:00:00.030642 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 81 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.030645 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 81, which may result in unusual behavior
00:00:00.031243 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [signal.c:214] [_rt_sigaction] Ignoring `sigaction` for signal 11

It seems natively calling sched_getaffinity and clock_getres causes a SegFault. The ptrace sim also broke, here are the logs:

00:00:00.000005 [shadow] n/a [INFO] [n/a] [main.c:68] [main_logBuildInfo] Starting Shadow v2.0.0-pre.4-244-g46437ab1-dirty 2021-09-23--18:21:32 with GLib v2.66.1
** Starting Shadow v2.0.0-pre.4-244-g46437ab1-dirty 2021-09-23--18:21:32 with GLib v2.66.1
00:00:00.000301 [shadow] n/a [INFO] [n/a] [main.c:72] [main_logBuildInfo] Shadow was built from branch main on 2022-04-26--00:24:11 in Release mode with compile options: -ggdb;-fno-omit-frame-pointer;-Wreturn-type;-Wswitch;-O3 and link options: -Wl,--no-as-needed
00:00:00.000394 [shadow] n/a [INFO] [n/a] [main.c:73] [main_logBuildInfo] For more information, visit https://shadow.github.io or https://github.com/shadow
00:00:00.000400 [shadow] n/a [INFO] [n/a] [main.c:74] [main_logBuildInfo] Logging current startup arguments and environment
00:00:00.000406 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: /root/.local/bin/shadow
00:00:00.000410 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: --parallelism=4
00:00:00.000413 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: shadow.yaml
00:00:00.000451 [shadow] n/a [INFO] [n/a] [controller.c:103] [controller_new] simulation controller created
00:00:00.000456 [shadow] n/a [INFO] [n/a] [controller.c:425] [controller_run] loading and initializing simulation data
00:00:00.000959 [shadow] n/a [INFO] [n/a] [manager.c:210] [manager_new] found required preload library libshadow-shim.so at path /root/.local/lib/libshadow-shim.so
00:00:00.000983 [shadow] n/a [INFO] [n/a] [manager.c:219] [manager_new] found optional preload library libshadow_openssl_rng.so at path /root/.local/lib/libshadow_openssl_rng.so
00:00:00.001403 [shadow] n/a [INFO] [n/a] [scheduler.c:179] [scheduler_new] main scheduler thread will operate with 1 worker threads
00:00:00.001559 [shadow] n/a [INFO] [n/a] [controller.c:445] [controller_run] registering plugins and hosts
00:00:00.001592 [shadow] n/a [INFO] [n/a] [host.c:131] [host_new] Created host id '2' name 'h1'
00:00:00.001652 [shadow] n/a [WARN] [n/a] [tsc.c:192] [Tsc_nativeCyclesPerSecond] Couldn't get CPU TSC frequency
00:00:00.001656 [shadow] n/a [WARN] [n/a] [host.c:177] [host_setup] Couldn't find TSC frequency. rdtsc emulation won't scale accurately wrt simulation time. For most applications this shouldn't matter.
00:00:00.001684 [shadow] n/a [INFO] [n/a] [host.c:222] [host_setup] Setup host id '2' name 'h1' with seed 1105148392, ip 11.0.0.1, 122070 bwUpKiBps, 122070 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.002224 [shadow] n/a [INFO] [n/a] [controller.c:470] [controller_run] running simulation
00:00:00.002241 [shadow] n/a [INFO] [n/a] [controller.c:474] [controller_run] log message buffering is enabled for efficiency
00:00:00.002476 [worker-0] n/a [INFO] [n/a] [scheduler.c:70] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.002706 [worker-0] 00:00:00.000000000 [INFO] [h1:11.0.0.1] [tracker.c:430] [_tracker_logNode] [shadow-heartbeat] [node-header] interval-seconds,recv-bytes,send-bytes,cpu-percent,delayed-count,avgdelay-milliseconds;inbound-localhost-counters;outbound-localhost-counters;inbound-remote-counters;outbound-remote-counters where counters are: packets-total,bytes-total,packets-control,bytes-control-header,packets-control-retrans,bytes-control-header-retrans,packets-data,bytes-data-header,bytes-data-payload,packets-data-retrans,bytes-data-header-retrans,bytes-data-payload-retrans
00:00:00.002740 [worker-0] 00:00:00.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.002772 [worker-0] n/a [INFO] [n/a] [scheduler.c:72] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.003324 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [process.c:497] [_process_start] starting process 'h1.java.1000'
00:00:00.003370 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [thread_ptrace.c:712] [threadptrace_run] forking new thread with environment 'SHADOW_SPAWNED=TRUE SHADOW_LOG_START_TIME=807701876952 SHADOW_LOG_LEVEL=3 SHADOW_INTERPOSE_METHOD=PTRACE LD_PRELOAD=/root/.local/lib/libshadow-shim.so:/root/.local/lib/libshadow_openssl_rng.so SHADOW_LOG_FILE=/root/library/build/install/library/shadow.data/hosts/h1/h1.java.1000.shimlog SHADOW_SHM_BLK=8,134217728,24,/shadow_shmemfile_807701.880037848-44200', arguments '/usr/lib/jvm/java-16-openjdk-amd64/bin/java --version', and working directory '/root/library/build/install/library'
00:00:00.004515 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [process.c:519] [_process_start] process 'h1.java.1000' started
00:00:00.040396 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [socket.c:1222] [syscallhandler_socket] unsupported socket domain "1", we only support AF_INET
00:00:00.040408 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [socket.c:1222] [syscallhandler_socket] unsupported socket domain "1", we only support AF_INET
00:00:00.041661 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 81 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.041663 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 81, which may result in unusual behavior
00:00:00.042949 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 81 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.042952 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 81, which may result in unusual behavior
00:00:00.043746 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [thread_ptrace.c:478] [_threadptrace_enterStateSignalled] Unhandled SIGSEGV at rip:00007fffeed04e53
00:00:00.043749 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [thread_ptrace.c:489] [_threadptrace_enterStateSignalled] Delivering signal 11
00:00:00.070605 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [thread_ptrace.c:489] [_threadptrace_enterStateSignalled] Delivering signal 6

ptrace without the native sched_affinity and clock_getres:

** Starting Shadow v2.0.0-pre.4-244-g46437ab1-dirty 2021-09-23--18:21:32 with GLib v2.66.1
00:00:00.000002 [shadow] n/a [INFO] [n/a] [main.c:68] [main_logBuildInfo] Starting Shadow v2.0.0-pre.4-244-g46437ab1-dirty 2021-09-23--18:21:32 with GLib v2.66.1
00:00:00.000128 [shadow] n/a [INFO] [n/a] [main.c:72] [main_logBuildInfo] Shadow was built from branch main on 2022-04-26--00:34:40 in Release mode with compile options: -ggdb;-fno-omit-frame-pointer;-Wreturn-type;-Wswitch;-O3 and link options: -Wl,--no-as-needed
00:00:00.000130 [shadow] n/a [INFO] [n/a] [main.c:73] [main_logBuildInfo] For more information, visit https://shadow.github.io or https://github.com/shadow
00:00:00.000132 [shadow] n/a [INFO] [n/a] [main.c:74] [main_logBuildInfo] Logging current startup arguments and environment
00:00:00.000134 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: /root/.local/bin/shadow
00:00:00.000136 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: --parallelism=4
00:00:00.000137 [shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: shadow.yaml
00:00:00.000151 [shadow] n/a [INFO] [n/a] [controller.c:103] [controller_new] simulation controller created
00:00:00.000153 [shadow] n/a [INFO] [n/a] [controller.c:425] [controller_run] loading and initializing simulation data
00:00:00.000473 [shadow] n/a [INFO] [n/a] [manager.c:210] [manager_new] found required preload library libshadow-shim.so at path /root/.local/lib/libshadow-shim.so
00:00:00.000491 [shadow] n/a [INFO] [n/a] [manager.c:219] [manager_new] found optional preload library libshadow_openssl_rng.so at path /root/.local/lib/libshadow_openssl_rng.so
00:00:00.000935 [shadow] n/a [INFO] [n/a] [scheduler.c:179] [scheduler_new] main scheduler thread will operate with 1 worker threads
00:00:00.001200 [shadow] n/a [INFO] [n/a] [controller.c:445] [controller_run] registering plugins and hosts
00:00:00.001268 [shadow] n/a [INFO] [n/a] [host.c:131] [host_new] Created host id '2' name 'h1'
00:00:00.001384 [shadow] n/a [WARN] [n/a] [tsc.c:192] [Tsc_nativeCyclesPerSecond] Couldn't get CPU TSC frequency
00:00:00.001413 [shadow] n/a [WARN] [n/a] [host.c:177] [host_setup] Couldn't find TSC frequency. rdtsc emulation won't scale accurately wrt simulation time. For most applications this shouldn't matter.
00:00:00.001469 [shadow] n/a [INFO] [n/a] [host.c:222] [host_setup] Setup host id '2' name 'h1' with seed 1105148392, ip 11.0.0.1, 122070 bwUpKiBps, 122070 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.002186 [shadow] n/a [INFO] [n/a] [controller.c:470] [controller_run] running simulation
00:00:00.002197 [shadow] n/a [INFO] [n/a] [controller.c:474] [controller_run] log message buffering is enabled for efficiency
00:00:00.002338 [worker-0] n/a [INFO] [n/a] [scheduler.c:70] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.002624 [worker-0] 00:00:00.000000000 [INFO] [h1:11.0.0.1] [tracker.c:430] [_tracker_logNode] [shadow-heartbeat] [node-header] interval-seconds,recv-bytes,send-bytes,cpu-percent,delayed-count,avgdelay-milliseconds;inbound-localhost-counters;outbound-localhost-counters;inbound-remote-counters;outbound-remote-counters where counters are: packets-total,bytes-total,packets-control,bytes-control-header,packets-control-retrans,bytes-control-header-retrans,packets-data,bytes-data-header,bytes-data-payload,packets-data-retrans,bytes-data-header-retrans,bytes-data-payload-retrans
00:00:00.002658 [worker-0] 00:00:00.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.002693 [worker-0] n/a [INFO] [n/a] [scheduler.c:72] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.003341 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [process.c:497] [_process_start] starting process 'h1.java.1000'
00:00:00.003391 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [thread_ptrace.c:712] [threadptrace_run] forking new thread with environment 'SHADOW_SPAWNED=TRUE SHADOW_LOG_START_TIME=808067171295 SHADOW_LOG_LEVEL=3 SHADOW_INTERPOSE_METHOD=PTRACE LD_PRELOAD=/root/.local/lib/libshadow-shim.so:/root/.local/lib/libshadow_openssl_rng.so SHADOW_LOG_FILE=/root/library/build/install/library/shadow.data/hosts/h1/h1.java.1000.shimlog SHADOW_SHM_BLK=8,134217728,24,/shadow_shmemfile_808067.174341807-54394', arguments '/usr/lib/jvm/java-16-openjdk-amd64/bin/java --version', and working directory '/root/library/build/install/library'
00:00:00.003868 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [process.c:519] [_process_start] process 'h1.java.1000' started
00:00:00.034072 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.034076 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.034826 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 229 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.034829 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 229, which may result in unusual behavior
00:00:00.035108 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 229 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.035109 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 229, which may result in unusual behavior
00:00:00.037342 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [socket.c:1222] [syscallhandler_socket] unsupported socket domain "1", we only support AF_INET
00:00:00.037356 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [socket.c:1222] [syscallhandler_socket] unsupported socket domain "1", we only support AF_INET
00:00:00.038940 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 81 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.038943 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 81, which may result in unusual behavior
00:00:00.039836 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 81 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.039839 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 81, which may result in unusual behavior
00:00:00.040237 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.040240 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.040435 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.040438 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.045183 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [thread_ptrace.c:478] [_threadptrace_enterStateSignalled] Unhandled SIGSEGV at rip:00007fffd02ad62d
00:00:00.045186 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [thread_ptrace.c:489] [_threadptrace_enterStateSignalled] Delivering signal 11
00:00:00.048492 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1002 in process h1.java.1000 on host h1
00:00:00.048495 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.048893 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1002 in process h1.java.1000 on host h1
00:00:00.048899 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.050372 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1003 in process h1.java.1000 on host h1
00:00:00.050375 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.050546 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1003 in process h1.java.1000 on host h1
00:00:00.050548 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.051669 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1004 in process h1.java.1000 on host h1
00:00:00.051671 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.051824 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1004 in process h1.java.1000 on host h1
00:00:00.051826 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.060052 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1005 in process h1.java.1000 on host h1
00:00:00.060055 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.060340 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1005 in process h1.java.1000 on host h1
00:00:00.060343 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.061039 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1006 in process h1.java.1000 on host h1
00:00:00.061041 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.061342 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1006 in process h1.java.1000 on host h1
00:00:00.061344 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.076854 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1007 in process h1.java.1000 on host h1
00:00:00.076857 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.077148 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1007 in process h1.java.1000 on host h1
00:00:00.077150 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.079940 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1008 in process h1.java.1000 on host h1
00:00:00.079943 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.080263 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1008 in process h1.java.1000 on host h1
00:00:00.080264 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.081279 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1009 in process h1.java.1000 on host h1
00:00:00.081282 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.081565 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1009 in process h1.java.1000 on host h1
00:00:00.081567 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.086018 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 98 called from thread 1006 in process h1.java.1000 on host h1
00:00:00.086021 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 98, which may result in unusual behavior
00:00:00.086316 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 98 called from thread 1006 in process h1.java.1000 on host h1
00:00:00.086319 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 98, which may result in unusual behavior
00:00:00.086426 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 98 called from thread 1006 in process h1.java.1000 on host h1
00:00:00.086429 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 98, which may result in unusual behavior
00:00:00.086589 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 98 called from thread 1006 in process h1.java.1000 on host h1
00:00:00.086591 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 98, which may result in unusual behavior
00:00:00.086764 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 98 called from thread 1005 in process h1.java.1000 on host h1
00:00:00.086766 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 98, which may result in unusual behavior
00:00:00.086972 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 98 called from thread 1003 in process h1.java.1000 on host h1
00:00:00.086974 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 98, which may result in unusual behavior
00:00:00.087316 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1010 in process h1.java.1000 on host h1
00:00:00.087319 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.087468 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1010 in process h1.java.1000 on host h1
00:00:00.087470 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.088386 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1011 in process h1.java.1000 on host h1
00:00:00.088389 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.088578 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1011 in process h1.java.1000 on host h1
00:00:00.088580 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.089464 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1012 in process h1.java.1000 on host h1
00:00:00.089467 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.089657 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1012 in process h1.java.1000 on host h1
00:00:00.089659 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.090547 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1013 in process h1.java.1000 on host h1
00:00:00.090550 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.090731 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1013 in process h1.java.1000 on host h1
00:00:00.090734 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.091098 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 24 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.091100 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 24, which may result in unusual behavior
00:00:00.095294 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1014 in process h1.java.1000 on host h1
00:00:00.095297 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.095463 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1014 in process h1.java.1000 on host h1
00:00:00.095465 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.095835 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 24 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.095838 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 24, which may result in unusual behavior
00:00:00.096864 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1015 in process h1.java.1000 on host h1
00:00:00.096866 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.097056 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1015 in process h1.java.1000 on host h1
00:00:00.097059 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.097415 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 24 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.097417 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 24, which may result in unusual behavior
00:00:00.101073 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1016 in process h1.java.1000 on host h1
00:00:00.101076 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.101264 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1016 in process h1.java.1000 on host h1
00:00:00.101267 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.102261 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1017 in process h1.java.1000 on host h1
00:00:00.102263 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.102446 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1017 in process h1.java.1000 on host h1
00:00:00.102447 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.103545 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.103548 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.103820 [worker-0] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:494] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.103821 [worker-0] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:498] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.104351 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 16 syscalls
00:00:00.109893 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 20 syscalls
00:00:00.110052 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 20 syscalls
00:00:00.110174 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 21 syscalls
00:00:00.110534 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 22 syscalls
00:00:00.110701 [worker-0] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 23 syscalls
00:00:00.111109 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 716 syscalls
00:00:00.111345 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 253 syscalls
00:00:00.111362 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 17 syscalls
00:00:00.111376 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 18 syscalls
00:00:00.111390 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 17 syscalls
00:00:00.111405 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 15 syscalls
00:00:00.111419 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 32 syscalls
00:00:00.111432 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 18 syscalls
00:00:00.111451 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 19 syscalls
00:00:00.111467 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 18 syscalls
00:00:00.111483 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 22 syscalls
00:00:00.112839 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:101] [_syscallhandler_free] handled 25 syscalls
00:00:00.112846 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [process.c:395] [_process_check] process 'h1.java.1000' has completed or is otherwise no longer running
00:00:00.112927 [worker-0] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [process.c:349] [_process_getAndLogReturnCode] main success code '0' for process 'h1.java.1000'
00:00:00.113259 [worker-0] 00:00:01.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.113354 [worker-0] 00:00:02.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.113377 [shadow] n/a [INFO] [n/a] [manager.c:644] [_manager_heartbeat] process resource usage at simtime 2000000000 reported by getrusage(): ru_maxrss=0.153519 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=3873, ru_nivcsw=132
00:00:00.113426 [worker-0] 00:00:03.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.113513 [shadow] n/a [INFO] [n/a] [manager.c:644] [_manager_heartbeat] process resource usage at simtime 4000000000 reported by getrusage(): ru_maxrss=0.153519 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=3876, ru_nivcsw=132
00:00:00.113516 [worker-0] 00:00:04.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.113624 [worker-0] 00:00:05.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.113709 [shadow] n/a [INFO] [n/a] [manager.c:644] [_manager_heartbeat] process resource usage at simtime 6000000000 reported by getrusage(): ru_maxrss=0.153519 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=3880, ru_nivcsw=132
00:00:00.113712 [worker-0] 00:00:06.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.113764 [worker-0] 00:00:07.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.113848 [shadow] n/a [INFO] [n/a] [manager.c:644] [_manager_heartbeat] process resource usage at simtime 8000000000 reported by getrusage(): ru_maxrss=0.153519 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=3884, ru_nivcsw=132
00:00:00.113853 [worker-0] 00:00:08.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.113958 [worker-0] 00:00:09.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.114044 [shadow] n/a [INFO] [n/a] [manager.c:644] [_manager_heartbeat] process resource usage at simtime 10000000000 reported by getrusage(): ru_maxrss=0.153519 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=3888, ru_nivcsw=132
00:00:00.114052 [worker-0] 00:00:10.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.114157 [worker-0] 00:00:11.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.114240 [shadow] n/a [INFO] [n/a] [manager.c:644] [_manager_heartbeat] process resource usage at simtime 12000000000 reported by getrusage(): ru_maxrss=0.153519 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=3892, ru_nivcsw=132
00:00:00.114245 [worker-0] 00:00:12.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.114348 [worker-0] 00:00:13.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.114429 [shadow] n/a [INFO] [n/a] [manager.c:644] [_manager_heartbeat] process resource usage at simtime 14000000000 reported by getrusage(): ru_maxrss=0.153519 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=3896, ru_nivcsw=132
00:00:00.114434 [worker-0] 00:00:14.000000000 [INFO] [h1:11.0.0.1] [tracker.c:456] [_tracker_logNode] [shadow-heartbeat] [node] 1,0,0,0.000000,0,0.000000;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0;0,0,0,0,0,0,0,0,0,0,0,0
00:00:00.114532 [worker-0] 00:00:15.000000000 [INFO] [n/a] [worker.c:480] [worker_finish] starting to shut down 1 hosts
00:00:00.114534 [worker-0] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [process.c:611] [process_stop] terminating process 'h1.java.1000'
00:00:00.114536 [worker-0] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [process.c:395] [_process_check] process 'h1.java.1000' has completed or is otherwise no longer running
00:00:00.114538 [worker-0] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [process.c:634] [process_stop] process 'h1.java.1000' stopped
00:00:00.114540 [worker-0] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [process.c:395] [_process_check] process 'h1.java.1000' has completed or is otherwise no longer running
00:00:00.114542 [worker-0] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [process.c:395] [_process_check] process 'h1.java.1000' has completed or is otherwise no longer running
00:00:00.116120 [worker-0] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [host.c:296] [host_shutdown] host 'h1' has been shut down
00:00:00.116123 [worker-0] 00:00:15.000000000 [INFO] [n/a] [worker.c:483] [worker_finish] 1 hosts are shut down
00:00:00.116334 [shadow] n/a [INFO] [n/a] [controller.c:484] [controller_run] log message buffering is disabled during cleanup
00:00:00.116345 [shadow] n/a [INFO] [n/a] [controller.c:488] [controller_run] simulation finished, cleaning up now
00:00:00.116722 [shadow] n/a [INFO] [n/a] [scheduler.c:187] [scheduler_shutdown] scheduler is shutting down now
00:00:00.116733 [shadow] n/a [INFO] [n/a] [scheduler.c:194] [scheduler_shutdown] waiting for 1 worker threads to finish
00:00:00.116948 [shadow] n/a [INFO] [n/a] [scheduler.c:207] [_scheduler_free] 1 worker threads finished
00:00:00.116963 [shadow] n/a [INFO] [n/a] [manager.c:318] [manager_free] Global syscall counts: {}
00:00:00.116995 [shadow] n/a [INFO] [n/a] [manager.c:325] [manager_free] Global allocated object counts: {LegacyDescriptor:148, Event:140, Task:140, File:119, StatusListener:76, SysCallCondition:66, Futex:60, Epoll:18, SysCallHandler:18, ThreadPtrace:18, Timer:11, NetworkInterface:2, FutexTable:1, Host:1, Process:1, Router:1}
00:00:00.117019 [shadow] n/a [INFO] [n/a] [manager.c:329] [manager_free] Global deallocated object counts: {LegacyDescriptor:148, Event:140, Task:140, File:119, StatusListener:76, SysCallCondition:66, Futex:60, Epoll:18, SysCallHandler:18, ThreadPtrace:18, Timer:11, NetworkInterface:2, FutexTable:1, Host:1, Process:1, Router:1}
00:00:00.117029 [shadow] n/a [INFO] [n/a] [manager.c:334] [manager_free] We allocated and deallocated the same number of objects :)
00:00:00.117046 [shadow] n/a [INFO] [n/a] [controller.c:136] [controller_free] simulation controller destroyed
** Shadow completed successfully

So in both cases a SegFault occurs but only with the native syscalls that Shadow hangs indefinitely.

bentoumia · 2022-04-26T01:00:35Z

bentoumia
Apr 26, 2022
Author

Here is my YAML file:

general:
  stop_time: 15s
network:
  graph:
    type: 1_gbit_switch
experimental:
  use_legacy_working_dir: true
  interpose_method: preload
hosts:
  h1:
    network_node_id: 0
    ip_addr: "11.0.0.1"
    options:
      log_level: debug
    processes:
    - path: /usr/bin/java
      args: --version
      start_time: 0s

0 replies

sporksmith · 2022-04-26T04:27:26Z

sporksmith
Apr 26, 2022
Collaborator

Thanks for the info and YAML file! Confirmed I see the same behavior here.

I got a slightly less mangled stack trace, but it looks like I'd need to install debug symbols for openjdk for it to be very useful.

Core was generated by `/usr/lib/jvm/java-16-openjdk-amd64/bin/java --version'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007ffff72cc4e5 in shim_native_syscallv (n=234, args=0x7ffff7312bd0 <_tlss+218032>) at /home/jnewsome/projects/shadow/dev/src/lib/shim/shim_syscall.c:94
94	    __asm__ __volatile__("syscall"
[Current thread is 1 (LWP 3969898)]
(gdb) bt
#0  0x00007ffff72cc4e5 in shim_native_syscallv (n=234, args=0x7ffff7312bd0 <_tlss+218032>) at /home/jnewsome/projects/shadow/dev/src/lib/shim/shim_syscall.c:94
#1  0x00007ffff72cd765 in shim_syscallv (n=234, args=0x7ffff7312bd0 <_tlss+218032>) at /home/jnewsome/projects/shadow/dev/src/lib/shim/shim_syscall.c:423
#2  0x00007ffff72cd838 in shim_syscall (n=234) at /home/jnewsome/projects/shadow/dev/src/lib/shim/shim_syscall.c:432
#3  0x00007ffff72cb4ce in _shim_seccomp_handle_sigsys (sig=31, info=0x7ffff7312e70 <_tlss+218704>, voidUcontext=0x7ffff7312d40 <_tlss+218400>) at /home/jnewsome/projects/shadow/dev/src/lib/shim/shim_seccomp.c:63
#4  <signal handler called>
#5  0x00007ffff7dc6019 in raise () from /lib/x86_64-linux-gnu/libc.so.6
#6  0x00007ffff72cad56 in _shim_rdtsc_die_with_sigsegv () at /home/jnewsome/projects/shadow/dev/src/lib/shim/shim_rdtsc.c:26
#7  0x00007ffff72cb130 in _shim_rdtsc_handle_sigsegv (sig=11, info=0x7ffff7313770 <_tlss+221008>, voidUcontext=0x7ffff7313640 <_tlss+220704>) at /home/jnewsome/projects/shadow/dev/src/lib/shim/shim_rdtsc.c:90
#8  <signal handler called>
#9  0x00007fffd02ad62d in ?? ()
#10 0x0000000000000202 in ?? ()
#11 0x00007fffd02ad724 in ?? ()
#12 0x00007fffeed1a0f0 in ?? () from /usr/lib/jvm/java-16-openjdk-amd64/lib/server/libjvm.so
#13 0x00007fffeda06420 in ?? ()
#14 0x00007fffee94325e in ?? () from /usr/lib/jvm/java-16-openjdk-amd64/lib/server/libjvm.so
#15 0x49656e696c65746e in ?? ()
#16 0x00100800000906ea in ?? ()
#17 0xbfebfbff7ffafbff in ?? ()
#18 0x01c0003f1c004121 in ?? ()
#19 0x000000000000003f in ?? ()
#20 0x029c6fbf00000000 in ?? ()
#21 0x9c002e0040000000 in ?? ()
#22 0x0000000200000001 in ?? ()
#23 0x0000000000000100 in ?? ()
#24 0x0000000c00000004 in ?? ()
#25 0x0000000000000201 in ?? ()
#26 0x0000000000000000 in ?? ()

Implementing fchdir seems like a reasonable next step - I'm surprised we haven't run into anything needing this up until now. Opened #2090.

Glancing through an
strace.txt
of java --version, nothing stands out to me that should cause tremendous difficulty. I can't think of any JITing runtime we've run in Shadow up until now, but I don't know of any particular reason it'd be a problem. I do see the fchdir there as well, supporting the hypothesis that it's something we need for this to work properly, and not just something it tries to do after it's already on the "error path".

I'm not sure when we'll get around to pursuing this further; successfully running a JVM under Shadow would be a nice milestone, but it's not on our current roadmap. Any thoughts @robgjansen ?

2 replies

bentoumia Apr 26, 2022
Author

@sporksmith Many many thanks for the clarification!

bergerch Apr 26, 2022

@sporksmith Thank you very much for the clarification, I really appreciate the effort!

sporksmith · 2022-04-26T12:46:43Z

sporksmith
Apr 26, 2022
Collaborator

I looked a bit into why this (appears to) work in ptrace mode. It turns out the SIGSEGV does happen in ptrace mode as well, but it doesn't crash the process:

00:00:00.236851 [3986808:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [thread_ptrace.c:470] [_threadptrace_enterStateSignalled] Unhandled SIGSEGV at rip:00007fffd02ad62d
00:00:00.236854 [3986808:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [thread_ptrace.c:481] [_threadptrace_enterStateSignalled] Delivering signal 11

I believe the reason is because of how ptrace mode implements signals. It mostly delegates to native signal handling rather than emulating. This has its own problems, but in this case it appears that the managed process installs a SIGSEGV handler that recovers. In ptrace mode this is allowed to execute, but in preload mode it isn't. Opened #2091

I had started a PR before to fix this issue, but backburnered it partly because we didn't have any real world examples of needing it. I'll see if I can resurrect it...

Btw the fchdir syscalls happen in ptrace mode as well. Given that the example works in ptrace mode, it seems unlikely these are causing the crash, though they might cause unexpected behavior in larger examples.

1 reply

sporksmith Apr 26, 2022
Collaborator

Also confirmed in the previously attached strace log that the SIGSEGV happens outside of Shadow as well, but that the JVM handles it and finishes successfully.

3969799 --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=NULL} ---
3969799 rt_sigprocmask(SIG_UNBLOCK, [ILL TRAP BUS FPE SEGV], NULL, 8) = 0
3969799 rt_sigreturn({mask=[QUIT]})     = 0

sporksmith · 2022-04-26T18:03:50Z

sporksmith
Apr 26, 2022
Collaborator

Chatted a bit with @robgjansen. We agree it makes sense to prioritize fixing gaps in preload mode that don't exist in ptrace mode before we remove ptrace mode. Opened #2094 to track the java --version example in particular.

We're currently a bit less inclined to invest in implementing syscall handlers, unless they can be implemented in Rust. Release 2.2 is going to focus on migrating core Shadow code to Rust and making it easier for syscall handlers to be written in Rust. Any C syscall handlers we write in the meantime will eventually be rewritten in Rust, so we're trying to minimize doing so.

Unfortunately chdir and fchdir currently can't be easily written in Rust, so we'll probably hold off on these if possible. At least in the java --version example, it appears it might not be strictly needed yet after all.

Strangely, the simulation works and completes successfully with ptrace

@bentoumia Does your BFT-SMaRt work sufficiently well in ptrace mode for now?

3 replies

bentoumia Apr 26, 2022
Author

Hi @sporksmith,

Yup the BFT-SMaRt sim terminates successfully in ptrace, only those 3 syscalls keep appearing in the warnings as well as the SIGSEGV, but it terminates successfully and the system's behavior, judging by the logs, is not affected (i am not yet sure how accurate is the simulation in spite of the warnings as i have to test this further).

I really appreciate the effort and i am very thankful to you @sporksmith, @robgjansen and the whole Shadow team for the excellent support and i'm looking forward to the next release :)

sporksmith Apr 26, 2022
Collaborator

Happy to help! We're always excited to see more people using shadow for more things :)

bentoumia Apr 26, 2022
Author

i will soon share my experience simulating libhotstuff(https://github.com/hot-stuff/libhotstuff) and bft-smart. libhotstuff worked perfectly and i got accurate results :)

sporksmith · 2022-04-28T15:57:37Z

sporksmith
Apr 28, 2022
Collaborator

Closed #2094; java -version and Hello World now appear to work in preload mode. If you get a chance definitely interested in knowing whether your BFT-SMaRt works now as well.

0 replies

bentoumia · 2022-05-02T00:17:35Z

bentoumia
May 2, 2022
Author

Hi,

sorry for taking too long to get back to you. I am currently running into issues with the newest Shadow version, build goes through but many tests (141/202 tests) are failing with ***Failed Error regular expression found in output. Regex=[main error code '.*' for process] 1.11 sec. I tried to run some simulations despite the failing tests, they all exit with error code 134.

i updated all dependencies i have, rebuilt and retried to no avail. I will retry again in the next days and report back once the newest version is working on my system again.

Thanks again for your help! :)

8 replies

bentoumia May 5, 2022
Author

Hello and thank you for the fast reply!
bt for test-sleep:

root@localhost:~/shadow# gdb build/src/test/target/debug/test_sleep build/src/test/sleep/sleep-shadow-preload.data/hosts/testnode/core
GNU gdb (Ubuntu 9.2-0ubuntu1~20.04.1) 9.2
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from build/src/test/target/debug/test_sleep...
[New LWP 1188216]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/root/shadow/build/src/test/target/debug/test_sleep'.
Program terminated with signal SIGABRT, Aborted.
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:49
49	../sysdeps/unix/sysv/linux/raise.c: No such file or directory.
warning: Missing auto-load script at offset 0 in section .debug_gdb_scripts
of file /root/shadow/build/src/test/target/debug/test_sleep.
Use `info auto-load python-scripts [REGEXP]' to list them.
(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:49
#1  0x00007ffff7d8c864 in __GI_abort () at abort.c:79
#2  0x00007ffff72b3aad in _inject_trampoline (parsedElf=parsedElf@entry=0x7fffffffe6d0, vdsoFnName=vdsoFnName@entry=0x7ffff72bb0d4 "__vdso_gettimeofday",
    replacementFn=replacementFn@entry=0x7ffff72b3840 <_replacement_gettimeofday>) at /root/shadow/src/lib/shim/patch_vdso.c:202
#3  0x00007ffff72b3ce9 in patch_vdso (vdsoBase=0x7ffff7fcc000) at /root/shadow/src/lib/shim/patch_vdso.c:215
#4  0x00007ffff72b34e4 in _shim_parent_init_preload () at /root/shadow/src/lib/shim/shim.c:485
#5  _shim_load () at /root/shadow/src/lib/shim/shim.c:556
#6  0x00007ffff72b702a in shim_syscallv (n=96, args=args@entry=0x7fffffffe7c0) at /root/shadow/src/lib/shim/shim_syscall.c:255
#7  0x00007ffff72b4f33 in shim_api_syscallv (n=<optimized out>, args=args@entry=0x7fffffffe7c0) at /root/shadow/src/lib/shim/shim_api_syscall.c:24
#8  0x00007ffff7fba8b1 in syscall (n=n@entry=96) at /root/shadow/src/lib/libc_preload/libc_impls.c:36
#9  0x00007ffff7fb6cdb in gettimeofday (a=<optimized out>, b=<optimized out>, c=<optimized out>, d=<optimized out>, e=<optimized out>, f=<optimized out>)
    at /root/shadow/src/lib/libc_preload/syscall_wrappers.c:321
#10 0x00007ffff71cc612 in g_get_real_time () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#11 0x00007ffff71eaddf in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#12 0x00007ffff71ebf23 in g_slice_alloc () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#13 0x00007ffff71b9c42 in g_hash_table_new_full () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#14 0x00007ffff71dd713 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#15 0x00007ffff7fdfdbe in ?? () from /lib64/ld-linux-x86-64.so.2
#16 0x00007ffff7fdfea8 in ?? () from /lib64/ld-linux-x86-64.so.2
#17 0x00007ffff7fcf10a in ?? () from /lib64/ld-linux-x86-64.so.2
#18 0x0000000000000001 in ?? ()
#19 0x00007fffffffec56 in ?? ()
#20 0x0000000000000000 in ?? ()
(gdb)

Huh; that's surprising. Not sure why it wouldn't also hit the rseq issue.

Here are the logs if you are interested in finding out more:

00:00:00.000002 [185067:shadow] n/a [INFO] [n/a] [main.c:68] [main_logBuildInfo] Starting Shadow v2.0.0-609-gecf31165 2022-04-29--11:10:37 with GLib v2.72.1
** Starting Shadow v2.0.0-609-gecf31165 2022-04-29--11:10:37 with GLib v2.72.1
00:00:00.005269 [185067:shadow] n/a [INFO] [n/a] [main.c:72] [main_logBuildInfo] Shadow was built from branch main on 2022-05-02--02:22:18 in Release mode with compile options: -ggdb;-fno-omit-frame-pointer;-Wreturn-type;-Wswitch;-O3 and link options: -Wl,--no-as-needed
00:00:00.005281 [185067:shadow] n/a [INFO] [n/a] [main.c:73] [main_logBuildInfo] For more information, visit https://shadow.github.io or https://github.com/shadow
00:00:00.005284 [185067:shadow] n/a [INFO] [n/a] [main.c:74] [main_logBuildInfo] Logging current startup arguments and environment
00:00:00.005287 [185067:shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: shadow
00:00:00.005289 [185067:shadow] n/a [INFO] [n/a] [main.rs:217] [shadow_rs::core::main] arg: shadow.yaml
00:00:00.005350 [185067:shadow] n/a [INFO] [n/a] [controller.c:116] [controller_new] simulation controller created
00:00:00.005368 [185067:shadow] n/a [INFO] [n/a] [controller.c:472] [controller_run] loading and initializing simulation data
00:00:00.005615 [185067:shadow] n/a [INFO] [n/a] [manager.c:189] [_manager_getRequiredPreloadPath] Found required preload library libshadow_injector.so at path /home/sadok/.local/lib/libshadow_injector.so.
00:00:00.005622 [185067:shadow] n/a [INFO] [n/a] [manager.c:189] [_manager_getRequiredPreloadPath] Found required preload library libshadow_libc.so at path /home/sadok/.local/lib/libshadow_libc.so.
00:00:00.005625 [185067:shadow] n/a [INFO] [n/a] [manager.c:189] [_manager_getRequiredPreloadPath] Found required preload library libshadow_openssl_rng.so at path /home/sadok/.local/lib/libshadow_openssl_rng.so.
00:00:00.005626 [185067:shadow] n/a [INFO] [n/a] [manager.c:259] [manager_new] Preloading the openssl crypto library is disabled.
00:00:00.005780 [185067:shadow] n/a [INFO] [n/a] [scheduler.c:178] [scheduler_new] main scheduler thread will operate with 1 worker threads
00:00:00.005900 [185067:shadow] n/a [INFO] [n/a] [controller.c:496] [controller_run] registering plugins and hosts
00:00:00.005917 [185067:shadow] n/a [INFO] [n/a] [host.c:145] [host_new] Created host id '1' name 'h1'
00:00:00.006040 [185067:shadow] n/a [INFO] [n/a] [host.c:243] [host_setup] Setup host id '1' name 'h1' with seed 3206231788, ip 11.0.0.1, 122070 bwUpKiBps, 122070 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 4200000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.006362 [185067:shadow] n/a [INFO] [n/a] [controller.c:519] [controller_run] using an initial minimum runahead of 1000000 ns
00:00:00.006368 [185067:shadow] n/a [INFO] [n/a] [controller.c:527] [controller_run] running simulation
00:00:00.006369 [185067:shadow] n/a [INFO] [n/a] [controller.c:531] [controller_run] log message buffering is enabled for efficiency
00:00:00.006435 [185071:shadow-worker] n/a [INFO] [n/a] [scheduler.c:69] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.006453 [185071:shadow-worker] n/a [INFO] [n/a] [scheduler.c:71] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.006626 [185071:shadow-worker] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [process.c:550] [_process_start] starting process 'h1.java.1000'
00:00:00.006644 [185071:shadow-worker] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [thread_ptrace.c:693] [threadptrace_run] forking new thread with environment 'SHADOW_SPAWNED=TRUE SHADOW_LOG_START_TIME=205033930012 SHADOW_LOG_LEVEL=3 SHADOW_INTERPOSE_METHOD=PTRACE LD_PRELOAD=/home/sadok/.local/lib/libshadow_injector.so:/home/sadok/.local/lib/libshadow_libc.so:/home/sadok/.local/lib/libshadow_openssl_rng.so SHADOW_SHM_HOST_BLK=8,134217728,112,/shadow_shmemfile_205033.935931522-185067 SHADOW_SHM_PROCESS_BLK=8200,134217728,6040,/shadow_shmemfile_205033.935931522-185067 SHADOW_LOG_FILE=/home/sadok/shadowtest/shadow.data/hosts/h1/h1.java.1000.shimlog SHADOW_SHM_THREAD_BLK=4104,134217728,4024,/shadow_shmemfile_205033.935931522-185067', arguments '/usr/lib/jvm/java-11-temurin/bin/java --version', and working directory '/home/sadok/shadowtest'
00:00:00.006744 [185071:shadow-worker] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [process.c:585] [_process_start] process 'h1.java.1000' started
00:00:00.012372 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 334 called from thread 1000 in process h1.java.1000 on host h1
00:00:00.012374 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 334, which may result in unusual behavior
00:00:00.020101 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [memory_mapper.rs:477] [shadow_rs::host::memory_manager::memory_mapper] munmap: EINVAL: Invalid argument
00:00:00.021213 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [memory_mapper.rs:477] [shadow_rs::host::memory_manager::memory_mapper] munmap: EINVAL: Invalid argument
00:00:00.021722 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.021724 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.022031 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.022033 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.022282 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 229 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.022283 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 229, which may result in unusual behavior
00:00:00.022622 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 309 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.022623 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 309, which may result in unusual behavior
00:00:00.023166 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [unix.rs:1787] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:00:00.023187 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [unix.rs:1787] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:00:00.023556 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 81 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.023557 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 81, which may result in unusual behavior
00:00:00.023807 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 81 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.023808 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 81, which may result in unusual behavior
00:00:00.023995 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.023996 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.024061 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.024062 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.024790 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [memory_mapper.rs:477] [shadow_rs::host::memory_manager::memory_mapper] munmap: EINVAL: Invalid argument
00:00:00.025138 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.025139 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.025714 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [thread_ptrace.c:470] [_threadptrace_enterStateSignalled] Unhandled SIGSEGV at rip:00007fffd083e62d
00:00:00.025716 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [thread_ptrace.c:481] [_threadptrace_enterStateSignalled] Delivering signal 11
00:00:00.026585 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1002 in process h1.java.1000 on host h1
00:00:00.026586 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.026665 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1002 in process h1.java.1000 on host h1
00:00:00.026666 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.028282 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1003 in process h1.java.1000 on host h1
00:00:00.028284 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.028350 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1003 in process h1.java.1000 on host h1
00:00:00.028351 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.028907 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1004 in process h1.java.1000 on host h1
00:00:00.028908 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.028974 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1004 in process h1.java.1000 on host h1
00:00:00.028974 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.039767 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1005 in process h1.java.1000 on host h1
00:00:00.039769 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.039850 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1005 in process h1.java.1000 on host h1
00:00:00.039852 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.040414 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1006 in process h1.java.1000 on host h1
00:00:00.040415 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.040480 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1006 in process h1.java.1000 on host h1
00:00:00.040481 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.053057 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1007 in process h1.java.1000 on host h1
00:00:00.053059 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.053138 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1007 in process h1.java.1000 on host h1
00:00:00.053139 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.056652 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.056655 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.058130 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1008 in process h1.java.1000 on host h1
00:00:00.058132 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.058169 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1008 in process h1.java.1000 on host h1
00:00:00.058170 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.058959 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1009 in process h1.java.1000 on host h1
00:00:00.058961 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.059090 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1009 in process h1.java.1000 on host h1
00:00:00.059091 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.059152 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1009 in process h1.java.1000 on host h1
00:00:00.059153 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.070686 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1010 in process h1.java.1000 on host h1
00:00:00.070688 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.070764 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1010 in process h1.java.1000 on host h1
00:00:00.070765 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.071314 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1011 in process h1.java.1000 on host h1
00:00:00.071316 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.071383 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1011 in process h1.java.1000 on host h1
00:00:00.071384 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.071874 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1012 in process h1.java.1000 on host h1
00:00:00.071875 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.071936 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1012 in process h1.java.1000 on host h1
00:00:00.071937 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.076881 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1013 in process h1.java.1000 on host h1
00:00:00.076883 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.076948 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1013 in process h1.java.1000 on host h1
00:00:00.076949 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.077742 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1014 in process h1.java.1000 on host h1
00:00:00.077744 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.077806 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1014 in process h1.java.1000 on host h1
00:00:00.077806 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.112317 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1015 in process h1.java.1000 on host h1
00:00:00.112319 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.112401 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1015 in process h1.java.1000 on host h1
00:00:00.112401 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.113590 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.113593 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.113671 [185071:shadow-worker] 00:00:00.000000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process h1.java.1000 on host h1
00:00:00.113672 [185071:shadow-worker] 00:00:00.000000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior
00:00:00.114090 [185071:shadow-worker] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 17 syscalls
00:00:00.114098 [185071:shadow-worker] 00:00:00.000000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1015 (java) syscall counts: {rt_sigprocmask:5, futex:4, getpid:1, gettid:1, mmap:1, mprotect:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.122133 [185071:shadow-worker] 00:00:00.001000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 98 called from thread 1003 in process h1.java.1000 on host h1
00:00:00.122135 [185071:shadow-worker] 00:00:00.001000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 98, which may result in unusual behavior
00:00:00.122230 [185071:shadow-worker] 00:00:00.001000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 98 called from thread 1005 in process h1.java.1000 on host h1
00:00:00.122231 [185071:shadow-worker] 00:00:00.001000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 98, which may result in unusual behavior
00:00:00.122361 [185071:shadow-worker] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 19 syscalls
00:00:00.122368 [185071:shadow-worker] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1005 (java) syscall counts: {futex:6, rt_sigprocmask:5, getpid:1, gettid:1, mmap:1, mprotect:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.122392 [185071:shadow-worker] 00:00:00.001000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 98 called from thread 1006 in process h1.java.1000 on host h1
00:00:00.122393 [185071:shadow-worker] 00:00:00.001000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 98, which may result in unusual behavior
00:00:00.122455 [185071:shadow-worker] 00:00:00.001000001 [WARN] [h1:11.0.0.1] [syscall_handler.c:520] [syscallhandler_make_syscall] Detected unsupported syscall 98 called from thread 1006 in process h1.java.1000 on host h1
00:00:00.122456 [185071:shadow-worker] 00:00:00.001000001 [ERROR] [h1:11.0.0.1] [syscall_handler.c:524] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 98, which may result in unusual behavior
00:00:00.122583 [185071:shadow-worker] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 22 syscalls
00:00:00.122588 [185071:shadow-worker] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1006 (java) syscall counts: {futex:8, rt_sigprocmask:5, getpid:1, gettid:1, mmap:1, mprotect:1, munmap:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.122671 [185071:shadow-worker] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 23 syscalls
00:00:00.122675 [185071:shadow-worker] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1003 (java) syscall counts: {futex:8, rt_sigprocmask:5, munmap:2, getpid:1, gettid:1, mmap:1, mprotect:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.122929 [185071:shadow-worker] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 22 syscalls
00:00:00.122934 [185071:shadow-worker] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1010 (java) syscall counts: {rt_sigprocmask:6, futex:4, mmap:3, mprotect:2, getpid:1, gettid:1, munmap:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.123043 [185071:shadow-worker] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 28 syscalls
00:00:00.123047 [185071:shadow-worker] 00:00:00.001000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1007 (java) syscall counts: {futex:15, rt_sigprocmask:5, getpid:1, gettid:1, mmap:1, mprotect:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.123216 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 1359 syscalls
00:00:00.123226 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1001 (java) syscall counts: {mprotect:545, pread64:385, mmap:96, futex:63, rt_sigprocmask:39, close:32, openat:31, read:29, newfstatat:25, rt_sigaction:23, write:20, clone:14, munmap:13, lseek:8, open:7, fstat:6, fcntl:3, getpid:3, uname:3, connect:2, getdents64:2, gettid:2, socket:2, sysinfo:2, nanosleep:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.123447 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 296 syscalls
00:00:00.123455 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1000 (java) syscall counts: {mmap:79, openat:75, newfstatat:48, mprotect:25, close:20, read:19, munmap:6, pread64:5, brk:4, rt_sigprocmask:3, getpid:2, clone:1, exit_group:1, futex:1, getrandom:1, prlimit64:1, rt_sigaction:1, set_robust_list:1, set_tid_address:1, shadow_init_memory_manager:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.123470 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 17 syscalls
00:00:00.123474 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1009 (java) syscall counts: {futex:4, rt_sigprocmask:4, mmap:2, mprotect:2, getpid:1, gettid:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.123489 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 35 syscalls
00:00:00.123493 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1012 (java) syscall counts: {mprotect:13, futex:10, rt_sigprocmask:4, mmap:2, getpid:1, gettid:1, munmap:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.123504 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 16 syscalls
00:00:00.123508 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1004 (java) syscall counts: {futex:4, rt_sigprocmask:4, getpid:1, gettid:1, mmap:1, mprotect:1, munmap:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.123520 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 173 syscalls
00:00:00.123524 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1013 (java) syscall counts: {gettid:109, sysinfo:35, futex:10, mprotect:9, rt_sigprocmask:4, mmap:2, getpid:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.123550 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 21 syscalls
00:00:00.123554 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1002 (java) syscall counts: {futex:8, rt_sigprocmask:4, munmap:2, getpid:1, gettid:1, mmap:1, mprotect:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.123571 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 18 syscalls
00:00:00.123575 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1008 (java) syscall counts: {futex:4, rt_sigprocmask:4, mmap:2, mprotect:2, getpid:1, gettid:1, munmap:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.123592 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 17 syscalls
00:00:00.123595 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1011 (java) syscall counts: {futex:4, rt_sigprocmask:4, mmap:2, mprotect:2, getpid:1, gettid:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.124667 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:97] [_syscallhandler_free] handled 18 syscalls
00:00:00.124671 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [syscall_handler.c:103] [_syscallhandler_free] Thread 1014 (java) syscall counts: {futex:4, rt_sigprocmask:4, mmap:2, mprotect:2, getpid:1, gettid:1, munmap:1, prctl:1, set_robust_list:1, shadow_get_shm_blk:1, shadow_set_ptrace_allow_native_syscalls:1}
00:00:00.124676 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [process.c:441] [_process_check] process 'h1.java.1000' has completed or is otherwise no longer running
00:00:00.124750 [185071:shadow-worker] 00:00:00.002000001 [INFO] [h1:11.0.0.1] [process.c:396] [_process_getAndLogReturnCode] main success code '0' for process 'h1.java.1000'
00:00:00.124833 [185067:shadow] n/a [INFO] [n/a] [manager.c:708] [_manager_heartbeat] process resource usage at simtime 1000000001 reported by getrusage(): ru_maxrss=0.161282 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=5029, ru_nivcsw=147
00:00:00.124897 [185067:shadow] n/a [INFO] [n/a] [manager.c:708] [_manager_heartbeat] process resource usage at simtime 3000000001 reported by getrusage(): ru_maxrss=0.161282 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=5032, ru_nivcsw=147
00:00:00.124965 [185067:shadow] n/a [INFO] [n/a] [manager.c:708] [_manager_heartbeat] process resource usage at simtime 5000000001 reported by getrusage(): ru_maxrss=0.161282 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=5035, ru_nivcsw=147
00:00:00.124977 [185067:shadow] n/a [INFO] [n/a] [manager.c:708] [_manager_heartbeat] process resource usage at simtime 7000000001 reported by getrusage(): ru_maxrss=0.161282 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=5038, ru_nivcsw=147
00:00:00.124995 [185067:shadow] n/a [INFO] [n/a] [manager.c:708] [_manager_heartbeat] process resource usage at simtime 9000000001 reported by getrusage(): ru_maxrss=0.161282 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=5041, ru_nivcsw=147
00:00:00.125013 [185067:shadow] n/a [INFO] [n/a] [manager.c:708] [_manager_heartbeat] process resource usage at simtime 11000000001 reported by getrusage(): ru_maxrss=0.161282 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=5044, ru_nivcsw=147
00:00:00.125030 [185067:shadow] n/a [INFO] [n/a] [manager.c:708] [_manager_heartbeat] process resource usage at simtime 13000000001 reported by getrusage(): ru_maxrss=0.161282 GiB, ru_utime=0.000000 minutes, ru_stime=0.000000 minutes, ru_nvcsw=5047, ru_nivcsw=147
00:00:00.125041 [185071:shadow-worker] 00:00:15.000000000 [INFO] [n/a] [worker.c:476] [worker_finish] starting to shut down 1 hosts
00:00:00.125043 [185071:shadow-worker] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [process.c:690] [process_stop] terminating process 'h1.java.1000'
00:00:00.125044 [185071:shadow-worker] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [process.c:441] [_process_check] process 'h1.java.1000' has completed or is otherwise no longer running
00:00:00.125045 [185071:shadow-worker] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [process.c:713] [process_stop] process 'h1.java.1000' stopped
00:00:00.125045 [185071:shadow-worker] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [process.c:441] [_process_check] process 'h1.java.1000' has completed or is otherwise no longer running
00:00:00.125046 [185071:shadow-worker] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [process.c:441] [_process_check] process 'h1.java.1000' has completed or is otherwise no longer running
00:00:00.125524 [185071:shadow-worker] 00:00:15.000000000 [WARN] [h1:11.0.0.1] [memory_mapper.rs:322] [shadow_rs::host::memory_manager::memory_mapper] munmap: EINVAL: Invalid argument
00:00:00.125533 [185071:shadow-worker] 00:00:15.000000000 [WARN] [h1:11.0.0.1] [memory_mapper.rs:322] [shadow_rs::host::memory_manager::memory_mapper] munmap: EINVAL: Invalid argument
00:00:00.126465 [185071:shadow-worker] 00:00:15.000000000 [INFO] [h1:11.0.0.1] [host.c:317] [host_shutdown] host 'h1' has been shut down
00:00:00.126467 [185071:shadow-worker] 00:00:15.000000000 [INFO] [n/a] [worker.c:479] [worker_finish] 1 hosts are shut down
00:00:00.126489 [185067:shadow] n/a [INFO] [n/a] [controller.c:541] [controller_run] log message buffering is disabled during cleanup
00:00:00.126490 [185067:shadow] n/a [INFO] [n/a] [controller.c:545] [controller_run] simulation finished, cleaning up now
00:00:00.126526 [185067:shadow] n/a [INFO] [n/a] [scheduler.c:186] [scheduler_shutdown] scheduler is shutting down now
00:00:00.126527 [185067:shadow] n/a [INFO] [n/a] [scheduler.c:193] [scheduler_shutdown] waiting for 1 worker threads to finish
00:00:00.126564 [185067:shadow] n/a [INFO] [n/a] [scheduler.c:206] [_scheduler_free] 1 worker threads finished
00:00:00.126581 [185067:shadow] n/a [INFO] [n/a] [manager.c:366] [manager_free] Global syscall counts: {mprotect:609, pread64:390, mmap:197, futex:157, gettid:124, openat:106, rt_sigprocmask:105, newfstatat:73, close:52, read:48, sysinfo:37, munmap:29, rt_sigaction:24, write:20, getpid:19, set_robust_list:16, shadow_set_ptrace_allow_native_syscalls:16, clone:15, shadow_get_shm_blk:15, prctl:14, lseek:8, open:7, fstat:6, brk:4, fcntl:3, uname:3, connect:2, getdents64:2, socket:2, exit_group:1, getrandom:1, nanosleep:1, prlimit64:1, set_tid_address:1, shadow_init_memory_manager:1}
00:00:00.126590 [185067:shadow] n/a [INFO] [n/a] [manager.c:373] [manager_free] Global allocated object counts: {LegacyDescriptor:146, Event:124, Task:124, File:116, StatusListener:75, SysCallCondition:62, Futex:61, Epoll:16, SysCallHandler:16, ThreadPtrace:16, Timer:14, NetworkInterface:2, FutexTable:1, Host:1, Process:1, Router:1}
00:00:00.126597 [185067:shadow] n/a [INFO] [n/a] [manager.c:377] [manager_free] Global deallocated object counts: {LegacyDescriptor:146, Event:124, Task:124, File:116, StatusListener:75, SysCallCondition:62, Futex:61, Epoll:16, SysCallHandler:16, ThreadPtrace:16, Timer:14, NetworkInterface:2, FutexTable:1, Host:1, Process:1, Router:1}
00:00:00.126600 [185067:shadow] n/a [INFO] [n/a] [manager.c:382] [manager_free] We allocated and deallocated the same number of objects :)
00:00:00.126606 [185067:shadow] n/a [INFO] [n/a] [controller.c:151] [controller_free] simulation controller destroyed
** Shadow completed successfully

Many thanks again! i really appreciate it.

sporksmith May 5, 2022
Collaborator

Thanks for the follow-up info!

#2 0x00007ffff72b3aad in _inject_trampoline (parsedElf=parsedElf@entry=0x7fffffffe6d0, vdsoFnName=vdsoFnName@entry=0x7ffff72bb0d4 "__vdso_gettimeofday",
replacementFn=replacementFn@entry=0x7ffff72b3840 <_replacement_gettimeofday>) at /root/shadow/src/lib/shim/patch_vdso.c:202

So that's here:

shadow/src/lib/shim/patch_vdso.c

Line 202 in c2f6cad

panic("Accidentally wrote %zd byte trampoline into %zd byte symbol %s",

I'm not sure how this could fail unless symbol->st_size is somehow changing between the line 171 check and the line 201 check; or that the actual trampoline size is larger than 13 bytes, but I don't see how that can happen either.

It might be interesting to see the relevant sizes in the panic log message, which should be at the end of build/src/test/sleep/sleep-shadow-preload.data/hosts/testnode/*.shimlog

Otherwise this is about the point where I'd start stepping through this function with gdb to see where things are going awry. I can't do that myself since I can't reproduce. LMK if you're interested in digging further and I can try to walk you through using gdb; otherwise maybe you can just carry on with ptrace-mode for now until if and when you're on a supported platform and we can revisit.

Btw I'm also not sure why you would hit this error in preload mode, but not in ptrace mode, which also patches the vdso...

sporksmith May 5, 2022
Collaborator

Btw so far the only place we've seen this vdso patch needed is in golang, but I wouldn't be surprised if java needs it as well. e.g. C and Rust programs call the gettimeofday libc functions, which we intercept with LD_PRELOAD, preventing the vdso from ever being accessed in the first place.

A potential short term workaround is to just inject a ud2 instruction over the vdso functions to ensure a crash in case they are somehow invoked. e.g. change line 186+ to:

    *(current++) = 0x0f;
    *(current++) = 0x0b;
    return;

bentoumia May 5, 2022
Author

Thanks for the follow-up info!

Happy to help anyway i can with my limited knowledge!

It might be interesting to see the relevant sizes in the panic log message, which should be at the end of build/src/test/sleep/sleep-shadow-preload.data/hosts/testnode/*.shimlog

Otherwise this is about the point where I'd start stepping through this function with gdb to see where things are going awry. I can't do that myself since I can't reproduce. LMK if you're interested in digging further and I can try to walk you through using gdb; otherwise maybe you can just carry on with ptrace-mode for now until if and when you're on a supported platform and we can revisit.

I will probably switch to a supported Platform/use dockerized Shadow by next week. But if you are interested in finding out more, i will happily investigate the issue further if you walk me through gdb :D

bentoumia May 6, 2022
Author

Btw so far the only place we've seen this vdso patch needed is in golang, but I wouldn't be surprised if java needs it as well. e.g. C and Rust programs call the gettimeofday libc functions, which we intercept with LD_PRELOAD, preventing the vdso from ever being accessed in the first place.

A potential short term workaround is to just inject a ud2 instruction over the vdso functions to ensure a crash in case they are somehow invoked. e.g. change line 186+ to:
    *(current++) = 0x0f;
    *(current++) = 0x0b;
    return;

Hello again,

so i just got around to try this and that sadly didnt fix it. It is okay tho ill be switching to a supported platform soon :)

Thanks again!

Simulating JVM #2084

Uh oh!

bentoumia Apr 25, 2022

Replies: 9 comments · 19 replies

Uh oh!

stevenengler Apr 25, 2022 Collaborator

Uh oh!

Uh oh!

bentoumia Apr 26, 2022 Author

Uh oh!

sporksmith Apr 25, 2022 Collaborator

Uh oh!

Uh oh!

bentoumia Apr 26, 2022 Author

Uh oh!

sporksmith Apr 26, 2022 Collaborator

Uh oh!

Uh oh!

bentoumia Apr 26, 2022 Author

Uh oh!

sporksmith Apr 25, 2022 Collaborator

Uh oh!

Uh oh!

bentoumia Apr 26, 2022 Author

Uh oh!

bentoumia Apr 26, 2022 Author

Uh oh!

sporksmith Apr 26, 2022 Collaborator

Uh oh!

bentoumia Apr 26, 2022 Author

Uh oh!

bergerch Apr 26, 2022

Uh oh!

sporksmith Apr 26, 2022 Collaborator

Uh oh!

sporksmith Apr 26, 2022 Collaborator

Uh oh!

sporksmith Apr 26, 2022 Collaborator

Uh oh!

bentoumia Apr 26, 2022 Author

Uh oh!

sporksmith Apr 26, 2022 Collaborator

Uh oh!

Uh oh!

bentoumia Apr 26, 2022 Author

Uh oh!

sporksmith Apr 28, 2022 Collaborator

Uh oh!

bentoumia May 2, 2022 Author

Uh oh!

bentoumia May 5, 2022 Author

Uh oh!

sporksmith May 5, 2022 Collaborator

Uh oh!

sporksmith May 5, 2022 Collaborator

Uh oh!

Uh oh!

bentoumia May 5, 2022 Author

Uh oh!

bentoumia May 6, 2022 Author

bentoumia
Apr 25, 2022

Replies: 9 comments 19 replies

stevenengler
Apr 25, 2022
Collaborator

bentoumia Apr 26, 2022
Author

sporksmith
Apr 25, 2022
Collaborator

bentoumia Apr 26, 2022
Author

sporksmith Apr 26, 2022
Collaborator

bentoumia Apr 26, 2022
Author

sporksmith
Apr 25, 2022
Collaborator

bentoumia Apr 26, 2022
Author

bentoumia
Apr 26, 2022
Author

sporksmith
Apr 26, 2022
Collaborator

bentoumia Apr 26, 2022
Author

sporksmith
Apr 26, 2022
Collaborator

sporksmith Apr 26, 2022
Collaborator

sporksmith
Apr 26, 2022
Collaborator

bentoumia Apr 26, 2022
Author

sporksmith Apr 26, 2022
Collaborator

bentoumia Apr 26, 2022
Author

sporksmith
Apr 28, 2022
Collaborator

bentoumia
May 2, 2022
Author

bentoumia May 5, 2022
Author

sporksmith May 5, 2022
Collaborator

sporksmith May 5, 2022
Collaborator

bentoumia May 5, 2022
Author

bentoumia May 6, 2022
Author