Discussion:
[clamav-users] ScanOnAccess: ... (null) FOUND
Kretschmer, Jens
2018-08-01 10:16:26 UTC
Permalink
Hi,

we have ScanOnAccess and OnAccessExtraScanning activated. When I open firefox I get a lot of messages written to /var/log/messages every couple of seconds:

Aug 1 12:07:02 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/3F5C8E984584F19905AC4995D97962FE97EFFBEB: (null) FOUND
Aug 1 12:07:02 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1472223436: (null) FOUND
Aug 1 12:07:02 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/5A9A7B6DCAF96FA85AB400F1EFB97A4D2BE4289E: (null) FOUND
Aug 1 12:07:02 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/715632663: (null) FOUND
Aug 1 12:07:04 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/8F2E3CF4AC8F00C3ACE4C932BEA76F2089A593E1: (null) FOUND
Aug 1 12:07:04 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/277127757: (null) FOUND
Aug 1 12:07:05 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/703A8CB3B4C8311394915B3A285359E7E1AF7520: (null) FOUND
Aug 1 12:07:06 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1628703657: (null) FOUND
Aug 1 12:07:06 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/5D7DBEB1898CFD7B33E3406F9CA1B6D3BA12C3B6: (null) FOUND
Aug 1 12:07:06 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1952686252: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/449677348: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/829574285: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/D2BB3C327EF38DDD2FE5E544DBBE084493F1D608: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/8F2E3CF4AC8F00C3ACE4C932BEA76F2089A593E1: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/636557989: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/5A9A7B6DCAF96FA85AB400F1EFB97A4D2BE4289E: (null) FOUND
Aug 1 12:07:10 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1707731390: (null) FOUND
Aug 1 12:07:10 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/617693635: (null) FOUND
Aug 1 12:07:11 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/5D7DBEB1898CFD7B33E3406F9CA1B6D3BA12C3B6: (null) FOUND
Aug 1 12:07:11 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1367025624: (null) FOUND
Aug 1 12:07:12 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1089051163: (null) FOUND
Aug 1 12:07:13 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/2003921810: (null) FOUND
Aug 1 12:07:15 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/703A8CB3B4C8311394915B3A285359E7E1AF7520: (null) FOUND
Aug 1 12:07:15 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1845070701: (null) FOUND
Aug 1 12:07:16 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/250378345: (null) FOUND
Aug 1 12:07:16 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/5D7DBEB1898CFD7B33E3406F9CA1B6D3BA12C3B6: (null) FOUND

I already hide the "ScanOnAccess: Performing additional scanning on file ..." messages by adding

:msg, startswith, "ScanOnAccess: Performing additional scanning on file" stop

to a file in /etc/rsyslog.d/. But the messages mentioned above have exactly the same format as when malware is found, so I would rather not hide them. Apart from the fact that those messages are cluttering /var/log/messages, they also trigger malware alarms on our central syslog server. What can I do to stop those messages?

Best regards,
Jens
Micah Snyder (micasnyd)
2018-08-01 17:43:00 UTC
Permalink
How long as this been going on?
What is your database set?
What version of ClamAV are you using?
Are you using the VirusEvent hook?

I've searched the code base high and low and can't find any reasonable excuse why the virus name would be "(null)". There is one reference, but it only uses "(null)" as the virus name in performance event logging for pcre statistics (a --statistics=pcre option for clamscan), and not for actual virus reporting. Suffice to say we're pretty stumped as to why you are seeing that.

You can disable Firefox caching as a bandaid to eliminate the logs, but I doubt you want to.


Micah Snyder
ClamAV Development
Talos
Cisco Systems, Inc.


On Aug 1, 2018, at 6:16 AM, Kretschmer, Jens <***@siemens.com<mailto:***@siemens.com>> wrote:

Hi,

we have ScanOnAccess and OnAccessExtraScanning activated. When I open firefox I get a lot of messages written to /var/log/messages every couple of seconds:

