Internal evaluation (training) on the server-side returns a subprocess timeout error

[Abderrahmenee]

python3 evolve.py --population 200 --generations 25 --test-type http --server forbidden.org --censor censor4 --server-side

File "/home/abe/geneva/evaluator.py", line 322, in run_docker_client
self.exec_cmd(command)
File "/home/abe/geneva/evaluator.py", line 494, in exec_cmd
subprocess.check_call(command, timeout=60)
File "/usr/lib/python3.9/subprocess.py", line 373, in check_call
raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['docker', 'exec', '--privileged', 'client_canary', 'python', 'code/plugins/plugin_client.py', '--server', '172.17.0.4', '--test-type', 'http', '--strategy', "''", '--log', 'debug', '--output-directory', 'trials/2022-06-22_11:40:18', '--server-side', '--port', '3818', '--censor', 'censor4', '--workers', '1', '--bad-word', 'ultrasurf', '--runs', '1', '--fitness-by', 'avg', '--no-engine', '--server', '172.17.0.4', '--wait-for-censor', '--host-header', "''", '--injected-http-contains', "''", '--environment-id', 'canary']' returned non-zero exit status 1.
Exception in thread Thread-1:

[flandweber]

Could reproduce. Also occurs on other censors (censor2 and censor8 tested).
Full execution log:

$ sudo python3 evolve.py --population 200 --generations 25 --test-type http --server forbidden.org --censor censor4 --server-side
2022-08-02 18:41:16 INFO:Logging results to trials/2022-08-02_18:41:16/logs
2022-08-02 18:41:17 INFO:Strategies will only be allowed to use protocols: TCP
2022-08-02 18:41:17 INFO:Initializing 200 strategies with 0 input-action trees and 1 output-action trees of input size 2 and output size 2 for evolution over 25 generations.
2022-08-02 18:41:17 INFO:Starting collection phase
2022-08-02 18:41:19 DEBUG:[ENGINE] Engine created with strategy \/ (ID canary) to port 27952
2022-08-02 18:41:19 DEBUG:[ENGINE] Configuring iptables rules
2022-08-02 18:41:19 DEBUG:[ENGINE] iptables -A OUTPUT -p tcp --match tcp --sport 27952 -j NFQUEUE --queue-num 2
2022-08-02 18:41:19 DEBUG:[ENGINE] iptables -A INPUT -p tcp --match tcp --dport 27952 -j NFQUEUE --queue-num 1
2022-08-02 18:41:19 DEBUG:[ENGINE] iptables -A OUTPUT -p udp --match udp --sport 27952 -j NFQUEUE --queue-num 2
2022-08-02 18:41:19 DEBUG:[ENGINE] iptables -A INPUT -p udp --match udp --dport 27952 -j NFQUEUE --queue-num 1
2022-08-02 18:41:19 DEBUG:[ENGINE] NFQueue Initialized after 0
/usr/local/lib/python3.6/site-packages/scapy/config.py:384: CryptographyDeprecationWarning: Python 3.6 is no longer supported by the Python core team. Therefore, support for it is deprecated in cryptography and will be removed in a future release.
  import cryptography
/usr/local/lib/python3.6/site-packages/scapy/layers/ipsec.py:469: CryptographyDeprecationWarning: Blowfish has been deprecated
  cipher=algorithms.Blowfish,
/usr/local/lib/python3.6/site-packages/scapy/layers/ipsec.py:483: CryptographyDeprecationWarning: CAST5 has been deprecated
  cipher=algorithms.CAST5,
2022-08-02 18:41:20 DEBUG:[CLIENT] Launching http
2022-08-02 18:41:20 DEBUG:[CLIENT] Sniffer starting to port 27952
2022-08-02 18:41:20 ERROR:[ENGINE] Could not identify trigger or tree
2022-08-02 18:41:21 DEBUG:[CLIENT] Sniffer stopping
Traceback (most recent call last):
  File "code/plugins/plugin_client.py", line 130, in <module>
    main(sys.argv[1:])
  File "code/plugins/plugin_client.py", line 127, in main
    client_plugin.start(plugin_args, logger)
  File "/code/plugins/plugin_client.py", line 72, in start
    with engine.Engine(port, args.get("strategy"), server_side=False, environment_id=eid, output_directory=output_path, log_level=args.get("log", "info"), enabled=use_engine) as eng:
  File "/code/engine.py", line 103, in __init__
    self.strategy = actions.utils.parse(string_strategy, self.logger)
  File "/code/actions/utils.py", line 95, in parse
    raise actions.tree.ActionTreeParseError("Failed to parse tree")
