Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Use separate log levels for relevant error types #863

Merged
merged 9 commits into from
Apr 1, 2024

Conversation

sarayourfriend
Copy link
Contributor

@sarayourfriend sarayourfriend commented Mar 29, 2024

Potentially fixes #514 (depending on interpretation of what would resolve that issue)

I wrote a little in the issue of my exploration of this problem. Basically, I think the issue comes down to a matter of opinion about what should and shouldn't be logged at the "warning" level.

In my experience, authentication errors are not worth logging at all in production environments, precisely because they happen so frequently with credentials stuffing or bots crawling for exposed WordPress/Drupal/Django/whatever admin pages. It is trivial to detect these based on request logs and response status code volumes, and even from pigallery2's own access logs, if enabled (though, those are debug-level so are a different question).

I admit that is an opinion, but for well configured servers, these logs will either unnecessarily frighten people who don't have experience running application services in production environments or fill up your log files and potentially cost you additional money in your log querying/transport solution if you have one. I run applications at a warn level in production, and wouldn't expect that to include anything other than predicted-but-unusual/notable/potentially-bad cases (contrasted to errors which would be unhandled edge cases/bugs).

To reflect that, this PR:

  1. Defines a log level for each ErrorCodes value, or at least defines specific ones for several error types and defaults to warn. This has an added benefit of actually increasing the log level for what may be true error-level stuff, though that's definitely something that needs input. I'm not familiar with all the features of pigallery2 as I only use the simplest ones myself, and haven't run into most of these edge cases to say whether they're definitely errors or warnings. This is easy to change though, just change which set of cases any particular error code is grouped into.
  2. Expands LoggerArgs to accept simple objects and Error instances. These get forwarded to console.log in Logger.log in the end, which is able to serialise such arguments and print them nicely. It looks like sometimes the console functions are used directly instead of Logger ones to leverage it's nice printing of objects, but the differences between Logger.error and console.error make it difficult to quickly update everywhere to use Logger. That could be done more carefully in a separate PR if desired.
  3. Updates the RenderingMWs::renderError function to use the log-level defined for the rendering error's error-code. This is the effective change which lowers authentication errors to debug level logs, removing them from production logs under the default logging configuration.

I also found some dead code in the rendering middleware's error logging routine and removed it. I'll add a comment explaining why it is dead code to clarify.

Also, I want to clarify again that this is just my interpretation of what the appropriate logging levels are for these kinds of authentication errors, based on my experience developing and running several different internet-facing applications in production. Happy to be wrong about this for pigallery2! Not all applications have the same logging needs.

I look forward to any comments on the PR 🙂 I really like pigallery2 and think it's a great application, and am excited to contribute any way I can.

@@ -11,7 +11,8 @@ if (forcedDebug === true) {
);
}

export type LoggerArgs = (string | number | (() => string))
// Match `console.log` inputs
export type LoggerArgs = Parameters<Console["log"]>[0]
Copy link
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is not exactly true. There was a recent PR that made it possible to use string returning functions as parameter, so the args do not equal with console.log.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

True, console.log's args are all any, so it happens to work. I could change this either to explicitly any, or try to expand the types of the original LoggerArgs to accept things like the ErrorDTO. Adding | any to the existing type reduces it to just any in the end anyway.

The underlying implementation of the Logger functions remains the same, so passing a string-returning function will continue to work exactly as before... there's just no indication in the types that that's an expected input 🤔

A type something like string | number | (() => string) | object might capture everything correctly and still indicate in the type that a string-returning function is expected. What do you think?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, trying this locally, | object widens the type to essentially any. () => 123 is accepted now, when previously it wouldn't have been. Incidentally, it does work, because there's nothing in the Logger.log function that expects the return type of the functions to be a string specifically, it just needs to be something console.log will accept as an argument (which is any).

A narrower type like Record<any, unknown> doesn't allow for the Error objects, but adding a further | Error keeps the stronger argument type than any while still opening up passing the error objects in RenderingMWs.

export type LoggerArgs = (string | number | (() => string) | Record<any, unknown> | Error);
const t: LoggerArgs = () => 123  // => not assignable
export type LoggerArgs = (string | number | (() => string) | object);
const t: LoggerArgs = () => 123 // => allowed, `LoggerArgs` is basically `any`

It feels a little fiddly to do it this way, considering console.log takes any anyway, but it's nice to have the types stay the same and reduce the potential scope of changes.

src/backend/model/database/GalleryManager.ts Outdated Show resolved Hide resolved
src/backend/model/extension/ExtensionConfigWrapper.ts Outdated Show resolved Hide resolved
src/backend/model/messenger/StdoutMessenger.ts Outdated Show resolved Hide resolved
@bpatrik
Copy link
Owner

bpatrik commented Mar 30, 2024

Thank you very much for your contribution.

I don't mind if login or other scraper errors are supressed . Moving /api /pgapi and updating nginx path helped a lot to reduce these attempts.

@sarayourfriend
Copy link
Contributor Author

Thanks for the revievw @bpatrik. I mentioned in a couple of the review comments, but to clarify, I'll go ahead and make the following changes:

  1. I'll set back LoggerArgs to the original type with | object added, to allow passing error objects for to leveral console.log's printing.
  2. I'll undo the broader logging "clean up" and stick to just the log-level changes. That'll cut the scope and make this easier to review. Sorry for the noise there!

These log calls either duplicated the generic error renderer logging or neighbouring log calls
This unifies logging across the backend to always use the Logger class,
always only logs to stdout (rather than an inconsistent mix of stdout
and stderr, depending on whether console.error was used), and removes
logging where two log events happened for the same message

For example, this pattern:

```js
Logger.error("Whoops, something went wrong:")
console.error(err)
```

That causes two separate log events, and depending on the log transport
used, could cause relevant log messages to get split across multiple
events and therefore be harder (usually just more tedious) to connect
and debug in production environments.
This unifies logging across the backend to always use the Logger class,
always only logs to stdout (rather than an inconsistent mix of stdout
and stderr, depending on whether console.error was used), and removes
logging where two log events happened for the same message

For example, this pattern:

```js
Logger.error("Whoops, something went wrong:")
console.error(err)
```

That causes two separate log events, and depending on the log transport
used, could cause relevant log messages to get split across multiple
events and therefore be harder (usually just more tedious) to connect
and debug in production environments.
This reverts commit a57a717717a676555b4e28d5746828477c2f9811.
@sarayourfriend sarayourfriend changed the title Unify backend logging and separate log levels for relevant error types Use separate log levels for relevant error types Mar 30, 2024
@bpatrik
Copy link
Owner

bpatrik commented Apr 1, 2024

Thank you!

This change looks good to me.

@bpatrik bpatrik merged commit 6c53aca into bpatrik:master Apr 1, 2024
4 of 8 checks passed
@sarayourfriend sarayourfriend deleted the fix/unify-logging branch April 1, 2024 21:18
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

'Invalid CSRF token'
2 participants