[Pkg-clamav-devel] Bug#749027: Bug#749027: The ClamAV daemon stops working.

Tue May 27 10:39:18 UTC 2014

Hi Jim,

On 27.05.2014 07:18, Jim Barber wrote:
> The ClamAV daemon hung again after rolling back to 0.98.3.

You could try it with 0.98.1, but I'm not sure if that would help.

> It went longer than a day this time, but still less than 2 days.
> Here's the havp log (with URL removed).
>
>      25/05/2014 08:51:59 === Starting HAVP Version: 0.92
>      25/05/2014 08:51:59 Running as user: havp, group: havp
>      25/05/2014 08:51:59 Use parent proxy: localhost:3130
>      25/05/2014 08:51:59 --- Initializing Clamd Socket Scanner
>      25/05/2014 08:51:59 Clamd Socket Scanner passed EICAR virus test
> (Eicar-Test-Signature)
>      25/05/2014 08:51:59 --- All scanners initialized
>      25/05/2014 08:51:59 Process ID: 23108
>      26/05/2014 23:20:04 Error: Some scanner has timed out! (lasturl:
> <url removed>)
>
> The complete ClamAV log from when I started it after backing out to the
> older
> version, to when I restarted it when I noticed it was hung is as follows:
>
>      Sun May 25 08:51:01 2014 -> +++ Started at Sun May 25 08:51:01 2014
[...]
>      Mon May 26 15:59:42 2014 -> SelfCheck: Database status OK.
>      Mon May 26 16:52:08 2014 -> Restarting on-access scan
>      Mon May 26 16:52:09 2014 -> Reading databases from /var/lib/clamav
>      Mon May 26 16:52:13 2014 -> Database correctly reloaded (3387113
> signatures)
>      Mon May 26 16:52:13 2014 -> ERROR: ScanOnAccess: fanotify_init
> failed: Operation not permitted
>      Mon May 26 16:52:13 2014 -> ScanOnAccess: clamd must be started by
> root
>      Mon May 26 17:52:13 2014 -> SelfCheck: Database status OK.
>      Mon May 26 18:52:13 2014 -> SelfCheck: Database status OK.
>      Mon May 26 19:52:13 2014 -> SelfCheck: Database status OK.
>      Mon May 26 21:52:05 2014 -> SelfCheck: Database status OK.
>      Mon May 26 22:52:19 2014 -> SelfCheck: Database modification
> detected. Forcing reload.
>      Mon May 26 22:52:19 2014 -> Restarting on-access scan
>      Mon May 26 22:52:19 2014 -> Reading databases from /var/lib/clamav
>      Mon May 26 22:52:23 2014 -> Database correctly reloaded (3387525
> signatures)
>      Mon May 26 22:52:23 2014 -> Restarting on-access scan
>      Tue May 27 06:39:04 2014 -> +++ Started at Tue May 27 06:39:04 2014
>
> It looks like it hung on 'Restarting on-access scan'.
> It didn't follow up with the following messages that usually
> happen seconds after:
>
>      -> Reading databases from /var/lib/clamav
>      -> Database correctly reloaded ([0-9]+ signatures)

I think the problem here is that there is a second 'Restarting on-access 
scan' message only 4 seconds after another one and without the usual 
'ERROR: ScanOnAccess: fanotify_init [...]' between them.

This looks as if the reload is started again, while the previous reload 
is not yet finished. Probably this should not happen, as it seems to 
cause a deadlock.

> I used to run this version of the ClamAV daemon without issue.
> So maybe it is something to do with getting freshclam updates working
> again.
> I went back through my freshclam logs and it was fine up until the
> evening of
> Thu Apr 24th where I started getting the freshclam update error.
> Prior to that I wasn't getting hangs either though.
>
> Actually, when I ran 'dpkg-reconfigure clamav-freshclam' to fix the
> freshclam
> update errors, one of the questions asked was:
>
>      Should clamd be notified after updates?
>
> I think this may have been 'No' before as I thought that was strange I
> would
> leave it set that way and I selected 'Yes'.
> So it is likely to be this that is now causing my hangs I guess.

