From 0f61040b0f1e0308d39a82a46d171b6eaa168ee2 Mon Sep 17 00:00:00 2001 From: Dimitri Bouniol Date: Thu, 19 Dec 2024 02:07:59 -0800 Subject: [PATCH 1/6] Updated main logger logic to use a fallback logger rather than a child logger --- Sources/WebPush/WebPushManager.swift | 20 ++++++++++++++++---- 1 file changed, 16 insertions(+), 4 deletions(-) diff --git a/Sources/WebPush/WebPushManager.swift b/Sources/WebPush/WebPushManager.swift index 78066f5..c62d687 100644 --- a/Sources/WebPush/WebPushManager.swift +++ b/Sources/WebPush/WebPushManager.swift @@ -36,7 +36,7 @@ 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. + /// The internal logger to use when reporting misconfiguration and background activity. nonisolated let logger: Logger /// The internal executor to use when delivering messages. @@ -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. + /// - logger: 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. /// - 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, + logger: Logger? = .defaultWebPushPrintLogger, eventLoopGroupProvider: NIOEventLoopGroupProvider = .shared(.singletonMultiThreadedEventLoopGroup) ) { - let logger = Logger(label: "WebPushManager", factory: { logger?.handler ?? PrintLogHandler(label: $0, metadataProvider: $1) }) + let logger = logger ?? .defaultWebPushNoOpLogger var httpClientConfiguration = HTTPClient.Configuration() httpClientConfiguration.httpVersion = .automatic @@ -676,3 +676,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() }) +} From 128c2a3fc2f2e35f7df70c327d884c8f1325a747 Mon Sep 17 00:00:00 2001 From: Dimitri Bouniol Date: Thu, 19 Dec 2024 02:09:36 -0800 Subject: [PATCH 2/6] Fixed the logging level of some logs to one appropriate for libraries --- Sources/WebPush/WebPushManager.swift | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/Sources/WebPush/WebPushManager.swift b/Sources/WebPush/WebPushManager.swift index c62d687..c61283a 100644 --- a/Sources/WebPush/WebPushManager.swift +++ b/Sources/WebPush/WebPushManager.swift @@ -456,7 +456,7 @@ public actor WebPushManager: Sendable { extension WebPushManager: Service { public func run() async throws { - logger.info("Starting up WebPushManager") + logger.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.") @@ -465,7 +465,7 @@ extension WebPushManager: Service { try await withTaskCancellationOrGracefulShutdownHandler { try await gracefulShutdown() } onCancelOrGracefulShutdown: { [logger, executor] in - logger.info("Shutting down WebPushManager") + logger.debug("Shutting down WebPushManager") do { if case let .httpClient(httpClient) = executor { try httpClient.syncShutdown() From 04149786a709ebecb333dda2eaa65b05b457b7b2 Mon Sep 17 00:00:00 2001 From: Dimitri Bouniol Date: Thu, 19 Dec 2024 02:20:13 -0800 Subject: [PATCH 3/6] Renamed WebPushManager's logger to backgroundActivityLogger to match AsyncHTTPClient's usage --- Sources/WebPush/WebPushManager.swift | 46 +++++++++---------- .../WebPushManager+Testing.swift | 6 +-- Tests/WebPushTests/WebPushManagerTests.swift | 14 +++--- 3 files changed, 33 insertions(+), 33 deletions(-) diff --git a/Sources/WebPush/WebPushManager.swift b/Sources/WebPush/WebPushManager.swift index c61283a..93d3cbe 100644 --- a/Sources/WebPush/WebPushManager.swift +++ b/Sources/WebPush/WebPushManager.swift @@ -37,7 +37,7 @@ public actor WebPushManager: Sendable { public static let maximumMessageSize = maximumEncryptedPayloadSize - 103 /// The internal logger to use when reporting misconfiguration and background activity. - nonisolated let logger: Logger + 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: 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. + /// - 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. /// - 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? = .defaultWebPushPrintLogger, + backgroundActivityLogger: Logger? = .defaultWebPushPrintLogger, eventLoopGroupProvider: NIOEventLoopGroupProvider = .shared(.singletonMultiThreadedEventLoopGroup) ) { - let logger = logger ?? .defaultWebPushNoOpLogger + 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,21 @@ 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 ) { 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 +120,7 @@ public actor WebPushManager: Sendable { allKeys.map { ($0.id, $0) }, uniquingKeysWith: { first, _ in first } ) - self.logger = logger + self.backgroundActivityLogger = backgroundActivityLogger self.executor = executor } @@ -354,7 +354,7 @@ public actor WebPushManager: Sendable { ) async throws { guard let signingKey = vapidKeyLookup[subscriber.vapidKeyID] else { - logger.warning("A key was not found for this subscriber.", metadata: [ + backgroundActivityLogger.warning("A key was not found for this subscriber.", metadata: [ "vapidKeyID": "\(subscriber.vapidKeyID)" ]) throw VAPID.ConfigurationError.matchingKeyNotFound @@ -374,7 +374,7 @@ public actor WebPushManager: Sendable { 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)"]) + backgroundActivityLogger.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)"]) } /// Prepare the payload by padding it so the final message is 4KB. @@ -424,9 +424,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)"]) + backgroundActivityLogger.error("The message expiration must be greater than or equal to \(Expiration.dropIfUndeliverable) seconds.", metadata: ["expiration": "\(expiration)"]) } else if expiration > Expiration.recommendedMaximum { - logger.warning("The message expiration should be less than \(Expiration.recommendedMaximum) seconds.", metadata: ["expiration": "\(expiration)"]) + backgroundActivityLogger.warning("The message expiration should be less than \(Expiration.recommendedMaximum) seconds.", metadata: ["expiration": "\(expiration)"]) } /// Add the VAPID authorization and corrent content encoding and type. @@ -440,7 +440,7 @@ public actor WebPushManager: Sendable { request.body = .bytes(ByteBuffer(bytes: requestContent)) /// Send the request to the push endpoint. - let response = try await httpClient.execute(request, deadline: .distantFuture, logger: logger) + let response = try await httpClient.execute(request, deadline: .distantFuture, logger: backgroundActivityLogger) /// 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 +450,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)") + backgroundActivityLogger.trace("Sent \(message) notification to \(subscriber): \(response)") } } extension WebPushManager: Service { public func run() async throws { - logger.debug("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.debug("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)" ]) } 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) From 831c443f34fb68930cebb95c87159b7e3a0e337e Mon Sep 17 00:00:00 2001 From: Dimitri Bouniol Date: Thu, 19 Dec 2024 02:26:50 -0800 Subject: [PATCH 4/6] Added loggers to the send methods --- Sources/WebPush/WebPushManager.swift | 46 ++++++++++++++++++---------- 1 file changed, 30 insertions(+), 16 deletions(-) diff --git a/Sources/WebPush/WebPushManager.swift b/Sources/WebPush/WebPushManager.swift index 93d3cbe..824b1e5 100644 --- a/Sources/WebPush/WebPushManager.swift +++ b/Sources/WebPush/WebPushManager.swift @@ -57,7 +57,7 @@ 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. - /// - 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. + /// - 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, @@ -241,11 +241,13 @@ 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): @@ -254,7 +256,8 @@ public actor WebPushManager: Sendable { data: message, subscriber: subscriber, expiration: expiration, - urgency: urgency + urgency: urgency, + logger: logger ?? backgroundActivityLogger ) case .handler(let handler): try await handler(.data(Data(message)), Subscriber(subscriber), expiration, urgency) @@ -270,17 +273,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 +299,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,11 +322,13 @@ 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 { switch executor { case .httpClient(let httpClient): @@ -326,7 +337,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,16 +357,18 @@ 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 { - backgroundActivityLogger.warning("A key was not found for this subscriber.", metadata: [ + logger.warning("A key was not found for this subscriber.", metadata: [ "vapidKeyID": "\(subscriber.vapidKeyID)" ]) throw VAPID.ConfigurationError.matchingKeyNotFound @@ -374,7 +388,7 @@ public actor WebPushManager: Sendable { for index in salt.indices { salt[index] = .random(in: .min ... .max) } if message.count > Self.maximumMessageSize { - backgroundActivityLogger.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.", metadata: ["message": "\(message)"]) } /// Prepare the payload by padding it so the final message is 4KB. @@ -424,9 +438,9 @@ public actor WebPushManager: Sendable { let requestContent = contentCodingHeader + encryptedRecord.ciphertext + encryptedRecord.tag if expiration < Expiration.dropIfUndeliverable { - backgroundActivityLogger.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.", metadata: ["expiration": "\(expiration)"]) } else if expiration > Expiration.recommendedMaximum { - backgroundActivityLogger.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.", metadata: ["expiration": "\(expiration)"]) } /// Add the VAPID authorization and corrent content encoding and type. @@ -440,7 +454,7 @@ public actor WebPushManager: Sendable { request.body = .bytes(ByteBuffer(bytes: requestContent)) /// Send the request to the push endpoint. - let response = try await httpClient.execute(request, deadline: .distantFuture, logger: backgroundActivityLogger) + let response = try await httpClient.execute(request, deadline: .distantFuture, logger: logger) /// 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,7 +464,7 @@ 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) } - backgroundActivityLogger.trace("Sent \(message) notification to \(subscriber): \(response)") + logger.trace("Sent \(message) notification to \(subscriber): \(response)") } } From 8f20fadeb5d36f6096cb08de6c40b5f136c9da30 Mon Sep 17 00:00:00 2001 From: Dimitri Bouniol Date: Thu, 19 Dec 2024 03:05:03 -0800 Subject: [PATCH 5/6] Fixed missing backticks on documentation --- Sources/WebPush/WebPushManager.swift | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Sources/WebPush/WebPushManager.swift b/Sources/WebPush/WebPushManager.swift index 824b1e5..ae475c1 100644 --- a/Sources/WebPush/WebPushManager.swift +++ b/Sources/WebPush/WebPushManager.swift @@ -651,7 +651,7 @@ extension WebPushManager { /// 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. From 3d1fddfe0b3e2a5b424c40859eb2b0b305dce243 Mon Sep 17 00:00:00 2001 From: Dimitri Bouniol Date: Thu, 19 Dec 2024 03:05:16 -0800 Subject: [PATCH 6/6] Added more comprehensive logging metadata --- Sources/WebPush/WebPushManager.swift | 67 ++++++++++++++++++++++------ 1 file changed, 54 insertions(+), 13 deletions(-) diff --git a/Sources/WebPush/WebPushManager.swift b/Sources/WebPush/WebPushManager.swift index ae475c1..5911be0 100644 --- a/Sources/WebPush/WebPushManager.swift +++ b/Sources/WebPush/WebPushManager.swift @@ -104,6 +104,16 @@ public actor WebPushManager: Sendable { 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.") 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.") @@ -251,13 +261,15 @@ public actor WebPushManager: Sendable { ) 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, - logger: logger ?? backgroundActivityLogger + logger: logger ) case .handler(let handler): try await handler(.data(Data(message)), Subscriber(subscriber), expiration, urgency) @@ -330,6 +342,8 @@ public actor WebPushManager: Sendable { urgency: Urgency, logger: Logger ) async throws { + var logger = logger + logger[metadataKey: "message"] = "\(message)" switch executor { case .httpClient(let httpClient): try await execute( @@ -366,11 +380,19 @@ public actor WebPushManager: Sendable { 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 } @@ -380,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. @@ -438,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. @@ -455,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 { @@ -464,7 +494,7 @@ 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") } } @@ -645,7 +675,7 @@ 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) @@ -670,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.