Delphi-BFT / tool

Delphi-BFT automates large-scale simulations of unmodified BFT protocol implementations through the Phantom simulator given a simple experimental description. For the first time, experiments with existing BFT protocol implementations can be effortless setup, configured and fed into a simulation engine
https://github.com/Delphi-BFT/tool
GNU Affero General Public License v3.0
10 stars 4 forks source link

Themis example problem #36

Closed zaminsirat closed 8 months ago

zaminsirat commented 8 months ago

I ran the Themis example, but it seems it did not reach a consensus, and I encountered some errors. Could you please tell me if everything works correctly? I am concerned about missing packages or system errors.

user@user:~/sim/tool$ npm run simulation -- examples/themis/themis-uniform.yaml

Delphi-BFT@1.0.0 simulation
 node ./src/orchestrator.js "examples/themis/themis-uniform.yaml"

2024-02-21T12:09:11.527Z [info] : [object Object] 
2024-02-21T12:09:11.528Z [info] : initiating orchestrator... 
{
  name: '4rep',
  misc: {
    runahead: '630 us',
    duration: '6 s',
    parallelism: 1,
    useShortestPath: false
  },
  network: {
    replicaBandwidthUp: '10 Gibits',
    replicaBandwidthDown: '10 Gibits',
    clientBandwidthUp: '100 Gibits',
    clientBandwidthDown: '100 Gibits',
    latency: { uniform: true, replicas: '10000 us', clients: '700 us' },
    packetLoss: 0
  },
  replica: {
    replicas: 4,
    minBatchSize: 400,
    maxBatchSize: 400,
    replySize: 1024,
    batchReplies: true,
    requestTimeout: 40000,
    batchTimeout: { secs: 0, nano: 10000000 }
  },
  client: {
    numberOfHosts: 1,
    clients: 4,
    startTime: '2 s',
    payload: 1024,
    concurrent: 175,
    duration: 8
  }
}
2024-02-21T12:09:11.530Z [info] : starting new experiment ... 
2024-02-21T12:09:11.530Z [info] : deleting clashing directories ... 
2024-02-21T12:09:11.532Z [info] : Calling protocol build function ... 
2024-02-21T12:09:11.532Z [info] : building Themis ... 
2024-02-21T12:09:11.532Z [info] : launching cargo with args: build,--bins with working Directory: /home/user/sim/tool/themis 
2024-02-21T12:09:12.020Z [error] : childprocess:     Finished dev [unoptimized + debuginfo] target(s) in 0.31s

2024-02-21T12:09:12.024Z [info] : child proess terminated with code: 0 
2024-02-21T12:09:12.025Z [info] : Themis build terminated sucessfully! 
2024-02-21T12:09:12.025Z [info] : Calling protocol configure function ... 
2024-02-21T12:09:12.025Z [info] : parsing replica and client objects 
2024-02-21T12:09:12.025Z [info] : objects parsed! 
2024-02-21T12:09:12.025Z [info] : generating keys for 4 replicas... 
2024-02-21T12:09:12.026Z [warn] : using a pre-existing keys directory 
2024-02-21T12:09:12.026Z [info] : launching cargo with args: run,--bin,keygen,--,Ed25519,0,4,--out-dir,keys with working Directory: /home/user/sim/tool/themis 
2024-02-21T12:09:12.114Z [error] : childprocess:     Finished dev [unoptimized + debuginfo] target(s) in 0.05s

2024-02-21T12:09:12.116Z [error] : childprocess:      Running `target/debug/keygen Ed25519 0 4 --out-dir keys`

2024-02-21T12:09:12.147Z [info] : child proess terminated with code: 0 
2024-02-21T12:09:12.148Z [info] : keys generated successfully! 
2024-02-21T12:09:12.149Z [info] : generating Themis config ... 
2024-02-21T12:09:12.158Z [info] : Config file generated! 
2024-02-21T12:09:12.158Z [info] : Created Shadow Host Config sucessfully 
2024-02-21T12:09:12.161Z [info] : launching shadow with args: --use-memory-manager=false,shadow.yaml with working Directory: /home/user/sim/tool/themis 
2024-02-21T12:09:12.338Z [error] : childprocess: ** Starting Shadow v2.2.0 with GLib v2.72.4

