It seems that amavisd isn't properly looking inside of "rar" attachments
in our configuration. The unrar binary is detected on startup as the
application to deal with rar archives, but nothing is (seemingly) done
with these archives when a message passes through the system.
I can successfully unrar stuff using the binary on the command line
(unrar e <filename>), and other archive utilities seem to be working
well. Problem seems to occur with numerous versions of amavisd-new
(2.3.2, 2.5.2, 2.6.1).
Thoughts on what I should be looking at here? Any help greatly appreciated.
Log snippit from message containing test.rar (which contains a (banned)
.exe file):
Oct 23 13:31:23 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
p002 1/2 Content-Type: application/octet-stream, size: 64622 B, name:
test.rar
Oct 23 13:31:23 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
reparenting p002 from p000 to p003
Oct 23 13:31:23 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
prolong_timer mime_decode: remaining time = 480 s
Oct 23 13:31:23 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
prolong_timer mime_decode-1: remaining time = 480 s
Oct 23 13:31:23 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
decode_parts: level=1, #parts=3 : p001, p002, p003
Oct 23 13:31:23 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
running file(1) on 2 files, arglist size 23
Oct 23 13:31:24 iscan1 amavis[22336]: [ID 702911 local1.info] (22296-01)
open_on_specific_fd: target fd0 closing, to become < /dev/null
Oct 23 13:31:24 iscan1 amavis[22336]: [ID 702911 local1.info] (22296-01)
open_on_specific_fd: target fd2 closing, to become > &1
Oct 23 13:31:24 iscan1 amavis[22336]: [ID 702911 local1.info] (22296-01)
open_on_specific_fd: target fd2 dup2 from fd1 > &1
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
run_command: [22336] /usr/bin/file p001 p002 </dev/null 2>&1
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
result line from file(1): p001:\t\tascii text
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup_re("ascii text") matches key "(?i-xsm:^(ASCII|text)\b)", result="asc"
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup (map_full_type_to_short_type) => true, "ascii text" matches,
result="asc", matching_key="(?i-xsm:^(ASCII|text)\\b)"
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
File-type of p001: ascii text; (asc)
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
result line from file(1): p002:\t\tdata
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup_re("data") matches key "(?-xism:^dataz)", result="dat"
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup (map_full_type_to_short_type) => true, "data" matches,
result="dat", matching_key="(?-xism:^data\\z)"
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
File-type of p002: data; (dat)
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
do_ascii: Decoding part p001
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
do_ascii: Setting sigaction handler, was 0
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
timer set to 320 s (was 480 s)
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
do_ascii: Decoding part p001 (0 items), uulib V0.5pl20
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
prolong_timer do_ascii: timer set to 480 s
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
decompose_part: p001 - atomic
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
decompose_part: p002 - atomic
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
prolong_timer parts_decode: remaining time = 480 s
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
query_keys: [EMAIL PROTECTED], jengbrec@, -----.ca, -----.ca, -----.ca,
.ca, .
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup_hash([EMAIL PROTECTED]), no matches
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup (bypass_header_checks) => undef, "[EMAIL PROTECTED]" does not match
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
check_header: 0, OK
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
query_keys: [EMAIL PROTECTED], jengbrec@, -----.ca, .-----.ca,
.ryerson.ca, .ca, .
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup_hash([EMAIL PROTECTED]), no matches
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup (bypass_header_checks) => undef, "[EMAIL PROTECTED]" does not match
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
Checking for banned types and filenames
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup: (scalar) matches, result="DEFAULT"
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup (banned_filename), 1 matches for "[EMAIL PROTECTED]", results:
"(constant:DEFAULT)"=>"DEFAULT"
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
collect banned table[0]: [EMAIL PROTECTED], tables:
DEFAULT=>Amavis::Lookup::RE=ARRAY(0xd910dc)
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
starting banned checks - traversing message structure tree
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
check_for_banned (p003,p001) multipart/mixed | text/plain,.asc
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
doing banned check for [EMAIL PROTECTED] on multipart/mixed |
text/plain,.asc
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup_re(["multipart/mixed","text/plain",".asc"]), no matches
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup (check_bann:[EMAIL PROTECTED]) => undef,
["multipart/mixed","text/plain",".asc"] does not match
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
p.path [EMAIL PROTECTED]: "P=p003,L=1,M=multipart/mixed |
P=p001,L=1/1,M=text/plain,T=asc"
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
check_for_banned (p003,p002) multipart/mixed |
application/octet-stream,.dat,test.rar
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
doing banned check for [EMAIL PROTECTED] on multipart/mixed |
application/octet-stream,.dat,test.rar
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup_re(["multipart/mixed","application/octet-stream",".dat","test.rar"]),
no matches
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
lookup (check_bann:[EMAIL PROTECTED]) => undef,
["multipart/mixed","application/octet-stream",".dat","test.rar"] does
not match
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
p.path [EMAIL PROTECTED]: "P=p003,L=1,M=multipart/mixed |
P=p002,L=1/2,M=application/octet-stream,T=dat,N=test.rar"
Oct 23 13:31:24 iscan1 amavis[22296]: [ID 702911 local1.info] (22296-01)
banned check: any=0, all=N (1)
-------------------------------------------------------------------------
This SF.Net email is sponsored by the Moblin Your Move Developer's challenge
Build the coolest Linux based applications with Moblin SDK & win great prizes
Grand prize is a trip for two to an Open Source event anywhere in the world
http://moblin-contest.org/redirect.php?banner_id=100&url=/
_______________________________________________
AMaViS-user mailing list
AMaViS-user@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/
