Replace usages of internal log package with log/slog

[adombeck]

Except in the PAM module, which configures the log package in such a
complex way that it's out of scope of this commit. Since the PAM module
also configures the log package to use systemd journal's formatting when
printing to the journal, we might want to migrate it to log/slog once we
add systemd journal formatting for it (UDENG-4621).

The log messages from our internal log package used to look like this:

time="2024-09-25T17:42:30+02:00" level=debug msg="Updating entry of user \"user1\" (UID: 1111)"

Now they look like this:

2024/09/25 17:41:03 DEBUG Registered user "user1" with UID 1111

UDENG-4622

[codecov-commenter]

Codecov Report

Attention: Patch coverage is 87.50000% with 7 lines in your changes missing coverage. Please review.

Project coverage is 84.78%. Comparing base (faa84f2) to head (3cc1aac).
Report is 4 commits behind head on main.

Files with missing lines	Patch %	Lines
internal/brokers/withexamples.go	33.33%	2 Missing ⚠️
internal/services/nss/nss.go	33.33%	2 Missing ⚠️
cmd/authd/daemon/config.go	90.00%	1 Missing ⚠️
internal/brokers/dbusbroker.go	66.66%	1 Missing ⚠️
internal/services/pam/pam.go	85.71%	1 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main     #551      +/-   ##
==========================================
+ Coverage   84.76%   84.78%   +0.02%     
==========================================
  Files          79       79              
  Lines        6957     6948       -9     
  Branches       75       75              
==========================================
- Hits         5897     5891       -6     
+ Misses        741      737       -4     
- Partials      319      320       +1     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[3v1n0]

Isn't slog.Warn supporting formatting natively?

[adombeck]

I don't think it does. I tried using slog.Warn("%s", "foo") and it prints WARN %s !BADKEY=foo. There is also no slog.Warnf function.

[3v1n0]

Mh, that's a bit annoying because in some code paths where we'd end up logging a lot (and potentially with complex parameters = e.g. PAM) it implies that we have to do everywhere slog.Default().Enabled() before calling the function or we'd end up allocating a lot of strings (sometimes causing introspection recursions in objects) for no reasons.

[adombeck]

One thing I want to note is that I don't think it's worth to put a lot of effort into optimizing the code that handles a login request, because those are initiated by the user, so they are relatively rare, and it doesn't matter much if it takes a few milliseconds longer to respond do it. That said, if the PAM module really logs so many complex parameters that it notably affects performance, we can consider wrapping the slog package with a package that provides Warnf, Infof, etc. functions and only does the string formatting if the log level is enabled.

I would like to postpone that until we actually use slog in the PAM module, which is not in scope of this PR.

[3v1n0]

That said, if the PAM module really logs so many complex parameters that it notably affects performance, we can consider wrapping the slog package with a package that provides Warnf, Infof, etc. functions and only does the string formatting if the log level is enabled.

Well it's mostly when used in gdm, where its polling nature makes it to waste a lot of resources already, so trying to optimize it's something we should try as much as possible

[adombeck]

Ah yes, I've seen that those polls are handled very frequently (the journal is spammed with it when debug mode is enabled for the PAM module), so if we can't avoid that, we should indeed make sure that the code which handles those polls is performant.

[denisonbarbosa]

Changes seem fine to me. I won't get into the whole "this was not scoped to be done now" discussion as I think this was already addressed in MM.

I have one request, though: in these cases where the actual impact of the changes is not visible (from a PR perspective), it's nice to have an example of the impact of the change in the description. Can you add it? (e.g. "The logs used to look like {this}, now they look like {new_this}").

[adombeck]

I have one request, though: in these cases where the actual impact of the changes is not visible (from a PR perspective), it's nice to have an example of the impact of the change in the description. Can you add it? (e.g. "The logs used to look like {this}, now they look like {new_this}").

Good idea! I added that to the commit message and also the PR description.

[3v1n0]

So, as mentioned by both me and @didrocks I think that the current log abstraction can be just re-used also with slog backend... And I'd perfer such solution TBH.

I've drafted it at 3v1n0@bda862e and it seems to just work with everything we have (PAM included) with just few lines changes.

However, my feeling is that if the problem we have(?) is the output readability, it would be just about using a custom logrus formatter to achieve the same, no?

That said, in general I think that having a logging abstraction is better because it allows us to be more dynamic if it comes to change backend without huge refactories.

[adombeck]

However, my feeling is that if the problem we have(?) is the output readability, it would be just about using a custom logrus formatter to achieve the same, no?

Yes, I think we could achieve that by adapting the formatter. However, the reason we filed UDENG-4622 was 1. to fix that we're using two different packages for logging, and 2. to get rid of the unused context.

That said, in general I think that having a logging abstraction is better because it allows us to be more dynamic if it comes to change backend without huge refactories.

That makes sense to me.

[3v1n0]

Yes, I think we could achieve that by adapting the formatter. However, the reason we filed UDENG-4622 was 1. to fix that we're using two different packages for logging, and 2. to get rid of the unused context.

Wasn't @didrocks also saying to continue using the context in MM?

However, we do can get rid of the context also in the current abstraction. Or make it optional.

One more thing, also with slog I think that if we want redirect the log to some output (and we do want it for pam), I think that also the slog.NewTextHandler has the very same format that we're trying to change here, so it's not a problem of the library in use but more of we format it, and AFAIK, the slog's default handler isn't exposed publicly. So we still have the same issue.

[adombeck]

Wasn't @didrocks also saying to continue using the context in MM?

The way I understood it was that he doesn't want to remove the context from the parameters of functions which used to call the internal log package (which I did in commit 3cc1aac to appease the linter).

[adombeck]

So, as mentioned by both me and @didrocks I think that the current log abstraction can be just re-used also with slog backend... And I'd perfer such solution TBH.

I'm fine with that if we then consistently use the internal log package and not slog directly. I won't work on that now though. If we decide that's what we want to do, I'll close the PR and update the description of UDENG-4622.

[3v1n0]

So, as mentioned by both me and @didrocks I think that the current log abstraction can be just re-used also with slog backend... And I'd perfer such solution TBH.

I'm fine with that if we then consistently use the internal log package and not slog directly. I won't work on that now though. If we decide that's what we want to do, I'll close the PR and update the description of UDENG-4622.

I'm not against with switching the logging backend, if you want we can just try to merge the efforts by cleaning up the commit I suggested above so that we can have just one log provider everywhere.

I'd keep this as a draft for the time being though.