2024-02-21T12:09:12.338Z [info] : childprocess: 00:00:00.000001 [127399:shadow] n/a [INFO] [n/a] [main.c:68] [main_logBuildInfo] Starting Shadow v2.2.0 with GLib v2.72.4
00:00:00.000083 [127399:shadow] n/a [INFO] [n/a] [main.c:72] [main_logBuildInfo] Shadow was built on 2024-02-19--11:32:27 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.000085 [127399: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.000086 [127399:shadow] n/a [INFO] [n/a] [main.c:74] [main_logBuildInfo] Logging current startup arguments and environment
00:00:00.000087 [127399:shadow] n/a [INFO] [n/a] [main.rs:229] [shadow_rs::core::main] arg: shadow
00:00:00.000087 [127399:shadow] n/a [INFO] [n/a] [main.rs:229] [shadow_rs::core::main] arg: --use-memory-manager=false
00:00:00.000087 [127399:shadow] n/a [INFO] [n/a] [main.rs:229] [shadow_rs::core::main] arg: shadow.yaml

2024-02-21T12:09:12.433Z [info] : childprocess: 00:00:00.000422 [127399:shadow] n/a [INFO] [n/a] [main.rs:168] [shadow_rs::core::main] Log message buffering is enabled for efficiency
00:00:00.000453 [127399:shadow] n/a [INFO] [n/a] [manager.rs:770] [shadow_rs::core::manager] Found required preload library libshadow_injector.so at path /home/user/.local/lib/libshadow_injector.so
00:00:00.000456 [127399:shadow] n/a [INFO] [n/a] [manager.rs:770] [shadow_rs::core::manager] Found required preload library libshadow_libc.so at path /home/user/.local/lib/libshadow_libc.so
00:00:00.000459 [127399:shadow] n/a [INFO] [n/a] [manager.rs:770] [shadow_rs::core::manager] Found required preload library libshadow_openssl_rng.so at path /home/user/.local/lib/libshadow_openssl_rng.so
00:00:00.000460 [127399:shadow] n/a [INFO] [n/a] [manager.rs:107] [shadow_rs::core::manager] Preloading the openssl crypto library is disabled
00:00:00.005242 [127399:shadow] n/a [INFO] [n/a] [controller.rs:101] [shadow_rs::core::controller] Running simulation
00:00:00.005523 [127399:shadow] n/a [INFO] [n/a] [scheduler.c:173] [scheduler_new] main scheduler thread will operate with 5 worker threads
00:00:00.005527 [127399:shadow] n/a [INFO] [n/a] [host.c:148] [host_new] Created host id '1' name 'themisClient0'
00:00:00.005940 [127399:shadow] n/a [INFO] [n/a] [host.c:246] [host_setup] Setup host id '1' name 'themisClient0' with seed 2099880381, ip 11.16.248.176, 13107200 bwUpKiBps, 13107200 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.005982 [127399:shadow] n/a [INFO] [n/a] [host.c:148] [host_new] Created host id '2' name 'themisReplica0'
00:00:00.006225 [127399:shadow] n/a [INFO] [n/a] [host.c:246] [host_setup] Setup host id '2' name 'themisReplica0' with seed 595507150, ip 11.92.212.145, 1310720 bwUpKiBps, 1310720 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.006254 [127399:shadow] n/a [INFO] [n/a] [host.c:148] [host_new] Created host id '3' name 'themisReplica1'
00:00:00.006303 [127399:shadow] n/a [INFO] [n/a] [host.c:246] [host_setup] Setup host id '3' name 'themisReplica1' with seed 1771684222, ip 11.92.217.160, 1310720 bwUpKiBps, 1310720 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.006325 [127399:shadow] n/a [INFO] [n/a] [host.c:148] [host_new] Created host id '4' name 'themisReplica2'
00:00:00.006384 [127399:shadow] n/a [INFO] [n/a] [host.c:246] [host_setup] Setup host id '4' name 'themisReplica2' with seed 1348384461, ip 11.138.123.72, 1310720 bwUpKiBps, 1310720 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.006417 [127399:shadow] n/a [INFO] [n/a] [host.c:148] [host_new] Created host id '5' name 'themisReplica3'
00:00:00.006656 [127399:shadow] n/a [INFO] [n/a] [host.c:246] [host_setup] Setup host id '5' name 'themisReplica3' with seed 519913615, ip 11.126.140.97, 1310720 bwUpKiBps, 1310720 bwDownKiBps, 131072 initSockSendBufSize, 174760 initSockRecvBufSize, 2500000 cpuFrequency, 0 cpuThreshold, 200 cpuPrecision
00:00:00.006726 [127404:shadow-worker] n/a [INFO] [n/a] [scheduler.c:66] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.006744 [127404:shadow-worker] n/a [INFO] [n/a] [scheduler.c:68] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.006751 [127405:shadow-worker] n/a [INFO] [n/a] [scheduler.c:66] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.006758 [127405:shadow-worker] n/a [INFO] [n/a] [scheduler.c:68] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.006762 [127406:shadow-worker] n/a [INFO] [n/a] [scheduler.c:66] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.006769 [127406:shadow-worker] n/a [INFO] [n/a] [scheduler.c:68] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.006773 [127407:shadow-worker] n/a [INFO] [n/a] [scheduler.c:66] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.006779 [127407:shadow-worker] n/a [INFO] [n/a] [scheduler.c:68] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.006783 [127408:shadow-worker] n/a [INFO] [n/a] [scheduler.c:66] [_scheduler_startHostsWorkerTaskFn] starting to boot 1 hosts
00:00:00.006789 [127408:shadow-worker] n/a [INFO] [n/a] [scheduler.c:68] [_scheduler_startHostsWorkerTaskFn] 1 hosts are booted
00:00:00.006923 [127404:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica3:11.126.140.97] [process.c:563] [_process_start] starting process 'themisReplica3.themis-bench-app.1000'
00:00:00.006943 [127404:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica3:11.126.140.97] [thread_preload.c:216] [threadpreload_run] forking new thread with environment 'SHADOW_SPAWNED=TRUE SHADOW_LOG_LEVEL=3 SHADOW_LOG_START_TIME=185582224183 RUST_LOG=INFO LD_PRELOAD=/home/user/.local/lib/libshadow_injector.so:/home/user/.local/lib/libshadow_libc.so:/home/user/.local/lib/libshadow_openssl_rng.so SHADOW_SHM_HOST_BLK=520,1048576,112,/shadow_shmemfile_185582.229711730-127399 SHADOW_SHM_PROCESS_BLK=40968,1048576,6040,/shadow_shmemfile_185582.229711730-127399 SHADOW_LOG_FILE=/home/user/sim/tool/myThemisExperiments/4rep/hosts/themisReplica3/themisReplica3.themis-bench-app.1000.shimlog SHADOW_SHM_THREAD_BLK=4104,1048576,4024,/shadow_shmemfile_185582.229711730-127399 SHADOW_IPC_BLK=1032,1048576,648,/shadow_shmemfile_185582.229711730-127399 SHADOW_USE_SECCOMP= SHADOW_PID=127399 SHADOW_TSC_HZ=4008000000', arguments '/home/user/sim/tool/themis/target/release/themis-bench-app 3 --config config/default', and working directory '/home/user/sim/tool/themis'
00:00:00.007254 [127404:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica3:11.126.140.97] [process.c:598] [_process_start] process 'themisReplica3.themis-bench-app.1000' started
00:00:00.044808 [127406:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica0:11.92.212.145] [process.c:563] [_process_start] starting process 'themisReplica0.themis-bench-app.1000'
00:00:00.044850 [127406:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica0:11.92.212.145] [thread_preload.c:216] [threadpreload_run] forking new thread with environment 'SHADOW_SPAWNED=TRUE SHADOW_LOG_START_TIME=185582224183 RUST_LOG=INFO SHADOW_LOG_LEVEL=3 LD_PRELOAD=/home/user/.local/lib/libshadow_injector.so:/home/user/.local/lib/libshadow_libc.so:/home/user/.local/lib/libshadow_openssl_rng.so SHADOW_SHM_HOST_BLK=136,1048576,112,/shadow_shmemfile_185582.229711730-127399 SHADOW_SHM_PROCESS_BLK=16392,1048576,6040,/shadow_shmemfile_185582.229711730-127399 SHADOW_LOG_FILE=/home/user/sim/tool/myThemisExperiments/4rep/hosts/themisReplica0/themisReplica0.themis-bench-app.1000.shimlog SHADOW_SHM_THREAD_BLK=49160,1048576,4024,/shadow_shmemfile_185582.229711730-127399 SHADOW_IPC_BLK=2056,1048576,648,/shadow_shmemfile_185582.229711730-127399 SHADOW_USE_SECCOMP= SHADOW_PID=127399 SHADOW_TSC_HZ=4008000000', arguments '/home/user/sim/tool/themis/target/release/themis-bench-app 0 --config config/default', and working directory '/home/user/sim/tool/themis'
00:00:00.044957 [127406:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica0:11.92.212.145] [process.c:598] [_process_start] process 'themisReplica0.themis-bench-app.1000' started
00:00:00.053324 [127407:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica2:11.138.123.72] [process.c:563] [_process_start] starting process 'themisReplica2.themis-bench-app.1000'
00:00:00.053359 [127407:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica2:11.138.123.72] [thread_preload.c:216] [threadpreload_run] forking new thread with environment 'SHADOW_LOG_START_TIME=185582224183 SHADOW_SPAWNED=TRUE RUST_LOG=INFO LD_PRELOAD=/home/user/.local/lib/libshadow_injector.so:/home/user/.local/lib/libshadow_libc.so:/home/user/.local/lib/libshadow_openssl_rng.so SHADOW_LOG_LEVEL=3 SHADOW_SHM_HOST_BLK=392,1048576,112,/shadow_shmemfile_185582.229711730-127399 SHADOW_SHM_PROCESS_BLK=32776,1048576,6040,/shadow_shmemfile_185582.229711730-127399 SHADOW_LOG_FILE=/home/user/sim/tool/myThemisExperiments/4rep/hosts/themisReplica2/themisReplica2.themis-bench-app.1000.shimlog SHADOW_SHM_THREAD_BLK=53256,1048576,4024,/shadow_shmemfile_185582.229711730-127399 SHADOW_IPC_BLK=3080,1048576,648,/shadow_shmemfile_185582.229711730-127399 SHADOW_USE_SECCOMP= SHADOW_PID=127399 SHADOW_TSC_HZ=4008000000', arguments '/home/user/sim/tool/themis/target/release/themis-bench-app 2 --config config/default', and working directory '/home/user/sim/tool/themis'
00:00:00.053465 [127407:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica2:11.138.123.72] [process.c:598] [_process_start] process 'themisReplica2.themis-bench-app.1000' started
00:00:00.062043 [127408:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica1:11.92.217.160] [process.c:563] [_process_start] starting process 'themisReplica1.themis-bench-app.1000'
00:00:00.062081 [127408:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica1:11.92.217.160] [thread_preload.c:216] [threadpreload_run] forking new thread with environment 'LD_PRELOAD=/home/user/.local/lib/libshadow_injector.so:/home/user/.local/lib/libshadow_libc.so:/home/user/.local/lib/libshadow_openssl_rng.so SHADOW_SPAWNED=TRUE RUST_LOG=INFO SHADOW_LOG_LEVEL=3 SHADOW_LOG_START_TIME=185582224183 SHADOW_SHM_HOST_BLK=264,1048576,112,/shadow_shmemfile_185582.229711730-127399 SHADOW_SHM_PROCESS_BLK=24584,1048576,6040,/shadow_shmemfile_185582.229711730-127399 SHADOW_LOG_FILE=/home/user/sim/tool/myThemisExperiments/4rep/hosts/themisReplica1/themisReplica1.themis-bench-app.1000.shimlog SHADOW_SHM_THREAD_BLK=57352,1048576,4024,/shadow_shmemfile_185582.229711730-127399 SHADOW_IPC_BLK=61448,1048576,648,/shadow_shmemfile_185582.229711730-127399 SHADOW_USE_SECCOMP= SHADOW_PID=127399 SHADOW_TSC_HZ=4008000000', arguments '/home/user/sim/tool/themis/target/release/themis-bench-app 1 --config config/default', and working directory '/home/user/sim/tool/themis'
00:00:00.062180 [127408:shadow-worker] 00:00:00.000000000 [INFO] [themisReplica1:11.92.217.160] [process.c:598] [_process_start] process 'themisReplica1.themis-bench-app.1000' started
00:00:00.075809 [127399:shadow] n/a [INFO] [n/a] [manager.rs:571] [shadow_rs::core::manager] Process resource usage at simtime 1010000000 reported by getrusage(): ru_maxrss=0.152 GiB, ru_utime=0.000 minutes, ru_stime=0.000 minutes, ru_nvcsw=717, ru_nivcsw=147, _manager_heartbeat
00:00:00.075958 [127405:shadow-worker] 00:00:02.000000000 [INFO] [themisClient0:11.16.248.176] [process.c:563] [_process_start] starting process 'themisClient0.bench-client.1000'
00:00:00.075991 [127405:shadow-worker] 00:00:02.000000000 [INFO] [themisClient0:11.16.248.176] [thread_preload.c:216] [threadpreload_run] forking new thread with environment 'SHADOW_LOG_LEVEL=3 LD_PRELOAD=/home/user/.local/lib/libshadow_injector.so:/home/user/.local/lib/libshadow_libc.so:/home/user/.local/lib/libshadow_openssl_rng.so SHADOW_SPAWNED=TRUE SHADOW_LOG_START_TIME=185582224183 RUST_LOG=INFO SHADOW_SHM_HOST_BLK=8,1048576,112,/shadow_shmemfile_185582.229711730-127399 SHADOW_SHM_PROCESS_BLK=8200,1048576,6040,/shadow_shmemfile_185582.229711730-127399 SHADOW_LOG_FILE=/home/user/sim/tool/myThemisExperiments/4rep/hosts/themisClient0/themisClient0.bench-client.1000.shimlog SHADOW_SHM_THREAD_BLK=65544,1048576,4024,/shadow_shmemfile_185582.229711730-127399 SHADOW_IPC_BLK=62472,1048576,648,/shadow_shmemfile_185582.229711730-127399 SHADOW_USE_SECCOMP= SHADOW_PID=127399 SHADOW_TSC_HZ=4008000000', arguments '/home/user/sim/tool/themis/target/release/bench-client -d 8 --config config/default --payload 1024 -c 4 --concurrent 175', and working directory '/home/user/sim/tool/themis'
00:00:00.076371 [127405:shadow-worker] 00:00:02.000000000 [INFO] [themisClient0:11.16.248.176] [process.c:598] [_process_start] process 'themisClient0.bench-client.1000' started
00:00:00.095826 [127405:shadow-worker] 00:00:02.000000000 [WARN] [themisClient0:11.16.248.176] [syscall_handler.c:527] [syscallhandler_make_syscall] Detected unsupported syscall 435 called from thread 1000 in process themisClient0.bench-client.1000 on host themisClient0
00:00:00.095828 [127405:shadow-worker] 00:00:02.000000000 [ERROR] [themisClient0:11.16.248.176] [syscall_handler.c:531] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 435, which may result in unusual behavior

2024-02-21T12:09:12.442Z [info] : childprocess: 00:00:00.104510 [127405:shadow-worker] 00:00:02.000000000 [WARN] [themisClient0:11.16.248.176] [syscall_handler.c:527] [syscallhandler_make_syscall] Detected unsupported syscall 435 called from thread 1000 in process themisClient0.bench-client.1000 on host themisClient0
00:00:00.104512 [127405:shadow-worker] 00:00:02.000000000 [ERROR] [themisClient0:11.16.248.176] [syscall_handler.c:531] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 435, which may result in unusual behavior

2024-02-21T12:09:12.450Z [info] : childprocess: 00:00:00.112868 [127405:shadow-worker] 00:00:02.000000000 [WARN] [themisClient0:11.16.248.176] [syscall_handler.c:527] [syscallhandler_make_syscall] Detected unsupported syscall 435 called from thread 1000 in process themisClient0.bench-client.1000 on host themisClient0
00:00:00.112869 [127405:shadow-worker] 00:00:02.000000000 [ERROR] [themisClient0:11.16.248.176] [syscall_handler.c:531] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 435, which may result in unusual behavior

2024-02-21T12:09:12.459Z [info] : childprocess: 00:00:00.121189 [127405:shadow-worker] 00:00:02.000000000 [WARN] [themisClient0:11.16.248.176] [syscall_handler.c:527] [syscallhandler_make_syscall] Detected unsupported syscall 435 called from thread 1000 in process themisClient0.bench-client.1000 on host themisClient0
00:00:00.121190 [127405:shadow-worker] 00:00:02.000000000 [ERROR] [themisClient0:11.16.248.176] [syscall_handler.c:531] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 435, which may result in unusual behavior

2024-02-21T12:09:12.468Z [info] : childprocess: 00:00:00.130647 [127405:shadow-worker] 00:00:02.000000000 [WARN] [themisClient0:11.16.248.176] [syscall_handler.c:527] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1001 in process themisClient0.bench-client.1000 on host themisClient0
00:00:00.130648 [127405:shadow-worker] 00:00:02.000000000 [ERROR] [themisClient0:11.16.248.176] [syscall_handler.c:531] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior

2024-02-21T12:09:12.470Z [info] : childprocess: 00:00:00.132800 [127405:shadow-worker] 00:00:02.000000000 [WARN] [themisClient0:11.16.248.176] [syscall_handler.c:527] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1002 in process themisClient0.bench-client.1000 on host themisClient0
00:00:00.132802 [127405:shadow-worker] 00:00:02.000000000 [ERROR] [themisClient0:11.16.248.176] [syscall_handler.c:531] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior

2024-02-21T12:09:12.471Z [info] : childprocess: 00:00:00.133428 [127405:shadow-worker] 00:00:02.000000000 [WARN] [themisClient0:11.16.248.176] [syscall_handler.c:527] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1003 in process themisClient0.bench-client.1000 on host themisClient0
00:00:00.133430 [127405:shadow-worker] 00:00:02.000000000 [ERROR] [themisClient0:11.16.248.176] [syscall_handler.c:531] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior

2024-02-21T12:09:12.471Z [info] : childprocess: 00:00:00.134106 [127405:shadow-worker] 00:00:02.000000000 [WARN] [themisClient0:11.16.248.176] [syscall_handler.c:527] [syscallhandler_make_syscall] Detected unsupported syscall 204 called from thread 1004 in process themisClient0.bench-client.1000 on host themisClient0
00:00:00.134108 [127405:shadow-worker] 00:00:02.000000000 [ERROR] [themisClient0:11.16.248.176] [syscall_handler.c:531] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 204, which may result in unusual behavior

2024-02-21T12:09:14.179Z [info] : current total mem usage of host: 1.489166336 
2024-02-21T12:09:14.199Z [info] : current cpu usage of shadow process: 0 
2024-02-21T12:09:14.199Z [info] : current mem usage of shadow process: 0.175128576 
2024-02-21T12:09:14.199Z [info] : current cpu usage of themis-bench-app process: 0 
2024-02-21T12:09:14.199Z [info] : current mem usage of themis-bench-app process: 0.082325504 
2024-02-21T12:09:16.179Z [info] : current total mem usage of host: 1.542959104 
2024-02-21T12:09:16.180Z [info] : current cpu usage of shadow process: 48.484848484848484 
2024-02-21T12:09:16.180Z [info] : current mem usage of shadow process: 0.181968896 
2024-02-21T12:09:16.184Z [info] : current cpu usage of themis-bench-app process: 23.115577889447238 
2024-02-21T12:09:16.184Z [info] : current mem usage of themis-bench-app process: 0.125149184 
2024-02-21T12:09:18.181Z [info] : current total mem usage of host: 1.597149184 
2024-02-21T12:09:18.182Z [info] : current cpu usage of shadow process: 49 
2024-02-21T12:09:18.182Z [info] : current mem usage of shadow process: 0.188973056 
2024-02-21T12:09:18.186Z [info] : current cpu usage of themis-bench-app process: 22.5 
2024-02-21T12:09:18.186Z [info] : current mem usage of themis-bench-app process: 0.17008230400000002 
2024-02-21T12:09:20.182Z [info] : current total mem usage of host: 1.617027072 
2024-02-21T12:09:20.183Z [info] : current cpu usage of shadow process: 49.5 
2024-02-21T12:09:20.183Z [info] : current mem usage of shadow process: 0.190816256 
2024-02-21T12:09:20.186Z [info] : current cpu usage of themis-bench-app process: 21.5 
2024-02-21T12:09:20.186Z [info] : current mem usage of themis-bench-app process: 0.20552908800000003 
2024-02-21T12:09:22.182Z [info] : current total mem usage of host: 1.670877184 
2024-02-21T12:09:22.184Z [info] : current cpu usage of shadow process: 48.756218905472636 
2024-02-21T12:09:22.184Z [info] : current mem usage of shadow process: 0.191053824 
2024-02-21T12:09:22.187Z [info] : current cpu usage of themis-bench-app process: 24 
2024-02-21T12:09:22.187Z [info] : current mem usage of themis-bench-app process: 0.263729152 
2024-02-21T12:09:22.472Z [info] : childprocess: 00:00:00.170486 [127399:shadow] n/a [INFO] [n/a] [manager.rs:571] [shadow_rs::core::manager] Process resource usage at simtime 2010700001 reported by getrusage(): ru_maxrss=0.153 GiB, ru_utime=0.000 minutes, ru_stime=0.000 minutes, ru_nvcsw=1610, ru_nivcsw=2311, _manager_heartbeat
00:00:05.340982 [127399:shadow] n/a [INFO] [n/a] [manager.rs:571] [shadow_rs::core::manager] Process resource usage at simtime 3012100001 reported by getrusage(): ru_maxrss=0.174 GiB, ru_utime=0.017 minutes, ru_stime=0.000 minutes, ru_nvcsw=8152, ru_nivcsw=217425, _manager_heartbeat

2024-02-21T12:09:24.184Z [info] : current total mem usage of host: 1.70467328 
2024-02-21T12:09:24.186Z [info] : current cpu usage of shadow process: 50 
2024-02-21T12:09:24.186Z [info] : current mem usage of shadow process: 0.191053824 
2024-02-21T12:09:24.189Z [info] : current cpu usage of themis-bench-app process: 21 
2024-02-21T12:09:24.189Z [info] : current mem usage of themis-bench-app process: 0.297549824 
2024-02-21T12:09:26.185Z [info] : current total mem usage of host: 1.740029952 
2024-02-21T12:09:26.187Z [info] : current cpu usage of shadow process: 49.5 
2024-02-21T12:09:26.187Z [info] : current mem usage of shadow process: 0.191229952 
2024-02-21T12:09:26.190Z [info] : current cpu usage of themis-bench-app process: 23 
2024-02-21T12:09:26.190Z [info] : current mem usage of themis-bench-app process: 0.332750848 
2024-02-21T12:09:28.187Z [info] : current total mem usage of host: 1.77272832 
2024-02-21T12:09:28.189Z [info] : current cpu usage of shadow process: 50 
2024-02-21T12:09:28.189Z [info] : current mem usage of shadow process: 0.191229952 
2024-02-21T12:09:28.192Z [info] : current cpu usage of themis-bench-app process: 22 
2024-02-21T12:09:28.192Z [info] : current mem usage of themis-bench-app process: 0.36684185599999997 
2024-02-21T12:09:30.192Z [info] : current total mem usage of host: 1.80242432 
2024-02-21T12:09:30.193Z [info] : current cpu usage of shadow process: 50.5 
2024-02-21T12:09:30.193Z [info] : current mem usage of shadow process: 0.191229952 
2024-02-21T12:09:30.197Z [info] : current cpu usage of themis-bench-app process: 22.38805970149254 
2024-02-21T12:09:30.197Z [info] : current mem usage of themis-bench-app process: 0.400662528 
2024-02-21T12:09:32.195Z [info] : current cpu usage of shadow process: 47.2636815920398 
2024-02-21T12:09:32.195Z [info] : current mem usage of shadow process: 0.191229952 
2024-02-21T12:09:32.196Z [info] : current total mem usage of host: 1.896493056 
2024-02-21T12:09:32.200Z [info] : current cpu usage of themis-bench-app process: 24.5 
2024-02-21T12:09:32.200Z [info] : current mem usage of themis-bench-app process: 0.481591296 
2024-02-21T12:09:32.472Z [info] : childprocess: 00:00:11.526454 [127399:shadow] n/a [INFO] [n/a] [manager.rs:571] [shadow_rs::core::manager] Process resource usage at simtime 4019000000 reported by getrusage(): ru_maxrss=0.178 GiB, ru_utime=0.050 minutes, ru_stime=0.017 minutes, ru_nvcsw=15295, ru_nivcsw=470556, _manager_heartbeat
00:00:17.820699 [127399:shadow] n/a [INFO] [n/a] [manager.rs:571] [shadow_rs::core::manager] Process resource usage at simtime 5019700000 reported by getrusage(): ru_maxrss=0.178 GiB, ru_utime=0.083 minutes, ru_stime=0.033 minutes, ru_nvcsw=22485, ru_nivcsw=727581, _manager_heartbeat

2024-02-21T12:09:34.195Z [info] : current total mem usage of host: 1.92927744 
2024-02-21T12:09:34.196Z [info] : current cpu usage of shadow process: 49.5 
2024-02-21T12:09:34.196Z [info] : current mem usage of shadow process: 0.189902848 
2024-02-21T12:09:34.200Z [info] : current cpu usage of themis-bench-app process: 22.5 
2024-02-21T12:09:34.200Z [info] : current mem usage of themis-bench-app process: 0.515145728 
2024-02-21T12:09:36.197Z [info] : current total mem usage of host: 1.969238016 
2024-02-21T12:09:36.198Z [info] : current cpu usage of shadow process: 49 
2024-02-21T12:09:36.198Z [info] : current mem usage of shadow process: 0.188096512 
2024-02-21T12:09:36.202Z [info] : current cpu usage of themis-bench-app process: 22 
2024-02-21T12:09:36.202Z [info] : current mem usage of themis-bench-app process: 0.548691968 
2024-02-21T12:09:36.353Z [info] : childprocess: 00:00:23.987281 [127404:shadow-worker] 00:00:06.000000000 [INFO] [n/a] [worker.c:478] [worker_finish] starting to shut down 1 hosts
00:00:23.987284 [127404:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica3:11.126.140.97] [process.c:717] [process_stop] terminating process 'themisReplica3.themis-bench-app.1000'
00:00:23.987292 [127404:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica3:11.126.140.97] [syscall_handler.c:102] [_syscallhandler_free] handled 14747 syscalls
00:00:23.987315 [127404:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica3:11.126.140.97] [syscall_handler.c:108] [_syscallhandler_free] Thread 1000 (themis-bench-app) syscall counts: {writev:11009, recvfrom:2443, epoll_wait:724, brk:295, write:98, read:32, mmap:14, statx:14, close:13, lseek:11, open:11, epoll_ctl:10, munmap:10, setsockopt:9, getpeername:7, getrandom:6, accept4:5, rt_sigaction:5, socket:5, connect:3, getsockopt:3, bind:2, getdents64:2, listen:2, newfstatat:2, openat:2, sigaltstack:2, epoll_create1:1, eventfd2:1, fcntl:1, ioctl:1, mprotect:1, mremap:1, poll:1, prlimit64:1, shadow_init_memory_manager:1}
00:00:23.987351 [127404:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica3:11.126.140.97] [process.c:467] [_process_check] process 'themisReplica3.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:23.993436 [127404:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica3:11.126.140.97] [process.c:422] [_process_getAndLogReturnCode] process 'themisReplica3.themis-bench-app.1000' killed by Shadow
00:00:23.993649 [127404:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica3:11.126.140.97] [process.c:740] [process_stop] process 'themisReplica3.themis-bench-app.1000' stopped
00:00:23.993650 [127404:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica3:11.126.140.97] [process.c:467] [_process_check] process 'themisReplica3.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:23.993656 [127404:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica3:11.126.140.97] [process.c:467] [_process_check] process 'themisReplica3.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:23.993709 [127404:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica3:11.126.140.97] [host.c:320] [host_shutdown] host 'themisReplica3' has been shut down
00:00:23.993711 [127404:shadow-worker] 00:00:06.000000000 [INFO] [n/a] [worker.c:481] [worker_finish] 1 hosts are shut down
00:00:23.993738 [127405:shadow-worker] 00:00:06.000000000 [INFO] [n/a] [worker.c:478] [worker_finish] starting to shut down 1 hosts
00:00:23.993739 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [process.c:717] [process_stop] terminating process 'themisClient0.bench-client.1000'
00:00:23.994527 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [syscall_handler.c:102] [_syscallhandler_free] handled 244347 syscalls
00:00:23.994535 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [syscall_handler.c:108] [_syscallhandler_free] Thread 1001 (bench-client) syscall counts: {recvfrom:139352, epoll_wait:69478, write:17547, writev:17396, mprotect:529, getrandom:6, epoll_ctl:5, connect:4, getpeername:4, getsockopt:4, setsockopt:4, socket:4, futex:2, mmap:2, munmap:2, sigaltstack:2, epoll_create1:1, eventfd2:1, fcntl:1, rseq:1, rt_sigprocmask:1, set_robust_list:1, shadow_get_shm_blk:1}
00:00:23.994586 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [syscall_handler.c:102] [_syscallhandler_free] handled 219684 syscalls
00:00:23.994592 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [syscall_handler.c:108] [_syscallhandler_free] Thread 1003 (bench-client) syscall counts: {recvfrom:125280, epoll_wait:62438, write:15787, writev:15636, mprotect:501, epoll_ctl:5, getrandom:5, connect:4, getpeername:4, getsockopt:4, setsockopt:4, socket:4, futex:2, mmap:2, sigaltstack:2, epoll_create1:1, eventfd2:1, fcntl:1, rseq:1, rt_sigprocmask:1, set_robust_list:1, shadow_get_shm_blk:1}
00:00:23.994595 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [syscall_handler.c:102] [_syscallhandler_free] handled 104 syscalls
00:00:23.994600 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [syscall_handler.c:108] [_syscallhandler_free] Thread 1000 (bench-client) syscall counts: {write:23, read:14, rt_sigprocmask:9, mmap:7, rt_sigaction:6, mprotect:5, statx:5, brk:4, clone:4, close:4, nanosleep:4, futex:2, getdents64:2, lseek:2, newfstatat:2, open:2, openat:2, sigaltstack:2, getrandom:1, mremap:1, munmap:1, poll:1, prlimit64:1, shadow_init_memory_manager:1}
00:00:23.994609 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [syscall_handler.c:102] [_syscallhandler_free] handled 220529 syscalls
00:00:23.994613 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [syscall_handler.c:108] [_syscallhandler_free] Thread 1002 (bench-client) syscall counts: {recvfrom:125760, epoll_wait:62682, write:15848, writev:15697, mprotect:499, epoll_ctl:5, getrandom:5, connect:4, getpeername:4, getsockopt:4, setsockopt:4, socket:4, futex:2, mmap:2, sigaltstack:2, epoll_create1:1, eventfd2:1, fcntl:1, munmap:1, rseq:1, rt_sigprocmask:1, set_robust_list:1, shadow_get_shm_blk:1}
00:00:23.994617 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [syscall_handler.c:102] [_syscallhandler_free] handled 220562 syscalls
00:00:23.994621 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [syscall_handler.c:108] [_syscallhandler_free] Thread 1004 (bench-client) syscall counts: {recvfrom:125784, epoll_wait:62690, write:15850, writev:15699, mprotect:497, epoll_ctl:5, getrandom:5, connect:4, getpeername:4, getsockopt:4, setsockopt:4, socket:4, mmap:2, sigaltstack:2, epoll_create1:1, eventfd2:1, fcntl:1, futex:1, munmap:1, rseq:1, rt_sigprocmask:1, set_robust_list:1, shadow_get_shm_blk:1}
00:00:23.994624 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [process.c:467] [_process_check] process 'themisClient0.bench-client.1000' has completed or is otherwise no longer running
00:00:23.994726 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [process.c:422] [_process_getAndLogReturnCode] process 'themisClient0.bench-client.1000' killed by Shadow
00:00:23.994788 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [process.c:740] [process_stop] process 'themisClient0.bench-client.1000' stopped
00:00:23.994789 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [process.c:467] [_process_check] process 'themisClient0.bench-client.1000' has completed or is otherwise no longer running
00:00:23.994790 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [process.c:467] [_process_check] process 'themisClient0.bench-client.1000' has completed or is otherwise no longer running
00:00:23.994952 [127405:shadow-worker] 00:00:06.000000000 [INFO] [themisClient0:11.16.248.176] [host.c:320] [host_shutdown] host 'themisClient0' has been shut down
00:00:23.994953 [127405:shadow-worker] 00:00:06.000000000 [INFO] [n/a] [worker.c:481] [worker_finish] 1 hosts are shut down
00:00:23.994968 [127406:shadow-worker] 00:00:06.000000000 [INFO] [n/a] [worker.c:478] [worker_finish] starting to shut down 1 hosts
00:00:23.994970 [127406:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica0:11.92.212.145] [process.c:717] [process_stop] terminating process 'themisReplica0.themis-bench-app.1000'
00:00:23.994988 [127406:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica0:11.92.212.145] [syscall_handler.c:102] [_syscallhandler_free] handled 38962 syscalls
00:00:23.994996 [127406:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica0:11.92.212.145] [syscall_handler.c:108] [_syscallhandler_free] Thread 1000 (themis-bench-app) syscall counts: {recvfrom:21996, writev:14855, epoll_wait:1546, brk:266, write:100, read:32, mmap:23, munmap:14, statx:14, close:13, mremap:12, accept4:11, lseek:11, open:11, epoll_ctl:10, setsockopt:9, getpeername:7, getrandom:6, rt_sigaction:5, bind:2, getdents64:2, listen:2, newfstatat:2, openat:2, sigaltstack:2, socket:2, epoll_create1:1, eventfd2:1, fcntl:1, ioctl:1, mprotect:1, poll:1, prlimit64:1, shadow_init_memory_manager:1}
00:00:23.995055 [127406:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica0:11.92.212.145] [process.c:467] [_process_check] process 'themisReplica0.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:24.001579 [127406:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica0:11.92.212.145] [process.c:422] [_process_getAndLogReturnCode] process 'themisReplica0.themis-bench-app.1000' killed by Shadow
00:00:24.001645 [127406:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica0:11.92.212.145] [process.c:740] [process_stop] process 'themisReplica0.themis-bench-app.1000' stopped
00:00:24.001646 [127406:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica0:11.92.212.145] [process.c:467] [_process_check] process 'themisReplica0.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:24.001656 [127406:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica0:11.92.212.145] [process.c:467] [_process_check] process 'themisReplica0.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:24.001683 [127406:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica0:11.92.212.145] [host.c:320] [host_shutdown] host 'themisReplica0' has been shut down
00:00:24.001686 [127406:shadow-worker] 00:00:06.000000000 [INFO] [n/a] [worker.c:481] [worker_finish] 1 hosts are shut down
00:00:24.001705 [127407:shadow-worker] 00:00:06.000000000 [INFO] [n/a] [worker.c:478] [worker_finish] starting to shut down 1 hosts
00:00:24.001708 [127407:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica2:11.138.123.72] [process.c:717] [process_stop] terminating process 'themisReplica2.themis-bench-app.1000'
00:00:24.001716 [127407:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica2:11.138.123.72] [syscall_handler.c:102] [_syscallhandler_free] handled 15376 syscalls
00:00:24.001734 [127407:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica2:11.138.123.72] [syscall_handler.c:108] [_syscallhandler_free] Thread 1000 (themis-bench-app) syscall counts: {writev:10937, recvfrom:2734, epoll_wait:1135, brk:295, write:98, read:32, mmap:14, statx:14, close:13, lseek:11, open:11, epoll_ctl:10, munmap:10, setsockopt:9, accept4:7, getpeername:7, getrandom:6, rt_sigaction:5, socket:4, bind:2, connect:2, getdents64:2, getsockopt:2, listen:2, newfstatat:2, openat:2, sigaltstack:2, epoll_create1:1, eventfd2:1, fcntl:1, ioctl:1, mprotect:1, mremap:1, poll:1, prlimit64:1, shadow_init_memory_manager:1}
00:00:24.001797 [127407:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica2:11.138.123.72] [process.c:467] [_process_check] process 'themisReplica2.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:24.007879 [127407:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica2:11.138.123.72] [process.c:422] [_process_getAndLogReturnCode] process 'themisReplica2.themis-bench-app.1000' killed by Shadow
00:00:24.008071 [127407:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica2:11.138.123.72] [process.c:740] [process_stop] process 'themisReplica2.themis-bench-app.1000' stopped
00:00:24.008072 [127407:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica2:11.138.123.72] [process.c:467] [_process_check] process 'themisReplica2.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:24.008083 [127407:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica2:11.138.123.72] [process.c:467] [_process_check] process 'themisReplica2.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:24.008131 [127407:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica2:11.138.123.72] [host.c:320] [host_shutdown] host 'themisReplica2' has been shut down
00:00:24.008132 [127407:shadow-worker] 00:00:06.000000000 [INFO] [n/a] [worker.c:481] [worker_finish] 1 hosts are shut down
00:00:24.008148 [127408:shadow-worker] 00:00:06.000000000 [INFO] [n/a] [worker.c:478] [worker_finish] starting to shut down 1 hosts
00:00:24.008149 [127408:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica1:11.92.217.160] [process.c:717] [process_stop] terminating process 'themisReplica1.themis-bench-app.1000'
00:00:24.008156 [127408:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica1:11.92.217.160] [syscall_handler.c:102] [_syscallhandler_free] handled 15240 syscalls
00:00:24.008166 [127408:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica1:11.92.217.160] [syscall_handler.c:108] [_syscallhandler_free] Thread 1000 (themis-bench-app) syscall counts: {writev:11009, recvfrom:2443, epoll_wait:1219, brk:295, write:98, read:32, mmap:14, statx:14, close:13, lseek:11, open:11, epoll_ctl:10, munmap:10, accept4:9, setsockopt:9, getpeername:7, getrandom:6, rt_sigaction:5, socket:3, bind:2, getdents64:2, listen:2, newfstatat:2, openat:2, sigaltstack:2, connect:1, epoll_create1:1, eventfd2:1, fcntl:1, getsockopt:1, ioctl:1, mprotect:1, mremap:1, poll:1, prlimit64:1, shadow_init_memory_manager:1}
00:00:24.008229 [127408:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica1:11.92.217.160] [process.c:467] [_process_check] process 'themisReplica1.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:24.014379 [127408:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica1:11.92.217.160] [process.c:422] [_process_getAndLogReturnCode] process 'themisReplica1.themis-bench-app.1000' killed by Shadow
00:00:24.014564 [127408:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica1:11.92.217.160] [process.c:740] [process_stop] process 'themisReplica1.themis-bench-app.1000' stopped
00:00:24.014565 [127408:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica1:11.92.217.160] [process.c:467] [_process_check] process 'themisReplica1.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:24.014575 [127408:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica1:11.92.217.160] [process.c:467] [_process_check] process 'themisReplica1.themis-bench-app.1000' has completed or is otherwise no longer running
00:00:24.014616 [127408:shadow-worker] 00:00:06.000000000 [INFO] [themisReplica1:11.92.217.160] [host.c:320] [host_shutdown] host 'themisReplica1' has been shut down
00:00:24.014618 [127408:shadow-worker] 00:00:06.000000000 [INFO] [n/a] [worker.c:481] [worker_finish] 1 hosts are shut down
00:00:24.014661 [127399:shadow] n/a [INFO] [n/a] [scheduler.c:181] [scheduler_shutdown] scheduler is shutting down now
00:00:24.014663 [127399:shadow] n/a [INFO] [n/a] [scheduler.c:188] [scheduler_shutdown] waiting for 5 worker threads to finish
00:00:24.015237 [127399:shadow] n/a [INFO] [n/a] [scheduler.c:201] [_scheduler_free] 5 worker threads finished
00:00:24.015304 [127399:shadow] n/a [INFO] [n/a] [manager.rs:285] [shadow_rs::core::manager] Global syscall counts: {recvfrom:545792, epoll_wait:261912, writev:112238, write:65449, mprotect:2035, brk:1155, read:142, mmap:80, statx:61, epoll_ctl:60, close:56, setsockopt:52, munmap:49, getrandom:46, lseek:46, open:46, getpeername:44, accept4:32, socket:30, rt_sigaction:26, connect:22, getsockopt:22, sigaltstack:18, mremap:16, rt_sigprocmask:13, getdents64:10, newfstatat:10, openat:10, futex:9, bind:8, epoll_create1:8, eventfd2:8, fcntl:8, listen:8, poll:5, prlimit64:5, shadow_init_memory_manager:5, clone:4, ioctl:4, nanosleep:4, rseq:4, set_robust_list:4, shadow_get_shm_blk:4}
00:00:24.015308 [127399:shadow] n/a [INFO] [n/a] [manager.rs:292] [shadow_rs::core::manager] Global allocated object counts: {TaskRef:2602670, Event:1042865, Packet:1017442, Payload:502830, StatusListener:261958, SysCallCondition:261902, Timer:258464, LegacyDescriptor:140, RegularFile:71, TCP:52, Epoll:17, NetworkInterface:10, SysCallHandler:9, ThreadPreload:9, FutexTable:5, Host:5, Process:5, Router:5, Futex:1}
00:00:24.015310 [127399:shadow] n/a [INFO] [n/a] [manager.rs:293] [shadow_rs::core::manager] Global deallocated object counts: {TaskRef:2602670, Event:1042865, Packet:1017442, Payload:502830, StatusListener:261958, SysCallCondition:261902, Timer:258464, LegacyDescriptor:140, RegularFile:71, TCP:52, Epoll:17, NetworkInterface:10, SysCallHandler:9, ThreadPreload:9, FutexTable:5, Host:5, Process:5, Router:5, Futex:1}
00:00:24.015311 [127399:shadow] n/a [INFO] [n/a] [manager.rs:296] [shadow_rs::core::manager] We allocated and deallocated the same number of objects :)
00:00:24.015312 [127399:shadow] n/a [INFO] [n/a] [controller.rs:103] [shadow_rs::core::controller] Finished simulation
00:00:24.015314 [127399:shadow] n/a [INFO] [n/a] [main.rs:178] [shadow_rs::core::main] Log message buffering is disabled during cleanup

