Add release logging to help debug issues related to service workers
authorcdumez@apple.com <cdumez@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Mon, 22 Jan 2018 21:08:46 +0000 (21:08 +0000)
committercdumez@apple.com <cdumez@apple.com@268f45cc-cd09-0410-ab3c-d52691b4dbfc>
Mon, 22 Jan 2018 21:08:46 +0000 (21:08 +0000)
https://bugs.webkit.org/show_bug.cgi?id=181935
<rdar://problem/36735900>

Reviewed by Brady Eidson.

Source/WebCore:

* workers/service/ServiceWorker.cpp:
(WebCore::ServiceWorker::ServiceWorker):
(WebCore::ServiceWorker::scheduleTaskToUpdateState):
(WebCore::ServiceWorker::postMessage):
(WebCore::ServiceWorker::isAlwaysOnLoggingAllowed const):
* workers/service/ServiceWorker.h:
* workers/service/ServiceWorkerContainer.cpp:
(WebCore::ServiceWorkerContainer::addRegistration):
(WebCore::ServiceWorkerContainer::removeRegistration):
(WebCore::ServiceWorkerContainer::updateRegistration):
(WebCore::ServiceWorkerContainer::jobFailedWithException):
(WebCore::ServiceWorkerContainer::jobResolvedWithRegistration):
(WebCore::ServiceWorkerContainer::jobResolvedWithUnregistrationResult):
(WebCore::ServiceWorkerContainer::startScriptFetchForJob):
(WebCore::ServiceWorkerContainer::jobFinishedLoadingScript):
(WebCore::ServiceWorkerContainer::jobFailedLoadingScript):
(WebCore::ServiceWorkerContainer::isAlwaysOnLoggingAllowed const):
* workers/service/ServiceWorkerContainer.h:
* workers/service/ServiceWorkerRegistration.cpp:
(WebCore::ServiceWorkerRegistration::ServiceWorkerRegistration):
(WebCore::ServiceWorkerRegistration::updateStateFromServer):
(WebCore::ServiceWorkerRegistration::scheduleTaskToFireUpdateFoundEvent):
* workers/service/server/SWServer.cpp:
(WebCore::SWServer::scriptContextFailedToStart):
(WebCore::SWServer::didFinishInstall):
(WebCore::SWServer::didFinishActivation):
(WebCore::SWServer::terminateWorkerInternal):
* workers/service/server/SWServerJobQueue.cpp:
(WebCore::SWServerJobQueue::didResolveRegistrationPromise):
(WebCore::SWServerJobQueue::runRegisterJob):

Source/WebKit:

* StorageProcess/ServiceWorker/WebSWServerConnection.cpp:
(WebKit::WebSWServerConnection::startFetch):
(WebKit::WebSWServerConnection::didFinishFetch):
(WebKit::WebSWServerConnection::didFailFetch):
(WebKit::WebSWServerConnection::didNotHandleFetch):

git-svn-id: https://svn.webkit.org/repository/webkit/trunk@227350 268f45cc-cd09-0410-ab3c-d52691b4dbfc

Source/WebCore/ChangeLog
Source/WebCore/workers/service/ServiceWorker.cpp
Source/WebCore/workers/service/ServiceWorker.h
Source/WebCore/workers/service/ServiceWorkerContainer.cpp
Source/WebCore/workers/service/ServiceWorkerContainer.h
Source/WebCore/workers/service/ServiceWorkerJobDataIdentifier.h
Source/WebCore/workers/service/ServiceWorkerRegistration.cpp
Source/WebCore/workers/service/server/SWServer.cpp
Source/WebCore/workers/service/server/SWServerJobQueue.cpp
Source/WebKit/ChangeLog
Source/WebKit/StorageProcess/ServiceWorker/WebSWServerConnection.cpp

