freshclam AV stops updating on my ReadyNAS

---

scrjs wrote: Which log was rotated?  Is there another mechanism to get this information?

Your first status includes

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

Systemd consolidates the logs, and that is what was rotated.  There's no other mechanism.

Thanks for letting me know StephenB 

---

StephenB wrote:

---

scrjs wrote: Which log was rotated?  Is there another mechanism to get this information?

Your first status includes

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

Systemd consolidates the logs, and that is what was rotated.  There's no other mechanism.

---

I'll check again in a few days

---

scrjs wrote:

Hi StephenB 

Many thanks for the continued discussion below

---

StephenB wrote:

The second status looks correct to me. 

 

It does look like the service had failed for some reason earlier, though there's not enough info to say why.  I'm not sure if the log rotation would have given more clues or not.

---

Which log was rotated?  Is there another mechanism to get this information?

I will check

# systemctl status clamav-freshclam.service

In a few days...

---

Hi StephenB 

I rebooted the ReadyNAS yesterday and just checked the status and noted the failure in 

clamav-freshclam.service - ClamAV virus database updater

This service yesterday, after the reboot, showed

root@xxxxxReadyNAS:~# systemctl status clamav-freshclam.service
● clamav-freshclam.service - ClamAV virus database updater
   Loaded: loaded (/lib/systemd/system/clamav-freshclam.service; static; vendor preset: disabled)
   Active: inactive (dead)

which looks correct.  Checking just now (Feb 21) it shows

root@xxxxxReadyNAS:~# systemctl status clamav-freshclam.service
● clamav-freshclam.service - ClamAV virus database updater
   Loaded: loaded (/lib/systemd/system/clamav-freshclam.service; static; vendor preset: disabled)
   Active: failed (Result: exit-code) since Sat 2021-02-20 16:55:56 AEDT; 19h ago
 Main PID: 5129 (code=exited, status=1/FAILURE)

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

Unfortunatly again no log info.

Ran freshclam -v with the following results and then checked clamav-freshclam.service with the following results with the service stilled in FAILED status

root@xxxxxReadyNAS:~# freshclam -v
Current working dir is /var/lib/clamav
Max retries == 5
ClamAV update process started at Sun Feb 21 12:29:49 2021
Using IPv6 aware code
Querying current.cvd.clamav.net
TTL: 1666
Software version from DNS: 0.103.1
main.cvd version from DNS: 59
main.cld is up to date (version: 59, sigs: 4564902, f-level: 60, builder: sigmgr)
daily.cvd version from DNS: 26086
Retrieving http://database.clamav.net/daily-26086.cdiff
Trying to download http://database.clamav.net/daily-26086.cdiff (IP: 104.16.218.84)
Downloading daily-26086.cdiff [100%]
cdiff_apply: Parsed 4327 lines and executed 4327 commands
Loading signatures from daily.cld
Properly loaded 3982440 signatures from new daily.cld
daily.cld updated (version: 26086, sigs: 4008487, f-level: 63, builder: raynman)
Querying daily.26086.93.1.0.6810DA54.ping.clamav.net
Can't query daily.26086.93.1.0.6810DA54.ping.clamav.net
bytecode.cvd version from DNS: 332
bytecode.cld is up to date (version: 332, sigs: 93, f-level: 63, builder: awillia2)
Database updated (8573482 signatures) from database.clamav.net (IP: 104.16.218.84)
Clamd successfully notified about the update.

root@xxxxxReadyNAS:~# systemctl status clamav-freshclam.service
● clamav-freshclam.service - ClamAV virus database updater
   Loaded: loaded (/lib/systemd/system/clamav-freshclam.service; static; vendor preset: disabled)
   Active: failed (Result: exit-code) since Sat 2021-02-20 16:55:56 AEDT; 19h ago
 Main PID: 5129 (code=exited, status=1/FAILURE)

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.

Is any way to detail detail on what happened to "clamav-freshclam.service - ClamAV virus database updater" cause the failure "failed (Result: exit-code) since Sat 2021-02-20 16:55:56 AEDT" ?

Are you seeing any errors in system.log, kernel.log, system-journal.log around the time that that service failed?

---

StephenB wrote:

Are you seeing any errors in system.log, kernel.log, system-journal.log around the time that that service failed?

---

Hi StephenB 

Can you please let me know the path to these logs?

I can't find them...

Also just checked the commands and this time I have some log info before they rotated and see the following (time now is 17:58 on Feb 22) with a failue in ClamAV virus database updater