2024-02-21T12:09:36.353Z [error] : childprocess: ** Shadow completed successfully

2024-02-21T12:09:36.362Z [info] : child proess terminated with code: 0 
2024-02-21T12:09:36.362Z [info] : clearing intervals ... 
2024-02-21T12:09:36.363Z [info] : intervals cleared! 
2024-02-21T12:09:36.367Z [info] : generating plots... 
2024-02-21T12:09:36.368Z [info] : plots generated!

I received these errors, but I don't know if they will cause any problems:

2024-02-21T12:09:12.020Z [error] : childprocess:     Finished dev [unoptimized + debuginfo] target(s) in 0.31s

00:00:00.076371 [127405:shadow-worker] 00:00:02.000000000 [INFO] [themisClient0:11.16.248.176] [process.c:598] [_process_start] process 'themisClient0.bench-client.1000' started
00:00:00.095826 [127405:shadow-worker] 00:00:02.000000000 [WARN] [themisClient0:11.16.248.176] [syscall_handler.c:527] [syscallhandler_make_syscall] Detected unsupported syscall 435 called from thread 1000 in process themisClient0.bench-client.1000 on host themisClient0
00:00:00.095828 [127405:shadow-worker] 00:00:02.000000000 [ERROR] [themisClient0:11.16.248.176] [syscall_handler.c:531] [syscallhandler_make_syscall] Returning error 38 (ENOSYS) for unsupported syscall 435, which may result in unusual behavior

