This discussion has been locked.

You can no longer post new replies to this discussion. If you have a question you can start a new discussion

Manual 'sweep' finds real virus in mail file on the server, scan by AMaViSd does not.

Hi there,

given is a simple AMaViSd-setup, utilizing the free scanner from Sophos without SAVDI. ClamAV is disabled in the AMaViSd-configuration.

Manual scan works:

---

# sweep -nb -f -all -rec -ss -sc -archive -cab -mime -oe -tnef -idedir=/opt/sophos-av/lib/sav --no-reset-atime ./
>>> Virus 'Troj/DocDl-HAW' found in file ./1490084101.M450955P26970V000000000000CA02I0000000000022B1D_60.mail-lsd-is,S=93763:2,S/PROJECT.gz/PROJECT.doc
>>> Virus 'Troj/DocDl-HAW' found in file ./1490084050.M224845P26970V000000000000CA02I0000000000022A6C_26.mail-lsd-is,S=93568:2,S/New.gz/New.doc

---

But this AMaViSd-based configuration does not find the above viruses:

---

@av_scanners = (

['Sophos Anti Virus (sweep)', '/usr/local/bin/sweep', '-nb -f -all -rec -ss -sc -archive -cab -mime -oe -tnef -idedir=/opt/sophos-av/lib/sav --no-reset-atime {}', [0,2], qr/Virus .*? found/m, qr/^>>> Virus(?: fragment)? '?(.*?)'? found/m ]

);

---

The exact same command line options were used.

Surprisingly a MIME-embedded EICAR attachment is found using AMaViSd without any problems.

Conclusion 1: Sophos's engine can unpack the MIME and archive, detect and even recognize the virus.

Conclusion 2: AMaViSd works properly, since MIME-embedded EICAR attachment was found.

Conclusion 3: The Sophos 'sweep' is utilized, since nothing else is active in AMaViSd.

So, why the real virus is not being detected using AMaViSd?

Thanks!

Regards

Manuel

This thread was automatically locked due to age.

Parents

0 Manuel Kraus over 6 years ago

A bit more AMaViSd-logging. This time ClamAV is active as well.

The relevant file "New.doc" with the trojan is unpacked successfully, but both scanners are blatantly lying about the result:

---

