Tag: Message transfer agents

This article explains how to read and interpret logs on PureMessage for the new Delay Queue feature.

The following sections are covered:

• Log lines
• Debug mode
• Mail is not re-injected
• Related information
• Feedback and contact

Applies to the following Sophos products and versions

PureMessage for Unix 6.4.0 and above

Log lines are in code format and comments are in bold.

pmx-log: when mail is delayed

1 2017-07-06T11:40:25 [29880,milter] 5963767C_31729_16_1: DelayHistory: sc=5,dt=2

2 2017-07-06T11:40:25 [29880,milter] 5963767C_31729_16_1: delayed: Suspect Spam

This log entry says that mail with Queue-Id 5963767C_31729_16_1 has been delayed for 2 minutes as dt=2 and its suspect count is 5 as sc=5.

delay.log: when mail times out

1 2017-07-06T11:43:49 [30551,delay_queue_runner] Queue-Id=5963767C_31729_16_1 successfully sent for rescan

This line says that mail with Queue-Id 5963767C_31729_16_1 has been successfully sent for rescan.

delay.log: when mail is re-injected from UI

1 2017-07-10T14:45:00 [27149,delay_queue_runner] delay file=27934 is marked for rescan from ui

1 2017-07-10T14:45:04 [27150,delay_queue_runner] Queue-Id=5963767C_31729_16_1 successfully sent for rescan

This says that mail in file 27931 in directory /opt/pmx6/var/qdir/delay/<minute> is marked for rescan / re-injection from the UI. The Second line says that mail with Queue-Id 5963767C_31729_16_1 has been successfully sent for rescan.

delay.log: when this mail is deleted from UI

1 2017-07-10T14:52:00 [27149,delay_queue_runner] delay file=/opt/pmx6/var/qdir/delay/52/27932 gid=27932-1 is deleted from ui

This says that a mail that was in /opt/pmx6/var/qdir/delay/52/27932 was deleted from the UI.

Increase the debug level with debug level = 10 in pmx.conf and restart the Milter and pmx-delay-queue-runner to run them in debug mode.

pmx-log: when mail is delayed

0 2017-07-10T15:12:12 [14191,milter,Message.pm:880] 59637D2B_14191_2_1: POLICY ACTION: pmx_suspect_delay

1 2017-07-10T15:12:12 [14191,milter,Message.pm:880] 59637D2B_14191_2_1: DelayHistory: sc=5,dt=2

0 2017-07-10T15:12:12 [14191,milter,Message.pm:880] 59637D2B_14191_2_1: delay file=27934, minute dir=14

0 2017-07-10T15:12:12 [14191,milter,Message.pm:880] 59637D2B_14191_2_1: POLICY STOP: message finished processing (end of policy script)

2 2017-07-10T15:12:12 [14191,milter,Policy.pm:668] 59637D2B_14191_2_1: delayed: Suspect Spam

This says that mail is delayed for 2 minutes as dt=2, and stored in file name 27934 in directory 14 (/opt/pmx6/var/qdir/delay/14/27934). Directory 14 means, when system’s local time reaches to 14 minutes, that mail will be rescanned.

delay.log: when this mail is timed out and sent for rescan

0 2017-07-10T15:14:00 [14146,delay_queue_runner,Runner.pm:166] delay file=27934 gid=27934-1 is marked for rescan

0 2017-07-10T15:14:00 [14146,delay_queue_runner,DelayqPmdb.pm:761] Message 27934-1 removed

0 2017-07-10T15:14:04 [14147,delay_queue_runner,Rescan.pm:287] delay file=27934 for Queue-Id=59637D2B_14191_2_1 is sent for rescan

1 2017-07-10T15:14:04 [14147,delay_queue_runner,Rescan.pm:289] Queue-Id=59637D2B_14191_2_1 successfully sent for rescan

The first line says the mail in file 27934 is marked for rescanning due to a timeout.

The second line says that it is removed from the database, so it will not show up in the UI.

The third line says the mail in file 27934 with Queue-Id 59637D2B_14191_2_1 is sent for rescanning.

Fourth line says the mail with Queue-Id 59637D2B_14191_2_1 has been successfully sent for a rescan.

delay.log: when this mail is re-injected from UI

1 2017-07-10T15:24:00 [14146,delay_queue_runner,DelayRetry.pm:107] delay file=27934 gid=27934-1 is marked for rescan from ui

0 2017-07-10T15:24:00 [14146,delay_queue_runner,DelayqPmdb.pm:761] Message 27934-1 removed

0 2017-07-10T15:24:04 [14147,delay_queue_runner,Rescan.pm:287] delay file=27934_r_50 for Queue-Id=59637D2B_14191_2_1 is sent for rescan

1 2017-07-10T15:24:04 [14147,delay_queue_runner,Rescan.pm:289] Queue-Id=59637D2B_14191_2_1 successfully sent for rescan

• The first line says that the mail in file 27934 is marked for rescanning from UI.
• The second line shows that it is removed from the database, so it will not be in the UI.
• The third line says that the mail in file 27934 with Queue-Id 59637D2B_14191_2_1 is sent for rescan. File=27934_r_60 , means the file name is 27934. The r means it is re-injected from the UI, 50 means that the mail is re-injected 50 minutes before timeout.
• The fourth line says that the mail with Queue-Id 59637D2B_14191_2_1 has been successfully sent for rescanning.
  

delay.log: when this mail is deleted from UI

1 2017-07-10T15:33:00 [14146,delay_queue_runner,DelayRetry.pm:155] delay file=/opt/pmx6/var/qdir/delay/14/27934 gid=27934-1 is deleted from ui

0 2017-07-10T15:33:00 [14146,delay_queue_runner,DelayqPmdb.pm:761] Message 27934-1 removed

• The first line shows that mail in file 27934 has been deleted from UI.
• The second line says that mail in file 27934 is removed from the database, so it will not be shown on the UI.

• If messages are not re-injected and you see mail stacked in the <PMX_PREFIX>/var/qdir/delay/rescan/ directory:
• Verify that the process delay-queue-runner is running.
• Verify that you have configured the parameter send_delayed_mail_to in delay.conf properly and the relay is accepting the messages. Check this especially if you have a log line like delay_queue_runner,Rescan.pm:194 not able to connect to 127.0.0.1:10025 or /opt/pmx6/etc/delay.conf file has not send_delayed_mail_to parameter.
• If the relay takes more than 10 seconds to respond to any SMTP command sent by delay_queue_runner, the process will drop that connection. The message will not be sent for rescang and is tried again in one minute.
• If the relay does not respond within 300 seconds after delay_queue_runner has submitted the message with the DATA command, delay_queue_runner assumes that the relay is not processing its request and terminates the connection. That message will be retried on next minute.
• UI actions such as Reinject or Delete delayed mail cannot be performed if the Edge server on which the message is delayed, is not able to communicate to the PostgreSQL database server. The log line displayed for this is like: delay_queue_runner,Runner.pm:199] DelayqPmdb.pm get_message_hash failed, can't process ui action if any.
  

• PureMessage for Unix: FAQ for version 6.4 Delay Queue
  

If you’ve spotted an error or would like to provide feedback on this article, please use the section below to rate and comment on the article.

This is invaluable to us to ensure that we continually strive to give our customers the best information possible.