Hi all,

I'm testing Amavisd-new since a few days ago. It seems I've got a 
problem, so:

* If Amavisd is active and I send a mail to anywhere, I always get the 
same error:

Considered UNSOLICITED BULK EMAIL, apparently from you

The /var/log/maillog reveals:

Aug  8 13:44:28 mail amavis[11097]: (11097-01) rw_loop: receiving
Aug  8 13:44:28 mail amavis[11097]: (11097-01) rw_loop read 52 chars< 
250 2.0.0 Ok: queued as 4D345D5028B\r\n221 2.0.0 Bye\r\
n
Aug  8 13:44:28 mail amavis[11097]: (11097-01) smtp resp to data-dot 
(<[EMAIL PROTECTED]>): 250 2.0.0 Ok: queued as 4D
345D5028B
Aug  8 13:44:28 mail amavis[11097]: (11097-01) smtp resp to QUIT: 221 
2.0.0 Bye
Aug  8 13:44:28 mail amavis[11097]: (11097-01) prolong_timer 
fwd-end-chkpnt: timer set to 479 s
Aug  8 13:44:28 mail amavis[11097]: (11097-01) SEND via SMTP: <> -> 
<[EMAIL PROTECTED]>,[EMAIL PROTECTED]
l.opengea.org 250 2.6.0 Ok, id=11097-01, from MTA([127.0.0.1]:10025): 
250 2.0.0 Ok: queued as 4D345D5028B
Aug  8 13:44:28 mail amavis[11097]: (11097-01) one_response_for_all <>: 
success, r=0,b=0,d=0, ndn_needed=0, '250 2.0.0 Ok: qu
eued as 4D345D5028B'
Aug  8 13:44:28 mail amavis[11097]: (11097-01) prolong_timer 
delivery-notification: remaining time = 479 s
Aug  8 13:44:28 mail amavis[11097]: (11097-01) parse_received: from = 
[192.168.1.33] (52.Red-83-50-11.dynamicIP.rima-tde[...]
/[192.168.1.33]/52.Red-83-50-11.dynamicIP.rima-tde.net/83.50.11.52
Aug  8 13:44:28 mail amavis[11097]: (11097-01) parse_received: by = 
mail.opengea.org /mail.opengea.org//
Aug  8 13:44:28 mail amavis[11097]: (11097-01) parse_received: with = 
ESMTP /ESMTP //
Aug  8 13:44:28 mail postfix/smtpd[11111]: disconnect from 
tartarus[127.0.0.1]
Aug  8 13:44:28 mail amavis[11097]: (11097-01) parse_received: id = 
2849CD50283\t/2849CD50283\t//
Aug  8 13:44:28 mail amavis[11097]: (11097-01) parse_received: for = 
<[EMAIL PROTECTED]>/<[EMAIL PROTECTED]>//
Aug  8 13:44:28 mail amavis[11097]: (11097-01) parse_received: ; = Wed, 
  8 Aug 2007 13:44:27 +0200 (CEST)/Wed,  8 Aug 2007 13
:44:27 +0200 (CEST)//
Aug  8 13:44:28 mail amavis[11097]: (11097-01) 
fish_out_ip_from_received: 83.50.11.52, [192.168.1.33] 
(52.Red-83-50-11.dynami
cIP.rima-tde.net [83.50.11.52])\t
Aug  8 13:44:28 mail amavis[11097]: (11097-01) lookup_ip_acl 
(publicnetworks): key="83.50.11.52" matches "::FFFF:0:0/96", res
ult=1
Aug  8 13:44:28 mail amavis[11097]: (11097-01) best_try_originator_ip: 
83.50.11.52
Aug  8 13:44:28 mail amavis[11097]: (11097-01) Blocked SPAM, 
[83.50.11.52] [83.50.11.52] <[EMAIL PROTECTED]> -> <jespa
[EMAIL PROTECTED]>, quarantine: S/spam-S0idyJZHTUUm.gz, Message-ID: 
<[EMAIL PROTECTED]>, mail_id: S0idyJZHTUUm, Hits:
9.112, size: 755, 906 ms
Aug  8 13:44:28 mail amavis[11097]: (11097-01) prolong_timer 
main_log_entry: remaining time = 479 s
Aug  8 13:44:28 mail amavis[11097]: (11097-01) updating snmp variables
Aug  8 13:44:28 mail amavis[11097]: (11097-01) prolong_timer check done: 
remaining time = 479 s
Aug  8 13:44:28 mail amavis[11097]: (11097-01) sending SMTP response: 
"250 2.5.0 Ok, id=11097-01, BOUNCE"
Aug  8 13:44:28 mail amavis[11097]: (11097-01) ESMTP> 250 2.5.0 Ok, 
id=11097-01, BOUNCE
Aug  8 13:44:28 mail postfix/smtp[11108]: 2849CD50283: 
to=<[EMAIL PROTECTED]>, relay=localhost[127.0.0.1]:10024, delay=1.3,
delays=0.41/0.01/0.01/0.9, dsn=2.5.0, status=sent (250 2.5.0 Ok, 
id=11097-01, BOUNCE)
Aug  8 13:44:28 mail postfix/qmgr[10687]: 2849CD50283: removed
Aug  8 13:44:28 mail amavis[11097]: (11097-01) switch_to_client_time 480 
s, smtp response sent
Aug  8 13:44:28 mail amavis[11097]: (11097-01) TempDir::strip: 
/var/amavis/tmp/amavis-20070808T134427-11097
Aug  8 13:44:28 mail amavis[11097]: (11097-01) rmdir_recursively: 
/var/amavis/tmp/amavis-20070808T134427-11097/parts, excl=1
Aug  8 13:44:28 mail amavis[11097]: (11097-01) TIMING [total 910 ms] - 
SMTP greeting: 9 (1%)1, SMTP EHLO: 3 (0%)1, SMTP pre-M
AIL: 3 (0%)2, mkdir tempdir: 1 (0%)2, create email.txt: 1 (0%)2, SMTP 
pre-DATA-flush: 6 (1%)2, SMTP DATA: 24 (3%)5, check_ini
t: 1 (0%)5, digest_hdr: 1 (0%)5, digest_body: 1 (0%)5, gen_mail_id: 1 
(0%)5, mkdir parts: 1 (0%)6, mime_decode: 12 (1%)7, get
-file-type1: 38 (4%)11, decompose_part: 3 (0%)11, parts_decode: 0 
(0%)11, check_header: 3 (0%)12, AV-scan-1: 8 (1%)13, spam-w
b-list: 6 (1%)13, SA parse: 6 (1%)14, SA check: 676 (74%)88, 
update_cache: 5 (1%)89, decide_mail_destiny: 4 (0%)89, open-mbx:
  15 (2%)91, write-header: 1 (0%)91, save-to-local-mailbox: 0 (0%)91, 
prepare-dsn: 21 (2%)93, fwd-connect: 14 (2%)95, fwd-mail
-pip: 9 (1%)96, fwd-rcpt-pip: 0 (0%)96, fwd-data-chkpnt: 0 (0%)96, 
write-header: 1 (0%)96, fwd-data-contents: 5 (1%)96, fwd-e
nd-chkpnt: 22 (2%)99, main_log_entry: 7 (1%)100, update_snmp: 1 (0%)100, 
SMTP pre-response: 1 (0%)100, SMTP response: 1 (0%)1
00, unlink-1-...
Aug  8 13:44:28 mail amavis[11097]: (11097-01) ...files: 1 (0%)100, 
rundown: 0 (0%)100
Aug  8 13:44:28 mail amavis[11097]: (11097-01) idle_proc, 6: was busy, 
890.6 ms, total idle 0.001 s, busy 0.910 s
Aug  8 13:44:28 mail amavis[11097]: (11097-01) idle_proc, 5: was idle, 
0.2 ms, total idle 0.001 s, busy 0.910 s
Aug  8 13:44:28 mail amavis[11097]: (11097-01) ESMTP< QUIT\r\n
Aug  8 13:44:28 mail amavis[11097]: (11097-01) switch_to_my_time     480 
s, SMTP QUIT received
Aug  8 13:44:28 mail amavis[11097]: (11097-01) ESMTP> 221 2.0.0 
[127.0.0.1] amavisd-new closing transmission channel
Aug  8 13:44:28 mail amavis[11097]: (11097-01) switch_to_client_time 480 
s, smtp response sent
Aug  8 13:44:28 mail amavis[11097]: (11097-01) SMTP session over, timer 
stopped
Aug  8 13:44:28 mail amavis[11097]: (11097-01) exiting process_request
Aug  8 13:44:28 mail amavis[11097]: (11097-01) 
post_process_request_hook: timer was not running
Aug  8 13:44:28 mail amavis[11097]: (11097-01) idle_proc, bye: was busy, 
3.0 ms, total idle 0.001 s, busy 0.913 s
Aug  8 13:44:28 mail amavis[11097]: (11097-01) load: 100 %, total idle 
0.001 s, busy 0.913 s
Aug  8 13:44:28 mail postfix/virtual[11113]: 4D345D5028B: 
to=<[EMAIL PROTECTED]>, relay=virtual, delay=0.06, delays=0.
02/0.03/0/0.01, dsn=2.0.0, status=sent (delivered to maildir)
Aug  8 13:44:28 mail postfix/qmgr[10687]: 4D345D5028B: removed
Aug  8 13:46:17 mail amavis[11098]: child_finish_hook: invoking DESTROY 
methods
Aug  8 13:46:17 mail amavis[11098]: Amavis::Cache DESTROY called

* if I deactivate amavisd service and test again to send, I get another 
error:

Aug  8 14:00:59 mail postfix/qmgr[11276]: 30D8ED5005C: 
from=<[EMAIL PROTECTED]>, size=753, nrcpt=1 (queue active)
Aug  8 14:00:59 mail postfix/smtp[11278]: connect to 
127.0.0.1[127.0.0.1]: Connection refused (port 10024)
Aug  8 14:00:59 mail postfix/smtp[11278]: 30D8ED5005C: 
to=<[EMAIL PROTECTED]>, relay=none, delay=0.78, delays=0.78/0/0/0, ds
n=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]: Connection 
refused)
Aug  8 14:00:59 mail postfix/smtpd[11291]: disconnect from 
52.Red-83-50-11.dynamicIP.rima-tde.net[83.50.11.52

In conclusion, currently the only solution I've found to SMTP still 
working is

- deactivate amavisd-new service
- comment content_filter variable in main.cf (Postfix)

And the log is:

Aug  8 14:03:57 mail postfix/smtpd[11389]: 62D01D5028B: 
client=52.Red-83-50-11.dynamicIP.rima-tde.net[83.50.11.52], sasl_meth
od=PLAIN, [EMAIL PROTECTED]
Aug  8 14:03:57 mail postfix/cleanup[11396]: 62D01D5028B: 
message-id=<[EMAIL PROTECTED]>
Aug  8 14:03:57 mail postfix/qmgr[11386]: 62D01D5028B: 
from=<[EMAIL PROTECTED]>, size=755, nrcpt=1 (queue active)
Aug  8 14:03:57 mail postfix/smtpd[11389]: disconnect from 
52.Red-83-50-11.dynamicIP.rima-tde.net[83.50.11.52]
Aug  8 14:04:01 mail postfix/smtp[11398]: 62D01D5028B: 
to=<[EMAIL PROTECTED]>, relay=gmail-smtp-in.l.google.com[64.233.183.2
7]:25, delay=4.2, delays=0.57/0.01/0.41/3.2, dsn=2.0.0, status=sent (250 
2.0.0 OK 1186574641 i7si2751199nfh)
Aug  8 14:04:01 mail postfix/qmgr[11386]: 62D01D5028B: removed

It's clear that the real problem is I don't understand what happens...

-- 
Thanks,
Jordi Espasa Clofent

-------------------------------------------------------------------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems?  Stop.
Now Search log events and configuration files using AJAX and a browser.
Download your FREE copy of Splunk now >>  http://get.splunk.com/
_______________________________________________
AMaViS-user mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/

Reply via email to