Interpreting the log

[Gary Aitken]

If someone can point me at an explanation of log entries it would be much
appreciated.

1)
This is a low traffic server.
Whenever a new entry arrives for processing, I see what looks like tables
getting reloaded, e.g.

dict_cidr_open: add a.b.c.0/17 OK
dict_cidr_open: add d.e.f.0/24 OK
dict_open: cidr:/etc/postfix/ok_client

Is that because the subprocesses have exited due to idle timeouts and are
restarting?

2)
I see what looks like two separate processes stepping on each other during
the opening client connection.  Is this normal?  Is there some setting I
can change to alleviate this?  All of this traffic is within one second.

[31458]: > localhost[127.0.0.1]: 220 host.me.com ESMTP Postfix (Ubuntu)
[31458]: < localhost[127.0.0.1]: EHLO me.com
...
[31458]: > localhost[127.0.0.1]: 250-host.me.com
...
[31458]: < localhost[127.0.0.1]: STARTTLS
[31458]: > localhost[127.0.0.1]: 220 2.0.0 Ready to start TLS
...
[31458]: < localhost[127.0.0.1]: EHLO me.com
...
[31458]: > localhost[127.0.0.1]: 250-host.me.com
...
[31458]: > localhost[127.0.0.1]: 250 SMTPUTF8
[31460]: match_string: parent_domain_matches_subdomains: smtpd_client_event_limit_exceptions ~? permit_mx_backup_networks
...
[31460]: > localhost[127.0.0.1]: 220 host.me.com ESMTP Postfix (Ubuntu)
[31460]: < localhost[127.0.0.1]: EHLO me.com
...
[31460]: > localhost[127.0.0.1]: 250-host.me.com
...
[31460]: < localhost[127.0.0.1]: STARTTLS
[31460]: > localhost[127.0.0.1]: 220 2.0.0 Ready to start TLS
...
[31460]: < localhost[127.0.0.1]: EHLO me.com
...
[31460]: > localhost[127.0.0.1]: 250-host.me.com
...
[31460]: < localhost[127.0.0.1]: MAIL FROM:<[hidden email]>
...
[31458]: < localhost[127.0.0.1]: MAIL FROM:<[hidden email]>

3)
reject_unknown_address: [hidden email]
rewrite_clnt: cached: local: [hidden email] -> [hidden email]
send attr request = rewrite
send attr rule = local
send attr address = [hidden email]

Is the reject_unknown_address an actual rejection, or just something being
probed?
What does this mean: cached: local: [hidden email] -> [hidden email] ?

4)
rewrite_clnt:
   local: [hidden email] -> [hidden email]
send attr request = resolve
send attr sender = [hidden email]
send attr address = [hidden email]

In this case the "sender" above is actually the "to" part of the message,
which doesn't seem like a "sender"; and the "address" is the "from" part,
which seems like it should be a "receiver".  What's the meaning of the
above sequence?

5)
ctable_locate:
   install entry key [hidden email]?[hidden email]

Is this a map insertion with a key of [hidden email] for a value of
[hidden email]?  What's ctable?

Gary

[Viktor Dukhovni]

On Sun, Feb 21, 2021 at 05:22:56PM -0700, Gary Aitken wrote:

> If someone can point me at an explanation of log entries it would be much
> appreciated.

Verbose logging is ad-hoc and not documented.  Your log level is too
high.

> Whenever a new entry arrives for processing, I see what looks like tables
> getting reloaded, e.g.
>
> dict_cidr_open: add a.b.c.0/17 OK
> dict_cidr_open: add d.e.f.0/24 OK
> dict_open: cidr:/etc/postfix/ok_client
>
> Is that because the subprocesses have exited due to idle timeouts and are
> restarting?

Yes, but your log level is too high.

> I see what looks like two separate processes stepping on each other during
> the opening client connection.  Is this normal?

Postfix can process multiple messages in parallel, and delivery of a
message to a content filter can begin (after "DOT") even before the
remote SMTP client has hung up.  Your log level is too high.

> 3)
> Is the reject_unknown_address an actual rejection, or just something
> being probed?  What does this mean: cached: local: [hidden email] ->
> [hidden email] ?
>
> 4)
> In this case the "sender" above is actually the "to" part of the message,
> which doesn't seem like a "sender"; and the "address" is the "from" part,
> which seems like it should be a "receiver".  What's the meaning of the
> above sequence?
>
> 5)
> Is this a map insertion with a key of [hidden email] for a value of
> [hidden email]?  What's ctable?

Your log level is too high.

--
    Viktor.

[Gary Aitken]

> Your log level is too high.

I believe you :-).  Although level 2 was the only way I could see
what was happening using the maps I had set, some of which weren't doing
what I (erroneously) thought they should.

What is the relationship between the -v args in master.cf and
debug_peer_level and debug_peer_list in main.cf?

Adding -v in master.cf for smtp seemed to have no effect unless I also set
   debug_peer_level and debug_peer_list
in main.cf.

Gary

[Viktor Dukhovni]

On Sun, Feb 21, 2021 at 10:09:43PM -0700, Gary Aitken wrote:

> What is the relationship between the -v args in master.cf and
> debug_peer_level and debug_peer_list in main.cf?

Each -v flag raises the verbosity level by 1 globally.  The
debug_peer_list parameter set the verbosity to debug_peer_level, when
delivering mail to the given peer.

> Adding -v in master.cf for smtp seemed to have no effect unless I also set
>    debug_peer_level and debug_peer_list
> in main.cf.

It raises the verbosity level by 1.

--
    Viktor.