Not every error needs a stacktrace

[joshka]

Description

As a new user setting up authelia under docker for the first time as a PoC, I'm running into a bunch of configuration errors (due to wanting to just take a config example and run it). The log format in use is overly noisy.

Every error has a backtrace, but the error message has enough information to solve the error. The backtraces are unnecessary information

Use Case

Only log backtraces for actual program errors, not for errors that are due to things that users can configure / do.

Details

With Stacktrace

What this would look like without stacktraces

Manually wrapped at 120 chars just to show the validity of the idea:

 ⠿ Container authelia  Created                                                                                                                                        0.0s
Attaching to authelia
authelia  | 2024-04-07T16:55:27-07:00 ERROR Configuration: failed to load configuration from file path(/config/configur
ation.yml) source: yaml: line 40: found character that cannot start any token"
authelia  | 2024-04-07T16:55:27-07:00 ERROR Configuration: authentication_backend: you must ensure either the 'file' or
 'ldap' authentication backend is configured"
authelia  | 2024-04-07T16:55:27-07:00 ERROR Configuration: access_control: 'default_policy' option 'deny' is invalid: w
hen no rules are specified it must be 'two_factor' or 'one_factor'"
authelia  | 2024-04-07T16:55:27-07:00 ERROR Configuration: session: option 'cookies' is required"
authelia  | 2024-04-07T16:55:27-07:00 ERROR Configuration: storage: configuration for a 'local', 'mysql' or 'postgres' 
database must be provided"
authelia  | 2024-04-07T16:55:27-07:00 ERROR Configuration: storage: option 'encryption_key' is required"
authelia  | 2024-04-07T16:55:27-07:00 ERROR Configuration: notifier: you must ensure either the 'smtp' or 'filesystem' 
notifier is configured"
authelia  | 2024-04-07T16:55:27-07:00 ERROR Configuration: identity_validation: reset_password: option 'jwt_secret' is 
required when the reset password functionality isn't disabled"
authelia  | 2024-04-07T16:55:27-07:00 FATAL Can't continue due to the errors loading the configuration"
authelia exited with code 1

Documentation

No response

Pre-Submission Checklist

• I agree to follow the Code of Conduct

• I have checked for related issues and checked the documentation

[glime-ai[bot]]

Please note this response was created using generative AI leveraging previously available information from the repository. This information may be helpful however it is our strong recommendation that you carefully consider the information before blindly applying it.

---

To address the issue of overly noisy log formats due to stack traces for configuration errors in Authelia, it's important to understand that Authelia's logging behavior, including error reporting and stack traces, is part of its design to aid in troubleshooting. However, based on the context provided, there isn't a direct mention of a feature to disable stack traces for configuration errors specifically.

The logging configuration in Authelia allows for adjusting the verbosity of the logs through the log_level setting, which can be set to trace, debug, info, warn, or error. Setting this to a higher level like error would reduce the amount of logged information, but it would not selectively remove stack traces while keeping the error messages intact as you've described. The documentation does not explicitly mention the ability to disable stack traces for configuration errors without affecting other types of errors.

Given this, the best course of action would be to adjust the log_level to control the verbosity of the logs to some extent. For more granular control over logging output, such as removing stack traces for configuration errors while keeping them for actual program errors, you would likely need to request this feature directly from the Authelia team. This could be done by creating an issue on the Authelia GitHub repository, explaining your use case and how this feature would benefit users.

For immediate relief from the noisy logs, reviewing and fixing the configuration errors as indicated by the error messages would be advisable. The error messages you've shared are quite descriptive and should guide you in correcting the configuration issues.

Remember, the logging and error reporting mechanisms are designed to assist in diagnosing and troubleshooting issues effectively. While stack traces can be verbose, they often provide valuable context for understanding the root cause of errors, especially in complex applications like Authelia.

This comment was generated by Glime.

[james-d-elliott]

While in this instance the errors are fairly noisy and unnecessary they are critical during normal operation to isolate causes of unexpected errors. Adding a specific rule for these may be possible but may however add unnecessary complexity for a fairly small gain. We can however look at it depending on user feedback so I'll convert this to an idea.

[joshka]

they are critical during normal operation to isolate causes of unexpected errors

This is a bit of an unexpected explanation. I wonder if you could provide more info here? Is this due to concerns about software quality, or more about the complexity of the various systems working together?

(As some background), I previously built and ran of the largest OAuth2 systems in the world - we wouldn't have ever logged exception messages for errors that were handled and due to known causes). One thing that system did have was wide events (information / metrics about various things from ever level of the stack in a single request) in addition to the application logs. I wonder if the backtraces here are in lieu of that sort of thing (i.e. authelia uses them for working out what parts of the system were hit by a particular part of the code).

These are some principles I'd personally apply to logging in any system:

