Below is an example on an incoming message taken from the Axigen log. The Axigen log is set to log "Protocol Communication" level, for the SMTP Receiving and Processing services, in order to obtain more details.
For each session belonging to a certain service, a specific ID is assigned. In the below examples, the ID for the SMTP Receiving session is 00000022.
The first line shows that a connection was established to Axigen:
SMTP-IN:00000022: [127.0.0.1:25] connection accepted from [192.168.0.5:58047] |
This line indicates that Axigen is ready to begin the SMTP communication:
SMTP-IN:00000022: >> 220 ts3.gecadco.local Axigen ESMTP ready |
The next lines show the SMTP communication between Axigen and the remote host:
SMTP-IN:00000022: << EHLO host.example.comSMTP-IN:00000022: Greylist disabledSMTP-IN:00000022: >> 250-ts3.gecadco.local Axigen ESMTP helloSMTP-IN:00000022: >> 250-SIZE 10485760SMTP-IN:00000022: >> 250-HELPSMTP-IN:00000022: >> 250 OK |
Here is where the sender of the message from the envelope is given by the remote host:
SMTP-IN:00000022: << MAIL FROM: remote_user@example.com |
The next lines indicate that a certain action was performed after the "MAIL FROM" command. This action is actually a SMTP policy defined in the smtpFilters.script file:
SMTP-IN:00000022: Set smtp action to ACCEPTSMTP-IN:00000022: Set smtp explanation to [Emails accepted from domain example.comSMTP-IN:00000022: >> 250 Emails accepted from domain example.com |
The recipient of the message is then provided and then the actual message which includes the headers and the body:
SMTP-IN:00000022: << RCPT TO: test@domain.tldSMTP-IN:00000022: >> 250 Recipient acceptedSMTP-IN:00000022: << dataSMTP-IN:00000022: >> 354 Ready to receive data; remember <CRLF>.<CRLF>SMTP-IN:00000022: << 3 bytes and final dot read |
After the remote host indicates that the message is complete Axigen takes the message and enqueues it with an ID which is further used in the PROCESSING service. As you could notice the SMTP-IN service has a unique ID also for this message:
SMTP-IN:00000022: New mail received from host.example.com (192.168.0.5) and enqueued with id 20D2FBSMTP-IN:00000022: >> 250 Mail queued for delivery |
The PROCESSING Service now starts and begins to filter the message:
PROCESSING:0020D2FB: Shepherd thread received signal for processingPROCESSING:0020D2FB: Start processing mail |
SpamAssassinBundled is enabled and identifies this message as not being spam:
PROCESSING:0020D2FB: Start filter AV:SpamAssassinBundled of type socket filter from serverPROCESSING:0020D2FB: Shepherd thread finished processing signalPROCESSING:0020D2FB: >> CHECK SPAMC/1.2PROCESSING:0020D2FB: >> Content-length:PROCESSING:0020D2FB: >> 133PROCESSING:0020D2FB: >>PROCESSING:0020D2FB: >> Send mail stream: 20D2FBPROCESSING:0020D2FB: << SPAMD/1.1 0 EX_OKPROCESSING:0020D2FB: << Spam: False ; 4.9 / 5.0PROCESSING:0020D2FB: Filter SpamAssassin Filter(127.0.0.1:1987):[PASS]: Spam: False ; 4.9 / 5.0PROCESSING:0020D2FB: Finished filtering mail object 20D2FB with filter: AV:SpamAssassinBundled of type socket filter from server |
Now the rules defined on the server level are applied:
PROCESSING:0020D2FB: Start filter WASieveServer of type script filter from serverPROCESSING:0020D2FB: Finished filtering mail object 20D2FB with filter: WASieveServer of type script filter from server |
And finally the delivery of the message occurs:
PROCESSING:0020D2FB: Finish processing mailPROCESSING:0020D2FB: Shepherd thread received signal for deliveryPROCESSING:0020D2FB: Shepherd thread finished processing signalPROCESSING:0020D2FB: Start mail deliveryPROCESSING:0020D2FB: Mail delivered to mailbox 'INBOX' of <test@domain.tld> with id 2PROCESSING:0020D2FB: Shepherd thread received signal for cleanupPROCESSING:0020D2FB: Start mail cleanupPROCESSING:0020D2FB: Mail removed from queuePROCESSING:0020D2FB: Shepherd thread finished processing signal |
Essentially to remember when investigating an issue related to mail delivery is that you need "Protocol Communication" logs in order to obtain more details. Then you can track a message path, from the time it enters Axigen to the moment when it's delivery is made, using the IDs corresponding to that message. As you can notice in the example above the message is received with an ID "000022" and then enqueued with the ID "20D2FB" which is also used when the PROCESSING service logs it's messages.