Aug 1 12:07:02 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/3F5C8E984584F19905AC4995D97962FE97EFFBEB: (null) FOUND
Aug 1 12:07:02 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1472223436: (null) FOUND
Aug 1 12:07:02 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/5A9A7B6DCAF96FA85AB400F1EFB97A4D2BE4289E: (null) FOUND
Aug 1 12:07:02 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/715632663: (null) FOUND
Aug 1 12:07:04 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/8F2E3CF4AC8F00C3ACE4C932BEA76F2089A593E1: (null) FOUND
Aug 1 12:07:04 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/277127757: (null) FOUND
Aug 1 12:07:05 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/703A8CB3B4C8311394915B3A285359E7E1AF7520: (null) FOUND
Aug 1 12:07:06 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1628703657: (null) FOUND
Aug 1 12:07:06 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/5D7DBEB1898CFD7B33E3406F9CA1B6D3BA12C3B6: (null) FOUND
Aug 1 12:07:06 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1952686252: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/449677348: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/829574285: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/D2BB3C327EF38DDD2FE5E544DBBE084493F1D608: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/8F2E3CF4AC8F00C3ACE4C932BEA76F2089A593E1: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/636557989: (null) FOUND
Aug 1 12:07:07 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/5A9A7B6DCAF96FA85AB400F1EFB97A4D2BE4289E: (null) FOUND
Aug 1 12:07:10 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1707731390: (null) FOUND
Aug 1 12:07:10 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/617693635: (null) FOUND
Aug 1 12:07:11 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/5D7DBEB1898CFD7B33E3406F9CA1B6D3BA12C3B6: (null) FOUND
Aug 1 12:07:11 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1367025624: (null) FOUND
Aug 1 12:07:12 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1089051163: (null) FOUND
Aug 1 12:07:13 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/2003921810: (null) FOUND
Aug 1 12:07:15 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/703A8CB3B4C8311394915B3A285359E7E1AF7520: (null) FOUND
Aug 1 12:07:15 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/1845070701: (null) FOUND
Aug 1 12:07:16 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/doomed/250378345: (null) FOUND
Aug 1 12:07:16 hostname1 clamd[4051]: ScanOnAccess: /home/user1/.cache/mozilla/firefox/0pnt0qc2.default/cache2/entries/5D7DBEB1898CFD7B33E3406F9CA1B6D3BA12C3B6: (null) FOUND

I already hide the “ScanOnAccess: Performing additional scanning on file 
” messages by adding

:msg, startswith, "ScanOnAccess: Performing additional scanning on file" stop

to a file in /etc/rsyslog.d/. But the messages mentioned above have exactly the same format as when malware is found, so I would rather not hide them. Apart from the fact that those messages are cluttering /var/log/messages, they also trigger malware alarms on our central syslog server. What can I do to stop those messages?

Best regards,
Jens

_______________________________________________
clamav-users mailing list
clamav-***@lists.clamav.net<mailto:clamav-***@lists.clamav.net>
http://lists.clamav.net/cgi-bin/mailman/listinfo/clamav-users


Help us build a comprehensive ClamAV guide:
https://github.com/vrtadmin/clamav-faq

http://www.clamav.net/contact.html#ml
Kretschmer, Jens
2018-08-02 12:45:40 UTC
Permalink
Post by Micah Snyder (micasnyd)
How long as this been going on?
Apparently it has been going on for a couple of days. I did not notice the "ScanOnAccess: ... (null) FOUND" messages, until I hid the "ScanOnAccess: Performing additional scanning on file ..." messages. The first occurrence was on July 23rd 13:00:08 with clamav-0.99.4-1.el7.x86_64

Jul 23 13:00:08 hostname1 clamd[6539]: ScanOnAccess: /home/user1/.nv/GLCache/ca7c949c26f976e0f53c14399c2ef02e/3a4ed7c703a940c9: (null) FOUND
Jul 23 13:00:08 hostname1 clamd[6539]: ScanOnAccess: /home/user1/.nv/GLCache/ca7c949c26f976e0f53c14399c2ef02e: (null) FOUND

As you can see, those messages do not only appear for the firefox cache.

