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

On Mon, 2021-03-29 at 16:50 +0900, Michael Paquier wrote:
> 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?

It's not a matter of the tests being stable, but of the tests needing
to change and evolve as the implementation changes. A big part of that
is visibility into what the tests are doing, so that you can debug
them.

I'm sorry I don't have any explicit examples; the NSS work is pretty
broad.

> 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.

I agree that it would be good in general, as long as the consistency
isn't at the expense of usefulness.

Keep in mind that the rotate-restart-slurp method comes from an
existing test. I assume Andrew chose that method for the same reasons I
did -- it works with what we currently have.

> 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.

I agree that it'd be ideal not to have to restart the server. But 20%
of less than ten seconds is less than two seconds, and the test suite
has to run thousands of times to make up a single hour of debugging
time that would be (hypothetically) lost by missing log files. (These
are not easy tests for me to debug and maintain, personally -- maybe
others have a different experience.)

> 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.

Is the additional effort to create (and maintain) that new system worth
two seconds per run? I feel like it's not -- but if you feel strongly
then I can definitely look into it.

Personally, I'd rather spend time making it easy for tests to get the
log entries associated with a given connection or query. It seems like
every suite has had to cobble together its own method of checking the
log files, with varying levels of success/correctness. Maybe something
with session_preload_libraries and the emit_log_hook? But that would be
a job for a different changeset.

> 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.

Which parts would you consider confusing/in need of change? I'm happy
to expand where needed. Would an inline sample be more helpful than a
textual explanation?

Thanks again for all the feedback!

--Jacob