Skip to content

clamd doesn't start sometimes

Weird bug, sometimes the pixelated platform builds fail because clamd isn't running. Usually we restart the build and then everything works. from https://go.pixelated-project.org/go/tab/build/detail/pixelated-platform/1561/configure-leap_with_user-agent/1/configure-leap_install_user-agent:

23:28:03.823 + leap -v 2 test --continue
23:28:12.569  = [pixelated] PASS: Network > Can connect to internet?
23:28:12.569  = [pixelated] PASS: Network > Is stunnel running?
23:28:12.570  = [pixelated] PASS: Network > Is shorewall running?
23:28:12.570  = [pixelated] PASS: Network > Are server certificates valid?
23:28:12.570  = [pixelated] PASS: CouchDB > Are daemons running?
23:28:12.570  = [pixelated] PASS: CouchDB > Is CouchDB running?
23:28:12.570  = [pixelated] PASS: CouchDB > Do ACL users exist?
23:28:12.570  = [pixelated] PASS: CouchDB > Do required databases exist?
23:28:12.570  = [pixelated] PASS: CouchDB > Can records be created?
23:28:12.570  = [pixelated] PASS: Webapp > Can contact couchdb?
23:28:12.570  = [pixelated] PASS: Webapp > Can contact couchdb via haproxy?
23:28:12.570  = [pixelated] PASS: Webapp > Are daemons running?
23:28:12.571  = [pixelated] PASS: Webapp > Can access webapp?
23:28:12.571  = [pixelated] PASS: Webapp > Can create and authenticate and delete user via API?
23:28:12.571  = [pixelated] PASS: Webapp > Can sync Soledad?
23:28:12.571  = [pixelated] PASS: Mx > Can contact couchdb?
23:28:12.571  = [pixelated] PASS: Mx > Can contact couchdb via haproxy?
23:28:12.571  = [pixelated] SKIP: Mx > Can query identities db? [mx.rb:166]:
23:28:12.571  = [pixelated]   There are no identity documents yet.
23:28:12.571  = [pixelated] FAIL: Mx > Are MX daemons running? [mx.rb:64]:
23:28:12.571  = [pixelated]   No running process for ^/usr/sbin/clamd
23:28:12.571  = [pixelated] SKIP: Mx > Can postfix query leapmx? [mx.rb:166]:
23:28:12.572  = [pixelated]   There are no identity documents yet.
23:28:12.572  = [pixelated] PASS: Mx > Can deliver email?
23:28:12.572  = [pixelated] PASS: Pixelated > Are daemons running?
23:28:12.582  = [pixelated] PASS: Pixelated > can connect to useragent?
23:28:12.583  = [pixelated] PASS: Soledad > Is Soledad running?
23:28:12.583  = [pixelated] 26 tests: 21 passes, 2 skips, 0 warnings, 1 failures, 0 errors
23:28:12.846 [go] Current job status: failed.

some debug info, hopefully enough to fix it:

root@pixelated:~# systemctl status clamav-daemon
● clamav-daemon.service - Clam AntiVirus userspace daemon
   Loaded: loaded (/lib/systemd/system/clamav-daemon.service; enabled)
   Active: inactive (dead)
           start condition failed at Tue 2016-08-30 23:12:21 CEST; 10h ago
     Docs: man:clamd(8)
           man:clamd.conf(5)
           http://www.clamav.net/lang/en/doc/

root@pixelated:~# cat /lib/systemd/system/clamav-daemon.service
[Unit]
Description=Clam AntiVirus userspace daemon
Documentation=man:clamd(8) man:clamd.conf(5) http://www.clamav.net/lang/en/doc/
Requires=clamav-daemon.socket
# Check for database existence
ConditionPathExistsGlob=/var/lib/clamav/main.{c[vl]d,inc}
ConditionPathExistsGlob=/var/lib/clamav/daily.{c[vl]d,inc}

[Service]
ExecStart=/usr/sbin/clamd --foreground=true
# Reload the database
ExecReload=/bin/kill -USR2 $MAINPID
StandardOutput=syslog

[Install]
WantedBy=multi-user.target
Also=clamav-daemon.socket