On Jul 26th we updated clamav to clamav-0.100.1-1.el7.x86_64. But the messages still appear.
Post by Micah Snyder (micasnyd)
What is your database set?
Database information
--------------------
Database directory: /var/lib/clamav
main.cvd: version 58, sigs: 4566249, built on Wed Jun 7 23:38:10 2017
bytecode.cld: version 326, sigs: 93, built on Thu Jul 26 18:44:35 2018
daily.cld: version 24803, sigs: 2034540, built on Wed Aug 1 18:43:39 2018
Total number of signatures: 6600882
Post by Micah Snyder (micasnyd)
What version of ClamAV are you using?
Currently clamav-0.100.1-1.el7.x86_64
Post by Micah Snyder (micasnyd)
Are you using the VirusEvent hook?
No

I noticed something else. There were out of memory messages showing for clamd.

Aug 02 13:07:17 cis4test clamd[4051]: out of memory [4051]
Aug 02 13:17:17 cis4test clamd[4051]: out of memory [4051]

Unfortunately they were not associated with clamd but with journal in rsyslog, that's why I did not notice them at first. At that time the machine had 3GB of free memory and more than 25GB of free swap, so I don't understand why those messages were showing up. They also started to show up on Jul 24th 14:38:08 (after the first "ScanOnAccess: ... (null) FOUND" messages showed up). On July 26th the messages stopped after updating clamav to 0.100.1-1, but then showed up again on Aug 1st 18:56:31. I just restarted clamav and the "out of memory" messages are no longer showing up and the "ScanOnAccess: ... (null) FOUND" are not either.

Summary:
Jul 23 13:00:08 -- first "ScanOnAccess: ... (null) FOUND" message
Jul 24 14:38:08 -- first "out of memory" message
Jul 26 14:44:03 -- update to clamav-0.100.1-1, "ScanOnAccess: ... (null) FOUND" messages and "out of memory" messages stop
Jul 30 09:40:44 -- "ScanOnAccess: ... (null) FOUND" messages reappear
Aug 1 18:56:31 -- "out of memory" messages reappear
Aug 2 13:38:51 -- restart ***@scan, "ScanOnAccess: ... (null) FOUND" messages and "out of memory" messages stop

I will closely monitor the faulty machine and I will try to reproduce this behavior on a different machine and report back to you with my findings.

I attached the output of clamconf.

Best regards,
Jens
Mickey Sola
2018-08-02 14:50:48 UTC
Permalink
Hi Jens,

Do you have the OnAccessExtraScanning option on by chance?

There's a known issue with that option which can cause memory consumption
problems. Though I'm still not certain why that would lead to printing
"(null)" virnames.

- Mickey

