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

Change Vapor's logging levels for errors. #2598

Merged
merged 6 commits into from
Apr 8, 2021
Merged

Change Vapor's logging levels for errors. #2598

merged 6 commits into from
Apr 8, 2021

Conversation

madsodgaard
Copy link
Contributor

@madsodgaard madsodgaard commented Apr 7, 2021

⚠️ If you're relying on Vapor logging errors at the .error level you should review this release to ensure that you don't start losing errors. ⚠️

As per the log level guidelines from the SSWG this changes many of the errors logged in Vapor to use the .warning level instead of .error. (#2598)

Fixes #2586.

@madsodgaard madsodgaard requested a review from 0xTim April 7, 2021 06:55
@0xTim
Copy link
Member

0xTim commented Apr 7, 2021

Thanks for this! There are a couple of other places in vapor/vapor that we should change in this PR as well. All the DotEnvFile+load.swift errors (both the deprecated and undeprecated ones) should only log at warning. I think the HTTPServer logs are fine at error since they only occur at the start and end and point to serious errors. Storage errors should be warnings as well

Comment on lines +27 to +32

if (500...599).contains(abort.status.code) {
level = .error
} else {
level = .warning
}
Copy link
Member

Choose a reason for hiding this comment

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

I think this should probably be logged as a warning for all cases. There are several cases where an internal server error may occur (such as a dropped connection to a database) that may automatically be retried and be successful. Anything logged at an error level should basically be considered something bad enough to wake people up. Since we can't work in any kind of flag for this, or configuration to choose which level, we should default to .warning. Anyone throwing Abort(.internalServerError) can alway add their own logger.error messages if they need.

However, this is a fairly big breaking change so I think we should throw this out to the community

Copy link

Choose a reason for hiding this comment

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

Yeah your wording is right @0xTim I think.

For the author or the PR, here is some guidance we're working on: swift-server/guides#19

Logging an "error" is very very very dramatic, and frameworks should avoid doing so if possible, especially "on each request"; A warning would be better.

Copy link
Member

Choose a reason for hiding this comment

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

How does this change permeate into end-projects? Is it only applicable if users are using the ErrorMiddleware or does it happen no matter what? I agree that it should be a warning for all cases, I'm just trying to wrap my head around how that changes output in projects specifically.

Copy link
Member

Choose a reason for hiding this comment

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

No it could affect anyone using logger.report. ErrorMiddleware does and most people won't but it could affect them if they've copied the ErrorMiddleware

Copy link
Member

Choose a reason for hiding this comment

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

Got it, that makes sense. I am +1 then!

Copy link
Contributor

Choose a reason for hiding this comment

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

I think this should probably be logged as a warning for all cases. There are several cases where an internal server error may occur (such as a dropped connection to a database) that may automatically be retried and be successful. Anything logged at an error level should basically be considered something bad enough to wake people up. Since we can't work in any kind of flag for this, or configuration to choose which level, we should default to .warning. Anyone throwing Abort(.internalServerError) can alway add their own logger.error messages if they need.

However, this is a fairly big breaking change so I think we should throw this out to the community

I would not say I am in disagreement here, but would like to add more to the discussion as to why perhaps it's worth logging internal errors at the error level.

To continue on the dropped connection example, one dropped connection from time to time is no big deal, but if you drop database connections often this could be the sign of a more serious, potentially developing issue. Now if we are talking about common 400es such as a validation or not found error, a rising amount of these should be of no concern and correlate with the amount of traffic you get. On the other hand, your internal error rate should remain constant regardless of traffic.

Large applications usually rely on time series based log analysis so that developers can be alerted when say, 10 errors, reported at the error level or higher, happen within a 5 minutes timeframe. If all non curated request errors are logged at the warning level, this type of analysis will be more difficult and require a precise, more vapor focused, integration on the part of the devops side.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

After some more time to think about it, I am for logging AbortError as warning. AbortError is really a user-facing error, which is used to format an error into a HTTP response that the client understands, not necessarily the developer. I think @0xTim is right in that the developer should really be logging any actual internal errors themselves using error besides throwing or returning an AbortError.

Copy link
Contributor

Choose a reason for hiding this comment

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

Ya I see it now, @0xTim is right. I did not see before that this was in the context of logging AbortError specifically. My bad.

@0xTim 0xTim added the semver-patch Internal changes only label Apr 8, 2021
@0xTim 0xTim changed the title Change Vapor's default logging levels for errors. Change Vapor's logging levels for errors. Apr 8, 2021
Copy link
Member

@0xTim 0xTim left a comment

Choose a reason for hiding this comment

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

LGTM thanks!

@0xTim 0xTim merged commit 2567c05 into main Apr 8, 2021
@0xTim 0xTim deleted the mads-log-levels branch April 8, 2021 15:26
@VaporBot
Copy link
Contributor

VaporBot commented Apr 8, 2021

These changes are now available in 4.43.1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
semver-patch Internal changes only
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Review Vapor's log level usage
6 participants