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

Better Logging #37

Merged
merged 6 commits into from
Dec 19, 2024
Merged

Better Logging #37

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
0f61040
Updated main logger logic to use a fallback logger rather than a chil…
dimitribouniol Dec 19, 2024
128c2a3
Fixed the logging level of some logs to one appropriate for libraries
dimitribouniol Dec 19, 2024
0414978
Renamed WebPushManager's logger to backgroundActivityLogger to match …
dimitribouniol Dec 19, 2024
831c443
Added loggers to the send methods
dimitribouniol Dec 19, 2024
8f20fad
Fixed missing backticks on documentation
dimitribouniol Dec 19, 2024
3d1fddf
Added more comprehensive logging metadata
dimitribouniol Dec 19, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
147 changes: 107 additions & 40 deletions Sources/WebPush/WebPushManager.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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
)
}
Expand All @@ -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.")

Expand All @@ -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
}

Expand Down Expand Up @@ -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)
Expand All @@ -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
)
}

Expand All @@ -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
)
}

Expand All @@ -313,20 +334,25 @@ 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(
httpClient: httpClient,
data: message.data,
subscriber: subscriber,
expiration: expiration,
urgency: urgency
urgency: urgency,
logger: logger
)
case .handler(let handler):
try await handler(
Expand All @@ -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
}

Expand All @@ -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.
Expand Down Expand Up @@ -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.
Expand All @@ -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 {
Expand All @@ -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)"
])
}
Expand Down Expand Up @@ -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.
Expand All @@ -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.
Expand All @@ -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() })
}
Loading
Loading