ipc/mscom/InterceptorLog.cpp

   1 /* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
   2 /* vim: set ts=8 sts=2 et sw=2 tw=80: */
   3 /* This Source Code Form is subject to the terms of the Mozilla Public
   4  * License, v. 2.0. If a copy of the MPL was not distributed with this
   5  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
   6
   7 #include "mozilla/mscom/InterceptorLog.h"
   8
   9 #include <callobj.h>
  10
  11 #include <utility>
  12
  13 #include "MainThreadUtils.h"
  14 #include "mozilla/ClearOnShutdown.h"
  15 #include "mozilla/DebugOnly.h"
  16 #include "mozilla/IntegerRange.h"
  17 #include "mozilla/Mutex.h"
  18 #include "mozilla/Services.h"
  19 #include "mozilla/StaticPtr.h"
  20 #include "mozilla/TimeStamp.h"
  21 #include "mozilla/Unused.h"
  22 #include "mozilla/mscom/Registration.h"
  23 #include "mozilla/mscom/Utils.h"
  24 #include "nsAppDirectoryServiceDefs.h"
  25 #include "nsDirectoryServiceDefs.h"
  26 #include "nsDirectoryServiceUtils.h"
  27 #include "nsIObserver.h"
  28 #include "nsIObserverService.h"
  29 #include "nsIOutputStream.h"
  30 #include "nsNetUtil.h"
  31 #include "nsPrintfCString.h"
  32 #include "nsReadableUtils.h"
  33 #include "nsTArray.h"
  34 #include "nsThreadUtils.h"
  35 #include "nsXPCOMPrivate.h"
  36 #include "nsXULAppAPI.h"
  37 #include "prenv.h"
  38
  39 using mozilla::DebugOnly;
  40 using mozilla::Mutex;
  41 using mozilla::MutexAutoLock;
  42 using mozilla::NewNonOwningRunnableMethod;
  43 using mozilla::StaticAutoPtr;
  44 using mozilla::TimeDuration;
  45 using mozilla::TimeStamp;
  46 using mozilla::Unused;
  47 using mozilla::mscom::ArrayData;
  48 using mozilla::mscom::FindArrayData;
  49 using mozilla::mscom::IsValidGUID;
  50 using mozilla::services::GetObserverService;
  51
  52 namespace {
  53
  54 class ShutdownEvent final : public nsIObserver {
  55  public:
  56   NS_DECL_ISUPPORTS
  57   NS_DECL_NSIOBSERVER
  58
  59  private:
  60   ~ShutdownEvent() {}
  61 };
  62
  63 NS_IMPL_ISUPPORTS(ShutdownEvent, nsIObserver)
  64
  65 class Logger final {
  66  public:
  67   explicit Logger(const nsACString& aLeafBaseName);
  68   bool IsValid() {
  69     MutexAutoLock lock(mMutex);
  70     return !!mThread;
  71   }
  72   void LogQI(HRESULT aResult, IUnknown* aTarget, REFIID aIid,
  73              IUnknown* aInterface, const TimeDuration* aOverheadDuration,
  74              const TimeDuration* aGeckoDuration);
  75   void CaptureFrame(ICallFrame* aCallFrame, IUnknown* aTargetInterface,
  76                     nsACString& aCapturedFrame);
  77   void LogEvent(const nsACString& aCapturedFrame,
  78                 const TimeDuration& aOverheadDuration,
  79                 const TimeDuration& aGeckoDuration);
  80   nsresult Shutdown();
  81
  82  private:
  83   void OpenFile();
  84   void Flush();
  85   void CloseFile();
  86   void AssertRunningOnLoggerThread();
  87   bool VariantToString(const VARIANT& aVariant, nsACString& aOut,
  88                        LONG aIndex = 0);
  89   bool TryParamAsGuid(REFIID aIid, ICallFrame* aCallFrame,
  90                       const CALLFRAMEPARAMINFO& aParamInfo, nsACString& aLine);
  91   static double GetElapsedTime();
  92
  93   nsCOMPtr<nsIFile> mLogFileName;
  94   nsCOMPtr<nsIOutputStream> mLogFile;  // Only accessed by mThread
  95   Mutex mMutex MOZ_UNANNOTATED;        // Guards mThread and mEntries
  96   nsCOMPtr<nsIThread> mThread;
  97   nsTArray<nsCString> mEntries;
  98 };
  99
 100 Logger::Logger(const nsACString& aLeafBaseName)
 101     : mMutex("mozilla::com::InterceptorLog::Logger") {
 102   MOZ_ASSERT(NS_IsMainThread());
 103   nsCOMPtr<nsIFile> logFileName;
 104   GeckoProcessType procType = XRE_GetProcessType();
 105   nsAutoCString leafName(aLeafBaseName);
 106   nsresult rv;
 107   if (procType == GeckoProcessType_Default) {
 108     leafName.AppendLiteral("-Parent-");
 109     rv = NS_GetSpecialDirectory(NS_OS_TEMP_DIR, getter_AddRefs(logFileName));
 110   } else if (procType == GeckoProcessType_Content) {
 111     leafName.AppendLiteral("-Content-");
 112 #if defined(MOZ_SANDBOX)
 113     rv = NS_GetSpecialDirectory(NS_APP_CONTENT_PROCESS_TEMP_DIR,
 114                                 getter_AddRefs(logFileName));
 115 #else
 116     rv = NS_GetSpecialDirectory(NS_OS_TEMP_DIR, getter_AddRefs(logFileName));
 117 #endif  // defined(MOZ_SANDBOX)
 118   } else {
 119     return;
 120   }
 121   if (NS_FAILED(rv)) {
 122     return;
 123   }
 124   DWORD pid = GetCurrentProcessId();
 125   leafName.AppendPrintf("%lu.log", pid);
 126   // Using AppendNative here because Windows
 127   rv = logFileName->AppendNative(leafName);
 128   if (NS_FAILED(rv)) {
 129     return;
 130   }
 131   mLogFileName.swap(logFileName);
 132
 133   nsCOMPtr<nsIObserverService> obsSvc = GetObserverService();
 134   nsCOMPtr<nsIObserver> shutdownEvent = new ShutdownEvent();
 135   rv = obsSvc->AddObserver(shutdownEvent, NS_XPCOM_SHUTDOWN_THREADS_OBSERVER_ID,
 136                            false);
 137   if (NS_FAILED(rv)) {
 138     return;
 139   }
 140
 141   nsCOMPtr<nsIRunnable> openRunnable(
 142       NewNonOwningRunnableMethod("Logger::OpenFile", this, &Logger::OpenFile));
 143   rv = NS_NewNamedThread("COM Intcpt Log", getter_AddRefs(mThread),
 144                          openRunnable);
 145   if (NS_FAILED(rv)) {
 146     obsSvc->RemoveObserver(shutdownEvent,
 147                            NS_XPCOM_SHUTDOWN_THREADS_OBSERVER_ID);
 148   }
 149 }
 150
 151 void Logger::AssertRunningOnLoggerThread() {
 152 #if defined(DEBUG)
 153   nsCOMPtr<nsIThread> curThread;
 154   if (NS_FAILED(NS_GetCurrentThread(getter_AddRefs(curThread)))) {
 155     return;
 156   }
 157   MutexAutoLock lock(mMutex);
 158   MOZ_ASSERT(curThread == mThread);
 159 #endif
 160 }
 161
 162 void Logger::OpenFile() {
 163   AssertRunningOnLoggerThread();
 164   MOZ_ASSERT(mLogFileName && !mLogFile);
 165   NS_NewLocalFileOutputStream(getter_AddRefs(mLogFile), mLogFileName,
 166                               PR_WRONLY | PR_CREATE_FILE | PR_TRUNCATE,
 167                               PR_IRUSR | PR_IWUSR | PR_IRGRP);
 168 }
 169
 170 void Logger::CloseFile() {
 171   AssertRunningOnLoggerThread();
 172   MOZ_ASSERT(mLogFile);
 173   if (!mLogFile) {
 174     return;
 175   }
 176   Flush();
 177   mLogFile->Close();
 178   mLogFile = nullptr;
 179 }
 180
 181 nsresult Logger::Shutdown() {
 182   MOZ_ASSERT(NS_IsMainThread());
 183   nsresult rv = mThread->Dispatch(
 184       NewNonOwningRunnableMethod("Logger::CloseFile", this, &Logger::CloseFile),
 185       NS_DISPATCH_NORMAL);
 186   NS_WARNING_ASSERTION(NS_SUCCEEDED(rv), "Dispatch failed");
 187
 188   rv = mThread->Shutdown();
 189   NS_WARNING_ASSERTION(NS_SUCCEEDED(rv), "Shutdown failed");
 190   (void)rv;
 191   return NS_OK;
 192 }
 193
 194 bool Logger::VariantToString(const VARIANT& aVariant, nsACString& aOut,
 195                              LONG aIndex) {
 196   switch (aVariant.vt) {
 197     case VT_DISPATCH: {
 198       aOut.AppendPrintf("(IDispatch*) 0x%p", aVariant.pdispVal);
 199       return true;
 200     }
 201     case VT_DISPATCH | VT_BYREF: {
 202       aOut.AppendPrintf("(IDispatch*) 0x%p", (aVariant.ppdispVal)[aIndex]);
 203       return true;
 204     }
 205     case VT_UNKNOWN: {
 206       aOut.AppendPrintf("(IUnknown*) 0x%p", aVariant.punkVal);
 207       return true;
 208     }
 209     case VT_UNKNOWN | VT_BYREF: {
 210       aOut.AppendPrintf("(IUnknown*) 0x%p", (aVariant.ppunkVal)[aIndex]);
 211       return true;
 212     }
 213     case VT_VARIANT | VT_BYREF: {
 214       return VariantToString((aVariant.pvarVal)[aIndex], aOut);
 215     }
 216     case VT_I4 | VT_BYREF: {
 217       aOut.AppendPrintf("%ld", aVariant.plVal[aIndex]);
 218       return true;
 219     }
 220     case VT_UI4 | VT_BYREF: {
 221       aOut.AppendPrintf("%lu", aVariant.pulVal[aIndex]);
 222       return true;
 223     }
 224     case VT_I4: {
 225       aOut.AppendPrintf("%ld", aVariant.lVal);
 226       return true;
 227     }
 228     case VT_UI4: {
 229       aOut.AppendPrintf("%lu", aVariant.ulVal);
 230       return true;
 231     }
 232     case VT_EMPTY: {
 233       aOut.AppendLiteral("(empty VARIANT)");
 234       return true;
 235     }
 236     case VT_NULL: {
 237       aOut.AppendLiteral("(null VARIANT)");
 238       return true;
 239     }
 240     case VT_BSTR: {
 241       aOut.AppendPrintf("\"%S\"", aVariant.bstrVal);
 242       return true;
 243     }
 244     case VT_BSTR | VT_BYREF: {
 245       aOut.AppendPrintf("\"%S\"", *aVariant.pbstrVal);
 246       return true;
 247     }
 248     default: {
 249       aOut.AppendPrintf("(VariantToString failed, VARTYPE == 0x%04hx)",
 250                         aVariant.vt);
 251       return false;
 252     }
 253   }
 254 }
 255
 256 /* static */
 257 double Logger::GetElapsedTime() {
 258   TimeStamp ts = TimeStamp::Now();
 259   TimeDuration duration = ts - TimeStamp::ProcessCreation();
 260   return duration.ToMicroseconds();
 261 }
 262
 263 void Logger::LogQI(HRESULT aResult, IUnknown* aTarget, REFIID aIid,
 264                    IUnknown* aInterface, const TimeDuration* aOverheadDuration,
 265                    const TimeDuration* aGeckoDuration) {
 266   if (FAILED(aResult)) {
 267     return;
 268   }
 269
 270   double elapsed = GetElapsedTime();
 271
 272   nsAutoCString strOverheadDuration;
 273   if (aOverheadDuration) {
 274     strOverheadDuration.AppendPrintf("%.3f",
 275                                      aOverheadDuration->ToMicroseconds());
 276   } else {
 277     strOverheadDuration.AppendLiteral("(none)");
 278   }
 279
 280   nsAutoCString strGeckoDuration;
 281   if (aGeckoDuration) {
 282     strGeckoDuration.AppendPrintf("%.3f", aGeckoDuration->ToMicroseconds());
 283   } else {
 284     strGeckoDuration.AppendLiteral("(none)");
 285   }
 286
 287   nsPrintfCString line("%.3f\t%s\t%s\t0x%p\tIUnknown::QueryInterface\t([in] ",
 288                        elapsed, strOverheadDuration.get(),
 289                        strGeckoDuration.get(), aTarget);
 290
 291   WCHAR buf[39] = {0};
 292   if (StringFromGUID2(aIid, buf, mozilla::ArrayLength(buf))) {
 293     line.AppendPrintf("%S", buf);
 294   } else {
 295     line.AppendLiteral("(IID Conversion Failed)");
 296   }
 297   line.AppendPrintf(", [out] 0x%p)\t0x%08lX\n", aInterface, aResult);
 298
 299   MutexAutoLock lock(mMutex);
 300   mEntries.AppendElement(std::move(line));
 301   mThread->Dispatch(
 302       NewNonOwningRunnableMethod("Logger::Flush", this, &Logger::Flush),
 303       NS_DISPATCH_NORMAL);
 304 }
 305
 306 bool Logger::TryParamAsGuid(REFIID aIid, ICallFrame* aCallFrame,
 307                             const CALLFRAMEPARAMINFO& aParamInfo,
 308                             nsACString& aLine) {
 309   if (aIid != IID_IServiceProvider) {
 310     return false;
 311   }
 312
 313   GUID** guid = reinterpret_cast<GUID**>(
 314       static_cast<BYTE*>(aCallFrame->GetStackLocation()) +
 315       aParamInfo.stackOffset);
 316
 317   if (!IsValidGUID(**guid)) {
 318     return false;
 319   }
 320
 321   WCHAR buf[39] = {0};
 322   if (!StringFromGUID2(**guid, buf, mozilla::ArrayLength(buf))) {
 323     return false;
 324   }
 325
 326   aLine.AppendPrintf("%S", buf);
 327   return true;
 328 }
 329
 330 void Logger::CaptureFrame(ICallFrame* aCallFrame, IUnknown* aTargetInterface,
 331                           nsACString& aCapturedFrame) {
 332   aCapturedFrame.Truncate();
 333
 334   // (1) Gather info about the call
 335   CALLFRAMEINFO callInfo;
 336   HRESULT hr = aCallFrame->GetInfo(&callInfo);
 337   if (FAILED(hr)) {
 338     return;
 339   }
 340
 341   PWSTR interfaceName = nullptr;
 342   PWSTR methodName = nullptr;
 343   hr = aCallFrame->GetNames(&interfaceName, &methodName);
 344   if (FAILED(hr)) {
 345     return;
 346   }
 347
 348   // (2) Serialize the call
 349   nsPrintfCString line("0x%p\t%S::%S\t(", aTargetInterface, interfaceName,
 350                        methodName);
 351
 352   CoTaskMemFree(interfaceName);
 353   interfaceName = nullptr;
 354   CoTaskMemFree(methodName);
 355   methodName = nullptr;
 356
 357   // Check for supplemental array data
 358   const ArrayData* arrayData = FindArrayData(callInfo.iid, callInfo.iMethod);
 359
 360   for (ULONG paramIndex = 0; paramIndex < callInfo.cParams; ++paramIndex) {
 361     CALLFRAMEPARAMINFO paramInfo;
 362     hr = aCallFrame->GetParamInfo(paramIndex, &paramInfo);
 363     if (SUCCEEDED(hr)) {
 364       line.AppendLiteral("[");
 365       if (paramInfo.fIn) {
 366         line.AppendLiteral("in");
 367       }
 368       if (paramInfo.fOut) {
 369         line.AppendLiteral("out");
 370       }
 371       line.AppendLiteral("] ");
 372     }
 373     VARIANT paramValue;
 374     hr = aCallFrame->GetParam(paramIndex, &paramValue);
 375     if (SUCCEEDED(hr)) {
 376       if (arrayData && paramIndex == arrayData->mArrayParamIndex) {
 377         VARIANT lengthParam;
 378         hr = aCallFrame->GetParam(arrayData->mLengthParamIndex, &lengthParam);
 379         if (SUCCEEDED(hr)) {
 380           line.AppendLiteral("{ ");
 381           StringJoinAppend(line, ", "_ns,
 382                            mozilla::IntegerRange<LONG>(0, *lengthParam.plVal),
 383                            [this, &paramValue](nsACString& line, const LONG i) {
 384                              VariantToString(paramValue, line, i);
 385                            });
 386           line.AppendLiteral(" }");
 387         } else {
 388           line.AppendPrintf("(GetParam failed with HRESULT 0x%08lX)", hr);
 389         }
 390       } else {
 391         VariantToString(paramValue, line);
 392       }
 393     } else if (hr != DISP_E_BADVARTYPE ||
 394                !TryParamAsGuid(callInfo.iid, aCallFrame, paramInfo, line)) {
 395       line.AppendPrintf("(GetParam failed with HRESULT 0x%08lX)", hr);
 396     }
 397     if (paramIndex < callInfo.cParams - 1) {
 398       line.AppendLiteral(", ");
 399     }
 400   }
 401   line.AppendLiteral(")\t");
 402
 403   HRESULT callResult = aCallFrame->GetReturnValue();
 404   line.AppendPrintf("0x%08lX\n", callResult);
 405
 406   aCapturedFrame = std::move(line);
 407 }
 408
 409 void Logger::LogEvent(const nsACString& aCapturedFrame,
 410                       const TimeDuration& aOverheadDuration,
 411                       const TimeDuration& aGeckoDuration) {
 412   double elapsed = GetElapsedTime();
 413
 414   nsPrintfCString line("%.3f\t%.3f\t%.3f\t%s", elapsed,
 415                        aOverheadDuration.ToMicroseconds(),
 416                        aGeckoDuration.ToMicroseconds(),
 417                        PromiseFlatCString(aCapturedFrame).get());
 418
 419   MutexAutoLock lock(mMutex);
 420   mEntries.AppendElement(line);
 421   mThread->Dispatch(
 422       NewNonOwningRunnableMethod("Logger::Flush", this, &Logger::Flush),
 423       NS_DISPATCH_NORMAL);
 424 }
 425
 426 void Logger::Flush() {
 427   AssertRunningOnLoggerThread();
 428   MOZ_ASSERT(mLogFile);
 429   if (!mLogFile) {
 430     return;
 431   }
 432   nsTArray<nsCString> linesToWrite;
 433   {  // Scope for lock
 434     MutexAutoLock lock(mMutex);
 435     linesToWrite = std::move(mEntries);
 436   }
 437
 438   for (uint32_t i = 0, len = linesToWrite.Length(); i < len; ++i) {
 439     uint32_t bytesWritten;
 440     nsCString& line = linesToWrite[i];
 441     nsresult rv = mLogFile->Write(line.get(), line.Length(), &bytesWritten);
 442     Unused << NS_WARN_IF(NS_FAILED(rv));
 443   }
 444 }
 445
 446 StaticAutoPtr<Logger> sLogger;
 447
 448 NS_IMETHODIMP
 449 ShutdownEvent::Observe(nsISupports* aSubject, const char* aTopic,
 450                        const char16_t* aData) {
 451   if (strcmp(aTopic, NS_XPCOM_SHUTDOWN_THREADS_OBSERVER_ID)) {
 452     MOZ_ASSERT(false);
 453     return NS_ERROR_NOT_IMPLEMENTED;
 454   }
 455   MOZ_ASSERT(sLogger);
 456   Unused << NS_WARN_IF(NS_FAILED(sLogger->Shutdown()));
 457   nsCOMPtr<nsIObserver> kungFuDeathGrip(this);
 458   nsCOMPtr<nsIObserverService> obsSvc = GetObserverService();
 459   obsSvc->RemoveObserver(this, aTopic);
 460   return NS_OK;
 461 }
 462 }  // anonymous namespace
 463
 464 static bool MaybeCreateLog(const char* aEnvVarName) {
 465   MOZ_ASSERT(NS_IsMainThread());
 466   MOZ_ASSERT(XRE_IsContentProcess() || XRE_IsParentProcess());
 467   MOZ_ASSERT(!sLogger);
 468   const char* leafBaseName = PR_GetEnv(aEnvVarName);
 469   if (!leafBaseName) {
 470     return false;
 471   }
 472   nsDependentCString strLeafBaseName(leafBaseName);
 473   if (strLeafBaseName.IsEmpty()) {
 474     return false;
 475   }
 476   sLogger = new Logger(strLeafBaseName);
 477   if (!sLogger->IsValid()) {
 478     sLogger = nullptr;
 479     return false;
 480   }
 481   ClearOnShutdown(&sLogger);
 482   return true;
 483 }
 484
 485 namespace mozilla {
 486 namespace mscom {
 487
 488 /* static */
 489 bool InterceptorLog::Init() {
 490   static const bool isEnabled = MaybeCreateLog("MOZ_MSCOM_LOG_BASENAME");
 491   return isEnabled;
 492 }
 493
 494 /* static */
 495 void InterceptorLog::QI(HRESULT aResult, IUnknown* aTarget, REFIID aIid,
 496                         IUnknown* aInterface,
 497                         const TimeDuration* aOverheadDuration,
 498                         const TimeDuration* aGeckoDuration) {
 499   if (!sLogger) {
 500     return;
 501   }
 502   sLogger->LogQI(aResult, aTarget, aIid, aInterface, aOverheadDuration,
 503                  aGeckoDuration);
 504 }
 505
 506 /* static */
 507 void InterceptorLog::CaptureFrame(ICallFrame* aCallFrame,
 508                                   IUnknown* aTargetInterface,
 509                                   nsACString& aCapturedFrame) {
 510   if (!sLogger) {
 511     return;
 512   }
 513   sLogger->CaptureFrame(aCallFrame, aTargetInterface, aCapturedFrame);
 514 }
 515
 516 /* static */
 517 void InterceptorLog::Event(const nsACString& aCapturedFrame,
 518                            const TimeDuration& aOverheadDuration,
 519                            const TimeDuration& aGeckoDuration) {
 520   if (!sLogger) {
 521     return;
 522   }
 523   sLogger->LogEvent(aCapturedFrame, aOverheadDuration, aGeckoDuration);
 524 }
 525
 526 }  // namespace mscom
 527 }  // namespace mozilla