Jul 7 17:24:59 mail amavis[5521]: (05521-02) Extracting mime components from a string
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Issued a new file name: p001
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Issued a new file name: p002
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Issued a new file name: p003
Jul 7 17:24:59 mail amavis[5521]: (05521-02) mime_decode_preamble: 1 lines
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Issued a new pseudo part: p004
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p004 1 Content-Type: multipart/mixed
Jul 7 17:24:59 mail amavis[5521]: (05521-02) mime_decode_preamble: 1 lines
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Issued a new pseudo part: p005
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p005 1/1 Content-Type: multipart/alternative
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Charging 1 bytes to remaining quota 47761500 (out of 47761500, (0%)) - by mime_decode
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p001 1/1/1 Content-Type: text/plain, size: 1 B, name:
Jul 7 17:24:59 mail amavis[5521]: (05521-02) reparenting p001 from p000 to p005
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Charging 493 bytes to remaining quota 47761499 (out of 47761500, (0%)) - by mime_decode
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p002 1/1/2 Content-Type: text/html, size: 493 B, name:
Jul 7 17:24:59 mail amavis[5521]: (05521-02) reparenting p002 from p000 to p005
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Charging 65701 bytes to remaining quota 47761006 (out of 47761500, (0%)) - by mime_decode
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p003 1/2 Content-Type: application/octet-stream, size: 65701 B, name: New.gz
Jul 7 17:24:59 mail amavis[5521]: (05521-02) reparenting p003 from p000 to p004
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline mime_decode - deadline in 480.0 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer mime_decode: timer 288, was 288, deadline in 480.0 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline mime_decode-1 - deadline in 480.0 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer mime_decode-1: timer 288, was 288, deadline in 480.0 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) decode_parts: level=1, #parts=5 : p001, p002, p003, p004, p005
Jul 7 17:24:59 mail amavis[5521]: (05521-02) running file(1) on 3 files, arglist size 28
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_command: [29767] /usr/bin/file p001 p002 p003 </dev/null 2>&1
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: target fd1 closing, to become (65) &=20
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: target fd1 dup2 from fd20 (65) &=20
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: source fd20 closed
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: target fd2 closing, to become (65) &1
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jul 7 17:24:59 mail amavis[5521]: (05521-02) result line from file(1): p001: very short file (no magic)\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re("very short file (no magic)") matches key "(?^:^)", result="dat"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [map_full_type_to_short_type] => true, "very short file (no magic)" matches, result="dat", matching_key="(?^:^)"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) File-type of p001: very short file (no magic); (dat)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) result line from file(1): p002: HTML document, ASCII text\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re("HTML document, ASCII text") matches key "(?^i:\\btext\\b)", result="asc"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [map_full_type_to_short_type] => true, "HTML document, ASCII text" matches, result="asc", matching_key="(?^i:\\btext\\b)"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) File-type of p002: HTML document, ASCII text; (asc)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) result line from file(1): p003: RAR archive data, v1d, os: Win32\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re("RAR archive data, v1d, os: Win32") matches key "(?^i:^RAR archive\\b)", result="rar"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [map_full_type_to_short_type] => true, "RAR archive data, v1d, os: Win32" matches, result="rar", matching_key="(?^i:^RAR archive\\b)"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) File-type of p003: RAR archive data, v1d, os: Win32; (rar)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) decompose_part: p001 - atomic
Jul 7 17:24:59 mail amavis[5521]: (05521-02) decompose_part: p002 - atomic
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Expanding RAR archive p003
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline do_unrar_pre - deadline in 480.0 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer do_unrar_pre: timer 288, was 288, deadline in 480.0 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_command: [29791] /usr/bin/unrar-free v -c- -p- -idcdp -- /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts/p003 </dev/null 2>&1
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: target fd1 closing, to become (65) &=20
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: target fd1 dup2 from fd20 (65) &=20
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: source fd20 closed
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: target fd2 closing, to become (65) &1
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jul 7 17:24:59 mail amavis[5521]: (05521-02) do_unrar: found unrar version < 5
Jul 7 17:24:59 mail amavis[5521]: (05521-02) do_unrar: member: "New.doc\n", size: 145408
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Charging 145408 bytes to remaining quota 47695305 (out of 47761500, (0%)) - by do_unrar-pre
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_command: [29805] /usr/bin/unrar-free x -inul -ver -o- -kb -c- -p- -idcdp -- /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts/p003 /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts/rar/ </dev/null 2>&1
Jul 7 17:24:59 mail amavis[5521]: (05521-02) collect_results from [29805] (/usr/bin/unrar-free), 243 bytes, (limit 16384)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) flatten_and_tidy_dir: processing directory "/var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts/rar"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Charging 0 bytes to remaining quota 47695305 (out of 47761500, (0%)) - by do_unrar
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline do_unrar - deadline in 480.0 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer do_unrar: timer 288, was 288, deadline in 480.0 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re("RAR archive data, v1d, os: Win32"), no matches
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [keep_decoded_original] => undef, "RAR archive data, v1d, os: Win32" does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) decompose_part: deleting /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts/p003
Jul 7 17:24:59 mail amavis[5521]: (05521-02) decompose_part: p003 - archive, unpacked
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline parts_decode - deadline in 480.0 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer parts_decode: timer 288, was 288, deadline in 480.0 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [bypass_header_checks] => undef, "...@..." does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) check_header: 0, OK
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [bypass_header_checks] => undef, "...@..." does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Checking for banned types and filenames
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup: (scalar) matches, result="DEFAULT"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [banned_filename], 1 matches for "...@...", results: "(constant:DEFAULT)"=>"DEFAULT"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) collect banned table[0]: ...@..., tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x39e8da0)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) starting banned checks - traversing message structure tree
Jul 7 17:24:59 mail amavis[5521]: (05521-02) check_for_banned (p004,p003) multipart/mixed | application/octet-stream,.rar,New.gz
Jul 7 17:24:59 mail amavis[5521]: (05521-02) doing banned check for ...@... on multipart/mixed | application/octet-stream,.rar,New.gz
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re(["multipart/mixed","application/octet-stream",".rar","New.gz"]), no matches
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [check_bann:...@...] => undef, ["multipart/mixed","application/octet-stream",".rar","New.gz"] does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [banned_namepath_re] => undef, "P=p004\tL=1\tM=multipart/mixed\nP=p003\tL=1/2\tM=application/octet-stream\tT=rar\tN=New.gz" does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p.path ...@...: "P=p004,L=1,M=multipart/mixed | P=p003,L=1/2,M=application/octet-stream,T=rar,N=New.gz"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) check_for_banned (p004,p005,p001) multipart/mixed | multipart/alternative | text/plain,.dat
Jul 7 17:24:59 mail amavis[5521]: (05521-02) doing banned check for ...@... on multipart/mixed | multipart/alternative | text/plain,.dat
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re(["multipart/mixed","multipart/alternative","text/plain",".dat"]), no matches
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [check_bann:...@...] => undef, ["multipart/mixed","multipart/alternative","text/plain",".dat"] does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [banned_namepath_re] => undef, "P=p004\tL=1\tM=multipart/mixed\nP=p005\tL=1/1\tM=multipart/alternative\nP=p001\tL=1/1/1\tM=text/plain\tT=dat" does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p.path ...@...: "P=p004,L=1,M=multipart/mixed | P=p005,L=1/1,M=multipart/alternative | P=p001,L=1/1/1,M=text/plain,T=dat"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) check_for_banned (p004,p005,p002) multipart/mixed | multipart/alternative | text/html,.asc
Jul 7 17:24:59 mail amavis[5521]: (05521-02) doing banned check for ...@... on multipart/mixed | multipart/alternative | text/html,.asc
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re(["multipart/mixed","multipart/alternative","text/html",".asc"]), no matches
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [check_bann:...@...] => undef, ["multipart/mixed","multipart/alternative","text/html",".asc"] does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [banned_namepath_re] => undef, "P=p004\tL=1\tM=multipart/mixed\nP=p005\tL=1/1\tM=multipart/alternative\nP=p002\tL=1/1/2\tM=text/html\tT=asc" does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p.path ...@...: "P=p004,L=1,M=multipart/mixed | P=p005,L=1/1,M=multipart/alternative | P=p002,L=1/1/2,M=text/html,T=asc"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) banned check: any=0, all=N (1)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re("MAIL"), no matches
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [keep_decoded_original] => undef, "MAIL" does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) files_to_scan: info: part p003 (rar) no longer present
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Calling virus scanners, 2 files to scan in /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts
Jul 7 17:24:59 mail amavis[5521]: (05521-02) invoking av-scanner ClamAV-clamd
Jul 7 17:24:59 mail amavis[5521]: (05521-02) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamav/clamd.ctl
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av (ClamAV-clamd): query template(1,1): CONTSCAN {}\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline run_av_pre - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer run_av_pre: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline run_av_scan - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer run_av_scan: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline ask_daemon_internal_connect_pre - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline ask_daemon_internal_connect - deadline in 479.9 s, set to 10.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer ask_daemon_internal_connect: timer 10, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) ClamAV-clamd: Connecting to socket /var/run/clamav/clamd.ctl
Jul 7 17:24:59 mail amavis[5521]: (05521-02) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout set to 10
Jul 7 17:24:59 mail amavis[5521]: (05521-02) connected to /var/run/clamav/clamd.ctl successfully
Jul 7 17:24:59 mail amavis[5521]: (05521-02) ClamAV-clamd: Sending CONTSCAN /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts\n to socket /var/run/clamav/clamd.ctl
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: needline=0, flush=1, wr=1, timeout=10
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: sending 73 chars
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop sent 73> CONTSCAN /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline ask_daemon_internal_scan - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer ask_daemon_internal_scan: timer 288, was 10, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: needline=0, flush=0, wr=0, timeout=287.998
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: receiving
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop read 68 chars< /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts: OK\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: needline=0, flush=0, wr=0, timeout=287.998
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: receiving
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop read: got eof
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline ask_daemon_internal - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer ask_daemon_internal: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline run_av_3 - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer run_av_3: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av (ClamAV-clamd) result: /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts: OK\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av (ClamAV-clamd): CLEAN
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av (ClamAV-clamd) result: clean
Jul 7 17:24:59 mail amavis[5521]: (05521-02) invoking av-scanner Sophos Anti Virus (sweep)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av (Sophos Anti Virus (sweep)): query template(0,1): -nb -f -all -rec -ss -sc -archive -cab -mime -oe -tnef -idedir=/opt/sophos-av/lib/sav --no-reset-atime {}
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline run_av_pre - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer run_av_pre: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline run_av_scan - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer run_av_scan: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av Using (Sophos Anti Virus (sweep)): /usr/local/bin/sweep -nb -f -all -rec -ss -sc -archive -cab -mime -oe -tnef -idedir=/opt/sophos-av/lib/sav --no-reset-atime /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_command: [29839] /usr/local/bin/sweep -nb -f -all -rec -ss -sc -archive -cab -mime -oe -tnef -idedir=/opt/sophos-av/lib/sav --no-reset-atime /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts </dev/null 2>&1
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: target fd1 closing, to become (65) &=20
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: target fd1 dup2 from fd20 (65) &=20
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: source fd20 closed
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: target fd2 closing, to become (65) &1
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jul 7 17:25:05 mail amavis[5521]: (05521-02) collect_results from [29839] (Sophos Anti Virus (sweep)), 0 bytes, (limit 204800)
Jul 7 17:25:05 mail amavis[5521]: (05521-02) get_deadline run_av_4 - deadline in 473.5 s, set to 285.000 s
Jul 7 17:25:05 mail amavis[5521]: (05521-02) prolong_timer run_av_4: timer 285, was 282, deadline in 473.5 s
Jul 7 17:25:05 mail amavis[5521]: (05521-02) run_av: /usr/local/bin/sweep exit 0,
Jul 7 17:25:05 mail amavis[5521]: (05521-02) run_av (Sophos Anti Virus (sweep)): CLEAN
Jul 7 17:25:05 mail amavis[5521]: (05521-02) run_av (Sophos Anti Virus (sweep)) result: clean

