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.

Sign up for GitHub

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

Jump to bottom

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
26e14ce
Change logging levels of report function
madsodgaard Apr 7, 2021
845add2
Change default logLevel of DebuggableError to warning
madsodgaard Apr 7, 2021
f5d4c7a
Merge main into branch
madsodgaard Apr 7, 2021
91c72db
Change to warning for storage and dotenv
madsodgaard Apr 7, 2021
5fb7c29
Fix compiler error
madsodgaard Apr 7, 2021
4bf2b33
Merge branch 'main' into mads-log-levels
0xTim Apr 8, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
2 changes: 1 addition & 1 deletion Sources/Vapor/Application.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -140,7 +140,7 @@ public final class Application {
do {
try self.eventLoopGroup.syncShutdownGracefully()
} catch {
self.logger.error("Shutting down EventLoopGroup failed: \(error)")
self.logger.warning("Shutting down EventLoopGroup failed: \(error)")
}
}

Expand Down
4 changes: 2 additions & 2 deletions Sources/Vapor/Deprecations/DotEnvFile+load.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,7 @@ extension DotEnvFile {
do {
try threadPool.syncShutdownGracefully()
} catch {
logger.error("Shutting down threadPool failed: \(error)")
logger.warning("Shutting down threadPool failed: \(error)")
}
}
let fileio = NonBlockingFileIO(threadPool: threadPool)
Expand Down Expand Up @@ -55,7 +55,7 @@ extension DotEnvFile {
do {
try threadPool.syncShutdownGracefully()
} catch {
logger.error("Shutting down threadPool failed: \(error)")
logger.warning("Shutting down threadPool failed: \(error)")
}
}
let fileio = NonBlockingFileIO(threadPool: threadPool)
Expand Down
2 changes: 1 addition & 1 deletion Sources/Vapor/Error/DebuggableError.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -106,7 +106,7 @@ extension DebuggableError {
}

public var logLevel: Logger.Level {
.error
.warning
}
}

Expand Down
61 changes: 10 additions & 51 deletions Sources/Vapor/Logging/Logger+Report.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,20 +24,26 @@ extension Logger {
case let abort as AbortError:
reason = abort.reason
source = nil
level = .error

if (500...599).contains(abort.status.code) {
level = .error
} else {
level = .warning
}
Comment on lines +27 to +32
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.

case let localized as LocalizedError:
reason = localized.localizedDescription
source = nil
level = .error
level = .warning
case let convertible as CustomStringConvertible:
reason = convertible.description
source = nil
level = .error
level = .warning
default:
reason = "\(error)"
source = nil
level = .error
level = .warning
}

self.log(
level: level,
.init(stringLiteral: reason),
Expand All @@ -47,50 +53,3 @@ extension Logger {
)
}
}

struct MyError: DebuggableError {
enum Value {
case userNotLoggedIn
case invalidEmail(String)
}

var identifier: String {
switch self.value {
case .userNotLoggedIn:
return "userNotLoggedIn"
case .invalidEmail:
return "invalidEmail"
}
}

var reason: String {
switch self.value {
case .userNotLoggedIn:
return "User is not logged in."
case .invalidEmail(let email):
return "Email address is not valid: \(email)."
}
}

var value: Value
var source: ErrorSource?
var stackTrace: StackTrace?

init(
_ value: Value,
file: String = #file,
function: String = #function,
line: UInt = #line,
column: UInt = #column,
stackTrace: StackTrace? = .capture()
) {
self.value = value
self.source = .init(
file: file,
function: function,
line: line,
column: column
)
self.stackTrace = stackTrace
}
}
4 changes: 2 additions & 2 deletions Sources/Vapor/Utilities/DotEnv.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,7 @@ public struct DotEnvFile {
do {
try eventLoopGroup.syncShutdownGracefully()
} catch {
logger.error("Shutting down EventLoopGroup failed: \(error)")
logger.warning("Shutting down EventLoopGroup failed: \(error)")
}
}
}
Expand Down Expand Up @@ -109,7 +109,7 @@ public struct DotEnvFile {
do {
try eventLoopGroup.syncShutdownGracefully()
} catch {
logger.error("Shutting down EventLoopGroup failed: \(error)")
logger.warning("Shutting down EventLoopGroup failed: \(error)")
}
}
}
Expand Down
2 changes: 1 addition & 1 deletion Sources/Vapor/Utilities/Storage.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@ public struct Storage {
do {
try self.onShutdown?(self.value)
} catch {
logger.error("Could not shutdown \(T.self): \(error)")
logger.warning("Could not shutdown \(T.self): \(error)")
}
}
}
Expand Down