The analysis fails to start and ends immediately. [Extraction container could not be reached.]

[oguzhanozgur]

FACT version

4.3-dev

Environment

Distribution : Ubuntu 22.04.5 LTS powered by FACT 4.3-dev © Fraunhofer FKIE 2015-2024

Steps to reproduce

1. Starting the tool by writing below command: ~/FACT_core/start_all_installed_fact_components
2. Then, filling the required fields for the file. (version, names etc.)
3. Starting analysis.

Observed Behavior

The analysis has ended immediately and nothing showed up at result screen.

Expeced Behavior

The analysis should start normally and the tool analyze the fields which I marked.

Installation logs

No response

Backend logs

[2024-10-01 13:29:01][connectionpool][WARNING]: Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7dbd805f7c70>: Failed to establish a new connection: [Errno 111] Connection refused')': /status [2024-10-01 13:29:01][connectionpool][WARNING]: Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7dbd805f7ee0>: Failed to establish a new connection: [Errno 111] Connection refused')': /status [2024-10-01 13:29:02][connectionpool][WARNING]: Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7dbd805f71c0>: Failed to establish a new connection: [Errno 111] Connection refused')': /status [2024-10-01 13:29:02][unpacking_scheduler][ERROR]: Could not fetch unpacking container logs [2024-10-01 13:29:02][unpacking_scheduler][ERROR]: Exception happened during extraction of 2bd7fcbb382db9223414bde8aefd4f7eab3299bc0084e43356e6c1ac26af3baf_4535.: Extraction container could not be reached. Traceback (most recent call last): File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connection.py", line 199, in _new_conn sock = connection.create_connection( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/util/connection.py", line 85, in create_connection raise err File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/util/connection.py", line 73, in create_connection sock.connect(sa) ConnectionRefusedError: [Errno 111] Connection refused

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 789, in urlopen response = self._make_request( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 495, in _make_request conn.request( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connection.py", line 441, in request self.endheaders() File "/usr/lib/python3.10/http/client.py", line 1278, in endheaders self._send_output(message_body, encode_chunked=encode_chunked) File "/usr/lib/python3.10/http/client.py", line 1038, in _send_output self.send(msg) File "/usr/lib/python3.10/http/client.py", line 976, in send self.connect() File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connection.py", line 279, in connect self.sock = self._new_conn() File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connection.py", line 214, in _new_conn raise NewConnectionError( urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPConnection object at 0x7dbd80424160>: Failed to establish a new connection: [Errno 111] Connection refused

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/requests/adapters.py", line 589, in send resp = conn.urlopen( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 873, in urlopen return self.urlopen( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 873, in urlopen return self.urlopen( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 873, in urlopen return self.urlopen( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 843, in urlopen retries = retries.increment( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/util/retry.py", line 519, in increment raise MaxRetryError(_pool, url, reason) from reason # type: ignore[arg-type] urllib3.exceptions.MaxRetryError: HTTPConnectionPool(host='localhost', port=9900): Max retries exceeded with url: /status (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7dbd80424160>: Failed to establish a new connection: [Errno 111] Connection refused'))

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack_base.py", line 55, in _extract_with_worker response = container.start_unpacking(tmp_dir, timeout=WORKER_TIMEOUT) File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 118, in start_unpacking response = self._check_connection() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 133, in _check_connection return session.get(url, timeout=5) File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/requests/sessions.py", line 602, in get return self.request("GET", url, kwargs) File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/requests/sessions.py", line 589, in request resp = self.send(prep, send_kwargs) File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/requests/sessions.py", line 703, in send r = adapter.send(request, **kwargs) File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/requests/adapters.py", line 622, in send raise ConnectionError(e, request=request) requests.exceptions.ConnectionError: HTTPConnectionPool(host='localhost', port=9900): Max retries exceeded with url: /status (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7dbd80424160>: Failed to establish a new connection: [Errno 111] Connection refused'))

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 199, in work_thread extracted_objects = self.unpacker.unpack(task, tmp_dir, container) File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack.py", line 42, in unpack extracted_files = self.extract_files_from_file(current_fo.file_path, tmp_dir, container) File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack_base.py", line 41, in extract_files_from_file self._extract_with_worker(file_path, container, tmp_dir) File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack_base.py", line 59, in _extract_with_worker raise ExtractionError('Extraction container could not be reached.') from error unpacker.unpack_base.ExtractionError: Extraction container could not be reached. [2024-10-01 13:29:02][unpacking_scheduler][INFO]: Unpacking completed: 2bd7fcbb382db9223414bde8aefd4f7eab3299bc0084e43356e6c1ac26af3baf_4535 (extracted files: 0) [2024-10-01 13:29:02][unpacking_scheduler][INFO]: Unpacking of firmware 2bd7fcbb382db9223414bde8aefd4f7eab3299bc0084e43356e6c1ac26af3baf_4535 completed. /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file /home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file/home/oguzhanozgur/FACT_core/src/bin/firmware' Process ExceptionSafeProcess-109: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. [2024-10-01 13:29:03][scheduler][INFO]: Analysis Completed: 2bd7fcbb382db9223414bde8aefd4f7eab3299bc0084e43356e6c1ac26af3baf_4535 [2024-10-01 13:29:03][analysis_status][INFO]: Analysis of firmware 2bd7fcbb382db9223414bde8aefd4f7eab3299bc0084e43356e6c1ac26af3baf_4535 completed

Frontend logs

No response

Other information

No response

[jstucke]

urllib3.exceptions.MaxRetryError: HTTPConnectionPool(host='localhost', port=9900): Max retries exceeded with url: /status (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0x7dbd80424160>: Failed to establish a new connection: [Errno 111] Connection refused'))

This means that the extractor container could not be reached. The extractor is responsible for unpacking the firmware image and runs inside a docker container. Could you make sure the docker image is there? docker image ls | grep -i fact_extractor should give at least one result with tag "latest". Also could you make sure there are no errors when you start the backend? It should look something like this when the unpacking scheduler starts without errors:

[2024-10-01 14:43:46][extraction_container][INFO]: Started unpack worker 0
[2024-10-01 14:43:47][extraction_container][INFO]: Started unpack worker 1
[2024-10-01 14:43:47][extraction_container][INFO]: Started unpack worker 2
[2024-10-01 14:43:47][extraction_container][INFO]: Started unpack worker 3
[2024-10-01 14:43:47][unpacking_scheduler][INFO]: Unpacking scheduler online

It could also be the case that extractor containers are still running from another time when you did not shut down FACT cleanly. Then you can run docker ps | grep fact_extractor | cut --delimiter " " --fields 1 | xargs docker stop to stop the containers before starting FACT again.

[oguzhanozgur]

When I start the tool, i can see these logs (and I guess there is no error here.)

oguzhanozgur@oguzhanozgur:~/FACT_core$ ./start_all_installed_fact_components [2024-10-01 15:56:46][start_all_installed_fact_components][INFO]: starting database [2024-10-01 15:56:46][start_all_installed_fact_components][INFO]: starting frontend [2024-10-01 15:56:46][start_all_installed_fact_components][INFO]: starting backend [2024-10-01 15:56:46][fact_base][INFO]: Starting FACT Frontend @ 4.3-dev (d96db1d1, Python 3.10.12) [2024-10-01 15:56:46][init][INFO]: Alembic DB revision: head: 05d8effce8b3, current: 05d8effce8b3 [2024-10-01 15:56:46][fact_base][INFO]: Starting FACT DB-Service @ 4.3-dev (d96db1d1, Python 3.10.12) [2024-10-01 15:56:46][init][INFO]: Alembic DB revision: head: 05d8effce8b3, current: 05d8effce8b3 [2024-10-01 15:56:46][fact_base][INFO]: Starting FACT Backend @ 4.3-dev (d96db1d1, Python 3.10.12) [2024-10-01 15:56:46][fact_base][INFO]: Successfully started FACT DB-Service [2024-10-01 15:56:46][init][INFO]: Alembic DB revision: head: 05d8effce8b3, current: 05d8effce8b3 [2024-10-01 15:56:47][fact_base][INFO]: Successfully started FACT Frontend [uWSGI] getting INI configuration from /home/oguzhanozgur/FACT_core/src/config/uwsgi_config.ini Starting uWSGI 2.0.25.1 (64bit) on [Tue Oct 1 15:56:47 2024] compiled with version: 11.4.0 on 01 October 2024 07:03:53 os: Linux-6.5.0-1027-oem #28-Ubuntu SMP PREEMPT_DYNAMIC Thu Jul 25 13:32:46 UTC 2024 nodename: oguzhanozgur machine: x86_64 clock source: unix detected number of CPU cores: 12 current working directory: /home/oguzhanozgur/FACT_core/src detected binary path: /home/oguzhanozgur/ozzy/bin/uwsgi !!! no internal routing support, rebuild with pcre support !!! your processes number limit is 125501 your memory page size is 4096 bytes detected max file descriptor number: 1024 lock engine: pthread robust mutexes thunder lock: enabled uwsgi socket 0 bound to TCP address 127.0.0.1:5000 fd 3 Python version: 3.10.12 (main, Sep 11 2024, 15:47:36) [GCC 11.4.0] Python main interpreter initialized at 0x58d1df7f1fc0 python threads support enabled your server socket listen backlog is limited to 100 connections your mercy for graceful operations on workers is 60 seconds mapped 500064 bytes (488 KB) for 10 cores Operational MODE: preforking+threaded [2024-10-01 15:56:47][ip_and_uri_finder_analysis][INFO]: ip signature path: /home/oguzhanozgur/ozzy/lib/python3.10/site-packages/common_analysis_ip_and_uri_finder/yara_rules/ip_rules.yara [2024-10-01 15:56:47][ip_and_uri_finder_analysis][INFO]: ip signature path: /home/oguzhanozgur/ozzy/lib/python3.10/site-packages/common_analysis_ip_and_uri_finder/yara_rules/uri_rules.yara [2024-10-01 15:56:47][frontend_main][INFO]: Web front end online WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x58d1df7f1fc0 pid: 54743 (default app) uWSGI is running in multiple interpreter mode spawned uWSGI master process (pid: 54743) spawned uWSGI worker 1 (pid: 54962, cores: 2) spawned uWSGI worker 2 (pid: 54964, cores: 2) spawned uWSGI worker 3 (pid: 54966, cores: 2) spawned uWSGI worker 4 (pid: 54968, cores: 2) spawned uWSGI worker 5 (pid: 54970, cores: 2) Stats server enabled on 127.0.0.1:9191 fd: 19 [2024-10-01 15:56:47][compare][INFO]: Comparison plugins available: Software, File_Coverage, File_Header [2024-10-01 15:56:48][scheduler][INFO]: Analysis scheduler online [2024-10-01 15:56:48][scheduler][INFO]: Analysis plugins available: binwalk 1.0.0, cpu_architecture 0.4.0, crypto_hints 0.2.1, crypto_material 0.5.2, cve_lookup 0.1.0, cwe_checker 0.5.4, device_tree 2.0.0, elf_analysis 0.3.4, exploit_mitigations 0.2.0, file_hashes 1.2, file_system_metadata 1.0.0, file_type 1.0.0, hardware_analysis 0.2, hashlookup 0.1.4, information_leaks 0.2.0, init_systems 0.4.2, input_vectors 0.1.2, interesting_uris 0.1, ip_and_uri_finder 0.4.2, ipc_analyzer 0.1.1, kernel_config 0.3.1, known_vulnerabilities 0.2.1, printable_strings 0.3.4, qemu_exec 0.5.2, software_components 0.4.2, source_code_analysis 0.7.1, string_evaluator 0.2.1, tlsh 0.2, users_and_passwords 0.5.4 [2024-10-01 15:56:48][unpacking_scheduler][INFO]: Unpacking scheduler online [2024-10-01 15:56:48][unpacking_scheduler][INFO]: Queue Length (Analysis/Unpack): 0 / 0 [2024-10-01 15:56:48][comparison_scheduler][INFO]: Comparison scheduler online [2024-10-01 15:56:48][back_end_binding][INFO]: Intercom online [2024-10-01 15:56:48][fact_base][INFO]: Successfully started FACT Backend [2024-10-01 15:56:51][fact_base][INFO]: System memory usage: 21.3%; open file count: 6 [2024-10-01 15:56:52][fact_base][INFO]: System memory usage: 21.3%; open file count: 7 [2024-10-01 15:56:53][fact_base][INFO]: System memory usage: 21.3%; open file count: 542

And here is the docker output you want : oguzhanozgur@oguzhanozgur:~$ docker image ls | grep -i fact_extractor fkiecad/fact_extractor latest d128d1a4c51c 12 days ago 2.26GB

Also, there is an error about the command you provided. oguzhanozgur@oguzhanozgur:~/FACT_core$ docker ps | grep fact_extractor | cut --delimiter " " --fields 1 | xargs docker stop "docker stop" requires at least 1 argument. See 'docker stop --help'.

Usage: docker stop [OPTIONS] CONTAINER [CONTAINER...]

Stop one or more running containers

[jstucke]

There is no log entry that suggest an extractor container was started. Did you change anything in the configuration file (src/config/fact-core-config.toml by default)? What happens if you try to start the extractor container manually with docker run -it --rm --entrypoint bash fkiecad/fact_extractor:latest (it should normally give you a shell which you can exit with Ctrl+D)?

Also, there is an error about the command you provided. oguzhanozgur@oguzhanozgur:~/FACT_core$ docker ps | grep fact_extractor | cut --delimiter " " --fields 1 | xargs docker stop "docker stop" requires at least 1 argument.

That is actually good, since it means there are no orphaned extractor containers running. It does not explain what the problem is, though.

[oguzhanozgur]

I didnt change anything in the conf flies. When i try to execute your command: What should i do now?

[jstucke]

I'm still not sure what the underlying problem is. Everything looks fine apart from the extraction containers not starting in the unpacking scheduler. Could you try running the scheduler tests?

pytest src/test/integration/scheduler

Also could you try starting only the backend with ./start_fact_backend.py from the src directory and after it has started check the output of docker ps?

Normally the extractor containers should show up in the output, e.g.

CONTAINER ID   IMAGE                                   COMMAND                   CREATED         STATUS                 PORTS                                                 NAMES
734b1efc61aa   fkiecad/fact_extractor                  "gunicorn --timeout …"    2 seconds ago   Up 2 seconds           0.0.0.0:9903->5000/tcp, [::]:9903->5000/tcp           relaxed_clarke
c3d3017ec49a   fkiecad/fact_extractor                  "gunicorn --timeout …"    3 seconds ago   Up 2 seconds           0.0.0.0:9902->5000/tcp, [::]:9902->5000/tcp           nice_leakey
fcf139c31a01   fkiecad/fact_extractor                  "gunicorn --timeout …"    3 seconds ago   Up 3 seconds           0.0.0.0:9901->5000/tcp, [::]:9901->5000/tcp           goofy_chaplygin
74760d59043d   fkiecad/fact_extractor                  "gunicorn --timeout …"    4 seconds ago   Up 3 seconds           0.0.0.0:9900->5000/tcp, [::]:9900->5000/tcp           adoring_turing

[oguzhanozgur]

Here is the all results :

oguzhanozgur@oguzhanozgur:~/FACT_core/src$ ls
alembic.ini          compile_yara_signatures.py  flask_app_wrapper.py  intercom                     plugins                 start_fact_frontend.py  unpacker
analysis             config                      helperFunctions       manage_users.py              __pycache__             start_fact.py           update_statistic.py
bin                  config.py                   init_postgres.py      migrate_database.py          scheduler               statistic               version.py
check_signatures.py  conftest.py                 install               migrate_db_to_postgresql.py  start_fact_backend.py   storage                 web_interface
compare              fact_base.py                install.py            objects                      start_fact_database.py  test
oguzhanozgur@oguzhanozgur:~/FACT_core/src$ ./start_fact_backend.py 
Traceback (most recent call last):
  File "/home/oguzhanozgur/FACT_core/src/./start_fact_backend.py", line 35, in <module>
    from intercom.back_end_binding import InterComBackEndBinding
  File "/home/oguzhanozgur/FACT_core/src/intercom/back_end_binding.py", line 15, in <module>
    from storage.binary_service import BinaryService
  File "/home/oguzhanozgur/FACT_core/src/storage/binary_service.py", line 11, in <module>
    from unpacker.tar_repack import TarRepack
  File "/home/oguzhanozgur/FACT_core/src/unpacker/tar_repack.py", line 11, in <module>
    from unpacker.unpack_base import UnpackBase
  File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack_base.py", line 11, in <module>
    from docker.types import Mount
ModuleNotFoundError: No module named 'docker'
oguzhanozgur@oguzhanozgur:~/FACT_core/src$ docker ps
CONTAINER ID   IMAGE     COMMAND   CREATED   STATUS    PORTS     NAMES
oguzhanozgur@oguzhanozgur:~/FACT_core/src$ pytest src/test/integration/scheduler
/usr/local/lib/python3.10/dist-packages/_pytest/config/__init__.py:329: PluggyTeardownRaisedWarning: A plugin raised an exception during an old-style hookwrapper teardown.
Plugin: helpconfig, Hook: pytest_cmdline_parse
ConftestImportFailure: ModuleNotFoundError: No module named 'semver' (from /home/oguzhanozgur/FACT_core/src/conftest.py)
For more information see https://pluggy.readthedocs.io/en/stable/api_reference.html#pluggy.PluggyTeardownRaisedWarning
  config = pluginmanager.hook.pytest_cmdline_parse(
ImportError while loading conftest '/home/oguzhanozgur/FACT_core/src/conftest.py'.
conftest.py:15: in <module>
    from analysis.plugin import AnalysisPluginV0
analysis/plugin/__init__.py:1: in <module>
    from .plugin import AnalysisPluginV0, Tag  # noqa: F401
analysis/plugin/plugin.py:8: in <module>
    import semver
E   ModuleNotFoundError: No module named 'semver'
oguzhanozgur@oguzhanozgur:~/FACT_core/src$ 

[jstucke]

Did you maybe forget to activate your virtualenv? There are some import errors:

ModuleNotFoundError: No module named 'docker'

ModuleNotFoundError: No module named 'semver'

[oguzhanozgur]

Yes, i forgot :( I tried again and here is the result :

1. When I try to start backend only :

``` (ozzy) oguzhanozgur@oguzhanozgur:~/FACT_core/src$ ./start_fact_backend.py [2024-10-01 17:46:31][fact_base][INFO]: Starting FACT Backend @ 4.3-dev (d96db1d1, Python 3.10.12) [2024-10-01 17:46:31][__init__][INFO]: Alembic DB revision: head: 05d8effce8b3, current: 05d8effce8b3 [2024-10-01 17:46:32][ip_and_uri_finder_analysis][INFO]: ip signature path: /home/oguzhanozgur/ozzy/lib/python3.10/site-packages/common_analysis_ip_and_uri_finder/yara_rules/ip_rules.yara [2024-10-01 17:46:32][ip_and_uri_finder_analysis][INFO]: ip signature path: /home/oguzhanozgur/ozzy/lib/python3.10/site-packages/common_analysis_ip_and_uri_finder/yara_rules/uri_rules.yara [2024-10-01 17:46:32][compare][INFO]: Comparison plugins available: Software, File_Coverage, File_Header [2024-10-01 17:46:32][scheduler][INFO]: Analysis scheduler online [2024-10-01 17:46:32][scheduler][INFO]: Analysis plugins available: binwalk 1.0.0, cpu_architecture 0.4.0, crypto_hints 0.2.1, crypto_material 0.5.2, cve_lookup 0.1.0, cwe_checker 0.5.4, device_tree 2.0.0, elf_analysis 0.3.4, exploit_mitigations 0.2.0, file_hashes 1.2, file_system_metadata 1.0.0, file_type 1.0.0, hardware_analysis 0.2, hashlookup 0.1.4, information_leaks 0.2.0, init_systems 0.4.2, input_vectors 0.1.2, interesting_uris 0.1, ip_and_uri_finder 0.4.2, ipc_analyzer 0.1.1, kernel_config 0.3.1, known_vulnerabilities 0.2.1, printable_strings 0.3.4, qemu_exec 0.5.2, software_components 0.4.2, source_code_analysis 0.7.1, string_evaluator 0.2.1, tlsh 0.2, users_and_passwords 0.5.4 [2024-10-01 17:46:32][unpacking_scheduler][INFO]: Unpacking scheduler online [2024-10-01 17:46:32][unpacking_scheduler][INFO]: Queue Length (Analysis/Unpack): 0 / 0 [2024-10-01 17:46:32][comparison_scheduler][INFO]: Comparison scheduler online [2024-10-01 17:46:32][back_end_binding][INFO]: Intercom online [2024-10-01 17:46:32][fact_base][INFO]: Successfully started FACT Backend [2024-10-01 17:46:37][fact_base][INFO]: System memory usage: 19.2%; open file count: 542 [2024-10-01 17:47:24][unpacking_scheduler][INFO]: Queue Length (Analysis/Unpack): 0 / 0 ```

3. This is the docker ps result :

   (ozzy) oguzhanozgur@oguzhanozgur:~$ docker ps
   CONTAINER ID   IMAGE     COMMAND   CREATED   STATUS    PORTS     NAMES

4. And lastly, this is the pytest result :

``` (ozzy) oguzhanozgur@oguzhanozgur:~/FACT_core$ pytest src/test/integration/scheduler ============================= test session starts ============================== platform linux -- Python 3.10.12, pytest-7.2.0, pluggy-1.5.0 -- /home/oguzhanozgur/ozzy/bin/python3 cachedir: .pytest_cache rootdir: /home/oguzhanozgur/FACT_core, configfile: pyproject.toml plugins: cov-4.0.0, timeout-2.1.0, flaky-3.7.0 collected 6 items src/test/integration/scheduler/test_cycle_with_tags.py::TestTagPropagation::test_run_analysis_with_tag FAILED [ 16%] src/test/integration/scheduler/test_regression_virtual_file_path.py::test_check_collision FAILED [ 33%] src/test/integration/scheduler/test_regression_virtual_file_path.py::test_unpacking_skip FAILED [ 50%] src/test/integration/scheduler/test_unpack_analyse_and_compare.py::TestFileAddition::test_unpack_analyse_and_compare FAILED [ 66%] src/test/integration/scheduler/test_unpack_and_analyse.py::TestFileAddition::test_unpack_and_analyse ERROR [ 83%] src/test/integration/scheduler/test_unpack_and_analyse.py::TestFileAddition::test_unpack_and_analyse ERROR [ 83%] src/test/integration/scheduler/test_unpack_only.py::TestFileAddition::test_unpack_only ERROR [100%] ==================================== ERRORS ==================================== __________ ERROR at setup of TestFileAddition.test_unpack_and_analyse __________ request = > pre_analysis_queue = post_analysis_queue = analysis_finished_event = analysis_finished_counter = _unpacking_lock_manager = test_config = SchedulerTestConfig(backend_db_class=, comparison_db_class=, pipeline=True, start_processes=True, items_to_analyze=0, items_to_unpack=0) monkeypatch = <_pytest.monkeypatch.MonkeyPatch object at 0x7b4e22318af0> > ??? src/test/conftest.py:325: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ src/scheduler/analysis/scheduler.py:111: in __init__ self._load_plugins() src/scheduler/analysis/scheduler.py:250: in _load_plugins runner = PluginRunner(plugin, runner_config, schemata) src/scheduler/analysis/plugin.py:66: in __init__ ??? /usr/lib/python3.10/multiprocessing/context.py:103: in Queue return Queue(maxsize, ctx=self.get_context()) /usr/lib/python3.10/multiprocessing/queues.py:42: in __init__ self._reader, self._writer = connection.Pipe(duplex=False) _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ duplex = False def Pipe(duplex=True): ''' Returns pair of connection objects at either end of a pipe ''' if duplex: s1, s2 = socket.socketpair() s1.setblocking(True) s2.setblocking(True) c1 = Connection(s1.detach()) c2 = Connection(s2.detach()) else: > fd1, fd2 = os.pipe() E OSError: [Errno 24] Too many open files /usr/lib/python3.10/multiprocessing/connection.py:527: OSError ------------------------------ Captured log setup ------------------------------ ERROR root:scheduler.py:235 Could not import analysis plugin elf_analysis Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/scheduler/analysis/scheduler.py", line 232, in _load_plugins self.analysis_plugins[PluginClass.NAME] = PluginClass() File "/home/oguzhanozgur/FACT_core/src/analysis/PluginBase.py", line 90, in __init__ self.manager = Manager() File "/usr/lib/python3.10/multiprocessing/context.py", line 57, in Manager m.start() File "/usr/lib/python3.10/multiprocessing/managers.py", line 552, in start reader, writer = connection.Pipe(duplex=False) File "/usr/lib/python3.10/multiprocessing/connection.py", line 527, in Pipe fd1, fd2 = os.pipe() OSError: [Errno 24] Too many open files ERROR root:scheduler.py:235 Could not import analysis plugin file_hashes Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/scheduler/analysis/scheduler.py", line 232, in _load_plugins self.analysis_plugins[PluginClass.NAME] = PluginClass() File "/home/oguzhanozgur/FACT_core/src/analysis/PluginBase.py", line 84, in __init__ self.in_queue = Queue() File "/usr/lib/python3.10/multiprocessing/context.py", line 103, in Queue return Queue(maxsize, ctx=self.get_context()) File "/usr/lib/python3.10/multiprocessing/queues.py", line 42, in __init__ self._reader, self._writer = connection.Pipe(duplex=False) File "/usr/lib/python3.10/multiprocessing/connection.py", line 527, in Pipe fd1, fd2 = os.pipe() OSError: [Errno 24] Too many open files ________ ERROR at teardown of TestFileAddition.test_unpack_and_analyse _________ @pytest.fixture def _firmware_file_storage_directory() -> str: # noqa: PT005 > with TemporaryDirectory(prefix='fact-firmware-file-storage-directory') as tmp_dir: src/conftest.py:33: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ /usr/lib/python3.10/tempfile.py:1017: in __exit__ self.cleanup() /usr/lib/python3.10/tempfile.py:1021: in cleanup self._rmtree(self.name, ignore_errors=self._ignore_cleanup_errors) /usr/lib/python3.10/tempfile.py:1003: in _rmtree _rmtree(name, onerror=onerror) /usr/lib/python3.10/shutil.py:725: in rmtree _rmtree_safe_fd(fd, path, onerror) /usr/lib/python3.10/shutil.py:633: in _rmtree_safe_fd onerror(os.scandir, path, sys.exc_info()) _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ topfd = 1023, path = '/tmp/fact-firmware-file-storage-directoryuh0vvob5' onerror = .onerror at 0x7b4e2231f640> def _rmtree_safe_fd(topfd, path, onerror): try: > with os.scandir(topfd) as scandir_it: E OSError: [Errno 24] Too many open files: '/tmp/fact-firmware-file-storage-directoryuh0vvob5' /usr/lib/python3.10/shutil.py:629: OSError ------------------------------ Captured log setup ------------------------------ ERROR root:scheduler.py:235 Could not import analysis plugin elf_analysis Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/scheduler/analysis/scheduler.py", line 232, in _load_plugins self.analysis_plugins[PluginClass.NAME] = PluginClass() File "/home/oguzhanozgur/FACT_core/src/analysis/PluginBase.py", line 90, in __init__ self.manager = Manager() File "/usr/lib/python3.10/multiprocessing/context.py", line 57, in Manager m.start() File "/usr/lib/python3.10/multiprocessing/managers.py", line 552, in start reader, writer = connection.Pipe(duplex=False) File "/usr/lib/python3.10/multiprocessing/connection.py", line 527, in Pipe fd1, fd2 = os.pipe() OSError: [Errno 24] Too many open files ERROR root:scheduler.py:235 Could not import analysis plugin file_hashes Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/scheduler/analysis/scheduler.py", line 232, in _load_plugins self.analysis_plugins[PluginClass.NAME] = PluginClass() File "/home/oguzhanozgur/FACT_core/src/analysis/PluginBase.py", line 84, in __init__ self.in_queue = Queue() File "/usr/lib/python3.10/multiprocessing/context.py", line 103, in Queue return Queue(maxsize, ctx=self.get_context()) File "/usr/lib/python3.10/multiprocessing/queues.py", line 42, in __init__ self._reader, self._writer = connection.Pipe(duplex=False) File "/usr/lib/python3.10/multiprocessing/connection.py", line 527, in Pipe fd1, fd2 = os.pipe() OSError: [Errno 24] Too many open files _____________ ERROR at setup of TestFileAddition.test_unpack_only ______________ @pytest.fixture def _unpacking_lock_manager() -> UnpackingLockManager: # noqa: PT005 > _manager = UnpackingLockManager() src/test/conftest.py:289: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ src/storage/unpacking_locks.py:8: in __init__ self.manager = Manager() /usr/lib/python3.10/multiprocessing/context.py:57: in Manager m.start() /usr/lib/python3.10/multiprocessing/managers.py:562: in start self._process.start() /usr/lib/python3.10/multiprocessing/process.py:121: in start self._popen = self._Popen(self) /usr/lib/python3.10/multiprocessing/context.py:281: in _Popen return Popen(process_obj) /usr/lib/python3.10/multiprocessing/popen_fork.py:19: in __init__ self._launch(process_obj) _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = process_obj = def _launch(self, process_obj): code = 1 > parent_r, child_w = os.pipe() E OSError: [Errno 24] Too many open files /usr/lib/python3.10/multiprocessing/popen_fork.py:64: OSError =================================== FAILURES =================================== ________________ TestTagPropagation.test_run_analysis_with_tag _________________ self = analysis_finished_event = unpacking_scheduler = backend_db = analysis_scheduler = @pytest.mark.SchedulerTestConfig( # 5 objects * 3 analyses = 15 calls items_to_analyze=15, pipeline=True, ) def test_run_analysis_with_tag(self, analysis_finished_event, unpacking_scheduler, backend_db, analysis_scheduler): test_fw = Firmware(file_path=f'{get_test_data_dir()}/container/with_key.7z') test_fw.version, test_fw.vendor, test_fw.device_name, test_fw.device_class = ['foo'] * 4 test_fw.release_date = '2017-01-01' test_fw.scheduled_analysis = ['crypto_material'] unpacking_scheduler.add_task(test_fw) > assert analysis_finished_event.wait(timeout=20) E assert False E + where False = >(timeout=20) E + where > = .wait src/test/integration/scheduler/test_cycle_with_tags.py:23: AssertionError ----------------------------- Captured stderr call ----------------------------- /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' Process ExceptionSafeProcess-70: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. _____________________________ test_check_collision _____________________________ frontend_db = unpacking_scheduler = unpacking_finished_counter = unpacking_finished_event = @flaky(max_runs=3, min_passes=1) # test may fail when the CI is very busy @pytest.mark.SchedulerTestConfig(items_to_unpack=4) def test_check_collision( frontend_db, unpacking_scheduler, unpacking_finished_counter, unpacking_finished_event, ): add_test_file(unpacking_scheduler, 'regression_one') > assert unpacking_finished_event.wait(timeout=25) E assert False E + where False = >(timeout=25) E + where > = .wait src/test/integration/scheduler/test_regression_virtual_file_path.py:41: AssertionError _____________________________ test_unpacking_skip ______________________________ frontend_db = unpacking_scheduler = unpacking_finished_event = post_unpack_queue = @flaky(max_runs=3, min_passes=1) # test may fail when the CI is very busy @pytest.mark.SchedulerTestConfig(items_to_unpack=4) def test_unpacking_skip( frontend_db, unpacking_scheduler, unpacking_finished_event, post_unpack_queue, ): add_test_file(unpacking_scheduler, 'vfp_test.zip') > assert unpacking_finished_event.wait(timeout=25) E assert False E + where False = >(timeout=25) E + where > = .wait src/test/integration/scheduler/test_regression_virtual_file_path.py:66: AssertionError ----------------------------- Captured stderr call ----------------------------- Process ExceptionSafeProcess-86: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. ----------------------------- Captured stderr call ----------------------------- Process ExceptionSafeProcess-90: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. ----------------------------- Captured stderr call ----------------------------- Process ExceptionSafeProcess-94: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. _______________ TestFileAddition.test_unpack_analyse_and_compare _______________ self = backend_db = unpacking_scheduler = analysis_scheduler = comparison_scheduler = comparison_db = analysis_finished_event = comparison_finished_event = post_analysis_queue = @pytest.mark.SchedulerTestConfig( # 2 container with 3 files each and 2 plugins items_to_analyze=4 * 2 * 2, start_processes=True, pipeline=True, backend_db_class=BackendDbInterface, ) def test_unpack_analyse_and_compare( # noqa: PLR0913 self, backend_db, unpacking_scheduler, analysis_scheduler, comparison_scheduler, comparison_db, analysis_finished_event, comparison_finished_event, post_analysis_queue, ): test_fw_1 = Firmware(file_path=f'{get_test_data_dir()}/container/test.zip') test_fw_2 = Firmware(file_path=f'{get_test_data_dir()}/regression_one') for fw in [test_fw_1, test_fw_2]: fw.version, fw.vendor, fw.device_name, fw.device_class = ['foo'] * 4 fw.release_date = '2017-01-01' unpacking_scheduler.unpacker.file_storage_system.store_file(fw) unpacking_scheduler.add_task(fw) > assert analysis_finished_event.wait(timeout=20) E assert False E + where False = >(timeout=20) E + where > = .wait src/test/integration/scheduler/test_unpack_analyse_and_compare.py:42: AssertionError ----------------------------- Captured stderr call ----------------------------- /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' ===Flaky Test Report=== test_check_collision failed (2 runs remaining out of 3). assert False + where False = >(timeout=25) + where > = .wait [] test_check_collision failed (1 runs remaining out of 3). assert False + where False = >(timeout=25) + where > = .wait [] test_check_collision failed; it passed 0 out of the required 1 times. assert False + where False = >(timeout=25) + where > = .wait [] test_unpacking_skip failed (2 runs remaining out of 3). assert False + where False = >(timeout=25) + where > = .wait [] test_unpacking_skip failed (1 runs remaining out of 3). assert False + where False = >(timeout=25) + where > = .wait [] test_unpacking_skip failed; it passed 0 out of the required 1 times. assert False + where False = >(timeout=25) + where > = .wait [] ===End Flaky Test Report=== =========================== short test summary info ============================ FAILED src/test/integration/scheduler/test_cycle_with_tags.py::TestTagPropagation::test_run_analysis_with_tag - assert False FAILED src/test/integration/scheduler/test_regression_virtual_file_path.py::test_check_collision - assert False FAILED src/test/integration/scheduler/test_regression_virtual_file_path.py::test_unpacking_skip - assert False FAILED src/test/integration/scheduler/test_unpack_analyse_and_compare.py::TestFileAddition::test_unpack_analyse_and_compare - assert False ERROR src/test/integration/scheduler/test_unpack_and_analyse.py::TestFileAddition::test_unpack_and_analyse - OSError: [Errno 24] Too many open files ERROR src/test/integration/scheduler/test_unpack_and_analyse.py::TestFileAddition::test_unpack_and_analyse - OSError: [Errno 24] Too many open files: '/tmp/fact-firmware-file-storage-d... ERROR src/test/integration/scheduler/test_unpack_only.py::TestFileAddition::test_unpack_only - OSError: [Errno 24] Too many open files =================== 4 failed, 3 errors in 209.56s (0:03:29) ==================== (ozzy) oguzhanozgur@oguzhanozgur:~/FACT_core$ ```

[jstucke]

OSError: [Errno 24] Too many open files

This could be the root cause. FACT needs a lot of open files at once. What do you get when you run ulimit -n and ulimit -n -H? This gives you the allowed number of open files (soft limit and hard limit respectively). If this is exceeded, you will get errors. The soft limit should be at least 600. You can raise the soft limit by running e.g. ulimit -n 9999. Raising the hard limit is a lot trickier (see https://askubuntu.com/questions/162229/how-do-i-increase-the-open-files-limit-for-a-non-root-user). The limits count only for your current shell, so you may need to set them for each shell/tab independently (you can also add it to the .bashrc for example). Could you try raising the limit and run the tests again?

[oguzhanozgur]

Hi again, Here is the new result:

``` (ozzy) oguzhanozgur@oguzhanozgur:~/FACT_core$ ulimit -n 1024 (ozzy) oguzhanozgur@oguzhanozgur:~/FACT_core$ ulimit -n -H 1048576 (ozzy) oguzhanozgur@oguzhanozgur:~/FACT_core$ ulimit -n 9999 (ozzy) oguzhanozgur@oguzhanozgur:~/FACT_core$ pytest src/test/integration/scheduler/ ================================================================================= test session starts ================================================================================= platform linux -- Python 3.10.12, pytest-7.2.0, pluggy-1.5.0 -- /home/oguzhanozgur/ozzy/bin/python3 cachedir: .pytest_cache rootdir: /home/oguzhanozgur/FACT_core, configfile: pyproject.toml plugins: cov-4.0.0, timeout-2.1.0, flaky-3.7.0 collected 6 items src/test/integration/scheduler/test_cycle_with_tags.py::TestTagPropagation::test_run_analysis_with_tag FAILED [ 16%] src/test/integration/scheduler/test_regression_virtual_file_path.py::test_check_collision FAILED [ 33%] src/test/integration/scheduler/test_regression_virtual_file_path.py::test_unpacking_skip FAILED [ 50%] src/test/integration/scheduler/test_unpack_analyse_and_compare.py::TestFileAddition::test_unpack_analyse_and_compare FAILED [ 66%] src/test/integration/scheduler/test_unpack_and_analyse.py::TestFileAddition::test_unpack_and_analyse FAILED [ 83%] src/test/integration/scheduler/test_unpack_only.py::TestFileAddition::test_unpack_only FAILED [100%] ====================================================================================== FAILURES ======================================================================================= ____________________________________________________________________ TestTagPropagation.test_run_analysis_with_tag ____________________________________________________________________ self = analysis_finished_event = unpacking_scheduler = backend_db = , analysis_scheduler = @pytest.mark.SchedulerTestConfig( # 5 objects * 3 analyses = 15 calls items_to_analyze=15, pipeline=True, ) def test_run_analysis_with_tag(self, analysis_finished_event, unpacking_scheduler, backend_db, analysis_scheduler): test_fw = Firmware(file_path=f'{get_test_data_dir()}/container/with_key.7z') test_fw.version, test_fw.vendor, test_fw.device_name, test_fw.device_class = ['foo'] * 4 test_fw.release_date = '2017-01-01' test_fw.scheduled_analysis = ['crypto_material'] unpacking_scheduler.add_task(test_fw) > assert analysis_finished_event.wait(timeout=20) E assert False E + where False = >(timeout=20) E + where > = .wait src/test/integration/scheduler/test_cycle_with_tags.py:23: AssertionError -------------------------------------------------------------------------------- Captured stderr call --------------------------------------------------------------------------------- /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' Process ExceptionSafeProcess-70: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. ________________________________________________________________________________ test_check_collision _________________________________________________________________________________ frontend_db = unpacking_scheduler = , unpacking_finished_counter = unpacking_finished_event = @flaky(max_runs=3, min_passes=1) # test may fail when the CI is very busy @pytest.mark.SchedulerTestConfig(items_to_unpack=4) def test_check_collision( frontend_db, unpacking_scheduler, unpacking_finished_counter, unpacking_finished_event, ): add_test_file(unpacking_scheduler, 'regression_one') > assert unpacking_finished_event.wait(timeout=25) E assert False E + where False = >(timeout=25) E + where > = .wait src/test/integration/scheduler/test_regression_virtual_file_path.py:41: AssertionError _________________________________________________________________________________ test_unpacking_skip _________________________________________________________________________________ frontend_db = unpacking_scheduler = unpacking_finished_event = , post_unpack_queue = @flaky(max_runs=3, min_passes=1) # test may fail when the CI is very busy @pytest.mark.SchedulerTestConfig(items_to_unpack=4) def test_unpacking_skip( frontend_db, unpacking_scheduler, unpacking_finished_event, post_unpack_queue, ): add_test_file(unpacking_scheduler, 'vfp_test.zip') > assert unpacking_finished_event.wait(timeout=25) E assert False E + where False = >(timeout=25) E + where > = .wait src/test/integration/scheduler/test_regression_virtual_file_path.py:66: AssertionError -------------------------------------------------------------------------------- Captured stderr call --------------------------------------------------------------------------------- Process ExceptionSafeProcess-86: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. -------------------------------------------------------------------------------- Captured stderr call --------------------------------------------------------------------------------- Process ExceptionSafeProcess-90: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. -------------------------------------------------------------------------------- Captured stderr call --------------------------------------------------------------------------------- Process ExceptionSafeProcess-94: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. __________________________________________________________________ TestFileAddition.test_unpack_analyse_and_compare ___________________________________________________________________ self = backend_db = unpacking_scheduler = analysis_scheduler = comparison_scheduler = comparison_db = analysis_finished_event = , comparison_finished_event = post_analysis_queue = @pytest.mark.SchedulerTestConfig( # 2 container with 3 files each and 2 plugins items_to_analyze=4 * 2 * 2, start_processes=True, pipeline=True, backend_db_class=BackendDbInterface, ) def test_unpack_analyse_and_compare( # noqa: PLR0913 self, backend_db, unpacking_scheduler, analysis_scheduler, comparison_scheduler, comparison_db, analysis_finished_event, comparison_finished_event, post_analysis_queue, ): test_fw_1 = Firmware(file_path=f'{get_test_data_dir()}/container/test.zip') test_fw_2 = Firmware(file_path=f'{get_test_data_dir()}/regression_one') for fw in [test_fw_1, test_fw_2]: fw.version, fw.vendor, fw.device_name, fw.device_class = ['foo'] * 4 fw.release_date = '2017-01-01' unpacking_scheduler.unpacker.file_storage_system.store_file(fw) unpacking_scheduler.add_task(fw) > assert analysis_finished_event.wait(timeout=20) E assert False E + where False = >(timeout=20) E + where > = .wait src/test/integration/scheduler/test_unpack_analyse_and_compare.py:42: AssertionError -------------------------------------------------------------------------------- Captured stderr call --------------------------------------------------------------------------------- /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' ______________________________________________________________________ TestFileAddition.test_unpack_and_analyse _______________________________________________________________________ self = analysis_scheduler = unpacking_scheduler = , post_analysis_queue = @pytest.mark.SchedulerTestConfig( pipeline=True, backend_db_class=MockDbInterface, ) def test_unpack_and_analyse(self, analysis_scheduler, unpacking_scheduler, post_analysis_queue): test_fw = Firmware(file_path=f'{get_test_data_dir()}/container/test.zip') test_fw.release_date = '1970-01-01' unpacking_scheduler.add_task(test_fw) processed_container = {} for _ in range(4 * 2): # container with 3 included files times 2 mandatory plugins run > uid, plugin, analysis_result = post_analysis_queue.get(timeout=3) src/test/integration/scheduler/test_unpack_and_analyse.py:21: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = , block = True, timeout = 2.9999988390009094 def get(self, block=True, timeout=None): if self._closed: raise ValueError(f"Queue {self!r} is closed") if block and timeout is None: with self._rlock: res = self._recv_bytes() self._sem.release() else: if block: deadline = time.monotonic() + timeout if not self._rlock.acquire(block, timeout): raise Empty try: if block: timeout = deadline - time.monotonic() if not self._poll(timeout): > raise Empty E _queue.Empty /usr/lib/python3.10/multiprocessing/queues.py:114: Empty -------------------------------------------------------------------------------- Captured stderr call --------------------------------------------------------------------------------- /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' Process ExceptionSafeProcess-235: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. __________________________________________________________________________ TestFileAddition.test_unpack_only __________________________________________________________________________ self = unpacking_scheduler = , post_unpack_queue = def test_unpack_only(self, unpacking_scheduler, post_unpack_queue): test_fw = Firmware(file_path=f'{get_test_data_dir()}/container/test.zip') unpacking_scheduler.add_task(test_fw) processed_container = post_unpack_queue.get(timeout=5) > assert len(processed_container.files_included) == 3, 'not all included files found' # noqa: PLR2004 E AssertionError: not all included files found E assert 0 == 3 E + where 0 = len(set()) E + where set() = None None v. None\nProcessed Analysis: ['unpacker']\nScheduled Analysis: None.files_included src/test/integration/scheduler/test_unpack_only.py:17: AssertionError ===Flaky Test Report=== test_check_collision failed (2 runs remaining out of 3). assert False + where False = >(timeout=25) + where > = .wait [] test_check_collision failed (1 runs remaining out of 3). assert False + where False = >(timeout=25) + where > = .wait [] test_check_collision failed; it passed 0 out of the required 1 times. assert False + where False = >(timeout=25) + where > = .wait [] test_unpacking_skip failed (2 runs remaining out of 3). assert False + where False = >(timeout=25) + where > = .wait [] test_unpacking_skip failed (1 runs remaining out of 3). assert False + where False = >(timeout=25) + where > = .wait [] test_unpacking_skip failed; it passed 0 out of the required 1 times. assert False + where False = >(timeout=25) + where > = .wait [] ===End Flaky Test Report=== =============================================================================== short test summary info =============================================================================== FAILED src/test/integration/scheduler/test_cycle_with_tags.py::TestTagPropagation::test_run_analysis_with_tag - assert False FAILED src/test/integration/scheduler/test_regression_virtual_file_path.py::test_check_collision - assert False FAILED src/test/integration/scheduler/test_regression_virtual_file_path.py::test_unpacking_skip - assert False FAILED src/test/integration/scheduler/test_unpack_analyse_and_compare.py::TestFileAddition::test_unpack_analyse_and_compare - assert False FAILED src/test/integration/scheduler/test_unpack_and_analyse.py::TestFileAddition::test_unpack_and_analyse - _queue.Empty FAILED src/test/integration/scheduler/test_unpack_only.py::TestFileAddition::test_unpack_only - AssertionError: not all included files found ============================================================================ 6 failed in 217.06s (0:03:37) ============================================================================ (ozzy) oguzhanozgur@oguzhanozgur:~/FACT_core$ ```

[jstucke]

It seems an exception occurred in the extraction container, but we need to activate additional logging to see what it was. Could you try to run this command?

pytest -vvv --log-cli-level=DEBUG -s src/test/integration/scheduler/test_unpack_and_analyse.py

[oguzhanozgur]

``` (ozzy) oguzhanozgur@oguzhanozgur:~/FACT_core$ pytest -vvv --log-cli-level=DEBUG -s src/test/integration/scheduler/test_unpack_and_analyse.py ==================================================================================== test session starts ===================================================================================== platform linux -- Python 3.10.12, pytest-7.2.0, pluggy-1.5.0 -- /home/oguzhanozgur/ozzy/bin/python3 cachedir: .pytest_cache rootdir: /home/oguzhanozgur/FACT_core, configfile: pyproject.toml plugins: cov-4.0.0, timeout-2.1.0, flaky-3.7.0 collected 1 item src/test/integration/scheduler/test_unpack_and_analyse.py::TestFileAddition::test_unpack_and_analyse --------------------------------------------------------------------------------------- live log setup --------------------------------------------------------------------------------------- DEBUG root:unpacking_locks.py:10 Started unpacking locks manager DEBUG root:db_interface_view_sync.py:18 view updated: source_code_analysis DEBUG root:db_interface_view_sync.py:18 view updated: crypto_hints DEBUG root:db_interface_view_sync.py:18 view updated: exploit_mitigations DEBUG root:db_interface_view_sync.py:18 view updated: file_system_metadata DEBUG root:scheduler.py:653 ExamplePlugin: No view available! Generic view will be used. DEBUG root:db_interface_view_sync.py:18 view updated: cpu_architecture DEBUG root:db_interface_view_sync.py:18 view updated: file_type DEBUG root:db_interface_view_sync.py:18 view updated: cve_lookup DEBUG root:db_interface_view_sync.py:18 view updated: information_leaks DEBUG root:base.py:29 hashlookup: No view available! Generic view will be used. DEBUG root:db_interface_view_sync.py:18 view updated: crypto_material DEBUG root:db_interface_view_sync.py:18 view updated: ipc_analyzer DEBUG root:db_interface_view_sync.py:18 view updated: tlsh DEBUG root:db_interface_view_sync.py:18 view updated: known_vulnerabilities DEBUG root:db_interface_view_sync.py:18 view updated: ip_and_uri_finder INFO root:ip_and_uri_finder_analysis.py:154 ip signature path: /home/oguzhanozgur/ozzy/lib/python3.10/site-packages/common_analysis_ip_and_uri_finder/yara_rules/ip_rules.yara INFO root:ip_and_uri_finder_analysis.py:158 ip signature path: /home/oguzhanozgur/ozzy/lib/python3.10/site-packages/common_analysis_ip_and_uri_finder/yara_rules/uri_rules.yara DEBUG root:base.py:29 interesting_uris: No view available! Generic view will be used. DEBUG root:base.py:29 dummy_plugin_for_testing_only: No view available! Generic view will be used. DEBUG root:db_interface_view_sync.py:18 view updated: kernel_config DEBUG root:db_interface_view_sync.py:18 view updated: cwe_checker DEBUG docker.utils.config:config.py:21 Trying paths: ['/home/oguzhanozgur/.docker/config.json', '/home/oguzhanozgur/.dockercfg'] DEBUG docker.utils.config:config.py:28 No config file found DEBUG docker.utils.config:config.py:21 Trying paths: ['/home/oguzhanozgur/.docker/config.json', '/home/oguzhanozgur/.dockercfg'] DEBUG docker.utils.config:config.py:28 No config file found DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "GET /version HTTP/11" 200 778 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/create HTTP/11" 201 88 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "GET /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/json HTTP/11" 200 None DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/start HTTP/11" 204 0 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/wait HTTP/11" 200 None DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "GET /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/logs?stderr=1&stdout=1×tamps=0&follow=0&tail=all HTTP/11" 200 None DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "GET /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/json HTTP/11" 200 None DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/stop HTTP/11" 304 0 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "DELETE /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561?v=False&link=False&force=False HTTP/11" 204 0 DEBUG root:cwe_checker.py:61 Version is cwe_checker 0.9.0 DEBUG root:db_interface_view_sync.py:18 view updated: binwalk DEBUG root:db_interface_view_sync.py:18 view updated: qemu_exec DEBUG root:db_interface_view_sync.py:18 view updated: users_and_passwords DEBUG root:db_interface_view_sync.py:18 view updated: input_vectors DEBUG root:db_interface_view_sync.py:18 view updated: software_components DEBUG root:db_interface_view_sync.py:18 view updated: printable_strings DEBUG root:db_interface_view_sync.py:18 view updated: string_evaluator DEBUG root:db_interface_view_sync.py:18 view updated: init_systems DEBUG root:db_interface_view_sync.py:18 view updated: hardware_analysis DEBUG root:db_interface_view_sync.py:18 view updated: elf_analysis DEBUG root:base.py:29 file_hashes: No view available! Generic view will be used. DEBUG root:db_interface_view_sync.py:18 view updated: device_tree DEBUG root:analysis_status.py:108 starting analysis status worker (pid: 77452) DEBUG root:scheduler.py:326 Started analysis scheduling worker 0 (pid=77454) DEBUG root:scheduler.py:326 Started analysis scheduling worker 1 (pid=77455) DEBUG root:scheduler.py:326 Started analysis scheduling worker 2 (pid=77458) DEBUG root:scheduler.py:326 Started analysis scheduling worker 3 (pid=77460) DEBUG root:scheduler.py:518 Started analysis result collector worker 0 (pid=77462) DEBUG root:PluginBase.py:112 exploit_mitigations: 1 worker threads started DEBUG root:scheduler.py:518 Started analysis result collector worker 1 (pid=77464) DEBUG root:PluginBase.py:251 started exploit_mitigations worker 0 (pid=77466) DEBUG root:PluginBase.py:251 started cpu_architecture worker 0 (pid=77468) DEBUG root:PluginBase.py:251 started cpu_architecture worker 1 (pid=77470) DEBUG root:PluginBase.py:251 started cpu_architecture worker 2 (pid=77472) DEBUG root:PluginBase.py:112 cpu_architecture: 4 worker threads started DEBUG root:PluginBase.py:251 started cpu_architecture worker 3 (pid=77474) DEBUG root:PluginBase.py:251 started cve_lookup worker 0 (pid=77476) DEBUG root:PluginBase.py:112 cve_lookup: 2 worker threads started DEBUG root:PluginBase.py:251 started cve_lookup worker 1 (pid=77478) DEBUG root:PluginBase.py:112 information_leaks: 1 worker threads started DEBUG root:PluginBase.py:251 started information_leaks worker 0 (pid=77480) DEBUG root:PluginBase.py:112 hashlookup: 1 worker threads started DEBUG root:PluginBase.py:251 started hashlookup worker 0 (pid=77482) DEBUG root:PluginBase.py:112 crypto_material: 1 worker threads started DEBUG root:PluginBase.py:251 started crypto_material worker 0 (pid=77484) DEBUG root:PluginBase.py:112 ipc_analyzer: 1 worker threads started DEBUG root:PluginBase.py:251 started ipc_analyzer worker 0 (pid=77486) DEBUG root:PluginBase.py:112 tlsh: 1 worker threads started DEBUG root:PluginBase.py:251 started tlsh worker 0 (pid=77488) DEBUG root:PluginBase.py:112 known_vulnerabilities: 1 worker threads started DEBUG root:PluginBase.py:251 started known_vulnerabilities worker 0 (pid=77490) DEBUG root:PluginBase.py:112 ip_and_uri_finder: 1 worker threads started DEBUG root:PluginBase.py:251 started ip_and_uri_finder worker 0 (pid=77492) DEBUG root:PluginBase.py:112 interesting_uris: 1 worker threads started DEBUG root:PluginBase.py:251 started interesting_uris worker 0 (pid=77494) DEBUG root:PluginBase.py:112 dummy_plugin_for_testing_only: 1 worker threads started DEBUG root:PluginBase.py:251 started dummy_plugin_for_testing_only worker 0 (pid=77496) DEBUG root:PluginBase.py:112 kernel_config: 1 worker threads started DEBUG root:PluginBase.py:251 started kernel_config worker 0 (pid=77498) DEBUG root:PluginBase.py:112 cwe_checker: 1 worker threads started DEBUG root:PluginBase.py:251 started cwe_checker worker 0 (pid=77500) DEBUG root:PluginBase.py:112 qemu_exec: 1 worker threads started DEBUG root:PluginBase.py:251 started qemu_exec worker 0 (pid=77502) DEBUG root:PluginBase.py:112 users_and_passwords: 1 worker threads started DEBUG root:PluginBase.py:251 started users_and_passwords worker 0 (pid=77504) DEBUG root:PluginBase.py:112 input_vectors: 1 worker threads started DEBUG root:PluginBase.py:251 started input_vectors worker 0 (pid=77506) DEBUG root:PluginBase.py:112 software_components: 1 worker threads started DEBUG root:PluginBase.py:251 started software_components worker 0 (pid=77508) DEBUG root:PluginBase.py:112 printable_strings: 1 worker threads started DEBUG root:PluginBase.py:251 started printable_strings worker 0 (pid=77510) DEBUG root:PluginBase.py:112 string_evaluator: 1 worker threads started DEBUG root:PluginBase.py:251 started string_evaluator worker 0 (pid=77512) DEBUG root:PluginBase.py:112 init_systems: 1 worker threads started DEBUG root:PluginBase.py:251 started init_systems worker 0 (pid=77514) DEBUG root:PluginBase.py:112 hardware_analysis: 1 worker threads started DEBUG root:PluginBase.py:251 started hardware_analysis worker 0 (pid=77516) DEBUG root:PluginBase.py:112 elf_analysis: 1 worker threads started DEBUG root:PluginBase.py:251 started elf_analysis worker 0 (pid=77518) DEBUG root:PluginBase.py:112 file_hashes: 1 worker threads started DEBUG root:PluginBase.py:251 started file_hashes worker 0 (pid=77520) INFO root:scheduler.py:131 Analysis scheduler online INFO root:scheduler.py:132 Analysis plugins available: binwalk 1.0.0, cpu_architecture 0.4.0, crypto_hints 0.2.1, crypto_material 0.5.2, cve_lookup 0.1.0, cwe_checker 0.5.4, device_tree 2.0.0, dummy_plugin_for_testing_only 0.0, elf_analysis 0.3.4, ExamplePlugin 0.0.0, exploit_mitigations 0.2.0, file_hashes 1.2, file_system_metadata 1.0.0, file_type 1.0.0, hardware_analysis 0.2, hashlookup 0.1.4, information_leaks 0.2.0, init_systems 0.4.2, input_vectors 0.1.2, interesting_uris 0.1, ip_and_uri_finder 0.4.2, ipc_analyzer 0.1.1, kernel_config 0.3.1, known_vulnerabilities 0.2.1, printable_strings 0.3.4, qemu_exec 0.5.2, software_components 0.4.2, source_code_analysis 0.7.1, string_evaluator 0.2.1, tlsh 0.2, users_and_passwords 0.5.4 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/create HTTP/11" 400 139 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/create HTTP/11" 400 139 INFO root:unpacking_scheduler.py:90 Unpacking scheduler online DEBUG root:unpacking_scheduler.py:294 Started unpacking work load monitor (pid=77557) INFO root:unpacking_scheduler.py:314 Queue Length (Analysis/Unpack): 0 / 0 DEBUG root:unpacking_scheduler.py:147 Starting unpacking scheduler loop (pid=77561) DEBUG root:unpacking_scheduler.py:158 Started Worker on 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787 () DEBUG urllib3.connectionpool:connectionpool.py:243 Starting new HTTP connection (1): localhost:9900 DEBUG urllib3.util.retry:retry.py:521 Incremented Retry for (url='/status'): Retry(total=2, connect=None, read=None, redirect=None, status=None) WARNING urllib3.connectionpool:connectionpool.py:870 Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError(': Failed to establish a new connection: [Errno 111] Connection refused')': /status DEBUG urllib3.connectionpool:connectionpool.py:243 Starting new HTTP connection (2): localhost:9900 DEBUG urllib3.util.retry:retry.py:521 Incremented Retry for (url='/status'): Retry(total=1, connect=None, read=None, redirect=None, status=None) WARNING urllib3.connectionpool:connectionpool.py:870 Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError(': Failed to establish a new connection: [Errno 111] Connection refused')': /status DEBUG urllib3.connectionpool:connectionpool.py:243 Starting new HTTP connection (3): localhost:9900 DEBUG urllib3.util.retry:retry.py:521 Incremented Retry for (url='/status'): Retry(total=0, connect=None, read=None, redirect=None, status=None) WARNING urllib3.connectionpool:connectionpool.py:870 Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError(': Failed to establish a new connection: [Errno 111] Connection refused')': /status DEBUG urllib3.connectionpool:connectionpool.py:243 Starting new HTTP connection (4): localhost:9900 ERROR root:unpacking_scheduler.py:273 Could not fetch unpacking container logs ERROR root:unpacking_scheduler.py:202 Exception happened during extraction of 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787.: Extraction container could not be reached. Traceback (most recent call last): File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connection.py", line 199, in _new_conn sock = connection.create_connection( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/util/connection.py", line 85, in create_connection raise err File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/util/connection.py", line 73, in create_connection sock.connect(sa) ConnectionRefusedError: [Errno 111] Connection refused The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 789, in urlopen response = self._make_request( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 495, in _make_request conn.request( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connection.py", line 441, in request self.endheaders() File "/usr/lib/python3.10/http/client.py", line 1278, in endheaders self._send_output(message_body, encode_chunked=encode_chunked) File "/usr/lib/python3.10/http/client.py", line 1038, in _send_output self.send(msg) File "/usr/lib/python3.10/http/client.py", line 976, in send self.connect() File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connection.py", line 279, in connect self.sock = self._new_conn() File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connection.py", line 214, in _new_conn raise NewConnectionError( urllib3.exceptions.NewConnectionError: : Failed to establish a new connection: [Errno 111] Connection refused The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/requests/adapters.py", line 589, in send resp = conn.urlopen( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 873, in urlopen return self.urlopen( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 873, in urlopen return self.urlopen( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 873, in urlopen return self.urlopen( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connectionpool.py", line 843, in urlopen retries = retries.increment( File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/util/retry.py", line 519, in increment raise MaxRetryError(_pool, url, reason) from reason # type: ignore[arg-type] urllib3.exceptions.MaxRetryError: HTTPConnectionPool(host='localhost', port=9900): Max retries exceeded with url: /status (Caused by NewConnectionError(': Failed to establish a new connection: [Errno 111] Connection refused')) During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack_base.py", line 55, in _extract_with_worker response = container.start_unpacking(tmp_dir, timeout=WORKER_TIMEOUT) File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 118, in start_unpacking response = self._check_connection() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 133, in _check_connection return session.get(url, timeout=5) File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/requests/sessions.py", line 602, in get return self.request("GET", url, **kwargs) File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/requests/sessions.py", line 589, in request resp = self.send(prep, **send_kwargs) File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/requests/sessions.py", line 703, in send r = adapter.send(request, **kwargs) File "/home/oguzhanozgur/ozzy/lib/python3.10/site-packages/requests/adapters.py", line 622, in send raise ConnectionError(e, request=request) requests.exceptions.ConnectionError: HTTPConnectionPool(host='localhost', port=9900): Max retries exceeded with url: /status (Caused by NewConnectionError(': Failed to establish a new connection: [Errno 111] Connection refused')) The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 199, in work_thread extracted_objects = self.unpacker.unpack(task, tmp_dir, container) File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack.py", line 42, in unpack extracted_files = self.extract_files_from_file(current_fo.file_path, tmp_dir, container) File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack_base.py", line 41, in extract_files_from_file self._extract_with_worker(file_path, container, tmp_dir) File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack_base.py", line 59, in _extract_with_worker raise ExtractionError('Extraction container could not be reached.') from error unpacker.unpack_base.ExtractionError: Extraction container could not be reached. INFO root:unpacking_scheduler.py:208 Unpacking completed: 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787 (extracted files: 0) DEBUG root:analysis_status.py:116 updating status (queue: 0) INFO root:unpacking_scheduler.py:241 Unpacking of firmware 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787 completed. DEBUG root:plugin.py:120 Queueing analysis for 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787 DEBUG root:plugin.py:218 : Beginning file_type analysis on 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787 /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' DEBUG root:plugin.py:238 : Finished file_type analysis on 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787 DEBUG root:PluginBase.py:255 Worker 0: Begin file_hashes analysis on 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787 DEBUG root:PluginBase.py:224 Worker 0: Finished file_hashes analysis on 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787 INFO root:scheduler.py:549 Analysis Completed: 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787 INFO root:analysis_status.py:193 Analysis of firmware 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787 completed Process ExceptionSafeProcess-70: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. DEBUG root:unpacking_scheduler.py:314 Queue Length (Analysis/Unpack): 0 / 0 FAILED ------------------------------------------------------------------------------------- live log teardown -------------------------------------------------------------------------------------- DEBUG root:unpacking_scheduler.py:101 Shutting down unpacking scheduler DEBUG root:unpacking_scheduler.py:316 Stopped unpacking work load monitor INFO root:unpacking_scheduler.py:112 Unpacking scheduler offline DEBUG root:scheduler.py:139 Shutting down analysis scheduler DEBUG root:scheduler.py:334 Stopped analysis scheduling worker 0 DEBUG root:scheduler.py:334 Stopped analysis scheduling worker 1 DEBUG root:scheduler.py:334 Stopped analysis scheduling worker 3 DEBUG root:scheduler.py:334 Stopped analysis scheduling worker 2 INFO root:plugin.py:188 received SIGTERM. Shutting down. INFO root:plugin.py:188 received SIGTERM. Shutting down. INFO root:plugin.py:188 received SIGTERM. Shutting down. INFO root:plugin.py:188 received SIGTERM. Shutting down. INFO root:plugin.py:188 received SIGTERM. Shutting down. INFO root:plugin.py:188 received SIGTERM. Shutting down. INFO root:plugin.py:188 received SIGTERM. Shutting down. DEBUG root:scheduler.py:537 Stopped analysis result collector worker 1 DEBUG root:scheduler.py:537 Stopped analysis result collector worker 0 DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:263 worker 1 stopped DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:263 worker 2 stopped DEBUG root:PluginBase.py:263 worker 3 stopped DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 1 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:PluginBase.py:263 worker 0 stopped DEBUG root:analysis_status.py:116 updating status (queue: 0) DEBUG root:analysis_status.py:120 stopped analysis status worker INFO root:scheduler.py:162 Analysis scheduler offline ========================================================================================== FAILURES ========================================================================================== __________________________________________________________________________ TestFileAddition.test_unpack_and_analyse __________________________________________________________________________ self = analysis_scheduler = unpacking_scheduler = , post_analysis_queue = @pytest.mark.SchedulerTestConfig( pipeline=True, backend_db_class=MockDbInterface, ) def test_unpack_and_analyse(self, analysis_scheduler, unpacking_scheduler, post_analysis_queue): test_fw = Firmware(file_path=f'{get_test_data_dir()}/container/test.zip') test_fw.release_date = '1970-01-01' unpacking_scheduler.add_task(test_fw) processed_container = {} for _ in range(4 * 2): # container with 3 included files times 2 mandatory plugins run > uid, plugin, analysis_result = post_analysis_queue.get(timeout=3) src/test/integration/scheduler/test_unpack_and_analyse.py:21: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ self = , block = True, timeout = 2.999998934999894 def get(self, block=True, timeout=None): if self._closed: raise ValueError(f"Queue {self!r} is closed") if block and timeout is None: with self._rlock: res = self._recv_bytes() self._sem.release() else: if block: deadline = time.monotonic() + timeout if not self._rlock.acquire(block, timeout): raise Empty try: if block: timeout = deadline - time.monotonic() if not self._poll(timeout): > raise Empty E _queue.Empty /usr/lib/python3.10/multiprocessing/queues.py:114: Empty ------------------------------------------------------------------------------------- Captured log setup ------------------------------------------------------------------------------------- DEBUG root:unpacking_locks.py:10 Started unpacking locks manager DEBUG root:db_interface_view_sync.py:18 view updated: source_code_analysis DEBUG root:db_interface_view_sync.py:18 view updated: crypto_hints DEBUG root:db_interface_view_sync.py:18 view updated: exploit_mitigations DEBUG root:db_interface_view_sync.py:18 view updated: file_system_metadata DEBUG root:scheduler.py:653 ExamplePlugin: No view available! Generic view will be used. DEBUG root:db_interface_view_sync.py:18 view updated: cpu_architecture DEBUG root:db_interface_view_sync.py:18 view updated: file_type DEBUG root:db_interface_view_sync.py:18 view updated: cve_lookup DEBUG root:db_interface_view_sync.py:18 view updated: information_leaks DEBUG root:base.py:29 hashlookup: No view available! Generic view will be used. DEBUG root:db_interface_view_sync.py:18 view updated: crypto_material DEBUG root:db_interface_view_sync.py:18 view updated: ipc_analyzer DEBUG root:db_interface_view_sync.py:18 view updated: tlsh DEBUG root:db_interface_view_sync.py:18 view updated: known_vulnerabilities DEBUG root:db_interface_view_sync.py:18 view updated: ip_and_uri_finder INFO root:ip_and_uri_finder_analysis.py:154 ip signature path: /home/oguzhanozgur/ozzy/lib/python3.10/site-packages/common_analysis_ip_and_uri_finder/yara_rules/ip_rules.yara INFO root:ip_and_uri_finder_analysis.py:158 ip signature path: /home/oguzhanozgur/ozzy/lib/python3.10/site-packages/common_analysis_ip_and_uri_finder/yara_rules/uri_rules.yara DEBUG root:base.py:29 interesting_uris: No view available! Generic view will be used. DEBUG root:base.py:29 dummy_plugin_for_testing_only: No view available! Generic view will be used. DEBUG root:db_interface_view_sync.py:18 view updated: kernel_config DEBUG root:db_interface_view_sync.py:18 view updated: cwe_checker DEBUG docker.utils.config:config.py:21 Trying paths: ['/home/oguzhanozgur/.docker/config.json', '/home/oguzhanozgur/.dockercfg'] DEBUG docker.utils.config:config.py:28 No config file found DEBUG docker.utils.config:config.py:21 Trying paths: ['/home/oguzhanozgur/.docker/config.json', '/home/oguzhanozgur/.dockercfg'] DEBUG docker.utils.config:config.py:28 No config file found DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "GET /version HTTP/11" 200 778 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/create HTTP/11" 201 88 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "GET /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/json HTTP/11" 200 None DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/start HTTP/11" 204 0 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/wait HTTP/11" 200 None DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "GET /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/logs?stderr=1&stdout=1×tamps=0&follow=0&tail=all HTTP/11" 200 None DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "GET /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/json HTTP/11" 200 None DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561/stop HTTP/11" 304 0 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "DELETE /v1.43/containers/e9ebd6a407f81788d3174bf03880b498c682d018b3a5086cab970ba889671561?v=False&link=False&force=False HTTP/11" 204 0 DEBUG root:cwe_checker.py:61 Version is cwe_checker 0.9.0 DEBUG root:db_interface_view_sync.py:18 view updated: binwalk DEBUG root:db_interface_view_sync.py:18 view updated: qemu_exec DEBUG root:db_interface_view_sync.py:18 view updated: users_and_passwords DEBUG root:db_interface_view_sync.py:18 view updated: input_vectors DEBUG root:db_interface_view_sync.py:18 view updated: software_components DEBUG root:db_interface_view_sync.py:18 view updated: printable_strings DEBUG root:db_interface_view_sync.py:18 view updated: string_evaluator DEBUG root:db_interface_view_sync.py:18 view updated: init_systems DEBUG root:db_interface_view_sync.py:18 view updated: hardware_analysis DEBUG root:db_interface_view_sync.py:18 view updated: elf_analysis DEBUG root:base.py:29 file_hashes: No view available! Generic view will be used. DEBUG root:db_interface_view_sync.py:18 view updated: device_tree DEBUG root:PluginBase.py:112 exploit_mitigations: 1 worker threads started DEBUG root:PluginBase.py:112 cpu_architecture: 4 worker threads started DEBUG root:PluginBase.py:112 cve_lookup: 2 worker threads started DEBUG root:PluginBase.py:112 information_leaks: 1 worker threads started DEBUG root:PluginBase.py:112 hashlookup: 1 worker threads started DEBUG root:PluginBase.py:112 crypto_material: 1 worker threads started DEBUG root:PluginBase.py:112 ipc_analyzer: 1 worker threads started DEBUG root:PluginBase.py:112 tlsh: 1 worker threads started DEBUG root:PluginBase.py:112 known_vulnerabilities: 1 worker threads started DEBUG root:PluginBase.py:112 ip_and_uri_finder: 1 worker threads started DEBUG root:PluginBase.py:112 interesting_uris: 1 worker threads started DEBUG root:PluginBase.py:112 dummy_plugin_for_testing_only: 1 worker threads started DEBUG root:PluginBase.py:112 kernel_config: 1 worker threads started DEBUG root:PluginBase.py:112 cwe_checker: 1 worker threads started DEBUG root:PluginBase.py:112 qemu_exec: 1 worker threads started DEBUG root:PluginBase.py:112 users_and_passwords: 1 worker threads started DEBUG root:PluginBase.py:112 input_vectors: 1 worker threads started DEBUG root:PluginBase.py:112 software_components: 1 worker threads started DEBUG root:PluginBase.py:112 printable_strings: 1 worker threads started DEBUG root:PluginBase.py:112 string_evaluator: 1 worker threads started DEBUG root:PluginBase.py:112 init_systems: 1 worker threads started DEBUG root:PluginBase.py:112 hardware_analysis: 1 worker threads started DEBUG root:PluginBase.py:112 elf_analysis: 1 worker threads started DEBUG root:PluginBase.py:112 file_hashes: 1 worker threads started INFO root:scheduler.py:131 Analysis scheduler online INFO root:scheduler.py:132 Analysis plugins available: binwalk 1.0.0, cpu_architecture 0.4.0, crypto_hints 0.2.1, crypto_material 0.5.2, cve_lookup 0.1.0, cwe_checker 0.5.4, device_tree 2.0.0, dummy_plugin_for_testing_only 0.0, elf_analysis 0.3.4, ExamplePlugin 0.0.0, exploit_mitigations 0.2.0, file_hashes 1.2, file_system_metadata 1.0.0, file_type 1.0.0, hardware_analysis 0.2, hashlookup 0.1.4, information_leaks 0.2.0, init_systems 0.4.2, input_vectors 0.1.2, interesting_uris 0.1, ip_and_uri_finder 0.4.2, ipc_analyzer 0.1.1, kernel_config 0.3.1, known_vulnerabilities 0.2.1, printable_strings 0.3.4, qemu_exec 0.5.2, software_components 0.4.2, source_code_analysis 0.7.1, string_evaluator 0.2.1, tlsh 0.2, users_and_passwords 0.5.4 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/create HTTP/11" 400 139 DEBUG urllib3.connectionpool:connectionpool.py:546 http://localhost:None "POST /v1.43/containers/create HTTP/11" 400 139 INFO root:unpacking_scheduler.py:90 Unpacking scheduler online ----------------------------------------------------------------------------------- Captured log teardown ------------------------------------------------------------------------------------ DEBUG root:unpacking_scheduler.py:101 Shutting down unpacking scheduler INFO root:unpacking_scheduler.py:112 Unpacking scheduler offline DEBUG root:scheduler.py:139 Shutting down analysis scheduler DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... DEBUG root:PluginBase.py:118 Shutting down... INFO root:scheduler.py:162 Analysis scheduler offline ================================================================================== short test summary info =================================================================================== FAILED src/test/integration/scheduler/test_unpack_and_analyse.py::TestFileAddition::test_unpack_and_analyse - _queue.Empty ===================================================================================== 1 failed in 6.58s ====================================================================================== (ozzy) oguzhanozgur@oguzhanozgur:~/FACT_core$ ```

[jstucke]

ERROR    root:unpacking_scheduler.py:273 Could not fetch unpacking container logs
ERROR    root:unpacking_scheduler.py:202 Exception happened during extraction of 418a54d78550e8584291c96e5d6168133621f352bfc1d43cf84e81187fef4962_787.: Extraction container could not be reached. 

Sadly, this was not really helpful: It seems the container did not start at all and therefore did not produce any error log. This is really puzzling. What happens if you try to start the container manually with the parameters used in FACT:

docker run --rm -it -p "9990:5000/tcp" --entrypoint gunicorn fkiecad/fact_extractor:latest --timeout 600 -w 1 -b 0.0.0.0:5000 server:app

Does it start? Are you able to do a curl "http://localhost:9990/status" in another shell when it runs?

[oguzhanozgur]

[jstucke]

So the container starts fine, just not when started from FACT using the docker python API it seems.

What is the version of the python docker package? (you can get it by running pip show docker | grep -i version with activated venv)

Also is does not look like you are really using a venv judging by the package path /home/oguzhanozgur/ozzy/lib/python3.10/site-packages/urllib3/connection.py. Could you try creating a venv in your src folder by running

python3 -m venv venv
. venv/bin/activate

and then in that shell reinstall all python packages with

pip install -r install/requirements_pre_install.txt
python3 install.py

and then try starting FACT again (also from this shell)?

[oguzhanozgur]

I thinks there is a problem with docker. Here are the new logs: (btw, i could start FACT successfully but same issue occured again)

``` oguzhanozgur@oguzhanozgur:~$ pip show docker | grep -i version WARNING: Package(s) not found: docker oguzhanozgur@oguzhanozgur:~$ . venv/bin/activate bash: venv/bin/activate: No such file or directory oguzhanozgur@oguzhanozgur:~$ cd FACT_core/src oguzhanozgur@oguzhanozgur:~/FACT_core/src$ . venv/bin/activate (venv) oguzhanozgur@oguzhanozgur:~/FACT_core/src$ pip show docker | grep -i version WARNING: Package(s) not found: docker (venv) oguzhanozgur@oguzhanozgur:~/FACT_core/src$ pip install -r install/requirements_pre_install.txt Collecting git+https://github.com/fkie-cad/common_helper_files.git (from -r install/requirements_pre_install.txt (line 12)) Cloning https://github.com/fkie-cad/common_helper_files.git to /tmp/pip-req-build-_wsabl92 Running command git clone --filter=blob:none --quiet https://github.com/fkie-cad/common_helper_files.git /tmp/pip-req-build-_wsabl92 Resolved https://github.com/fkie-cad/common_helper_files.git to commit 3f9a641d56216e6a74774737b310a5d4b598e017 Preparing metadata (setup.py) ... done Collecting virtualenv Downloading virtualenv-20.26.6-py3-none-any.whl (6.0 MB) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 6.0/6.0 MB 5.6 MB/s eta 0:00:00 Collecting distro==1.8.0 Downloading distro-1.8.0-py3-none-any.whl (20 kB) Collecting python-magic==0.4.27 Downloading python_magic-0.4.27-py2.py3-none-any.whl (13 kB) Collecting requests==2.32.2 Downloading requests-2.32.2-py3-none-any.whl (63 kB) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 63.9/63.9 KB 8.1 MB/s eta 0:00:00 Collecting pydantic==2.4.0 Downloading pydantic-2.4.0-py3-none-any.whl (395 kB) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 395.4/395.4 KB 9.9 MB/s eta 0:00:00 Collecting werkzeug~=3.0.3 Downloading werkzeug-3.0.4-py3-none-any.whl (227 kB) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 227.6/227.6 KB 9.6 MB/s eta 0:00:00 Collecting toml==0.10.2 Downloading toml-0.10.2-py2.py3-none-any.whl (16 kB) Collecting charset-normalizer<4,>=2 Using cached charset_normalizer-3.3.2-cp310-cp310-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (142 kB) Collecting urllib3<3,>=1.21.1 Downloading urllib3-2.2.3-py3-none-any.whl (126 kB) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 126.3/126.3 KB 8.9 MB/s eta 0:00:00 Collecting certifi>=2017.4.17 Downloading certifi-2024.8.30-py3-none-any.whl (167 kB) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 167.3/167.3 KB 10.0 MB/s eta 0:00:00 Collecting idna<4,>=2.5 Downloading idna-3.10-py3-none-any.whl (70 kB) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 70.4/70.4 KB 6.9 MB/s eta 0:00:00 Collecting annotated-types>=0.4.0 Downloading annotated_types-0.7.0-py3-none-any.whl (13 kB) Collecting pydantic-core==2.10.0 Downloading pydantic_core-2.10.0-cp310-cp310-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (2.0 MB) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 2.0/2.0 MB 8.7 MB/s eta 0:00:00 Collecting typing-extensions>=4.6.1 Using cached typing_extensions-4.12.2-py3-none-any.whl (37 kB) Collecting platformdirs<5,>=3.9.1 Downloading platformdirs-4.3.6-py3-none-any.whl (18 kB) Collecting distlib<1,>=0.3.7 Downloading distlib-0.3.8-py2.py3-none-any.whl (468 kB) ━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━━ 468.9/468.9 KB 10.5 MB/s eta 0:00:00 Collecting filelock<4,>=3.12.2 Downloading filelock-3.16.1-py3-none-any.whl (16 kB) Collecting MarkupSafe>=2.1.1 Downloading MarkupSafe-2.1.5-cp310-cp310-manylinux_2_17_x86_64.manylinux2014_x86_64.whl (25 kB) Collecting bitmath Using cached bitmath-1.3.3.1-py3-none-any.whl Using legacy 'setup.py install' for common-helper-files, since package 'wheel' is not installed. Installing collected packages: distlib, bitmath, urllib3, typing-extensions, toml, python-magic, platformdirs, MarkupSafe, idna, filelock, distro, common-helper-files, charset-normalizer, certifi, annotated-types, werkzeug, virtualenv, requests, pydantic-core, pydantic Running setup.py install for common-helper-files ... done Successfully installed MarkupSafe-2.1.5 annotated-types-0.7.0 bitmath-1.3.3.1 certifi-2024.8.30 charset-normalizer-3.3.2 common-helper-files-0.3.1 distlib-0.3.8 distro-1.8.0 filelock-3.16.1 idna-3.10 platformdirs-4.3.6 pydantic-2.4.0 pydantic-core-2.10.0 python-magic-0.4.27 requests-2.32.2 toml-0.10.2 typing-extensions-4.12.2 urllib3-2.2.3 virtualenv-20.26.6 werkzeug-3.0.4 (venv) oguzhanozgur@oguzhanozgur:~/FACT_core/src$ python3 install.py [2024-10-02 12:33:36][install][INFO]: FACT Installer 1.2 [2024-10-02 12:33:36][common][INFO]: Updating system [sudo] password for oguzhanozgur: [2024-10-02 12:33:42][install][INFO]: Installing apt-transport-https autoconf automake build-essential git gnupg2 libtool python3 python3-dev unzip wget libfuzzy-dev libmagic-dev [2024-10-02 12:34:05][install][INFO]: Installing nodejs papirus-icon-theme [2024-10-02 12:34:21][frontend][INFO]: Creating directory for authentication [2024-10-02 12:34:21][frontend][INFO]: Initializing docker container for radare [2024-10-02 12:34:24][frontend][INFO]: Pulling pdf report container psql (PostgreSQL) 14.13 (Ubuntu 14.13-1.pgdg22.04+1) [2024-10-02 12:34:26][db][INFO]: Skipping PostgreSQL installation. Reason: Already installed. [2024-10-02 12:34:26][db][INFO]: Initializing PostgreSQL database [2024-10-02 12:34:26][install][INFO]: Installing libjpeg-dev libssl-dev redis binutils file openssl bison flex pkg-config [2024-10-02 12:34:34][backend][INFO]: Skipping yara installation: Already installed and up to date [2024-10-02 12:34:34][backend][INFO]: Installing checksec.sh [2024-10-02 12:34:34][backend][INFO]: Pulling fact extraction container [2024-10-02 12:34:36][backend][INFO]: Installing linter plugin. [2024-10-02 12:34:52][backend][INFO]: Finished installing linter plugin. [2024-10-02 12:34:52][backend][INFO]: Installing crypto_hints plugin. [2024-10-02 12:34:53][backend][INFO]: Finished installing crypto_hints plugin. [2024-10-02 12:34:53][backend][INFO]: Installing file_system_metadata plugin. [2024-10-02 12:34:53][backend][INFO]: Finished installing file_system_metadata plugin. [2024-10-02 12:34:53][backend][INFO]: Installing architecture_detection plugin. [2024-10-02 12:34:55][backend][INFO]: Finished installing architecture_detection plugin. [2024-10-02 12:34:55][backend][INFO]: Installing cve_lookup plugin. [2024-10-02 12:36:15][backend][INFO]: Finished installing cve_lookup plugin. [2024-10-02 12:36:15][backend][INFO]: Installing ipc plugin. [2024-10-02 12:36:16][backend][INFO]: Finished installing ipc plugin. [2024-10-02 12:36:16][backend][INFO]: Installing known_vulnerabilities plugin. [2024-10-02 12:36:17][backend][INFO]: Finished installing known_vulnerabilities plugin. [2024-10-02 12:36:17][backend][INFO]: Installing ip_and_uri_finder plugin. [2024-10-02 12:36:24][backend][INFO]: Finished installing ip_and_uri_finder plugin. [2024-10-02 12:36:24][backend][INFO]: Installing kernel_config plugin. [2024-10-02 12:36:28][backend][INFO]: Finished installing kernel_config plugin. [2024-10-02 12:36:28][backend][INFO]: Installing cwe_checker plugin. [2024-10-02 12:36:30][backend][INFO]: Finished installing cwe_checker plugin. [2024-10-02 12:36:30][backend][INFO]: Installing binwalk plugin. [2024-10-02 12:36:59][backend][INFO]: Finished installing binwalk plugin. [2024-10-02 12:36:59][backend][INFO]: Installing qemu_exec plugin. [2024-10-02 12:37:02][backend][INFO]: Finished installing qemu_exec plugin. [2024-10-02 12:37:02][backend][INFO]: Installing users_and_passwords plugin. [2024-10-02 12:37:05][backend][INFO]: Finished installing users_and_passwords plugin. [2024-10-02 12:37:05][backend][INFO]: Installing input_vectors plugin. [2024-10-02 12:37:06][backend][INFO]: Finished installing input_vectors plugin. [2024-10-02 12:37:06][backend][INFO]: Installing software_components plugin. [2024-10-02 12:37:07][backend][INFO]: Finished installing software_components plugin. [2024-10-02 12:37:07][backend][INFO]: Installing device_tree plugin. [2024-10-02 12:37:07][backend][INFO]: Finished installing device_tree plugin. [2024-10-02 12:37:07][backend][INFO]: Creating firmware directory Create signature directory /home/oguzhanozgur/FACT_core/src/analysis/signatures Compile signatures in /home/oguzhanozgur/FACT_core/src/plugins/analysis/crypto_hints/signatures Compile signatures in /home/oguzhanozgur/FACT_core/src/plugins/analysis/crypto_material/signatures Compile signatures in /home/oguzhanozgur/FACT_core/src/plugins/analysis/known_vulnerabilities/signatures Compile signatures in /home/oguzhanozgur/FACT_core/src/plugins/analysis/software_components/signatures [2024-10-02 12:37:08][install][INFO]: installation complete (venv) oguzhanozgur@oguzhanozgur:~/FACT_core/src$ ls alembic.ini init_postgres.py start_fact_backend.py analysis install start_fact_database.py bin install.log start_fact_frontend.py check_signatures.py install.py start_fact.py compare intercom statistic compile_yara_signatures.py manage_users.py storage config migrate_database.py test config.py migrate_db_to_postgresql.py unpacker conftest.py objects update_statistic.py fact_base.py plugins venv flask_app_wrapper.py __pycache__ version.py helperFunctions scheduler web_interface (venv) oguzhanozgur@oguzhanozgur:~/FACT_core/src$ cd .. (venv) oguzhanozgur@oguzhanozgur:~/FACT_core$ ls CODE_OF_CONDUCT.md INSTALL.md src CONTRIBUTING.md INSTALL.vagrant.md start_all_installed_fact_components docs LICENSE start_fact_backend docsrc pyproject.toml start_fact_database install.log README.md start_fact_frontend (venv) oguzhanozgur@oguzhanozgur:~/FACT_core$ ./start_all_installed_fact_components [2024-10-02 12:38:04][start_all_installed_fact_components][INFO]: starting database [2024-10-02 12:38:04][start_all_installed_fact_components][INFO]: starting frontend [2024-10-02 12:38:04][start_all_installed_fact_components][INFO]: starting backend [2024-10-02 12:38:04][fact_base][INFO]: Starting FACT Frontend @ 4.3-dev (d96db1d1, Python 3.10.12) [2024-10-02 12:38:04][fact_base][INFO]: Starting FACT DB-Service @ 4.3-dev (d96db1d1, Python 3.10.12) [2024-10-02 12:38:04][__init__][INFO]: Alembic DB revision: head: 05d8effce8b3, current: 05d8effce8b3 [2024-10-02 12:38:04][__init__][INFO]: Alembic DB revision: head: 05d8effce8b3, current: 05d8effce8b3 [2024-10-02 12:38:04][fact_base][INFO]: Successfully started FACT DB-Service [2024-10-02 12:38:04][fact_base][INFO]: Starting FACT Backend @ 4.3-dev (d96db1d1, Python 3.10.12) [2024-10-02 12:38:04][__init__][INFO]: Alembic DB revision: head: 05d8effce8b3, current: 05d8effce8b3 [2024-10-02 12:38:04][fact_base][INFO]: Successfully started FACT Frontend [uWSGI] getting INI configuration from /home/oguzhanozgur/FACT_core/src/config/uwsgi_config.ini *** Starting uWSGI 2.0.25.1 (64bit) on [Wed Oct 2 12:38:04 2024] *** compiled with version: 11.4.0 on 01 October 2024 07:03:53 os: Linux-6.5.0-1027-oem #28-Ubuntu SMP PREEMPT_DYNAMIC Thu Jul 25 13:32:46 UTC 2024 nodename: oguzhanozgur machine: x86_64 clock source: unix detected number of CPU cores: 12 current working directory: /home/oguzhanozgur/FACT_core/src detected binary path: /home/oguzhanozgur/FACT_core/src/venv/bin/uwsgi !!! no internal routing support, rebuild with pcre support !!! your processes number limit is 125501 your memory page size is 4096 bytes detected max file descriptor number: 1024 lock engine: pthread robust mutexes thunder lock: enabled uwsgi socket 0 bound to TCP address 127.0.0.1:5000 fd 3 Python version: 3.10.12 (main, Sep 11 2024, 15:47:36) [GCC 11.4.0] Python main interpreter initialized at 0x652a5c91f0e0 python threads support enabled your server socket listen backlog is limited to 100 connections your mercy for graceful operations on workers is 60 seconds mapped 500064 bytes (488 KB) for 10 cores *** Operational MODE: preforking+threaded *** [2024-10-02 12:38:04][ip_and_uri_finder_analysis][INFO]: ip signature path: /home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/common_analysis_ip_and_uri_finder/yara_rules/ip_rules.yara [2024-10-02 12:38:04][ip_and_uri_finder_analysis][INFO]: ip signature path: /home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/common_analysis_ip_and_uri_finder/yara_rules/uri_rules.yara [2024-10-02 12:38:05][frontend_main][INFO]: Web front end online WSGI app 0 (mountpoint='') ready in 1 seconds on interpreter 0x652a5c91f0e0 pid: 84798 (default app) *** uWSGI is running in multiple interpreter mode *** spawned uWSGI master process (pid: 84798) spawned uWSGI worker 1 (pid: 84987, cores: 2) spawned uWSGI worker 2 (pid: 84989, cores: 2) spawned uWSGI worker 3 (pid: 84991, cores: 2) spawned uWSGI worker 4 (pid: 84993, cores: 2) spawned uWSGI worker 5 (pid: 84995, cores: 2) *** Stats server enabled on 127.0.0.1:9191 fd: 19 *** [2024-10-02 12:38:05][compare][INFO]: Comparison plugins available: Software, File_Coverage, File_Header [2024-10-02 12:38:05][scheduler][INFO]: Analysis scheduler online [2024-10-02 12:38:05][scheduler][INFO]: Analysis plugins available: binwalk 1.0.0, cpu_architecture 0.4.0, crypto_hints 0.2.1, crypto_material 0.5.2, cve_lookup 0.1.0, cwe_checker 0.5.4, device_tree 2.0.0, elf_analysis 0.3.4, exploit_mitigations 0.2.0, file_hashes 1.2, file_system_metadata 1.0.0, file_type 1.0.0, hardware_analysis 0.2, hashlookup 0.1.4, information_leaks 0.2.0, init_systems 0.4.2, input_vectors 0.1.2, interesting_uris 0.1, ip_and_uri_finder 0.4.2, ipc_analyzer 0.1.1, kernel_config 0.3.1, known_vulnerabilities 0.2.1, printable_strings 0.3.4, qemu_exec 0.5.2, software_components 0.4.2, source_code_analysis 0.7.1, string_evaluator 0.2.1, tlsh 0.2, users_and_passwords 0.5.4 [2024-10-02 12:38:05][unpacking_scheduler][INFO]: Unpacking scheduler online [2024-10-02 12:38:05][unpacking_scheduler][INFO]: Queue Length (Analysis/Unpack): 0 / 0 [2024-10-02 12:38:05][comparison_scheduler][INFO]: Comparison scheduler online [2024-10-02 12:38:05][back_end_binding][INFO]: Intercom online [2024-10-02 12:38:05][fact_base][INFO]: Successfully started FACT Backend [2024-10-02 12:38:09][fact_base][INFO]: System memory usage: 19.9%; open file count: 6 [2024-10-02 12:38:09][fact_base][INFO]: System memory usage: 19.9%; open file count: 7 [2024-10-02 12:38:11][fact_base][INFO]: System memory usage: 19.8%; open file count: 542 [2024-10-02 12:38:12][update][INFO]: time to create stats: 0s [pid: 84987|app: 0|req: 1/1] 127.0.0.1 () {46 vars in 903 bytes} [Wed Oct 2 12:38:12 2024] GET / => generated 18170 bytes in 71 msecs (HTTP/1.1 200) 3 headers in 96 bytes (1 switches on core 0) [pid: 84987|app: 0|req: 2/2] 127.0.0.1 () {44 vars in 879 bytes} [Wed Oct 2 12:38:12 2024] GET /static/node_modules/bootstrap/dist/css/bootstrap.min.css => generated 162264 bytes in 3 msecs via sendfile() (HTTP/1.1 200) 8 headers in 305 bytes (0 switches on core 1) [pid: 84993|app: 0|req: 2/3] 127.0.0.1 () {44 vars in 805 bytes} [Wed Oct 2 12:38:12 2024] GET /static/css/home.css => generated 428 bytes in 8 msecs via sendfile() (HTTP/1.1 200) 8 headers in 292 bytes (0 switches on core 1) [pid: 84989|app: 0|req: 2/4] 127.0.0.1 () {44 vars in 937 bytes} [Wed Oct 2 12:38:12 2024] GET /static/node_modules/bootstrap-datepicker/dist/css/bootstrap-datepicker.standalone.css => generated 18058 bytes in 11 msecs via sendfile() (HTTP/1.1 200) 8 headers in 322 bytes (0 switches on core 1) [pid: 84989|app: 0|req: 2/5] 127.0.0.1 () {44 vars in 889 bytes} [Wed Oct 2 12:38:12 2024] GET /static/node_modules/@fortawesome/fontawesome-free/css/all.css => generated 73577 bytes in 11 msecs via sendfile() (HTTP/1.1 200) 8 headers in 295 bytes (0 switches on core 0) [pid: 84993|app: 0|req: 2/6] 127.0.0.1 () {44 vars in 861 bytes} [Wed Oct 2 12:38:12 2024] GET /static/node_modules/bootstrap/dist/js/bootstrap.min.js => generated 62563 bytes in 11 msecs via sendfile() (HTTP/1.1 200) 8 headers in 310 bytes (0 switches on core 0) [pid: 84991|app: 0|req: 2/7] 127.0.0.1 () {44 vars in 843 bytes} [Wed Oct 2 12:38:12 2024] GET /static/node_modules/jquery/dist/jquery.min.js => generated 87462 bytes in 11 msecs via sendfile() (HTTP/1.1 200) 8 headers in 308 bytes (0 switches on core 0) [pid: 84991|app: 0|req: 2/8] 127.0.0.1 () {44 vars in 857 bytes} [Wed Oct 2 12:38:12 2024] GET /static/node_modules/popper.js/dist/umd/popper.min.js => generated 21233 bytes in 11 msecs via sendfile() (HTTP/1.1 200) 8 headers in 308 bytes (0 switches on core 1) [pid: 84987|app: 0|req: 3/9] 127.0.0.1 () {44 vars in 803 bytes} [Wed Oct 2 12:38:12 2024] GET /static/js/quick_search.js => generated 3568 bytes in 1 msecs via sendfile() (HTTP/1.1 200) 8 headers in 308 bytes (0 switches on core 0) [pid: 84987|app: 0|req: 4/10] 127.0.0.1 () {44 vars in 861 bytes} [Wed Oct 2 12:38:12 2024] GET /static/fact_logo_inv.svg => generated 32224 bytes in 0 msecs via sendfile() (HTTP/1.1 200) 8 headers in 310 bytes (0 switches on core 1) [pid: 84993|app: 0|req: 3/11] 127.0.0.1 () {44 vars in 853 bytes} [Wed Oct 2 12:38:12 2024] GET /static/fact_logo.png => generated 70887 bytes in 0 msecs via sendfile() (HTTP/1.1 200) 8 headers in 287 bytes (0 switches on core 1) [pid: 84995|app: 0|req: 2/12] 127.0.0.1 () {44 vars in 897 bytes} [Wed Oct 2 12:38:12 2024] GET /static/node_modules/bootstrap-datepicker/dist/js/bootstrap-datepicker.js => generated 58136 bytes in 8 msecs via sendfile() (HTTP/1.1 200) 8 headers in 318 bytes (0 switches on core 1) [pid: 84995|app: 0|req: 2/13] 127.0.0.1 () {44 vars in 835 bytes} [Wed Oct 2 12:38:12 2024] GET /static/node_modules/moment/dist/moment.js => generated 154671 bytes in 12 msecs via sendfile() (HTTP/1.1 200) 8 headers in 306 bytes (0 switches on core 0) [pid: 84989|app: 0|req: 4/14] 127.0.0.1 () {46 vars in 999 bytes} [Wed Oct 2 12:38:12 2024] GET /static/node_modules/@fortawesome/fontawesome-free/webfonts/fa-solid-900.woff2 => generated 78268 bytes in 3 msecs via sendfile() (HTTP/1.1 200) 8 headers in 293 bytes (0 switches on core 0) [pid: 84993|app: 0|req: 4/15] 127.0.0.1 () {44 vars in 853 bytes} [Wed Oct 2 12:38:12 2024] GET /static/fact_icon.ico => generated 5216 bytes in 0 msecs via sendfile() (HTTP/1.1 200) 8 headers in 300 bytes (0 switches on core 0) [pid: 84989|app: 0|req: 4/16] 127.0.0.1 () {46 vars in 865 bytes} [Wed Oct 2 12:38:12 2024] GET /ajax/stats/system => generated 65 bytes in 39 msecs (HTTP/1.1 200) 3 headers in 85 bytes (1 switches on core 1) [pid: 84991|app: 0|req: 3/17] 127.0.0.1 () {48 vars in 960 bytes} [Wed Oct 2 12:38:15 2024] GET /upload => generated 46073 bytes in 49 msecs (HTTP/1.1 200) 3 headers in 96 bytes (1 switches on core 0) [pid: 84991|app: 0|req: 4/18] 127.0.0.1 () {48 vars in 998 bytes} [Wed Oct 2 12:38:15 2024] GET /static/node_modules/bootstrap/dist/css/bootstrap.min.css => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 206 bytes (0 switches on core 1) [pid: 84987|app: 0|req: 6/19] 127.0.0.1 () {48 vars in 963 bytes} [Wed Oct 2 12:38:15 2024] GET /static/node_modules/jquery/dist/jquery.min.js => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 203 bytes (0 switches on core 1) [pid: 84993|app: 0|req: 5/20] 127.0.0.1 () {48 vars in 977 bytes} [Wed Oct 2 12:38:15 2024] GET /static/node_modules/popper.js/dist/umd/popper.min.js => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 203 bytes (0 switches on core 1) [pid: 84987|app: 0|req: 6/21] 127.0.0.1 () {48 vars in 1009 bytes} [Wed Oct 2 12:38:15 2024] GET /static/node_modules/@fortawesome/fontawesome-free/css/all.css => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 197 bytes (0 switches on core 0) [pid: 84995|app: 0|req: 4/23] 127.0.0.1 () {44 vars in 797 bytes} [Wed Oct 2 12:38:15 2024] GET /static/js/upload.js => generated 2229 bytes in 1 msecs via sendfile() (HTTP/1.1 200) 8 headers in 302 bytes (0 switches on core 0) [pid: 84995|app: 0|req: 4/23] 127.0.0.1 () {48 vars in 980 bytes} [Wed Oct 2 12:38:15 2024] GET /static/node_modules/bootstrap/dist/js/bootstrap.min.js => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 205 bytes (0 switches on core 1) [pid: 84987|app: 0|req: 7/25] 127.0.0.1 () {48 vars in 922 bytes} [Wed Oct 2 12:38:15 2024] GET /static/js/quick_search.js => generated 0 bytes in 0 msecs (HTTP/1.1 304) 5 headers in 204 bytes (0 switches on core 1) [pid: 84993|app: 0|req: 6/25] 127.0.0.1 () {48 vars in 1056 bytes} [Wed Oct 2 12:38:15 2024] GET /static/node_modules/bootstrap-datepicker/dist/css/bootstrap-datepicker.standalone.css => generated 0 bytes in 0 msecs (HTTP/1.1 304) 5 headers in 224 bytes (0 switches on core 0) [pid: 84991|app: 0|req: 6/26] 127.0.0.1 () {48 vars in 956 bytes} [Wed Oct 2 12:38:15 2024] GET /static/node_modules/moment/dist/moment.js => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 200 bytes (0 switches on core 0) [pid: 84989|app: 0|req: 6/27] 127.0.0.1 () {44 vars in 815 bytes} [Wed Oct 2 12:38:15 2024] GET /static/css/upload.css => generated 94 bytes in 1 msecs via sendfile() (HTTP/1.1 200) 8 headers in 292 bytes (0 switches on core 0) [pid: 84989|app: 0|req: 6/28] 127.0.0.1 () {44 vars in 799 bytes} [Wed Oct 2 12:38:15 2024] GET /static/js/loading.js => generated 190 bytes in 1 msecs via sendfile() (HTTP/1.1 200) 8 headers in 301 bytes (0 switches on core 1) [pid: 84991|app: 0|req: 6/29] 127.0.0.1 () {48 vars in 1017 bytes} [Wed Oct 2 12:38:15 2024] GET /static/node_modules/bootstrap-datepicker/dist/js/bootstrap-datepicker.js => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 213 bytes (0 switches on core 1) [pid: 84987|app: 0|req: 8/30] 127.0.0.1 () {48 vars in 981 bytes} [Wed Oct 2 12:38:15 2024] GET /static/fact_logo_inv.svg => generated 0 bytes in 0 msecs (HTTP/1.1 304) 5 headers in 207 bytes (0 switches on core 0) [pid: 84993|app: 0|req: 7/31] 127.0.0.1 () {44 vars in 853 bytes} [Wed Oct 2 12:38:15 2024] GET /static/Pacman.gif => generated 71915 bytes in 0 msecs via sendfile() (HTTP/1.1 200) 8 headers in 283 bytes (0 switches on core 1) [pid: 84995|app: 0|req: 5/32] 127.0.0.1 () {56 vars in 1143 bytes} [Wed Oct 2 12:38:42 2024] POST /upload => generated 11313 bytes in 37 msecs (HTTP/1.1 200) 3 headers in 96 bytes (1 switches on core 0) [pid: 84995|app: 0|req: 6/33] 127.0.0.1 () {48 vars in 998 bytes} [Wed Oct 2 12:38:42 2024] GET /static/node_modules/bootstrap/dist/css/bootstrap.min.css => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 206 bytes (0 switches on core 1) [pid: 84993|app: 0|req: 8/35] 127.0.0.1 () {48 vars in 1056 bytes} [Wed Oct 2 12:38:42 2024] GET /static/node_modules/bootstrap-datepicker/dist/css/bootstrap-datepicker.standalone.css => generated 0 bytes in 0 msecs (HTTP/1.1 304) 5 headers in 224 bytes (0 switches on core 0) [pid: 84987|app: 0|req: 9/35] 127.0.0.1 () {48 vars in 1009 bytes} [Wed Oct 2 12:38:42 2024] GET /static/node_modules/@fortawesome/fontawesome-free/css/all.css => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 197 bytes (0 switches on core 1) [pid: 84989|app: 0|req: 8/36] 127.0.0.1 () {48 vars in 977 bytes} [Wed Oct 2 12:38:42 2024] GET /static/node_modules/popper.js/dist/umd/popper.min.js => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 203 bytes (0 switches on core 0) [pid: 84991|app: 0|req: 8/37] 127.0.0.1 () {48 vars in 956 bytes} [Wed Oct 2 12:38:42 2024] GET /static/node_modules/moment/dist/moment.js => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 200 bytes (0 switches on core 1) [pid: 84989|app: 0|req: 8/38] 127.0.0.1 () {48 vars in 980 bytes} [Wed Oct 2 12:38:42 2024] GET /static/node_modules/bootstrap/dist/js/bootstrap.min.js => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 205 bytes (0 switches on core 1) [pid: 84991|app: 0|req: 8/39] 127.0.0.1 () {48 vars in 963 bytes} [Wed Oct 2 12:38:42 2024] GET /static/node_modules/jquery/dist/jquery.min.js => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 203 bytes (0 switches on core 0) [pid: 84987|app: 0|req: 10/40] 127.0.0.1 () {48 vars in 1017 bytes} [Wed Oct 2 12:38:42 2024] GET /static/node_modules/bootstrap-datepicker/dist/js/bootstrap-datepicker.js => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 213 bytes (0 switches on core 0) [pid: 84993|app: 0|req: 9/41] 127.0.0.1 () {48 vars in 922 bytes} [Wed Oct 2 12:38:42 2024] GET /static/js/quick_search.js => generated 0 bytes in 0 msecs (HTTP/1.1 304) 5 headers in 204 bytes (0 switches on core 1) [pid: 84995|app: 0|req: 7/42] 127.0.0.1 () {48 vars in 981 bytes} [Wed Oct 2 12:38:42 2024] GET /static/fact_logo_inv.svg => generated 0 bytes in 1 msecs (HTTP/1.1 304) 5 headers in 207 bytes (0 switches on core 0) [2024-10-02 12:38:43][connectionpool][WARNING]: Retrying (Retry(total=2, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError(': Failed to establish a new connection: [Errno 111] Connection refused')': /status [2024-10-02 12:38:43][connectionpool][WARNING]: Retrying (Retry(total=1, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError(': Failed to establish a new connection: [Errno 111] Connection refused')': /status [2024-10-02 12:38:43][connectionpool][WARNING]: Retrying (Retry(total=0, connect=None, read=None, redirect=None, status=None)) after connection broken by 'NewConnectionError(': Failed to establish a new connection: [Errno 111] Connection refused')': /status [2024-10-02 12:38:43][unpacking_scheduler][ERROR]: Could not fetch unpacking container logs [2024-10-02 12:38:43][unpacking_scheduler][ERROR]: Exception happened during extraction of 325cb643b5f6849f9351fe8a21014e6a79687251603337ce0df02136799b7564_3889376.: Extraction container could not be reached. Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/connection.py", line 199, in _new_conn sock = connection.create_connection( File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/util/connection.py", line 85, in create_connection raise err File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/util/connection.py", line 73, in create_connection sock.connect(sa) ConnectionRefusedError: [Errno 111] Connection refused The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/connectionpool.py", line 789, in urlopen response = self._make_request( File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/connectionpool.py", line 495, in _make_request conn.request( File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/connection.py", line 441, in request self.endheaders() File "/usr/lib/python3.10/http/client.py", line 1278, in endheaders self._send_output(message_body, encode_chunked=encode_chunked) File "/usr/lib/python3.10/http/client.py", line 1038, in _send_output self.send(msg) File "/usr/lib/python3.10/http/client.py", line 976, in send self.connect() File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/connection.py", line 279, in connect self.sock = self._new_conn() File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/connection.py", line 214, in _new_conn raise NewConnectionError( urllib3.exceptions.NewConnectionError: : Failed to establish a new connection: [Errno 111] Connection refused The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/requests/adapters.py", line 589, in send resp = conn.urlopen( File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/connectionpool.py", line 873, in urlopen return self.urlopen( File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/connectionpool.py", line 873, in urlopen return self.urlopen( File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/connectionpool.py", line 873, in urlopen return self.urlopen( File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/connectionpool.py", line 843, in urlopen retries = retries.increment( File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/urllib3/util/retry.py", line 519, in increment raise MaxRetryError(_pool, url, reason) from reason # type: ignore[arg-type] urllib3.exceptions.MaxRetryError: HTTPConnectionPool(host='localhost', port=9900): Max retries exceeded with url: /status (Caused by NewConnectionError(': Failed to establish a new connection: [Errno 111] Connection refused')) During handling of the above exception, another exception occurred: Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack_base.py", line 55, in _extract_with_worker response = container.start_unpacking(tmp_dir, timeout=WORKER_TIMEOUT) File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 118, in start_unpacking response = self._check_connection() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 133, in _check_connection return session.get(url, timeout=5) File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/requests/sessions.py", line 602, in get return self.request("GET", url, **kwargs) File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/requests/sessions.py", line 589, in request resp = self.send(prep, **send_kwargs) File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/requests/sessions.py", line 703, in send r = adapter.send(request, **kwargs) File "/home/oguzhanozgur/FACT_core/src/venv/lib/python3.10/site-packages/requests/adapters.py", line 622, in send raise ConnectionError(e, request=request) requests.exceptions.ConnectionError: HTTPConnectionPool(host='localhost', port=9900): Max retries exceeded with url: /status (Caused by NewConnectionError(': Failed to establish a new connection: [Errno 111] Connection refused')) The above exception was the direct cause of the following exception: Traceback (most recent call last): File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 199, in work_thread extracted_objects = self.unpacker.unpack(task, tmp_dir, container) File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack.py", line 42, in unpack extracted_files = self.extract_files_from_file(current_fo.file_path, tmp_dir, container) File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack_base.py", line 41, in extract_files_from_file self._extract_with_worker(file_path, container, tmp_dir) File "/home/oguzhanozgur/FACT_core/src/unpacker/unpack_base.py", line 59, in _extract_with_worker raise ExtractionError('Extraction container could not be reached.') from error unpacker.unpack_base.ExtractionError: Extraction container could not be reached. [2024-10-02 12:38:43][unpacking_scheduler][INFO]: Unpacking completed: 325cb643b5f6849f9351fe8a21014e6a79687251603337ce0df02136799b7564_3889376 (extracted files: 0) [2024-10-02 12:38:43][unpacking_scheduler][INFO]: Unpacking of firmware 325cb643b5f6849f9351fe8a21014e6a79687251603337ce0df02136799b7564_3889376 completed. /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' /home/oguzhanozgur/FACT_core/src/bin/internal_symlink_magic, 7: Warning: using regular magic file `/home/oguzhanozgur/FACT_core/src/bin/firmware' Process ExceptionSafeProcess-109: Traceback (most recent call last): File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap self.run() File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 93, in run raise exception File "/home/oguzhanozgur/FACT_core/src/helperFunctions/process.py", line 87, in run Process.run(self) File "/usr/lib/python3.10/multiprocessing/process.py", line 108, in run self._target(*self._args, **self._kwargs) File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 149, in extraction_loop self.check_pending() File "/home/oguzhanozgur/FACT_core/src/scheduler/unpacking_scheduler.py", line 173, in check_pending container.restart() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 91, in restart self.stop() File "/home/oguzhanozgur/FACT_core/src/unpacker/extraction_container.py", line 67, in stop raise RuntimeError('Container is not running.') RuntimeError: Container is not running. [2024-10-02 12:38:44][scheduler][INFO]: Analysis Completed: 325cb643b5f6849f9351fe8a21014e6a79687251603337ce0df02136799b7564_3889376 [2024-10-02 12:38:44][analysis_status][INFO]: Analysis of firmware 325cb643b5f6849f9351fe8a21014e6a79687251603337ce0df02136799b7564_3889376 completed [2024-10-02 12:38:57][unpacking_scheduler][INFO]: Queue Length (Analysis/Unpack): 0 / 0 ^C[2024-10-02 12:39:05][fact_base][INFO]: Received signal 10. Shutting down FACT Backend... [2024-10-02 12:39:06][fact_base][INFO]: Shutting down components of FACT Backend [2024-10-02 12:39:07][back_end_binding][INFO]: Intercom offline [2024-10-02 12:39:07][comparison_scheduler][INFO]: Comparison scheduler offline [2024-10-02 12:39:08][unpacking_scheduler][INFO]: Unpacking scheduler offline [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:08][plugin][INFO]: received SIGTERM. Shutting down. [2024-10-02 12:39:09][fact_base][INFO]: System memory usage: 17.1%; open file count: 6 [2024-10-02 12:39:10][fact_base][INFO]: System memory usage: 17.1%; open file count: 7 [2024-10-02 12:39:11][scheduler][INFO]: Analysis scheduler offline [2024-10-02 12:39:11][process][CRITICAL]: SHUTTING DOWN SYSTEM [2024-10-02 12:39:11][fact_base][INFO]: Received signal 10. Shutting down FACT Frontend... [2024-10-02 12:39:15][fact_base][INFO]: Shutting down components of FACT Frontend SIGINT/SIGTERM received...killing workers... [deadlock-detector] a process holding a robust mutex died. recovering... worker 1 buried after 1 seconds worker 2 buried after 1 seconds worker 3 buried after 1 seconds worker 4 buried after 1 seconds worker 5 buried after 1 seconds goodbye to uWSGI. [2024-10-02 12:39:26][fact_base][INFO]: Received signal 10. Shutting down FACT DB-Service... [2024-10-02 12:39:29][fact_base][INFO]: Shutting down components of FACT DB-Service (venv) oguzhanozgur@oguzhanozgur:~/FACT_core$ (venv) oguzhanozgur@oguzhanozgur:~/FACT_core$ (venv) oguzhanozgur@oguzhanozgur:~/FACT_core$ ```

[jstucke]

I thinks there is a problem with docker.

That's the only remaining source for this problem I can think of at this point. There are some problems that can occur if you install docker and then try to use it without restarting. Have you restarted the system since you installed docker (or FACT)? If not, that could also be worth a try.

And if that wasn't the issue, could you try running this script to try starting the container manually using the python docker API?

from time import sleep

import docker

DOCKER_CLIENT = docker.from_env()

container = DOCKER_CLIENT.containers.run(
    image='fkiecad/fact_extractor',
    ports={'5000/tcp': 9999},
    volumes={'/dev': {'bind': '/dev', 'mode': 'rw'}},
    privileged=True,
    detach=True,
    remove=True,
    entrypoint='gunicorn --timeout 600 -w 1 -b 0.0.0.0:5000 server:app',
)
sleep(3)
print(container.logs().decode())
container.stop()

[oguzhanozgur]

Where should I write this script, couldnt understand

[jstucke]

You could either write it to a file and run the file with python3 <file> or simply start a python shell by running python3 in the terminal and pasting the contents into the shell (with ctrl+shift+v).

[oguzhanozgur]

Here is the script result:

[jstucke]

That also looks normal. I'm really not sure what to make of this: Starting the containers doesn't work when you start FACT, but it works when you do it manually. There could in theory be a problem with permissions on the mounted folders. Could you try it like this (so that it works exactly like it is called in FACT):

from multiprocessing import Manager
from pathlib import Path
from tempfile import TemporaryDirectory
from time import sleep

from config import load, backend
from unpacker.extraction_container import ExtractionContainer

load()
Path(backend.docker_mount_base_dir).mkdir(exist_ok=True)
tmp_dir = TemporaryDirectory(dir=backend.docker_mount_base_dir)
try:
    with Manager() as manager:
        ec = ExtractionContainer(id_=1, tmp_dir=tmp_dir, value=manager.Value('i', 0))
        ec.start()
        sleep(3)
        container = ec._get_container()
        print(container.logs())
        ec.stop()
finally:
    tmp_dir.cleanup()

There is also one thing I did not ask about: How much RAM do you have in the system where FACT is running?

[oguzhanozgur]

I think there is a problem here :

[jstucke]

I think there is a problem here :

This script must be executed form the src directory for the import paths to line up. Sorry for the confusion.

[oguzhanozgur]

Hi again, Sorry for the late response.

[jstucke]

Sorry that was my fault: The directory does not exists yet which causes the error. I updated the script. Also you didn't answer this question:

How much RAM do you have in the system where FACT is running?

This can be a problem, because FACT is rather memory hungry. Normally it shouldn't be a problem during startup, though.

[oguzhanozgur]

Sorry, didnt see that one. I have 32GB ram total.

[oguzhanozgur]

By the way, I dont know why this happened but I can not start FACT anymore. Here are the logs:

oguzhanozgur@oguzhanozgur:~$ source .venv/bin/activate
(.venv) oguzhanozgur@oguzhanozgur:~$ cd FACT_core/
(.venv) oguzhanozgur@oguzhanozgur:~/FACT_core$ ./start_all_installed_fact_components 
[2024-10-09 17:01:06][start_all_installed_fact_components][INFO]: starting database
[2024-10-09 17:01:06][start_all_installed_fact_components][INFO]: starting frontend
[2024-10-09 17:01:06][start_all_installed_fact_components][INFO]: starting backend
[2024-10-09 17:01:06][fact_base][INFO]: Starting FACT DB-Service @ 4.3-dev (adfbfe8f, Python 3.12.3)
[2024-10-09 17:01:06][fact_base][INFO]: Starting FACT Frontend @ 4.3-dev (adfbfe8f, Python 3.12.3)
[2024-10-09 17:01:06][__init__][INFO]: Alembic DB revision:  head: 05d8effce8b3, current: 05d8effce8b3
[2024-10-09 17:01:06][__init__][INFO]: Alembic DB revision:  head: 05d8effce8b3, current: 05d8effce8b3
[2024-10-09 17:01:06][fact_base][INFO]: Successfully started FACT DB-Service
[2024-10-09 17:01:06][install][ERROR]: Failed to run docker compose -f /home/oguzhanozgur/FACT_core/src/install/radare/docker-compose.yml up -d:
time="2024-10-09T17:01:06+03:00" level=warning msg="/home/oguzhanozgur/FACT_core/src/install/radare/docker-compose.yml: the attribute `version` is obsolete, it will be ignored, please remove it to avoid potential confusion"
 Network radare_default  Creating
 Network radare_default  Error
failed to create network radare_default: Error response from daemon: could not find an available, non-overlapping IPv4 address pool among the defaults to assign to the network

Traceback (most recent call last):
  File "/home/oguzhanozgur/FACT_core/src/../start_fact_frontend", line 92, in <module>
    FactFrontend().main()
    ^^^^^^^^^^^^^^
  File "/home/oguzhanozgur/FACT_core/src/../start_fact_frontend", line 72, in __init__
    run_cmd_with_logging(f'docker compose -f {COMPOSE_YAML} up -d')
  File "/home/oguzhanozgur/FACT_core/src/helperFunctions/install.py", line 221, in run_cmd_with_logging
    raise err
  File "/home/oguzhanozgur/FACT_core/src/helperFunctions/install.py", line 216, in run_cmd_with_logging
    subprocess.run(cmd_, stdout=PIPE, stderr=STDOUT, encoding='UTF-8', shell=shell, check=True, **kwargs)
  File "/usr/lib/python3.12/subprocess.py", line 571, in run
    raise CalledProcessError(retcode, process.args,
subprocess.CalledProcessError: Command '['docker', 'compose', '-f', '/home/oguzhanozgur/FACT_core/src/install/radare/docker-compose.yml', 'up', '-d']' returned non-zero exit status 1.
[2024-10-09 17:01:06][fact_base][INFO]: Starting FACT Backend @ 4.3-dev (adfbfe8f, Python 3.12.3)
[2024-10-09 17:01:07][__init__][INFO]: Alembic DB revision:  head: 05d8effce8b3, current: 05d8effce8b3
[2024-10-09 17:01:07][ip_and_uri_finder_analysis][INFO]: ip signature path: /home/oguzhanozgur/.venv/lib/python3.12/site-packages/common_analysis_ip_and_uri_finder/yara_rules/ip_rules.yara
[2024-10-09 17:01:07][ip_and_uri_finder_analysis][INFO]: ip signature path: /home/oguzhanozgur/.venv/lib/python3.12/site-packages/common_analysis_ip_and_uri_finder/yara_rules/uri_rules.yara
[2024-10-09 17:01:08][compare][INFO]: Comparison plugins available: Software, File_Coverage, File_Header
[2024-10-09 17:01:08][scheduler][INFO]: Analysis scheduler online
[2024-10-09 17:01:08][scheduler][INFO]: Analysis plugins available: binwalk 1.0.0, cpu_architecture 0.4.0, crypto_hints 0.2.1, crypto_material 0.5.2, cve_lookup 0.1.0, cwe_checker 0.5.4, device_tree 2.0.0, elf_analysis 0.3.4, exploit_mitigations 0.2.0, file_hashes 1.2, file_system_metadata 1.0.0, file_type 1.0.0, hardware_analysis 0.2, hashlookup 0.1.4, information_leaks 0.2.0, init_systems 0.4.2, input_vectors 0.1.2, interesting_uris 0.1, ip_and_uri_finder 0.4.2, ipc_analyzer 0.1.1, kernel_config 0.3.1, known_vulnerabilities 0.3.0, printable_strings 0.3.4, qemu_exec 0.5.2, software_components 0.5.0, source_code_analysis 0.7.1, string_evaluator 0.2.1, tlsh 0.2, users_and_passwords 0.5.4
[2024-10-09 17:01:08][unpacking_scheduler][INFO]: Unpacking scheduler online
[2024-10-09 17:01:08][unpacking_scheduler][INFO]: Queue Length (Analysis/Unpack): 0 / 0
[2024-10-09 17:01:08][comparison_scheduler][INFO]: Comparison scheduler online
[2024-10-09 17:01:08][back_end_binding][INFO]: Intercom online
[2024-10-09 17:01:08][fact_base][INFO]: Successfully started FACT Backend
[2024-10-09 17:01:11][fact_base][INFO]: System memory usage: 23.0%; open file count: 7
[2024-10-09 17:01:13][fact_base][INFO]: System memory usage: 23.0%; open file count: 542

[jstucke]

I have 32GB ram total.

That shoud be plenty.

failed to create network radare_default: Error response from daemon: could not find an available, non-overlapping IPv4 address pool among the defaults to assign to the network

This is not a problem I encountered before. Maybe it is also related to the problems with starting the extractor containers. According to https://stackoverflow.com/questions/43720339/docker-error-could-not-find-an-available-non-overlapping-ipv4-address-pool-am this may have something to do with a VPN running in the background. Could this be the problem in your case?

[oguzhanozgur]

Yes, you are right. I disconnected from VPN and tool worked again but our problem is still continuing.

[jstucke]

our problem is still continuing.

I'm sorry that the problem still persists. I'm still puzzled what could be the underlying issue here. What you could also do is running FACT in a VM. There are also pre-built Vagrant VirtualBox images that you can download here: https://portal.cloud.hashicorp.com/vagrant/discover/fact-cad/FACT-master (you may need to add port forwarding to access the web interface from your system as it uses NAT by default)

[oguzhanozgur]

Hi again,

Vagrant is also has same issue. Also I want to install the tool with normal way. I tried re-installation several times but nothing changed. What should I do?

[jstucke]

Vagrant is also has same issue

Are you sure that it is the same issue? Since it runs in a VM, this would not make a lot of sense. Maybe it has something to do with your hardware or your network