---

I really like to know, what's goin' on here. Otherwise the Sophos scanner is absolutely worthless within the AMaViSd-framework.

Remember: Scanning the mail file manually using 'sweep' worked like a charm!

Ideas?
Cancel
Vote Up 0 Vote Down

Cancel

Reply

0 Manuel Kraus over 6 years ago

A bit more AMaViSd-logging. This time ClamAV is active as well.

The relevant file "New.doc" with the trojan is unpacked successfully, but both scanners are blatantly lying about the result:

---

Jul 7 17:24:59 mail amavis[5521]: (05521-02) Extracting mime components from a string
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Issued a new file name: p001
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Issued a new file name: p002
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Issued a new file name: p003
Jul 7 17:24:59 mail amavis[5521]: (05521-02) mime_decode_preamble: 1 lines
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Issued a new pseudo part: p004
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p004 1 Content-Type: multipart/mixed
Jul 7 17:24:59 mail amavis[5521]: (05521-02) mime_decode_preamble: 1 lines
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Issued a new pseudo part: p005
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p005 1/1 Content-Type: multipart/alternative
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Charging 1 bytes to remaining quota 47761500 (out of 47761500, (0%)) - by mime_decode
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p001 1/1/1 Content-Type: text/plain, size: 1 B, name:
Jul 7 17:24:59 mail amavis[5521]: (05521-02) reparenting p001 from p000 to p005
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Charging 493 bytes to remaining quota 47761499 (out of 47761500, (0%)) - by mime_decode
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p002 1/1/2 Content-Type: text/html, size: 493 B, name:
Jul 7 17:24:59 mail amavis[5521]: (05521-02) reparenting p002 from p000 to p005
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Charging 65701 bytes to remaining quota 47761006 (out of 47761500, (0%)) - by mime_decode
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p003 1/2 Content-Type: application/octet-stream, size: 65701 B, name: New.gz
Jul 7 17:24:59 mail amavis[5521]: (05521-02) reparenting p003 from p000 to p004
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline mime_decode - deadline in 480.0 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer mime_decode: timer 288, was 288, deadline in 480.0 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline mime_decode-1 - deadline in 480.0 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer mime_decode-1: timer 288, was 288, deadline in 480.0 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) decode_parts: level=1, #parts=5 : p001, p002, p003, p004, p005
Jul 7 17:24:59 mail amavis[5521]: (05521-02) running file(1) on 3 files, arglist size 28
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_command: [29767] /usr/bin/file p001 p002 p003 </dev/null 2>&1
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: target fd1 closing, to become (65) &=20
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: target fd1 dup2 from fd20 (65) &=20
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: source fd20 closed
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: target fd2 closing, to become (65) &1
Jul 7 17:24:59 mail amavis[29767]: (05521-02) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jul 7 17:24:59 mail amavis[5521]: (05521-02) result line from file(1): p001: very short file (no magic)\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re("very short file (no magic)") matches key "(?^:^)", result="dat"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [map_full_type_to_short_type] => true, "very short file (no magic)" matches, result="dat", matching_key="(?^:^)"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) File-type of p001: very short file (no magic); (dat)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) result line from file(1): p002: HTML document, ASCII text\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re("HTML document, ASCII text") matches key "(?^i:\\btext\\b)", result="asc"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [map_full_type_to_short_type] => true, "HTML document, ASCII text" matches, result="asc", matching_key="(?^i:\\btext\\b)"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) File-type of p002: HTML document, ASCII text; (asc)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) result line from file(1): p003: RAR archive data, v1d, os: Win32\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re("RAR archive data, v1d, os: Win32") matches key "(?^i:^RAR archive\\b)", result="rar"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [map_full_type_to_short_type] => true, "RAR archive data, v1d, os: Win32" matches, result="rar", matching_key="(?^i:^RAR archive\\b)"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) File-type of p003: RAR archive data, v1d, os: Win32; (rar)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) decompose_part: p001 - atomic
Jul 7 17:24:59 mail amavis[5521]: (05521-02) decompose_part: p002 - atomic
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Expanding RAR archive p003
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline do_unrar_pre - deadline in 480.0 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer do_unrar_pre: timer 288, was 288, deadline in 480.0 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_command: [29791] /usr/bin/unrar-free v -c- -p- -idcdp -- /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts/p003 </dev/null 2>&1
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: target fd1 closing, to become (65) &=20
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: target fd1 dup2 from fd20 (65) &=20
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: source fd20 closed
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: target fd2 closing, to become (65) &1
Jul 7 17:24:59 mail amavis[29791]: (05521-02) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jul 7 17:24:59 mail amavis[5521]: (05521-02) do_unrar: found unrar version < 5
Jul 7 17:24:59 mail amavis[5521]: (05521-02) do_unrar: member: "New.doc\n", size: 145408
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Charging 145408 bytes to remaining quota 47695305 (out of 47761500, (0%)) - by do_unrar-pre
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_command: [29805] /usr/bin/unrar-free x -inul -ver -o- -kb -c- -p- -idcdp -- /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts/p003 /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts/rar/ </dev/null 2>&1
Jul 7 17:24:59 mail amavis[5521]: (05521-02) collect_results from [29805] (/usr/bin/unrar-free), 243 bytes, (limit 16384)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) flatten_and_tidy_dir: processing directory "/var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts/rar"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Charging 0 bytes to remaining quota 47695305 (out of 47761500, (0%)) - by do_unrar
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline do_unrar - deadline in 480.0 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer do_unrar: timer 288, was 288, deadline in 480.0 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re("RAR archive data, v1d, os: Win32"), no matches
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [keep_decoded_original] => undef, "RAR archive data, v1d, os: Win32" does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) decompose_part: deleting /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts/p003
Jul 7 17:24:59 mail amavis[5521]: (05521-02) decompose_part: p003 - archive, unpacked
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline parts_decode - deadline in 480.0 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer parts_decode: timer 288, was 288, deadline in 480.0 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [bypass_header_checks] => undef, "...@..." does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) check_header: 0, OK
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [bypass_header_checks] => undef, "...@..." does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Checking for banned types and filenames
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup: (scalar) matches, result="DEFAULT"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [banned_filename], 1 matches for "...@...", results: "(constant:DEFAULT)"=>"DEFAULT"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) collect banned table[0]: ...@..., tables: DEFAULT=>Amavis::Lookup::RE=ARRAY(0x39e8da0)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) starting banned checks - traversing message structure tree
Jul 7 17:24:59 mail amavis[5521]: (05521-02) check_for_banned (p004,p003) multipart/mixed | application/octet-stream,.rar,New.gz
Jul 7 17:24:59 mail amavis[5521]: (05521-02) doing banned check for ...@... on multipart/mixed | application/octet-stream,.rar,New.gz
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re(["multipart/mixed","application/octet-stream",".rar","New.gz"]), no matches
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [check_bann:...@...] => undef, ["multipart/mixed","application/octet-stream",".rar","New.gz"] does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [banned_namepath_re] => undef, "P=p004\tL=1\tM=multipart/mixed\nP=p003\tL=1/2\tM=application/octet-stream\tT=rar\tN=New.gz" does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p.path ...@...: "P=p004,L=1,M=multipart/mixed | P=p003,L=1/2,M=application/octet-stream,T=rar,N=New.gz"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) check_for_banned (p004,p005,p001) multipart/mixed | multipart/alternative | text/plain,.dat
Jul 7 17:24:59 mail amavis[5521]: (05521-02) doing banned check for ...@... on multipart/mixed | multipart/alternative | text/plain,.dat
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re(["multipart/mixed","multipart/alternative","text/plain",".dat"]), no matches
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [check_bann:...@...] => undef, ["multipart/mixed","multipart/alternative","text/plain",".dat"] does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [banned_namepath_re] => undef, "P=p004\tL=1\tM=multipart/mixed\nP=p005\tL=1/1\tM=multipart/alternative\nP=p001\tL=1/1/1\tM=text/plain\tT=dat" does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p.path ...@...: "P=p004,L=1,M=multipart/mixed | P=p005,L=1/1,M=multipart/alternative | P=p001,L=1/1/1,M=text/plain,T=dat"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) check_for_banned (p004,p005,p002) multipart/mixed | multipart/alternative | text/html,.asc
Jul 7 17:24:59 mail amavis[5521]: (05521-02) doing banned check for ...@... on multipart/mixed | multipart/alternative | text/html,.asc
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re(["multipart/mixed","multipart/alternative","text/html",".asc"]), no matches
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [check_bann:...@...] => undef, ["multipart/mixed","multipart/alternative","text/html",".asc"] does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [banned_namepath_re] => undef, "P=p004\tL=1\tM=multipart/mixed\nP=p005\tL=1/1\tM=multipart/alternative\nP=p002\tL=1/1/2\tM=text/html\tT=asc" does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) p.path ...@...: "P=p004,L=1,M=multipart/mixed | P=p005,L=1/1,M=multipart/alternative | P=p002,L=1/1/2,M=text/html,T=asc"
Jul 7 17:24:59 mail amavis[5521]: (05521-02) banned check: any=0, all=N (1)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup_re("MAIL"), no matches
Jul 7 17:24:59 mail amavis[5521]: (05521-02) lookup [keep_decoded_original] => undef, "MAIL" does not match
Jul 7 17:24:59 mail amavis[5521]: (05521-02) files_to_scan: info: part p003 (rar) no longer present
Jul 7 17:24:59 mail amavis[5521]: (05521-02) Calling virus scanners, 2 files to scan in /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts
Jul 7 17:24:59 mail amavis[5521]: (05521-02) invoking av-scanner ClamAV-clamd
Jul 7 17:24:59 mail amavis[5521]: (05521-02) ask_daemon: proto=DFLT, spawn=0, (ClamAV-clamd) /var/run/clamav/clamd.ctl
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av (ClamAV-clamd): query template(1,1): CONTSCAN {}\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline run_av_pre - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer run_av_pre: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline run_av_scan - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer run_av_scan: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av Using (ClamAV-clamd): (code) CONTSCAN /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline ask_daemon_internal_connect_pre - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline ask_daemon_internal_connect - deadline in 479.9 s, set to 10.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer ask_daemon_internal_connect: timer 10, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) ClamAV-clamd: Connecting to socket /var/run/clamav/clamd.ctl
Jul 7 17:24:59 mail amavis[5521]: (05521-02) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.ctl, timeout set to 10
Jul 7 17:24:59 mail amavis[5521]: (05521-02) connected to /var/run/clamav/clamd.ctl successfully
Jul 7 17:24:59 mail amavis[5521]: (05521-02) ClamAV-clamd: Sending CONTSCAN /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts\n to socket /var/run/clamav/clamd.ctl
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: needline=0, flush=1, wr=1, timeout=10
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: sending 73 chars
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop sent 73> CONTSCAN /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline ask_daemon_internal_scan - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer ask_daemon_internal_scan: timer 288, was 10, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: needline=0, flush=0, wr=0, timeout=287.998
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: receiving
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop read 68 chars< /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts: OK\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: needline=0, flush=0, wr=0, timeout=287.998
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop: receiving
Jul 7 17:24:59 mail amavis[5521]: (05521-02) rw_loop read: got eof
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline ask_daemon_internal - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer ask_daemon_internal: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline run_av_3 - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer run_av_3: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av (ClamAV-clamd) result: /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts: OK\n
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av (ClamAV-clamd): CLEAN
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av (ClamAV-clamd) result: clean
Jul 7 17:24:59 mail amavis[5521]: (05521-02) invoking av-scanner Sophos Anti Virus (sweep)
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av (Sophos Anti Virus (sweep)): query template(0,1): -nb -f -all -rec -ss -sc -archive -cab -mime -oe -tnef -idedir=/opt/sophos-av/lib/sav --no-reset-atime {}
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline run_av_pre - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer run_av_pre: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) get_deadline run_av_scan - deadline in 479.9 s, set to 288.000 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) prolong_timer run_av_scan: timer 288, was 288, deadline in 479.9 s
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_av Using (Sophos Anti Virus (sweep)): /usr/local/bin/sweep -nb -f -all -rec -ss -sc -archive -cab -mime -oe -tnef -idedir=/opt/sophos-av/lib/sav --no-reset-atime /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts
Jul 7 17:24:59 mail amavis[5521]: (05521-02) run_command: [29839] /usr/local/bin/sweep -nb -f -all -rec -ss -sc -archive -cab -mime -oe -tnef -idedir=/opt/sophos-av/lib/sav --no-reset-atime /var/lib/amavis/tmp/amavis-20180707T171107-05521-Ha5M4KKZ/parts </dev/null 2>&1
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: target fd0 closing, to become < /dev/null
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: target fd1 closing, to become (65) &=20
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: target fd1 dup2 from fd20 (65) &=20
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: source fd20 closed
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: target fd2 closing, to become (65) &1
Jul 7 17:24:59 mail amavis[29839]: (05521-02) open_on_specific_fd: target fd2 dup2 from fd1 (65) &1
Jul 7 17:25:05 mail amavis[5521]: (05521-02) collect_results from [29839] (Sophos Anti Virus (sweep)), 0 bytes, (limit 204800)
Jul 7 17:25:05 mail amavis[5521]: (05521-02) get_deadline run_av_4 - deadline in 473.5 s, set to 285.000 s
Jul 7 17:25:05 mail amavis[5521]: (05521-02) prolong_timer run_av_4: timer 285, was 282, deadline in 473.5 s
Jul 7 17:25:05 mail amavis[5521]: (05521-02) run_av: /usr/local/bin/sweep exit 0,
Jul 7 17:25:05 mail amavis[5521]: (05521-02) run_av (Sophos Anti Virus (sweep)): CLEAN
Jul 7 17:25:05 mail amavis[5521]: (05521-02) run_av (Sophos Anti Virus (sweep)) result: clean

