[SOLVED] Error sending notification

[thiagotgc]

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

 

[Stoiko Ivanov]

: 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

 

[thiagotgc]

: 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.

 

[Stoiko Ivanov]

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

 

[thiagotgc]

The "mail.log" log has already been posted.

syslog:

Feb 11 13:13:30 server pmg-smtp-filter[29116]: 406F95E44112124210: notify <mail@gmail.com> (rule: Quarantine Multimedia Files) failed

 

[thiagotgc]

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

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

 

[thiagotgc]

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

 

[thiagotgc]

I found the problem.

In my notification, there was a character that was not being recognized.

I redid the text, and it worked.