Support tor test suite

[sporksmith]

Successfully running the tor test suite under shadow would be helpful for verifying that platform functionality that tor uses works as expected under shadow.

Using the not-yet-merged execve implementation I was able to run it. Most tests pass, but there are a few failures. Some of these are worth investigating further.

config:

general:
  stop_time: 600s
  model_unblocked_syscall_latency: true

network:
  graph:
    type: 1_gbit_switch

hosts:
  host:
    network_node_id: 0
    processes:
    - path: bash 
      start_time: 3s`
      args:
       - -c
       - |
         set -euo pipefail
         /home/jnewsome/projects/tor/src/test/test
     echo done

Full test suite stdout:
shadow-tor-make-test.stdout.txt

Just the failures:

address/get_if_addrs_ioctl: [forking] Jan 01 00:00:03.038 [err] ioctl failed: Invalid argument

  [get_if_addrs_ioctl FAILED]
crypto/openssl/rng_engine: [forking] 
  FAIL src/test/test_crypto_openssl.c:29: assert(0 OP_EQ crypto_force_rand_ssleay()): 0 vs 1
  [rng_engine FAILED]
dir/bwauth_bw_file_digest256: 
  FAIL src/test/test_dir.c:4471: assert(-1 OP_EQ dirserv_read_measured_bandwidths(fname, NULL, NULL, digest)): -1 vs 0
  [bwauth_bw_file_digest256 FAILED]
dir_handle_get/server_descriptors_all: [forking] 
  FAIL src/test/test_dir_handle_get.c:633: assert(body_used OP_EQ mock_routerinfo->cache_info.signed_descriptor_len): 18238 vs 2306
  [server_descriptors_all FAILED]
sandbox/is_active: [forking] Jan 01 00:00:06.038 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:144: assert(sandbox_is_active())
  [is_active FAILED]
sandbox/open_filename: [forking] Jan 01 00:00:06.042 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:168: assert(fd OP_EQ -1): 9 vs -1
  [open_filename FAILED]
sandbox/opendir_dirname: [forking] Jan 01 00:00:06.045 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:269: assert(dir OP_EQ NULL): 0x55555632d490 vs (nil)
  [opendir_dirname FAILED]
sandbox/openat_filename: [forking] Jan 01 00:00:06.048 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:247: assert(fd OP_EQ -1): 9 vs -1 
  [openat_filename FAILED]
sandbox/chmod_filename: [forking] Jan 01 00:00:06.052 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:188: assert(rc OP_EQ -1): 0 vs -1
  [chmod_filename FAILED]    
sandbox/chown_filename: [forking] Jan 01 00:00:06.055 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:206: assert(rc OP_EQ -1): 0 vs -1
  [chown_filename FAILED]
sandbox/rename_filename: [forking] Jan 01 00:00:06.058 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:226: assert(rc OP_EQ -1): 0 vs -1
  [rename_filename FAILED]
tortls/verify: [forking]
  FAIL src/test/test_tortls.c:512: assert(ret OP_EQ 0): -1 vs 0
  [verify FAILED]
tortls/openssl/cert_is_valid: [forking]
  FAIL src/test/test_tortls_openssl.c:2085: assert(ret OP_EQ 1): 0 vs 1
  [cert_is_valid FAILED]
util/monotonic_time:           
  FAIL src/test/test_util.c:6492: assert(monotime_diff_msec(&mt1, &mt2) OP_GE 175): 0 vs 175
  [monotonic_time FAILED]    
14/1481 TESTS FAILED. (27 skipped)

additionally, the test compat/libevent/postloop_events deadlocks unless model_unblocked_syscall_latency is enabled, which could be a busy-loop bug in tor (but may only be an issue in the test).

Here are shadow's warnings:

$ grep -E 'WARN|ERROR' build/src/test/examples/bash/shadow.log 
00:00:00.008151 [62233:shadow-worker] 00:00:03.000058030 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:00:00.008309 [62233:shadow-worker] 00:00:03.000060030 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:00:00.009371 [62233:shadow-worker] 00:00:03.000080050 [WARN] [host:11.0.0.1] [ioctl.c:50] [_syscallhandler_ioctlFileHelper] We do not yet handle ioctl request 21519 on file 2
00:00:00.009473 [62233:shadow-worker] 00:00:03.000082050 [WARN] [host:11.0.0.1] [ioctl.c:50] [_syscallhandler_ioctlFileHelper] We do not yet handle ioctl request 21519 on file 2
00:00:09.797390 [62233:shadow-worker] 00:00:03.038214360 [WARN] [host:11.0.0.1] [udp.rs:639] [shadow_rs::host::descriptor::socket::inet::udp] (LOG_ONCE) We do not yet handle ioctl request SIOCGIFCONF on tcp sockets
00:00:51.485479 [62233:shadow-worker] 00:00:03.197940420 [WARN] [host:11.0.0.1] [syscall_handler.c:564] [syscallhandler_make_syscall] Detected unsupported syscall 95 called from thread 1052 in process bash on host host
00:10:44.289734 [62233:shadow-worker] 00:00:05.590938360 [WARN] [host:11.0.0.1] [dns.c:195] [dns_resolveNameToAddress] unable to find address from name 'fractabling'
00:12:41.844376 [62233:shadow-worker] 00:00:06.038913340 [WARN] [host:11.0.0.1] [syscall_handler.c:564] [syscallhandler_make_syscall] Detected unsupported syscall 317 called from thread 1801 in process bash on host host
00:12:41.845162 [62233:shadow-worker] 00:00:06.038917340 [WARN] [host:11.0.0.1] [process.c:87] [syscallhandler_prctl] Not allowing seccomp prctl 22
00:12:42.881769 [62233:shadow-worker] 00:00:06.042251150 [WARN] [host:11.0.0.1] [syscall_handler.c:564] [syscallhandler_make_syscall] Detected unsupported syscall 317 called from thread 1802 in process bash on host host
00:12:42.882640 [62233:shadow-worker] 00:00:06.042255150 [WARN] [host:11.0.0.1] [process.c:87] [syscallhandler_prctl] Not allowing seccomp prctl 22
00:12:43.922078 [62233:shadow-worker] 00:00:06.045564680 [WARN] [host:11.0.0.1] [syscall_handler.c:564] [syscallhandler_make_syscall] Detected unsupported syscall 317 called from thread 1803 in process bash on host host
00:12:43.922853 [62233:shadow-worker] 00:00:06.045568680 [WARN] [host:11.0.0.1] [process.c:87] [syscallhandler_prctl] Not allowing seccomp prctl 22
00:12:44.920891 [62233:shadow-worker] 00:00:06.048910510 [WARN] [host:11.0.0.1] [syscall_handler.c:564] [syscallhandler_make_syscall] Detected unsupported syscall 317 called from thread 1804 in process bash on host host
00:12:44.921787 [62233:shadow-worker] 00:00:06.048914510 [WARN] [host:11.0.0.1] [process.c:87] [syscallhandler_prctl] Not allowing seccomp prctl 22
00:12:45.966656 [62233:shadow-worker] 00:00:06.052260400 [WARN] [host:11.0.0.1] [syscall_handler.c:564] [syscallhandler_make_syscall] Detected unsupported syscall 317 called from thread 1805 in process bash on host host
00:12:45.967394 [62233:shadow-worker] 00:00:06.052264400 [WARN] [host:11.0.0.1] [process.c:87] [syscallhandler_prctl] Not allowing seccomp prctl 22
00:12:46.964458 [62233:shadow-worker] 00:00:06.055548700 [WARN] [host:11.0.0.1] [syscall_handler.c:564] [syscallhandler_make_syscall] Detected unsupported syscall 317 called from thread 1806 in process bash on host host
00:12:46.965217 [62233:shadow-worker] 00:00:06.055552700 [WARN] [host:11.0.0.1] [process.c:87] [syscallhandler_prctl] Not allowing seccomp prctl 22
00:12:47.904569 [62233:shadow-worker] 00:00:06.058884470 [WARN] [host:11.0.0.1] [syscall_handler.c:564] [syscallhandler_make_syscall] Detected unsupported syscall 317 called from thread 1807 in process bash on host host
00:12:47.905328 [62233:shadow-worker] 00:00:06.058888470 [WARN] [host:11.0.0.1] [process.c:87] [syscallhandler_prctl] Not allowing seccomp prctl 22
00:14:36.369296 [62233:shadow-worker] 00:00:06.460652570 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:14:36.369436 [62233:shadow-worker] 00:00:06.460654570 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:14:36.375405 [62233:shadow-worker] 00:00:06.460726570 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:14:36.375540 [62233:shadow-worker] 00:00:06.460728570 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:14:36.380071 [62233:shadow-worker] 00:00:06.460815580 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:14:36.380880 [62233:shadow-worker] 00:00:06.460831580 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:14:36.381006 [62233:shadow-worker] 00:00:06.460833580 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:14:36.384379 [62233:shadow-worker] 00:00:06.460904590 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:14:36.385234 [62233:shadow-worker] 00:00:06.460920590 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:14:36.385359 [62233:shadow-worker] 00:00:06.460924590 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported
00:14:36.388777 [62233:shadow-worker] 00:00:06.460995600 [WARN] [host:11.0.0.1] [unix.rs:2211] [shadow_rs::host::descriptor::socket::unix] Unix sockets with pathname addresses are not yet supported

[sporksmith]

The address/get_if_addrs_ioctl failure probably corresponds to shadow's warning about SIOCGIFCONF being unimplemented. This wouldn't be too bad to implement, but we could reasonably ignore this failure since tor simulations still work without it.

The sandbox failures are expected since shadow doesn't support seccomp.

The util/monotonic_time: failure is likely due to shadow's time model of not moving time forward (much) unless there's a blocking syscall, but is probably worth double-checking.

The remaining failures are a bit concerning, but could still be artifacts of shadow's environment.

crypto/openssl/rng_engine: [forking] 
  FAIL src/test/test_crypto_openssl.c:29: assert(0 OP_EQ crypto_force_rand_ssleay()): 0 vs 1
  [rng_engine FAILED]
dir/bwauth_bw_file_digest256: 
  FAIL src/test/test_dir.c:4471: assert(-1 OP_EQ dirserv_read_measured_bandwidths(fname, NULL, NULL, digest)): -1 vs 0
  [bwauth_bw_file_digest256 FAILED]
dir_handle_get/server_descriptors_all: [forking] 
  FAIL src/test/test_dir_handle_get.c:633: assert(body_used OP_EQ mock_routerinfo->cache_info.signed_descriptor_len): 18238 vs 2306
  [server_descriptors_all FAILED]
tortls/verify: [forking]
  FAIL src/test/test_tortls.c:512: assert(ret OP_EQ 0): -1 vs 0
  [verify FAILED]
tortls/openssl/cert_is_valid: [forking]
  FAIL src/test/test_tortls_openssl.c:2085: assert(ret OP_EQ 1): 0 vs 1
  [cert_is_valid FAILED]

[sporksmith]

crypto/openssl/rng_engine: [forking] 
  FAIL src/test/test_crypto_openssl.c:29: assert(0 OP_EQ crypto_force_rand_ssleay()): 0 vs 1
  [rng_engine FAILED]

Here's the tor function that's failing, from src/lib/crypt_ops/crypto_rand.c:

int   
crypto_force_rand_ssleay(void)
{
#ifdef ENABLE_OPENSSL 
  RAND_METHOD *default_method;
  default_method = RAND_OpenSSL();
  if (RAND_get_rand_method() != default_method) { 
    log_notice(LD_CRYPTO, "It appears that one of our engines has provided "
               "a replacement the OpenSSL RNG. Resetting it to the default "
               "implementation.");
    RAND_set_rand_method(default_method);
    return 1;
  }   
#endif /* defined(ENABLE_OPENSSL) */
  return 0;
}

I think this is detecting shadow's LD_PRELOAD shenanigans that installed an easier-to-make-deterministic RNG. Setting the shadow flag --use-preload-openssl-rng=false causes this test to pass.

I think we can safely ignore this test.

[sporksmith]

dir/bwauth_bw_file_digest256: 
  FAIL src/test/test_dir.c:4471: assert(-1 OP_EQ dirserv_read_measured_bandwidths(fname, NULL, NULL, digest)): -1 vs 0
  [bwauth_bw_file_digest256 FAILED]

This failure comes from src/test/test_dir.c:

  const char *content =
    "1541171221\n"
    "node_id=$68A483E05A2ABDCA6DA5A3EF8DB5177638A27F80 "
    "master_key_ed25519=YaqV4vbvPYKucElk297eVdNArDz9HtIwUoIeo0+cVIpQ "
    "bw=760 nick=Test time=2018-05-08T16:13:26\n";
...
  /* When there is a timestamp but it is too old. */
  write_str_to_file(fname, content, 0);
  tt_int_op(-1, OP_EQ,
            dirserv_read_measured_bandwidths(fname,
                                             NULL, NULL, digest));

The test is expecting the bandwidth file to be rejected for being too old, but since the test uses Y2018 for an "old" date and shadow simulates time starting at Y2000, the file isn't rejected.

So we can safely ignore this one too, though it might be nice to tweak the test so that it passes (or maybe add a feature in Shadow to be able to start simulated time a bit closer to "now").

[sporksmith]

dir_handle_get/server_descriptors_all: [forking] 
  FAIL src/test/test_dir_handle_get.c:633: assert(body_used OP_EQ mock_routerinfo->cache_info.signed_descriptor_len): 18238 vs 2306
  [server_descriptors_all FAILED]

This one's interesting. Here's the code:

  //TODO: Is this a BUG?
  //It requires strlen(signed_descriptor_len)+1 as body_len but returns a body
  //which is smaller than that by annotation_len bytes
  fetch_from_buf_http(TO_CONN(conn)->outbuf, &header, MAX_HEADERS_SIZE,
                      &body, &body_used,
                      1024*1024, 0);
...
  //TODO: Is this a BUG?
  //This is what should be expected: tt_int_op(body_used, OP_EQ, strlen(body));
  tt_int_op(body_used, OP_EQ,
            mock_routerinfo->cache_info.signed_descriptor_len);

I added a printf:

  printf("\nbody_used:%ld signed_descriptor_len:%ld strlen(body):%ld\n",
      body_used, mock_routerinfo->cache_info.signed_descriptor_len, strlen(body));

Which prints:

body_used:18238 signed_descriptor_len:2306 strlen(body):18238

So, the test is validating that the behavior matches the past observed behavior (body_used == signed_descriptor_len), but the commenter is confused why body_used is getting set to that and not strlen(body).

Under shadow it does get set to strlen(body) as the commenter expected, but unlike what happens on real systems.

This test doesn't do any network syscalls; fetch_from_buf_http fetches from an in-memory buffer.

There is some time handling earlier in the test setup; I haven't fully traced it but I suspect this is again something to do with unusual wall-clock time of y2000 and hard-coded test dates. i.e. some validation somewhere is getting a different result and making different accept/reject decisions over the test data.

It might be useful to track down, since the comments indicate the test isn't really working as the test-writer expected either, but probably not a shadow bug.

[sporksmith]

I reran the tests starting from a more recent simulation time, and verified that a lot of the failures were indeed because of the unusual simulated time of Y2000.

I ran the tests from a wrapper script that sleeps for ~23 years before starting the tests [EDIT: in hindsight I could've skipped the wrapper script and just set the test process start_time to 201618h in the shadow config file]:

         date
         sleep 201618h
         date

         /home/jnewsome/projects/tor/src/test/test

Output:

Sat Jan  1 00:00:03 GMT 2000
Sat Dec 31 18:00:03 GMT 2022
onion_handshake: OK
...

I set shadow's stop_time to 201619h to accomodate this, and set the tracker and minimum runahead intervals to 1h to speed up shadow's "fast forwarding" of time here. I also disabled the RNG preload library.

/home/jnewsome/projects/shadow/dev/build/src/main/shadow       --data-directory=bash-example-shadow.data       --log-level=info       --use-preload-openssl-rng=false --use-memory-manager=false --use-cpu-pinning false --strace-logging-mode standard --parallelism 1  --heartbeat-interval=3600 --host-heartbeat-interval=3600 --runahead=3600   /home/jnewsome/projects/shadow/dev/src/test/examples/bash/bash-example.yaml > shadow.log

The failing tests from this run:

$ grep -Ev " OK| SKIPPED" build/src/test/examples/bash/bash-example-shadow.data/hosts/host/bash.1000.stdout 
Sat Jan  1 00:00:03 GMT 2000
Sat Dec 31 18:00:03 GMT 2022
address/get_if_addrs_ioctl: [forking] Dec 31 18:00:03.038 [err] ioctl failed: Invalid argument

  [get_if_addrs_ioctl FAILED]
sandbox/is_active: [forking] Dec 31 18:00:06.032 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:144: assert(sandbox_is_active())
  [is_active FAILED]
sandbox/open_filename: [forking] Dec 31 18:00:06.035 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:168: assert(fd OP_EQ -1): 9 vs -1
  [open_filename FAILED]
sandbox/opendir_dirname: [forking] Dec 31 18:00:06.039 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:269: assert(dir OP_EQ NULL): 0x555556355f80 vs (nil)
  [opendir_dirname FAILED]
sandbox/openat_filename: [forking] Dec 31 18:00:06.042 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:247: assert(fd OP_EQ -1): 9 vs -1
  [openat_filename FAILED]
sandbox/chmod_filename: [forking] Dec 31 18:00:06.045 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:188: assert(rc OP_EQ -1): 0 vs -1
  [chmod_filename FAILED]
sandbox/chown_filename: [forking] Dec 31 18:00:06.049 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:206: assert(rc OP_EQ -1): 0 vs -1
  [chown_filename FAILED]
sandbox/rename_filename: [forking] Dec 31 18:00:06.052 [err] install_syscall_filter(): Bug: (Sandbox) failed to load: -125 (Operation canceled)! Are you sure that your kernel has seccomp2 support? The sandbox won't work without it. (on Tor 0.4.7.13 7c1601fb6edd780f)

  FAIL src/test/test_sandbox.c:226: assert(rc OP_EQ -1): 0 vs -1
  [rename_filename FAILED]
util/monotonic_time: 
  FAIL src/test/test_util.c:6492: assert(monotime_diff_msec(&mt1, &mt2) OP_GE 175): 0 vs 175
  [monotonic_time FAILED]
9/1481 TESTS FAILED. (27 skipped)

Summarizing these:

• address/get_if_addrs_ioctl fails because of an ioctl that shadow doesn't implement. This doesn't appear to affect normal tor operation.
• the sandbox failures are expected, because shadow doesn't emulate seccomp.
• util/monotonic_time is because shadow doesn't always move time forward between syscalls. This can be tweaked with --model-unblocked-syscall-latency and related parameters, but probably isn't worth worrying about much wrt tor network simulations.

[sporksmith]

If we wanted to add this to the CI, we could pass test a list of tests to skip

$ src/test/test --help
Options are: [--verbose|--quiet|--terse] [--no-fork]
  Specify tests by name, or using a prefix ending with '..'
  To skip a test, prefix its name with a colon.
  To enable a disabled test, prefix its name with a plus.
  Use --list-tests for a list of tests.

OTOH I'm not sure such a CI test is worth fleshing out and maintaining at the moment with both shadow and tor development slowing down. (But maybe it'd be worth running arti's unit tests in addition to adding arti to the Tor integration test)