[SOLVED] Error sending notification

thiagotgc

Active Member
Dec 17, 2019
144
16
38
36
I configured some rules to send notification emails when an email with an attachment ".mp3" arrived

It does everything correctly, but does not send the notification email.

In the log, just the failure.


Feb 11 13:13:22 avas2 postfix/cleanup[27299]: 6619D9FB6D: info: header Subject: Teste mp3 from helo.x.x[x.x.x.x]; from=<mail@gmail.com> to=<destiny@domain.com> proto=ESMTP helo=<helo.x.x>
Feb 11 13:13:22 avas2 postfix/cleanup[27299]: 6619D9FB6D: info: header To: destiny@domain.com from helo.x.x[x.x.x.x]; from=<mail@gmail.com> to=<destiny@domain.com> proto=ESMTP helo=<helo.x.x>
Feb 11 13:13:22 avas2 postfix/qmgr[1026]: 6619D9FB6D: from=<mail@gmail.com>, size=1552953, nrcpt=1 (queue active)
Feb 11 13:13:22 avas2 postfix/smtpd[27297]: disconnect from helo.x.x[x.x.x.x] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Feb 11 13:13:22 avas2 pmg-smtp-filter[27307]: 3FE085E42D2A2985C2: new mail message-id=<CAGHRcymR4cH19MqPuix2Bfmys0QUjwSGFTpR3a2ijqY8ayrRKQ@mail.gmail.com>#012
Feb 11 13:13:24 avas2 pmg-smtp-filter[27307]: 3FE085E42D2A2985C2: SA score=1/5 time=1.288 bayes=undefined autolearn=no autolearn_force=no hits=AWL(0.645),DKIM_SIGNED(0.1),DKIM_VALID(-1),DKIM_VALID_AU(-0.1),DKIM_VALID_EF(-0.1),FREEMAIL_FROM(0.001),HTML_MESSAGE(0.001),KAM_NUMSUBJECT(0.5),PYZOR_CHECK(1.5),RCVD_IN_DNSWL_LOW(-0.7),SPF_HELO_PASS(-0.001),SPF_SOFTFAIL(0.972)
Feb 11 13:13:24 avas2 pmg-smtp-filter[27307]: 3FE085E42D2A2985C2: notify <mail@gmail.com> (rule: Quarantine Multimedia Files) failed
Feb 11 13:13:24 avas2 pmg-smtp-filter[27307]: 3FE085E42D2A2985C2: notify <destiny@domain.com> (rule: Quarantine Multimedia Files) failed
Feb 11 13:13:24 avas2 pmg-smtp-filter[27307]: 3FE085E42D2A2985C2: moved mail for <destiny@domain.com> to spam quarantine - 406D15E42D2A413C0E (rule: Quarantine Multimedia Files)
Feb 11 13:13:24 avas2 pmg-smtp-filter[27307]: 3FE085E42D2A2985C2: processing time: 1.446 seconds (1.288, 0.041, 0)
Feb 11 13:13:24 avas2 postfix/lmtp[27388]: 6619D9FB6D: to=<destiny@domain.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.8, delays=0.23/0/0.05/1.5, dsn=2.5.0, status=sent (250 2.5.0 OK (3FE085E42D2A2985C2))
Feb 11 13:13:24 avas2 postfix/qmgr[1026]: 6619D9FB6D: removed
 
Code:
: notify <destiny@domain.com> (rule: Quarantine Multimedia Files) failed

seems the notify action failed - please post the complete mail.log for the timeframe -that should show some more hints to what went wrong
 
Code:
: notify <destiny@domain.com> (rule: Quarantine Multimedia Files) failed

seems the notify action failed - please post the complete mail.log for the timeframe -that should show some more hints to what went wrong

The Log is in the message.

It is complete for this action.
 
Sorry - I meant everything from that timeframe in the files matching:
- '/var/log/syslog*'
- '/var/log/mail.log*'

There should be the initial connection from pmg-smtp-filter to smtpd listening on 10025
 
