Re: Proposal: Save user's original authenticated identity for logging

On Fri, Mar 26, 2021 at 10:41:03PM +0000, Jacob Champion wrote:
> For a few of the bugs I was tracking down, it was imperative. The tests
> aren't isolated enough (or at all) to keep one from affecting the
> others.

If the output of the log file is redirected to stderr and truncated,
while the connection attempts are isolated according to the position
where the file is truncated, I am not quite sure to follow this line
of thoughts. What actually happened? Should we make the tests more
stable instead? The kerberos have been running for one week now with
11e1577a on HEAD, and look stable so it would be good to be consistent
on all fronts.

> And if the test is written incorrectly, or becomes incorrect
> due to implementation changes, then the log files are really the only
> way to debug after a false positive -- with truncation, the bad test
> succeeds incorrectly and then swallows the evidence. :)

Hmm, okay. However, I still see a noticeable difference in the tests
without the additional restarts done so I would rather avoid this
cost. For example, on my laptop, the restarts make
authentication/t/001_password.pl last 7s. Truncating the logs without
any restarts bring the test down to 5.3s so that's 20% faster without
impacting its coverage. If you want to keep this information around
for debugging, I guess that we could just print the contents of the
backend logs to regress_log_001_password instead? This could be done
with a simple wrapper routine that prints the past contents of the log
file before truncating them. I am not sure that we need to stop the
server while checking for the logs contents either, to start it again
a bit later in the test while the configuration does not change. that
costs in speed.

>> Could you make the comments in those various areas more
>> explicit about the difference and that it is intentional to register
>> the auth ID before checking the user map? Anybody reading this code
>> in the future may get confused with the differences in handling all
>> that according to the auth type involved if that's not clearly
>> stated.
>
> I took a stab at this in v12, attached.

This part looks good, thanks!

Causes each attempted connection to the server to be logged,
- as well as successful completion of client authentication.
+ as well as successful completion of client authentication and authorization.
I am wondering if this paragraph can be confusing for the end-user
without more explanation and a link to the "User Name Maps" section,
and if we actually need this addition at all. The difference is that
the authenticated log is logged before the authorized log, with user
name map checks in-between for some of the auth methods. HEAD refers
to the existing authorized log as "authentication" in the logs, while
you correct that.
--
Michael