root@xxxxxReadyNAS:~# systemctl status clamav-freshclam.service
● clamav-freshclam.service - ClamAV virus database updater
   Loaded: loaded (/lib/systemd/system/clamav-freshclam.service; static; vendor preset: disabled)
   Active: failed (Result: exit-code) since Mon 2021-02-22 17:17:34 AEDT; 35min ago
 Main PID: 4077 (code=exited, status=1/FAILURE)

Feb 22 17:17:34 xxxxxReadyNAS systemd[1]: Starting ClamAV virus database updater...
Feb 22 17:17:34 xxxxxReadyNAS freshclam[4077]: ClamAV update process started at Mon Feb 22 17:17:34 2021
Feb 22 17:17:34 xxxxxReadyNAS freshclam[4077]: main.cld is up to date (version: 59, sigs: 4564902, f-level: 60, builder: sigmgr)
Feb 22 17:17:34 xxxxxReadyNAS freshclam[4077]: daily.cld is up to date (version: 26087, sigs: 4008904, f-level: 63, builder: raynman)
Feb 22 17:17:34 xxxxxReadyNAS freshclam[4077]: bytecode.cld is up to date (version: 332, sigs: 93, f-level: 63, builder: awillia2)
Feb 22 17:17:34 xxxxxReadyNAS systemd[1]: clamav-freshclam.service: Main process exited, code=exited, status=1/FAILURE
Feb 22 17:17:34 xxxxxReadyNAS systemd[1]: Failed to start ClamAV virus database updater.
Feb 22 17:17:34 xxxxxReadyNAS systemd[1]: clamav-freshclam.service: Unit entered failed state.
Feb 22 17:17:34 xxxxxReadyNAS systemd[1]: clamav-freshclam.service: Failed with result 'exit-code'.


root@xxxxxReadyNAS:~# systemctl status clamav-daemon.service
● clamav-daemon.service - Clam AntiVirus userspace daemon
   Loaded: loaded (/lib/systemd/system/clamav-daemon.service; enabled; vendor preset: disabled)
   Active: active (running) since Mon 2021-02-22 17:01:22 AEDT; 52min ago
 Main PID: 3329 (clamd)
   CGroup: /system.slice/clamav-daemon.service
           └─3329 /usr/sbin/clamd --foreground=true --config-file=/etc/clamav/clamd.conf

Feb 22 17:13:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:13:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:23:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:23:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:33:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:33:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:43:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:43:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:53:05 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:53:05 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.


root@xxxxxReadyNAS:~# systemctl status clamav-daemon.service
● clamav-daemon.service - Clam AntiVirus userspace daemon
   Loaded: loaded (/lib/systemd/system/clamav-daemon.service; enabled; vendor preset: disabled)
   Active: active (running) since Mon 2021-02-22 17:01:22 AEDT; 52min ago
 Main PID: 3329 (clamd)
   CGroup: /system.slice/clamav-daemon.service
           └─3329 /usr/sbin/clamd --foreground=true --config-file=/etc/clamav/clamd.conf

Feb 22 17:13:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:13:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:23:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:23:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:33:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:33:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:43:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:43:04 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:53:05 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.
Feb 22 17:53:05 xxxxxReadyNAS clamd[3329]: SelfCheck: Database status OK.

Ran freshclam -v and all appears up to date

root@xxxxxReadyNAS:~# freshclam -v
Current working dir is /var/lib/clamav
Max retries == 5
ClamAV update process started at Mon Feb 22 18:04:29 2021
Using IPv6 aware code
Querying current.cvd.clamav.net
TTL: 548
Software version from DNS: 0.103.1
main.cvd version from DNS: 59
main.cld is up to date (version: 59, sigs: 4564902, f-level: 60, builder: sigmgr)
daily.cvd version from DNS: 26087
daily.cld is up to date (version: 26087, sigs: 4008904, f-level: 63, builder: raynman)
bytecode.cvd version from DNS: 332
bytecode.cld is up to date (version: 332, sigs: 93, f-level: 63, builder: awillia2)

Thoughts?

---

scrjs wrote:

---

StephenB wrote:

Are you seeing any errors in system.log, kernel.log, system-journal.log around the time that that service failed?

---

Hi StephenB 

Can you please let me know the path to these logs?

I can't find them...

Download the log zip file from the NAS web ui.  These logs are extracted from the systemd journal when you download the zip - they don't exist in the OS partition.

You could also attempt to search the journal directly with journalctl, but there's a lot of stuff in there, so you'd want to filter the search.  That could result in missing some errors.

---

scrjs wrote:

---

StephenB wrote:

Are you seeing any errors in system.log, kernel.log, system-journal.log around the time that that service failed?

---

Hi StephenB 

