Logging improvements (#2412)

* logging improvements

* fix error test expectations

* stacktrace capture

Sources/Development/routes.swift

@@ -208,7 +208,7 @@ public func routes(_ app: Application) throws {
     }
 }
 
-struct TestError: AbortError {
+struct TestError: AbortError, DebuggableError {
     var status: HTTPResponseStatus {
         .internalServerError
     }
@@ -226,7 +226,7 @@ struct TestError: AbortError {
         line: UInt = #line,
         column: UInt = #column,
         range: Range<UInt>? = nil,
-        stackTrace: StackTrace? = .capture()
+        stackTrace: StackTrace? = .capture(skip: 1)
     ) {
         self.source = .init(
             file: file,

Sources/Vapor/Authentication/AuthenticationCache.swift

@@ -36,7 +36,6 @@ extension Request.Authentication {
         where A: Authenticatable
     {
         guard let a = self.get(A.self) else {
-            self.request.logger.error("\(A.self) has not been authorized")
             throw Abort(.unauthorized)
         }
         return a

Sources/Vapor/Authentication/Authenticator.swift

@@ -68,7 +68,6 @@ extension CredentialsAuthenticator {
         do {
             credentials = try request.content.decode(Credentials.self)
         } catch {
-            request.logger.error("Could not decode credentials: \(error)")
             return request.eventLoop.makeSucceededFuture(())
         }
         return self.authenticate(credentials: credentials, for: request)

Sources/Vapor/Error/AbortError.swift

@@ -24,6 +24,11 @@ extension AbortError {
     public var headers: HTTPHeaders {
         [:]
     }
+
+    /// See `AbortError`.
+    public var reason: String {
+        self.status.reasonPhrase
+    }
 }
 
 extension AbortError where Self: DebuggableError {

Sources/Vapor/Error/DebuggableError.swift

@@ -54,6 +54,10 @@ public protocol DebuggableError: LocalizedError, CustomDebugStringConvertible, C
     /// - note: Defaults to an empty array.
     /// Provide a custom implementation to a list of pertinent issues.
     var gitHubIssues: [String] { get }
+
+    /// Which log level this error should report as. 
+    /// Defaults to `.error`.
+    var logLevel: Logger.Level { get }
 }
 
 extension DebuggableError {
@@ -100,6 +104,10 @@ extension DebuggableError {
     public var stackTrace: StackTrace? {
         nil
     }
+
+    public var logLevel: Logger.Level { 
+        .error
+    }
 }
 
 /// MARK: Custom...StringConvertible
@@ -154,34 +162,10 @@ extension DebuggableError {
         var print: [String] = []
 
         switch format {
-        case .long:
-            print.append("\(Self.readableName): \(self.reason)\n- id: \(self.fullIdentifier)")
-        case .short:
+        case .long, .short:
             print.append("\(self.fullIdentifier): \(self.reason)")
         }
 
-        if let source = self.source {
-            switch format {
-            case .long:
-                var help: [String] = []
-                help.append("File: \(source.file)")
-                help.append("- func: \(source.function)")
-                help.append("- line: \(source.line)")
-                help.append("- column: \(source.column)")
-                if let range = source.range {
-                    help.append("- range: \(range)")
-                }
-                print.append(help.joined(separator: "\n"))
-            case .short:
-                var string = "[\(source.file):\(source.line):\(source.column)"
-                if let range = source.range {
-                    string += " (\(range))"
-                }
-                string += "]"
-                print.append(string)
-            }
-        }
-
         switch format {
         case .long:
             if !self.possibleCauses.isEmpty {
@@ -217,7 +201,7 @@ extension DebuggableError {
 
         switch format {
         case .long:
-            return print.joined(separator: "\n\n")
+            return print.joined(separator: "\n") + "\n"
         case .short:
             return print.joined(separator: " ")
         }

Sources/Vapor/HTTP/Server/HTTPServer.swift

@@ -331,7 +331,7 @@ final class HTTPServerErrorHandler: ChannelInboundHandler {
     }
 
     func errorCaught(context: ChannelHandlerContext, error: Error) {
-        self.logger.error("Unhandled HTTP server error: \(error)")
+        self.logger.debug("Unhandled HTTP server error: \(error)")
         context.close(mode: .output, promise: nil)
     }
 }

Sources/Vapor/Logging/Logger+Report.swift

@@ -11,29 +11,35 @@ extension Logger {
     ) {
         let source: ErrorSource?
         let reason: String
+        let level: Logger.Level
         switch error {
         case let debuggable as DebuggableError:
-            if self.logLevel <= .debug {
-                reason = debuggable.debuggableHelp(format: .short)
-            } else {
+            if self.logLevel <= .trace {
                 reason = debuggable.debuggableHelp(format: .long)
+            } else {
+                reason = debuggable.debuggableHelp(format: .short)
             }
             source = debuggable.source
+            level = debuggable.logLevel
         case let abort as AbortError:
             reason = abort.reason
             source = nil
+            level = .error
         case let localized as LocalizedError:
             reason = localized.localizedDescription
             source = nil
+            level = .error
         case let convertible as CustomStringConvertible:
             reason = convertible.description
             source = nil
+            level = .error
         default:
             reason = "\(error)"
             source = nil
+            level = .error
         }
         self.log(
-            level: .error,
+            level: level,
             .init(stringLiteral: reason),
             file: source?.file ?? file,
             function: source?.function ?? function,

Sources/Vapor/Logging/LoggingSystem+Environment.swift

@@ -11,8 +11,8 @@ extension LoggingSystem {
             ?? Environment.process.LOG_LEVEL
             ?? (environment == .production ? .notice: .info)
 
-        // Disable stack traces if log level > debug.
-        if level > .debug {
+        // Disable stack traces if log level > trace.
+        if level > .trace {
             StackTrace.isCaptureEnabled = false
         }
 

Sources/Vapor/Request/Request.swift

@@ -73,7 +73,7 @@ public final class Request: CustomStringConvertible {
 
         func decode<D>(_ decodable: D.Type, using decoder: ContentDecoder) throws -> D where D : Decodable {
             guard let body = self.request.body.data else {
-                self.request.logger.error("Decoding streaming bodies not supported")
+                self.request.logger.debug("Decoding streaming bodies not supported")
                 throw Abort(.unprocessableEntity)
             }
             return try decoder.decode(D.self, from: body, headers: self.request.headers)
@@ -89,7 +89,7 @@ public final class Request: CustomStringConvertible {
 
         func decode<C>(_ content: C.Type, using decoder: ContentDecoder) throws -> C where C : Content {
             guard let body = self.request.body.data else {
-                self.request.logger.error("Decoding streaming bodies not supported")
+                self.request.logger.debug("Decoding streaming bodies not supported")
                 throw Abort(.unprocessableEntity)
             }
             var decoded = try decoder.decode(C.self, from: body, headers: self.request.headers)

Sources/Vapor/Responder/DefaultResponder.swift

@@ -111,6 +111,24 @@ internal struct DefaultResponder: Responder {
 
 private struct NotFoundResponder: Responder {
     func respond(to request: Request) -> EventLoopFuture<Response> {
-        request.eventLoop.makeFailedFuture(Abort(.notFound))
+        request.eventLoop.makeFailedFuture(RouteNotFound())
     }
 }
+
+struct RouteNotFound: Error { }
+
+extension RouteNotFound: AbortError {
+    static var typeIdentifier: String {
+        "Abort"
+    }
+
+    var status: HTTPResponseStatus {
+        .notFound
+    }
+}
+
+extension RouteNotFound: DebuggableError {
+    var logLevel: Logger.Level { 
+        .debug
+    }
+}

Tests/VaporTests/ErrorTests.swift

@@ -4,24 +4,20 @@ import Vapor
 final class ErrorTests: XCTestCase {
     func testPrintable() throws {
         print(FooError.noFoo.debugDescription)
-
         let expectedPrintable = """
-        Foo Error: You do not have a `foo`.
-        - id: FooError.noFoo
-
+        FooError.noFoo: You do not have a `foo`.
         Here are some possible causes:
         - You did not set the flongwaffle.
         - The session ended before a `Foo` could be made.
         - The universe conspires against us all.
         - Computers are hard.
-
         These suggestions could address the issue:
         - You really want to use a `Bar` here.
         - Take up the guitar and move to the beach.
-
         Vapor's documentation talks about this:
         - http://documentation.com/Foo
         - http://documentation.com/foo/noFoo
+
         """
         XCTAssertEqual(FooError.noFoo.debugDescription, expectedPrintable)
     }
@@ -64,8 +60,8 @@ final class ErrorTests: XCTestCase {
         let minimum = MinimumError.alpha
         let description = minimum.debugDescription
         let expectation = """
-        MinimumError: Not enabled
-        - id: MinimumError.alpha
+        MinimumError.alpha: Not enabled
+        
         """
         XCTAssertEqual(description, expectation)
     }