/var/log/syslog.1:Aug 30 23:05:03 baseimage freshclam[24956]: ClamAV update process started at Tue Aug 30 23:05:03 2016
/var/log/syslog.1:Aug 30 23:05:07 baseimage clamav-milter[25532]: touch: cannot touch ‘/var/run/clamav/clamav-milter.pid’: No such file or directory
/var/log/syslog.1:Aug 30 23:05:07 baseimage clamav-milter[25532]: chown: cannot access ‘/var/run/clamav/clamav-milter.pid’: No such file or directory
/var/log/syslog.1:Aug 30 23:05:07 baseimage clamav-milter[25532]: Starting Sendmail milter plugin for ClamAV: clamav-milter.
/var/log/syslog.1:Aug 30 23:05:22 baseimage clamav-milter: ClamAV: mi_stop=1
/var/log/syslog.1:Aug 30 23:05:22 baseimage clamav-milter[26168]: Stopping Sendmail milter plugin for ClamAV: clamav-milter.
/var/log/syslog.1:Aug 30 23:05:22 baseimage clamav-milter[26287]: Starting Sendmail milter plugin for ClamAV: clamav-milter.
/var/log/syslog.1:Aug 30 23:12:45 baseimage freshclam[24956]: Downloading main.cvd [100%]
/var/log/syslog.1:Aug 30 23:13:09 baseimage freshclam[24956]: main.cvd updated (version: 57, sigs: 4218790, f-level: 60, builder: amishhammer)
/var/log/syslog.1:Aug 30 23:13:11 baseimage freshclam[24956]: Downloading daily.cvd [100%]
/var/log/syslog.1:Aug 30 23:13:12 baseimage freshclam[24956]: daily.cvd updated (version: 22157, sigs: 559188, f-level: 63, builder: neo)
/var/log/syslog.1:Aug 30 23:13:13 baseimage freshclam[24956]: Downloading bytecode.cvd [100%]
/var/log/syslog.1:Aug 30 23:13:13 baseimage freshclam[24956]: bytecode.cvd updated (version: 283, sigs: 53, f-level: 63, builder: neo)
/var/log/syslog.1:Aug 30 23:13:17 baseimage freshclam[24956]: Database updated (4778031 signatures) from db.local.clamav.net (IP: 212.227.138.145)
/var/log/syslog.1:Aug 30 23:13:17 baseimage freshclam[24956]: WARNING: Clamd was NOT notified: Can't connect to clamd through /var/run/clamav/clamd.ctl: No such file or directory
/var/log/syslog.1:Aug 30 23:45:01 pixelated CRON[5352]: (clamav) CMD ([ -x /usr/sbin/clamav-unofficial-sigs ] && /usr/sbin/clamav-unofficial-sigs)
/var/log/syslog.1:Aug 31 00:45:01 pixelated CRON[19110]: (clamav) CMD ([ -x /usr/sbin/clamav-unofficial-sigs ] && /usr/sbin/clamav-unofficial-sigs)
/var/log/syslog.1:Aug 31 01:45:01 pixelated CRON[949]: (clamav) CMD ([ -x /usr/sbin/clamav-unofficial-sigs ] && /usr/sbin/clamav-unofficial-sigs)
/var/log/syslog.1:Aug 31 02:45:01 pixelated CRON[14119]: (clamav) CMD ([ -x /usr/sbin/clamav-unofficial-sigs ] && /usr/sbin/clamav-unofficial-sigs)
/var/log/syslog.1:Aug 31 03:45:01 pixelated CRON[27273]: (clamav) CMD ([ -x /usr/sbin/clamav-unofficial-sigs ] && /usr/sbin/clamav-unofficial-sigs)
/var/log/syslog.1:Aug 31 04:45:01 pixelated CRON[7980]: (clamav) CMD ([ -x /usr/sbin/clamav-unofficial-sigs ] && /usr/sbin/clamav-unofficial-sigs)
/var/log/syslog.1:Aug 31 05:45:01 pixelated CRON[21137]: (clamav) CMD ([ -x /usr/sbin/clamav-unofficial-sigs ] && /usr/sbin/clamav-unofficial-sigs)