Also just checked the commands and this time I have some log info before they rotated and see the following (time now is 17:58 on Feb 22) with a failue in ClamAV virus database updater

root@xxxxxReadyNAS:~# systemctl status clamav-freshclam.service
● clamav-freshclam.service - ClamAV virus database updater
   Loaded: loaded (/lib/systemd/system/clamav-freshclam.service; static; vendor preset: disabled)
   Active: failed (Result: exit-code) since Mon 2021-02-22 17:17:34 AEDT; 35min ago
 Main PID: 4077 (code=exited, status=1/FAILURE)

Thoughts?

 

---

If you manually start the service with systemctl start clamav-freshclam.service do you see the same failure?

Hi StephenB 

I did a log update yesterday that seems to have been lost. 

What I can confirm is that when the clamav-freshclam.service - ClamAV virus database updater is in a FAILED status, a systemctl start clamav-freshclam.service does in fact restart the service.

Since that start after it failed the services continues to run as noted below and updated my AV this morning successfully

root@xxxxxReadyNAS:~# systemctl status clamav-freshclam.service
● clamav-freshclam.service - ClamAV virus database updater
   Loaded: loaded (/lib/systemd/system/clamav-freshclam.service; static; vendor preset: disabled)
   Active: inactive (dead) since Wed 2021-02-24 08:24:18 AEDT; 4h 51min ago
  Process: 5693 ExecStart=/usr/bin/freshclam --quiet (code=exited, status=0/SUCCESS)
 Main PID: 5693 (code=exited, status=0/SUCCESS)

Feb 24 08:22:40 xxxxxReadyNAS systemd[1]: Starting ClamAV virus database updater...
Feb 24 08:22:44 xxxxxReadyNAS freshclam[5693]: ClamAV update process started at Wed Feb 24 08:22:44 2021
Feb 24 08:22:44 xxxxxReadyNAS freshclam[5693]: main.cld is up to date (version: 59, sigs: 4564902, f-level: 60, builder: sigmgr)
Feb 24 08:22:46 xxxxxReadyNAS freshclam[5693]: Downloading daily-26089.cdiff [100%]
Feb 24 08:24:03 xxxxxReadyNAS freshclam[5693]: daily.cld updated (version: 26089, sigs: 4000162, f-level: 63, builder: raynman)
Feb 24 08:24:09 xxxxxReadyNAS freshclam[5693]: Can't query daily.26089.93.1.0.6810DA54.ping.clamav.net
Feb 24 08:24:09 xxxxxReadyNAS freshclam[5693]: bytecode.cld is up to date (version: 332, sigs: 93, f-level: 63, builder: awillia2)
Feb 24 08:24:17 xxxxxReadyNAS freshclam[5693]: Database updated (8565157 signatures) from database.clamav.net (IP: 104.16.218.84)
Feb 24 08:24:17 xxxxxReadyNAS freshclam[5693]: Clamd successfully notified about the update.
Feb 24 08:24:18 xxxxxReadyNAS systemd[1]: Started ClamAV virus database updater.

Netgear are asking for logs, however we have always seens that this failure occurs without any notification so log collection before rotation is difficult.

Thoughts...

---

scrjs wrote:

Netgear are asking for logs, however we have always seens that this failure occurs without any notification so log collection before rotation is difficult.

 

Thoughts...

 

---

They are apparently actively working on a hot fix, so perhaps you should just restart the service manually if you see it fails again.

How quickly are your logs rotating?  (journalctl will tell you the oldest log entry, since by default it lists the oldest first).

Hi StephenB 

---

StephenB wrote:

---

scrjs wrote:

Netgear are asking for logs, however we have always seens that this failure occurs without any notification so log collection before rotation is difficult.

 

Thoughts...

 

---

They are apparently actively working on a hot fix, so perhaps you should just restart the service manually if you see it fails again.

 

How quickly are your logs rotating?  (journalctl will tell you the oldest log entry, since by default it lists the oldest first).

---

Yes I was aware Netgear are working on a Hotfix so you suggestion makes sense.

I just ran journalctl and currently it suggests

-- Logs begin at Mon 2021-02-22 21:30:50 AEDT, end at Wed 2021-02-24 22:13:22 AEDT. --

The begin date is just after a boot of the NAS so they have not yet rotated.

Just checked systemctl status clamav-freshclam.service which continues to run as noted below 