index 1e39b3f..f900ee3 100644 (file)
@@ -1,3 +1,42 @@
+2018-01-22  Chris Dumez  <cdumez@apple.com>
+
+        Add release logging to help debug issues related to service workers
+        https://bugs.webkit.org/show_bug.cgi?id=181935
+        <rdar://problem/36735900>
+
+        Reviewed by Brady Eidson.
+
+        * workers/service/ServiceWorker.cpp:
+        (WebCore::ServiceWorker::ServiceWorker):
+        (WebCore::ServiceWorker::scheduleTaskToUpdateState):
+        (WebCore::ServiceWorker::postMessage):
+        (WebCore::ServiceWorker::isAlwaysOnLoggingAllowed const):
+        * workers/service/ServiceWorker.h:
+        * workers/service/ServiceWorkerContainer.cpp:
+        (WebCore::ServiceWorkerContainer::addRegistration):
+        (WebCore::ServiceWorkerContainer::removeRegistration):
+        (WebCore::ServiceWorkerContainer::updateRegistration):
+        (WebCore::ServiceWorkerContainer::jobFailedWithException):
+        (WebCore::ServiceWorkerContainer::jobResolvedWithRegistration):
+        (WebCore::ServiceWorkerContainer::jobResolvedWithUnregistrationResult):
+        (WebCore::ServiceWorkerContainer::startScriptFetchForJob):
+        (WebCore::ServiceWorkerContainer::jobFinishedLoadingScript):
+        (WebCore::ServiceWorkerContainer::jobFailedLoadingScript):
+        (WebCore::ServiceWorkerContainer::isAlwaysOnLoggingAllowed const):
+        * workers/service/ServiceWorkerContainer.h:
+        * workers/service/ServiceWorkerRegistration.cpp:
+        (WebCore::ServiceWorkerRegistration::ServiceWorkerRegistration):
+        (WebCore::ServiceWorkerRegistration::updateStateFromServer):
+        (WebCore::ServiceWorkerRegistration::scheduleTaskToFireUpdateFoundEvent):
+        * workers/service/server/SWServer.cpp:
+        (WebCore::SWServer::scriptContextFailedToStart):
+        (WebCore::SWServer::didFinishInstall):
+        (WebCore::SWServer::didFinishActivation):
+        (WebCore::SWServer::terminateWorkerInternal):
+        * workers/service/server/SWServerJobQueue.cpp:
+        (WebCore::SWServerJobQueue::didResolveRegistrationPromise):
+        (WebCore::SWServerJobQueue::runRegisterJob):
+
 2018-01-22  Youenn Fablet  <youenn@apple.com>
 
         Safari Tech Preview can't use GitHub login at forums.swift.org
index e9f8cb0..0b8ce93 100644 (file)
@@ -30,6 +30,7 @@
 
 #include "Document.h"
 #include "EventNames.h"
+#include "Logging.h"
 #include "MessagePort.h"
 #include "SWClientConnection.h"
 #include "ScriptExecutionContext.h"
@@ -40,6 +41,9 @@
 #include <runtime/JSCJSValueInlines.h>
 #include <wtf/NeverDestroyed.h>
 
