Remote Delivery Status Log

The component that executes remote deliveries within GreenArrow Engine writes a log with general statistics about what it’s doing.

$ tail -n 9 /var/hvmail/log/rspawn-limiter/current | tai64nlocal
2017-12-18 07:52:07.384080500 greenarrow-remote.10427: cache: file cache: 16 entries
2017-12-18 07:52:07.388506500 greenarrow-remote.10427: cache: mx_blacklist: 1 entries
2017-12-18 07:52:07.388507500 greenarrow-remote.10427: cache: dns ip: 1674 entries
2017-12-18 07:52:07.388525500 greenarrow-remote.10427: cache: dns mx: 1384 entries
2017-12-18 07:52:07.388717500 greenarrow-remote.10427: cache: ipme: 1 entries
2017-12-18 07:52:07.388718500 greenarrow-remote.10427: dns cache: num_lookups=0 num_resolves=0 avg_resolve_semaphore_time_ms=0 avg_resolve_query_time_ms=0
2017-12-18 07:52:07.388719500 greenarrow-remote.10427: dns cache: mx: num_lookups=0 num_resolves=0 avg_resolve_semaphore_time_ms=0 avg_resolve_query_time_ms=0
2017-12-18 07:52:07.396060500 greenarrow-remote.10427: request processor: total=64 pgqueue=0/4096(full=0,sql=0) gaproxyconn=0 mx=0 init1=0 dns1=0 init2=0 litebounce=0 deliveryoverride=0 nondelivered=0 bouncenomx=0 dns2=0(0/100) waiting=0 concurrency=64/10000 throttle=2 tcpconn=2 smtpconn=11 hello=1 tls=9 auth=0 from=3 rcpt=5 data=3 read=0 write=23 quit=7 pattern_match=0 bounce_cat=0 bounce_cat=0 cachedconn=5 cachedconn_quit=0
2017-12-18 07:52:07.396062500 greenarrow-remote.10427: request processor: 158 sent; sending 0.11 MM; success 92.41%; deferral 3.16%; failure 4.43% (avg msg size 82kb)

These log entries are printed every five seconds.

The first five lines print information about the internal caches.

file cache, mx_blacklist, and ipme are configuration files that are loaded from disk and kept in memory for a few seconds at a time.
dns ip and dns mx are DNS caches used to speed up delivery.

The two dns cache: lines include details about the DNS resolution.

num_lookups - The number of DNS lookups that were attempted in this time window (the last five seconds). This includes all delivery attempts that make any request for DNS information.
num_resolves - The number of actual DNS resolutions that were required to provide answers to the DNS lookups. This will be lower if more of the lookup requests are found in the DNS cache.
avg_resolve_semaphore_time_ms - The average length of time in milliseconds a DNS request had to wait for their turn to perform the request.
avg_resolve_query_time_ms - The average length of time in milliseconds a DNS request took to receive an answer.

The first request processor: line includes the following information. These counts represent the number of delivery attempts that are currently in the given phase of the delivery process.

total - The total number of delivery requests that are being worked on.
pgqueue - Status of an internal Postgres queue. This queue contains signals to enter backoff mode due to smtp_match_begin_backoff_mode.
- The first numbers (i.e. 0/4096 in pgqueue=0/4096(full=0,sql=0)) are the length and capacity of this queue.
- The second numbers (i.e. full=0,sql=0) are the number of signals that were dropped either due to the queue being full or an SQL error since the last status line.
gaproxyconn - Delivery attempts that are waiting for a connection to the greenarrow-proxy to be established.
mx - The number of active MX lookups that are underway. This represents delivery attempts that are not yet in progress.
init1 - Initial configuration. The recipient address is being parsed.
dns1 - An initial DNS resolution of the recipient domain.
init2 - Calculation of configuration to be used for this delivery attempt. This uses the result of dns1 for MX-based configuration.
litebounce - Matching of lite_bounce_processor_address and lite_fbl_processor_address regular expressions against recipients. When a recipient is matched, this phase includes: reading messages from the disk, inserting messages into the Lite Bounce Processor / FBL Processor queue, and potentially waiting due to backpressure in that queue.
deliveryoverride - Determination of if this delivery attempt should be overrided by the delivery_override configuration directive.
nondelivered - Determination of if this delivery attempt should be prevented based on Engine’s internal suppression list.
bouncenomx - Determination of if this delivery attempt should be prevented because the recipient domain has no MX records (due to the bounce_recipients_with_no_mx configuration directive).
dns2 - Delivery attempts that are waiting for a DNS response. In parentheses are the number of DNS requests that are active over the number of concurrent DNS requests that are allowed.
waiting - Delivery attempts that are waiting for a “concurrency” slot.
concurrency - The numerator is the number of delivery attempts that have obtained a concurrency slot - meaning they’re cleared to make a remote connection. The denominator is the total number of delivery attempts that are allowed to have open connections simultaneously.
throttle - Delivery attempts that are waiting for throttle availability.
tcpconn - Delivery attempts that are waiting for the TCP socket to connect.
smtpconn - Delivery attempts that are beginning an SMTP session on an open TCP socket.
hello - Delivery attempts sending (or waiting for a response to) a HELO or EHLO.
tls - Delivery attempts negotiating a STARTTLS activation.
auth - Delivery attempts sending (or waiting for a response to) authorization.
from - Delivery attempts sending (or waiting for a response to) MAIL FROM.
rcpt - Delivery attempts sending (or waiting for a response to) RCPT.
data - Delivery attempts sending (or waiting for a response to) DATA - not including the actual message payload.
read - Delivery attempts reading the message payload from memory or disk.
write - Delivery attempts transmitting the message payload to the remote server.
quit - Delivery attempts being shut down and disconnected.
pattern_match - The number of completed delivery attempts that are currently evaluating the smtp_pattern, override_smtp_result, or smtp_match_begin_backoff_mode configuration directives.
bounce_cat - The number of completed delivery attempts being processed by the bounce processor to calculate bounce_code.
cachedconn - The number of connections being held open for reuse.
cachedconn_quit - The number of connections that were being held open for reuse that are now terminating.

The second request processor: line includes the following information.

X sent - The number of delivery attempts that completed during this time window (the last five seconds).
sending X MM - An estimated number of millions of delivery attempts per hour that the current delivery rate (over the last five seconds) would equate to, extrapolated over a full hour.
success X% - The percentage of delivery attempts that resulted in success during this time window.
deferral X% - The percentage of delivery attempts that resulted in deferral during this time window.
failure X% - The percentage of delivery attempts that resulted in failure during this time window.
(avg msg size XXXkb) - The average byte-size of messages during this time window. This only includes messages that were actually loaded – if the SMTP session ended before the DATA command, the message is not included in the average.