root@xxxxxReadyNAS:~# systemctl status clamav-freshclam.service
● clamav-freshclam.service - ClamAV virus database updater
   Loaded: loaded (/lib/systemd/system/clamav-freshclam.service; static; vendor preset: disabled)
   Active: inactive (dead) since Wed 2021-02-24 08:24:18 AEDT; 4h 51min ago
  Process: 5693 ExecStart=/usr/bin/freshclam --quiet (code=exited, status=0/SUCCESS)
 Main PID: 5693 (code=exited, status=0/SUCCESS)

Feb 24 08:22:40 xxxxxReadyNAS systemd[1]: Starting ClamAV virus database updater...
Feb 24 08:22:44 xxxxxReadyNAS freshclam[5693]: ClamAV update process started at Wed Feb 24 08:22:44 2021
Feb 24 08:22:44 xxxxxReadyNAS freshclam[5693]: main.cld is up to date (version: 59, sigs: 4564902, f-level: 60, builder: sigmgr)
Feb 24 08:22:46 xxxxxReadyNAS freshclam[5693]: Downloading daily-26089.cdiff [100%]
Feb 24 08:24:03 xxxxxReadyNAS freshclam[5693]: daily.cld updated (version: 26089, sigs: 4000162, f-level: 63, builder: raynman)
Feb 24 08:24:09 xxxxxReadyNAS freshclam[5693]: Can't query daily.26089.93.1.0.6810DA54.ping.clamav.net
Feb 24 08:24:09 xxxxxReadyNAS freshclam[5693]: bytecode.cld is up to date (version: 332, sigs: 93, f-level: 63, builder: awillia2)
Feb 24 08:24:17 xxxxxReadyNAS freshclam[5693]: Database updated (8565157 signatures) from database.clamav.net (IP: 104.16.218.84)
Feb 24 08:24:17 xxxxxReadyNAS freshclam[5693]: Clamd successfully notified about the update.
Feb 24 08:24:18 xxxxxReadyNAS systemd[1]: Started ClamAV virus database updater.

I hope the hotfix will be available soon...

---

scrjs wrote:

Hi StephenB 

---

I just ran journalctl and currently it suggests

-- Logs begin at Mon 2021-02-22 21:30:50 AEDT, end at Wed 2021-02-24 22:13:22 AEDT. --

The begin date is just after a boot of the NAS so they have not yet rotated.

The journal doesn't start fresh when the NAS reboots.  2 days isn't much retention, my main NAS goes back about a month.

Have you enabled the audit service?  Just wondering what is generating so many log entries.

Hi StephenB 

---

StephenB wrote:

---

scrjs wrote:

Hi StephenB 

---

I just ran journalctl and currently it suggests

-- Logs begin at Mon 2021-02-22 21:30:50 AEDT, end at Wed 2021-02-24 22:13:22 AEDT. --

The begin date is just after a boot of the NAS so they have not yet rotated.

The journal doesn't start fresh when the NAS reboots.  2 days isn't much retention, my main NAS goes back about a month.

 

Have you enabled the audit service?  Just wondering what is generating so many log entries.

---

I have NOT enabled the Audit Service.  What can I check?

---

scrjs wrote: I have NOT enabled the Audit Service.  What can I check?

Maybe just scroll through a few screens worth of journalctl entries, and see if anything seems to be flooding the logs.

FWIW, I generally see about ~700 log entries per day.  But of course this will vary, depending on how your NAS is configured and how it is used.  So the low retention doesn't necessarily mean anything is wrong - it just seems to me that your system is doing a lot of logging.

You can count the number of entries for a specific day:

root@NAS:~# journalctl --no-pager | grep "Feb 19" | wc
    701    8685   61460

The first entry is the number of lines that go through the grep filter - so there were 701 entries in my main NAS dated Feb 19.

You can also count them for a specific hour by simply changing the filter a bit.

root@NAS:~# journalctl --no-pager | grep "Feb 19 23:" | wc
     34     419    3132

So my system logged 34 entries between Feb 19 23:00:00 and Feb 19 23:59:59

Hi StephenB 

Thanks for the education!  I am not proficient with Unix OS

---

StephenB wrote:

---

scrjs wrote: I have NOT enabled the Audit Service.  What can I check?

Maybe just scroll through a few screens worth of journalctl entries, and see if anything seems to be flooding the logs.

 

FWIW, I generally see about ~700 log entries per day.  But of course this will vary, depending on how your NAS is configured and how it is used.  So the low retention doesn't necessarily mean anything is wrong - it just seems to me that your system is doing a lot of logging.

 

You can count the number of entries for a specific day:

root@NAS:~# journalctl --no-pager | grep "Feb 19" | wc
    701    8685   61460

The first entry is the number of lines that go through the grep filter - so there were 701 entries in my main NAS dated Feb 19.

 

You can also count them for a specific hour by simply changing the filter a bit.

