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

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?

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. ;-)

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. ;-)