Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
deependhulla opened this issue Feb 22, 2023 · 4 comments
Open

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

deependhulla opened this issue Feb 22, 2023 · 4 comments
Labels
question

Comments

@deependhulla
Copy link

deependhulla commented Feb 22, 2023 •
edited
Loading

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=[email protected]
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=[email protected] to=[email protected] 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=[email protected] to=[email protected] 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=[email protected] to=[email protected] 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=[email protected] to=[email protected] proto=ESMTP helo=<mailgw.hiddentdomain.com>
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=[email protected] to=[email protected] proto=ESMTP helo=<mailgw.hiddentdomain.com>
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=[email protected], 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 [email protected] [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=[email protected] to=[email protected] 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=[email protected] to=[email protected] 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=[email protected], 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
Copy link

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

@shawniverson
Copy link
Member

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
Copy link
Author

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
Copy link
Member

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
question
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@deependhulla @shawniverson