Mark, > Steve, > > > I am having a problem where my content filter (amavisd-new) > is failing > > to deal with large messages, even though it knows to bypass all > > filtering on messages over 1M and pass it up to the second postfix > > smtpd. > > We need to be able to receive these large messages (I know, > I know...) > > How large is your 'large'? > See detailed amavisd-new timing log (at $log_level=2) and identify > what operation is taking excessively long time. Fix the problem > where it occurs. (followups if any to the amavis-user ML please) > > Mark
Well, 40MB in this case. And I am using the amavis-new variant from Maia, so I didn't want to bug you guys ;) But, since you asked...This is what the log looks like at level 5. As you can see, spam filtering is being bypassed and we aren't hitting any timeouts. Just seems to fall over. Jan 18 14:29:55 spam amavis[8890]: (08890-01) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready Jan 18 14:29:55 spam amavis[8890]: (08890-01) idle_proc, 4: was busy, 40.9 ms, total idle 0.000 s, busy 0.041 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) idle_proc, 5: was idle, 1.9 ms, total idle 0.002 s, busy 0.041 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) prolong_timer after reading SMTP command: remaining time = 600 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) SMTP< EHLO spam.example.com\\r\\n Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP> 250-[127.0.0.1] Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP> 250-PIPELINING Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP> 250-SIZE Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP> 250-8BITMIME Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP> 250-ENHANCEDSTATUSCODES Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP> 250 XFORWARD NAME ADDR PROTO HELO Jan 18 14:29:55 spam amavis[8890]: (08890-01) idle_proc, 6: was busy, 8.4 ms, total idle 0.002 s, busy 0.049 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) idle_proc, 5: was idle, 1.1 ms, total idle 0.003 s, busy 0.049 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) prolong_timer after reading SMTP command: remaining time = 600 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP< MAIL FROM:<[EMAIL PROTECTED]> SIZE=40107064\\r\\n Jan 18 14:29:55 spam amavis[8890]: (08890-01) prolong_timer after MAIL FROM received - timer reset: remaining time = 600 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) prepare_tempdir: creating directory /var/spool/spamassassin/tmp/amavis-20060118T142955-08890 Jan 18 14:29:55 spam amavis[8890]: (08890-01) prepare_tempdir: creating file /var/spool/spamassassin/tmp/amavis-20060118T142955-08890/email.txt Jan 18 14:29:55 spam amavis[8890]: (08890-01) lookup (debug_sender) => undef, "[EMAIL PROTECTED]" does not match Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP> 250 2.1.0 Sender [EMAIL PROTECTED] OK Jan 18 14:29:55 spam amavis[8890]: (08890-01) idle_proc, 6: was busy, 17.0 ms, total idle 0.003 s, busy 0.066 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) idle_proc, 5: was idle, 0.8 ms, total idle 0.004 s, busy 0.066 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) prolong_timer after reading SMTP command: remaining time = 600 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP< RCPT TO:<[EMAIL PROTECTED]>\\r\\n Jan 18 14:29:55 spam amavis[8890]: (08890-01) Connecting to SQL database server Jan 18 14:29:55 spam amavis[8890]: (08890-01) connect_to_sql: trying 'DBI:mysql:maia:localhost' Jan 18 14:29:55 spam amavis[8890]: (08890-01) connect_to_sql: 'DBI:mysql:maia:localhost' succeeded Jan 18 14:29:55 spam amavis[8890]: (08890-01) lookup_acl([EMAIL PROTECTED]) matches key ".example.com", result=1 Jan 18 14:29:55 spam amavis[8890]: (08890-01) lookup (local_domains) => true, "[EMAIL PROTECTED]" matches, result="1", matching_key=".nth-inc.com" Jan 18 14:29:55 spam amavis[8890]: (08890-01) query_keys: [EMAIL PROTECTED], fred, @example.com, @.example.com, @.com, @. Jan 18 14:29:55 spam amavis[8890]: (08890-01) SQL prepare(6): SELECT *,users.id FROM users,policy WHERE (users.policy_id=policy.id) AND (users.email IN (?,?,?,?,?,?)) ORDER BY users.priority DESC Jan 18 14:29:55 spam amavis[8890]: (08890-01) lookup_sql "[EMAIL PROTECTED]", query keys: "[EMAIL PROTECTED]", "fred", "@example.com", "@.example.com", "@.com", "@." Jan 18 14:29:55 spam amavis[8890]: (08890-01) lookup_sql select: SELECT *,users.id FROM users,policy WHERE (users.policy_id=policy.id) AND (users.email IN (?,?,?,?,?,?)) ORDER BY users.priority DESC Jan 18 14:29:55 spam amavis[8890]: (08890-01) lookup_sql: "[EMAIL PROTECTED]" matches catchall, local=>undef Jan 18 14:29:55 spam amavis[8890]: (08890-01) lookup_sql([EMAIL PROTECTED]) matches, result=(id=>"11", priority=>"2", policy_id=>"12", email=>"@nth-inc.com", maia_user_id=>"11", maia_domain_id=>"3", id=>"11", policy_name=>"@nth-inc.com", virus_lover=>"N", spam_lover=>"N", banned_files_lover=>"N", bad_header_lover=>"Y", bypass_virus_checks=>"N", bypass_spam_checks=>"N", bypass_banned_checks=>"N", bypass_header_checks=>"Y", discard_viruses=>"N", discard_spam=>"N", discard_banned_files=>"N", discard_bad_headers=>"N", spam_modifies_subj=>"N", spam_quarantine_to=>-, spam_tag_level=>"-999", spam_tag2_level=>"5", spam_kill_level=>"5", id=>"11") Jan 18 14:29:55 spam amavis[8890]: (08890-01) lookup_sql([EMAIL PROTECTED]) matches, result=(id=>"1", priority=>"0", policy_id=>"1", email=>"@.", maia_user_id=>"1", maia_domain_id=>"1", id=>"1", policy_name=>"Default", virus_lover=>"N", spam_lover=>"N", banned_files_lover=>"N", bad_header_lover=>"Y", bypass_virus_checks=>"N", bypass_spam_checks=>"N", bypass_banned_checks=>"N", bypass_header_checks=>"Y", discard_viruses=>"N", discard_spam=>"N", discard_banned_files=>"N", discard_bad_headers=>"N", spam_modifies_subj=>"N", spam_quarantine_to=>-, spam_tag_level=>"-999", spam_tag2_level=>"5", spam_kill_level=>"5", id=>"1", local=>-) Jan 18 14:29:55 spam amavis[8890]: (08890-01) lookup_sql_field(message_size_limit), no field, "[EMAIL PROTECTED]" result=undef Jan 18 14:29:55 spam amavis[8890]: (08890-01) lookup_sql_field(message_size_limit), no field, "[EMAIL PROTECTED]" result=undef Jan 18 14:29:55 spam amavis[8890]: (08890-01) lookup (message_size_limit) => undef, "[EMAIL PROTECTED]" does not match Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP> 250 2.1.5 Recipient [EMAIL PROTECTED] OK Jan 18 14:29:55 spam amavis[8890]: (08890-01) idle_proc, 6: was busy, 46.5 ms, total idle 0.004 s, busy 0.113 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) idle_proc, 5: was idle, 0.8 ms, total idle 0.005 s, busy 0.113 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) prolong_timer after reading SMTP command: remaining time = 600 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP< DATA\\r\\n Jan 18 14:29:55 spam amavis[8890]: (08890-01) prolong_timer after DATA received - timer reset: remaining time = 600 s Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP::10024 /var/spool/spamassassin/tmp/amavis-20060118T142955-08890: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> Received: SIZE=40107064 from spam.example.com ([127.0.0.1]) by localhost (filter.example.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 08890-01 for <[EMAIL PROTECTED]>; Wed, 18 Jan 2006 14:29:55 -0600 (CST) Jan 18 14:29:55 spam amavis[8890]: (08890-01) ESMTP> 354 End data with <CR><LF>.<CR><LF> Jan 18 14:30:11 spam amavis[8890]: (08890-01) ESMTP< .\\r\\n Jan 18 14:30:13 spam amavis[8890]: (08890-01) body hash: 1a1c345413875f89487014f8b16e5a27 Jan 18 14:30:13 spam amavis[8890]: (08890-01) Original mail size: 40107064; quota set to: 314572800 bytes Jan 18 14:30:13 spam amavis[8890]: (08890-01) Checking: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [connect_to_sql] Connecting to SQL database server Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [connect_to_sql] Trying 'DBI:mysql:maia:localhost' Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [connect_to_sql] 'DBI:mysql:maia:localhost' succeeded Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [connect] Database type is MySQL Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] False negative management is ENABLED Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] Virus scanning is ENABLED Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] Spam filtering is ENABLED Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] Bad header checking is ENABLED Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] Banned files checking is ENABLED Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] User autocreation is DISABLED Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] Internal authentication mechanism is ENABLED Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] Stats tracking is ENABLED Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] Spam traps are ENABLED Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] Mail larger than 1000000 bytes will be PASSED Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] The system default user (@.) WILL apply to non-local recipients Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [read_system_config] Blowfish encryption is DISABLED Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [get_mysql_size_limit] MySQL max_allowed_packet size is 1048576 bytes Jan 18 14:30:13 spam amavis[8890]: (08890-01) Maia: [check_mail] Oversized item, skipping all tests Jan 18 14:30:13 spam amavis[8890]: (08890-01) Extracting mime components Jan 18 14:30:13 spam amavis[8890]: (08890-01) Issued a new file name: p001 Jan 18 14:30:13 spam amavis[8890]: (08890-01) Issued a new file name: p002 Jan 18 14:30:21 spam amavis[8890]: (08890-01) Issued a new file name: p003 Jan 18 14:30:29 spam amavis[8890]: (08890-01) mime_decode_preamble: 2 lines Jan 18 14:30:29 spam amavis[8890]: (08890-01) Issued a new pseudo part: p004 Jan 18 14:30:29 spam amavis[8890]: (08890-01) p004 1 Content-Type: multipart/mixed Jan 18 14:30:29 spam amavis[8890]: (08890-01) mime_decode_preamble: 1 lines Jan 18 14:30:29 spam amavis[8890]: (08890-01) Issued a new pseudo part: p005 Jan 18 14:30:29 spam amavis[8890]: (08890-01) p005 1/1 Content-Type: multipart/alternative Jan 18 14:30:29 spam amavis[8890]: (08890-01) mime_decode_epilogue: 1 lines Jan 18 14:30:29 spam amavis[8890]: (08890-01) Charging 1173 bytes to remaining quota 314572800 (out of 314572800, (0%)) - by mime_decode Jan 18 14:30:29 spam amavis[8890]: (08890-01) p001 1/1/1 Content-Type: text/plain, size: 1173 B, name: Jan 18 14:30:29 spam amavis[8890]: (08890-01) reparenting p001 from p000 to p005 Jan 18 14:30:29 spam amavis[8890]: (08890-01) Charging 5339 bytes to remaining quota 314571627 (out of 314572800, (0%)) - by mime_decode Jan 18 14:30:29 spam amavis[8890]: (08890-01) p002 1/1/2 Content-Type: text/html, size: 5339 B, name: Jan 18 14:30:29 spam amavis[8890]: (08890-01) reparenting p002 from p000 to p005 Jan 18 14:30:29 spam amavis[8890]: (08890-01) Charging 29302074 bytes to remaining quota 314566288 (out of 314572800, (9%)) - by mime_decode Jan 18 14:30:29 spam amavis[8890]: (08890-01) p003 1/2 Content-Type: application/octet-stream, size: 29302074 B, name: InteriorWalls_SpecialOlympicsMNpdf.pdf Jan 18 14:30:29 spam amavis[8890]: (08890-01) reparenting p003 from p000 to p004 Jan 18 14:30:29 spam amavis[8890]: (08890-01) prolong_timer after mime_decode-1: remaining time = 567 s Jan 18 14:30:29 spam amavis[8890]: (08890-01) decode_parts: level=1, #parts=5 : p001, p002, p003, p004, p005 Jan 18 14:30:29 spam amavis[8890]: (08890-01) run_command: [31229] /usr/bin/file p001 p002 p003 </dev/null 2>&1 Jan 18 14:30:29 spam amavis[8890]: (08890-01) result line from file(1): p001: ASCII English text Jan 18 14:30:29 spam amavis[8890]: (08890-01) lookup_re(ASCII English text) matches key "(?i-xsm:^(ASCII|text)\\b)", result=asc Jan 18 14:30:29 spam amavis[8890]: (08890-01) lookup (map_full_type_to_short_type) => true, "ASCII English text" matches, result="asc", matching_key="(?i-xsm:^(ASCII|text)\\\\b)" Jan 18 14:30:29 spam amavis[8890]: (08890-01) File-type of p001: ASCII English text; (asc) Jan 18 14:30:29 spam amavis[8890]: (08890-01) result line from file(1): p002: HTML document text Jan 18 14:30:29 spam amavis[8890]: (08890-01) lookup_re(HTML document text) matches key "(?-xism:^HTML document text\\b)", result=html Jan 18 14:30:29 spam amavis[8890]: (08890-01) lookup (map_full_type_to_short_type) => true, "HTML document text" matches, result="html", matching_key="(?-xism:^HTML document text\\\\b)" Jan 18 14:30:29 spam amavis[8890]: (08890-01) File-type of p002: HTML document text; (html) Jan 18 14:30:29 spam amavis[8890]: (08890-01) result line from file(1): p003: PDF document, version 1.6 Jan 18 14:30:29 spam amavis[8890]: (08890-01) lookup_re(PDF document, version 1.6) matches key "(?-xism:^PDF document\\b)", result=pdf Jan 18 14:30:29 spam amavis[8890]: (08890-01) lookup (map_full_type_to_short_type) => true, "PDF document, version 1.6" matches, result="pdf", matching_key="(?-xism:^PDF document\\\\b)" Jan 18 14:30:29 spam amavis[8890]: (08890-01) File-type of p003: PDF document, version 1.6; (pdf) Jan 18 14:30:29 spam amavis[8890]: (08890-01) do_ascii: Decoding part p001 (0 items), uulib V0.5pl20 Jan 18 14:30:29 spam amavis[8890]: (08890-01) decompose_part: p001 - atomic Jan 18 14:30:29 spam amavis[8890]: (08890-01) decompose_part: p002 - atomic Jan 18 14:30:29 spam amavis[8890]: (08890-01) decompose_part: p003 - atomic Jan 18 14:30:29 spam amavis[8890]: (08890-01) prolong_timer after parts_decode: remaining time = 567 s Jan 18 14:30:53 spam amavis[8890]: (08890-01) at the END handler: invoking DESTROY methods Jan 18 14:30:53 spam amavis[8890]: (08890-01) Amavis::In::SMTP::DESTROY called Jan 18 14:30:53 spam amavis[8890]: (08890-01) SMTP shutdown: tempdir is being removed: /var/spool/spamassassin/tmp/amavis-20060118T142955-08890 Jan 18 14:30:53 spam amavis[8890]: (08890-01) rmdir_recursively: /var/spool/spamassassin/tmp/amavis-20060118T142955-08890, excl= Jan 18 14:30:53 spam amavis[8890]: (08890-01) rmdir_recursively: /var/spool/spamassassin/tmp/amavis-20060118T142955-08890/parts, excl=0 Jan 18 14:30:53 spam amavis[8890]: (08890-01) ESMTP> 421 4.3.2 Service shutting down, closing channel Jan 18 14:30:53 spam amavis[8890]: (08890-01) Amavis::Lookup::SQL called Jan 18 14:30:53 spam amavis[8890]: (08890-01) Amavis::Lookup::SQL called ------------------------------------------------------- This SF.net email is sponsored by: Splunk Inc. Do you grep through log files for problems? Stop! Download the new AJAX search engine that makes searching your log files as easy as surfing the web. DOWNLOAD SPLUNK! http://sel.as-us.falkag.net/sel?cmd=lnk&kid3432&bid#0486&dat1642 _______________________________________________ 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/