+#define WORKER_RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(isAlwaysOnLoggingAllowed(), ServiceWorker, "%p - ServiceWorker::" fmt, this, ##__VA_ARGS__)
+#define WORKER_RELEASE_LOG_ERROR_IF_ALLOWED(fmt, ...) RELEASE_LOG_ERROR_IF(isAlwaysOnLoggingAllowed(), ServiceWorker, "%p - ServiceWorker::" fmt, this, ##__VA_ARGS__)
+
 namespace WebCore {
 
 Ref<ServiceWorker> ServiceWorker::getOrCreate(ScriptExecutionContext& context, ServiceWorkerData&& data)
@@ -59,6 +63,8 @@ ServiceWorker::ServiceWorker(ScriptExecutionContext& context, ServiceWorkerData&
 
     relaxAdoptionRequirement();
     updatePendingActivityForEventDispatch();
+
+    WORKER_RELEASE_LOG_IF_ALLOWED("ServiceWorker: ID: %llu, state: %u", identifier().toUInt64(), m_data.state);
 }
 
 ServiceWorker::~ServiceWorker()
@@ -76,6 +82,7 @@ void ServiceWorker::scheduleTaskToUpdateState(State state)
     context->postTask([this, protectedThis = makeRef(*this), state](ScriptExecutionContext&) {
         ASSERT(this->state() != state);
 
+        WORKER_RELEASE_LOG_IF_ALLOWED("scheduleTaskToUpdateState: Updating service worker %llu state from %u to %u. Registration ID: %llu", identifier().toUInt64(), m_data.state, state, registrationIdentifier().toUInt64());
         m_data.state = state;
         if (state != State::Installing && !m_isStopped) {
             ASSERT(m_pendingActivityForEventDispatch);
@@ -111,8 +118,10 @@ ExceptionOr<void> ServiceWorker::postMessage(ScriptExecutionContext& context, JS
 
     // FIXME: Support sending the channels.
     auto channels = channelsOrException.releaseReturnValue();
-    if (!channels.isEmpty())
+    if (!channels.isEmpty()) {
+        WORKER_RELEASE_LOG_ERROR_IF_ALLOWED("postMessage: Passing MessagePort objects to postMessage is not yet supported");
         return Exception { NotSupportedError, ASCIILiteral("Passing MessagePort objects to postMessage is not yet supported") };
+    }
 
     ServiceWorkerOrClientIdentifier sourceIdentifier;
     if (is<ServiceWorkerGlobalScope>(context))
@@ -170,6 +179,19 @@ void ServiceWorker::updatePendingActivityForEventDispatch()
     m_pendingActivityForEventDispatch = makePendingActivity(*this);
 }
 
+bool ServiceWorker::isAlwaysOnLoggingAllowed() const
+{
+    auto* context = scriptExecutionContext();
+    if (!context)
+        return false;
+
+    auto* container = context->serviceWorkerContainer();
+    if (!container)
+        return false;
+
+    return container->isAlwaysOnLoggingAllowed();
+}
+
 } // namespace WebCore
 
 #endif // ENABLE(SERVICE_WORKER)
index e771b1a..157de85 100644 (file)
@@ -78,6 +78,8 @@ private:
     bool canSuspendForDocumentSuspension() const final;
     void stop() final;
 
+    bool isAlwaysOnLoggingAllowed() const;
+
     ServiceWorkerData m_data;
     bool m_isStopped { false };
     RefPtr<PendingActivity<ServiceWorker>> m_pendingActivityForEventDispatch;
index 157bfd0..e603149 100644 (file)
@@ -52,6 +52,9 @@
 #include <wtf/RunLoop.h>
 #include <wtf/Scope.h>
 
+#define CONTAINER_RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(isAlwaysOnLoggingAllowed(), ServiceWorker, "%p - ServiceWorkerContainer::" fmt, this, ##__VA_ARGS__)
+#define CONTAINER_RELEASE_LOG_ERROR_IF_ALLOWED(fmt, ...) RELEASE_LOG_ERROR_IF(isAlwaysOnLoggingAllowed(), ServiceWorker, "%p - ServiceWorkerContainer::" fmt, this, ##__VA_ARGS__)
+
 namespace WebCore {
 
 ServiceWorkerContainer::ServiceWorkerContainer(ScriptExecutionContext& context, NavigatorBase& navigator)
@@ -127,17 +130,20 @@ void ServiceWorkerContainer::addRegistration(const String& relativeScriptURL, co
 
     jobData.scriptURL = context->completeURL(relativeScriptURL);
     if (!jobData.scriptURL.isValid()) {
+        CONTAINER_RELEASE_LOG_ERROR_IF_ALLOWED("addRegistration: Invalid scriptURL");
         promise->reject(Exception { TypeError, ASCIILiteral("serviceWorker.register() must be called with a valid relative script URL") });
         return;
     }
 
     if (!SchemeRegistry::canServiceWorkersHandleURLScheme(jobData.scriptURL.protocol().toStringWithoutCopying())) {
+        CONTAINER_RELEASE_LOG_ERROR_IF_ALLOWED("addRegistration: Invalid scriptURL scheme is not HTTP or HTTPS");
         promise->reject(Exception { TypeError, ASCIILiteral("serviceWorker.register() must be called with a script URL whose protocol is either HTTP or HTTPS") });
         return;
     }
 
     String path = jobData.scriptURL.path();
     if (path.containsIgnoringASCIICase("%2f") || path.containsIgnoringASCIICase("%5c")) {
+        CONTAINER_RELEASE_LOG_ERROR_IF_ALLOWED("addRegistration: scriptURL contains invalid character");
         promise->reject(Exception { TypeError, ASCIILiteral("serviceWorker.register() must be called with a script URL whose path does not contain '%2f' or '%5c'") });
         return;
     }
@@ -148,16 +154,20 @@ void ServiceWorkerContainer::addRegistration(const String& relativeScriptURL, co
         jobData.scopeURL = URL(jobData.scriptURL, "./");
 
     if (!jobData.scopeURL.isNull() && !SchemeRegistry::canServiceWorkersHandleURLScheme(jobData.scopeURL.protocol().toStringWithoutCopying())) {
+        CONTAINER_RELEASE_LOG_ERROR_IF_ALLOWED("addRegistration: scopeURL scheme is not HTTP or HTTPS");
         promise->reject(Exception { TypeError, ASCIILiteral("Scope URL provided to serviceWorker.register() must be either HTTP or HTTPS") });
         return;
     }
 
     path = jobData.scopeURL.path();
     if (path.containsIgnoringASCIICase("%2f") || path.containsIgnoringASCIICase("%5c")) {
+        CONTAINER_RELEASE_LOG_ERROR_IF_ALLOWED("addRegistration: scopeURL contains invalid character");
         promise->reject(Exception { TypeError, ASCIILiteral("Scope URL provided to serviceWorker.register() cannot have a path that contains '%2f' or '%5c'") });
         return;
     }
 
+    CONTAINER_RELEASE_LOG_IF_ALLOWED("addRegistration: Registering service worker. Job ID: %llu", jobData.identifier().jobIdentifier.toUInt64());
+
     jobData.clientCreationURL = context->url();
     jobData.topOrigin = SecurityOriginData::fromSecurityOrigin(context->topOrigin());
     jobData.type = ServiceWorkerJobType::Register;
@@ -187,6 +197,8 @@ void ServiceWorkerContainer::removeRegistration(const URL& scopeURL, Ref<Deferre
     jobData.type = ServiceWorkerJobType::Unregister;
     jobData.scopeURL = scopeURL;
 
+    CONTAINER_RELEASE_LOG_IF_ALLOWED("removeRegistration: Unregistering service worker. Job ID: %llu", jobData.identifier().jobIdentifier.toUInt64());
+
     scheduleJob(ServiceWorkerJob::create(*this, WTFMove(promise), WTFMove(jobData)));
 }
 
@@ -211,6 +223,8 @@ void ServiceWorkerContainer::updateRegistration(const URL& scopeURL, const URL&
     jobData.scopeURL = scopeURL;
     jobData.scriptURL = scriptURL;
 
+    CONTAINER_RELEASE_LOG_IF_ALLOWED("removeRegistration: Updating service worker. Job ID: %llu", jobData.identifier().jobIdentifier.toUInt64());
+
     scheduleJob(ServiceWorkerJob::create(*this, WTFMove(promise), WTFMove(jobData)));
 }
 
@@ -360,6 +374,8 @@ void ServiceWorkerContainer::jobFailedWithException(ServiceWorkerJob& job, const
         jobDidFinish(job);
     });
 
+    CONTAINER_RELEASE_LOG_ERROR_IF_ALLOWED("jobFailedWithException: Job %llu failed with error %s", job.identifier().toUInt64(), exception.message().utf8().data());
+
     if (!job.promise())
         return;
 
@@ -391,6 +407,13 @@ void ServiceWorkerContainer::jobResolvedWithRegistration(ServiceWorkerJob& job,
         jobDidFinish(job);
     });
 
+    if (job.data().type == ServiceWorkerJobType::Register)
+        CONTAINER_RELEASE_LOG_IF_ALLOWED("jobResolvedWithRegistration: Registration job %llu succeeded", job.identifier().toUInt64());
+    else {
+        ASSERT(job.data().type == ServiceWorkerJobType::Update);
+        CONTAINER_RELEASE_LOG_IF_ALLOWED("jobResolvedWithRegistration: Update job %llu succeeded", job.identifier().toUInt64());
+    }
+
     WTF::Function<void()> notifyWhenResolvedIfNeeded = [] { };
     if (shouldNotifyWhenResolved == ShouldNotifyWhenResolved::Yes) {
         notifyWhenResolvedIfNeeded = [connection = m_swConnection, registrationKey = data.key.isolatedCopy()]() mutable {
@@ -418,7 +441,7 @@ void ServiceWorkerContainer::jobResolvedWithRegistration(ServiceWorkerJob& job,
 
         auto registration = ServiceWorkerRegistration::getOrCreate(context, *this, WTFMove(data));
 
-        LOG(ServiceWorker, "Container %p resolved job with registration %p", this, registration.ptr());
+        CONTAINER_RELEASE_LOG_IF_ALLOWED("jobResolvedWithRegistration: Resolving promise for job %llu. Registration ID: %llu", job->identifier().toUInt64(), registration->identifier().toUInt64());
 
         job->promise()->resolve<IDLInterface<ServiceWorkerRegistration>>(WTFMove(registration));
 
@@ -438,6 +461,8 @@ void ServiceWorkerContainer::jobResolvedWithUnregistrationResult(ServiceWorkerJo
         jobDidFinish(job);
     });
 
+    CONTAINER_RELEASE_LOG_IF_ALLOWED("jobResolvedWithUnregistrationResult: Unregister job %llu finished. Success? %d", job.identifier().toUInt64(), unregistrationResult);
+
     auto* context = scriptExecutionContext();
     if (!context) {
         LOG_ERROR("ServiceWorkerContainer::jobResolvedWithUnregistrationResult called but the containers ScriptExecutionContext is gone");
@@ -455,7 +480,7 @@ void ServiceWorkerContainer::startScriptFetchForJob(ServiceWorkerJob& job, Fetch
     ASSERT(m_creationThread.ptr() == &Thread::current());
 #endif
 
-    LOG(ServiceWorker, "SeviceWorkerContainer %p starting script fetch for job %s", this, job.identifier().loggingString().utf8().data());
+    CONTAINER_RELEASE_LOG_IF_ALLOWED("startScriptFetchForJob: Starting script fetch for job %llu", job.identifier().toUInt64());
 
     auto* context = scriptExecutionContext();
     if (!context) {
@@ -476,7 +501,7 @@ void ServiceWorkerContainer::jobFinishedLoadingScript(ServiceWorkerJob& job, con
     ASSERT(m_creationThread.ptr() == &Thread::current());
 #endif
 
-    LOG(ServiceWorker, "SeviceWorkerContainer %p finished fetching script for job %s", this, job.identifier().loggingString().utf8().data());
+    CONTAINER_RELEASE_LOG_IF_ALLOWED("jobFinishedLoadingScript: Successfuly finished fetching script for job %llu", job.identifier().toUInt64());
 
     callOnMainThread([connection = m_swConnection, jobDataIdentifier = job.data().identifier(), registrationKey = job.data().registrationKey(), script = script.isolatedCopy(), contentSecurityPolicy = contentSecurityPolicy.isolatedCopy()] {
         connection->finishFetchingScriptInServer({ jobDataIdentifier, registrationKey, script, contentSecurityPolicy, { } });
@@ -490,7 +515,7 @@ void ServiceWorkerContainer::jobFailedLoadingScript(ServiceWorkerJob& job, const
 #endif
     ASSERT_WITH_MESSAGE(job.promise() || job.data().type == ServiceWorkerJobType::Update, "Only soft updates have no promise");
 
-    LOG(ServiceWorker, "SeviceWorkerContainer %p failed fetching script for job %s", this, job.identifier().loggingString().utf8().data());
+    CONTAINER_RELEASE_LOG_ERROR_IF_ALLOWED("jobFinishedLoadingScript: Failed to fetch script for job %llu, error: %s", job.identifier().toUInt64(), error.localizedDescription().utf8().data());
 
     if (exception && job.promise())
         job.promise()->reject(*exception);
@@ -597,6 +622,19 @@ DocumentOrWorkerIdentifier ServiceWorkerContainer::contextIdentifier()
     return downcast<Document>(*scriptExecutionContext()).identifier();
 }
 
+bool ServiceWorkerContainer::isAlwaysOnLoggingAllowed() const
+{
+    auto* context = scriptExecutionContext();
+    if (!context)
+        return false;
+
+    if (is<Document>(*context))
+        return downcast<Document>(*context).sessionID().isAlwaysOnLoggingAllowed();
+
+    // FIXME: No logging inside service workers for now.
+    return false;
+}
+
 } // namespace WebCore
 
 #endif // ENABLE(SERVICE_WORKER)
index 14b526f..ad3851b 100644 (file)
@@ -84,6 +84,8 @@ public:
 
     bool isStopped() const { return m_isStopped; };
 
+    bool isAlwaysOnLoggingAllowed() const;
+
 private:
     void scheduleJob(Ref<ServiceWorkerJob>&&);
 
index 3846abe..725a83a 100644 (file)
@@ -35,12 +35,10 @@ struct ServiceWorkerJobDataIdentifier {
     SWServerConnectionIdentifier connectionIdentifier;
     ServiceWorkerJobIdentifier jobIdentifier;
 
-#ifndef NDEBUG
     String loggingString() const
     {
         return connectionIdentifier.loggingString() + "-" + jobIdentifier.loggingString();
     }
-#endif
 
     template<class Encoder> void encode(Encoder&) const;
     template<class Decoder> static std::optional<ServiceWorkerJobDataIdentifier> decode(Decoder&);
index 093ea75..f269b8e 100644 (file)
@@ -37,6 +37,9 @@
 #include "ServiceWorkerTypes.h"
 #include "WorkerGlobalScope.h"
 
+#define REGISTRATION_RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(m_container->isAlwaysOnLoggingAllowed(), ServiceWorker, "%p - ServiceWorkerRegistration::" fmt, this, ##__VA_ARGS__)
+#define REGISTRATION_RELEASE_LOG_ERROR_IF_ALLOWED(fmt, ...) RELEASE_LOG_ERROR_IF(m_container->isAlwaysOnLoggingAllowed(), ServiceWorker, "%p - ServiceWorkerRegistration::" fmt, this, ##__VA_ARGS__)
+
 namespace WebCore {
 
 Ref<ServiceWorkerRegistration> ServiceWorkerRegistration::getOrCreate(ScriptExecutionContext& context, Ref<ServiceWorkerContainer>&& container, ServiceWorkerRegistrationData&& data)
@@ -64,6 +67,8 @@ ServiceWorkerRegistration::ServiceWorkerRegistration(ScriptExecutionContext& con
     if (m_registrationData.activeWorker)
         m_activeWorker = ServiceWorker::getOrCreate(context, WTFMove(*m_registrationData.activeWorker));
 
+    REGISTRATION_RELEASE_LOG_IF_ALLOWED("ServiceWorkerRegistration: ID %llu, installing: %llu, waiting: %llu, active: %llu", identifier().toUInt64(), m_installingWorker ? m_installingWorker->identifier().toUInt64() : 0, m_waitingWorker ? m_waitingWorker->identifier().toUInt64() : 0, m_activeWorker ? m_activeWorker->identifier().toUInt64() : 0);
+
     m_container->addRegistration(*this);
 
     relaxAdoptionRequirement();
@@ -171,12 +176,15 @@ void ServiceWorkerRegistration::updateStateFromServer(ServiceWorkerRegistrationS
 {
     switch (state) {
     case ServiceWorkerRegistrationState::Installing:
+        REGISTRATION_RELEASE_LOG_IF_ALLOWED("updateStateFromServer: Setting registration %llu installing worker to %llu", identifier().toUInt64(), serviceWorker ? serviceWorker->identifier().toUInt64() : 0);
         m_installingWorker = WTFMove(serviceWorker);
         break;
     case ServiceWorkerRegistrationState::Waiting:
+        REGISTRATION_RELEASE_LOG_IF_ALLOWED("updateStateFromServer: Setting registration %llu waiting worker to %llu", identifier().toUInt64(), serviceWorker ? serviceWorker->identifier().toUInt64() : 0);
         m_waitingWorker = WTFMove(serviceWorker);
         break;
     case ServiceWorkerRegistrationState::Active:
+        REGISTRATION_RELEASE_LOG_IF_ALLOWED("updateStateFromServer: Setting registration %llu active worker to %llu", identifier().toUInt64(), serviceWorker ? serviceWorker->identifier().toUInt64() : 0);
         m_activeWorker = WTFMove(serviceWorker);
         break;
     }
@@ -192,6 +200,8 @@ void ServiceWorkerRegistration::scheduleTaskToFireUpdateFoundEvent()
         if (m_isStopped)
             return;
 
+        REGISTRATION_RELEASE_LOG_IF_ALLOWED("scheduleTaskToFireUpdateFoundEvent: Firing updatefound event for registration %llu", identifier().toUInt64());
+
         ASSERT(m_pendingActivityForEventDispatch);
         dispatchEvent(Event::create(eventNames().updatefoundEvent, false, false));
     });
index 161d15b..632c7ae 100644 (file)
@@ -334,6 +334,8 @@ void SWServer::scriptContextFailedToStart(const std::optional<ServiceWorkerJobDa
     if (!jobDataIdentifier)
         return;
 
+    RELEASE_LOG_ERROR(ServiceWorker, "%p - SWServer::scriptContextFailedToStart: Failed to start SW for job %s, error: %s", this, jobDataIdentifier->loggingString().utf8().data(), message.utf8().data());
+
     if (auto* jobQueue = m_jobQueues.get(worker.registrationKey()))
         jobQueue->scriptContextFailedToStart(*jobDataIdentifier, worker.identifier(), message);
 }
@@ -352,12 +354,19 @@ void SWServer::didFinishInstall(const std::optional<ServiceWorkerJobDataIdentifi
     if (!jobDataIdentifier)
         return;
 
+    if (wasSuccessful)
+        RELEASE_LOG(ServiceWorker, "%p - SWServer::didFinishInstall: Successfuly finished SW install for job %s", this, jobDataIdentifier->loggingString().utf8().data());
+    else
+        RELEASE_LOG_ERROR(ServiceWorker, "%p - SWServer::didFinishInstall: Failed SW install for job %s", this, jobDataIdentifier->loggingString().utf8().data());
+
     if (auto* jobQueue = m_jobQueues.get(worker.registrationKey()))
         jobQueue->didFinishInstall(*jobDataIdentifier, worker.identifier(), wasSuccessful);
 }
 
 void SWServer::didFinishActivation(SWServerWorker& worker)
 {
+    RELEASE_LOG(ServiceWorker, "%p - SWServer::didFinishActivation: Finished activation for service worker %llu", this, worker.identifier().toUInt64());
+
     if (auto* registration = getRegistration(worker.registrationKey()))
         registration->didFinishActivation(worker.identifier());
 }
@@ -575,6 +584,8 @@ void SWServer::terminateWorkerInternal(SWServerWorker& worker, TerminationMode m
     ASSERT(m_runningOrTerminatingWorkers.get(worker.identifier()) == &worker);
     ASSERT(worker.isRunning());
 
+    RELEASE_LOG(ServiceWorker, "%p - SWServer::terminateWorkerInternal: Terminating service worker %llu", this, worker.identifier().toUInt64());
+
     worker.setState(SWServerWorker::State::Terminating);
 
     auto* connection = SWServerToContextConnection::connectionForIdentifier(worker.contextConnectionIdentifier());
index db3b81f..0e15522 100644 (file)
@@ -159,6 +159,8 @@ void SWServerJobQueue::didResolveRegistrationPromise()
     ASSERT(registration);
     ASSERT(registration->installingWorker());
 
+    RELEASE_LOG(ServiceWorker, "%p - SWServerJobQueue::didResolveRegistrationPromise: Registration ID: %llu. Now proceeding with install", this, registration->identifier().toUInt64());
+
     // Queue a task to fire an event named updatefound at all the ServiceWorkerRegistration objects
     // for all the service worker clients whose creation URL matches registration's scope url and
     // all the service workers whose containing service worker registration is registration.
@@ -263,6 +265,7 @@ void SWServerJobQueue::runRegisterJob(const ServiceWorkerJobData& job)
         registration->setIsUninstalling(false);
         auto* newestWorker = registration->getNewestWorker();
         if (newestWorker && equalIgnoringFragmentIdentifier(job.scriptURL, newestWorker->scriptURL()) && job.registrationOptions.updateViaCache == registration->updateViaCache()) {
+            RELEASE_LOG(ServiceWorker, "%p - SWServerJobQueue::runRegisterJob: Found directly reusable registration %llu for job %s (DONE)", this, registration->identifier().toUInt64(), job.identifier().loggingString().utf8().data());
             m_server.resolveRegistrationJob(job, registration->data(), ShouldNotifyWhenResolved::No);
             finishCurrentJob();
             return;
@@ -270,9 +273,12 @@ void SWServerJobQueue::runRegisterJob(const ServiceWorkerJobData& job)
         // This is not specified yet (https://github.com/w3c/ServiceWorker/issues/1189).
         if (registration->updateViaCache() != job.registrationOptions.updateViaCache)
             registration->setUpdateViaCache(job.registrationOptions.updateViaCache);
+        RELEASE_LOG(ServiceWorker, "%p - SWServerJobQueue::runRegisterJob: Found registration %llu for job %s but it needs updating", this, registration->identifier().toUInt64(), job.identifier().loggingString().utf8().data());
     } else {
         auto newRegistration = std::make_unique<SWServerRegistration>(m_server, m_registrationKey, job.registrationOptions.updateViaCache, job.scopeURL, job.scriptURL);
         m_server.addRegistration(WTFMove(newRegistration));
+
+        RELEASE_LOG(ServiceWorker, "%p - SWServerJobQueue::runRegisterJob: No existing registration for job %s, constructing a new one.", this, job.identifier().loggingString().utf8().data());
     }
 
     runUpdateJob(job);
index 7017959..c6e996d 100644 (file)
@@ -1,3 +1,17 @@
+2018-01-22  Chris Dumez  <cdumez@apple.com>
+
+        Add release logging to help debug issues related to service workers
+        https://bugs.webkit.org/show_bug.cgi?id=181935
+        <rdar://problem/36735900>
+
+        Reviewed by Brady Eidson.
+
+        * StorageProcess/ServiceWorker/WebSWServerConnection.cpp:
+        (WebKit::WebSWServerConnection::startFetch):
+        (WebKit::WebSWServerConnection::didFinishFetch):
+        (WebKit::WebSWServerConnection::didFailFetch):
+        (WebKit::WebSWServerConnection::didNotHandleFetch):
+
 2018-01-22  Brent Fulgham  <bfulgham@apple.com>
 
         [iOS] REGRESSION (r225763): Allow access to power logging features
index 18d841d..d1d1159 100644 (file)
@@ -56,6 +56,9 @@ using namespace WebCore;
 
 namespace WebKit {
 
+#define SWSERVERCONNECTION_RELEASE_LOG_IF_ALLOWED(fmt, ...) RELEASE_LOG_IF(m_sessionID.isAlwaysOnLoggingAllowed(), ServiceWorker, "%p - WebSWServerConnection::" fmt, this, ##__VA_ARGS__)
+#define SWSERVERCONNECTION_RELEASE_LOG_ERROR_IF_ALLOWED(fmt, ...) RELEASE_LOG_ERROR_IF(m_sessionID.isAlwaysOnLoggingAllowed(), ServiceWorker, "%p - WebSWServerConnection::" fmt, this, ##__VA_ARGS__)
+
 WebSWServerConnection::WebSWServerConnection(SWServer& server, IPC::Connection& connection, SessionID sessionID)
     : SWServer::Connection(server)
     , m_sessionID(sessionID)
@@ -130,6 +133,7 @@ void WebSWServerConnection::startFetch(uint64_t fetchIdentifier, ServiceWorkerRe
 {
     auto* worker = server().activeWorkerFromRegistrationID(serviceWorkerRegistrationIdentifier);
     if (!worker) {
+        SWSERVERCONNECTION_RELEASE_LOG_ERROR_IF_ALLOWED("startFetch: fetchIdentifier: %llu -> DidNotHandle because no active worker", fetchIdentifier);
         m_contentConnection->send(Messages::ServiceWorkerClientFetch::DidNotHandle { }, fetchIdentifier);
         return;
     }
@@ -140,6 +144,7 @@ void WebSWServerConnection::startFetch(uint64_t fetchIdentifier, ServiceWorkerRe
             return;
 
         if (!success) {
+            SWSERVERCONNECTION_RELEASE_LOG_ERROR_IF_ALLOWED("startFetch: fetchIdentifier: %llu -> DidNotHandle because worker did not become activated", fetchIdentifier);
             m_contentConnection->send(Messages::ServiceWorkerClientFetch::DidNotHandle { }, fetchIdentifier);
             return;
         }
@@ -148,10 +153,13 @@ void WebSWServerConnection::startFetch(uint64_t fetchIdentifier, ServiceWorkerRe
             if (!weakThis)
                 return;
 
-            if (success)
+            if (success) {
+                SWSERVERCONNECTION_RELEASE_LOG_IF_ALLOWED("startFetch: Starting fetch %llu via service worker %llu", fetchIdentifier, serviceWorkerIdentifier.toUInt64());
                 sendToContextProcess(contextConnection, Messages::WebSWContextManagerConnection::StartFetch { identifier(), fetchIdentifier, serviceWorkerIdentifier, request, options, formData, referrer });
-            else
+            } else {
+                SWSERVERCONNECTION_RELEASE_LOG_ERROR_IF_ALLOWED("startFetch: fetchIdentifier: %llu -> DidNotHandle because failed to run service worker", fetchIdentifier);
                 m_contentConnection->send(Messages::ServiceWorkerClientFetch::DidNotHandle { }, fetchIdentifier);
+            }
         });
     };
 
@@ -201,16 +209,19 @@ void WebSWServerConnection::didReceiveFetchFormData(uint64_t fetchIdentifier, co
 
 void WebSWServerConnection::didFinishFetch(uint64_t fetchIdentifier)
 {
+    SWSERVERCONNECTION_RELEASE_LOG_IF_ALLOWED("didFinishFetch: fetchIdentifier: %llu", fetchIdentifier);
     m_contentConnection->send(Messages::ServiceWorkerClientFetch::DidFinish { }, fetchIdentifier);
 }
 
 void WebSWServerConnection::didFailFetch(uint64_t fetchIdentifier)
 {
+    SWSERVERCONNECTION_RELEASE_LOG_ERROR_IF_ALLOWED("didFailFetch: fetchIdentifier: %llu", fetchIdentifier);
     m_contentConnection->send(Messages::ServiceWorkerClientFetch::DidFail { }, fetchIdentifier);
 }
 
 void WebSWServerConnection::didNotHandleFetch(uint64_t fetchIdentifier)
 {
+    SWSERVERCONNECTION_RELEASE_LOG_IF_ALLOWED("didNotHandleFetch: fetchIdentifier: %llu", fetchIdentifier);
     m_contentConnection->send(Messages::ServiceWorkerClientFetch::DidNotHandle { }, fetchIdentifier);
 }