Title: [292232] trunk
Revision
292232
Author
[email protected]
Date
2022-04-01 13:47:45 -0700 (Fri, 01 Apr 2022)

Log Message

Add more push-related logging
https://bugs.webkit.org/show_bug.cgi?id=238591

Reviewed by Youenn Fablet.

Source/WebCore:

Add logging to help diagnose Push API errors. We currently log very little, which is making
it hard for us to diagnose bug reports.

 - Log if PushManager.subscribe fails the user gesture check. We log this to both syslog and
   the developer console. We do the latter to inform developers, and we already log an
   identical message from Notification.requestPermission when that fails in this manner.
 - Log if we can't fire a push event because the service worker registration went away.

* Modules/push-api/PushManager.cpp:
(WebCore::PushManager::subscribe):
* workers/service/server/SWServer.cpp:
(WebCore::SWServer::processPushMessage):

Source/WebKit:

Add logging to help diagnose Push API errors. We currently log very little, which is making
it hard for us to diagnose bug reports.

 - Log when we try to fetch or process push messages in NetworkProcess.
 - Log when we enqueue, start, and finish a PushServiceRequest. This helps catch issues such
   as a queued request never running because the OS push daemon never completing a request.
 - Log if we failed trying to wake up the browser to process a push message.

* NetworkProcess/NetworkProcess.cpp:
(WebKit::NetworkProcess::processPushMessage):
* UIProcess/API/Cocoa/WKWebsiteDataStore.mm:
(-[WKWebsiteDataStore _getPendingPushMessages:]):
(-[WKWebsiteDataStore _processPushMessage:completionHandler:]):
* webpushd/PushService.mm:
(WebPushD::PushService::create):
(WebPushD::PushServiceRequestImpl::fulfill):
(WebPushD::PushServiceRequestImpl::reject):
(WebPushD::SubscribeRequest::startImpl):
(WebPushD::UnsubscribeRequest::startInternal):
(WebPushD::PushService::enqueuePushServiceRequest):
(WebPushD::PushService::incrementSilentPushCount):
(WebPushD::PushService::removeRecordsImpl):
(WebPushD::makeRawPushMessage):
(WebPushD::PushService::didReceivePushMessage):
* webpushd/WebPushDaemon.mm:
(WebPushD::Daemon::injectEncryptedPushMessageForTesting):
(WebPushD::Daemon::notifyClientPushMessageIsAvailable):
(WebPushD::Daemon::getPendingPushMessages):

LayoutTests:

Modify test cases to check for user gesture error console message.

* http/tests/push-api/subscribe-default-permissions-expected.txt:
* http/tests/push-api/subscribe-default-permissions-iframe-same-origin-expected.txt:
* http/tests/push-api/subscribe-deny-permissions-on-prompt-expected.txt:

Modified Paths

Diff

Modified: trunk/LayoutTests/ChangeLog (292231 => 292232)


--- trunk/LayoutTests/ChangeLog	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/LayoutTests/ChangeLog	2022-04-01 20:47:45 UTC (rev 292232)
@@ -1,3 +1,16 @@
+2022-04-01  Ben Nham  <[email protected]>
+
+        Add more push-related logging
+        https://bugs.webkit.org/show_bug.cgi?id=238591
+
+        Reviewed by Youenn Fablet.
+
+        Modify test cases to check for user gesture error console message.
+
+        * http/tests/push-api/subscribe-default-permissions-expected.txt:
+        * http/tests/push-api/subscribe-default-permissions-iframe-same-origin-expected.txt:
+        * http/tests/push-api/subscribe-deny-permissions-on-prompt-expected.txt:
+
 2022-04-01  Matteo Flores  <[email protected]>
 
         REGRESSION(r292072): [ wk1 ] fast/text/install-font-style-recalc.html is a constant text failure

Modified: trunk/LayoutTests/http/tests/push-api/subscribe-default-permissions-expected.txt (292231 => 292232)


--- trunk/LayoutTests/http/tests/push-api/subscribe-default-permissions-expected.txt	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/LayoutTests/http/tests/push-api/subscribe-default-permissions-expected.txt	2022-04-01 20:47:45 UTC (rev 292232)
@@ -1,3 +1,4 @@
+CONSOLE MESSAGE: Push notification prompting can only be done from a user gesture.
 PASS: service worker permissionState was prompt
 PASS: document permissionState was prompt
 PASS: service worker subscribe was error: NotAllowedError

