ClamAV doesn't report O..o

[info-sic]

a clamav worker seems to be running, but he finishes tasks way to quickly and doesn't report to the result-page. It is also doesn't show up in the "Advanced" module-list of choosable options on submit.html?
systemctl status and clamdtop look good to me. clamav.yml, too:
meta:
name: ClamAV
description: Local ClamAV scanner
replicas: 1

settings:
socket_path: /var/run/clamav/clamd.ctl

Feeling dumb again ;)

Startupsequence of pandora/logs/warning.log
2024-04-03 09:07:24,001 clamav INFO:Initializing clamav-1
2024-04-03 09:07:24,001 clamav DEBUG:Create redis stream group...
2024-04-03 09:07:24,001 clamav DEBUG:Redis stream group already exists.
2024-04-03 09:07:35,914 WorkersManager INFO:starting worker clamav-1...
2024-04-03 09:07:35,950 clamav INFO:Worker is running...
2024-04-03 09:07:35,951 clamav DEBUG:Waiting for new task...
2024-04-03 09:08:27,744 clamav INFO:Initializing clamav-1
2024-04-03 09:08:27,744 clamav DEBUG:Create redis stream group...
2024-04-03 09:08:27,745 clamav DEBUG:Redis stream group already exists.
2024-04-03 09:08:39,266 WorkersManager INFO:starting worker clamav-1...
2024-04-03 09:08:39,275 clamav INFO:Worker is running...
2024-04-03 09:08:39,276 clamav DEBUG:Waiting for new task...
2024-04-03 09:14:39,137 clamav DEBUG:[ac126e53-957a-4a70-be68-f0b31deb3d98] Got new task
2024-04-03 09:14:39,170 clamav DEBUG:[ac126e53-957a-4a70-be68-f0b31deb3d98] Done with task.
2024-04-03 09:14:39,170 clamav DEBUG:Waiting for new task...
2024-04-03 09:14:40,319 clamav DEBUG:[70805228-a1e8-4b25-bf00-2d57aa5e8e89] Got new task
2024-04-03 09:14:40,327 clamav DEBUG:[70805228-a1e8-4b25-bf00-2d57aa5e8e89] Done with task.
2024-04-03 09:14:40,327 clamav DEBUG:Waiting for new task...

[Rafiot]

It's probably because the file isn't known by clamav (either good or bad), so the module cannot say and reports nothing.

[Rafiot]

possibly? what were the strange errors?

[info-sic]

Example 1:

[2024-04-04 05:20:28 +0200] [1884] [INFO] Booting worker with pid: 1884

(process:2280): dconf-CRITICAL **: 05:20:32.529: unable to create file '/home/pandora/.cache/dconf/user': Permission denied.  dconf will not work properly.

(process:2489): dconf-CRITICAL **: 05:20:36.060: unable to create file '/home/pandora/.cache/dconf/user': Permission denied.  dconf will not work properly.
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.10/logging/handlers.py", line 74, in emit
    self.doRollover()
  File "/usr/lib/python3.10/logging/handlers.py", line 175, in doRollover
    os.rename(sfn, dfn)
FileNotFoundError: [Errno 2] No such file or directory: '/home/pandora/pandora/logs/warning.log.3' -> '/home/pandora/pandora/logs/warning.log.4'
Call stack:
  File "/home/pandora/.cache/pypoetry/virtualenvs/pandora-Y9WI11B0-py3.10/bin/workers_manager", line 6, in <module>
    sys.exit(main())
  File "/home/pandora/pandora/bin/workers_manager.py", line 108, in main
    wm = WorkersManager()
  File "/home/pandora/pandora/bin/workers_manager.py", line 36, in __init__
    worker.start()
  File "/usr/lib/python3.10/multiprocessing/process.py", line 121, in start
    self._popen = self._Popen(self)
  File "/usr/lib/python3.10/multiprocessing/context.py", line 224, in _Popen
    return _default_context.get_context().Process._Popen(process_obj)
  File "/usr/lib/python3.10/multiprocessing/context.py", line 281, in _Popen
    return Popen(process_obj)
  File "/usr/lib/python3.10/multiprocessing/popen_fork.py", line 19, in __init__
    self._launch(process_obj)
  File "/usr/lib/python3.10/multiprocessing/popen_fork.py", line 71, in _launch
    code = process_obj._bootstrap(parent_sentinel=child_r)
  File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap
    self.run()
  File "/home/pandora/pandora/pandora/workers/base.py", line 187, in run
    self.analyse(task, report, self.module == manual_worker)
  File "/home/pandora/pandora/pandora/workers/observables.py", line 15, in analyse
    task.init_observables_from_file()
  File "/home/pandora/pandora/pandora/task.py", line 278, in init_observables_from_file
    for observable_type, values in self.file.observables.items():
  File "/home/pandora/pandora/pandora/file.py", line 627, in observables
    oid = process_maybe_encrypted(self.path)
  File "/home/pandora/.cache/pypoetry/virtualenvs/pandora-Y9WI11B0-py3.10/lib/python3.10/site-packages/oletools/msodde.py", line 932, in process_maybe_encrypted
    result = process_file(filepath, **kwargs)
  File "/home/pandora/.cache/pypoetry/virtualenvs/pandora-Y9WI11B0-py3.10/lib/python3.10/site-packages/oletools/msodde.py", line 895, in process_file
    return process_xlsx(filepath)
  File "/home/pandora/.cache/pypoetry/virtualenvs/pandora-Y9WI11B0-py3.10/lib/python3.10/site-packages/oletools/msodde.py", line 666, in process_xlsx
    logger.debug('{0}: {1}'.format(subfile, record))
  File "/usr/lib/python3.10/logging/__init__.py", line 1835, in debug
    self.log(DEBUG, msg, *args, **kwargs)
  File "/home/pandora/.cache/pypoetry/virtualenvs/pandora-Y9WI11B0-py3.10/lib/python3.10/site-packages/oletools/common/log_helper/_logger_adapter.py", line 32, in log
    self.logger.log(lvl, msg, *args, **kwargs)