On Thu, Aug 2, 2018 at 8:45 AM, Kretschmer, Jens <
Post by Kretschmer, Jens
Post by Micah Snyder (micasnyd)
How long as this been going on?
Apparently it has been going on for a couple of days. I did not notice the
Performing additional scanning on file ..." messages. The first occurrence
was on July 23rd 13:00:08 with clamav-0.99.4-1.el7.x86_64
(null) FOUND
/home/user1/.nv/GLCache/ca7c949c26f976e0f53c14399c2ef02e: (null) FOUND
As you can see, those messages do not only appear for the firefox cache.
On Jul 26th we updated clamav to clamav-0.100.1-1.el7.x86_64. But the
messages still appear.
Post by Micah Snyder (micasnyd)
What is your database set?
Database information
--------------------
Database directory: /var/lib/clamav
main.cvd: version 58, sigs: 4566249, built on Wed Jun 7 23:38:10 2017
bytecode.cld: version 326, sigs: 93, built on Thu Jul 26 18:44:35 2018
daily.cld: version 24803, sigs: 2034540, built on Wed Aug 1 18:43:39 2018
Total number of signatures: 6600882
Post by Micah Snyder (micasnyd)
What version of ClamAV are you using?
Currently clamav-0.100.1-1.el7.x86_64
Post by Micah Snyder (micasnyd)
Are you using the VirusEvent hook?
No
I noticed something else. There were out of memory messages showing for clamd.
Aug 02 13:07:17 cis4test clamd[4051]: out of memory [4051]
Aug 02 13:17:17 cis4test clamd[4051]: out of memory [4051]
Unfortunately they were not associated with clamd but with journal in
rsyslog, that's why I did not notice them at first. At that time the
machine had 3GB of free memory and more than 25GB of free swap, so I don't
understand why those messages were showing up. They also started to show up
on Jul 24th 14:38:08 (after the first "ScanOnAccess: ... (null) FOUND"
messages showed up). On July 26th the messages stopped after updating
clamav to 0.100.1-1, but then showed up again on Aug 1st 18:56:31. I just
restarted clamav and the "out of memory" messages are no longer showing up
and the "ScanOnAccess: ... (null) FOUND" are not either.
Jul 23 13:00:08 -- first "ScanOnAccess: ... (null) FOUND" message
Jul 24 14:38:08 -- first "out of memory" message
Jul 26 14:44:03 -- update to clamav-0.100.1-1, "ScanOnAccess: ... (null)
FOUND" messages and "out of memory" messages stop
Jul 30 09:40:44 -- "ScanOnAccess: ... (null) FOUND" messages reappear
Aug 1 18:56:31 -- "out of memory" messages reappear
messages and "out of memory" messages stop
I will closely monitor the faulty machine and I will try to reproduce this
behavior on a different machine and report back to you with my findings.
I attached the output of clamconf.
Best regards,
Jens
_______________________________________________
clamav-users mailing list
http://lists.clamav.net/cgi-bin/mailman/listinfo/clamav-users
https://github.com/vrtadmin/clamav-faq
http://www.clamav.net/contact.html#ml
G.W. Haywood
2018-08-02 16:57:09 UTC
Permalink
Hi there,
Post by Micah Snyder (micasnyd)
Suffice to say we're pretty stumped as to why you are seeing that.
That's a little worrying. Have you looked in the C libraries?
--
73,
Ged.
_______________________________________________
clamav-users mailing list
clamav-***@lists.clamav.net
http://lists.clamav.net/cgi-bin/mailman/listinfo/clamav-users


Help us build a comprehensive ClamAV guide:
https://github.com/vrtadmin/clamav-faq

http://www.clamav.net/contact.html#ml
Kretschmer, Jens
2018-08-09 08:03:25 UTC
Permalink
Post by Mickey Sola
Do you have the OnAccessExtraScanning option on by chance?
Yes, OnAccessExtraScanning is turned on.

I was able to reproduce this behavior on a different machine. It uses the same configuration as the first machine (the clamconf output can be found in my previous E-Mail).
I rebooted the machine yesterday at 13:45 and left it untouched. I did not even log in. Today I logged in via ssh and the first ScanOnAccess message since the reboot in the journal was:

Aug 09 09:36:47 hostname2 clamd[8888]: SelfCheck: Database status OK.
Aug 09 09:37:24 hostname2 clamd[8888]: ScanOnAccess: Performing additional scanning on file '/home/user1/.sh_histdir/hostname2.0'
Aug 09 09:37:24 hostname2 clamd[8888]: ScanOnAccess: /home/user1/.sh_histdir/hostname2.0: (null) FOUND
Aug 09 09:39:34 hostname2 clamd[8888]: ScanOnAccess: Performing additional scanning on file '/home/user1/test2'
Aug 09 09:39:34 hostname2 clamd[8888]: ScanOnAccess: /home/user1/test2: (null) FOUND

On the first machine I restarted ***@scan yesterday 13:32:05 and ran the following script

#!/bin/ksh
file="testfile.txt"
while true; do
echo "test123" > $file
sync
rm $file
done

after about 13 hours clamd starts to show only the messages: "ScanOnAccess: Unable to kick off extra scanning."

