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
This commit is contained in:
David Parks 2023-01-31 21:10:26 +00:00
parent a72b3cc46c
commit 04713ddc93
2 changed files with 55 additions and 0 deletions

View File

@ -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__);

View File

@ -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) {