diff options
Diffstat (limited to 'ipc/mscom/InterceptorLog.cpp')
| -rw-r--r-- | ipc/mscom/InterceptorLog.cpp | 526 |
1 files changed, 526 insertions, 0 deletions
diff --git a/ipc/mscom/InterceptorLog.cpp b/ipc/mscom/InterceptorLog.cpp new file mode 100644 index 0000000000..3d9d6ce9f8 --- /dev/null +++ b/ipc/mscom/InterceptorLog.cpp @@ -0,0 +1,526 @@ +/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */ +/* vim: set ts=8 sts=2 et sw=2 tw=80: */ +/* This Source Code Form is subject to the terms of the Mozilla Public + * License, v. 2.0. If a copy of the MPL was not distributed with this + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ + +#include "mozilla/mscom/InterceptorLog.h" + +#include <callobj.h> + +#include <utility> + +#include "MainThreadUtils.h" +#include "mozilla/ClearOnShutdown.h" +#include "mozilla/DebugOnly.h" +#include "mozilla/IntegerRange.h" +#include "mozilla/Mutex.h" +#include "mozilla/Services.h" +#include "mozilla/StaticPtr.h" +#include "mozilla/TimeStamp.h" +#include "mozilla/Unused.h" +#include "mozilla/mscom/Registration.h" +#include "mozilla/mscom/Utils.h" +#include "nsAppDirectoryServiceDefs.h" +#include "nsDirectoryServiceDefs.h" +#include "nsDirectoryServiceUtils.h" +#include "nsIObserver.h" +#include "nsIObserverService.h" +#include "nsIOutputStream.h" +#include "nsNetUtil.h" +#include "nsPrintfCString.h" +#include "nsReadableUtils.h" +#include "nsTArray.h" +#include "nsThreadUtils.h" +#include "nsXPCOMPrivate.h" +#include "nsXULAppAPI.h" +#include "prenv.h" + +using mozilla::DebugOnly; +using mozilla::Mutex; +using mozilla::MutexAutoLock; +using mozilla::NewNonOwningRunnableMethod; +using mozilla::StaticAutoPtr; +using mozilla::TimeDuration; +using mozilla::TimeStamp; +using mozilla::Unused; +using mozilla::mscom::ArrayData; +using mozilla::mscom::FindArrayData; +using mozilla::mscom::IsValidGUID; +using mozilla::services::GetObserverService; + +namespace { + +class ShutdownEvent final : public nsIObserver { + public: + NS_DECL_ISUPPORTS + NS_DECL_NSIOBSERVER + + private: + ~ShutdownEvent() {} +}; + +NS_IMPL_ISUPPORTS(ShutdownEvent, nsIObserver) + +class Logger final { + public: + explicit Logger(const nsACString& aLeafBaseName); + bool IsValid() { + MutexAutoLock lock(mMutex); + return !!mThread; + } + void LogQI(HRESULT aResult, IUnknown* aTarget, REFIID aIid, + IUnknown* aInterface, const TimeDuration* aOverheadDuration, + const TimeDuration* aGeckoDuration); + void CaptureFrame(ICallFrame* aCallFrame, IUnknown* aTargetInterface, + nsACString& aCapturedFrame); + void LogEvent(const nsACString& aCapturedFrame, + const TimeDuration& aOverheadDuration, + const TimeDuration& aGeckoDuration); + nsresult Shutdown(); + + private: + void OpenFile(); + void Flush(); + void CloseFile(); + void AssertRunningOnLoggerThread(); + bool VariantToString(const VARIANT& aVariant, nsACString& aOut, + LONG aIndex = 0); + bool TryParamAsGuid(REFIID aIid, ICallFrame* aCallFrame, + const CALLFRAMEPARAMINFO& aParamInfo, nsACString& aLine); + static double GetElapsedTime(); + + nsCOMPtr<nsIFile> mLogFileName; + nsCOMPtr<nsIOutputStream> mLogFile; // Only accessed by mThread + Mutex mMutex; // Guards mThread and mEntries + nsCOMPtr<nsIThread> mThread; + nsTArray<nsCString> mEntries; +}; + +Logger::Logger(const nsACString& aLeafBaseName) + : mMutex("mozilla::com::InterceptorLog::Logger") { + MOZ_ASSERT(NS_IsMainThread()); + nsCOMPtr<nsIFile> logFileName; + GeckoProcessType procType = XRE_GetProcessType(); + nsAutoCString leafName(aLeafBaseName); + nsresult rv; + if (procType == GeckoProcessType_Default) { + leafName.AppendLiteral("-Parent-"); + rv = NS_GetSpecialDirectory(NS_OS_TEMP_DIR, getter_AddRefs(logFileName)); + } else if (procType == GeckoProcessType_Content) { + leafName.AppendLiteral("-Content-"); +#if defined(MOZ_SANDBOX) + rv = NS_GetSpecialDirectory(NS_APP_CONTENT_PROCESS_TEMP_DIR, + getter_AddRefs(logFileName)); +#else + rv = NS_GetSpecialDirectory(NS_OS_TEMP_DIR, getter_AddRefs(logFileName)); +#endif // defined(MOZ_SANDBOX) + } else { + return; + } + if (NS_FAILED(rv)) { + return; + } + DWORD pid = GetCurrentProcessId(); + leafName.AppendPrintf("%u.log", pid); + // Using AppendNative here because Windows + rv = logFileName->AppendNative(leafName); + if (NS_FAILED(rv)) { + return; + } + mLogFileName.swap(logFileName); + + nsCOMPtr<nsIObserverService> obsSvc = GetObserverService(); + nsCOMPtr<nsIObserver> shutdownEvent = new ShutdownEvent(); + rv = obsSvc->AddObserver(shutdownEvent, NS_XPCOM_SHUTDOWN_THREADS_OBSERVER_ID, + false); + if (NS_FAILED(rv)) { + return; + } + + nsCOMPtr<nsIRunnable> openRunnable( + NewNonOwningRunnableMethod("Logger::OpenFile", this, &Logger::OpenFile)); + rv = NS_NewNamedThread("COM Intcpt Log", getter_AddRefs(mThread), + openRunnable); + if (NS_FAILED(rv)) { + obsSvc->RemoveObserver(shutdownEvent, + NS_XPCOM_SHUTDOWN_THREADS_OBSERVER_ID); + } +} + +void Logger::AssertRunningOnLoggerThread() { +#if defined(DEBUG) + nsCOMPtr<nsIThread> curThread; + if (NS_FAILED(NS_GetCurrentThread(getter_AddRefs(curThread)))) { + return; + } + MutexAutoLock lock(mMutex); + MOZ_ASSERT(curThread == mThread); +#endif +} + +void Logger::OpenFile() { + AssertRunningOnLoggerThread(); + MOZ_ASSERT(mLogFileName && !mLogFile); + NS_NewLocalFileOutputStream(getter_AddRefs(mLogFile), mLogFileName, + PR_WRONLY | PR_CREATE_FILE | PR_TRUNCATE, + PR_IRUSR | PR_IWUSR | PR_IRGRP); +} + +void Logger::CloseFile() { + AssertRunningOnLoggerThread(); + MOZ_ASSERT(mLogFile); + if (!mLogFile) { + return; + } + Flush(); + mLogFile->Close(); + mLogFile = nullptr; +} + +nsresult Logger::Shutdown() { + MOZ_ASSERT(NS_IsMainThread()); + nsresult rv = mThread->Dispatch( + NewNonOwningRunnableMethod("Logger::CloseFile", this, &Logger::CloseFile), + NS_DISPATCH_NORMAL); + NS_WARNING_ASSERTION(NS_SUCCEEDED(rv), "Dispatch failed"); + + rv = mThread->Shutdown(); + NS_WARNING_ASSERTION(NS_SUCCEEDED(rv), "Shutdown failed"); + return NS_OK; +} + +bool Logger::VariantToString(const VARIANT& aVariant, nsACString& aOut, + LONG aIndex) { + switch (aVariant.vt) { + case VT_DISPATCH: { + aOut.AppendPrintf("(IDispatch*) 0x%0p", aVariant.pdispVal); + return true; + } + case VT_DISPATCH | VT_BYREF: { + aOut.AppendPrintf("(IDispatch*) 0x%0p", (aVariant.ppdispVal)[aIndex]); + return true; + } + case VT_UNKNOWN: { + aOut.AppendPrintf("(IUnknown*) 0x%0p", aVariant.punkVal); + return true; + } + case VT_UNKNOWN | VT_BYREF: { + aOut.AppendPrintf("(IUnknown*) 0x%0p", (aVariant.ppunkVal)[aIndex]); + return true; + } + case VT_VARIANT | VT_BYREF: { + return VariantToString((aVariant.pvarVal)[aIndex], aOut); + } + case VT_I4 | VT_BYREF: { + aOut.AppendPrintf("%d", aVariant.plVal[aIndex]); + return true; + } + case VT_UI4 | VT_BYREF: { + aOut.AppendPrintf("%u", aVariant.pulVal[aIndex]); + return true; + } + case VT_I4: { + aOut.AppendPrintf("%d", aVariant.lVal); + return true; + } + case VT_UI4: { + aOut.AppendPrintf("%u", aVariant.ulVal); + return true; + } + case VT_EMPTY: { + aOut.AppendLiteral("(empty VARIANT)"); + return true; + } + case VT_NULL: { + aOut.AppendLiteral("(null VARIANT)"); + return true; + } + case VT_BSTR: { + aOut.AppendPrintf("\"%S\"", aVariant.bstrVal); + return true; + } + case VT_BSTR | VT_BYREF: { + aOut.AppendPrintf("\"%S\"", *aVariant.pbstrVal); + return true; + } + default: { + aOut.AppendPrintf("(VariantToString failed, VARTYPE == 0x%04hx)", + aVariant.vt); + return false; + } + } +} + +/* static */ +double Logger::GetElapsedTime() { + TimeStamp ts = TimeStamp::Now(); + TimeDuration duration = ts - TimeStamp::ProcessCreation(); + return duration.ToMicroseconds(); +} + +void Logger::LogQI(HRESULT aResult, IUnknown* aTarget, REFIID aIid, + IUnknown* aInterface, const TimeDuration* aOverheadDuration, + const TimeDuration* aGeckoDuration) { + if (FAILED(aResult)) { + return; + } + + double elapsed = GetElapsedTime(); + + nsAutoCString strOverheadDuration; + if (aOverheadDuration) { + strOverheadDuration.AppendPrintf("%.3f", + aOverheadDuration->ToMicroseconds()); + } else { + strOverheadDuration.AppendLiteral("(none)"); + } + + nsAutoCString strGeckoDuration; + if (aGeckoDuration) { + strGeckoDuration.AppendPrintf("%.3f", aGeckoDuration->ToMicroseconds()); + } else { + strGeckoDuration.AppendLiteral("(none)"); + } + + nsPrintfCString line("%.3f\t%s\t%s\t0x%0p\tIUnknown::QueryInterface\t([in] ", + elapsed, strOverheadDuration.get(), + strGeckoDuration.get(), aTarget); + + WCHAR buf[39] = {0}; + if (StringFromGUID2(aIid, buf, mozilla::ArrayLength(buf))) { + line.AppendPrintf("%S", buf); + } else { + line.AppendLiteral("(IID Conversion Failed)"); + } + line.AppendPrintf(", [out] 0x%p)\t0x%08X\n", aInterface, aResult); + + MutexAutoLock lock(mMutex); + mEntries.AppendElement(std::move(line)); + mThread->Dispatch( + NewNonOwningRunnableMethod("Logger::Flush", this, &Logger::Flush), + NS_DISPATCH_NORMAL); +} + +bool Logger::TryParamAsGuid(REFIID aIid, ICallFrame* aCallFrame, + const CALLFRAMEPARAMINFO& aParamInfo, + nsACString& aLine) { + if (aIid != IID_IServiceProvider) { + return false; + } + + GUID** guid = reinterpret_cast<GUID**>( + static_cast<BYTE*>(aCallFrame->GetStackLocation()) + + aParamInfo.stackOffset); + + if (!IsValidGUID(**guid)) { + return false; + } + + WCHAR buf[39] = {0}; + if (!StringFromGUID2(**guid, buf, mozilla::ArrayLength(buf))) { + return false; + } + + aLine.AppendPrintf("%S", buf); + return true; +} + +void Logger::CaptureFrame(ICallFrame* aCallFrame, IUnknown* aTargetInterface, + nsACString& aCapturedFrame) { + aCapturedFrame.Truncate(); + + // (1) Gather info about the call + CALLFRAMEINFO callInfo; + HRESULT hr = aCallFrame->GetInfo(&callInfo); + if (FAILED(hr)) { + return; + } + + PWSTR interfaceName = nullptr; + PWSTR methodName = nullptr; + hr = aCallFrame->GetNames(&interfaceName, &methodName); + if (FAILED(hr)) { + return; + } + + // (2) Serialize the call + nsPrintfCString line("0x%p\t%S::%S\t(", aTargetInterface, interfaceName, + methodName); + + CoTaskMemFree(interfaceName); + interfaceName = nullptr; + CoTaskMemFree(methodName); + methodName = nullptr; + + // Check for supplemental array data + const ArrayData* arrayData = FindArrayData(callInfo.iid, callInfo.iMethod); + + for (ULONG paramIndex = 0; paramIndex < callInfo.cParams; ++paramIndex) { + CALLFRAMEPARAMINFO paramInfo; + hr = aCallFrame->GetParamInfo(paramIndex, ¶mInfo); + if (SUCCEEDED(hr)) { + line.AppendLiteral("["); + if (paramInfo.fIn) { + line.AppendLiteral("in"); + } + if (paramInfo.fOut) { + line.AppendLiteral("out"); + } + line.AppendLiteral("] "); + } + VARIANT paramValue; + hr = aCallFrame->GetParam(paramIndex, ¶mValue); + if (SUCCEEDED(hr)) { + if (arrayData && paramIndex == arrayData->mArrayParamIndex) { + VARIANT lengthParam; + hr = aCallFrame->GetParam(arrayData->mLengthParamIndex, &lengthParam); + if (SUCCEEDED(hr)) { + line.AppendLiteral("{ "); + StringJoinAppend(line, ", "_ns, + mozilla::IntegerRange<LONG>(0, *lengthParam.plVal), + [this, ¶mValue](nsACString& line, const LONG i) { + VariantToString(paramValue, line, i); + }); + line.AppendLiteral(" }"); + } else { + line.AppendPrintf("(GetParam failed with HRESULT 0x%08X)", hr); + } + } else { + VariantToString(paramValue, line); + } + } else if (hr != DISP_E_BADVARTYPE || + !TryParamAsGuid(callInfo.iid, aCallFrame, paramInfo, line)) { + line.AppendPrintf("(GetParam failed with HRESULT 0x%08X)", hr); + } + if (paramIndex < callInfo.cParams - 1) { + line.AppendLiteral(", "); + } + } + line.AppendLiteral(")\t"); + + HRESULT callResult = aCallFrame->GetReturnValue(); + line.AppendPrintf("0x%08X\n", callResult); + + aCapturedFrame = std::move(line); +} + +void Logger::LogEvent(const nsACString& aCapturedFrame, + const TimeDuration& aOverheadDuration, + const TimeDuration& aGeckoDuration) { + double elapsed = GetElapsedTime(); + + nsPrintfCString line("%.3f\t%.3f\t%.3f\t%s", elapsed, + aOverheadDuration.ToMicroseconds(), + aGeckoDuration.ToMicroseconds(), + PromiseFlatCString(aCapturedFrame).get()); + + MutexAutoLock lock(mMutex); + mEntries.AppendElement(line); + mThread->Dispatch( + NewNonOwningRunnableMethod("Logger::Flush", this, &Logger::Flush), + NS_DISPATCH_NORMAL); +} + +void Logger::Flush() { + AssertRunningOnLoggerThread(); + MOZ_ASSERT(mLogFile); + if (!mLogFile) { + return; + } + nsTArray<nsCString> linesToWrite; + { // Scope for lock + MutexAutoLock lock(mMutex); + linesToWrite = std::move(mEntries); + } + + for (uint32_t i = 0, len = linesToWrite.Length(); i < len; ++i) { + uint32_t bytesWritten; + nsCString& line = linesToWrite[i]; + nsresult rv = mLogFile->Write(line.get(), line.Length(), &bytesWritten); + Unused << NS_WARN_IF(NS_FAILED(rv)); + } +} + +StaticAutoPtr<Logger> sLogger; + +NS_IMETHODIMP +ShutdownEvent::Observe(nsISupports* aSubject, const char* aTopic, + const char16_t* aData) { + if (strcmp(aTopic, NS_XPCOM_SHUTDOWN_THREADS_OBSERVER_ID)) { + MOZ_ASSERT(false); + return NS_ERROR_NOT_IMPLEMENTED; + } + MOZ_ASSERT(sLogger); + Unused << NS_WARN_IF(NS_FAILED(sLogger->Shutdown())); + nsCOMPtr<nsIObserver> kungFuDeathGrip(this); + nsCOMPtr<nsIObserverService> obsSvc = GetObserverService(); + obsSvc->RemoveObserver(this, aTopic); + return NS_OK; +} +} // anonymous namespace + +static bool MaybeCreateLog(const char* aEnvVarName) { + MOZ_ASSERT(NS_IsMainThread()); + MOZ_ASSERT(XRE_IsContentProcess() || XRE_IsParentProcess()); + MOZ_ASSERT(!sLogger); + const char* leafBaseName = PR_GetEnv(aEnvVarName); + if (!leafBaseName) { + return false; + } + nsDependentCString strLeafBaseName(leafBaseName); + if (strLeafBaseName.IsEmpty()) { + return false; + } + sLogger = new Logger(strLeafBaseName); + if (!sLogger->IsValid()) { + sLogger = nullptr; + return false; + } + ClearOnShutdown(&sLogger); + return true; +} + +namespace mozilla { +namespace mscom { + +/* static */ +bool InterceptorLog::Init() { + static const bool isEnabled = MaybeCreateLog("MOZ_MSCOM_LOG_BASENAME"); + return isEnabled; +} + +/* static */ +void InterceptorLog::QI(HRESULT aResult, IUnknown* aTarget, REFIID aIid, + IUnknown* aInterface, + const TimeDuration* aOverheadDuration, + const TimeDuration* aGeckoDuration) { + if (!sLogger) { + return; + } + sLogger->LogQI(aResult, aTarget, aIid, aInterface, aOverheadDuration, + aGeckoDuration); +} + +/* static */ +void InterceptorLog::CaptureFrame(ICallFrame* aCallFrame, + IUnknown* aTargetInterface, + nsACString& aCapturedFrame) { + if (!sLogger) { + return; + } + sLogger->CaptureFrame(aCallFrame, aTargetInterface, aCapturedFrame); +} + +/* static */ +void InterceptorLog::Event(const nsACString& aCapturedFrame, + const TimeDuration& aOverheadDuration, + const TimeDuration& aGeckoDuration) { + if (!sLogger) { + return; + } + sLogger->LogEvent(aCapturedFrame, aOverheadDuration, aGeckoDuration); +} + +} // namespace mscom +} // namespace mozilla |