Modified: trunk/LayoutTests/http/tests/push-api/subscribe-default-permissions-iframe-same-origin-expected.txt (292231 => 292232)


--- trunk/LayoutTests/http/tests/push-api/subscribe-default-permissions-iframe-same-origin-expected.txt	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/LayoutTests/http/tests/push-api/subscribe-default-permissions-iframe-same-origin-expected.txt	2022-04-01 20:47:45 UTC (rev 292232)
@@ -1,3 +1,4 @@
+CONSOLE MESSAGE: Push notification prompting can only be done from a user gesture.
 
 PASS: service worker permissionState was prompt
 PASS: document permissionState was prompt

Modified: trunk/LayoutTests/http/tests/push-api/subscribe-deny-permissions-on-prompt-expected.txt (292231 => 292232)


--- trunk/LayoutTests/http/tests/push-api/subscribe-deny-permissions-on-prompt-expected.txt	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/LayoutTests/http/tests/push-api/subscribe-deny-permissions-on-prompt-expected.txt	2022-04-01 20:47:45 UTC (rev 292232)
@@ -1,3 +1,5 @@
+CONSOLE MESSAGE: Push notification prompting can only be done from a user gesture.
+CONSOLE MESSAGE: Push notification prompting can only be done from a user gesture.
 PASS: service worker permissionState was prompt
 PASS: document permissionState was prompt
 PASS: service worker subscribe was error: NotAllowedError

Modified: trunk/Source/WebCore/ChangeLog (292231 => 292232)


--- trunk/Source/WebCore/ChangeLog	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/Source/WebCore/ChangeLog	2022-04-01 20:47:45 UTC (rev 292232)
@@ -1,3 +1,23 @@
+2022-04-01  Ben Nham  <[email protected]>
+
+        Add more push-related logging
+        https://bugs.webkit.org/show_bug.cgi?id=238591
+
+        Reviewed by Youenn Fablet.
+
+        Add logging to help diagnose Push API errors. We currently log very little, which is making
+        it hard for us to diagnose bug reports.
+
+         - Log if PushManager.subscribe fails the user gesture check. We log this to both syslog and
+           the developer console. We do the latter to inform developers, and we already log an
+           identical message from Notification.requestPermission when that fails in this manner.
+         - Log if we can't fire a push event because the service worker registration went away.
+
+        * Modules/push-api/PushManager.cpp:
+        (WebCore::PushManager::subscribe):
+        * workers/service/server/SWServer.cpp:
+        (WebCore::SWServer::processPushMessage):
+
 2022-04-01  Kate Cheney  <[email protected]>
 
         CSP: WASM fails to execute after window.open

Modified: trunk/Source/WebCore/Modules/push-api/PushManager.cpp (292231 => 292232)


--- trunk/Source/WebCore/Modules/push-api/PushManager.cpp	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/Source/WebCore/Modules/push-api/PushManager.cpp	2022-04-01 20:47:45 UTC (rev 292232)
@@ -34,6 +34,7 @@
 #include "Exception.h"
 #include "JSPushPermissionState.h"
 #include "JSPushSubscription.h"
+#include "Logging.h"
 #include "NotificationClient.h"
 #include "PushCrypto.h"
 #include "ScriptExecutionContext.h"
@@ -139,7 +140,12 @@
 
             auto* window = document.frame() ? document.frame()->window() : nullptr;
             if (!window || !window->consumeTransientActivation()) {
-                promise.reject(Exception { NotAllowedError, "Push notification prompting can only be done from a user gesture"_s });
+                Seconds lastActivationDuration = window ? MonotonicTime::now() - window->lastActivationTimestamp() : Seconds::infinity();
+                RELEASE_LOG_ERROR(Push, "Failing PushManager.subscribe call due to failed transient activation check; last activated %.2f sec ago", lastActivationDuration.value());
+
+                auto errorMessage = "Push notification prompting can only be done from a user gesture."_s;
+                document.addConsoleMessage(MessageSource::Security, MessageLevel::Error, errorMessage);
+                promise.reject(Exception { NotAllowedError, errorMessage });
                 return;
             }
 