Aug 09 02:40:37 hostname1 clamd[15866]: ScanOnAccess: Performing additional scanning on file '/home/user1/test/testfile.txt'
Aug 09 02:40:38 hostname1 clamd[15866]: ScanOnAccess: Performing additional scanning on file '/home/user1/test/testfile.txt'
Aug 09 02:40:39 hostname1 clamd[15866]: ScanOnAccess: Unable to kick off extra scanning.
Aug 09 02:40:39 hostname1 clamd[15866]: ScanOnAccess: Unable to kick off extra scanning.

Best regards,
Jens
_______________________________________________
clamav-users mailing list
clamav-***@lists.clamav.net
http://lists.clamav.net/cgi-bin/mailman/listinfo/clamav-users


Help us build a comprehensive ClamAV guide:
https://github.com/vrtadmin/clamav-faq

http://www.clamav.net/contact.html#ml
Micah Snyder (micasnyd)
2018-08-09 12:38:32 UTC
Permalink
I've been running clamd with OnAccess on a box using Firefox and just yesterday saw the (null) FOUND as well. I haven't had a chance to take the file in question and debug with clamscan to reproduce it and figure out what's causing it but I will do so soon.

Regarding your second issue, I believe there is a memory leak with the OnAccessExtraScanning feature because the threads that process the extra scanning work aren't being join()'d.
I have a feeling that may be why you're seeing "Unable to kick off extra scanning". We're getting near the end of our development cycle for 0.101 and still have some tough work left, but we'll try to find a solution to the OnAccessExtraScanning thread joining issue if time permits.

Micah Snyder
ClamAV Development
Talos
Cisco Systems, Inc.


On Aug 9, 2018, at 4:03 AM, Kretschmer, Jens <***@siemens.com<mailto:***@siemens.com>> wrote:

Do you have the OnAccessExtraScanning option on by chance?

Yes, OnAccessExtraScanning is turned on.

I was able to reproduce this behavior on a different machine. It uses the same configuration as the first machine (the clamconf output can be found in my previous E-Mail).
I rebooted the machine yesterday at 13:45 and left it untouched. I did not even log in. Today I logged in via ssh and the first ScanOnAccess message since the reboot in the journal was:

Aug 09 09:36:47 hostname2 clamd[8888]: SelfCheck: Database status OK.
Aug 09 09:37:24 hostname2 clamd[8888]: ScanOnAccess: Performing additional scanning on file '/home/user1/.sh_histdir/hostname2.0'
Aug 09 09:37:24 hostname2 clamd[8888]: ScanOnAccess: /home/user1/.sh_histdir/hostname2.0: (null) FOUND
Aug 09 09:39:34 hostname2 clamd[8888]: ScanOnAccess: Performing additional scanning on file '/home/user1/test2'
Aug 09 09:39:34 hostname2 clamd[8888]: ScanOnAccess: /home/user1/test2: (null) FOUND

On the first machine I restarted ***@scan yesterday 13:32:05 and ran the following script

#!/bin/ksh
file="testfile.txt"
while true; do
echo "test123" > $file
sync
rm $file
done

after about 13 hours clamd starts to show only the messages: "ScanOnAccess: Unable to kick off extra scanning."

Aug 09 02:40:37 hostname1 clamd[15866]: ScanOnAccess: Performing additional scanning on file '/home/user1/test/testfile.txt'
Aug 09 02:40:38 hostname1 clamd[15866]: ScanOnAccess: Performing additional scanning on file '/home/user1/test/testfile.txt'
Aug 09 02:40:39 hostname1 clamd[15866]: ScanOnAccess: Unable to kick off extra scanning.
Aug 09 02:40:39 hostname1 clamd[15866]: ScanOnAccess: Unable to kick off extra scanning.

Best regards,
Jens
_______________________________________________
clamav-users mailing list
clamav-***@lists.clamav.net<mailto:clamav-***@lists.clamav.net>
http://lists.clamav.net/cgi-bin/mailman/listinfo/clamav-users


Help us build a comprehensive ClamAV guide:
https://github.com/vrtadmin/clamav-faq

http://www.clamav.net/contact.html#ml
Kretschmer, Jens
2018-09-05 14:44:52 UTC
Permalink
Hi Micah,

did you have time to investigate those issues?