root@NAS:~# journalctl --no-pager | grep "Feb 19 23:" | wc
     34     419    3132

So my system logged 34 entries between Feb 19 23:00:00 and Feb 19 23:59:59

 

---

In my case I am logging a bit more then you +300 per day and +20 per hour

root@xxxxxReadyNAS:~# journalctl --no-pager | grep "Feb 23" | wc
   1085   11442   94861

root@xxxxxReadyNAS:~# journalctl --no-pager | grep "Feb 23 10:" | wc
     51     530    4505

Looks like my Windows FileHistory is creating the extra entries for some Apple MobileSync.  Not critical but extra logging

Feb 22 21:30:50 xxxxxReadyNAS tracker-miner-fs[2731]: (tracker-miner-fs:2731): Tracker-CRITICAL **:   (Sparql buffer) Error in task 2 (file:///data/Backup/FileHist-T590/scrjs/xxxxxxxxxx-T590/Data/C/Users/scrjs/Apple/MobileSync/Backup/097
38580e54d9155c885c64d0eb6853c06fdaaf6/06/06b60848b6afef08d879bf24afe5855bb7fd0d44%20(2020_08_12%2001_26_35%20UTC)) of the array-update: UNIQUE constraint failed: nie:DataObject.nie:url (strerror of errno (not necessarily related): Reso
urce temporarily unavailable)

Feb 22 21:30:50 xxxxxReadyNAS tracker-miner-fs[2731]: (tracker-miner-fs:2731): Tracker-CRITICAL **: Could not execute sparql: UNIQUE constraint failed: nie:DataObject.nie:url (strerror of errno (not necessarily related): Resource tempo
rarily unavailable)

Thanks again for the tip!

Hi StephenB 

FWIW AV My NAS has been updaing AV successfully for 7 days after the restart after failure command systemctl start clamav-freshclam.service

root@xxxxxReadyNAS:~# systemctl status clamav-freshclam.service
● clamav-freshclam.service - ClamAV virus database updater
   Loaded: loaded (/lib/systemd/system/clamav-freshclam.service; static; vendor preset: disabled)
   Active: inactive (dead) since Tue 2021-03-02 08:31:18 AEDT; 6h ago
  Process: 12506 ExecStart=/usr/bin/freshclam --quiet (code=exited, status=0/SUCCESS)
 Main PID: 12506 (code=exited, status=0/SUCCESS)

Mar 02 08:27:34 xxxxxReadyNAS systemd[1]: Starting ClamAV virus database updater...
Mar 02 08:27:35 xxxxxReadyNAS freshclam[12506]: ClamAV update process started at Tue Mar  2 08:27:35 2021
Mar 02 08:27:36 xxxxxReadyNAS freshclam[12506]: main.cld is up to date (version: 59, sigs: 4564902, f-level: 60, builder: sigmgr)
Mar 02 08:27:40 xxxxxReadyNAS freshclam[12506]: Downloading daily-26095.cdiff [100%]
Mar 02 08:30:36 xxxxxReadyNAS freshclam[12506]: daily.cld updated (version: 26095, sigs: 3956535, f-level: 63, builder: raynman)
Mar 02 08:30:43 xxxxxReadyNAS freshclam[12506]: Can't query daily.26095.93.1.0.6810DB54.ping.clamav.net
Mar 02 08:30:43 xxxxxReadyNAS freshclam[12506]: bytecode.cld is up to date (version: 332, sigs: 93, f-level: 63, builder: awillia2)
Mar 02 08:31:14 xxxxxReadyNAS freshclam[12506]: Database updated (8521530 signatures) from database.clamav.net (IP: 104.16.219.84)
Mar 02 08:31:15 xxxxxReadyNAS freshclam[12506]: Clamd successfully notified about the update.
Mar 02 08:31:18 xxxxxReadyNAS systemd[1]: Started ClamAV virus database updater.

---

scrjs wrote:

FWIW AV My NAS has been updaing AV successfully for 7 days after the restart after failure command systemctl start clamav-freshclam.service

Thx for updating us.  Netgear says they are still working on the hotfix (no idea why it's taken that long).

Hi StephenB 

The hotfix automatically applied to my ReadyNAS as noted in the Logs presented in the User Interface where I now see (in timezone AEDT)

Prior to the application of the Hotfix my AV was updating as indicated in my revious update

---

StephenB wrote:

---

scrjs wrote:

FWIW AV My NAS has been updaing AV successfully for 7 days after the restart after failure command systemctl start clamav-freshclam.service

Thx for updating us.  Netgear says they are still working on the hotfix (no idea why it's taken that long).

---