Re: clamav (under amavis) not filtering out viruses!

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,  "[email protected]" 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 "[email protected]", results: 
"(constant:DEFAULT)"=>"DEFAULT"
Oct 15 14:43:44 mailgw3 amavis[3253]: (03253-10) collect banned 
table[0]: [email protected], 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 
[email protected] 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:[email protected]] => 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 [email protected]: 
"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 
[email protected] 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:[email protected]] => 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 [email protected]: 
"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