Modified: trunk/Source/WebCore/workers/service/server/SWServer.cpp (292231 => 292232)


--- trunk/Source/WebCore/workers/service/server/SWServer.cpp	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/Source/WebCore/workers/service/server/SWServer.cpp	2022-04-01 20:47:45 UTC (rev 292232)
@@ -1284,7 +1284,7 @@
         ServiceWorkerRegistrationKey registrationKey { WTFMove(origin), WTFMove(registrationURL) };
         auto registration = m_scopeToRegistrationMap.get(registrationKey);
         if (!registration) {
-            LOG(Push, "Cannot process push messasge: Failed to find SW registration for registration key %s", registrationKey.loggingString().utf8().data());
+            RELEASE_LOG_ERROR(Push, "Cannot process push message: Failed to find SW registration for scope %" PRIVATE_LOG_STRING, registrationKey.scope().string().utf8().data());
             callback(true);
             return;
         }
@@ -1291,7 +1291,7 @@
 
         auto* worker = registration->activeWorker();
         if (!worker) {
-            LOG(Push, "Cannot process push messasge: No active worker for registration key %s", registrationKey.loggingString().utf8().data());
+            RELEASE_LOG_ERROR(Push, "Cannot process push message: No active worker for scope %" PRIVATE_LOG_STRING, registrationKey.scope().string().utf8().data());
             callback(true);
             return;
         }

Modified: trunk/Source/WebKit/ChangeLog (292231 => 292232)


--- trunk/Source/WebKit/ChangeLog	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/Source/WebKit/ChangeLog	2022-04-01 20:47:45 UTC (rev 292232)
@@ -1,3 +1,39 @@
+2022-04-01  Ben Nham  <[email protected]>
+
+        Add more push-related logging
+        https://bugs.webkit.org/show_bug.cgi?id=238591
+
+        Reviewed by Youenn Fablet.
+
+        Add logging to help diagnose Push API errors. We currently log very little, which is making
+        it hard for us to diagnose bug reports.
+
+         - Log when we try to fetch or process push messages in NetworkProcess.
+         - Log when we enqueue, start, and finish a PushServiceRequest. This helps catch issues such
+           as a queued request never running because the OS push daemon never completing a request.
+         - Log if we failed trying to wake up the browser to process a push message.
+
+        * NetworkProcess/NetworkProcess.cpp:
+        (WebKit::NetworkProcess::processPushMessage):
+        * UIProcess/API/Cocoa/WKWebsiteDataStore.mm:
+        (-[WKWebsiteDataStore _getPendingPushMessages:]):
+        (-[WKWebsiteDataStore _processPushMessage:completionHandler:]):
+        * webpushd/PushService.mm:
+        (WebPushD::PushService::create):
+        (WebPushD::PushServiceRequestImpl::fulfill):
+        (WebPushD::PushServiceRequestImpl::reject):
+        (WebPushD::SubscribeRequest::startImpl):
+        (WebPushD::UnsubscribeRequest::startInternal):
+        (WebPushD::PushService::enqueuePushServiceRequest):
+        (WebPushD::PushService::incrementSilentPushCount):
+        (WebPushD::PushService::removeRecordsImpl):
+        (WebPushD::makeRawPushMessage):
+        (WebPushD::PushService::didReceivePushMessage):
+        * webpushd/WebPushDaemon.mm:
+        (WebPushD::Daemon::injectEncryptedPushMessageForTesting):
+        (WebPushD::Daemon::notifyClientPushMessageIsAvailable):
+        (WebPushD::Daemon::getPendingPushMessages):
+
 2022-04-01  Chris Dumez  <[email protected]>
 
         REGRESSION(r292197): 3 TestWebKitAPI.ContentRuleList API tests are constant failures/timeout

Modified: trunk/Source/WebKit/NetworkProcess/NetworkProcess.cpp (292231 => 292232)


--- trunk/Source/WebKit/NetworkProcess/NetworkProcess.cpp	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/Source/WebKit/NetworkProcess/NetworkProcess.cpp	2022-04-01 20:47:45 UTC (rev 292232)
@@ -2319,7 +2319,6 @@
             RELEASE_LOG(Push, "Push message from %" PRIVATE_LOG_STRING " won't be processed since permission is in the prompt state; removing push subscription", origin.toString().utf8().data());
             session->notificationManager().removePushSubscriptionsForOrigin(SecurityOriginData { origin }, [callback = WTFMove(callback)](auto&&) mutable {
                 callback(false);
-                return;
             });
             return;
         }
