log entry missing when email of 100k per day for delivery. --or any fine tune

[deependhulla]

4 Core + 4GB RAM. Debian 11.6 Postfix 3.5.17 MailScanner 5.4.5-3 (via deb package & ms-configure update done) and archiving mails. MailWatch 1.2.18 Using msmilter with postfix.

We are using to relay outgoing mails of 100K+ Mails (100000 mails+) For few of the email
Daily for roughly 8-10 mails we do not get any delivery log (sent or bounce/deffered or failed or error) At the same time no error in journalctl ,syslog, messages or in maillog.

Example Below : cat /var/log/mail.log | grep 4PL3j0443nz30Ms 2023-02-20T19:20:44.573590+05:30 esmtp27.hiddentdomain.com postfix/smtpd[277165]: 4PL3j0443nz30Ms: client=unknown[192.168.99.84], sasl_method=XCLIENT, sasl_username=appserver@smtpbulk.hiddentdomain.com 2023-02-20T19:20:44.577683+05:30 esmtp27.hiddentdomain.com postfix/cleanup[277171]: 4PL3j0443nz30Ms: info: header Subject: Fund Transfer Status from unknown[192.168.99.84]; from=noreply@hiddentdomain.com to=enduser@outsidedomainhidden.com proto=ESMTP helo= 2023-02-20T19:20:44.577781+05:30 esmtp27.hiddentdomain.com postfix/cleanup[277171]: 4PL3j0443nz30Ms: message-id=<> 2023-02-20T19:20:44.580042+05:30 esmtp27.hiddentdomain.com postfix/cleanup[277171]: 4PL3j0443nz30Ms: milter-discard: END-OF-MESSAGE from unknown[192.168.99.84]: milter triggers DISCARD action; from=noreply@hiddentdomain.com to=enduser@outsidedomainhidden.com proto=ESMTP helo= 2023-02-20T19:20:48.439892+05:30 esmtp27.hiddentdomain.com MailScanner[277162]: Saved archive copies of 4PL3j0443nz30Ms 2023-02-20T19:20:48.466326+05:30 esmtp27.hiddentdomain.com MailScanner[277162]: Requeue: 4PL3j0443nz30Ms to 4PL3j0443nz30Ms 2023-02-20T19:20:48.475660+05:30 esmtp27.hiddentdomain.com postfix/cleanup[277171]: 4PL3j43LwZz30Mv: info: header X-MailScanner-ID: 4PL3j0443nz30Ms from localhost[127.0.0.1]; from=noreply@hiddentdomain.com to=enduser@outsidedomainhidden.com proto=QMQP

(BUT The Email is delivered to users ..as we get open-view msg)

2023-02-18T09:02:06.601327+05:30 esmtp27.hiddentdomain.com postfix/smtpd[145114]: 4PJZ464GB1z30Mc: client=unknown[192.168.100.242] 2023-02-18T09:02:06.608213+05:30 esmtp27.hiddentdomain.com postfix/cleanup[145102]: 4PJZ464GB1z30Mc: info: header Subject: You have been marked absent on 17/02/2023 from unknown[192.168.100.242]; from=myzone@hiddentdomain.com to=internaluser@hiddentdomain.com proto=ESMTP helo= 2023-02-18T09:02:06.608247+05:30 esmtp27.hiddentdomain.com postfix/cleanup[145102]: 4PJZ464GB1z30Mc: message-id=<> 2023-02-18T09:02:06.654573+05:30 esmtp27.hiddentdomain.com postfix/cleanup[145102]: 4PJZ464GB1z30Mc: milter-discard: END-OF-MESSAGE from unknown[192.168.100.242]: milter triggers DISCARD action; from=myzone@hiddentdomain.com to=internaluser@hiddentdomain.com proto=ESMTP helo= 2023-02-18T09:02:13.758065+05:30 esmtp27.hiddentdomain.com MailScanner[143392]: Saved archive copies of 4PJZ46702Jz30MM 4PJZ464Y9Rz30NX 4PJZ466Nr4z30Nb 4PJZ464GB1z30Mc 4PJZ466f3tz30MV 4PJZ466kKjz30MT 4PJZ4624msz30MY 4PJZ463zBCz30M6 4PJZ466nSqz30M6 4PJZ463wBmz30Mv 4PJZ466qSbz30PL 4PJZ4642tvz30Mm 4PJZ46415gz30M6 4PJZ461lycz30MM 4PJZ46257vz30Ms 4PJZ462Dg6z30MV 4PJZ4670WXz30Mv 4PJZ466yJMz30MV 4PJZ4700FDz30MT 4PJZ46459mz30NX 4PJZ464B13z30Mc 4PJZ461tghz30MT 4PJZ4621K9z30MG 4PJZ461dpZz30MG 4PJZ466dbqz30MY 4PJZ464HR8z30MJ 4PJZ475glyz30YM 4PJZ4627CLz30MY 4PJZ472whtz30PL 4PJZ462J4Vz30NF 2023-02-18T09:02:13.973118+05:30 esmtp27.hiddentdomain.com MailScanner[143392]: Requeue: 4PJZ464GB1z30Mc to 4PJZ464GB1z30Mc 2023-02-18T09:02:14.632857+05:30 esmtp27.hiddentdomain.com postfix/smtp[145064]: 4PJZ4G2hNXz2ynL: to=internaluser@hiddentdomain.com, relay=192.168.100.181[192.168.100.181]:25, delay=0.25, delays=0.07/0/0.02/0.16, dsn=2.6.0, status=sent (250 2.6.0 4PJZ4G2hNXz2ynL@esmtp27.hiddentdomain.com [InternalId=15874199127440, Hostname=EXCHG-MB12.myinteralpc.com] 4267 bytes in 0.150, 27.674 KB/sec Queued mail for delivery) 2023-02-18T09:02:16.011307+05:30 esmtp27.hiddentdomain.com MailScanner[143392]: MailWatch: Logging message 4PJZ464GB1z30Mc to SQL 2023-02-18T09:02:16.016556+05:30 esmtp27.hiddentdomain.com MailScanner[143394]: MailWatch: 4PJZ464GB1z30Mc: Logged to MailWatch SQL

