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