themisclient0.stdout file:

RUST_LOG=INFO
Opts {
    clients: 4,
    config: [
        "config/default",
    ],
    payload: 1024,
    concurrent_requests: 175,
    requests: None,
    duration: Some(
        8,
    ),
    quiet: false,
    no_wait_for_primary: false,
}
 [2m2000-01-01T00:00:02.000000Z [0m  [32m INFO [0m  [2mbench_client [0m [2m: [0m waiting for 4 connected clients
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 0 from 11.92.212.145:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 0 from 11.92.212.145:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 0 from 11.92.212.145:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 0 from 11.92.212.145:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mbench_client [0m [2m: [0m go
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 1 from 11.92.217.160:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 1 from 11.92.217.160:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 1 from 11.92.217.160:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 1 from 11.92.217.160:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 2 from 11.138.123.72:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 2 from 11.138.123.72:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 2 from 11.138.123.72:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 2 from 11.138.123.72:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 3 from 11.126.140.97:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 3 from 11.126.140.97:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 3 from 11.126.140.97:1000
 [2m2000-01-01T00:00:02.002800Z [0m  [32m INFO [0m  [2mthemis_core::net::tcp::group [0m [2m: [0m Connected 3 from 11.126.140.97:1000
 [2m2000-01-01T00:00:03.002800Z [0m  [32m INFO [0m  [2mbench_client [0m [2m: [0m RPS: 16200
 [2m2000-01-01T00:00:03.002800Z [0m  [32m INFO [0m  [2mbench_client [0m [2m: [0m LAG: 42
 [2m2000-01-01T00:00:04.002800Z [0m  [32m INFO [0m  [2mbench_client [0m [2m: [0m RPS: 17650
 [2m2000-01-01T00:00:04.002800Z [0m  [32m INFO [0m  [2mbench_client [0m [2m: [0m LAG: 38
 [2m2000-01-01T00:00:05.002800Z [0m  [32m INFO [0m  [2mbench_client [0m [2m: [0m RPS: 18000
 [2m2000-01-01T00:00:05.002800Z [0m  [32m INFO [0m  [2mbench_client [0m [2m: [0m LAG: 37

themisReplica0 file:

2000-01-01T00:00:00.000000Z  INFO themis_bench_app: STARTING REPLICA 0    
2000-01-01T00:00:00.000000Z  INFO themis_bench_app: Logging: INFO    
2000-01-01T00:00:00.000000Z  INFO themis_bench_app: selected runtime Single    
2000-01-01T00:00:00.000000Z  INFO themis_pbft: PBFTConfig {
    num_peers: 4,
    faults: 1,
    checkpoint_interval: 1200,
    high_mark_delta: 3200,
    request_timeout: 40000,
    keep_checkpoints: 2,
    request_proposals: false,
    primary_forwarding: Full,
    backup_forwarding: Full,
    reply_mode: All,
    debug_delay_proposal_us: 0,
    debug_force_vc: ForceVc {
        in_view: 0,
        at_seq: 0,
    },
}
2000-01-01T00:00:00.000000Z  INFO themis_bench_app: setup modules    
2000-01-01T00:00:00.000000Z  INFO themis_core::net::tcp::endpoint: binding ("11.92.212.145", 10003)
2000-01-01T00:00:00.000000Z  INFO themis_core::net::tcp::endpoint: binding ("11.92.212.145", 1000)
2000-01-01T00:00:00.000000Z  INFO themis_core::modules: batching=true
2000-01-01T00:00:00.000000Z  INFO themis_core::modules: BatchConfig {
    min: 400,
    max: 400,
    timeout: Some(
        10ms,
    ),
    rel_timeout: None,
}
2000-01-01T00:00:00.030000Z  INFO themis_core::net::tcp::group: Connected 1 from 11.92.217.160:62240
2000-01-01T00:00:00.030000Z  INFO themis_core::net::tcp::group: Connected 2 from 11.138.123.72:37005
2000-01-01T00:00:00.030000Z  INFO themis_core::net::tcp::group: Connected 3 from 11.126.140.97:44120
2000-01-01T00:00:02.003500Z  INFO themis_core::net::tcp::group: Connected 100 from 11.16.248.176:13527
2000-01-01T00:00:02.003500Z  INFO themis_core::net::tcp::group: Connected 101 from 11.16.248.176:39521
2000-01-01T00:00:02.003500Z  INFO themis_core::net::tcp::group: Connected 102 from 11.16.248.176:48120
2000-01-01T00:00:02.003500Z  INFO themis_core::net::tcp::group: Connected 103 from 11.16.248.176:34852
bergerch commented 8 months ago

Hello!

Personally, I think everything looks fine.

Note that during the execution of Shadow, there might be multiple warnings regarding not implemented syscalls. These are usually no problem at all. Apart from that some events which should be of level [info] seem to be reported as [error] like

2024-02-21T12:09:12.338Z [error] : childprocess: ** Starting Shadow v2.2.0 with GLib v2.72.4

But there is no need to worry here either! :-)

Just from seeing your Client and Replica Log files, the system did sucessfully reach consensus on several requests. For instance:

[2m2000-01-01T00:00:03.002800Z [0m [32m INFO [0m [2mbench_client [0m [2m: [0m RPS: 16200 [2m2000-01-01T00:00:03.002800Z [0m [32m INFO [0m [2mbench_client [0m [2m: [0m LAG: 42

means the client achieved a throughput of 16200 requests per second (RPS) and a latency of 42 milliseconds This also implies the replicas sucessfully executed the PBFT algorithm! Usually the replica logs do not show much in Themis since the client logs both throughput and latency results.

The configuration file you use seems also fine to me at first sight. I would recommend to use a higher duration (both experiment as a whole and higher client duration) Note that the client's start time PLUS client duration should not exceed the experiment duration, or else the client process is killed by the experiment tear-down procedure (and will not report aggregated results). I also only recomment having a single client initially before making more complex experiments.

I would recommend the following: (here in JSON, you have to edit the YAML file in YAML):

{ name: '4rep', misc: { runahead: '630 us', duration: '70 s', parallelism: 5, useShortestPath: false }, network: { replicaBandwidthUp: '10 Gibits', replicaBandwidthDown: '10 Gibits', clientBandwidthUp: '10 Gibits', clientBandwidthDown: '10 Gibits', latency: { uniform: true, replicas: '1 ms', clients: '1 ms' }, packetLoss: 0 }, replica: { replicas: 4, minBatchSize: 400, maxBatchSize: 400, replySize: 1024, batchReplies: true, requestTimeout: 40000, batchTimeout: { secs: 1, nano: 10000000 } }, client: { numberOfHosts: 1, clients: 1, startTime: '5 s', payload: 1024, concurrent: 400, duration: 60 } }

zaminsirat commented 8 months ago

Thanks for your answer. Due to the lack of documentation on Themis, your answer helped me a lot. Actually, my thesis is on PBFT and It seems that there is no plotting facility in Themis.

I expect that Themis give us more information in log such as messages: pre-prepare, prepare, commit, viewchange and ...

I ran your recommend config and expected commit message but there is no additional info:

2000-01-01T00:00:00.000000Z  INFO themis_bench_app: STARTING REPLICA 1    
2000-01-01T00:00:00.000000Z  INFO themis_bench_app: Logging: INFO    
2000-01-01T00:00:00.000000Z  INFO themis_bench_app: selected runtime Single    
2000-01-01T00:00:00.000000Z  INFO themis_pbft: PBFTConfig {
    num_peers: 4,
    faults: 1,
    checkpoint_interval: 1200,
    high_mark_delta: 3200,
    request_timeout: 40000,
    keep_checkpoints: 2,
    request_proposals: false,
    primary_forwarding: Full,
    backup_forwarding: Full,
    reply_mode: All,
    debug_delay_proposal_us: 0,
    debug_force_vc: ForceVc {
        in_view: 0,
        at_seq: 0,
    },
}
2000-01-01T00:00:00.000000Z  INFO themis_bench_app: setup modules    
2000-01-01T00:00:00.000000Z  INFO themis_core::net::tcp::endpoint: binding ("11.54.205.89", 10003)
2000-01-01T00:00:00.000000Z  INFO themis_core::net::tcp::endpoint: binding ("11.54.205.89", 1000)
2000-01-01T00:00:00.000000Z  INFO themis_core::modules: batching=true
2000-01-01T00:00:00.000000Z  INFO themis_core::modules: BatchConfig {
    min: 400,
    max: 400,
    timeout: Some(
        1.1s,
    ),
    rel_timeout: None,
}
2000-01-01T00:00:00.004000Z  INFO themis_core::net::tcp::group: Connected 2 from 11.230.234.197:32348
2000-01-01T00:00:00.004000Z  INFO themis_core::net::tcp::group: Connected 3 from 11.241.101.12:34555
2000-01-01T00:00:00.005000Z  INFO themis_core::net::tcp::group: Connected 0 from 11.96.183.127:10003
2000-01-01T00:00:05.005000Z  INFO themis_core::net::tcp::group: Connected 100 from 11.117.168.245:40548
2000-01-01T00:01:05.005000Z  WARN themis_core::net::tcp::group: Connection to 100 disconnected.
2000-01-01T00:01:05.821000Z  WARN themis_core::net::tcp::group: Cannot send Request message to 100: Does not have a connection.
2000-01-01T00:01:05.821000Z  WARN themis_core::net::tcp::group: Cannot send Request message to 100: Does not have a connection.

Then I ran Themis tmux sample: https://github.com/ibr-ds/themis/blob/753b48f56f5bf37cae75189d45ef47396b8eb1a5/tmux.yaml

I can get connection and commit log from the replica.

2024-02-21T16:25:39.080931Z  INFO themis_bench_app: STARTING REPLICA 3                                                                                        
2024-02-21T16:25:39.080950Z  INFO themis_bench_app: Logging: info                                                                                             
2024-02-21T16:25:39.080954Z  INFO themis_bench_app: selected runtime Single                                                                                   
2024-02-21T16:25:39.081346Z  INFO themis_pbft: PBFTConfig {                                                                                                   
    num_peers: 4,                                                                                                                                             
    faults: 1,                                                                                                                                                
    checkpoint_interval: 1000,                                                                                                                                
    high_mark_delta: 3000,                                                                                                                                    
    request_timeout: 1000,                                                                                                                                    
    keep_checkpoints: 2,                                                                                                                                      
    request_proposals: false,                                                                                                                                 
    primary_forwarding: Full,                                                                                                                                 
    backup_forwarding: Full,                                                                                                                                  
    reply_mode: All,                                                                                                                                          
    debug_delay_proposal_us: 0,                                                                                                                               
    debug_force_vc: ForceVc {                                                                                                                                 
        in_view: 0,                                                                                                                                           
        at_seq: 0,                                                                                                                                            
    },                                                                                                                                                        
}                                                                                                                                                             
2024-02-21T16:25:39.081360Z  INFO themis_bench_app: setup modules                                                                                             
2024-02-21T16:25:39.081395Z  INFO themis_core::net::tcp::endpoint: binding ("::", 10303)                                                                      
2024-02-21T16:25:39.081445Z  INFO themis_core::net::tcp::endpoint: binding ("::", 10302)                                                                      
2024-02-21T16:25:39.081461Z  INFO themis_core::modules: batching=false                                                                                        
2024-02-21T16:25:39.081465Z  INFO themis_core::modules: BatchConfig {                                                                                         
    min: 100,                                                                                                                                                 
    max: 100,                                                                                                                                                 
    timeout: Some(                                                                                                                                            
        10ms,                                                                                                                                                 
    ),                                                                                                                                                        
    rel_timeout: None,                                                                                                                                        
}                                                                                                                                                             
2024-02-21T16:25:39.081689Z  INFO themis_core::net::tcp::group: Connected 0 from 127.0.0.1:10003                                                              
2024-02-21T16:25:39.081747Z  INFO themis_core::net::tcp::group: Connected 1 from 127.0.0.1:10103                                                              
2024-02-21T16:25:39.081782Z  INFO themis_core::net::tcp::group: Connected 2 from 127.0.0.1:10203                                                              
2024-02-21T16:25:39.117417Z  INFO themis_core::net::tcp::group: Connected 100 from [::ffff:127.0.0.1]:50016                                                   
2024-02-21T16:25:39.118436Z  INFO themis_core::net::tcp::group: Connected 111 from [::ffff:127.0.0.1]:50040                                                   
2024-02-21T16:25:39.118502Z  INFO themis_core::net::tcp::group: Connected 104 from [::ffff:127.0.0.1]:50024                                                   
2024-02-21T16:25:39.121850Z  INFO themis_core::net::tcp::group: Connected 101 from [::ffff:127.0.0.1]:50038
2024-02-21T16:25:39.128167Z  INFO themis_core::net::tcp::group: Connected 113 from [::ffff:127.0.0.1]:50058
2024-02-21T16:25:39.128944Z  INFO themis_core::net::tcp::group: Connected 106 from [::ffff:127.0.0.1]:50056
2024-02-21T16:25:39.128994Z  INFO themis_core::net::tcp::group: Connected 102 from [::ffff:127.0.0.1]:50084
2024-02-21T16:25:39.129290Z  INFO themis_core::net::tcp::group: Connected 107 from [::ffff:127.0.0.1]:50060
2024-02-21T16:25:39.130796Z  INFO themis_core::net::tcp::group: Connected 114 from [::ffff:127.0.0.1]:50134
2024-02-21T16:25:39.133731Z  INFO themis_core::net::tcp::group: Connected 110 from [::ffff:127.0.0.1]:50150
2024-02-21T16:25:39.134460Z  INFO themis_core::net::tcp::group: Connected 109 from [::ffff:127.0.0.1]:50100
2024-02-21T16:25:39.134532Z  INFO themis_core::net::tcp::group: Connected 115 from [::ffff:127.0.0.1]:50142
2024-02-21T16:25:39.134937Z  INFO themis_core::net::tcp::group: Connected 112 from [::ffff:127.0.0.1]:50124
2024-02-21T16:25:39.135430Z  INFO themis_core::net::tcp::group: Connected 108 from [::ffff:127.0.0.1]:50112
2024-02-21T16:25:39.140069Z  INFO themis_core::net::tcp::group: Connected 119 from [::ffff:127.0.0.1]:50194
2024-02-21T16:25:39.140516Z  INFO themis_core::net::tcp::group: Connected 118 from [::ffff:127.0.0.1]:50178
2024-02-21T16:25:39.141350Z  INFO themis_core::net::tcp::group: Connected 117 from [::ffff:127.0.0.1]:50164
2024-02-21T16:25:39.142059Z  INFO themis_core::net::tcp::group: Connected 103 from [::ffff:127.0.0.1]:50086
2024-02-21T16:25:39.142746Z  INFO themis_core::net::tcp::group: Connected 116 from [::ffff:127.0.0.1]:50160
2024-02-21T16:25:39.617216Z  WARN themis_pbft: checkpoint at 1000 stable. Last commit: 1000
2024-02-21T16:25:40.027739Z  WARN themis_pbft: checkpoint at 2000 stable. Last commit: 2000
2024-02-21T16:25:40.427091Z  WARN themis_pbft: checkpoint at 3000 stable. Last commit: 3033
2024-02-21T16:25:40.832923Z  WARN themis_pbft: checkpoint at 4000 stable. Last commit: 4033
2024-02-21T16:25:41.239574Z  WARN themis_pbft: checkpoint at 5000 stable. Last commit: 5033
2024-02-21T16:25:41.672694Z  WARN themis_pbft: checkpoint at 6000 stable. Last commit: 6033
2024-02-21T16:25:42.077355Z  WARN themis_pbft: checkpoint at 7000 stable. Last commit: 7033
2024-02-21T16:25:42.483192Z  WARN themis_pbft: checkpoint at 8000 stable. Last commit: 8033
2024-02-21T16:25:42.890582Z  WARN themis_pbft: checkpoint at 9000 stable. Last commit: 9033
2024-02-21T16:25:43.297246Z  WARN themis_pbft: checkpoint at 10000 stable. Last commit: 10033
2024-02-21T16:25:43.701913Z  WARN themis_pbft: checkpoint at 11000 stable. Last commit: 11033
2024-02-21T16:25:44.105472Z  WARN themis_pbft: checkpoint at 12000 stable. Last commit: 12033
2024-02-21T16:25:44.510216Z  WARN themis_pbft: checkpoint at 13000 stable. Last commit: 13033
2024-02-21T16:25:44.916271Z  WARN themis_pbft: checkpoint at 14000 stable. Last commit: 14033
2024-02-21T16:25:45.375702Z  WARN themis_pbft: checkpoint at 15000 stable. Last commit: 15033
2024-02-21T16:25:45.768180Z  WARN themis_pbft: checkpoint at 16000 stable. Last commit: 16033
2024-02-21T16:25:46.176518Z  WARN themis_pbft: checkpoint at 17000 stable. Last commit: 17033
2024-02-21T16:25:46.581520Z  WARN themis_pbft: checkpoint at 18000 stable. Last commit: 18033
2024-02-21T16:25:46.987001Z  WARN themis_pbft: checkpoint at 19000 stable. Last commit: 19033
2024-02-21T16:25:47.390155Z  WARN themis_pbft: checkpoint at 20000 stable. Last commit: 20033 

I ran crash-pbft-4-mini and replica logs gives me some additional info:

2000-01-01T00:00:00.108110Z  INFO themis_core::net::tcp::group: Connected 2 from 11.165.186.13:10003
2000-01-01T00:00:00.402760Z  INFO themis_core::net::tcp::group: Connected 0 from 11.43.98.47:10003
2000-01-01T00:00:00.715710Z  INFO themis_core::net::tcp::group: Connected 1 from 11.199.5.168:10003
2000-01-01T00:00:10.503080Z  INFO themis_core::net::tcp::group: Connected 100 from 11.14.164.41:23418
2000-01-01T00:00:20.185700Z  WARN themis_core::net::tcp::group: Connection to 0 disconnected.
2000-01-01T00:00:22.568000Z  WARN themis_core::net::tcp::group: Cannot send Protocol(FORWARD) message to 0: Does not have a connection.
2000-01-01T00:00:24.669900Z  WARN themis_core::net::tcp::group: Cannot send Protocol(FORWARD) message to 0: Does not have a connection.
2000-01-01T00:00:26.568900Z  INFO __measure::timeout: timeout reason=Request: a0ffdcc3
2000-01-01T00:00:26.931540Z  WARN themis_pbft: <0x2|0xffffffffffffffff|<Protocol(PREPARE)|1,1|80171d9f>|5408f5e3> message rejected due to active view change
2000-01-01T00:00:26.931540Z  WARN themis_pbft: <0x2|0xffffffffffffffff|<Protocol(PREPARE)|1,2|b17f5b2b>|38d5ea4c> message rejected due to active view change

I remember receiving a commit message when testing PBFT in the example files, but in the main example, I cannot see the commit.

bergerch commented 8 months ago

Be aware that the "crash-pbft-4-mini" is an experimental description file what will simulate, i.e., induce a crash during the experiment. by killing replica 0. When that happens connection to 0 is lost, and the other replicas will initiate a view-change. Probably you want to comment out the following lines to run the experiment without a simulated fault:

  fault:
    type: crash
    threshold: 0.25
    timestamp: 20 s

(otherwise replica 0 is crashed at time=20s)

What you observe in your tmux runs with themis are just checkpoints (not the actual commits ;-) ). These checkpoints are also made in the simulation, but less freuqently, you might want to choose a lower checkpoint interval by modifying this file: https://github.com/Delphi-BFT/tool/blob/d4b501e9758cdc27ac8df28c7fd1ba9f8ee03943/src/connectors/assets/themis/pbft.toml

If you really want to observe allReplica messages like Prepare and Commit, I you have to use LOG LEVEL of either DEBUG or TRACE (this is true for both your lcoal tmux execution and execution in the simulator).

On your system, set the environment variable "RUST_LOG" to either DEBUG or TRACE, and restart your bash or tmux.

In https://github.com/Delphi-BFT/tool/blob/d4b501e9758cdc27ac8df28c7fd1ba9f8ee03943/src/connectors/themis.js Replace 'RUST_LOG=INFO' with 'RUST_LOG=TRACE' for both the client and the replica application :-)