• If something is configured wrong and there's a message that covers that, log the error, skip the stack trace
• If a request comes in that fails some auth check, log the reason it failed the check, bump a metric, and skip the stack trace.
• Stack traces are an indication of broken software, not a tool for the diagnosing the standard day to day running of the software.
• A stack trace generally leads to raising a bug with a software vendor (to be clear, I mean this in the general case).

In case any of this comes across ascerbic, I want to make sure that I express my gratitude for making this software open source and explicitly disclaim any sort of entitlement implied.

Here's another example. The stack trace is ~3.5x the size of the message and useful properties.

authelia | time="2024-04-07T19:21:13-07:00" level=error msg="Authorization Request failed with error: Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method). The requested OAuth 2.0 Client does not exist. Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method). Client with id '' does not appear to be a registered client." method=GET path=/api/oidc/authorization remote_ip=172.24.0.1 stack="github.com/authelia/authelia/v4/internal/handlers/handler_oidc_authorization.go:41 OpenIDConnectAuthorization\ngithub.com/authelia/authelia/v4/internal/middlewares/http_to_authelia_handler_adaptor.go:114 handleRouter.NewHTTPToAutheliaHandlerAdaptor.func21\ngithub.com/authelia/authelia/v4/internal/middlewares/bridge.go:54 handleRouter.(*BridgeBuilder).Build.func16.1\ngithub.com/authelia/authelia/v4/internal/middlewares/headers.go:91 SecurityHeadersNoStore.func1\ngithub.com/valyala/fasthttp@v1.52.0/userdata.go:57 (*userData).Get\ngithub.com/authelia/authelia/v4/internal/middlewares/headers.go:30 SecurityHeadersBase.func1\ngithub.com/authelia/authelia/v4/internal/middlewares/cors.go:216 handleRouter.(*CORSPolicy).Middleware.func22\ngithub.com/fasthttp/router@v1.5.0/router.go:441 (*Router).Handler\ngithub.com/authelia/authelia/v4/internal/middlewares/log_request.go:14 handleRouter.LogRequest.func40\ngithub.com/authelia/authelia/v4/internal/middlewares/errors.go:38 RecoverPanic.func1\ngithub.com/valyala/fasthttp@v1.52.0/server.go:2374 (*Server).serveConn\ngithub.com/valyala/fasthttp@v1.52.0/workerpool.go:224 (*workerPool).workerFunc\ngithub.com/valyala/fasthttp@v1.52.0/workerpool.go:196 (*workerPool).getCh.func1\nruntime/asm_amd64.s:1695 goexit"

[james-d-elliott]

I have discussed this with the other maintainers of the project. We can understand why the verbosity here does not seem particularly helpful and that it's not clear the reason we include the stacktrace when errors occur. This response will be rather wordy because while I feel like I articulated this I guess our whole thought process isn't exactly obvious.

We specifically include stacktraces in errors as this is probably one of regular support requests; "An error occurred, how do I fix it?". In many situations the error itself is enough to diagnose it, however in those that are not generally the stacktrace is the key element that allows us to promptly identify the cause and fix it if it is actually a bug. This is actually most helpful in the scenarios that involve elements like OpenID Connect 1.0 and WebAuthn where complex inputs and conditions exist.

It's for the above reasons that I at least feel that while your ideas are somewhat similar to ours in some ways they are also different enough to produce a different conclusion. To me the stacktrace is an essential part of the debugging process. As you mentioned there are other ways to collect this information however we do not currently do this. If we were to implement telemetry like this we'd be very likely make it opt-in and we'd have them configure their own instance; this is not very conducive to being able to collect this information. It can be difficult at the best of times to get someone to submit the necessary information to debug things, adding another element (which is optionally enabled) is just going to make this that much harder. In lieu of this the stacktrace in the logs is a very effective tool.

If an error occurs, we want that information to be available for the purpose of finding out why it occurred and the areas where it could potentially be fixed. The stacktrace in go essentially shows all of the functions and information about the arguments which allows us to see nil pointers, non-nil pointers, which functions were called, which order they were called in, and ultimately the most likely location to start looking for a bug if one were to exist including the file location and/or specific module (i.e. library) this occurred in. In a post-mortem it is my opinion that a stacktrace can be incredibly beneficial and when dealing with a functional-first language like Go the benefit is orders of magnitude higher than with object-orientated languages.

Fundamentally however a error may be reliant on input or conditions outside of anyone's control (either via lack of knowledge or lack of accessibility). In those instances it may be impossible to get a stacktrace again leaving a potential bug difficult to solve when realistically we want to be able to swiftly resolve it (desirable outcome for everyone). While they are not helpful to most users, they are very helpful to us, and in some circumstances even the users have identified the location of a bug using the stacktrace.

The compromise the team is likely willing to move forward with is to remove the stacktraces from the error level, unless the level is debug or trace, in which case the current behavior would persist. As debug or trace are the requested levels for bug reports and troubleshooting this generally would satisfy both our support needs and the essence of the request.

[joshka]

Thanks for the explanation.

[james-d-elliott]

Changes to the effect I described here.