Merge pull request #321 from manicmaniac/log-http

manicmaniac · web-flow · commit f0732c1176eb · 2021-06-10T14:30:53.000+09:00
Log HTTP
diff --git a/ApolloDeveloperKit.xcodeproj/project.pbxproj b/ApolloDeveloperKit.xcodeproj/project.pbxproj
@@ -53,6 +53,7 @@
 		5B53B14D24F9BFA000A946D4 /* Schema+EventStreamMessageConvertible.swift in Sources */ = {isa = PBXBuildFile; fileRef = 5B53B14C24F9BFA000A946D4 /* Schema+EventStreamMessageConvertible.swift */; };
 		5B53B15324F9C33E00A946D4 /* EventStreamMessageTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 5B53B15224F9C33E00A946D4 /* EventStreamMessageTests.swift */; };
 		5B53B15524FBFD0D00A946D4 /* ApolloDeveloperKitTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 5B53B15424FBFD0D00A946D4 /* ApolloDeveloperKitTests.swift */; };
+		5B57D689267004F600269F68 /* Logger.swift in Sources */ = {isa = PBXBuildFile; fileRef = 5B57D688267004F600269F68 /* Logger.swift */; };
 		5B5EBB9C2510E31400D0D025 /* InterfaceAddress.swift in Sources */ = {isa = PBXBuildFile; fileRef = 5B5EBB9B2510E31400D0D025 /* InterfaceAddress.swift */; };
 		5B5EBB9E2510E32B00D0D025 /* InterfaceAddressIterator.swift in Sources */ = {isa = PBXBuildFile; fileRef = 5B5EBB9D2510E32B00D0D025 /* InterfaceAddressIterator.swift */; };
 		5B60660122D64790002A2013 /* ApolloDebugServerTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 5B60660022D64790002A2013 /* ApolloDebugServerTests.swift */; };
@@ -224,6 +225,7 @@
 		5B53B14C24F9BFA000A946D4 /* Schema+EventStreamMessageConvertible.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = "Schema+EventStreamMessageConvertible.swift"; sourceTree = "<group>"; };
 		5B53B15224F9C33E00A946D4 /* EventStreamMessageTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = EventStreamMessageTests.swift; sourceTree = "<group>"; };
 		5B53B15424FBFD0D00A946D4 /* ApolloDeveloperKitTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = ApolloDeveloperKitTests.swift; sourceTree = "<group>"; };
+		5B57D688267004F600269F68 /* Logger.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = Logger.swift; sourceTree = "<group>"; };
 		5B5EBB9B2510E31400D0D025 /* InterfaceAddress.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = InterfaceAddress.swift; sourceTree = "<group>"; };
 		5B5EBB9D2510E32B00D0D025 /* InterfaceAddressIterator.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = InterfaceAddressIterator.swift; sourceTree = "<group>"; };
 		5B60660022D64790002A2013 /* ApolloDebugServerTests.swift */ = {isa = PBXFileReference; explicitFileType = sourcecode.swift; path = ApolloDebugServerTests.swift; sourceTree = "<group>"; };
@@ -452,6 +454,7 @@
 				5B53B14924F9BB7C00A946D4 /* EventStreamMessage */,
 				5B67343D22BFF02200A09DF7 /* GraphQL */,
 				5B7C983622BABA06000F4D7B /* JSON */,
+				5B57D687267004E500269F68 /* Logger */,
 				5BBA27942662FCFE00EBE185 /* Network */,
 				5B53B15024F9C27A00A946D4 /* Schema */,
 				5B7C983422BAB9E3000F4D7B /* Store */,
@@ -568,6 +571,14 @@
 			path = EventStreamMessage;
 			sourceTree = "<group>";
 		};