root@pixelated:~# grep -i clam /var/log/leap/deploy.log 
Aug 30 22:59:03 pixelated: Notice: /Stage[main]/Clamav::Daemon/File[/etc/default/clamav-daemon]/ensure: defined content as '{md5}dfda3b6786217d5556366cf9fb8265f6'
Aug 30 22:59:03 pixelated: Notice: /Stage[main]/Clamav::Milter/File[/etc/default/clamav-milter]/ensure: defined content as '{md5}43d85aa4a64e12dde926c4fa448adcd0'
Aug 30 23:04:40 pixelated: Notice: /Stage[main]/Clamav::Daemon/Package[arj]/ensure: ensure changed 'purged' to 'present'
Aug 30 23:05:09 pixelated: Notice: /Stage[main]/Clamav::Milter/Package[clamav-milter]/ensure: ensure changed 'purged' to 'present'
Aug 30 23:05:09 pixelated: Notice: /Stage[main]/Clamav::Milter/File[/etc/clamav/whitelisted_addresses]/ensure: defined content as '{md5}d41d8cd98f00b204e9800998ecf8427e'
Aug 30 23:05:22 pixelated: Notice: /Stage[main]/Clamav::Milter/Service[clamav-milter]: Triggered 'refresh' from 1 events
Aug 30 23:09:10 pixelated: Notice: /Stage[main]/Clamav::Milter/File[/etc/clamav/clamav-milter.conf]/content: content changed '{md5}16133f37014e3fe24b297819ef4b2695' to '{md5}55876e135eeeffc2540b83f8fb8eaba6'
Aug 30 23:10:38 pixelated: Notice: /Stage[main]/Clamav::Unofficial_sigs/Package[clamav-unofficial-sigs]/ensure: ensure changed 'purged' to 'present'
Aug 30 23:12:04 pixelated: Notice: /Stage[main]/Clamav::Daemon/File_line[enable_phishscanurls]/ensure: created
Aug 30 23:12:04 pixelated: Notice: /Stage[main]/Clamav::Daemon/File_line[clamav_daemon_tmp]/ensure: created
Aug 30 23:12:04 pixelated: Notice: /Stage[main]/Clamav::Daemon/File_line[clamav_LogSyslog_true]/ensure: created
Aug 30 23:12:04 pixelated: Notice: /Stage[main]/Clamav::Daemon/File[/var/lib/clamav/local.pdb]/ensure: defined content as '{md5}d57648d17b4503f4d25012046c917469'
Aug 30 23:12:04 pixelated: Notice: /Stage[main]/Clamav::Daemon/File_line[clamav_LogFile]/ensure: created
Aug 30 23:12:20 pixelated: Notice: /Stage[main]/Clamav::Daemon/File_line[clamav_MaxThreads]/ensure: created
Aug 30 23:12:21 pixelated: Notice: /Stage[main]/Clamav::Daemon/Service[clamav-daemon]/ensure: ensure changed 'stopped' to 'running'
Aug 30 23:18:54 pixelated: Notice: /Stage[main]/Clamav::Unofficial_sigs/Package[socat]/ensure: ensure changed 'purged' to 'present'
Aug 30 23:21:04 pixelated: Notice: /Stage[main]/Clamav::Unofficial_sigs/File[/etc/clamav-unofficial-sigs.conf.d/01-leap.conf]/ensure: defined content as '{md5}94a1f8fd250611d37bacb8f386a8f0be'
Aug 30 23:22:15 pixelated: Notice: /Stage[main]/Site_postfix::Mx/Postfix::Config[smtpd_milters]/Exec[postconf -e smtpd_milters='unix:/run/clamav/milter.ctl,unix:/run/opendkim/opendkim.sock']/returns: executed successfully
Aug 30 23:22:48 pixelated: Notice: /Stage[main]/Clamav::Daemon/File[/var/run/clamav]/group: group changed 'root' to 'postfix'
Aug 30 23:22:48 pixelated: Notice: /Stage[main]/Clamav::Daemon/File[/var/run/clamav]/mode: mode changed '0755' to '0750'

from the above puppet log it looks like the ownership and permissions of '/var/run/clamav' is set after starting clamd.

starting it (8h) later succeeds:

root@pixelated:~# systemctl start clamav-daemon
root@pixelated:~# systemctl status clamav-daemon
● clamav-daemon.service - Clam AntiVirus userspace daemon
   Loaded: loaded (/lib/systemd/system/clamav-daemon.service; enabled)
   Active: active (running) since Wed 2016-08-31 09:26:02 CEST; 1s ago
     Docs: man:clamd(8)
           man:clamd.conf(5)
           http://www.clamav.net/lang/en/doc/
 Main PID: 5362 (clamd)
   CGroup: /system.slice/clamav-daemon.service
           └─5362 /usr/sbin/clamd --foreground=true

(from redmine: created on 2016-08-31, closed on 2016-09-08, relates #8048 (closed))