There should be the initial connection from pmg-smtp-filter to smtpd listening on 10025

Code:
nmap -sT -O localhost

Starting Nmap 7.70 ( https://nmap.org ) at 2020-02-12 19:15 -03
Nmap scan report for localhost (127.0.0.1)
Host is up (0.00028s latency).
rDNS record for 127.0.0.1: localhost.localdomain
Not shown: 992 closed ports
PORT      STATE SERVICE
25/tcp    open  smtp
26/tcp    open  rsftp
85/tcp    open  mit-ml-dev
111/tcp   open  rpcbind
443/tcp   open  https
5432/tcp  open  postgresql
10024/tcp open  unknown
10025/tcp open  unknown
Device type: general purpose
Running: Linux 3.X
OS CPE: cpe:/o:linux:linux_kernel:3
OS details: Linux 3.7 - 3.10
Network Distance: 0 hops
 
I decided to restart the server, and now I notice this:

Feb 13 09:00:51 pmg.domain.com postfix/postscreen[1819]: CONNECT from [x.x.x.x]:32848 to [10.68.20.35]:25
Feb 13 09:00:51 pmg.domain.com postfix/postscreen[1819]: PASS OLD [x.x.x.x]:32848
Feb 13 09:00:51 pmg.domain.com postfix/smtpd[2600]: connect from mailserver.domain.com[x.x.x.x]
Feb 13 09:00:52 pmg.domain.com pmgpolicy[2657]: accept mails from backup MX host - x.x.x.x
Feb 13 09:00:52 pmg.domain.com postfix/smtpd[2600]: 1A1999FB6D: client=mailserver.domain.com[x.x.x.x]
Feb 13 09:00:52 pmg.domain.com postfix/cleanup[2383]: 1A1999FB6D: info: header From: mymail <mymail@gmail.com> from mailserver.domain.com[x.x.x.x]; from=<mymail@gmail.com> to=<destiny@domain.com> proto=ESMTP helo=<mailserver.domain.com>
Feb 13 09:00:52 pmg.domain.com postfix/cleanup[2383]: 1A1999FB6D: message-id=<CAGHRcyk9s05PixhgEGAggt70+AFfa78H60nh2QqYnw6nEKiaUA@mail.gmail.com>
Feb 13 09:00:52 pmg.domain.com postfix/cleanup[2383]: 1A1999FB6D: info: header Subject: teste from mailserver.domain.com[x.x.x.x]; from=<mymail@gmail.com> to=<destiny@domain.com> proto=ESMTP helo=<mailserver.domain.com>
Feb 13 09:00:52 pmg.domain.com postfix/cleanup[2383]: 1A1999FB6D: info: header To: destiny@domain.com from mailserver.domain.com[x.x.x.x]; from=<mymail@gmail.com> to=<destiny@domain.com> proto=ESMTP helo=<mailserver.domain.com>
Feb 13 09:00:52 pmg.domain.com postfix/qmgr[942]: 1A1999FB6D: from=<mymail@gmail.com>, size=1552947, nrcpt=1 (queue active)
Feb 13 09:00:52 pmg.domain.com pmg-smtp-filter[2384]: 2020/02/13-09:00:52 CONNECT TCP Peer: "[127.0.0.1]:44916" Local: "[127.0.0.1]:10024"
Feb 13 09:00:52 pmg.domain.com postfix/smtpd[2600]: disconnect from mailserver.domain.com[x.x.x.x] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Feb 13 09:00:52 pmg.domain.com pmg-smtp-filter[2384]: 407015E453A7451FC7: new mail message-id=<CAGHRcyk9s05PixhgEGAggt70+AFfa78H60nh2QqYnw6nEKiaUA@mail.gmail.com>
Feb 13 09:00:54 pmg.domain.com pmg-smtp-filter[2384]: 407015E453A7451FC7: SA score=0/5 time=1.324 bayes=undefined autolearn=no autolearn_force=no hits=AWL(-0.000),DKIM_SIGNED(0.1),DKIM_VALID(-1),DKIM_VALID_AU(-0.1),DKIM_VALID_EF(-0.1),FREEMAIL_FROM(0.001),HTML_MESSAGE(0.001),PYZOR_CHECK(1.5),RCVD_IN_DNSWL_LOW(-0.7),SPF_HELO_PASS(-0.001),SPF_SOFTFAIL(0.972),TVD_SPACE_RATIO(0.001)
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[2398]: connect from localhost.localdomain[127.0.0.1]
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[2398]: 27F889FB70: client=localhost.localdomain[127.0.0.1]
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[2398]: lost connection after DATA (382 bytes) from localhost.localdomain[127.0.0.1]
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[2398]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=0/1 commands=3/4
Feb 13 09:00:54 pmg.domain.com pmg-smtp-filter[2384]: open body: Invalid argument at /usr/share/perl5/MIME/Entity.pm line 1892.
Feb 13 09:00:54 pmg.domain.com postfix/cleanup[1826]: 27F889FB70: message-id=<20200213120054.27F889FB70@pmg.domain.com>
Feb 13 09:00:54 pmg.domain.com pmg-smtp-filter[2384]: 407015E453A7451FC7: notify <thiago@hostlp.net> (rule: Quarantine Multimedia Files) failed
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[1840]: connect from localhost.localdomain[127.0.0.1]
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[1840]: 299839FB70: client=localhost.localdomain[127.0.0.1]
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[1840]: lost connection after DATA (226 bytes) from localhost.localdomain[127.0.0.1]
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[1840]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=0/1 commands=3/4
Feb 13 09:00:54 pmg.domain.com pmg-smtp-filter[2384]: open body: Invalid argument at /usr/share/perl5/MIME/Entity.pm line 1892.
Feb 13 09:00:54 pmg.domain.com pmg-smtp-filter[2384]: 407015E453A7451FC7: notify <mymail@gmail.com> (rule: Quarantine Multimedia Files) failed

Feb 13 09:00:54 pmg.domain.com postfix/cleanup[2383]: 299839FB70: message-id=<20200213120054.299839FB70@pmg.domain.com>
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[2398]: connect from localhost.localdomain[127.0.0.1]
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[2398]: 2ACB59FB70: client=localhost.localdomain[127.0.0.1]
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[2398]: lost connection after DATA (238 bytes) from localhost.localdomain[127.0.0.1]
Feb 13 09:00:54 pmg.domain.com postfix/smtpd[2398]: disconnect from localhost.localdomain[127.0.0.1] ehlo=1 mail=1 rcpt=1 data=0/1 commands=3/4
Feb 13 09:00:54 pmg.domain.com postfix/cleanup[1826]: 2ACB59FB70: message-id=<20200213120054.2ACB59FB70@pmg.domain.com>
Feb 13 09:00:54 pmg.domain.com pmg-smtp-filter[2384]: open body: Invalid argument at /usr/share/perl5/MIME/Entity.pm line 1892.
Feb 13 09:00:54 pmg.domain.com pmg-smtp-filter[2384]: 407015E453A7451FC7: notify <destiny@domain.com> (rule: Quarantine Multimedia Files) failed
Feb 13 09:00:54 pmg.domain.com pmg-smtp-filter[2384]: 407015E453A7451FC7: moved mail for <destiny@domain.com> to spam quarantine - 4072D5E453A762B8C1 (rule: Quarantine Multimedia Files)

Feb 13 09:00:54 pmg.domain.com pmg-smtp-filter[2384]: 407015E453A7451FC7: processing time: 1.842 seconds (1.324, 0.415, 0)
Feb 13 09:00:54 pmg.domain.com postfix/lmtp[2344]: 1A1999FB6D: to=<destiny@domain.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=2.2, delays=0.3/0/0.05/1.9, dsn=2.5.0, status=sent (250 2.5.0 OK (407015E453A7451FC7))
Feb 13 09:00:54 pmg.domain.com postfix/qmgr[942]: 1A1999FB6D: removed
 

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!