Message: 'xl/printerSettings/printerSettings1.bin: [XlsbRecord type 102 (size 0 from 12)]

Example 2

127.0.0.1 - - [04/Apr/2024 07:32:05] "POST /RPC2 HTTP/1.1" 200 -
--- Logging error ---
--- Logging error ---
Traceback (most recent call last):
Traceback (most recent call last):
  File "/usr/lib/python3.10/logging/handlers.py", line 74, in emit
    self.doRollover()
  File "/usr/lib/python3.10/logging/handlers.py", line 175, in doRollover
    os.rename(sfn, dfn)
  File "/usr/lib/python3.10/logging/handlers.py", line 74, in emit
    self.doRollover()
  File "/usr/lib/python3.10/logging/handlers.py", line 174, in doRollover
    os.remove(dfn)
FileNotFoundError: [Errno 2] No such file or directory: '/home/pandora/pandora/logs/warning.log.5'
FileNotFoundError: [Errno 2] No such file or directory: '/home/pandora/pandora/logs/warning.log.4' -> '/home/pandora/pandora/logs/warning.log.5'
Call stack:
Call stack:
  File "/home/pandora/.cache/pypoetry/virtualenvs/pandora-Y9WI11B0-py3.10/bin/workers_manager", line 6, in <module>
    sys.exit(main())
  File "/home/pandora/pandora/bin/workers_manager.py", line 108, in main
    wm = WorkersManager()
  File "/home/pandora/pandora/bin/workers_manager.py", line 36, in __init__
    worker.start()
  File "/usr/lib/python3.10/multiprocessing/process.py", line 121, in start
    self._popen = self._Popen(self)
  File "/usr/lib/python3.10/multiprocessing/context.py", line 224, in _Popen
    return _default_context.get_context().Process._Popen(process_obj)
  File "/usr/lib/python3.10/multiprocessing/context.py", line 281, in _Popen
    return Popen(process_obj)
  File "/home/pandora/.cache/pypoetry/virtualenvs/pandora-Y9WI11B0-py3.10/bin/workers_manager", line 6, in <module>
    sys.exit(main())
  File "/usr/lib/python3.10/multiprocessing/popen_fork.py", line 19, in __init__
    self._launch(process_obj)
  File "/home/pandora/pandora/bin/workers_manager.py", line 108, in main
    wm = WorkersManager()
  File "/usr/lib/python3.10/multiprocessing/popen_fork.py", line 71, in _launch
    code = process_obj._bootstrap(parent_sentinel=child_r)
  File "/home/pandora/pandora/bin/workers_manager.py", line 36, in __init__
    worker.start()
  File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap
    self.run()
  File "/usr/lib/python3.10/multiprocessing/process.py", line 121, in start
    self._popen = self._Popen(self)
  File "/home/pandora/pandora/pandora/workers/base.py", line 163, in run
    logger.debug('Got new task')
  File "/usr/lib/python3.10/multiprocessing/context.py", line 224, in _Popen
    return _default_context.get_context().Process._Popen(process_obj)
  File "/usr/lib/python3.10/multiprocessing/context.py", line 281, in _Popen
    return Popen(process_obj)
  File "/usr/lib/python3.10/multiprocessing/popen_fork.py", line 19, in __init__
    self._launch(process_obj)
