Bug 1704500: Add logging to UtilityProcessHost/Manager r=gerard-majax

Adds a "utilityproc" log to trace utility process launch and shutdown steps.

Differential Revision: https://phabricator.services.mozilla.com/D155017

ipc/glue/UtilityProcessHost.cpp

@@ -28,6 +28,9 @@
 
 namespace mozilla::ipc {
 
+LazyLogModule gUtilityProcessLog("utilityproc");
+#define LOGD(...) MOZ_LOG(gUtilityProcessLog, LogLevel::Debug, (__VA_ARGS__))
+
 #if defined(XP_MACOSX) && defined(MOZ_SANDBOX)
 bool UtilityProcessHost::sLaunchWithMacSandbox = false;
 #endif
@@ -38,6 +41,9 @@ UtilityProcessHost::UtilityProcessHost(SandboxingKind aSandbox,
       mListener(std::move(aListener)),
       mLiveToken(new media::Refcountable<bool>(true)) {
   MOZ_COUNT_CTOR(UtilityProcessHost);
+  LOGD("[%p] UtilityProcessHost::UtilityProcessHost sandboxingKind=%" PRIu64,
+       this, aSandbox);
+
 #if defined(XP_MACOSX) && defined(MOZ_SANDBOX)
   if (!sLaunchWithMacSandbox) {
     sLaunchWithMacSandbox =
@@ -52,6 +58,12 @@ UtilityProcessHost::UtilityProcessHost(SandboxingKind aSandbox,
 
 UtilityProcessHost::~UtilityProcessHost() {
   MOZ_COUNT_DTOR(UtilityProcessHost);
+#if defined(MOZ_SANDBOX)
+  LOGD("[%p] UtilityProcessHost::~UtilityProcessHost sandboxingKind=%" PRIu64,
+       this, mSandbox);
+#else
+  LOGD("[%p] UtilityProcessHost::~UtilityProcessHost", this);
+#endif
 }
 
 bool UtilityProcessHost::Launch(StringVector aExtraOpts) {
@@ -60,6 +72,8 @@ bool UtilityProcessHost::Launch(StringVector aExtraOpts) {
   MOZ_ASSERT(mLaunchPhase == LaunchPhase::Unlaunched);
   MOZ_ASSERT(!mUtilityProcessParent);
 
+  LOGD("[%p] UtilityProcessHost::Launch", this);
+
   mPrefSerializer = MakeUnique<ipc::SharedPreferenceSerializer>();
   if (!mPrefSerializer->SerializeToSharedMemory(GeckoProcessType_Utility,
                                                 /* remoteType */ ""_ns)) {
@@ -107,6 +121,7 @@ bool UtilityProcessHost::Launch(StringVector aExtraOpts) {
     mPrefSerializer = nullptr;
     return false;
   }
+  LOGD("[%p] UtilityProcessHost::Launch launching async", this);
   return true;
 }
 
@@ -143,6 +158,7 @@ RefPtr<GenericNonExclusivePromise> UtilityProcessHost::LaunchPromise() {
 
 void UtilityProcessHost::OnChannelConnected(base::ProcessId peer_pid) {
   MOZ_ASSERT(!NS_IsMainThread());
+  LOGD("[%p] UtilityProcessHost::OnChannelConnected", this);
 
   GeckoChildProcessHost::OnChannelConnected(peer_pid);
 
@@ -157,6 +173,7 @@ void UtilityProcessHost::OnChannelConnected(base::ProcessId peer_pid) {
 
 void UtilityProcessHost::OnChannelError() {
   MOZ_ASSERT(!NS_IsMainThread());
+  LOGD("[%p] UtilityProcessHost::OnChannelError", this);
 
   GeckoChildProcessHost::OnChannelError();
 
@@ -221,6 +238,8 @@ void UtilityProcessHost::InitAfterConnect(bool aSucceeded) {
   Unused << GetActor()->SendInitProfiler(
       ProfilerParent::CreateForProcess(GetActor()->OtherPid()));
 
+  LOGD("[%p] UtilityProcessHost::InitAfterConnect succeeded", this);
+
   // Promise will be resolved later, from UtilityProcessParent when the child
   // will send the InitCompleted message.
 }
@@ -228,10 +247,14 @@ void UtilityProcessHost::InitAfterConnect(bool aSucceeded) {
 void UtilityProcessHost::Shutdown() {
   MOZ_ASSERT(NS_IsMainThread());
   MOZ_ASSERT(!mShutdownRequested);
+  LOGD("[%p] UtilityProcessHost::Shutdown", this);
 
   RejectPromise();
 
   if (mUtilityProcessParent) {
+    LOGD("[%p] UtilityProcessHost::Shutdown not destroying utility process.",
+         this);
+
     // OnChannelClosed uses this to check if the shutdown was expected or
     // unexpected.
     mShutdownRequested = true;
@@ -261,6 +284,7 @@ void UtilityProcessHost::Shutdown() {
 
 void UtilityProcessHost::OnChannelClosed() {
   MOZ_ASSERT(NS_IsMainThread());
+  LOGD("[%p] UtilityProcessHost::OnChannelClosed", this);
 
   RejectPromise();
 
@@ -277,6 +301,7 @@ void UtilityProcessHost::OnChannelClosed() {
 
 void UtilityProcessHost::KillHard(const char* aReason) {
   MOZ_ASSERT(NS_IsMainThread());
+  LOGD("[%p] UtilityProcessHost::KillHard", this);
 
   ProcessHandle handle = GetChildProcessHandle();
   if (!base::KillProcess(handle, base::PROCESS_END_KILLED_BY_USER)) {
@@ -288,6 +313,8 @@ void UtilityProcessHost::KillHard(const char* aReason) {
 
 void UtilityProcessHost::DestroyProcess() {
   MOZ_ASSERT(NS_IsMainThread());
+  LOGD("[%p] UtilityProcessHost::DestroyProcess", this);
+
   RejectPromise();
 
   // Any pending tasks will be cancelled from now on.
@@ -299,6 +326,7 @@ void UtilityProcessHost::DestroyProcess() {
 
 void UtilityProcessHost::ResolvePromise() {
   MOZ_ASSERT(NS_IsMainThread());
+  LOGD("[%p] UtilityProcessHost connected - resolving launch promise", this);
 
   if (!mLaunchPromiseSettled) {
     mLaunchPromise->Resolve(true, __func__);
@@ -311,6 +339,8 @@ void UtilityProcessHost::ResolvePromise() {
 
 void UtilityProcessHost::RejectPromise() {
   MOZ_ASSERT(NS_IsMainThread());
+  LOGD("[%p] UtilityProcessHost connection failed - rejecting launch promise",
+       this);
 
   if (!mLaunchPromiseSettled) {
     mLaunchPromise->Reject(NS_ERROR_FAILURE, __func__);

ipc/glue/UtilityProcessManager.cpp

@@ -25,6 +25,9 @@
 
 namespace mozilla::ipc {
 
+extern LazyLogModule gUtilityProcessLog;
+#define LOGD(...) MOZ_LOG(gUtilityProcessLog, LogLevel::Debug, (__VA_ARGS__))
+
 static StaticRefPtr<UtilityProcessManager> sSingleton;
 
 static bool sXPCOMShutdown = false;
@@ -50,6 +53,8 @@ RefPtr<UtilityProcessManager> UtilityProcessManager::GetIfExists() {
 }
 
 UtilityProcessManager::UtilityProcessManager() : mObserver(new Observer(this)) {
+  LOGD("[%p] UtilityProcessManager::UtilityProcessManager", this);
+
   // Start listening for pref changes so we can
   // forward them to the process once it is running.
   nsContentUtils::RegisterShutdownObserver(mObserver);
@@ -57,6 +62,8 @@ UtilityProcessManager::UtilityProcessManager() : mObserver(new Observer(this)) {
 }
 
 UtilityProcessManager::~UtilityProcessManager() {
+  LOGD("[%p] UtilityProcessManager::~UtilityProcessManager", this);
+
   // The Utility process should ALL have already been shut down.
   MOZ_ASSERT(NoMoreProcesses());
 }
@@ -80,6 +87,8 @@ UtilityProcessManager::Observer::Observe(nsISupports* aSubject,
 }
 
 void UtilityProcessManager::OnXPCOMShutdown() {
+  LOGD("[%p] UtilityProcessManager::OnXPCOMShutdown", this);
+
   MOZ_ASSERT(NS_IsMainThread());
   sXPCOMShutdown = true;
   nsContentUtils::UnregisterShutdownObserver(mObserver);
@@ -124,6 +133,9 @@ RefPtr<UtilityProcessManager::ProcessFields> UtilityProcessManager::GetProcess(
 
 RefPtr<GenericNonExclusivePromise> UtilityProcessManager::LaunchProcess(
     SandboxingKind aSandbox) {
+  LOGD("[%p] UtilityProcessManager::LaunchProcess SandboxingKind=%" PRIu64,
+       this, aSandbox);
+
   MOZ_ASSERT(NS_IsMainThread());
 
   if (IsShutdown()) {
@@ -213,6 +225,11 @@ RefPtr<GenericNonExclusivePromise> UtilityProcessManager::LaunchProcess(
 template <typename Actor>
 RefPtr<GenericNonExclusivePromise> UtilityProcessManager::StartUtility(
     RefPtr<Actor> aActor, SandboxingKind aSandbox) {
+  LOGD(
+      "[%p] UtilityProcessManager::StartUtility actor=%p "
+      "SandboxingKind=%" PRIu64,
+      this, aActor.get(), aSandbox);
+
   if (!aActor) {
     MOZ_ASSERT(false, "Actor singleton failure");
     return GenericNonExclusivePromise::CreateAndReject(NS_ERROR_FAILURE,
@@ -396,6 +413,8 @@ void UtilityProcessManager::OnProcessUnexpectedShutdown(
 }
 
 void UtilityProcessManager::CleanShutdownAllProcesses() {
+  LOGD("[%p] UtilityProcessManager::CleanShutdownAllProcesses", this);
+
   for (auto& it : mProcesses) {
     if (it) {
       DestroyProcess(it->mSandbox);
@@ -404,6 +423,9 @@ void UtilityProcessManager::CleanShutdownAllProcesses() {
 }
 
 void UtilityProcessManager::CleanShutdown(SandboxingKind aSandbox) {
+  LOGD("[%p] UtilityProcessManager::CleanShutdown SandboxingKind=%" PRIu64,
+       this, aSandbox);
+
   DestroyProcess(aSandbox);
 }
 
@@ -420,6 +442,9 @@ uint16_t UtilityProcessManager::AliveProcesses() {
 bool UtilityProcessManager::NoMoreProcesses() { return AliveProcesses() == 0; }
 
 void UtilityProcessManager::DestroyProcess(SandboxingKind aSandbox) {
+  LOGD("[%p] UtilityProcessManager::DestroyProcess SandboxingKind=%" PRIu64,
+       this, aSandbox);
+
   MOZ_RELEASE_ASSERT(NS_IsMainThread());
 
   if (AliveProcesses() <= 1) {