---

I really like to know, what's goin' on here. Otherwise the Sophos scanner is absolutely worthless within the AMaViSd-framework.

Remember: Scanning the mail file manually using 'sweep' worked like a charm!

Ideas?
Cancel
Vote Up 0 Vote Down

Cancel

Children

+1 Manuel Kraus over 6 years ago in reply to Manuel Kraus

After trying

/usr/bin/unrar-free v -c- -p- -idcdp -- /var/lib/amavis/tmp/amavis-20180707T214049-27443-Nf_ig2Vn/parts/p003 </dev/null 2>&1
/usr/bin/unrar-free x -inul -ver -o- -kb -c- -p- -idcdp -- /var/lib/amavis/tmp/amavis-20180707T215249-27444-J6CYjGUs/parts/p003 /var/lib/amavis/tmp/amavis-20180707T215249-27444-J6CYjGUs/parts/rar/ </dev/null 2>&1

at the command line manually, errors were returned about invalid options:

/usr/bin/unrar-free: invalid option -- 'i'
Try `unrar-free --help' or `unrar-free --usage' for more information.

The RAR-files were simply not decompressed and absolutely no error was reported by AMaViSd on that.

So 'amavisd' and 'unrar-free' are not working together and the AMaViSd-folks are to blame not doing proper dependency checks on the utilized tools and more importantly ... useful error reporting!