Message: '[3e37cc28-3e3c-473c-b5ab-524fcab5fa76] Got new task'
Arguments: ()
  File "/usr/lib/python3.10/multiprocessing/popen_fork.py", line 71, in _launch
    code = process_obj._bootstrap(parent_sentinel=child_r)
  File "/usr/lib/python3.10/multiprocessing/process.py", line 314, in _bootstrap
    self.run()
  File "/home/pandora/pandora/pandora/workers/base.py", line 163, in run
    logger.debug('Got new task')
Message: '[3e37cc28-3e3c-473c-b5ab-524fcab5fa76] Got new task'
Arguments: ()
[2024-04-04 10:38:05 +0200] [1699] [INFO] Handling signal: winch
[2024-04-04 10:38:06 +0200] [1699] [INFO] Handling signal: term
[2024-04-04 10:38:06 +0200] [1795] [INFO] Worker exiting (pid: 1795)
[2024-04-04 10:38:06 +0200] [1859] [INFO] Worker exiting (pid: 1859)
[2024-04-04 10:38:06 +0200] [1813] [INFO] Worker exiting (pid: 1813)
[2024-04-04 10:38:06 +0200] [1810] [INFO] Worker exiting (pid: 1810)
[2024-04-04 10:38:06 +0200] [1872] [INFO] Worker exiting (pid: 1872)
[2024-04-04 10:38:06 +0200] [1881] [INFO] Worker exiting (pid: 1881)
[2024-04-04 10:38:06 +0200] [1835] [INFO] Worker exiting (pid: 1835)
[2024-04-04 10:38:06 +0200] [1882] [INFO] Worker exiting (pid: 1882)
[2024-04-04 10:38:06 +0200] [1884] [INFO] Worker exiting (pid: 1884)
[2024-04-04 10:38:06 +0200] [1887] [INFO] Worker exiting (pid: 1887)
+ ../../redis/src/redis-server ./cache.conf
+ ../../kvrocks/build/kvrocks -c kvrocks.conf
[2024-04-04 10:39:19 +0200] [5179] [INFO] Starting gunicorn 21.2.0
[2024-04-04 10:39:19 +0200] [5179] [INFO] Listening at: http://0.0.0.0:6100 (5179)
[2024-04-04 10:39:19 +0200] [5179] [INFO] Using worker: sync
[2024-04-04 10:39:19 +0200] [5196] [INFO] Booting worker with pid: 5196
[2024-04-04 10:39:19 +0200] [5197] [INFO] Booting worker with pid: 5197
[2024-04-04 10:39:19 +0200] [5201] [INFO] Booting worker with pid: 5201
[2024-04-04 10:39:19 +0200] [5203] [INFO] Booting worker with pid: 5203
[2024-04-04 10:39:19 +0200] [5204] [INFO] Booting worker with pid: 5204
[2024-04-04 10:39:19 +0200] [5205] [INFO] Booting worker with pid: 5205

(process:5202): dconf-CRITICAL **: 10:39:19.884: unable to create file '/home/pandora/.cache/dconf/user': Permission denied.  dconf will not work properly.
[2024-04-04 10:39:19 +0200] [5206] [INFO] Booting worker with pid: 5206
[2024-04-04 10:39:19 +0200] [5210] [INFO] Booting worker with pid: 5210
[2024-04-04 10:39:20 +0200] [5211] [INFO] Booting worker with pid: 5211
[2024-04-04 10:39:20 +0200] [5212] [INFO] Booting worker with pid: 5212

(process:5220): dconf-CRITICAL **: 10:39:21.274: unable to create file '/home/pandora/.cache/dconf/user': Permission denied.  dconf will not work properly.
127.0.0.1 - - [04/Apr/2024 10:40:09] "POST /RPC2 HTTP/1.1" 200 -

[info-sic]

Reproducable for me:
restart VM (either via vCenter scheduled task or by hand)
clamAV does not come up as a selectable option in the "Advanced" list on submit.html and the worker produces no output

poetry run shudown
poetry run start update

voilá, clamAV appears in the list and reports in the analysis

[info-sic]

Q&D fix: changed the pandora.service for systemd to
ExecStart=/bin/bash -c "exec poetry run update --yes"
Voilá clamAV is enabled in pandora.
My best guess: clamd ist started via init.d and if not ready when systemd starts pandora, it will not "connect" to clamd.
Since poetry run update --yes takes much longer than start there's enough time to start clamd and pandora will connect.
OK for q&d but maybe I should investigate howto make pandora.service dependable of clamd already running...

[Rafiot]

poetry run start update will just run start, update will be ignored, and update doesn't start the clamd service.

But you're correct that if clamav isn't started when the systemd module for pandora starts, the clamav module will be disabled.

Seems the way to do that is to use Wants in the systemd file.