Clamav log rotation failing

pollux commented 3 years ago

Classification

[X] Minor bug

Reproducibility

[x] I didn’t try

Docker information

docker info:

Client:
 Debug Mode: false

Server:
 Containers: 6
  Running: 6
  Paused: 0
  Stopped: 0
 Images: 15
 Server Version: 19.03.13
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 8fba4e9a7d01810a393d5d25a3621dc101981175
 runc version: dc9208a3303feef5b3839f4323d9beb36df0a9dd
 init version: fec3683
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 4.19.0-10-amd64
 Operating System: Debian GNU/Linux 10 (buster)
 OSType: linux
 Architecture: x86_64
 CPUs: 2
 Total Memory: 3.854GiB
 Name: mail
 ID: PZ7E:7IHS:BBYF:LDZ4:6PNM:KVCZ:S3SZ:LTM4:ZXRY:D72T:Z2F5:RI5I
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

WARNING: No swap limit support

docker images mailserver2/mailserver --digests --filter "dangling=false":

REPOSITORY               TAG                 DIGEST                                                                    IMAGE ID            CREATED             SIZE
mailserver2/mailserver   latest              sha256:9839a6a9593f28ce8099be9faad37f579c9aba58e12ebd2274610c4407cf284f   51798da0fc86        7 weeks ago         311MB

Description

I recently migrated from hardware/mailserver to mailserver2/mailserver. Now i sometimes get emails with cron errors when a clamav log rotation occurs.

Subject: Cron <root@mail> test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ) Body:

/etc/cron.daily/logrotate:
invoke-rc.d: could not determine current runlevel
invoke-rc.d: policy-rc.d denied execution of reload-log.
invoke-rc.d: could not determine current runlevel
invoke-rc.d: policy-rc.d denied execution of reload-log.

Occurred on:

27.09.2020 @08:51 AM (UTC+1)
04.10.2020 @08:51 AM (UTC+1)
11.10.2020 @08:43 AM (UTC+1)

Expected results

Not receiving such emails.

Actual results

Receiving such emails.

Debugging information

docker logs mailserver

Configuration (docker-compose.yml, traefik.toml...etc)

/

AndrewSav commented 3 years ago

I did a bit of investigation around this and here are my findings:

The error produced are caused by this piece of code:

https://salsa.debian.org/clamav-team/clamav/-/blob/6dd3b97af8d02675c88d4f9d59a3c9407878a5be/debian/clamav-daemon.postinst.in#L433

If you run: invoke-rc.d clamav-daemon reload-log in the container you will get the same error message. The error message happens twice because it's being run for clamav-daemon and clamav-freshclam.

invoke-rc.d has action as the second parameter (see here) and this action cannot be reload-log. In earlier versions of Debian it used to work - it would execute an action even if it does not know that particular action, the current version is stricter, it simply fails.

My conclusion so, that this is a problem with clamav-daemon Debian package. Having said that, non-systemd usage is not very prevalent, and this is probably the reason it was not fixed.

It looks like tomav project went as far as commenting out this line completely to suppress the errors.

I guess we could do the same, but it may be worth raising this issue first with Debian, although I'm not very optimistic about success of that.

AndrewSav commented 3 years ago

So I talked to some Debian guy on IRC, and it turns out that in fact invoke-rc.d works fine for unknown actions.

I still do not understand how this ever worked but people did report before similar but not quite the same issue. The advice was to ignore it.

Now I had a good look at what's going on in those scripts, and here is my best understanding:

There is a daily cronjob that runs logrotate. logrotate only rotates logs as per configuration, so it does not have to happen every day if criteria is no met. When it does, it first does the rotation, and then it reaches out to the process the logs belong to, so that it could recycle and use new logs.

For clamav this is configured by the Debian package, in the postinst script linked above. This is what logrotate calls according to this configuration:

if [ -d /run/systemd/system ]; then
    systemctl -q is-active clamav-daemon && systemctl kill --signal=SIGHUP clamav-daemon || true
else
    invoke-rc.d clamav-daemon reload-log > /dev/null || true
fi

So the thing here is: the first part is using systemd that we do not have, and the second uses system V init that we do not have either. There are some issues with policy-rc.d, but even if those are solved I cannot see how this can work, because ultimately it will call /etc/init.d/clamav-daemon, which will refuse to reload config, if run in foreground!

The source code of that is here: https://salsa.debian.org/clamav-team/clamav/-/blob/6dd3b97af8d02675c88d4f9d59a3c9407878a5be/debian/clamav-daemon.init.in

I think this code is reflection of older supervisor model, that does not apply to s6 - it does quite a few things differently.

All in all this is quite a kerfuffle. I think that probably most straightforward fix, is to sed the logrotate configuration like this:

For /etc/logrotate.d/clamav-daemon, change:

invoke-rc.d clamav-daemon reload-log > /dev/null to pkill -HUP -F /var/run/clamav/clamd.pid clamd > /dev/null 2>&1

For /etc/logrotate.d/clamav-freshclam, change:

invoke-rc.d clamav-freshclam reload-log > /dev/null to pkill -HUP -F /var/run/clamav/freshclam.pid freshclam 2> /dev/null

AndrewSav commented 3 years ago

@SaraSmiseth @sknight80 @ksylvan, guys, how are your skills in this department? Can you review my findings please?

sknight80 commented 3 years ago

wow, thank you so much, for digging into the problem. Personally, I don't have this detailed knowledge but I will ask around in my network who potentially has.

On Mon, Oct 12, 2020 at 3:50 AM Andrew Savinykh notifications@github.com wrote:

@SaraSmiseth https://github.com/SaraSmiseth @sknight80 https://github.com/sknight80 @ksylvan https://github.com/ksylvan, guys, how are your skills in this department? Can you review my findings please?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/mailserver2/mailserver/issues/24#issuecomment-706944360, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABB5S2BIH2EFAHR6FM2CVBLSKKYMJANCNFSM4SLURRPQ .

SaraSmiseth commented 3 years ago

I think that probably most straightforward fix, is to sed the logrotate configuration like this:

For /etc/logrotate.d/clamav-daemon, change:

invoke-rc.d clamav-daemon reload-log > /dev/null to pkill -HUP -F /var/run/clamav/clamd.pid clamd > /dev/null 2>&1

For /etc/logrotate.d/clamav-freshclam, change:

invoke-rc.d clamav-freshclam reload-log > /dev/null to pkill -HUP -F /var/run/clamav/freshclam.pid freshclam 2> /dev/null

Yep thanks for your work. I don't have a lot of knowledge of this either. As far as I understand it, it should be fine doing what you suggested. Just to be sure: You want to replace the second version of reloading the service that causes the error by using pkill to reload the service right?

AndrewSav commented 3 years ago

Yes, because this is what init.d scripts for clamav-daemon and clamav-freshclam respectively are using.

sknight80 commented 3 years ago

@AndrewSav I saw the following settings in calmd

...
Foreground BOOL
Don't fork into background.
Default: no
...
LogRotate BOOL
Rotate log file. Requires LogFileMaxSize option set prior to this option.
Default: no

Do you think, if we create this kind of config file, we could remove the logrotation settings for clamd?

AndrewSav commented 3 years ago

@sknight80 may be. There is probably a reason why debian created separate log rotate scripts and did not use this built-in facility. In addition it is not clear if these settings affect clamd only or freshclam as well. Additional complication is that "unofficial signatures" script also doing something with logrotate. It would be good to understand what it is if we are touch this area more.

AndrewSav commented 3 years ago

Guys, if you've been running with clamav on (I haven't been) could you please see if you have rotated log files with the current settings and report back:

docker exec -it mailserver ls -al /var/log/clamav/

SaraSmiseth commented 3 years ago

My containers were created 3 days ago.

drwxr-xr-x 1 clamav clamav  4096 Oct 11 06:33 .
drwxr-xr-x 1 root   root    4096 Oct 11 06:33 ..
-rw-r----- 1 clamav adm        0 Oct 11 06:33 clamav.log
-rw-r----- 1 clamav clamav  7828 Oct 13 04:15 clamav.log.1
-rw-r----- 1 clamav adm        0 Oct 11 06:33 freshclam.log
-rw-r----- 1 clamav clamav 10082 Oct 12 22:59 freshclam.log.1

AndrewSav commented 3 years ago

From @pollux:

root@mail:/home/pollux# docker exec -it mailserver ls -al /var/log/clamav/
total 32
drwxr-xr-x 1 clamav clamav 4096 Oct 11 06:43 .
drwxr-xr-x 1 root   root   4096 Oct  1 06:28 ..
-rw-r----- 1 clamav adm       0 Oct 11 06:43 clamav.log
-rw-r----- 1 clamav adm       0 Oct  4 06:51 clamav.log.1
-rw-r----- 1 clamav adm      20 Sep 27 06:51 clamav.log.2.gz
-rw-r----- 1 clamav clamav 2691 Oct  4 06:08 clamav.log.3.gz
-rw-r----- 1 clamav adm       0 Oct 11 06:43 freshclam.log
-rw-r----- 1 clamav adm       0 Oct  4 06:51 freshclam.log.1
-rw-r----- 1 clamav adm      20 Sep 27 06:51 freshclam.log.2.gz
-rw-r----- 1 clamav clamav 3201 Oct  4 06:08 freshclam.log.3.gz

Internal LogRotate is by default true in clamd: cat /etc/clamav/clamd.conf | grep -i logrotate
Internal one files would look differently
This probably means that internal ones do not kick in if external logrorate is doing its job

We probably could disabled debian logrotate for clamd/freshclam completely but I'm not sure what the built-in does, and why debian chose to use external one. I'm inclined to keep using external one...

AndrewSav commented 3 years ago

s6-svc -h /services/clamd is s6 native way to send HUP signal to supervised processes. Should use that instead of pkill.

sknight80 commented 3 years ago

Here is mine (2 weeks old container):

root@mail:/var/log/clamav# ls -la
total 52
drwxr-xr-x 1 clamav clamav  4096 Oct 12 06:29 .
drwxr-xr-x 1 root   root    4096 Oct  4 06:35 ..
-rw-r----- 1 clamav adm        0 Oct 12 06:29 clamav.log
-rw-r----- 1 clamav adm        0 Oct  4 06:35 clamav.log.1
-rw-r----- 1 clamav clamav  3869 Oct 12 05:45 clamav.log.2.gz
-rw-r----- 1 clamav adm     3505 Oct 13 12:30 freshclam.log
-rw-r----- 1 clamav adm    19788 Oct 12 06:29 freshclam.log.1
-rw-r----- 1 clamav clamav  1790 Oct  4 06:35 freshclam.log.2.gz

I agreed with @AndrewSav . If the s6-svc command works correctly, then we should go with that. I feel that the pkill is for very last case...

SaraSmiseth commented 3 years ago

I also agree on using s6's way to send HUP. I think that is the cleanest solution.

mailserver2 / mailserver