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, ¶mInfo);
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, ¶mValue);
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