While some email got delivered but there is no co-relation entry for us to track as info: header X-MailScanner-ID: is not added in Log...its missing. in above case 4PJZ464GB1z30Mc --> 4PJZ4G2hNXz2ynL

Also by default when using msmilter with postfix log show Requeue: 4PJZ464GB1z30Mc to 4PJZ464GB1z30Mc (Same) while if postfix with holdqueue is used with mailscanner requeue show different number. as we are using msmilter for log-co-relation we use X-MailScanner-ID

Also sometime without deliery stattus..email-is removed. root@smtpauth:~# cat /var/log/mail.log | grep 4PLSbQ5Nt3z20dm 2023-02-21T11:02:18.759680+05:30 smtpauth.myinteralpc.com postfix/qmqpd[1047435]: 4PLSbQ5Nt3z20dm: client=localhost[127.0.0.1] 2023-02-21T11:02:18.761532+05:30 smtpauth.myinteralpc.com postfix/cleanup[1047536]: 4PLSbQ5Nt3z20dm: info: header Subject: One-time Password (OTP) 39555 for login to Investor/Trader app or? web portal from localhost[127.0.0.1]; from=onlinetrade@myinteralpc.com to=sampleuser@REDIFFMAIL.COM proto=QMQP 2023-02-21T11:02:18.761594+05:30 smtpauth.myinteralpc.com postfix/cleanup[1047536]: 4PLSbQ5Nt3z20dm: message-id=ALWX6MJM8JU4.2647MDB3UYEO@appsserver 2023-02-21T11:02:18.761631+05:30 smtpauth.myinteralpc.com postfix/cleanup[1047536]: 4PLSbQ5Nt3z20dm: info: header X-CASPER-MailScanner-ID: 4PLSbK6gPgz20Ms from localhost[127.0.0.1]; from=onlinetrade@myinteralpc.com to=sampleuser@REDIFFMAIL.COM proto=QMQP 2023-02-21T11:02:18.764622+05:30 smtpauth.myinteralpc.com opendkim[297]: 4PLSbQ5Nt3z20dm: DKIM-Signature field added (s=mail, d=myinteralpc.com) 2023-02-21T11:02:18.821504+05:30 smtpauth.myinteralpc.com postfix/qmgr[1339]: 4PLSbQ5Nt3z20dm: from=onlinetrade@myinteralpc.com, size=1948, nrcpt=1 (queue active) 2023-02-21T11:02:20.010911+05:30 smtpauth.myinteralpc.com postfix/qmgr[1339]: 4PLSbQ5Nt3z20dm: removed

Any idea how to debug or fix what...or how to tune this ..on mailscanner or postfix if any or its a bug.

[github-actions[bot]]

Thank you for submitting your first issue to MailScanner! We will respond to you soon!

[shawniverson]

Delivery status logging comes from postfix, not mailscanner. I doubt there is any sort of bug in postfix causing this.

Requeue of same ID is normal behavior with the milter. It is not really being requeued to postfix but rather to milterout, which mailscanner then feeds to QMQP in your case.

With the large number of emails in this flow and systemd/syslog at play, have you looked at the rate limiting settings for logging for both services? It is possible that some of the log entries are not being recorded due to rate limiting.

https://www.rootusers.com/how-to-change-log-rate-limiting-in-linux/

[deependhulla]

Thanks for Quick Reply. Had tried increasing default ratelimit..but no success. Also no syslog/messages/debug shows msg like givien https://www.rootusers.com/how-to-change-log-rate-limiting-in-linux/

journal: Suppressed 7124 messages imjournal: begin to drop messages imjournal: 143847 messages lost due to rate-limit

Thats the reason..any guide to debug and what to fix it ?

[shawniverson]

I'm not sure I understand. What is the reason?