diff --git a/Sources/WebPush/WebPushManager.swift b/Sources/WebPush/WebPushManager.swift index 78066f5..5911be0 100644 --- a/Sources/WebPush/WebPushManager.swift +++ b/Sources/WebPush/WebPushManager.swift @@ -36,8 +36,8 @@ public actor WebPushManager: Sendable { /// This is currently set to 3,993 plaintext bytes. See the discussion for ``maximumEncryptedPayloadSize`` for more information. public static let maximumMessageSize = maximumEncryptedPayloadSize - 103 - /// The internal logger to use when reporting status. - nonisolated let logger: Logger + /// The internal logger to use when reporting misconfiguration and background activity. + nonisolated let backgroundActivityLogger: Logger /// The internal executor to use when delivering messages. var executor: Executor @@ -57,15 +57,15 @@ public actor WebPushManager: Sendable { /// - Note: On debug builds, this initializer will assert if VAPID authorization header expiration times are inconsistently set. /// - Parameters: /// - vapidConfiguration: The VAPID configuration to use when identifying the application server. - /// - logger: An optional parent logger to use for status updates. + /// - backgroundActivityLogger: The logger to use for misconfiguration and background activity. By default, a print logger will be used, and if set to `nil`, a no-op logger will be used in release builds. When running in a server environment, your shared logger should be used instead giving you full control of logging and metadata. /// - eventLoopGroupProvider: The event loop to use for the internal HTTP client. public init( vapidConfiguration: VAPID.Configuration, // TODO: Add networkConfiguration for proxy, number of simultaneous pushes, etc… - logger: Logger? = nil, + backgroundActivityLogger: Logger? = .defaultWebPushPrintLogger, eventLoopGroupProvider: NIOEventLoopGroupProvider = .shared(.singletonMultiThreadedEventLoopGroup) ) { - let logger = Logger(label: "WebPushManager", factory: { logger?.handler ?? PrintLogHandler(label: $0, metadataProvider: $1) }) + let backgroundActivityLogger = backgroundActivityLogger ?? .defaultWebPushNoOpLogger var httpClientConfiguration = HTTPClient.Configuration() httpClientConfiguration.httpVersion = .automatic @@ -75,18 +75,18 @@ public actor WebPushManager: Sendable { .httpClient(HTTPClient( eventLoopGroupProvider: .shared(eventLoopGroup), configuration: httpClientConfiguration, - backgroundActivityLogger: logger + backgroundActivityLogger: backgroundActivityLogger )) case .createNew: .httpClient(HTTPClient( configuration: httpClientConfiguration, - backgroundActivityLogger: logger + backgroundActivityLogger: backgroundActivityLogger )) } self.init( vapidConfiguration: vapidConfiguration, - logger: logger, + backgroundActivityLogger: backgroundActivityLogger, executor: executor ) } @@ -96,21 +96,31 @@ public actor WebPushManager: Sendable { /// Note that this must be called before ``run()`` is called or the client's syncShutdown won't be called. /// - Parameters: /// - vapidConfiguration: The VAPID configuration to use when identifying the application server. - /// - logger: The logger to use for status updates. + /// - backgroundActivityLogger: The logger to use for misconfiguration and background activity. /// - executor: The executor to use when sending push messages. package init( vapidConfiguration: VAPID.Configuration, // TODO: Add networkConfiguration for proxy, number of simultaneous pushes, etc… - logger: Logger, + backgroundActivityLogger: Logger, executor: Executor ) { + var backgroundActivityLogger = backgroundActivityLogger + backgroundActivityLogger[metadataKey: "vapidConfiguration"] = [ + "contactInformation" : "\(vapidConfiguration.contactInformation)", + "primaryKey" : "\(vapidConfiguration.primaryKey?.id.description ?? "nil")", + "keys" : .array(vapidConfiguration.keys.map { .string($0.id.description) }), + "deprecatedKeys" : .array((vapidConfiguration.deprecatedKeys ?? []).map { .string($0.id.description) }), + "validityDuration" : "\(vapidConfiguration.validityDuration)", + "expirationDuration" : "\(vapidConfiguration.expirationDuration)", + ] + if vapidConfiguration.validityDuration > vapidConfiguration.expirationDuration { assertionFailure("The validity duration must be earlier than the expiration duration since it represents when the VAPID Authorization token will be refreshed ahead of it expiring.") - logger.error("The validity duration must be earlier than the expiration duration since it represents when the VAPID Authorization token will be refreshed ahead of it expiring. Run your application server with the same configuration in debug mode to catch this.") + backgroundActivityLogger.error("The validity duration must be earlier than the expiration duration since it represents when the VAPID Authorization token will be refreshed ahead of it expiring. Run your application server with the same configuration in debug mode to catch this.") } if vapidConfiguration.expirationDuration > .hours(24) { assertionFailure("The expiration duration must be less than 24 hours or else push endpoints will reject messages sent to them.") - logger.error("The expiration duration must be less than 24 hours or else push endpoints will reject messages sent to them. Run your application server with the same configuration in debug mode to catch this.") + backgroundActivityLogger.error("The expiration duration must be less than 24 hours or else push endpoints will reject messages sent to them. Run your application server with the same configuration in debug mode to catch this.") } precondition(!vapidConfiguration.keys.isEmpty, "VAPID.Configuration must have keys specified. Please report this as a bug with reproduction steps if encountered: https://github.com/mochidev/swift-webpush/issues.") @@ -120,7 +130,7 @@ public actor WebPushManager: Sendable { allKeys.map { ($0.id, $0) }, uniquingKeysWith: { first, _ in first } ) - self.logger = logger + self.backgroundActivityLogger = backgroundActivityLogger self.executor = executor } @@ -241,20 +251,25 @@ public actor WebPushManager: Sendable { /// - subscriber: The subscriber to send the push message to. /// - expiration: The expiration of the push message, after wich delivery will no longer be attempted. /// - urgency: The urgency of the delivery of the push message. + /// - logger: The logger to use for status updates. If not provided, the background activity logger will be used instead. When running in a server environment, your contextual logger should be used instead giving you full control of logging and metadata. public func send( data message: some DataProtocol, to subscriber: some SubscriberProtocol, expiration: Expiration = .recommendedMaximum, - urgency: Urgency = .high + urgency: Urgency = .high, + logger: Logger? = nil ) async throws { switch executor { case .httpClient(let httpClient): + var logger = logger ?? backgroundActivityLogger + logger[metadataKey: "message"] = "\(message)" try await execute( httpClient: httpClient, data: message, subscriber: subscriber, expiration: expiration, - urgency: urgency + urgency: urgency, + logger: logger ) case .handler(let handler): try await handler(.data(Data(message)), Subscriber(subscriber), expiration, urgency) @@ -270,17 +285,20 @@ public actor WebPushManager: Sendable { /// - subscriber: The subscriber to send the push message to. /// - expiration: The expiration of the push message, after wich delivery will no longer be attempted. /// - urgency: The urgency of the delivery of the push message. + /// - logger: The logger to use for status updates. If not provided, the background activity logger will be used instead. When running in a server environment, your contextual logger should be used instead giving you full control of logging and metadata. public func send( string message: some StringProtocol, to subscriber: some SubscriberProtocol, expiration: Expiration = .recommendedMaximum, - urgency: Urgency = .high + urgency: Urgency = .high, + logger: Logger? = nil ) async throws { try await routeMessage( message: .string(String(message)), to: subscriber, expiration: expiration, - urgency: urgency + urgency: urgency, + logger: logger ?? backgroundActivityLogger ) } @@ -293,17 +311,20 @@ public actor WebPushManager: Sendable { /// - subscriber: The subscriber to send the push message to. /// - expiration: The expiration of the push message, after wich delivery will no longer be attempted. /// - urgency: The urgency of the delivery of the push message. + /// - logger: The logger to use for status updates. If not provided, the background activity logger will be used instead. When running in a server environment, your contextual logger should be used instead giving you full control of logging and metadata. public func send( json message: some Encodable&Sendable, to subscriber: some SubscriberProtocol, expiration: Expiration = .recommendedMaximum, - urgency: Urgency = .high + urgency: Urgency = .high, + logger: Logger? = nil ) async throws { try await routeMessage( message: .json(message), to: subscriber, expiration: expiration, - urgency: urgency + urgency: urgency, + logger: logger ?? backgroundActivityLogger ) } @@ -313,12 +334,16 @@ public actor WebPushManager: Sendable { /// - subscriber: The subscriber to sign the message against. /// - expiration: The expiration of the message. /// - urgency: The urgency of the message. + /// - logger: The logger to use for status updates. func routeMessage( message: _Message, to subscriber: some SubscriberProtocol, expiration: Expiration, - urgency: Urgency + urgency: Urgency, + logger: Logger ) async throws { + var logger = logger + logger[metadataKey: "message"] = "\(message)" switch executor { case .httpClient(let httpClient): try await execute( @@ -326,7 +351,8 @@ public actor WebPushManager: Sendable { data: message.data, subscriber: subscriber, expiration: expiration, - urgency: urgency + urgency: urgency, + logger: logger ) case .handler(let handler): try await handler( @@ -345,18 +371,28 @@ public actor WebPushManager: Sendable { /// - subscriber: The subscriber to sign the message against. /// - expiration: The expiration of the message. /// - urgency: The urgency of the message. + /// - logger: The logger to use for status updates. func execute( httpClient: some HTTPClientProtocol, data message: some DataProtocol, subscriber: some SubscriberProtocol, expiration: Expiration, - urgency: Urgency + urgency: Urgency, + logger: Logger ) async throws { - guard let signingKey = vapidKeyLookup[subscriber.vapidKeyID] - else { - logger.warning("A key was not found for this subscriber.", metadata: [ - "vapidKeyID": "\(subscriber.vapidKeyID)" - ]) + var logger = logger + logger[metadataKey: "subscriber"] = [ + "vapidKeyID" : "\(subscriber.vapidKeyID)", + "endpoint" : "\(subscriber.endpoint)", + ] + logger[metadataKey: "expiration"] = "\(expiration)" + logger[metadataKey: "urgency"] = "\(urgency)" + logger[metadataKey: "origin"] = "\(subscriber.endpoint.origin)" + logger[metadataKey: "messageSize"] = "\(message.count)" + logger.trace("Sending notification") + + guard let signingKey = vapidKeyLookup[subscriber.vapidKeyID] else { + logger.warning("A key was not found for this subscriber.") throw VAPID.ConfigurationError.matchingKeyNotFound } @@ -366,15 +402,20 @@ public actor WebPushManager: Sendable { /// Perform key exchange between the user agent's public key and our private key, deriving a shared secret. let userAgent = subscriber.userAgentKeyMaterial - guard let sharedSecret = try? applicationServerECDHPrivateKey.sharedSecretFromKeyAgreement(with: userAgent.publicKey) - else { throw BadSubscriberError() } + let sharedSecret: SharedSecret + do { + sharedSecret = try applicationServerECDHPrivateKey.sharedSecretFromKeyAgreement(with: userAgent.publicKey) + } catch { + logger.debug("A shared secret could not be derived from the subscriber's public key and the newly-generated private key.", metadata: ["error" : "\(error)"]) + throw BadSubscriberError() + } /// Generate a 16-byte salt. var salt: [UInt8] = Array(repeating: 0, count: 16) for index in salt.indices { salt[index] = .random(in: .min ... .max) } if message.count > Self.maximumMessageSize { - logger.warning("Push message is longer than the maximum guarantee made by the spec: \(Self.maximumMessageSize) bytes. Sending this message may fail, and its size will be leaked despite being encrypted. Please consider sending less data to keep your communications secure.", metadata: ["message": "\(message)"]) + logger.warning("Push message is longer than the maximum guarantee made by the spec: \(Self.maximumMessageSize) bytes. Sending this message may fail, and its size will be leaked despite being encrypted. Please consider sending less data to keep your communications secure.") } /// Prepare the payload by padding it so the final message is 4KB. @@ -424,9 +465,9 @@ public actor WebPushManager: Sendable { let requestContent = contentCodingHeader + encryptedRecord.ciphertext + encryptedRecord.tag if expiration < Expiration.dropIfUndeliverable { - logger.error("The message expiration must be greater than or equal to \(Expiration.dropIfUndeliverable) seconds.", metadata: ["expiration": "\(expiration)"]) + logger.error("The message expiration must be greater than or equal to \(Expiration.dropIfUndeliverable) seconds.") } else if expiration > Expiration.recommendedMaximum { - logger.warning("The message expiration should be less than \(Expiration.recommendedMaximum) seconds.", metadata: ["expiration": "\(expiration)"]) + logger.warning("The message expiration should be less than \(Expiration.recommendedMaximum) seconds.") } /// Add the VAPID authorization and corrent content encoding and type. @@ -441,6 +482,9 @@ public actor WebPushManager: Sendable { /// Send the request to the push endpoint. let response = try await httpClient.execute(request, deadline: .distantFuture, logger: logger) + logger[metadataKey: "response"] = "\(response)" + logger[metadataKey: "statusCode"] = "\(response.status)" + logger.trace("Sent notification") /// Check the response and determine if the subscription should be removed from our records, or if the notification should just be skipped. switch response.status { @@ -450,28 +494,28 @@ public actor WebPushManager: Sendable { // TODO: 429 too many requests, 500 internal server error, 503 server shutting down - check config and perform a retry after a delay? default: throw HTTPError(response: response) } - logger.trace("Sent \(message) notification to \(subscriber): \(response)") + logger.trace("Successfully sent notification") } } extension WebPushManager: Service { public func run() async throws { - logger.info("Starting up WebPushManager") + backgroundActivityLogger.debug("Starting up WebPushManager") guard !didShutdown else { assertionFailure("The manager was already shutdown and cannot be started.") - logger.error("The manager was already shutdown and cannot be started. Run your application server in debug mode to catch this.") + backgroundActivityLogger.error("The manager was already shutdown and cannot be started. Run your application server in debug mode to catch this.") return } try await withTaskCancellationOrGracefulShutdownHandler { try await gracefulShutdown() - } onCancelOrGracefulShutdown: { [logger, executor] in - logger.info("Shutting down WebPushManager") + } onCancelOrGracefulShutdown: { [backgroundActivityLogger, executor] in + backgroundActivityLogger.debug("Shutting down WebPushManager") do { if case let .httpClient(httpClient) = executor { try httpClient.syncShutdown() } } catch { - logger.error("Graceful Shutdown Failed", metadata: [ + backgroundActivityLogger.error("Graceful Shutdown Failed", metadata: [ "error": "\(error)" ]) } @@ -631,13 +675,13 @@ extension WebPushManager.Urgency: Codable { extension WebPushManager { /// An internal type representing a push message, accessible when using ``/WebPushTesting``. - public enum _Message: Sendable { + public enum _Message: Sendable, CustomStringConvertible { /// A message originally sent via ``WebPushManager/send(data:to:expiration:urgency:)`` case data(Data) /// A message originally sent via ``WebPushManager/send(string:to:expiration:urgency:)`` case string(String) - /// A message originally sent via ``WebPushManager/send(json:to:expiration:urgency:) + /// A message originally sent via ``WebPushManager/send(json:to:expiration:urgency:)`` case json(any Encodable&Sendable) /// The message, encoded as data. @@ -656,6 +700,17 @@ extension WebPushManager { } } } + + public var description: String { + switch self { + case .data(let data): + return ".data(\(data.base64URLEncodedString()))" + case .string(let string): + return ".string(\(string))" + case .json(let json): + return ".json(\(json))" + } + } } /// An internal type representing the executor for a push message. @@ -676,3 +731,15 @@ extension WebPushManager { ) async throws -> Void) } } + +extension Logger { + /// A logger that will print logs by default. + /// + /// This is used by ``WebPushManager/init(vapidConfiguration:logger:eventLoopGroupProvider:)`` to provide a default logger when one is not provided. + public static let defaultWebPushPrintLogger = Logger(label: "WebPushManager", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }) + + /// A logger that will not print anything by default. + /// + /// This is used by ``WebPushManager/init(vapidConfiguration:logger:eventLoopGroupProvider:)`` to provide a default logger when nil is specified. + public static let defaultWebPushNoOpLogger = Logger(label: "WebPushManager", factory: { _, _ in SwiftLogNoOpLogHandler() }) +} diff --git a/Sources/WebPushTesting/WebPushManager+Testing.swift b/Sources/WebPushTesting/WebPushManager+Testing.swift index 0e99a17..1cd6979 100644 --- a/Sources/WebPushTesting/WebPushManager+Testing.swift +++ b/Sources/WebPushTesting/WebPushManager+Testing.swift @@ -25,7 +25,7 @@ extension WebPushManager { public static func makeMockedManager( vapidConfiguration: VAPID.Configuration = .mockedConfiguration, // TODO: Add networkConfiguration for proxy, number of simultaneous pushes, etc… - logger: Logger? = nil, + backgroundActivityLogger: Logger? = .defaultWebPushPrintLogger, messageHandler: @escaping @Sendable ( _ message: Message, _ subscriber: Subscriber, @@ -33,11 +33,11 @@ extension WebPushManager { _ urgency: Urgency ) async throws -> Void ) -> WebPushManager { - let logger = Logger(label: "MockWebPushManager", factory: { logger?.handler ?? PrintLogHandler(label: $0, metadataProvider: $1) }) + let backgroundActivityLogger = backgroundActivityLogger ?? .defaultWebPushNoOpLogger return WebPushManager( vapidConfiguration: vapidConfiguration, - logger: logger, + backgroundActivityLogger: backgroundActivityLogger, executor: .handler(messageHandler) ) } diff --git a/Tests/WebPushTests/WebPushManagerTests.swift b/Tests/WebPushTests/WebPushManagerTests.swift index 7c3b0c2..abc1af2 100644 --- a/Tests/WebPushTests/WebPushManagerTests.swift +++ b/Tests/WebPushTests/WebPushManagerTests.swift @@ -33,7 +33,7 @@ struct WebPushManagerTests { let logger = Logger(label: "ServiceLogger", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }) let manager = WebPushManager( vapidConfiguration: .makeTesting(), - logger: logger + backgroundActivityLogger: logger ) await withThrowingTaskGroup(of: Void.self) { group in group.addTask { @@ -217,7 +217,7 @@ struct WebPushManagerTests { let manager = WebPushManager( vapidConfiguration: vapidConfiguration, - logger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), + backgroundActivityLogger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), executor: .httpClient(MockHTTPClient({ request in try validateAuthotizationHeader( request: request, @@ -264,7 +264,7 @@ struct WebPushManagerTests { let manager = WebPushManager( vapidConfiguration: vapidConfiguration, - logger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), + backgroundActivityLogger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), executor: .httpClient(MockHTTPClient({ request in try validateAuthotizationHeader( request: request, @@ -311,7 +311,7 @@ struct WebPushManagerTests { let manager = WebPushManager( vapidConfiguration: vapidConfiguration, - logger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), + backgroundActivityLogger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), executor: .httpClient(MockHTTPClient({ request in try validateAuthotizationHeader( request: request, @@ -358,7 +358,7 @@ struct WebPushManagerTests { let manager = WebPushManager( vapidConfiguration: vapidConfiguration, - logger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), + backgroundActivityLogger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), executor: .httpClient(MockHTTPClient({ request in requestWasMade() return HTTPClientResponse(status: .notFound) @@ -387,7 +387,7 @@ struct WebPushManagerTests { let manager = WebPushManager( vapidConfiguration: vapidConfiguration, - logger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), + backgroundActivityLogger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), executor: .httpClient(MockHTTPClient({ request in requestWasMade() return HTTPClientResponse(status: .gone) @@ -416,7 +416,7 @@ struct WebPushManagerTests { let manager = WebPushManager( vapidConfiguration: vapidConfiguration, - logger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), + backgroundActivityLogger: Logger(label: "WebPushManagerTests", factory: { PrintLogHandler(label: $0, metadataProvider: $1) }), executor: .httpClient(MockHTTPClient({ request in requestWasMade() return HTTPClientResponse(status: .internalServerError)