actions.tree.ActionTreeParseError: Failed to parse tree
Traceback (most recent call last):
  File "/home/vagrant/geneva/plugins/http/plugin.py", line 143, in start
    fitness = evaluator.run_client(evaluator.client_args, environment, logger)
  File "/home/vagrant/geneva/evaluator.py", line 299, in run_client
    self.run_docker_client(args, environment, logger)
  File "/home/vagrant/geneva/evaluator.py", line 322, in run_docker_client
    self.exec_cmd(command)
  File "/home/vagrant/geneva/evaluator.py", line 494, in exec_cmd
    subprocess.check_call(command, timeout=60)
  File "/usr/lib/python3.9/subprocess.py", line 373, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['docker', 'exec', '--privileged', 'client_canary', 'python', 'code/plugins/plugin_client.py', '--server', '172.17.0.4', '--test-type', 'http', '--strategy', "''", '--log', 'debug', '--output-directory', 'trials/2022-08-02_18:41:16', '--server-side', '--port', '27952', '--censor', 'censor4', '--workers', '1', '--bad-word', 'ultrasurf', '--runs', '1', '--fitness-by', 'avg', '--no-engine', '--server', '172.17.0.4', '--wait-for-censor', '--host-header', "''", '--injected-http-contains', "''", '--environment-id', 'canary']' returned non-zero exit status 1.
2022-08-02 18:41:21 DEBUG:[ENGINE] Shutting down NFQueue
2022-08-02 18:41:23 DEBUG:[ENGINE] Configuring iptables rules
2022-08-02 18:41:23 DEBUG:[ENGINE] iptables -D OUTPUT -p tcp --match tcp --sport 27952 -j NFQUEUE --queue-num 2
2022-08-02 18:41:23 DEBUG:[ENGINE] iptables -D INPUT -p tcp --match tcp --dport 27952 -j NFQUEUE --queue-num 1
2022-08-02 18:41:23 DEBUG:[ENGINE] iptables -D OUTPUT -p udp --match udp --sport 27952 -j NFQUEUE --queue-num 2
2022-08-02 18:41:23 DEBUG:[ENGINE] iptables -D INPUT -p udp --match udp --dport 27952 -j NFQUEUE --queue-num 1
Traceback (most recent call last):
  File "/home/vagrant/geneva/evolve.py", line 835, in <module>
    driver(sys.argv[1:])
  File "/home/vagrant/geneva/evolve.py", line 814, in driver
    hall_of_fame = genetic_solve(logger, options, ga_evaluator)
  File "/home/vagrant/geneva/evolve.py", line 522, in genetic_solve
    canary_id = run_collection_phase(logger, ga_evaluator)
  File "/home/vagrant/geneva/evolve.py", line 409, in run_collection_phase
    canary_id = ga_evaluator.canary_phase(canary)
  File "/home/vagrant/geneva/evaluator.py", line 650, in canary_phase
    self.worker([canary], canary.environment_id, environment)
  File "/home/vagrant/geneva/evaluator.py", line 808, in worker
    eid, fitness = self.run_test(environment, ind)
  File "/home/vagrant/geneva/evaluator.py", line 239, in run_test
    self.plugin.start(self.args, self, environment, ind, self.logger)
  File "/home/vagrant/geneva/plugins/http/plugin.py", line 143, in start
    fitness = evaluator.run_client(evaluator.client_args, environment, logger)
  File "/home/vagrant/geneva/evaluator.py", line 299, in run_client
    self.run_docker_client(args, environment, logger)
  File "/home/vagrant/geneva/evaluator.py", line 322, in run_docker_client
    self.exec_cmd(command)
  File "/home/vagrant/geneva/evaluator.py", line 494, in exec_cmd
    subprocess.check_call(command, timeout=60)
  File "/usr/lib/python3.9/subprocess.py", line 373, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['docker', 'exec', '--privileged', 'client_canary', 'python', 'code/plugins/plugin_client.py', '--server', '172.17.0.4', '--test-type', 'http', '--strategy', "''", '--log', 'debug', '--output-directory', 'trials/2022-08-02_18:41:16', '--server-side', '--port', '27952', '--censor', 'censor4', '--workers', '1', '--bad-word', 'ultrasurf', '--runs', '1', '--fitness-by', 'avg', '--no-engine', '--server', '172.17.0.4', '--wait-for-censor', '--host-header', "''", '--injected-http-contains', "''", '--environment-id', 'canary']' returned non-zero exit status 1.
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/home/vagrant/geneva/evaluator.py", line 496, in exec_cmd
    subprocess.check_call(command, stderr=subprocess.DEVNULL, stdout=subprocess.DEVNULL, timeout=60)
  File "/usr/lib/python3.9/subprocess.py", line 368, in check_call
    retcode = call(*popenargs, **kwargs)
  File "/usr/lib/python3.9/subprocess.py", line 351, in call
    return p.wait(timeout=timeout)
  File "/usr/lib/python3.9/subprocess.py", line 1189, in wait
    return self._wait(timeout=timeout)
  File "/usr/lib/python3.9/subprocess.py", line 1911, in _wait
    raise TimeoutExpired(self.args, timeout)
subprocess.TimeoutExpired: Command '['docker', 'exec', '--privileged', 'server_canary', 'python', 'code/plugins/plugin_server.py', '--test-type', 'http', '--test-type', 'http', '--strategy', '" \\/ "', '--log', 'debug', '--output-directory', 'trials/2022-08-02_18:41:16', '--server-side', '--port', '27952', '--censor', 'censor4', '--workers', '1', '--bad-word', 'ultrasurf', '--runs', '1', '--fitness-by', 'avg', '--wait-for-shutdown', '--environment-id', 'canary', '--no-engine']' timed out after 60 seconds

Python 3.9.2, Debian 11, Kernel: 5.10.0-16-amd64