Should I create bug reports for them or are those issues being tracked already? Do you need any more information from my side?

Kr,
Jens

From: Micah Snyder (micasnyd) <***@cisco.com>
Sent: Thursday, August 9, 2018 2:39 PM
To: ClamAV users ML <clamav-***@lists.clamav.net>
Subject: Re: [clamav-users] ScanOnAccess: ... (null) FOUND

I've been running clamd with OnAccess on a box using Firefox and just yesterday saw the (null) FOUND as well. I haven't had a chance to take the file in question and debug with clamscan to reproduce it and figure out what's causing it but I will do so soon.

Regarding your second issue, I believe there is a memory leak with the OnAccessExtraScanning feature because the threads that process the extra scanning work aren't being join()'d.
I have a feeling that may be why you're seeing "Unable to kick off extra scanning". We're getting near the end of our development cycle for 0.101 and still have some tough work left, but we'll try to find a solution to the OnAccessExtraScanning thread joining issue if time permits.

Micah Snyder
ClamAV Development
Talos
Cisco Systems, Inc.


On Aug 9, 2018, at 4:03 AM, Kretschmer, Jens <***@siemens.com<mailto:***@siemens.com>> wrote:

Do you have the OnAccessExtraScanning option on by chance?

Yes, OnAccessExtraScanning is turned on.

I was able to reproduce this behavior on a different machine. It uses the same configuration as the first machine (the clamconf output can be found in my previous E-Mail).
I rebooted the machine yesterday at 13:45 and left it untouched. I did not even log in. Today I logged in via ssh and the first ScanOnAccess message since the reboot in the journal was:

Aug 09 09:36:47 hostname2 clamd[8888]: SelfCheck: Database status OK.
Aug 09 09:37:24 hostname2 clamd[8888]: ScanOnAccess: Performing additional scanning on file '/home/user1/.sh_histdir/hostname2.0'
Aug 09 09:37:24 hostname2 clamd[8888]: ScanOnAccess: /home/user1/.sh_histdir/hostname2.0: (null) FOUND
Aug 09 09:39:34 hostname2 clamd[8888]: ScanOnAccess: Performing additional scanning on file '/home/user1/test2'
Aug 09 09:39:34 hostname2 clamd[8888]: ScanOnAccess: /home/user1/test2: (null) FOUND

On the first machine I restarted ***@scan yesterday 13:32:05 and ran the following script

#!/bin/ksh
file="testfile.txt"
while true; do
echo "test123" > $file
sync
rm $file
done

after about 13 hours clamd starts to show only the messages: "ScanOnAccess: Unable to kick off extra scanning."

Aug 09 02:40:37 hostname1 clamd[15866]: ScanOnAccess: Performing additional scanning on file '/home/user1/test/testfile.txt'
Aug 09 02:40:38 hostname1 clamd[15866]: ScanOnAccess: Performing additional scanning on file '/home/user1/test/testfile.txt'
Aug 09 02:40:39 hostname1 clamd[15866]: ScanOnAccess: Unable to kick off extra scanning.
Aug 09 02:40:39 hostname1 clamd[15866]: ScanOnAccess: Unable to kick off extra scanning.

Best regards,
Jens
_______________________________________________
clamav-users mailing list
clamav-***@lists.clamav.net<mailto:clamav-***@lists.clamav.net>
http://lists.clamav.net/cgi-bin/mailman/listinfo/clamav-users


Help us build a comprehensive ClamAV guide:
https://github.com/vrtadmin/clamav-faq

http://www.clamav.net/contact.html#ml
Micah Snyder (micasnyd)
2018-09-07 15:16:34 UTC
Permalink
Hi Jens,

Sorry I have not yet found time to investigate the source of the "(null) FOUND" issue. Thank-you for the reminder.

It would be helpful if you submitted a bug report to track the issue.


Micah Snyder
ClamAV Development
Talos
Cisco Systems, Inc.


On Sep 5, 2018, at 10:44 AM, Kretschmer, Jens <***@siemens.com<mailto:***@siemens.com>> wrote:

Hi Micah,

did you have time to investigate those issues?

Should I create bug reports for them or are those issues being tracked already? Do you need any more information from my side?

Kr,
Jens

From: Micah Snyder (micasnyd) <***@cisco.com<mailto:***@cisco.com>>
Sent: Thursday, August 9, 2018 2:39 PM
To: ClamAV users ML <clamav-***@lists.clamav.net<mailto:clamav-***@lists.clamav.net>>
Subject: Re: [clamav-users] ScanOnAccess: ... (null) FOUND

I've been running clamd with OnAccess on a box using Firefox and just yesterday saw the (null) FOUND as well. I haven't had a chance to take the file in question and debug with clamscan to reproduce it and figure out what's causing it but I will do so soon.

Regarding your second issue, I believe there is a memory leak with the OnAccessExtraScanning feature because the threads that process the extra scanning work aren't being join()'d.
I have a feeling that may be why you're seeing "Unable to kick off extra scanning". We're getting near the end of our development cycle for 0.101 and still have some tough work left, but we'll try to find a solution to the OnAccessExtraScanning thread joining issue if time permits.

Micah Snyder
ClamAV Development
Talos
Cisco Systems, Inc.


On Aug 9, 2018, at 4:03 AM, Kretschmer, Jens <***@siemens.com<mailto:***@siemens.com>> wrote:

Do you have the OnAccessExtraScanning option on by chance?

Yes, OnAccessExtraScanning is turned on.

I was able to reproduce this behavior on a different machine. It uses the same configuration as the first machine (the clamconf output can be found in my previous E-Mail).
I rebooted the machine yesterday at 13:45 and left it untouched. I did not even log in. Today I logged in via ssh and the first ScanOnAccess message since the reboot in the journal was:

Aug 09 09:36:47 hostname2 clamd[8888]: SelfCheck: Database status OK.
Aug 09 09:37:24 hostname2 clamd[8888]: ScanOnAccess: Performing additional scanning on file '/home/user1/.sh_histdir/hostname2.0'
Aug 09 09:37:24 hostname2 clamd[8888]: ScanOnAccess: /home/user1/.sh_histdir/hostname2.0: (null) FOUND
Aug 09 09:39:34 hostname2 clamd[8888]: ScanOnAccess: Performing additional scanning on file '/home/user1/test2'
Aug 09 09:39:34 hostname2 clamd[8888]: ScanOnAccess: /home/user1/test2: (null) FOUND

On the first machine I restarted ***@scan yesterday 13:32:05 and ran the following script

#!/bin/ksh
file="testfile.txt"
while true; do
echo "test123" > $file
sync
rm $file
done

after about 13 hours clamd starts to show only the messages: "ScanOnAccess: Unable to kick off extra scanning."

Aug 09 02:40:37 hostname1 clamd[15866]: ScanOnAccess: Performing additional scanning on file '/home/user1/test/testfile.txt'
Aug 09 02:40:38 hostname1 clamd[15866]: ScanOnAccess: Performing additional scanning on file '/home/user1/test/testfile.txt'
Aug 09 02:40:39 hostname1 clamd[15866]: ScanOnAccess: Unable to kick off extra scanning.
Aug 09 02:40:39 hostname1 clamd[15866]: ScanOnAccess: Unable to kick off extra scanning.

Best regards,
Jens
_______________________________________________
clamav-users mailing list
clamav-***@lists.clamav.net<mailto:clamav-***@lists.clamav.net>
http://lists.clamav.net/cgi-bin/mailman/listinfo/clamav-users


Help us build a comprehensive ClamAV guide:
https://github.com/vrtadmin/clamav-faq

http://www.clamav.net/contact.html#ml

_______________________________________________
clamav-users mailing list
clamav-***@lists.clamav.net<mailto:clamav-***@lists.clamav.net>
http://lists.clamav.net/cgi-bin/mailman/listinfo/clamav-users


Help us build a comprehensive ClamAV guide:
https://github.com/vrtadmin/clamav-faq

http://www.clamav.net/contact.html#ml

Loading...