Below solutions are valid for Debian/Ubuntu.

Ubuntu 16.04.4 LTS

amavisd-new 1:2.10.1-2ubuntu1

unrar-free 1:0.0.1+cvs20140707

Solution 1

Change file '/etc/amavis/conf.d/01-debian' from

# $unrar = ['rar', 'unrar']; #disabled (non-free, no security support)
$unrar = ['unrar-free'];

to

$unrar = ['rar', 'unrar']; #disabled (non-free, no security support)
# $unrar = ['unrar-free'];

and install the 'unrar'-package.

Solution 2

Change file '/etc/amavis/conf.d/20-debian_defaults' from

@keep_decoded_original_maps = (new_RE(
# qr'^MAIL$', # retain full original message for virus checking (can be slow)
qr'^MAIL-UNDECIPHERABLE$', # recheck full mail if it contains undecipherables
qr'^(ASCII(?! cpio)|text|uuencoded|xxencoded|binhex)'i,
# qr'^Zip archive data', # don't trust Archive::Zip
));

to

@keep_decoded_original_maps = (new_RE(
qr'^MAIL$', # retain full original message for virus checking (can be slow)
# qr'^MAIL-UNDECIPHERABLE$', # recheck full mail if it contains undecipherables
# qr'^(ASCII(?! cpio)|text|uuencoded|xxencoded|binhex)'i,
# qr'^Zip archive data', # don't trust Archive::Zip
));

and let Sophos do all levels of decoding.

I hate to say that, but that was another day wasted to Linux.

At least it's not Sophos fault. ;-)
Cancel
Vote Up 0 Vote Down

Cancel