+		5B57D687267004E500269F68 /* Logger */ = {
+			isa = PBXGroup;
+			children = (
+				5B57D688267004F600269F68 /* Logger.swift */,
+			);
+			path = Logger;
+			sourceTree = "<group>";
+		};
 		5B67343D22BFF02200A09DF7 /* GraphQL */ = {
 			isa = PBXGroup;
 			children = (
@@ -880,6 +891,7 @@
 				5B4F46092370A7D70039495A /* FileDescriptorDuplicator.swift in Sources */,
 				5B05890A24EB5DC60071DB57 /* HTTPRequestMessage.swift in Sources */,
 				5B207730236E098700817E45 /* HTTPChunkedResponse.swift in Sources */,
+				5B57D689267004F600269F68 /* Logger.swift in Sources */,
 				5B53B14B24F9BB9700A946D4 /* EventStreamMessage.swift in Sources */,
 				5B2F84F122B4378B0025A211 /* ApolloDebugServer.swift in Sources */,
 				5B3A83A722C87FA2002B4FFB /* HTTPServer.swift in Sources */,
diff --git a/ApolloDeveloperKit.xcodeproj/xcshareddata/xcschemes/ApolloDeveloperKit.xcscheme b/ApolloDeveloperKit.xcodeproj/xcshareddata/xcschemes/ApolloDeveloperKit.xcscheme
@@ -81,6 +81,13 @@
             ReferencedContainer = "container:ApolloDeveloperKit.xcodeproj">
          </BuildableReference>
       </MacroExpansion>
+      <EnvironmentVariables>
+         <EnvironmentVariable
+            key = "APOLLO_DEVELOPER_KIT_DIAGNOSTICS"
+            value = "1"
+            isEnabled = "YES">
+         </EnvironmentVariable>
+      </EnvironmentVariables>
    </LaunchAction>
    <ProfileAction
       buildConfiguration = "Release"
diff --git a/Sources/ApolloDeveloperKit/ApolloDebugServer.swift b/Sources/ApolloDeveloperKit/ApolloDebugServer.swift
@@ -178,7 +178,9 @@ public class ApolloDebugServer {
             let message = String(data: notification.data, encoding: .utf8) else { return }
         let event = ConsoleEvent(data: message, type: eventType(for: notification.destination))
         let chunk = HTTPChunkedResponse(event: event)
-        eventStreams.broadcast(data: chunk.data)
+        Logger.withSuppressing(.http) {
+            eventStreams.broadcast(data: chunk.data)
+        }
     }
 }
 
@@ -258,6 +260,7 @@ extension ApolloDebugServer: HTTPServerDelegate {
             let jsonObject = try JSONSerialization.jsonObject(with: body)
             let operationJSONObject = try Operation(jsonValue: jsonObject)
             let operation = AnyGraphQLOperation(operation: operationJSONObject)
+            Logger.apollo?.info("Sending operation \(operation.operationName).")
             _ = networkTransport.send(operation: operation, cachePolicy: .fetchIgnoringCacheCompletely, contextIdentifier: nil, callbackQueue: .global()) { [weak self] result in
                 guard let self = self else { return }
                 do {
@@ -269,18 +272,22 @@ extension ApolloDebugServer: HTTPServerDelegate {
                         options = []
                     }
                     let body = try JSONSerialization.data(withJSONObject: graphQLResult.jsonValue, options: options)
+                    Logger.apollo?.info("Received result \(body) for operation \(operation.operationName)")
                     context.respondJSONData(body)
                 } catch ResponseCodeInterceptor.ResponseCodeError.invalidResponseCode(let response?, let rawData) {
+                    Logger.apollo?.info("Received error response \(response.statusCode) for operation \(operation.operationName)")
                     let stream = context.respond(proxying: response)
                     if let rawData = rawData {
                         stream.write(data: rawData)
                     }
                     stream.close()
                 } catch let error {
+                    Logger.apollo?.info("Received error \(error) for operation \(operation.operationName)")
                     self.respondBadRequest(context, jsError: ErrorLike(error: error))
                 }
             }
         } catch let error {
+            Logger.apollo?.info("Failed to parse GraphQL request \(error).")
             respondBadRequest(context, jsError: ErrorLike(error: error))
         }
     }