This may be, as the hang happens precisely when clamd itself notices a 
'Database modification' and triggers a reload, likely just before 
freshclam triggers a reload.

Nonetheless I think this is a bug in clamd, as it should handle this 
gracefully.

> Looking back over my past logs, the 'Restarting on-access scan' message
> used to happen infrequently:
>
>      Fri Apr 25 00:01:13 2014 -> Restarting on-access scan
>      Tue Apr 29 13:41:24 2014 -> Restarting on-access scan
>      Mon May  5 00:07:08 2014 -> Restarting on-access scan
>      Thu May  8 19:46:58 2014 -> Restarting on-access scan
>      Sun May 11 18:47:52 2014 -> Restarting on-access scan
>      Fri May 16 17:48:07 2014 -> Restarting on-access scan
>      Mon May 19 23:15:10 2014 -> Restarting on-access scan
>
> Then after the reconfigure of clamav-freshclam it is regular:
>
>      Tue May 20 23:49:57 2014 -> Restarting on-access scan
>      Wed May 21 00:50:01 2014 -> Restarting on-access scan
>      Wed May 21 01:50:07 2014 -> Restarting on-access scan
>      Wed May 21 01:50:12 2014 -> Restarting on-access scan
>      Wed May 21 22:44:12 2014 -> Restarting on-access scan
>      Wed May 21 23:44:06 2014 -> Restarting on-access scan
>      Thu May 22 04:44:15 2014 -> Restarting on-access scan
>      Thu May 22 04:44:19 2014 -> Restarting on-access scan
>      Thu May 22 06:44:23 2014 -> Restarting on-access scan
>      Thu May 22 06:44:28 2014 -> Restarting on-access scan
>      Thu May 22 18:03:34 2014 -> Restarting on-access scan
>      Thu May 22 18:03:38 2014 -> Restarting on-access scan
>      Thu May 22 23:03:48 2014 -> Restarting on-access scan
>      Thu May 22 23:03:52 2014 -> Restarting on-access scan
>      Fri May 23 01:03:56 2014 -> Restarting on-access scan
>      Fri May 23 01:04:01 2014 -> Restarting on-access scan
>      Fri May 23 08:26:56 2014 -> Restarting on-access scan
>      Fri May 23 10:25:41 2014 -> Restarting on-access scan
>      Fri May 23 16:25:56 2014 -> Restarting on-access scan
>      Fri May 23 23:26:10 2014 -> Restarting on-access scan
>      Fri May 23 23:26:14 2014 -> Restarting on-access scan
>      Sat May 24 04:26:28 2014 -> Restarting on-access scan
>      Sat May 24 11:26:42 2014 -> Restarting on-access scan
>      Sat May 24 16:26:51 2014 -> Restarting on-access scan
>      Sat May 24 16:26:55 2014 -> Restarting on-access scan
>      Sat May 24 21:17:05 2014 -> Restarting on-access scan
>      Sat May 24 23:27:09 2014 -> Restarting on-access scan
>      Sun May 25 05:27:23 2014 -> Restarting on-access scan
>      and so on...
>
> So this may be a bug that has always been around but only triggered
> when freshclam prompts the ClamAV daemon to reload its definitions.
>
> What steps would you like me to do now?
>
> Shall I upgrade to 0.98.4~rc1 again and reconfigure freshclam to no longer
> notify the ClamAV daemon when an update is available?

Yes, please try this and let us know, if it helps.

Also could you please check, if /var/log/clamav/freshclam.log contains 
'Clamd successfully notified about the update.' around the time 'Mon May 
26 22:52:23 2014', where the hang happened, or if there is a related 
error message.

> Or shall I upgrade and leave the notificatons on and turn on some verbose
> debugging messages in ClamAV to see if something more useful is logged?

You can set 'Debug true' in clamd.conf.

> Is the problem perhaps related to these messages?
>
>      -> ERROR: ScanOnAccess: fanotify_init failed: Operation not permitted
>      -> ScanOnAccess: clamd must be started by root

I don't think this is related, but if the above doesn't help, you could 
try disabling ScanOnAccess or running clamd as root.

Best regards,
Andreas