search

prehor / amavisd-milter

Milter interface for the amavis spam filter engine.
BSD 3-Clause "New" or "Revised" License
8 stars 4 forks source link

TROUBLE in check_mail: gen_mail_id FAILED: find_or_save_addr with empty from addresses #12

Closed Gazoo closed 4 years ago

Gazoo commented 4 years ago

After enabling the amavisd-milter with postfix I see these in the maillog (These don't appear when just using Amavis as an after queue content filter). :

Sep  5 02:24:45 www0 amavis[3470]: (03470-02) (!!)TROUBLE in check_mail: gen_mail_id FAILED: find_or_save_addr: failed to insert addr : sql exec: err=1048, 23000, DBD::mysql::st execute failed: Column 'email' cannot be null at (eval 134) line 173. at (eval 135) line 116.
Sep  5 02:24:45 www0 postfix/cleanup[17028]: 36FBE2D02A87: milter-reject: END-OF-MESSAGE from localhost[127.0.0.1]: 4.5.0 Error in processing, id=03470-02, gen_mail_id FAILED: find_or_save_addr: failed to insert addr : sql exec: err=1048, 23000, DBD::mysql::st execute failed: Column 'email' cannot be null at (eval 134) line 173. at (eval 135) line 116.; from=<> to=<test@example.com>

The amavis DB schema is created as per: https://amavis.org/README.sql-mysql.txt

Empty from address seems valid as per (RFC 1123 section 5.2.9) https://serverfault.com/questions/151955/why-an-empty-mail-from-address-can-sent-out-email

Test Machine is running:

# rpm -qa | grep amavis
amavisd-milter-1.7.0-1.el7.x86_64
amavis-2.12.0-9.el7.noarch

I'm trying to work out if this is a bug with amavisd-milter, a bug in Amavis when using the AM.PDP protocol, or a bug with the DB schema?

Any help would be appreciated.

Edit also seeing this:

Sep 06 14:19:47 www0 amavis[18766]: (!)policy protocol: INVALID AM.PDP ATTRIBUTE LINE: sender\n
Gazoo commented 4 years ago

Here is the full debug (-d 9) . It looks like amavisd-milter can't handle the empty from <> that the sieve filter vacation responder is doing. Once this starts it just keeps looping in the error log:

Sep  6 14:33:45 web0 postfix/pickup[31611]: 4444740EDD21D: uid=30 from=<>
Sep  6 14:33:45 web0 amavisd-milter[7258]: localhost: CONNECT
Sep  6 14:33:45 web0 amavisd-milter[7258]: localhost: client name: localhost
Sep  6 14:33:45 web0 amavisd-milter[7258]: localhost: host address: 127.0.0.1
Sep  6 14:33:45 web0 amavisd-milter[7258]: localhost: Daemon name: web0.example.com
Sep  6 14:33:45 web0 amavisd-milter[7258]: localhost: HELO: localhost
Sep  6 14:33:45 web0 amavisd-milter[7258]: localhost: CLEANUP MESSAGE CONTEXT
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: MAIL FROM:
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: create working directory /var/spool/amavisd/tmp/af4444740EDD21D
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: create message file /var/spool/amavisd/tmp/af4444740EDD21D/email.txt
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: ADDHDR: Received: from localhost (localhost [127.0.0.1])#012#011by web0.example.com (amavisd-milter) id 4444740EDD21D;#012#011Sun, 6 Sep 2020 14:33:45 -0600 (MDT)#012#011(envelope-from <>)
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: RCPT TO: bounce+e15021.bdc51-museum=replaceddomain.com@othersite.com
Sep  6 14:33:45 web0 postfix/cleanup[31613]: 4444740EDD21D: message-id=<dovecot-sieve-1599400291-175939-0@web0.example.com>
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: X-Sieve: Pigeonhole Sieve 0.5.10 (bf8ef1c2)
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: Message-ID: <dovecot-sieve-1599400291-175939-0@web0.example.com>
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: Date: Sun, 06 Sep 2020 07:51:31 -0600
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: From: <museum@replaceddomain.com>
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: To: <bounce+e15021.bdc51-museum=replaceddomain.com@othersite.com>
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: Subject: Out of Office - LdSH(RC) Museum
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: In-Reply-To: <20200906135041.eb4a1f6f8bf05757@othersite.com>
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: References: <20200906135041.eb4a1f6f8bf05757@othersite.com>
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: Auto-Submitted: auto-replied (vacation)
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: Precedence: bulk
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: X-Auto-Response-Suppress: All
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: MIME-Version: 1.0
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: Content-Type: text/plain; charset=utf-8
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: Content-Transfer-Encoding: 8bit
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: X-PPP-Message-ID: <20200906135131.25335.4570@web0.example.com>
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: HEADER: X-PPP-Vhost: web0.example.com
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: MESSAGE BODY
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: body chunk: 337
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: after CRLF to LF conversion: 334
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: CONTENT CHECK
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: close message file /var/spool/amavisd/tmp/af4444740EDD21D/email.txt
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: open amavisd communication socket /run/amavisd/amavisd.sock
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: AMAVISD REQUEST
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: request=AM.PDP
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: queue_id=4444740EDD21D
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: sender=(null)
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: recipient=bounce+e15021.bdc51-museum=replaceddomain.com@othersite.com
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: tempdir=/var/spool/amavisd/tmp/af4444740EDD21D
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: tempdir_removed_by=client
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: mail_file=/var/spool/amavisd/tmp/af4444740EDD21D/email.txt
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: delivery_care_of=client
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: client_address=127.0.0.1
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: client_name=localhost
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: helo_name=localhost
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: policy_bank=web0.example.com
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: AMAVISD RESPONSE
Sep  6 14:33:45 web0 amavis[6539]: (!)policy protocol: INVALID AM.PDP ATTRIBUTE LINE: sender\n
Sep  6 14:33:45 web0 amavis[6539]: (06539-01) (!!)TROUBLE in check_mail: gen_mail_id FAILED: find_or_save_addr: failed to insert addr : sql exec: err=1048, 23000, DBD::mysql::st execute failed: Column 'email' cannot be null at (eval 134) line 173. at (eval 135) line 116.
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: version_server=2
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: log_id=06539-01
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: setreply=451 4.5.0 Error in processing, id=06539-01, gen_mail_id FAILED: find_or_save_addr: failed to insert addr : sql exec: err=1048, 23000, DBD::mysql::st execute failed: Column 'email' cannot be null at (eval 134) line 173. at (eval 135) line 116.
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: return_value=tempfail
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: exit_code=75
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: close amavisd communication socket
Sep  6 14:33:45 web0 postfix/cleanup[31613]: 4444740EDD21D: milter-reject: END-OF-MESSAGE from localhost[127.0.0.1]: 4.5.0 Error in processing, id=06539-01, gen_mail_id FAILED: find_or_save_addr: failed to insert addr : sql exec: err=1048, 23000, DBD::mysql::st execute failed: Column 'email' cannot be null at (eval 134) line 173. at (eval 135) line 116.; from=<> to=<bounce+e15021.bdc51-museum=replaceddomain.com@othersite.com>
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: CLOSE
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: CLEANUP MESSAGE CONTEXT
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: unlink file /var/spool/amavisd/tmp/af4444740EDD21D/email.txt
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: remove directory /var/spool/amavisd/tmp/af4444740EDD21D
Sep  6 14:33:45 web0 amavisd-milter[7258]: 4444740EDD21D: CLEANUP CONNECTION CONTEXT
Sep  6 14:33:45 web0 psa-pc-remote[24038]: Message aborted.
prehor commented 4 years ago

Please try amavisd-milter-1.7.1.

Gazoo commented 4 years ago

1.7.1 fixes the problem đź‘Ť Many thanks again!