@@ -2332,10 +2331,12 @@
         }
 
         ASSERT(permissionState == PushPermissionState::Granted);
-        session->ensureSWServer().processPushMessage(WTFMove(pushMessage.pushData), WTFMove(pushMessage.registrationURL), [this, protectedThis = Ref { *this }, sessionID, origin = WTFMove(origin), callback = WTFMove(callback)](bool result) mutable {
+        auto scope = pushMessage.registrationURL.string();
+        session->ensureSWServer().processPushMessage(WTFMove(pushMessage.pushData), WTFMove(pushMessage.registrationURL), [this, protectedThis = Ref { *this }, sessionID, origin = WTFMove(origin), scope = WTFMove(scope), callback = WTFMove(callback)](bool result) mutable {
             NetworkSession* session;
             if (!result && (session = networkSession(sessionID))) {
-                session->notificationManager().incrementSilentPushCount(WTFMove(origin), [callback = WTFMove(callback), result](unsigned) mutable {
+                session->notificationManager().incrementSilentPushCount(WTFMove(origin), [scope = WTFMove(scope), callback = WTFMove(callback), result](unsigned newSilentPushCount) mutable {
+                    RELEASE_LOG_ERROR(Push, "Push message for scope %" PRIVATE_LOG_STRING " not handled properly; new silent push count: %u", scope.utf8().data(), newSilentPushCount);
                     callback(result);
                 });
                 return;

Modified: trunk/Source/WebKit/UIProcess/API/Cocoa/WKWebsiteDataStore.mm (292231 => 292232)


--- trunk/Source/WebKit/UIProcess/API/Cocoa/WKWebsiteDataStore.mm	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/Source/WebKit/UIProcess/API/Cocoa/WKWebsiteDataStore.mm	2022-04-01 20:47:45 UTC (rev 292232)
@@ -799,7 +799,7 @@
 
 -(void)_getPendingPushMessages:(void(^)(NSArray<NSDictionary *> *))completionHandler
 {
-    LOG(Push, "Getting pending push messages");
+    RELEASE_LOG(Push, "Getting pending push messages");
 
 #if ENABLE(SERVICE_WORKER)
     _websiteDataStore->networkProcess().getPendingPushMessages(_websiteDataStore->sessionID(), [completionHandler = makeBlockPtr(completionHandler)] (const Vector<WebKit::WebPushMessage>& messages) {
@@ -807,7 +807,7 @@
         for (auto& message : messages)
             [result addObject:message.toDictionary()];
 
-        LOG(Push, "Giving application %u pending push messages", messages.size());
+        RELEASE_LOG(Push, "Giving application %zu pending push messages", messages.size());
         completionHandler(result.get());
     });
 #endif
@@ -818,14 +818,14 @@
 #if ENABLE(SERVICE_WORKER)
     auto pushMessage = WebKit::WebPushMessage::fromDictionary(pushMessageDictionary);
     if (!pushMessage) {
-        LOG(Push, "Asked to handle an invalid push message");
+        RELEASE_LOG_ERROR(Push, "Asked to handle an invalid push message");
         completionHandler(false);
         return;
     }
 
-    LOG(Push, "Sending push message to network process to handle");
+    RELEASE_LOG(Push, "Sending push message for scope %" PRIVATE_LOG_STRING " to network process to handle", pushMessage->registrationURL.string().utf8().data());
     _websiteDataStore->networkProcess().processPushMessage(_websiteDataStore->sessionID(), *pushMessage, [completionHandler = makeBlockPtr(completionHandler)] (bool wasProcessed) {
-        LOG(Push, "Push message processing complete. Callback result: %i", wasProcessed);
+        RELEASE_LOG(Push, "Push message processing complete. Callback result: %d", wasProcessed);
         completionHandler(wasProcessed);
     });
 #endif

Modified: trunk/Source/WebKit/webpushd/PushService.mm (292231 => 292232)


--- trunk/Source/WebKit/webpushd/PushService.mm	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/Source/WebKit/webpushd/PushService.mm	2022-04-01 20:47:45 UTC (rev 292232)
@@ -63,7 +63,7 @@
 
     PushDatabase::create(databasePath, [transaction = WTFMove(transaction), connection = WTFMove(connection), messageHandler = WTFMove(messageHandler), creationHandler = WTFMove(creationHandler)](auto&& databaseResult) mutable {
         if (!databaseResult) {
-            RELEASE_LOG(Push, "Push service initialization failed with database error");
+            RELEASE_LOG_ERROR(Push, "Push service initialization failed with database error");
             creationHandler(std::unique_ptr<PushService>());
             transaction = nullptr;
             return;
@@ -184,6 +184,8 @@
 
         String transactionDescription = String("com.apple.webkit.webpushd:"_s) + description() + ":"_s + m_bundleIdentifier + ":"_s + m_scope;
         m_transaction = adoptOSObject(os_transaction_create(transactionDescription.utf8().data()));
+
+        RELEASE_LOG(Push, "Started pushServiceRequest %{public}s (%p) for bundleID = %{public}s, scope = %{private}s", description().characters(), this, m_bundleIdentifier.utf8().data(), m_scope.utf8().data());
         startInternal();
     }
 
@@ -201,6 +203,8 @@
 
     void fulfill(ResultType result)
     {
+        RELEASE_LOG(Push, "Finished pushServiceRequest %{public}s (%p) with result for bundleID = %{public}s, scope = %{private}s", description().characters(), this, m_bundleIdentifier.utf8().data(), m_scope.utf8().data());
+
         m_resultHandler(WTFMove(result));
         finish();
     }
@@ -207,6 +211,8 @@
 
     void reject(WebCore::ExceptionData&& data)
     {
+        RELEASE_LOG(Push, "Finished pushServiceRequest %{public}s (%p) with exception for bundleID = %{public}s, scope = %{private}s", description().characters(), this, m_bundleIdentifier.utf8().data(), m_scope.utf8().data());
+
         m_resultHandler(makeUnexpected(WTFMove(data)));
         finish();
     }
@@ -293,7 +299,7 @@
                 }
 #endif
 
-                RELEASE_LOG(Push, "PushManager.subscribe(bundleID: %{public}s, scope: %{sensitive}s) failed with domain: %{public}s code: %lld)", m_bundleIdentifier.utf8().data(), m_scope.utf8().data(), error.domain.UTF8String, static_cast<int64_t>(error.code));
+                RELEASE_LOG_ERROR(Push, "PushManager.subscribe(bundleID: %{public}s, scope: %{private}s) failed with domain: %{public}s code: %lld)", m_bundleIdentifier.utf8().data(), m_scope.utf8().data(), error.domain.UTF8String, static_cast<int64_t>(error.code));
                 reject(WebCore::ExceptionData { WebCore::AbortError, "Failed due to internal service error"_s });
                 return;
             }
@@ -312,7 +318,7 @@
 
             m_database.insertRecord(record, [this](auto&& result) mutable {
                 if (!result) {
-                    RELEASE_LOG(Push, "PushManager.subscribe(bundleID: %{public}s, scope: %{sensitive}s) failed with database error", m_bundleIdentifier.utf8().data(), m_scope.utf8().data());
+                    RELEASE_LOG_ERROR(Push, "PushManager.subscribe(bundleID: %{public}s, scope: %{private}s) failed with database error", m_bundleIdentifier.utf8().data(), m_scope.utf8().data());
                     reject(WebCore::ExceptionData { WebCore::AbortError, "Failed due to internal database error"_s });
                     return;
                 }
@@ -389,7 +395,7 @@
 
             auto topic = makePushTopic(m_bundleIdentifier, m_scope);
             m_connection.unsubscribe(topic, serverVAPIDPublicKey, [this](bool unsubscribed, NSError *error) mutable {
-                RELEASE_LOG_ERROR_IF(!unsubscribed, Push, "PushSubscription.unsubscribe(bundleID: %{public}s, scope: %{sensitive}s) failed with domain: %{public}s code: %lld)", m_bundleIdentifier.utf8().data(), m_scope.utf8().data(), error.domain.UTF8String ?: "none", static_cast<int64_t>(error.code));
+                RELEASE_LOG_ERROR_IF(!unsubscribed, Push, "PushSubscription.unsubscribe(bundleID: %{public}s, scope: %{private}s) failed with domain: %{public}s code: %lld)", m_bundleIdentifier.utf8().data(), m_scope.utf8().data(), error.domain.UTF8String ?: "none", static_cast<int64_t>(error.code));
             });
         });
     });
@@ -406,8 +412,11 @@
     });
 
     auto addedRequest = request.get();
-    addResult.iterator->value.append(WTFMove(request));
+    auto& queue = addResult.iterator->value;
 
+    RELEASE_LOG(Push, "Enqueuing PushServiceRequest %p (current queue size: %zu", request.get(), queue.size());
+    queue.append(WTFMove(request));
+
     if (addResult.isNewEntry)
         addedRequest->start();
 }
@@ -498,7 +507,7 @@
             return;
         }
 
-        RELEASE_LOG(Push, "Removing all subscriptions associated with %{public}s %{sensitive}s since it processed %u silent pushes", bundleIdentifier.utf8().data(), securityOrigin.utf8().data(), silentPushCount);
+        RELEASE_LOG(Push, "Removing all subscriptions associated with %{public}s %{private}s since it processed %u silent pushes", bundleIdentifier.utf8().data(), securityOrigin.utf8().data(), silentPushCount);
 
         removeRecordsImpl(bundleIdentifier, securityOrigin, [handler = WTFMove(handler), silentPushCount](auto&&) mutable {
             handler(silentPushCount);
@@ -527,7 +536,7 @@
     auto removedRecordsHandler = [this, bundleIdentifier, securityOrigin, handler = WTFMove(handler)](Vector<RemovedPushRecord>&& removedRecords) mutable {
         for (auto& record : removedRecords) {
             m_connection->unsubscribe(record.topic, record.serverVAPIDPublicKey, [topic = record.topic](bool unsubscribed, NSError* error) {
-                RELEASE_LOG_ERROR_IF(!unsubscribed, Push, "removeRecordsImpl couldn't remove subscription for topic %{sensitive}s: %{public}s code: %lld)", topic.utf8().data(), error.domain.UTF8String ?: "none", static_cast<int64_t>(error.code));
+                RELEASE_LOG_ERROR_IF(!unsubscribed, Push, "removeRecordsImpl couldn't remove subscription for topic %{private}s: %{public}s code: %lld)", topic.utf8().data(), error.domain.UTF8String ?: "none", static_cast<int64_t>(error.code));
             });
         }
 
@@ -583,7 +592,7 @@
             NSString *serverPublicKeyBase64URL = userInfo[@"as_publickey"];
             NSString *saltBase64URL = userInfo[@"as_salt"];
             if (!serverPublicKeyBase64URL || !saltBase64URL) {
-                RELEASE_LOG(Push, "Dropping aesgcm-encrypted push without required server key and salt");
+                RELEASE_LOG_ERROR(Push, "Dropping aesgcm-encrypted push without required server key and salt");
                 return std::nullopt;
             }
 
@@ -590,7 +599,7 @@
             auto serverPublicKey = base64URLDecode(serverPublicKeyBase64URL);
             auto salt = base64URLDecode(saltBase64URL);
             if (!serverPublicKey || !salt) {
-                RELEASE_LOG(Push, "Dropping aesgcm-encrypted push with improperly encoded server key and salt");
+                RELEASE_LOG_ERROR(Push, "Dropping aesgcm-encrypted push with improperly encoded server key and salt");
                 return std::nullopt;
             }
 
@@ -597,13 +606,13 @@
             message.serverPublicKey = WTFMove(*serverPublicKey);
             message.salt = WTFMove(*salt);
         } else {
-            RELEASE_LOG(Push, "Dropping push with unknown content encoding: %{public}s", contentEncoding.UTF8String);
+            RELEASE_LOG_ERROR(Push, "Dropping push with unknown content encoding: %{public}s", contentEncoding.UTF8String);
             return std::nullopt;
         }
 
         auto payload = base64Decode(payloadBase64);
         if (!payload) {
-            RELEASE_LOG(Push, "Dropping push with improperly encoded payload");
+            RELEASE_LOG_ERROR(Push, "Dropping push with improperly encoded payload");
             return std::nullopt;
         }
         message.encryptedPayload = WTFMove(*payload);
@@ -620,7 +629,7 @@
 
     m_database->getRecordByTopic(topic, [this, message = WTFMove(*messageResult), completionHandler = WTFMove(completionHandler)](auto&& recordResult) mutable {
         if (!recordResult) {
-            RELEASE_LOG(Push, "Dropping incoming push sent to unknown topic: %{sensitive}s", message.topic.utf8().data());
+            RELEASE_LOG_ERROR(Push, "Dropping incoming push sent to unknown topic: %{private}s", message.topic.utf8().data());
             completionHandler();
             return;
         }
@@ -644,11 +653,13 @@
             decryptedPayload = decryptAESGCMPayload(clientKeys, message.serverPublicKey, message.salt, message.encryptedPayload);
 
         if (!decryptedPayload) {
-            RELEASE_LOG(Push, "Dropping incoming push due to decryption error for topic %{sensitive}s", message.topic.utf8().data());
+            RELEASE_LOG_ERROR(Push, "Dropping incoming push due to decryption error for topic %{private}s", message.topic.utf8().data());
             completionHandler();
             return;
         }
 
+        RELEASE_LOG(Push, "Decoded incoming push message for %{public}s %{private}s", record.bundleID.utf8().data(), record.scope.utf8().data());
+
         m_incomingPushMessageHandler(record.bundleID, WebKit::WebPushMessage { WTFMove(*decryptedPayload), URL { record.scope } });
 
         completionHandler();

Modified: trunk/Source/WebKit/webpushd/WebPushDaemon.mm (292231 => 292232)


--- trunk/Source/WebKit/webpushd/WebPushDaemon.mm	2022-04-01 19:53:44 UTC (rev 292231)
+++ trunk/Source/WebKit/webpushd/WebPushDaemon.mm	2022-04-01 20:47:45 UTC (rev 292232)
@@ -572,7 +572,6 @@
             replySender(false);
             return;
         }
-        NSLog(@"got obj: %@", obj);
 
         m_pushService->didReceivePushMessage(obj[@"topic"], obj[@"userInfo"], [replySender = WTFMove(replySender)]() mutable {
             replySender(true);
@@ -592,6 +591,8 @@
 
 void Daemon::notifyClientPushMessageIsAvailable(const String& clientCodeSigningIdentifier)
 {
+    RELEASE_LOG(Push, "Launching %{public}s in response to push", clientCodeSigningIdentifier.utf8().data());
+
 #if PLATFORM(MAC)
     CFArrayRef urls = (__bridge CFArrayRef)@[ [NSURL URLWithString:@"x-webkit-app-launch://1"] ];
     CFStringRef identifier = (__bridge CFStringRef)((NSString *)clientCodeSigningIdentifier);
@@ -604,7 +605,9 @@
         (id)_kLSOpenOptionHideKey: @YES,
     };
 
-    _LSOpenURLsUsingBundleIdentifierWithCompletionHandler(urls, identifier, options, ^(LSASNRef newProcessSerialNumber, Boolean processWasLaunched, CFErrorRef cfError) { });
+    _LSOpenURLsUsingBundleIdentifierWithCompletionHandler(urls, identifier, options, ^(LSASNRef, Boolean, CFErrorRef cfError) {
+        RELEASE_LOG_ERROR_IF(cfError, Push, "Failed to launch process in response to push: %{public}@", (__bridge NSError *)cfError);
+    });
 #else
     // FIXME: Figure out equivalent iOS code here
     UNUSED_PARAM(clientCodeSigningIdentifier);
@@ -633,6 +636,7 @@
         m_testingPushMessages.remove(iterator);
     }
 
+    RELEASE_LOG(Push, "Fetched %zu pending push messages for %{public}s", resultMessages.size(), hostAppCodeSigningIdentifier.utf8().data());
     connection->broadcastDebugMessage(makeString("Fetching ", String::number(resultMessages.size()), " pending push messages"));
 
     replySender(WTFMove(resultMessages));
_______________________________________________
webkit-changes mailing list
[email protected]
https://lists.webkit.org/mailman/listinfo/webkit-changes

Reply via email to