clamav (under amavis) not filtering out viruses!
Nikolaos Milas
nmilas at noa.gr
Thu Oct 15 14:41:29 CEST 2020
On 15/10/2020 3:26 μ.μ., Nikolaos Milas wrote:
> This doesn't seem to be the problem, because the infected attachments
> are simply found CLEAN;
For your reference, here is a verbose log of the AV check on a message
which should have been found INFECTED, but it is rather judged CLEAN:
==================================================================================
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) Extracting mime
components from a string
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) Issued a new file name:
p001
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) Issued a new file name:
p002
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) Issued a new pseudo
part: p003
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) p003 1 Content-Type:
multipart/mixed
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) mime_decode_epilogue: 1
lines
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) Charging 239 bytes to
remaining quota 97559500 (out of 97559500, (0%)) - by mime_decode
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) p001 1/1 Content-Type:
text/html, size: 239 B, name:
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) reparenting p001 from
p000 to p003
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) Charging 140468 bytes
to remaining quota 97559261 (out of 97559500, (0%)) - by mime_decode
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) p002 1/2 Content-Type:
application/msword, size: 140468 B, name: attachments 54972.doc
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) reparenting p002 from
p000 to p003
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline
mime_decode - deadline in 480.0 s, set to 336.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) prolong_timer
mime_decode: timer 336, was 336, deadline in 480.0 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline
mime_decode-1 - deadline in 480.0 s, set to 336.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) prolong_timer
mime_decode-1: timer 336, was 336, deadline in 480.0 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) decode_parts: level=1,
#parts=3 : p001, p002, p003
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) running file(1) on 2
files, arglist size 23
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) run_command: [3286]
/usr/bin/file p001 p002 </dev/null 2>&1
Oct 15 14:43:44 mailgw3 amavis[3286]: (03253-10) open_on_specific_fd:
target fd0 closing, to become < /dev/null
Oct 15 14:43:44 mailgw3 amavis[3286]: (03253-10) open_on_specific_fd:
target fd1 closing, to become (65) &=13
Oct 15 14:43:44 mailgw3 amavis[3286]: (03253-10) open_on_specific_fd:
target fd1 dup2 from fd13 (65) &=13
Oct 15 14:43:44 mailgw3 amavis[3286]: (03253-10) open_on_specific_fd:
source fd13 closed
Oct 15 14:43:44 mailgw3 amavis[3286]: (03253-10) open_on_specific_fd:
target fd2 closing, to become (65) &1
Oct 15 14:43:44 mailgw3 amavis[3286]: (03253-10) open_on_specific_fd:
target fd2 dup2 from fd1 (65) &1
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) result line from
file(1): p001: HTML document text\n
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup_re("HTML
document text") matches key "(?-xism:^HTML document text\b)", result="html"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup
[map_full_type_to_short_type] => true, "HTML document text" matches,
result="html", matching_key="(?-xism:^HTML document text\134b)"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) File-type of p001: HTML
document text; (html)
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) result line from
file(1): p002: CDF V2 Document, corrupt: Can't expand summary_info\n
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup_re("CDF V2
Document, corrupt: Can't expand summary_info") matches key "(?-xism:^)",
result="dat"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup
[map_full_type_to_short_type] => true, "CDF V2 Document, corrupt: Can't
expand summary_info" matches, result="dat",matching_key="(?-xism:^)"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) File-type of p002: CDF
V2 Document, corrupt: Can't expand summary_info; (dat)
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) decompose_part: p001 -
atomic
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) decompose_part: p002 -
atomic
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline
parts_decode - deadline in 479.9 s, set to 336.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) prolong_timer
parts_decode: timer 336, was 336, deadline in 479.9 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup: (scalar)
matches, result="1"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup
[bypass_header_checks] => true, "userxxx at noa.gr" matches, result="1",
matching_key="(constant:1)"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) Checking for banned
types and filenames
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup: (scalar)
matches, result="DEFAULT"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup
[banned_filename], 1 matches for "userxxx at noa.gr", results:
"(constant:DEFAULT)"=>"DEFAULT"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) collect banned
table[0]: userxxx at noa.gr, tables:
DEFAULT=>Amavis::Lookup::RE=ARRAY(0x35a37f8)
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) starting banned checks
- traversing message structure tree
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) check_for_banned
(p003,p001) multipart/mixed | text/html,.html
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) doing banned check for
userxxx at noa.gr on multipart/mixed | text/html,.html
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10)
lookup_re(["multipart/mixed","text/html",".html"]), no matches
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup
[check_bann:userxxx at noa.gr] => undef,
["multipart/mixed","text/html",".html"] does not match
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup
[banned_namepath_re] => undef,
"P=p003\tL=1\tM=multipart/mixed\nP=p001\tL=1/1\tM=text/html\tT=html"
does not match
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) p.path userxxx at noa.gr:
"P=p003,L=1,M=multipart/mixed | P=p001,L=1/1,M=text/html,T=html"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) check_for_banned
(p003,p002) multipart/mixed | application/msword,.dat,attachments 54972.doc
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) doing banned check for
userxxx at noa.gr on multipart/mixed | application/msword,.dat,attachments
54972.doc
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10)
lookup_re(["multipart/mixed","application/msword",".dat","attachments
54972.doc"]), no matches
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup
[check_bann:userxxx at noa.gr] => undef,
["multipart/mixed","application/msword",".dat","attachments 54972.doc"]
does not match
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup
[banned_namepath_re] => undef,
"P=p003\tL=1\tM=multipart/mixed\nP=p002\tL=1/2\tM=application/msword\tT=dat\tN=attachments
54972.doc" does not match
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) p.path userxxx at noa.gr:
"P=p003,L=1,M=multipart/mixed |
P=p002,L=1/2,M=application/msword,T=dat,N=attachments 54972.doc"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) banned check: any=0,
all=N (1)
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup_re("MAIL")
matches key "(?-xism:^MAIL$)", result="1"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) lookup
[keep_decoded_original] => true, "MAIL" matches, result="1",
matching_key="(?-xism:^MAIL$)"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) Issued a new file name:
p004
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) presenting full
original message to scanners as
/var/amavis/tmp/amavis-20201015T144232-03253-hA2kU9oE/parts/p004
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) Calling virus scanners,
3 files to scan in
/var/amavis/tmp/amavis-20201015T144232-03253-hA2kU9oE/parts
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) invoking av-scanner
ClamAV-clamd
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) ask_daemon: proto=DFLT,
spawn=0, (ClamAV-clamd) /var/run/clamav/clamd.sock
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) run_av (ClamAV-clamd):
query template(1,2): CONTSCAN {}\n
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline run_av_pre
- deadline in 479.9 s, set to 336.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) prolong_timer
run_av_pre: timer 336, was 336, deadline in 479.9 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline
run_av_scan - deadline in 479.9 s, set to 336.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) prolong_timer
run_av_scan: timer 336, was 336, deadline in 479.9 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) run_av Using
(ClamAV-clamd): (code) CONTSCAN
/var/amavis/tmp/amavis-20201015T144232-03253-hA2kU9oE/parts\n
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline
ask_daemon_internal_connect_pre - deadline in 479.9 s, set to 336.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline
ask_daemon_internal_connect - deadline in 479.9 s, set to 10.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) prolong_timer
ask_daemon_internal_connect: timer 10, was 336, deadline in 479.9 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) ClamAV-clamd:
Connecting to socket /var/run/clamav/clamd.sock
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) new socket by
IO::Socket::UNIX to /var/run/clamav/clamd.sock, timeout 10
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) connected to
/var/run/clamav/clamd.sock successfully
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) ClamAV-clamd: Sending
CONTSCAN /var/amavis/tmp/amavis-20201015T144232-03253-hA2kU9oE/parts\n
to socket /var/run/clamav/clamd.sock
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop: needline=0,
flush=1, wr=1, timeout=10
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop: sending 69 chars
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop sent 69>
CONTSCAN /var/amavis/tmp/amavis-20201015T144232-03253-hA2kU9oE/parts\n
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline
ask_daemon_internal_scan - deadline in 479.9 s, set to 336.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) prolong_timer
ask_daemon_internal_scan: timer 336, was 10, deadline in 479.9 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop: needline=0,
flush=0, wr=0, timeout=335.994
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop: receiving
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop read 64 chars<
/var/amavis/tmp/amavis-20201015T144232-03253-hA2kU9oE/parts: OK\n
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop: needline=0,
flush=0, wr=0, timeout=335.994
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop: receiving
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop read: got eof
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline
ask_daemon_internal - deadline in 479.9 s, set to 336.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) prolong_timer
ask_daemon_internal: timer 336, was 336, deadline in 479.9 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline run_av_3 -
deadline in 479.9 s, set to 336.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) prolong_timer run_av_3:
timer 336, was 336, deadline in 479.9 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) run_av (ClamAV-clamd)
result: /var/amavis/tmp/amavis-20201015T144232-03253-hA2kU9oE/parts: OK\n
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop: needline=0,
flush=0, wr=0, timeout=335.994
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop: receiving
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) rw_loop read: got eof
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline
ask_daemon_internal - deadline in 479.9 s, set to 336.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) prolong_timer
ask_daemon_internal: timer 336, was 336, deadline in 479.9 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) get_deadline run_av_3 -
deadline in 479.9 s, set to 336.000 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) prolong_timer run_av_3:
timer 336, was 336, deadline in 479.9 s
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) run_av (ClamAV-clamd)
result: /var/amavis/tmp/amavis-20201015T144232-03253-hA2kU9oE/parts: OK\n
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) run_av (ClamAV-clamd):
CLEAN
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) run_av (ClamAV-clamd)
result: clean
======================================================================================================
Nick
More information about the amavis-users
mailing list