PMDF System Manager's Guide

The exact field format and list of fields logged in the PMDF message logging files will vary according to exactly what logging options a site sets; see Section 2.3.4.84 for a description of the basic fields, and see the discussion of the various LOG_* options in Section 7.3.6 for descriptions of additional, optional fields. But there are general principles for understanding such log entries; this section will show a few examples of interpreting typical sorts of log entries.

When looking over a logging file, keep in mind that on a typical system many messages are being handled at once. Typically, the entries relating to a particular message will be interspersed among entries relating to other message being processed during that same time. The basic logging information is suitable for gathering a sense of the overall numbers of messages moving through PMDF. However, if you want to correlate particular entries relating to the same message to the same recipient(s), you will probably want to enable LOG_MESSAGE_ID. And if you want to correlate particular messages with particular files in the PMDF queue area, or to see from the entries how many times a particular not-yet-successfully-dequeued message has had delivery reattempted, you will probably want to enable LOG_FILENAME. For SMTP messages (handled via a TCP/IP channel), if you want to correlate TCP connections to and from remote systems with the messages sent, you will probably want to enable LOG_PROCESS and some level of LOG_CONNECTION.

Figure 31-1 Logging: A Local User Sends an Outgoing Message

15-Nov-2012 19:16:57.64 l tcp_local E 1 (1) adam@example.com rfc822;marlowe@example.com marlowe@example.com (2) 15-Nov-2012 19:17:01.16 tcp_local D 1 (3) adam@example.com rfc822;marlowe@example.com marlowe@example.com (4) dns;thor.example.com (TCP|206.184.139.12|2788|192.160.253.66|25) (5) (THOR.EXAMPLE.COM -- Server ESMTP [PMDF V5.1-10 #8694]) (6) smtp;250 2.1.5 marlowe@example.com and options OK. (7)

The above entries show a basic example of the sorts of log entries one might see if a local user sends a message out an outgoing TCP/IP channel, e.g., to the Internet. The lines marked with (1) and (2) are one entry---they would appear on one physical line in an actual log file. Similarly, the lines marked with (3)--(7) are one entry and would appear on one physical line.

1. This line shows the date and time of an enqueue (E) from the L channel to the tcp_local channel of a one (1) block message.
2. This is part of the same physical line of the log file as , presented here as a separate line for typographical convenience. It shows the envelope From: address, in this case adam@example.com, and the original version and current version of the envelope To: address, in this case marlowe@example.com.
3. This shows the date and time of a dequeue (D) from the tcp_local channel of a one (1) block message---that is, a successful send by the tcp_local channel to some remote SMTP server.
4. This shows the envelope From: address, the original envelope To: address, and the current form of the envelope To: address.
5. This shows that the actual system to which the connection was made is named thor.example.com in the DNS, that the local sending system has IP address 206.184.139.12 and is sending from port 2788, that the remote destination system has IP address 192.160.253.66 and the connection port on the remote destination system is port 25.
6. This shows the SMTP banner line of the remote SMTP server.
7. This shows the SMTP status code returned for this address; 250 is the basic SMTP success code and in addition, this remote SMTP server responds with extended SMTP status codes and some additional text.

Figure 31-2 Logging: Including Optional Logging Fields

15-Nov-2012 19:16:57.64 l tcp_local E 1 adam@example.com rfc822;marlowe@example.com marlowe@example.com PMDF_QUEUE:[tcp_local]ZZ01ISKLSKLZLI90N15M.00;1 <01ISKLSKC2QC90N15M@example.com> (1) 15-Nov-2012 19:17:01.16 tcp_local D 1 adam@example.com rfc822;marlowe@example.com marlowe@example.com PMDF_QUEUE:[tcp_local]ZZ01ISKLSKLZLI90N15M.00 <01ISKLSKC2QC90N15M@example.com> (2) dns;thor.example.com (TCP|206.184.139.12|2788|192.160.253.66|25) (THOR.EXAMPLE.COM -- Server ESMTP [PMDF V5.1-10 #8694]) smtp;250 2.1.5 marlowe@example.com and options OK.

This example is similar to that shown in Figure 31-1, but with the additional information logged by setting LOG_FILENAME=1 and LOG_MESSAGE_ID=1 showing the filename and message-id; see (1) and (2). The message-id in particular can be used to correlate which entries relate to which message.

Figure 31-3 Logging: Sending to a List

15-Nov-2012 20:01:44.10 l l E 1 adam@example.com rfc822;test-list@example.com bob PMDF_QUEUE:[l]ZZ01ISKND3DE1K90N15M.00;1 <01ISKND2H8MS90N15M@example.com> 15-Nov-2012 20:01:44.81 l tcp_local E 1 adam@example.com rfc822;test-list@example.com carol@otherco.com PMDF_QUEUE:[tcp_local]ZZ01ISKND2WS1I90N15M.00;1 <01ISKND2H8MS90N15M@example.com> 15-Nov-2012 20:01:44.81 l tcp_local E 1 adam@example.com rfc822;test-list@example.com david@otherco.com PMDF_QUEUE:[tcp_local]ZZ01ISKND2WS1I90N15M.00;1 <01ISKND2H8MS90N15M@example.com> 15-Nov-2012 20:01:50.69 l D 1 adam@example.com rfc822;test-list@example.com bob PMDF_QUEUE:[l]ZZ01ISKND3DE1K90N15M.00 <01ISKND2H8MS90N15M@example.com> 15-Nov-2012 20:01:57.36 tcp_local D 1 adam@example.com rfc822;test-list@example.com carol@otherco.com PMDF_QUEUE:[tcp_local]ZZ01ISKND2WS1I90N15M.00 <01ISKND2H8MS90N15M@example.com> dns;gw.otherco.com (TCP|206.184.139.12|2788|192.160.253.66|25) (gw.otherco.com -- SMTP Sendmail) smtp;250 OK. 15-Nov-2012 20:02:06.14 tcp_local D 1 adam@example.com rfc822;test-list@example.com david@otherco.com PMDF_QUEUE:[tcp_local]ZZ01ISKND2WS1I90N15M.00 <01ISKND2H8MS90N15M@example.com> dns;gw.otherco.com (TCP|206.184.139.12|2788|192.160.253.66|25) (gw.otherco.com -- SMTP Sendmail) smtp;250 OK.

The preceding entries illustrate sending to multiple recipients with LOG_FILENAME=1 and LOG_MESSAGE_ID=1 enabled. Here user adam@example.com has sent to the PMDF mailing list test-list@example.com, which expanded to bob@example.com, carol@otherco.com, and david@otherco.com. Note that the original envelope To: address is test-list@example.com for each recipient, though the current envelope To: address is each respective address. Note how the message-id is the same throughout, though two separate files (one for the L channel and one going out the tcp_local channel) are involved.

Figure 31-4 Logging: Sending to a non-existent Domain

15-Nov-2012 20:49:04 l tcp_local E 1 adam@example.com rfc822;user@very.bogus.com user@very.bogus.com PMDF_QUEUE:[tcp_local]ZZ01ISKP0S0LVQ94DU0K.00;1 <01ISKP0RYMAS94DU0K@EXAMPLE.COM> 15-Nov-2012 20:49:33 tcp_local process E 1 (1) rfc822;adam@example.com adam@example.com (2) PMDF_QUEUE:[process]ZZ01ISKP0S0LVQ94DTZB.00 <01ISKP22MW8894DTAS@EXAMPLE.COM>,<01ISKP0RYMAS94DU0K@EXAMPLE.COM> (3) 15-Nov-2012 20:49:33 tcp_local process E 1 (4) rfc822;postmaster@example.com postmaster@example.com PMDF_QUEUE:[process]ZZ01ISKP0S0LVQ94DTZB.00 <01ISKP22MW8894DTAS@EXAMPLE.COM>,<01ISKP0RYMAS94DU0K@EXAMPLE.COM> 15-Nov-2012 20:50:07 tcp_local R 1 (5) adam@example.com rfc822;user@very.bogus.com user@very.bogus.com PMDF_QUEUE:[tcp_local]ZZ01ISKP0S0LVQ94DU0K.00 <01ISKP0RYMAS94DU0K@EXAMPLE.COM> Illegal host/domain name found (6) 15-Nov-2012 20:50:08 process l E 3 (7) rfc822;adam@example.com adam (8) PMDF_QUEUE:[l]ZZ01ISKP23BUQS94DTYL.00;1 <01ISKP22MW8894DTAS@EXAMPLE.COM> 15-Nov-2012 20:50:08 process l E 3 rfc822:postmaster@example.com postmaster PMDF_QUEUE:[l]ZZ01ISKP23BUQS94DTYL.00;1 <01ISKP22MW8894DTAS@EXAMPLE.COM> 15-Nov-2012 20:50:12 l D 3 rfc822;adam@example.com adam PMDF_QUEUE:[l]ZZ01ISKP23BUQS94DTYL.00 <01ISKP22MW8894DTAS@EXAMPLE.COM> 15-Nov-2012 20:50:12 l D 3 rfc822;postmaster@example.com postmaster PMDF_QUEUE:[l]ZZ01ISKP23BUQS94DTYL.00 <01ISKP22MW8894DTAS@EXAMPLE.COM>

The above entries illustrate an attempt to send to a non-existent pseudodomain (here very.bogus.com); that is, sending to a pseudodomain name that is not noticed as illegal by PMDF's rewrite rules and which PMDF matches to an outgoing TCP/IP channel. This example assumes PMDF option settings of LOG_FILENAME=1 and LOG_MESSAGE_ID=1.

When the TCP/IP channel runs and checks for the pseudodomain name in the DNS, the DNS returns an error that no such name exists. Note the "rejection" entry (R), as seen in (5), with the DNS returning an error that this is not a legal domain name, as seen in (6). Since the address is rejected after the message has been submitted, PMDF has to generate a bounce message back to the original sender. Note that PMDF enqueues the new rejection message to the original sender, (1), and (depending on how PMDF is configured regarding bounce copies to the postmaster, as discussed in Section 2.3.4.21) copied to the postmaster, see (3), before deleting the original outbound message (the R entry shown in (5)). Note that notification messages, such as bounce messages, have an empty envelope From: address---as seen, for instance, in (2) and (8) in which the envelope From: field is shown as an empty space. Note that the initial enqueue of a bounce message generated by PMDF shows the message-id for the new notification message followed by the message-id for the original message, (3). (Such information is not always available to PMDF, but when it is available to be logged it allows correlation of the log entries corresponding to the outbound failed message with the log entries corresponding to the resulting notification message.) Such notification messages are enqueued to the process channel, which in turn enqueues them to an appropriate destination channel, (7).

Figure 31-5 Logging: Sending to a non-existent Remote User

15-Nov-2012 13:11:05 l tcp_local E 1 adam@example.com rfc822;nonesuch@example.com nonesuch@example.com PMDF_QUEUE:[tcp_local]ZZ01ISLNBB1JOE94DUWH.00;1 <01ISLNBAWV3094DUWH@example.com> 15-Nov-2012 13:11:08 tcp_local process E 1 rfc822;adam@example.com adam@example.com PMDF_QUEUE:[process]ZZ01ISLNBB1JOE94DSGB.00;1 <01ISLNBFKIDS94DUJ8@example.com>,<01ISLNBAWV3094DUWH@example.com> 15-Nov-2012 13:11:08 tcp_local process E 1 rfc822;postmaster@example.com postmaster@example.com PMDF_QUEUE:[process]ZZ01ISLNBB1JOE94DSGB.00;1 <01ISLNBFKIDS94DUJ8@example.com>,<01ISLNBAWV3094DUWH@example.com> 15-Nov-2012 13:11:11 tcp_local R 1 (1) adam@.example.com rfc822;nonesuch@example.com nonesuch@example.com PMDF_QUEUE:[tcp_local]ZZ01ISLNBB1JOE94DUWH.00 <01ISLNBAWV3094DUWH@example.com> dns;thor.example.com (TCP|206.184.139.12|2788|192.160.253.66|25) (2) (THOR.EXAMPLE.COM -- Server ESMTP [PMDF V5.1-10 #8694]) smtp; 553 unknown or illegal user: nonesuch@example.com (3) 15-Nov-2012 13:11:12 process l E 3 rfc822;adam@example PMDF_QUEUE:[l]ZZ01ISLNBGND1094DQDP.00;1 <01ISLNBFKIDS94DUJ8@example.com> 15-Nov-2012 13:11:12 process l E 3 rfc822;postmaster@example.com postmaster PMDF_QUEUE:[l]ZZ01ISLNBGND1094DQDP.00;1 <01ISLNBFKIDS94DUJ8@example.com> 15-Nov-2012 13:11:13 l D 3 rfc822;adam@example.com adam@example.com PMDF_QUEUE:[l]ZZ01ISLNBGND1094DQDP.00 <01ISLNBFKIDS94DUJ8@example.com> 15-Nov-2012 13:11:13 l D 3 rfc822;postmaster@example.com postmaster@example.com PMDF_QUEUE:[l]ZZ01ISLNBGND1094DQDP.00 <01ISLNBFKIDS94DUJ8@example.com>

The above entries illustrate an attempt to send to a bad address on a remote system. This example assumes PMDF option settings of LOG_FILENAME=1 and LOG_MESSAGE_ID=1, and channel option settings of LOG_BANNER=1 and LOG_TRANSPORTINFO=1. Note the rejection entry (R), seen in (1). But in contrast to the rejection entry in Figure 31-4, note that the rejection entry here shows that a connection to a remote system was made, and shows the SMTP error code issued by the remote SMTP server, (2) and (3). The inclusion of the information shown in (2) is due to setting the channel options LOG_BANNER=1 and LOG_TRANSPORTINFO=1

Figure 31-6 Logging: Rejecting a Remote Side's Attempt to Submit a Message

15-Nov-2012 12:02:23 tcp_local J 0 (1) harold@hotmail.com rfc822; alan@very.bogus.com (2) 550 5.7.1 Relaying not permitted: alan@very.bogus.com (3)

The above entry illustrates the sort of log file entry resulting when PMDF rejects a remote side's attempt to submit a message. (This example assumes that no optional LOG_* options are enabled, so only the basic fields are logged in the entry. Note that enabling the LOG_CONNECTION option, in particular, would result in additional informative fields in such J entries.) In this case, the example is for a site has set up SMTP relay blocking (see Section 16.1.6) with an ORIG_SEND_ACCESS mapping including

ORIG_SEND_ACCESS ! ...numerous entries omitted... ! tcp_local|*|tcp_local|* $NRelaying$ not$ permitted

and where alan@very.bogus.com is not an internal address. Hence the attempt of the remote user harold@hotmail.com to relay through the PMDF system to the remote user alan@very.bogus.com is rejected.

1. This shows the date and time of PMDF rejecting a remote side's attempt to submit a message. Note that as opposed to cases where a PMDF channel is attempting to send a message which is rejected (indicated by R records, as in Figure 31-4 and Figure 31-5 above), this case of PMDF rejecting a message submission attempt is indicated by a J record.
2. The attempted envelope From: and To: addresses are shown. In this case, no original envelope To: information was available so that field is empty.
3. The entry includes the SMTP error message PMDF issued to the remote (attempted sender) side.

Figure 31-7 Logging: Multiple Delivery Attempts

15-Nov-2012 10:31:05.18 tcp_internal tcp_local E 3 (1) adam@sample.example.com rfc822;user@some.org user@some.org PMDF_QUEUE:[tcp_local]ZZ01IS3D2ZP7FQ9UN54R.00 <01IRUD7SVA3Q9UN2D4@example.com> 15-Nov-2012 10:31:10.37 tcp_local Q 0 (2) adam@sample.example.com rfc822;user@some.org user@some.org PMDF_QUEUE:[tcp_local]ZZ01IS3D2ZP7FQ9UN54R.00 <01IRUD7SVA3Q9UN2D4@example.com> (3) TCP active open: Failed connect() Error: no route to host (4) ...several hours worth of entries... 15-Nov-2012 12:45:39.48 tcp_local Q 0 (5) adam@sample.example.com rfc822;user@some.org user@some.org PMDF_QUEUE:[tcp_local]ZY01IS3D2ZP7FQ9UN54R.00 <01IRUD7SVA3Q9UN2D4@example.com> (6) TCP active open: Failed connect() Error: no route to host ...several hours worth of entries... 15-Nov-2012 16:45:24.72 tcp_local Q 0 adam@sample.example.com rfc822;user@some.org user@some.org PMDF_QUEUE:[tcp_local]ZX01IS67NY4RRK9UN7GP.00 <01IRUD7SVA3Q9UN2D4@example.com> (7) TCP active open: Failed connect() Error: connection refused (8) ...several hours worth of entries... 15-Nov-2012 20:45:51.55 tcp_local D 3 (9) adam@sample.example.com rfc822;user@some.org user@some.org PMDF_QUEUE:[tcp_local]ZX01IS67NY4RRK9UN7GP.00 <01IRUD7SVA3Q9UN2D4@example.com> dns;host.some.org (TCP|206.184.139.12|2788|192.1.1.1|25) (All set, fire away) smtp; 250 Ok

The above entries illustrate the sort of log file entries resulting when a message can not be delivered upon the first attempt, so that PMDF has to retry sending it several times. This example assumes option settings of LOG_FILENAME=1 and LOG_MESSAGE_ID=1.

1. The message comes in the tcp_internal channel---perhaps from a POP or IMAP client, or perhaps from another host within the organization using PMDF as an SMTP relay---and PMDF enqueues it to the outgoing tcp_local channel.
2. The first delivery attempt fails---this is a Q entry---and note that message size is shown as 0 for such unsuccessful dequeue attempts.
3. That this is a first delivery attempt can be seen from the ZZ* filename.
4. This delivery attempt failed when the TCP/IP package could not find a route to the remote side. Note that, as opposed to Figure 31-4, the DNS did not object to the destination domain name, some.org; rather, the "no route to host" error indicates that there is some network problem between the sending and receiving side.
5. The next time the PMDF periodic job runs it reattempts delivery, again unsuccessfully.
6. Note that the file name is now ZY*, indicating that this is a second attempt.
7. Note that the file name is ZX* for this third unsuccessful attempt.
8. And again the next time the periodic job reattempts delivery the delivery fails, though this time the TCP/IP package is not complaining that it cannot get through to the remote SMTP server, but rather the remote SMTP server is not accepting connections. (Perhaps the remote side fixed their network problem, but has not yet brought their SMTP server back up---or their SMTP server is swamped handling other messages and hence was not accepting connections at the moment PMDF tried to connect.)
9. Finally the message is dequeued.

Figure 31-8 Logging: Z Entries

15-Nov-2012 20:56:43 l tcp_local E 1 (1) adam@example.com rfc822;barbara@else.where.com barbara@else.where.com PMDF_QUEUE:[tcp_local]ZZ01IT1GSE6O069AMK60.00;1 <01IT1GSE4VYC9AMK60@EXAMPLE.COM> 15-Nov-2012 20:56:43 l tcp_local E 1 (2) adam@example.com rfc822;carl@else.where.com carl@else.where.com PMDF_QUEUE:[tcp_local]ZZ01IT1GSE6O069AMK60.00;1 <01IT1GSE4VYC9AMK60@EXAMPLE.COM> 15-Nov-2012 20:56:48 l tcp_local E 1 (3) adam@example.com rfc822;barbara@else.where.com barbara@else.where.com PMDF_QUEUE:[tcp_local]ZZ01IT1GTR1SS69AMJBD.00;1 <01IT1GSE4VYC9AMK60@EXAMPLE.COM> (4) 15-Nov-2012 20:56:48 tcp_local Z 1 (5) adam@example.com rfc822;barbara@else.where.com barbara@else.where.com PMDF_QUEUE:[tcp_local]ZZ01IT1GSE6O069AMK60.00 <01IT1GSE4VYC9AMK60@EXAMPLE.COM> smtp;422 user over quota; cannot receive new mail: barbara@else.where.com 15-Nov-2012 20:56:48 tcp_local D 1 (6) adam@example.com rfc822;carl@else.where.com carl@else.where.com PMDF_QUEUE:[tcp_local]ZZ01IT1GSE6O069AMK60.00 <01IT1GSE4VYC9AMK60@EXAMPLE.COM> smtp;250 2.1.5 carl@else.where.com and options OK. 15-Nov-2012 20:56:50 tcp_local Q 1 (7) adam@example.com rfc822;barbara@else.where.com barbara@else.where.com PMDF_QUEUE:[tcp_local]ZZ01IT1GTR1SS69AMJBD.00 <01IT1GSE4VYC9AMK60@EXAMPLE.COM> barbara@else.where.com: smtp;422 user over quota; cannot receive new mail: barbara@else.where.com (8) ...several hours of entries... 15-Nov-2012 23:20:14 tcp_local D 1 (9) adam@example.com rfc822;barbara@else.where.com barbara@else.where.com PMDF_QUEUE:[tcp_local]ZZY1IT1GTR1SS69AMJBD.00 <01IT1GSE4VYC9AMK60@EXAMPLE.COM> smtp;250 OK.

The above entries illustrate the case of a message file including multiple recipients for which one recipient succeeds and another recipient gets a temporary failure; this example assumes option settings of LOG_FILENAME=1 and LOG_MESSAGE_ID=1. This is a less common case---it can only arise with certain protocols, for instance, SMTP and DECnet MAIL-11, that allow both for multiple recipients per transaction and for temporary failures. When a temporary failure occurs on a message file which had other, successful recipients, PMDF must make a new message file containing only the unsuccessful recipient(s). The original message file (containing all recipients) is deleted. PMDF then immediately retries delivery to the unsuccessful recipient(s) since such temporary errors may be due simply to the remote side not wanting to accept that many recipients all at once. Thus in the above entries, adam@example.com is trying to send to two recipients at the same remote site, barbara@else.where.com, and carl@else.where.com.

1. We see the initial enqueue to the first recipient...
2. ...and the initial enqueue to the second recipient; note that the message id is the same, since it is the same message to both recipients, and indeed the file name is the same meaning both recipients will be attempted in the same SMTP transaction.
3. Here we see PMDF reenqueuing a new message file containing only the unsuccessful message recipient. The entry showing the unsuccessful dequeue attempt is written later, in ---PMDF cannot delete the original message file until the new message file is written, so this reenqueue operation is completed and its log entry written before the unsuccessful dequeue attempt log entry can be written.
4. Note that the message id for the reenqueue is the same (this is the same message content) as in the original enqueue shown in , but the file name is different (it is a different file since this new file contains only barbara@else.where.com as a recipient).
5. For the barbara@else.where.com recipient address, the remote side issued a temporary error. PMDF does not delete (dequeue) the original message file (containing both recipients) until after the new message file (containing only the barbara@else.where.com recipient) has been written (reenqueued); that is why the log entry for the reenqueue for the barbara@else.where.com recipient appears before the and log entries for the dequeue of the original message file.
6. The carl@else.where.com recipient address was accepted by the remote side.
7. Since the failure on the barbara@else.where.com recipient was a temporary failure on a message where another recipient was accepted, PMDF immediately retries delivery to the unsuccessful recipient.
8. This immediate retry is again unsuccessful, (as indicated by being a "Q" record ), with an error message as shown here. So the message will await retry by the next periodic delivery job.
9. This example shows a case where the remote barbara@else.where.com user apparently cleared out some disk space; the next retry succeeded.

Figure 31-9 Logging: Incoming SMTP Message Routed Through the Conversion Channel

15-Nov-2012 00:06:26.72 tcp_local conversion E 9 (1) amy@example.com rfc822;bert@example.com bert@example.com PMDF_QUEUE:[conversion]ZZ01IT5UAMZ4QW98518O.00;1 <01IT5UALL14498518O@state.edu> 15-Nov-2012 00:06:29.06 conversion l E 9 (2) amy@sample.com rfc822;bert@example.com bert PMDF_QUEUE:[l]ZZ01IT5UAOXLDW98509E.00;1 <01IT5STUMUFO984Z8L@sample.com> 15-Nov-2012 00:06:29.31 conversion D 9 (3) amy@sample.com rfc822;bert@example.com bert PMDF_QUEUE:[conversion]ZZ01IT5UAMZ4QW98518O.00 <01IT5UALL14498518O@sample.com> 15-Nov-2012 00:06:32.62 l D 9 (4) amy@sample.com rfc822;bert@example.com bert PMDF_QUEUE:[l]ZZ01IT5UAOXLDW98509E.00 <01IT5STUMUFO984Z8L@sample.com>

The above entries illustrate the case of a message routed through the conversion channel. That is, this is an example where the site is assumed to have a CONVERSION mapping table along the lines of

CONVERSIONS IN-CHAN=tcp_local;OUT-CHAN=l;CONVERT Yes

This example assumes option settings of LOG_FILENAME=1 and LOG_MESSAGE_ID=1.

1. The message from external user amy@sample.com comes in addressed to the L channel recipient bert@example.com. The CONVERSIONS mapping entry, however, causes the message to be initially enqueued to the conversion channel (rather than directly to the L channel).
2. The conversion channel runs and enqueues the message to the L channel.
3. Then the conversion channel can dequeue the message (delete the old message file).
4. And finally the L channel dequeues (delivers) the message.

Figure 31-10 Logging: Outbound Connection Logging

15-Nov-2012 10:52:05.41 1e488.0 l tcp_local E 1 adam@example.com rfc822;bobby@sample.example.com bobby@sample.example.com PMDF_QUEUE:[tcp_local]ZZ01ITRF7BO388000FCN.00;1 <01ITRF7BDHS6000FCN@EXAMPLE.COM> (1) 15-Nov-2012 10:52:05.41 1e488.0 l tcp_local E 1 adam@example.com rfc822;carl@sample.example.com carl@sample.example.com PMDF_QUEUE:[tcp_local]ZZ01ITRF7BO388000FCN.00;1 <01ITRF7BDHS6000FCN@EXAMPLE.COM> (2) 15-Nov-2012 10:52:05.74 1e488.1 l tcp_local E 1 adam@example.com rfc822;dave@milan.example.com dave@milan.example.com PMDF_QUEUE:[tcp_local]ZZ01ITRF7C11FU000FCN.00;1 <01ITRF7BDHS6000FCN@EXAMPLE.COM> (3) 15-Nov-2012 10:52:10.79 1f625.2.0 tcp_local - O (4) TCP|206.184.139.12|5900|206.184.139.66|25 SMTP/milan.example.com/mailhub.example.com (5) 15-Nov-2012 10:52:10.87 1f625.3.0 tcp_local - O (6) TCP|206.184.139.12|5901|206.184.139.70|25 SMTP/sample.example.com/sample.example.com (7) 15-Nov-2012 10:52:12.28 1f625.3.1 tcp_local D 1 adam@example.com rfc822;bobby@sample.example.com bobby@sample.example.com PMDF_QUEUE:[tcp_local]ZZ01ITRF7BO388000FCN.00 <01ITRF7BDHS6000FCN@EXAMPLE.COM> sample.example.com dns;sample.example.com (8) (TCP|206.184.139.12|5901|206.184.139.70|25) (sample.example.com -- Server ESMTP [PMDF V5.1-9 #8790]) (TCP|206.184.139.12|5901|206.184.139.70|25) smtp;250 2.1.5 bobby@sample.example.com and options OK. 15-Nov-2012 10:52:12.28 1f625.3.1 tcp_local D 1 adam@example.com rfc822;carl@sample.example.com carl@sample.example.com PMDF_QUEUE:[tcp_local]ZZ01ITRF7BO388000FCN.00 <01ITRF7BDHS6000FCN@EXAMPLE.COM> sample.example.com dns;sample.example.com (TCP|206.184.139.12|5901|206.184.139.70|25) (sample.example.com -- Server ESMTP [PMDF V5.1-9 #8790]) (TCP|206.184.139.12|5901|206.184.139.70|25) smtp;250 2.1.5 carl@sample.example.com and options OK. 15-Nov-2012 10:52:12.40 1f625.3.2 tcp_local - C (9) TCP|206.184.139.12|5901|206.184.139.70|25 SMTP/sample.example.com/sample.example.com 15-Nov-2012 10:52:13.01 1f625.2.1 tcp_local D 1 adam@example.com rfc822;dave@milan.example.com dave@milan.example.com PMDF_QUEUE:[tcp_local]ZZ01ITRF7C11FU000FCN.00 <01ITRF7BDHS6000FCN@EXAMPLE.COM> mailhub.example.com dns;mailhub.example.com (TCP|206.184.139.12|5900|206.184.139.66|25) (MAILHUB.EXAMPLE.COM -- Server ESMTP [PMDF V5.1-7 #8694]) (TCP|206.184.139.12|5900|206.184.139.66|25) smtp;250 2.1.5 dave@milan.example.com and options OK. 15-Nov-2012 10:52:13.05 1f625.2.2 tcp_local - C (10) TCP|206.184.139.12|5900|206.184.139.66|25 SMTP/milan.example.com/mailhub.example.com

The above entries illustrate log output for an outgoing message when connection logging is enabled, via LOG_CONNECTION=3. LOG_PROCESS=1, LOG_MESSAGE_ID=1, and LOG_FILENAME=1 are also assumed in this example. The example shows the case of user adam@example.com sending the same message (note that the message ID is the same for each message copy) to three recipients, bobby@sample.example.com, carl@sample.example.com, and dave@milan.example.com. This example assumes that the message is going out a tcp_local channel marked (as such channels usually are) with the single_sys channel keyword. Therefore, a separate message file on disk will be created for each set of recipients to a separate host name, as seen in (1), (2), and (3), where the bobby@sample.example.com and carl@sample.example.com recipients are stored in the same message file, but the dave@milan.example.com recipient is stored in a different message file.

1. The message is enqueued to the first recipient...
2. ...and to the second recipient...
3. ...and to the third recipient.
4. Having LOG_CONNECTION=3 set causes PMDF to write this entry. The minus,-, indicates that this entry refers to an outgoing connection. The O means that this entry corresponds to the opening of the connection. Also note that the process id here is the same, 1f625, as in , since the same process is used for the multithreaded TCP/IP channel for these separate connection opens, though this open is being performed by thread 2 vs. thread 3 for .
5. As there are two separate remote systems to which to connect, the multithreaded SMTP client in separate threads opens up a connection to each -- the first in this entry, and the second shown in . This part of the entry shows the sending and destination IP numbers and port numbers, and shows both the initial host name, and the host name found by doing a DNS lookup. That is, in the SMTP/initial-host/dns-host clauses, note the display of both the initial host name, and that used after performing a DNS MX record lookup on the initial host name: the system milan.example.com is apparently MXed to mailhub.example.com.
6. The multithreaded SMTP client opens up a connection to the second system in a separate thread (though the same process).
7. As there are two separate remote systems to which to connect, the multithreaded SMTP client in separate threads opens up a connection to each -- the second in this entry, and the first shown above in . This part of the entry shows the sending and destination IP numbers and port numbers, and shows both the initial host name, and the host name found by doing a DNS lookup. In this example, the system sample.example.com apparently receives mail directly itself.
8. Besides resulting in specific connection entries, LOG_CONNECTION=3 also causes inclusion of connection related information in the regular message entries, as seen here for instance.
9. Having LOG_CONNECTION=3 causes PMDF to write this entry. After any messages are dequeued, (the bobby and carl messages in this example), the connection is closed, as indicated by the C in this entry.
10. Having LOG_CONNECTION=3 causes PMDF to write this entry. After any messages are dequeued, (the dave message in this example), the connection is closed, as indicated by the C in this entry.

Figure 31-11 Logging: Inbound Connection Logging

15-Nov-2012 17:02:08.70 tcp_local + O (1) TCP|206.184.139.12|25|192.160.253.66|1244 SMTP (2) 15-Nov-2012 17:02:26.65 tcp_local l E 1 service@example.com rfc822;adam@example.com adam THOR.EXAMPLE.COM (THOR.EXAMPLE.COM [108.165.158.93]) (3) 15-Nov-2012 17:02:27.05 tcp_local + C (4) TCP|206.184.139.12|25|192.160.253.66|1244 SMTP 15-Nov-2012 17:02:31.73 l D 1 service@example.com rfc822;adam@example.com adam

The above entries illustrate log output for an incoming SMTP message when connection logging is enabled, via LOG_CONNECTION=3.

1. The remote system opens a connection. The O character indicates that this entry regards the "O"pening of a connection; the + character indicates that this entry regards an incoming connection.
2. The IP numbers and ports for the connection are shown. In this entry, the receiving system (the system making the log file entry) has IP address 206.184.139.12 and the connection is being made to port 25; the sending system has IP address 192.160.253.66 and is sending from port 1244.
3. In the entry for the enqueue of the message from the incoming TCP/IP channel (tcp_local) to the L channel recipient, note that information beyond the default is included since LOG_CONNECTION=3 is enabled. Specifically, the name that the sending system claimed on its HELO or EHLO line, the sending system's name as found by a DNS reverse lookup on the connection IP number, and the sending system's IP address are all logged; see Section 2.3.4.40 for a discussion of channel keywords affecting this behavior.
4. The inbound connection is closed. The C character indicates that this entry regards the "C"losing of a connection; the + character indicates that this entry regards an incoming connection.