Custom parameter logging in Postfix MTA logs
8 min readMar 5, 2024
Postfix is a free and open-source mail transfer agent (MTA), which is a software application used to send, receive, and route email.
Logging:
Postfix SMTP server’s logs are generated in /var/log/mail.logfile. We can not change the format of logs without changing the source code of Postfix.
Here are the samples of logs for one message:
- Successfully Sent
2024-03-05T05:40:51.848676+00:00 mail postfix/submission/smtpd[980527]: CF1863E42C: client=mail.example.in[15.235.141.97], sasl_method=PLAIN, sasl_username=admin
2024-03-05T05:40:51.850328+00:00 mail postfix/cleanup[980497]: CF1863E42C: message-id=<170961725183.980526.12014383539444281007@http://example.in>
2024-03-05T05:40:51.856413+00:00 mail opendkim[96535]: CF1863E42C: DKIM-Signature field added (s=default, d=example.in)
2024-03-05T05:40:51.858741+00:00 mail postfix/qmgr[980290]: CF1863E42C: from=<admin@example.in>, size=11194, nrcpt=1 (queue active)
2024-03-05T05:40:53.736472+00:00 mail postfix/smtp[980530]: CF1863E42C: to=<anuragrana@yopmail.com>, relay=smtp.yopmail.com[87.98.164.155]:25, delay=1.9, delays=0.01/0.03/1.1/0.76, dsn=2.0.0, status=sent (250 mail saved)
2024-03-05T05:40:53.737306+00:00 mail postfix/qmgr[980290]: CF1863E42C: removed2. Deferred
2024-03-05T05:21:14.170321+00:00 mail postfix/submission/smtpd[979812]: 297A6467CF: client=mail.example.in[15.235.141.97], sasl_method=PLAIN, sasl_username=admin
2024-03-05T05:21:14.172010+00:00 mail postfix/cleanup[979644]: 297A6467CF: message-id=<170961607416.979811.8802451082338038519@http://example.in>
2024-03-05T05:21:14.178237+00:00 mail opendkim[96535]: 297A6467CF: DKIM-Signature field added (s=default, d=example.in)
2024-03-05T05:21:14.180714+00:00 mail postfix/qmgr[972509]: 297A6467CF: from=<admin@example.in>, size=11172, nrcpt=1 (queue active)
2024-03-05T05:21:16.683501+00:00 mail postfix/smtp[979664]: 297A6467CF: to=<anuragrana@gmail.com>, relay=gmail-smtp-in.l.google.com[64.233.170.26]:25, delay=2.5, delays=0.01/0/1.8/0.65, dsn=5.7.1, status=bounced (host gmail-smtp-in.l.google.com[64.233.170.26] said: 550-5.7.1 [15.235.141.97 18] Gmail has detected that this message is likely 550-5.7.1 suspicious due to the very low reputation of the sending IP address. 550-5.7.1 To best protect our users from spam, the message has been blocked. 550-5.7.1 For more information, go to 550 5.7.1 https://support.google.com/mail/answer/188131 l10-20020a170903120a00b001dd24550463si1343363plh.31 - gsmtp (in reply to end of DATA command))
2024-03-05T05:21:16.695975+00:00 mail postfix/bounce[979816]: 297A6467CF: sender non-delivery notification: A7575467D4
2024-03-05T05:21:16.696398+00:00 mail postfix/qmgr[972509]: 297A6467CF: removed3. Deferred and then bounced (due to full mailbox of recipient)
2024-03-04T19:35:05.462109+00:00 mail postfix/qmgr[940114]: EAAD656207: from=<admin@example.in>, size=11161, nrcpt=1 (queue active)
2024-03-04T19:35:14.809625+00:00 mail postfix/smtp[966674]: EAAD656207: host gmail-smtp-in.l.google.com[172.217.194.26] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp ka29-20020a056a00939d00b006e56478cc42si9015129pfb.187 - gsmtp (in reply to RCPT TO command)
2024-03-04T19:35:16.398141+00:00 mail postfix/smtp[966674]: EAAD656207: to=<anuragrana@gmail.com>, relay=alt1.gmail-smtp-in.l.google.com[173.194.202.26]:25, delay=216143, delays=216133/8.4/2.2/0.32, dsn=4.2.2, status=deferred (host alt1.gmail-smtp-in.l.google.com[173.194.202.26] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp h9-20020a170902680900b001dc90d81400si8517967plk.247 - gsmtp (in reply to RCPT TO command))
2024-03-04T20:45:05.121190+00:00 mail postfix/qmgr[940114]: EAAD656207: from=<admin@example.in>, size=11161, nrcpt=1 (queue active)
2024-03-04T20:45:15.102053+00:00 mail postfix/smtp[968395]: EAAD656207: host gmail-smtp-in.l.google.com[64.233.170.26] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp y64-20020a638a43000000b005dc42fd8c40si8621284pgd.404 - gsmtp (in reply to RCPT TO command)
2024-03-04T20:45:16.779488+00:00 mail postfix/smtp[968395]: EAAD656207: to=<anuragrana@gmail.com>, relay=alt1.gmail-smtp-in.l.google.com[173.194.202.26]:25, delay=220344, delays=220332/9/2.3/0.41, dsn=4.2.2, status=deferred (host alt1.gmail-smtp-in.l.google.com[173.194.202.26] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp me13-20020a17090b17cd00b0029a6fad127fsi11185859pjb.4 - gsmtp (in reply to RCPT TO command))
2024-03-04T21:55:04.565352+00:00 mail postfix/qmgr[940114]: EAAD656207: from=<admin@example.in>, size=11161, nrcpt=1 (queue active)
2024-03-04T21:55:14.538900+00:00 mail postfix/smtp[970090]: EAAD656207: host gmail-smtp-in.l.google.com[64.233.170.27] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp t15-20020a63224f000000b005dbcf612461si8936801pgm.416 - gsmtp (in reply to RCPT TO command)
2024-03-04T21:55:16.112088+00:00 mail postfix/smtp[970090]: EAAD656207: to=<anuragrana@gmail.com>, relay=alt1.gmail-smtp-in.l.google.com[173.194.202.27]:25, delay=224543, delays=224532/9/2.2/0.31, dsn=4.2.2, status=deferred (host alt1.gmail-smtp-in.l.google.com[173.194.202.27] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp mi3-20020a17090b4b4300b0029ad0b92d8esi9155337pjb.13 - gsmtp (in reply to RCPT TO command))
2024-03-04T23:05:05.177326+00:00 mail postfix/qmgr[940114]: EAAD656207: from=<admin@example.in>, size=11161, nrcpt=1 (queue active)
2024-03-04T23:05:14.797085+00:00 mail postfix/smtp[971572]: EAAD656207: host gmail-smtp-in.l.google.com[64.233.170.26] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp i3-20020a17090a974300b0029986d5b232si10920375pjw.122 - gsmtp (in reply to RCPT TO command)
2024-03-04T23:05:16.534105+00:00 mail postfix/smtp[971572]: EAAD656207: to=<anuragrana@gmail.com>, relay=alt1.gmail-smtp-in.l.google.com[173.194.202.26]:25, delay=228744, delays=228732/8.7/2.2/0.47, dsn=4.2.2, status=deferred (host alt1.gmail-smtp-in.l.google.com[173.194.202.26] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp u11-20020a17090341cb00b001dcf9785bc7si4757591ple.381 - gsmtp (in reply to RCPT TO command))
2024-03-05T00:15:04.761369+00:00 mail postfix/qmgr[972509]: EAAD656207: from=<admin@example.in>, size=11161, nrcpt=1 (queue active)
2024-03-05T00:15:14.260451+00:00 mail postfix/smtp[972819]: EAAD656207: host gmail-smtp-in.l.google.com[64.233.170.26] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp d18-20020a056a00199200b006e4cb94758asi9088581pfl.292 - gsmtp (in reply to RCPT TO command)
2024-03-05T00:15:15.841588+00:00 mail postfix/smtp[972819]: EAAD656207: to=<anuragrana@gmail.com>, relay=alt1.gmail-smtp-in.l.google.com[173.194.202.26]:25, delay=232943, delays=232932/8.5/2.3/0.31, dsn=4.2.2, status=deferred (host alt1.gmail-smtp-in.l.google.com[173.194.202.26] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp fb22-20020a056a002d9600b006e5e84cc230si4865230pfb.89 - gsmtp (in reply to RCPT TO command))
2024-03-05T01:25:05.288561+00:00 mail postfix/qmgr[972509]: EAAD656207: from=<admin@example.in>, size=11161, nrcpt=1 (queue active)
2024-03-05T01:25:14.688353+00:00 mail postfix/smtp[974394]: EAAD656207: host gmail-smtp-in.l.google.com[64.233.170.27] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp y16-20020a17090264d000b001dc418f6df8si8849742pli.482 - gsmtp (in reply to RCPT TO command)
2024-03-05T01:25:16.264392+00:00 mail postfix/smtp[974394]: EAAD656207: to=<anuragrana@gmail.com>, relay=alt1.gmail-smtp-in.l.google.com[173.194.202.26]:25, delay=237143, delays=237132/8.4/2.3/0.31, dsn=4.2.2, status=deferred (host alt1.gmail-smtp-in.l.google.com[173.194.202.26] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp d3-20020a170902cec300b001dc67d1c03dsi9433071plg.298 - gsmtp (in reply to RCPT TO command))
2024-03-05T02:35:04.780852+00:00 mail postfix/qmgr[972509]: EAAD656207: from=<admin@example.in>, size=11161, nrcpt=1 (queue active)
2024-03-05T02:35:13.983026+00:00 mail postfix/smtp[975825]: EAAD656207: host gmail-smtp-in.l.google.com[64.233.170.27] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp j1-20020a056a00174100b006e636d7ea41si714688pfc.226 - gsmtp (in reply to RCPT TO command)
2024-03-05T02:35:15.557008+00:00 mail postfix/smtp[975825]: EAAD656207: to=<anuragrana@gmail.com>, relay=alt1.gmail-smtp-in.l.google.com[173.194.202.26]:25, delay=241343, delays=241332/8.2/2.2/0.31, dsn=4.2.2, status=deferred (host alt1.gmail-smtp-in.l.google.com[173.194.202.26] said: 452-4.2.2 The recipient's inbox is out of storage space. Please direct the 452-4.2.2 recipient to 452 4.2.2 https://support.google.com/mail/?p=OverQuotaTemp n5-20020a170903110500b001dd151bfaa6si2384247plh.617 - gsmtp (in reply to RCPT TO command))
2024-03-05T03:45:05.385214+00:00 mail postfix/qmgr[972509]: EAAD656207: from=<admin@example.in>, size=11161, nrcpt=1 (queue active)
2024-03-05T03:45:15.291059+00:00 mail postfix/smtp[977349]: EAAD656207: to=<anuragrana@gmail.com>, relay=gmail-smtp-in.l.google.com[172.217.194.26]:25, delay=245542, delays=245532/8.6/0.65/0.68, dsn=5.7.1, status=bounced (host gmail-smtp-in.l.google.com[172.217.194.26] said: 550-5.7.1 [15.235.141.97 18] Gmail has detected that this message is likely 550-5.7.1 suspicious due to the very low reputation of the sending IP address. 550-5.7.1 To best protect our users from spam, the message has been blocked. 550-5.7.1 For more information, go to 550 5.7.1 https://support.google.com/mail/answer/188131 w2-20020a1709027b8200b001dcd2ed9c89si8785790pll.623 - gsmtp (in reply to end of DATA command))
2024-03-05T03:45:15.305817+00:00 mail postfix/bounce[977356]: EAAD656207: sender non-delivery notification: 4800246F64
2024-03-05T03:45:15.306240+00:00 mail postfix/qmgr[972509]: EAAD656207: removedAs we can see there are multi-line logs for a single email.
4. Deferred due to high volume from sending SMTP server
2024-03-07T12:13:08.930949+00:00 mail postfix/submission/smtpd[1033100]: E32FD4934F: client=mail.example.in[15.235.141.97], sasl_method=PLAIN, sasl_username=admin
2024-03-07T12:13:08.932659+00:00 mail postfix/cleanup[1033104]: E32FD4934F: message-id=<170981358892.1033099.6007283664252477449@http://example.in>
2024-03-07T12:13:08.933092+00:00 mail postfix/cleanup[1033104]: E32FD4934F: warning: header X-Custom-Header: xxranaxx from mail.example.in[15.235.141.97]; from=<admin@example.in> to=<someone@yahoo.co.in> proto=ESMTP helo=<mail.example.in>: Custom Header: xxranaxx
2024-03-07T12:13:08.938583+00:00 mail opendkim[96535]: E32FD4934F: DKIM-Signature field added (s=default, d=example.in)
2024-03-07T12:13:08.940589+00:00 mail postfix/qmgr[1026607]: E32FD4934F: from=<admin@example.in>, size=11198, nrcpt=1 (queue active)
2024-03-07T12:13:09.005022+00:00 mail postfix/smtp[1033105]: E32FD4934F: host mx-apac.mail.gm0.yahoodns.net[106.10.248.73] said: 421 4.7.0 [TSS04] Messages from 15.235.141.97 temporarily deferred due to unexpected volume or user complaints - 4.16.55.1; see https://postmaster.yahooinc.com/error-codes (in reply to MAIL FROM command)
2024-03-07T12:13:09.005622+00:00 mail postfix/smtp[1033105]: E32FD4934F: lost connection with mx-apac.mail.gm0.yahoodns.net[106.10.248.73] while sending RCPT TO
2024-03-07T12:13:09.070883+00:00 mail postfix/smtp[1033105]: E32FD4934F: to=<someone@yahoo.co.in>, relay=mx-apac.mail.gm0.yahoodns.net[106.10.248.74]:25, delay=0.14, delays=0.01/0/0.12/0, dsn=4.7.0, status=deferred (host mx-apac.mail.gm0.yahoodns.net[106.10.248.74] said: 421 4.7.0 [TSS04] Messages from 15.235.141.97 temporarily deferred due to unexpected volume or user complaints - 4.16.55.1; see https://postmaster.yahooinc.com/error-codes (in reply to MAIL FROM command))
2024-03-07T12:20:03.254061+00:00 mail postfix/qmgr[1026607]: E32FD4934F: from=<admin@example.in>, size=11198, nrcpt=1 (queue active)
2024-03-07T12:20:03.840277+00:00 mail postfix/smtp[1033200]: E32FD4934F: host mx-apac.mail.gm0.yahoodns.net[106.10.248.74] said: 421 4.7.0 [TSS04] Messages from 15.235.141.97 temporarily deferred due to unexpected volume or user complaints - 4.16.55.1; see https://postmaster.yahooinc.com/error-codes (in reply to MAIL FROM command)
2024-03-07T12:20:03.840853+00:00 mail postfix/smtp[1033200]: E32FD4934F: lost connection with mx-apac.mail.gm0.yahoodns.net[106.10.248.74] while sending RCPT TO
2024-03-07T12:20:03.913225+00:00 mail postfix/smtp[1033200]: E32FD4934F: to=<someone@yahoo.co.in>, relay=mx-apac.mail.gm0.yahoodns.net[106.10.248.73]:25, delay=415, delays=414/0.52/0.13/0, dsn=4.7.0, status=deferred (host mx-apac.mail.gm0.yahoodns.net[106.10.248.73] said: 421 4.7.0 [TSS04] Messages from 15.235.141.97 temporarily deferred due to unexpected volume or user complaints - 4.16.55.1; see https://postmaster.yahooinc.com/error-codes (in reply to MAIL FROM command))
2024-03-07T12:30:03.708773+00:00 mail postfix/qmgr[1026607]: E32FD4934F: from=<admin@example.in>, size=11198, nrcpt=1 (queue active)
2024-03-07T12:30:05.164962+00:00 mail postfix/smtp[1033334]: E32FD4934F: to=<someone@yahoo.co.in>, relay=mx-apac.mail.gm0.yahoodns.net[106.10.248.73]:25, delay=1016, delays=1015/1.2/0.07/0.22, dsn=2.0.0, status=sent (250 ok dirdel)
2024-03-07T12:30:05.166067+00:00 mail postfix/qmgr[1026607]: E32FD4934F: removedCustom parameter logging:
We can leverage the Postfix Header Checks to print a custom parameters in logs. We need to add the below line in /etc/postfix/main.cffile.
header_checks = regexp:/etc/postfix/header_checksNow create a separate file header_checks and put the below content in it.
/^X-Custom-Header: (.*)/ WARN Custom Header: $1This configuration will log lines containing the custom header “X-Custom-Header”. The WARN action in Postfix logs the entire line when the specified pattern is matched.
Reload the postfix process.
sudo systemctl restart postfixSend the custom header in the mail. Sample Python code below.
msg = MIMEMultipart("alternative")
msg['message-id'] = utils.make_msgid(domain=self.domain)
print(msg['message-id'])
msg["Subject"] = subject
msg["From"] = f"{self.sender_name} <{self.sender_address}>"
msg["To"] = to_address
# Attach the body of the email - text plain
text_content = html2text.html2text(body_html)
msg.attach(MIMEText(text_content, "plain"))
# Attach the body of the email - html
msg.attach(MIMEText(body_html, "html"))
# Add the List-Unsubscribe header
msg.add_header('List-Unsubscribe', unsubscribe_url)
msg["Date"] = utils.formatdate(localtime=True)
msg["X-Custom-Header"] = "xxranaxx"Log output:
2024-03-05T05:40:51.848676+00:00 mail postfix/submission/smtpd[980527]: CF1863E42C: client=mail.example.in[15.235.141.97], sasl_method=PLAIN, sasl_username=admin
2024-03-05T05:40:51.850328+00:00 mail postfix/cleanup[980497]: CF1863E42C: message-id=<170961725183.980526.12014383539444281007@http://example.in>
2024-03-05T05:40:51.850770+00:00 mail postfix/cleanup[980497]: CF1863E42C: warning: header X-Custom-Header: xxranaxx from mail.example.in[15.235.141.97]; from=<admin@example.in> to=<anuragrana@yopmail.com> proto=ESMTP helo=<mail.example.in>: Custom Header: xxranaxx
2024-03-05T05:40:51.856413+00:00 mail opendkim[96535]: CF1863E42C: DKIM-Signature field added (s=default, d=example.in)
2024-03-05T05:40:51.858741+00:00 mail postfix/qmgr[980290]: CF1863E42C: from=<admin@example.in>, size=11194, nrcpt=1 (queue active)
2024-03-05T05:40:53.736472+00:00 mail postfix/smtp[980530]: CF1863E42C: to=<anuragrana@yopmail.com>, relay=smtp.yopmail.com[87.98.164.155]:25, delay=1.9, delays=0.01/0.03/1.1/0.76, dsn=2.0.0, status=sent (250 mail saved)
2024-03-05T05:40:53.737306+00:00 mail postfix/qmgr[980290]: CF1863E42C: removedThe 3rd line in the above logs contains the custom parameter.
2024-03-05T05:40:51.850770+00:00 mail postfix/cleanup[980497]: CF1863E42C: warning: header X-Custom-Header: xxranaxx from mail.example.in[15.235.141.97]; from=<admin@example.in> to=<anuragrana@yopmail.com> proto=ESMTP helo=<mail.example.in>: Custom Header: xxranaxx
We can see these custom headers in email client headers as well.
Removing custom parameters before delivery
We might want to remove these custom parameters after logging them in mail logs but before delivering the email. We can do so by making these changes in the postfix conf file.
Add below line main.cf file
smtp_header_checks = pcre:/etc/postfix/smtp_header_checksCreate a new file /etc/postfix/smtp_header_checks and add the below line to it.
/^X-Custom-Header:/ IGNORERealod the postfix server. Now custom parameters will be logged in the mail log file but will not be delivered with email to the client.
Soon we will explore the possibility of custom parameter logging by changing the source code.
Connect with me if you want to set up a fully functional new email Postfix SMTP server to send and receive emails.
