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 dns=0(0/100) waiting=0 concurrency=64/10000 tcpconn=2 smtpconn=11 hello=1 tls=9 auth=0 from=3 rcpt=5 data=3 read=0 write=23 quit=7 cachedconn=5
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%

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.

total - The total number of delivery requests that are being worked on.
dns - 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.
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.
cachedconn - The number of connections being held open for reuse.

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.