diff --git a/Sources/ApolloDeveloperKit/Logger/Logger.swift b/Sources/ApolloDeveloperKit/Logger/Logger.swift
@@ -0,0 +1,90 @@
+//
+//  Logger.swift
+//  ApolloDeveloperKit
+//
+//  Created by Ryosuke Ito on 6/9/21.
+//  Copyright © 2021 Ryosuke Ito. All rights reserved.
+//
+
+import Foundation
+import asl
+import os.log
+
+final class Logger {
+    static let apollo = Logger(category: "apollo")
+    static let http = Logger(category: "http")
+
+    private let logger: Any
+    private var isSuppressed = false
+
+    init?(category: String) {
+        guard ProcessInfo().environment.keys.contains("APOLLO_DEVELOPER_KIT_DIAGNOSTICS") else {
+            return nil
+        }
+        let subsystem = "com.github.manicmaniac.ApolloDeveloperKit"
+        if #available(macOS 10.12, iOS 10, *) {
+            logger = OSLog(subsystem: subsystem, category: category)
+        } else {
+            logger = asl_new(UInt32(ASL_TYPE_MSG))!
+        }
+    }
+
+    static func withSuppressing(_ logger: Logger?, body: () throws -> Void) rethrows {
+        try withExtendedLifetime(logger) {
+            logger?.isSuppressed = true
+            defer { logger?.isSuppressed = false }
+            try body()
+        }
+    }
+
+    func debug(_ message: @autoclosure () -> String) {
+        log(level: .debug, message())
+    }
+
+    func info(_ message: @autoclosure () -> String) {
+        log(level: .info, message())
+    }
+
+    func error(_ message: @autoclosure () -> String) {
+        log(level: .error, message())
+    }
+
+    private func log(level: LogLevel, _ message: String) {
+        if isSuppressed { return }
+        if #available(macOS 10.12, iOS 10, *) {
+            os_log("%@", log: logger as! OSLog, type: level.osLogType, message)
+        } else {
+            asl_vlog((logger as! asl_object_t), nil, level.aslLogLevel, "%@", getVaList([message]))
+        }
+    }
+
+}
+
+private enum LogLevel {
+    case debug
+    case info
+    case error
+
+    @available(macOS 10.12, iOS 10, *)
+    var osLogType: OSLogType {
+        switch self {
+        case .debug:
+            return .debug
+        case .info:
+            return .info
+        case .error:
+            return .error
+        }
+    }
+
+    var aslLogLevel: Int32 {
+        switch self {
+        case .debug:
+            return ASL_LEVEL_DEBUG
+        case .info:
+            return ASL_LEVEL_INFO
+        case .error:
+            return ASL_LEVEL_ERR
+        }
+    }
+}
diff --git a/Sources/ApolloDeveloperKit/WebServer/HTTPConnection.swift b/Sources/ApolloDeveloperKit/WebServer/HTTPConnection.swift
@@ -27,11 +27,13 @@ final class HTTPConnection {
     weak var delegate: HTTPConnectionDelegate?
     private let incomingRequest = HTTPRequestMessage()
     private let socket: Socket
+    private let address: Data
     private var eventQueue = ArraySlice<Event>()
     private let eventQueueLock = NSLock()
 
-    init(httpVersion: String, nativeHandle: CFSocketNativeHandle) throws {
+    init(httpVersion: String, nativeHandle: CFSocketNativeHandle, address: Data) throws {
         self.httpVersion = httpVersion
+        self.address = address
         let socket = try Socket(nativeHandle: nativeHandle, callbackTypes: [.dataCallBack, .writeCallBack])
         self.socket = socket
         socket.isNonBlocking = true
@@ -44,6 +46,33 @@ final class HTTPConnection {
     }
 }
 
+// MARK: CustomStringConvertible
+
+extension HTTPConnection: CustomStringConvertible {
+    var description: String {
+        let address = self.address.withUnsafeBytes { $0.load(as: sockaddr.self) }
+        let numericAddress: String
+        let port: in_port_t
+        switch Int32(address.sa_family) {
+        case AF_INET:
+            var buffer = [CChar](repeating: 0, count: Int(INET_ADDRSTRLEN))
+            var address = self.address.withUnsafeBytes { $0.load(as: sockaddr_in.self) }
+            inet_ntop(AF_INET, &address.sin_addr, &buffer, socklen_t(buffer.count))
+            numericAddress = String(cString: buffer)
+            port = address.sin_port.bigEndian
+        case AF_INET6:
+            var buffer = [CChar](repeating: 0, count: Int(INET6_ADDRSTRLEN))
+            var address = self.address.withUnsafeBytes { $0.load(as: sockaddr_in6.self) }
+            inet_ntop(AF_INET6, &address.sin6_addr, &buffer, socklen_t(buffer.count))
+            numericAddress = String(cString: buffer)
+            port = address.sin6_port.bigEndian
+        default:
+            fatalError("Unexpected address family: \(address.sa_family).")
+        }
+        return "HTTP connection to (\(numericAddress):\(port))"
+    }
+}
+
 // MARK: HTTPOutputStream
 
 extension HTTPConnection: HTTPOutputStream {
diff --git a/Sources/ApolloDeveloperKit/WebServer/HTTPOutputStreamSet.swift b/Sources/ApolloDeveloperKit/WebServer/HTTPOutputStreamSet.swift
@@ -19,6 +19,7 @@ final class HTTPOutputStreamSet: Sequence {
         for stream in self {
             stream.write(data: data)
         }
+        Logger.http?.debug("Broadcasted \(data) to \(hashTable.count) streams.")
     }
 
     func makeIterator() -> AnyIterator<HTTPOutputStream> {
diff --git a/Sources/ApolloDeveloperKit/WebServer/HTTPRequestContext.swift b/Sources/ApolloDeveloperKit/WebServer/HTTPRequestContext.swift
@@ -56,6 +56,7 @@ final class HTTPRequestContext {
     }
 
     func respond(statusCode: Int) -> HTTPOutputStream {
+        defer { Logger.http?.info("Send status \(statusCode) in \(connection).") }
         let message = HTTPResponseMessage(statusCode: statusCode, statusDescription: nil, httpVersion: version)
         for (headerField, value) in responseHeaderFields {
             message.setValue(value, for: headerField)
diff --git a/Sources/ApolloDeveloperKit/WebServer/HTTPServer.swift b/Sources/ApolloDeveloperKit/WebServer/HTTPServer.swift
@@ -106,6 +106,7 @@ final class HTTPServer {
             socket.schedule(in: .current, forMode: .default)
             return socket
         }
+        Logger.http?.info("Server has been started at port \(port).")
     }
 
     /**
@@ -144,6 +145,7 @@ final class HTTPServer {
         }
         socket?.invalidate()
         socket = nil
+        Logger.http?.info("Server has been stopped.")
     }
 
     private var port: UInt16? {
@@ -226,23 +228,26 @@ extension HTTPServer: HTTPConnectionDelegate {
     func httpConnection(_ connection: HTTPConnection, didReceive request: HTTPRequestMessage) {
         let context = HTTPRequestContext(request: request, connection: connection)
         delegate?.server(self, didReceiveRequest: context)
+        Logger.http?.info("Received \(request.requestMethod ?? "unknown method") \(request.requestURL?.absoluteString ?? "unknown URL") in \(connection).")
     }
 
     func httpConnectionWillClose(_ connection: HTTPConnection) {
         connections.remove(connection)
+        Logger.http?.info("Closed \(connection).")
     }
 
     func httpConnection(_ connection: HTTPConnection, didFailToHandle request: HTTPRequestMessage, error: Error) {
         let context = HTTPRequestContext(request: request, connection: connection)
         delegate?.server(self, didFailToHandle: context, error: error)
+        Logger.http?.info("Failed to handle \(request.requestMethod ?? "unknown method") \(request.requestURL?.absoluteString ?? "unknown URL") in \(connection).")
     }
 }
 
 // MARK: SocketDelegate
 
 extension HTTPServer: SocketDelegate {
     func socket(_ socket: Socket, didAccept nativeHandle: CFSocketNativeHandle, address: Data) {
-        guard let connection = try? HTTPConnection(httpVersion: kCFHTTPVersion1_1 as String, nativeHandle: nativeHandle) else {
+        guard let connection = try? HTTPConnection(httpVersion: kCFHTTPVersion1_1 as String, nativeHandle: nativeHandle, address: address) else {
             return
         }
         connection.delegate = self
diff --git a/Tests/ApolloDeveloperKitTests/ApolloDebugServerTests.swift b/Tests/ApolloDeveloperKitTests/ApolloDebugServerTests.swift

Original file line number	Diff line number	Diff line change
`@@ -178,7 +178,9 @@ public class ApolloDebugServer {`
`178`	`178`	`let message = String(data: notification.data, encoding: .utf8) else { return }`
`179`	`179`	`let event = ConsoleEvent(data: message, type: eventType(for: notification.destination))`
`180`	`180`	`let chunk = HTTPChunkedResponse(event: event)`
`181`		`- eventStreams.broadcast(data: chunk.data)`
	`181`	`+ Logger.withSuppressing(.http) {`
	`182`	`+ eventStreams.broadcast(data: chunk.data)`
	`183`	`+ }`
`182`	`184`	`}`
`183`	`185`	`}`
`184`	`186`
`@@ -258,6 +260,7 @@ extension ApolloDebugServer: HTTPServerDelegate {`
`258`	`260`	`let jsonObject = try JSONSerialization.jsonObject(with: body)`
`259`	`261`	`let operationJSONObject = try Operation(jsonValue: jsonObject)`
`260`	`262`	`let operation = AnyGraphQLOperation(operation: operationJSONObject)`
	`263`	`+ Logger.apollo?.info("Sending operation \(operation.operationName).")`
`261`	`264`	`_ = networkTransport.send(operation: operation, cachePolicy: .fetchIgnoringCacheCompletely, contextIdentifier: nil, callbackQueue: .global()) { [weak self] result in`
`262`	`265`	`guard let self = self else { return }`
`263`	`266`	`do {`
`@@ -269,18 +272,22 @@ extension ApolloDebugServer: HTTPServerDelegate {`
`269`	`272`	`options = []`
`270`	`273`	`}`
`271`	`274`	`let body = try JSONSerialization.data(withJSONObject: graphQLResult.jsonValue, options: options)`
	`275`	`+ Logger.apollo?.info("Received result \(body) for operation \(operation.operationName)")`
`272`	`276`	`context.respondJSONData(body)`
`273`	`277`	`} catch ResponseCodeInterceptor.ResponseCodeError.invalidResponseCode(let response?, let rawData) {`
	`278`	`+ Logger.apollo?.info("Received error response \(response.statusCode) for operation \(operation.operationName)")`
`274`	`279`	`let stream = context.respond(proxying: response)`
`275`	`280`	`if let rawData = rawData {`
`276`	`281`	`stream.write(data: rawData)`
`277`	`282`	`}`
`278`	`283`	`stream.close()`
`279`	`284`	`} catch let error {`
	`285`	`+ Logger.apollo?.info("Received error \(error) for operation \(operation.operationName)")`
`280`	`286`	`self.respondBadRequest(context, jsError: ErrorLike(error: error))`
`281`	`287`	`}`
`282`	`288`	`}`
`283`	`289`	`} catch let error {`
	`290`	`+ Logger.apollo?.info("Failed to parse GraphQL request \(error).")`
`284`	`291`	`respondBadRequest(context, jsError: ErrorLike(error: error))`
`285`	`292`	`}`
`286`	`293`	`}`
Original file line number	Diff line number	Diff line change
`@@ -19,6 +19,7 @@ final class HTTPOutputStreamSet: Sequence {`
`19`	`19`	`for stream in self {`
`20`	`20`	`stream.write(data: data)`
`21`	`21`	`}`
	`22`	`+ Logger.http?.debug("Broadcasted \(data) to \(hashTable.count) streams.")`
`22`	`23`	`}`
`23`	`24`
`24`	`25`	`func makeIterator() -> AnyIterator<HTTPOutputStream> {`
Original file line number	Diff line number	Diff line change
`@@ -56,6 +56,7 @@ final class HTTPRequestContext {`
`56`	`56`	`}`
`57`	`57`
`58`	`58`	`func respond(statusCode: Int) -> HTTPOutputStream {`
	`59`	`+ defer { Logger.http?.info("Send status \(statusCode) in \(connection).") }`
`59`	`60`	`let message = HTTPResponseMessage(statusCode: statusCode, statusDescription: nil, httpVersion: version)`
`60`	`61`	`for (headerField, value) in responseHeaderFields {`
`61`	`62`	`message.setValue(value, for: headerField)`
Original file line number	Diff line number	Diff line change
`@@ -106,6 +106,7 @@ final class HTTPServer {`
`106`	`106`	`socket.schedule(in: .current, forMode: .default)`
`107`	`107`	`return socket`
`108`	`108`	`}`
	`109`	`+ Logger.http?.info("Server has been started at port \(port).")`
`109`	`110`	`}`
`110`	`111`
`111`	`112`	`/**`
`@@ -144,6 +145,7 @@ final class HTTPServer {`
`144`	`145`	`}`
`145`	`146`	`socket?.invalidate()`
`146`	`147`	`socket = nil`
	`148`	`+ Logger.http?.info("Server has been stopped.")`
`147`	`149`	`}`
`148`	`150`
`149`	`151`	`private var port: UInt16? {`
`@@ -226,23 +228,26 @@ extension HTTPServer: HTTPConnectionDelegate {`
`226`	`228`	`func httpConnection(_ connection: HTTPConnection, didReceive request: HTTPRequestMessage) {`
`227`	`229`	`let context = HTTPRequestContext(request: request, connection: connection)`
`228`	`230`	`delegate?.server(self, didReceiveRequest: context)`
	`231`	`+ Logger.http?.info("Received \(request.requestMethod ?? "unknown method") \(request.requestURL?.absoluteString ?? "unknown URL") in \(connection).")`
`229`	`232`	`}`
`230`	`233`
`231`	`234`	`func httpConnectionWillClose(_ connection: HTTPConnection) {`
`232`	`235`	`connections.remove(connection)`
	`236`	`+ Logger.http?.info("Closed \(connection).")`
`233`	`237`	`}`
`234`	`238`
`235`	`239`	`func httpConnection(_ connection: HTTPConnection, didFailToHandle request: HTTPRequestMessage, error: Error) {`
`236`	`240`	`let context = HTTPRequestContext(request: request, connection: connection)`
`237`	`241`	`delegate?.server(self, didFailToHandle: context, error: error)`
	`242`	`+ Logger.http?.info("Failed to handle \(request.requestMethod ?? "unknown method") \(request.requestURL?.absoluteString ?? "unknown URL") in \(connection).")`
`238`	`243`	`}`
`239`	`244`	`}`
`240`	`245`
`241`	`246`	`// MARK: SocketDelegate`
`242`	`247`
`243`	`248`	`extension HTTPServer: SocketDelegate {`
`244`	`249`	`func socket(_ socket: Socket, didAccept nativeHandle: CFSocketNativeHandle, address: Data) {`
`245`		`- guard let connection = try? HTTPConnection(httpVersion: kCFHTTPVersion1_1 as String, nativeHandle: nativeHandle) else {`
	`250`	`+ guard let connection = try? HTTPConnection(httpVersion: kCFHTTPVersion1_1 as String, nativeHandle: nativeHandle, address: address) else {`
`246`	`251`	`return`
`247`	`252`	`}`
`248`	`253`	`connection.delegate = self`