Bug 1690340 - Part 4: Insert the "Page Source" before the "Extensions for Developers...
[gecko.git] / xpcom / base / Logging.cpp
blobbfcef302a669b6ec7222f2e80a9c4f3e39653a11
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/. */
7 #include "mozilla/Logging.h"
9 #include <algorithm>
11 #include "mozilla/ClearOnShutdown.h"
12 #include "mozilla/FileUtils.h"
13 #include "mozilla/LateWriteChecks.h"
14 #include "mozilla/Mutex.h"
15 #include "mozilla/StaticPtr.h"
16 #include "mozilla/Printf.h"
17 #include "mozilla/Atomics.h"
18 #include "mozilla/Sprintf.h"
19 #include "mozilla/UniquePtrExtensions.h"
20 #include "MainThreadUtils.h"
21 #include "nsClassHashtable.h"
22 #include "nsDebug.h"
23 #include "nsDebugImpl.h"
24 #include "NSPRLogModulesParser.h"
25 #include "LogCommandLineHandler.h"
27 #include "prenv.h"
28 #ifdef XP_WIN
29 # include <fcntl.h>
30 # include <process.h>
31 #else
32 # include <sys/stat.h> // for umask()
33 # include <sys/types.h>
34 # include <unistd.h>
35 #endif
37 // NB: Initial amount determined by auditing the codebase for the total amount
38 // of unique module names and padding up to the next power of 2.
39 const uint32_t kInitialModuleCount = 256;
40 // When rotate option is added to the modules list, this is the hardcoded
41 // number of files we create and rotate. When there is rotate:40,
42 // we will keep four files per process, each limited to 10MB. Sum is 40MB,
43 // the given limit.
45 // (Note: When this is changed to be >= 10, SandboxBroker::LaunchApp must add
46 // another rule to allow logfile.?? be written by content processes.)
47 const uint32_t kRotateFilesNumber = 4;
49 namespace mozilla {
51 namespace detail {
53 void log_print(const LogModule* aModule, LogLevel aLevel, const char* aFmt,
54 ...) {
55 va_list ap;
56 va_start(ap, aFmt);
57 aModule->Printv(aLevel, aFmt, ap);
58 va_end(ap);
61 void log_print(const LogModule* aModule, LogLevel aLevel, TimeStamp* aStart,
62 const char* aFmt, ...) {
63 va_list ap;
64 va_start(ap, aFmt);
65 aModule->Printv(aLevel, aStart, aFmt, ap);
66 va_end(ap);
69 } // namespace detail
71 LogLevel ToLogLevel(int32_t aLevel) {
72 aLevel = std::min(aLevel, static_cast<int32_t>(LogLevel::Verbose));
73 aLevel = std::max(aLevel, static_cast<int32_t>(LogLevel::Disabled));
74 return static_cast<LogLevel>(aLevel);
77 static const char* ToLogStr(LogLevel aLevel) {
78 switch (aLevel) {
79 case LogLevel::Error:
80 return "E";
81 case LogLevel::Warning:
82 return "W";
83 case LogLevel::Info:
84 return "I";
85 case LogLevel::Debug:
86 return "D";
87 case LogLevel::Verbose:
88 return "V";
89 case LogLevel::Disabled:
90 default:
91 MOZ_CRASH("Invalid log level.");
92 return "";
96 namespace detail {
98 /**
99 * A helper class providing reference counting for FILE*.
100 * It encapsulates the following:
101 * - the FILE handle
102 * - the order number it was created for when rotating (actual path)
103 * - number of active references
105 class LogFile {
106 FILE* mFile;
107 uint32_t mFileNum;
109 public:
110 LogFile(FILE* aFile, uint32_t aFileNum)
111 : mFile(aFile), mFileNum(aFileNum), mNextToRelease(nullptr) {}
113 ~LogFile() {
114 fclose(mFile);
115 delete mNextToRelease;
118 FILE* File() const { return mFile; }
119 uint32_t Num() const { return mFileNum; }
121 LogFile* mNextToRelease;
124 static const char* ExpandLogFileName(const char* aFilename,
125 char (&buffer)[2048]) {
126 MOZ_ASSERT(aFilename);
127 static const char kPIDToken[] = MOZ_LOG_PID_TOKEN;
128 static const char kMOZLOGExt[] = MOZ_LOG_FILE_EXTENSION;
130 bool hasMozLogExtension = StringEndsWith(nsDependentCString(aFilename),
131 nsLiteralCString(kMOZLOGExt));
133 const char* pidTokenPtr = strstr(aFilename, kPIDToken);
134 if (pidTokenPtr &&
135 SprintfLiteral(buffer, "%.*s%s%d%s%s",
136 static_cast<int>(pidTokenPtr - aFilename), aFilename,
137 XRE_IsParentProcess() ? "-main." : "-child.",
138 base::GetCurrentProcId(), pidTokenPtr + strlen(kPIDToken),
139 hasMozLogExtension ? "" : kMOZLOGExt) > 0) {
140 return buffer;
143 if (!hasMozLogExtension &&
144 SprintfLiteral(buffer, "%s%s", aFilename, kMOZLOGExt) > 0) {
145 return buffer;
148 return aFilename;
151 // Drop initial lines from the given file until it is less than or equal to the
152 // given size.
154 // For simplicity and to reduce memory consumption, lines longer than the given
155 // long line size may be broken.
157 // This function uses `mkstemp` and `rename` on POSIX systems and `_mktemp_s`
158 // and `ReplaceFileA` on Win32 systems. `ReplaceFileA` was introduced in
159 // Windows 7 so it's available.
160 bool LimitFileToLessThanSize(const char* aFilename, uint32_t aSize,
161 uint16_t aLongLineSize = 16384) {
162 // `tempFilename` will be further updated below.
163 char tempFilename[2048];
164 SprintfLiteral(tempFilename, "%s.tempXXXXXX", aFilename);
166 bool failedToWrite = false;
168 { // Scope `file` and `temp`, so that they are definitely closed.
169 ScopedCloseFile file(fopen(aFilename, "rb"));
170 if (!file) {
171 return false;
174 if (fseek(file, 0, SEEK_END)) {
175 // If we can't seek for some reason, better to just not limit the log at
176 // all and hope to sort out large logs upon further analysis.
177 return false;
180 // `ftell` returns a positive `long`, which might be more than 32 bits.
181 uint64_t fileSize = static_cast<uint64_t>(ftell(file));
183 if (fileSize <= aSize) {
184 return true;
187 uint64_t minBytesToDrop = fileSize - aSize;
188 uint64_t numBytesDropped = 0;
190 if (fseek(file, 0, SEEK_SET)) {
191 // Same as above: if we can't seek, hope for the best.
192 return false;
195 ScopedCloseFile temp;
197 #if defined(OS_WIN)
198 // This approach was cribbed from
199 // https://searchfox.org/mozilla-central/rev/868935867c6241e1302e64cf9be8f56db0fd0d1c/xpcom/build/LateWriteChecks.cpp#158.
200 HANDLE hFile;
201 do {
202 // mkstemp isn't supported so keep trying until we get a file.
203 _mktemp_s(tempFilename, strlen(tempFilename) + 1);
204 hFile = CreateFileA(tempFilename, GENERIC_WRITE, 0, nullptr, CREATE_NEW,
205 FILE_ATTRIBUTE_NORMAL, nullptr);
206 } while (GetLastError() == ERROR_FILE_EXISTS);
208 if (hFile == INVALID_HANDLE_VALUE) {
209 NS_WARNING("INVALID_HANDLE_VALUE");
210 return false;
213 int fd = _open_osfhandle((intptr_t)hFile, _O_APPEND);
214 if (fd == -1) {
215 NS_WARNING("_open_osfhandle failed!");
216 return false;
219 temp.reset(_fdopen(fd, "ab"));
220 #elif defined(OS_POSIX)
222 // Coverity would prefer us to set a secure umask before using `mkstemp`.
223 // However, the umask is process-wide, so setting it may lead to difficult
224 // to debug complications; and it is fine for this particular short-lived
225 // temporary file to be insecure.
227 // coverity[SECURE_TEMP : FALSE]
228 int fd = mkstemp(tempFilename);
229 if (fd == -1) {
230 NS_WARNING("mkstemp failed!");
231 return false;
233 temp.reset(fdopen(fd, "ab"));
234 #else
235 # error Do not know how to open named temporary file
236 #endif
238 if (!temp) {
239 NS_WARNING(nsPrintfCString("could not open named temporary file %s",
240 tempFilename)
241 .get());
242 return false;
245 // `fgets` always null terminates. If the line is too long, it won't
246 // include a trailing '\n' but will be null-terminated.
247 UniquePtr<char[]> line = MakeUnique<char[]>(aLongLineSize + 1);
248 while (fgets(line.get(), aLongLineSize + 1, file)) {
249 if (numBytesDropped >= minBytesToDrop) {
250 if (fputs(line.get(), temp) < 0) {
251 NS_WARNING(
252 nsPrintfCString("fputs failed: ferror %d\n", ferror(temp)).get());
253 failedToWrite = true;
254 break;
256 } else {
257 // Binary mode avoids platform-specific wrinkles with text streams. In
258 // particular, on Windows, `\r\n` gets read as `\n` (and the reverse
259 // when writing), complicating this calculation.
260 numBytesDropped += strlen(line.get());
265 // At this point, `file` and `temp` are closed, so we can remove and rename.
266 if (failedToWrite) {
267 remove(tempFilename);
268 return false;
271 #if defined(OS_WIN)
272 if (!::ReplaceFileA(aFilename, tempFilename, nullptr, 0, 0, 0)) {
273 NS_WARNING(
274 nsPrintfCString("ReplaceFileA failed: %d\n", GetLastError()).get());
275 return false;
277 #elif defined(OS_POSIX)
278 if (rename(tempFilename, aFilename)) {
279 NS_WARNING(
280 nsPrintfCString("rename failed: %s (%d)\n", strerror(errno), errno)
281 .get());
282 return false;
284 #else
285 # error Do not know how to atomically replace file
286 #endif
288 return true;
291 } // namespace detail
293 namespace {
294 // Helper method that initializes an empty va_list to be empty.
295 void empty_va(va_list* va, ...) {
296 va_start(*va, va);
297 va_end(*va);
299 } // namespace
301 class LogModuleManager {
302 public:
303 LogModuleManager()
304 : mModulesLock("logmodules"),
305 mModules(kInitialModuleCount),
306 mPrintEntryCount(0),
307 mOutFile(nullptr),
308 mToReleaseFile(nullptr),
309 mOutFileNum(0),
310 mOutFilePath(strdup("")),
311 mMainThread(PR_GetCurrentThread()),
312 mSetFromEnv(false),
313 mAddTimestamp(false),
314 mAddProfilerMarker(false),
315 mIsRaw(false),
316 mIsSync(false),
317 mRotate(0),
318 mInitialized(false) {}
320 ~LogModuleManager() {
321 detail::LogFile* logFile = mOutFile.exchange(nullptr);
322 delete logFile;
326 * Loads config from command line args or env vars if present, in
327 * this specific order of priority.
329 * Notes:
331 * 1) This function is only intended to be called once per session.
332 * 2) None of the functions used in Init should rely on logging.
334 void Init(int argc, char* argv[]) {
335 MOZ_DIAGNOSTIC_ASSERT(!mInitialized);
336 mInitialized = true;
338 LoggingHandleCommandLineArgs(argc, static_cast<char const* const*>(argv),
339 [](nsACString const& env) {
340 // We deliberately set/rewrite the
341 // environment variables so that when child
342 // processes are spawned w/o passing the
343 // arguments they still inherit the logging
344 // settings as well as sandboxing can be
345 // correctly set. Scripts can pass
346 // -MOZ_LOG=$MOZ_LOG,modules as an argument
347 // to merge existing settings, if required.
349 // PR_SetEnv takes ownership of the string.
350 PR_SetEnv(ToNewCString(env));
353 bool shouldAppend = false;
354 bool addTimestamp = false;
355 bool isSync = false;
356 bool isRaw = false;
357 bool isMarkers = false;
358 int32_t rotate = 0;
359 int32_t maxSize = 0;
360 const char* modules = PR_GetEnv("MOZ_LOG");
361 if (!modules || !modules[0]) {
362 modules = PR_GetEnv("MOZ_LOG_MODULES");
363 if (modules) {
364 NS_WARNING(
365 "MOZ_LOG_MODULES is deprecated."
366 "\nPlease use MOZ_LOG instead.");
369 if (!modules || !modules[0]) {
370 modules = PR_GetEnv("NSPR_LOG_MODULES");
371 if (modules) {
372 NS_WARNING(
373 "NSPR_LOG_MODULES is deprecated."
374 "\nPlease use MOZ_LOG instead.");
378 // Need to capture `this` since `sLogModuleManager` is not set until after
379 // initialization is complete.
380 NSPRLogModulesParser(
381 modules, [this, &shouldAppend, &addTimestamp, &isSync, &isRaw, &rotate,
382 &maxSize, &isMarkers](const char* aName, LogLevel aLevel,
383 int32_t aValue) mutable {
384 if (strcmp(aName, "append") == 0) {
385 shouldAppend = true;
386 } else if (strcmp(aName, "timestamp") == 0) {
387 addTimestamp = true;
388 } else if (strcmp(aName, "sync") == 0) {
389 isSync = true;
390 } else if (strcmp(aName, "raw") == 0) {
391 isRaw = true;
392 } else if (strcmp(aName, "rotate") == 0) {
393 rotate = (aValue << 20) / kRotateFilesNumber;
394 } else if (strcmp(aName, "maxsize") == 0) {
395 maxSize = aValue << 20;
396 } else if (strcmp(aName, "profilermarkers") == 0) {
397 isMarkers = true;
398 } else {
399 this->CreateOrGetModule(aName)->SetLevel(aLevel);
403 // Rotate implies timestamp to make the files readable
404 mAddTimestamp = addTimestamp || rotate > 0;
405 mIsSync = isSync;
406 mIsRaw = isRaw;
407 mRotate = rotate;
408 mAddProfilerMarker = isMarkers;
410 if (rotate > 0 && shouldAppend) {
411 NS_WARNING("MOZ_LOG: when you rotate the log, you cannot use append!");
414 if (rotate > 0 && maxSize > 0) {
415 NS_WARNING(
416 "MOZ_LOG: when you rotate the log, you cannot use maxsize! (ignoring "
417 "maxsize)");
418 maxSize = 0;
421 if (maxSize > 0 && !shouldAppend) {
422 NS_WARNING(
423 "MOZ_LOG: when you limit the log to maxsize, you must use append! "
424 "(ignorning maxsize)");
425 maxSize = 0;
428 const char* logFile = PR_GetEnv("MOZ_LOG_FILE");
429 if (!logFile || !logFile[0]) {
430 logFile = PR_GetEnv("NSPR_LOG_FILE");
433 if (logFile && logFile[0]) {
434 char buf[2048];
435 logFile = detail::ExpandLogFileName(logFile, buf);
436 mOutFilePath.reset(strdup(logFile));
438 if (mRotate > 0) {
439 // Delete all the previously captured files, including non-rotated
440 // log files, so that users don't complain our logs eat space even
441 // after the rotate option has been added and don't happen to send
442 // us old large logs along with the rotated files.
443 remove(mOutFilePath.get());
444 for (uint32_t i = 0; i < kRotateFilesNumber; ++i) {
445 RemoveFile(i);
449 mOutFile = OpenFile(shouldAppend, mOutFileNum, maxSize);
450 mSetFromEnv = true;
454 void SetLogFile(const char* aFilename) {
455 // For now we don't allow you to change the file at runtime.
456 if (mSetFromEnv) {
457 NS_WARNING(
458 "LogModuleManager::SetLogFile - Log file was set from the "
459 "MOZ_LOG_FILE environment variable.");
460 return;
463 const char* filename = aFilename ? aFilename : "";
464 char buf[2048];
465 filename = detail::ExpandLogFileName(filename, buf);
467 // Can't use rotate or maxsize at runtime yet.
468 MOZ_ASSERT(mRotate == 0,
469 "We don't allow rotate for runtime logfile changes");
470 mOutFilePath.reset(strdup(filename));
472 // Exchange mOutFile and set it to be released once all the writes are done.
473 detail::LogFile* newFile = OpenFile(false, 0);
474 detail::LogFile* oldFile = mOutFile.exchange(newFile);
476 // Since we don't allow changing the logfile if MOZ_LOG_FILE is already set,
477 // and we don't allow log rotation when setting it at runtime,
478 // mToReleaseFile will be null, so we're not leaking.
479 DebugOnly<detail::LogFile*> prevFile = mToReleaseFile.exchange(oldFile);
480 MOZ_ASSERT(!prevFile, "Should be null because rotation is not allowed");
482 // If we just need to release a file, we must force print, in order to
483 // trigger the closing and release of mToReleaseFile.
484 if (oldFile) {
485 va_list va;
486 empty_va(&va);
487 Print("Logger", LogLevel::Info, "Flushing old log files\n", va);
491 uint32_t GetLogFile(char* aBuffer, size_t aLength) {
492 uint32_t len = strlen(mOutFilePath.get());
493 if (len + 1 > aLength) {
494 return 0;
496 snprintf(aBuffer, aLength, "%s", mOutFilePath.get());
497 return len;
500 void SetIsSync(bool aIsSync) { mIsSync = aIsSync; }
502 void SetAddTimestamp(bool aAddTimestamp) { mAddTimestamp = aAddTimestamp; }
504 detail::LogFile* OpenFile(bool aShouldAppend, uint32_t aFileNum,
505 uint32_t aMaxSize = 0) {
506 FILE* file;
508 if (mRotate > 0) {
509 char buf[2048];
510 SprintfLiteral(buf, "%s.%d", mOutFilePath.get(), aFileNum);
512 // rotate doesn't support append (or maxsize).
513 file = fopen(buf, "w");
514 } else if (aShouldAppend && aMaxSize > 0) {
515 detail::LimitFileToLessThanSize(mOutFilePath.get(), aMaxSize >> 1);
516 file = fopen(mOutFilePath.get(), "a");
517 } else {
518 file = fopen(mOutFilePath.get(), aShouldAppend ? "a" : "w");
521 if (!file) {
522 return nullptr;
525 return new detail::LogFile(file, aFileNum);
528 void RemoveFile(uint32_t aFileNum) {
529 char buf[2048];
530 SprintfLiteral(buf, "%s.%d", mOutFilePath.get(), aFileNum);
531 remove(buf);
534 LogModule* CreateOrGetModule(const char* aName) {
535 OffTheBooksMutexAutoLock guard(mModulesLock);
536 return mModules
537 .GetOrInsertWith(aName,
538 [&] {
539 return UniquePtr<LogModule>(
540 new LogModule{aName, LogLevel::Disabled});
542 .get();
545 void Print(const char* aName, LogLevel aLevel, const char* aFmt,
546 va_list aArgs) MOZ_FORMAT_PRINTF(4, 0) {
547 Print(aName, aLevel, nullptr, aFmt, aArgs);
550 void Print(const char* aName, LogLevel aLevel, const TimeStamp* aStart,
551 const char* aFmt, va_list aArgs) MOZ_FORMAT_PRINTF(5, 0) {
552 AutoSuspendLateWriteChecks suspendLateWriteChecks;
553 long pid = static_cast<long>(base::GetCurrentProcId());
554 const size_t kBuffSize = 1024;
555 char buff[kBuffSize];
557 char* buffToWrite = buff;
558 SmprintfPointer allocatedBuff;
560 va_list argsCopy;
561 va_copy(argsCopy, aArgs);
562 int charsWritten = VsprintfLiteral(buff, aFmt, argsCopy);
563 va_end(argsCopy);
565 if (charsWritten < 0) {
566 // Print out at least something. We must copy to the local buff,
567 // can't just assign aFmt to buffToWrite, since when
568 // buffToWrite != buff, we try to release it.
569 MOZ_ASSERT(false, "Probably incorrect format string in LOG?");
570 strncpy(buff, aFmt, kBuffSize - 1);
571 buff[kBuffSize - 1] = '\0';
572 charsWritten = strlen(buff);
573 } else if (static_cast<size_t>(charsWritten) >= kBuffSize - 1) {
574 // We may have maxed out, allocate a buffer instead.
575 allocatedBuff = mozilla::Vsmprintf(aFmt, aArgs);
576 buffToWrite = allocatedBuff.get();
577 charsWritten = strlen(buffToWrite);
580 #ifdef MOZ_GECKO_PROFILER
581 if (mAddProfilerMarker && profiler_can_accept_markers()) {
582 struct LogMarker {
583 static constexpr Span<const char> MarkerTypeName() {
584 return MakeStringSpan("Log");
586 static void StreamJSONMarkerData(
587 baseprofiler::SpliceableJSONWriter& aWriter,
588 const ProfilerString8View& aModule,
589 const ProfilerString8View& aText) {
590 aWriter.StringProperty("module", aModule);
591 aWriter.StringProperty("name", aText);
593 static MarkerSchema MarkerTypeDisplay() {
594 using MS = MarkerSchema;
595 MS schema{MS::Location::markerTable};
596 schema.SetTableLabel("({marker.data.module}) {marker.data.name}");
597 schema.AddKeyLabelFormat("module", "Module", MS::Format::string);
598 schema.AddKeyLabelFormat("name", "Name", MS::Format::string);
599 return schema;
603 profiler_add_marker(
604 "LogMessages", geckoprofiler::category::OTHER,
605 aStart ? MarkerTiming::IntervalUntilNowFrom(*aStart)
606 : MarkerTiming::InstantNow(),
607 LogMarker{}, ProfilerString8View::WrapNullTerminatedString(aName),
608 ProfilerString8View::WrapNullTerminatedString(buffToWrite));
610 #endif
612 // Determine if a newline needs to be appended to the message.
613 const char* newline = "";
614 if (charsWritten == 0 || buffToWrite[charsWritten - 1] != '\n') {
615 newline = "\n";
618 FILE* out = stderr;
620 // In case we use rotate, this ensures the FILE is kept alive during
621 // its use. Increased before we load mOutFile.
622 ++mPrintEntryCount;
624 detail::LogFile* outFile = mOutFile;
625 if (outFile) {
626 out = outFile->File();
629 // This differs from the NSPR format in that we do not output the
630 // opaque system specific thread pointer (ie pthread_t) cast
631 // to a long. The address of the current PR_Thread continues to be
632 // prefixed.
634 // Additionally we prefix the output with the abbreviated log level
635 // and the module name.
636 PRThread* currentThread = PR_GetCurrentThread();
637 const char* currentThreadName = (mMainThread == currentThread)
638 ? "Main Thread"
639 : PR_GetThreadName(currentThread);
641 char noNameThread[40];
642 if (!currentThreadName) {
643 SprintfLiteral(noNameThread, "Unnamed thread %p", currentThread);
644 currentThreadName = noNameThread;
647 if (!mAddTimestamp && !aStart) {
648 if (!mIsRaw) {
649 fprintf_stderr(out, "[%s %ld: %s]: %s/%s %s%s",
650 nsDebugImpl::GetMultiprocessMode(), pid,
651 currentThreadName, ToLogStr(aLevel), aName, buffToWrite,
652 newline);
653 } else {
654 fprintf_stderr(out, "%s%s", buffToWrite, newline);
656 } else {
657 if (aStart) {
658 // XXX is there a reasonable way to convert one to the other? this is
659 // bad
660 PRTime prnow = PR_Now();
661 TimeStamp tmnow = TimeStamp::NowUnfuzzed();
662 TimeDuration duration = tmnow - *aStart;
663 PRTime prstart = prnow - duration.ToMicroseconds();
665 PRExplodedTime now;
666 PRExplodedTime start;
667 PR_ExplodeTime(prnow, PR_GMTParameters, &now);
668 PR_ExplodeTime(prstart, PR_GMTParameters, &start);
669 // Ignore that the start time might be in a different day
670 fprintf_stderr(
671 out,
672 "%04d-%02d-%02d %02d:%02d:%02d.%06d -> %02d:%02d:%02d.%06d UTC "
673 "(%.1gms)- [%s %ld: %s]: %s/%s %s%s",
674 now.tm_year, now.tm_month + 1, start.tm_mday, start.tm_hour,
675 start.tm_min, start.tm_sec, start.tm_usec, now.tm_hour, now.tm_min,
676 now.tm_sec, now.tm_usec, duration.ToMilliseconds(),
677 nsDebugImpl::GetMultiprocessMode(), pid, currentThreadName,
678 ToLogStr(aLevel), aName, buffToWrite, newline);
679 } else {
680 PRExplodedTime now;
681 PR_ExplodeTime(PR_Now(), PR_GMTParameters, &now);
682 fprintf_stderr(
683 out,
684 "%04d-%02d-%02d %02d:%02d:%02d.%06d UTC - [%s %ld: %s]: %s/%s %s%s",
685 now.tm_year, now.tm_month + 1, now.tm_mday, now.tm_hour, now.tm_min,
686 now.tm_sec, now.tm_usec, nsDebugImpl::GetMultiprocessMode(), pid,
687 currentThreadName, ToLogStr(aLevel), aName, buffToWrite, newline);
691 if (mIsSync) {
692 fflush(out);
695 if (mRotate > 0 && outFile) {
696 int32_t fileSize = ftell(out);
697 if (fileSize > mRotate) {
698 uint32_t fileNum = outFile->Num();
700 uint32_t nextFileNum = fileNum + 1;
701 if (nextFileNum >= kRotateFilesNumber) {
702 nextFileNum = 0;
705 // And here is the trick. The current out-file remembers its order
706 // number. When no other thread shifted the global file number yet,
707 // we are the thread to open the next file.
708 if (mOutFileNum.compareExchange(fileNum, nextFileNum)) {
709 // We can work with mToReleaseFile because we are sure the
710 // mPrintEntryCount can't drop to zero now - the condition
711 // to actually delete what's stored in that member.
712 // And also, no other thread can enter this piece of code
713 // because mOutFile is still holding the current file with
714 // the non-shifted number. The compareExchange() above is
715 // a no-op for other threads.
716 outFile->mNextToRelease = mToReleaseFile;
717 mToReleaseFile = outFile;
719 mOutFile = OpenFile(false, nextFileNum);
724 if (--mPrintEntryCount == 0 && mToReleaseFile) {
725 // We were the last Print() entered, if there is a file to release
726 // do it now. exchange() is atomic and makes sure we release the file
727 // only once on one thread.
728 detail::LogFile* release = mToReleaseFile.exchange(nullptr);
729 delete release;
733 private:
734 OffTheBooksMutex mModulesLock;
735 nsClassHashtable<nsCharPtrHashKey, LogModule> mModules;
737 // Print() entry counter, actually reflects concurrent use of the current
738 // output file. ReleaseAcquire ensures that manipulation with mOutFile
739 // and mToReleaseFile is synchronized by manipulation with this value.
740 Atomic<uint32_t, ReleaseAcquire> mPrintEntryCount;
741 // File to write to. ReleaseAcquire because we need to sync mToReleaseFile
742 // with this.
743 Atomic<detail::LogFile*, ReleaseAcquire> mOutFile;
744 // File to be released when reference counter drops to zero. This member
745 // is assigned mOutFile when the current file has reached the limit.
746 // It can be Relaxed, since it's synchronized with mPrintEntryCount
747 // manipulation and we do atomic exchange() on it.
748 Atomic<detail::LogFile*, Relaxed> mToReleaseFile;
749 // The next file number. This is mostly only for synchronization sake.
750 // Can have relaxed ordering, since we only do compareExchange on it which
751 // is atomic regardless ordering.
752 Atomic<uint32_t, Relaxed> mOutFileNum;
753 // Just keeps the actual file path for further use.
754 UniqueFreePtr<char[]> mOutFilePath;
756 PRThread* mMainThread;
757 bool mSetFromEnv;
758 Atomic<bool, Relaxed> mAddTimestamp;
759 Atomic<bool, Relaxed> mAddProfilerMarker;
760 Atomic<bool, Relaxed> mIsRaw;
761 Atomic<bool, Relaxed> mIsSync;
762 int32_t mRotate;
763 bool mInitialized;
766 StaticAutoPtr<LogModuleManager> sLogModuleManager;
768 LogModule* LogModule::Get(const char* aName) {
769 // This is just a pass through to the LogModuleManager so
770 // that the LogModuleManager implementation can be kept internal.
771 MOZ_ASSERT(sLogModuleManager != nullptr);
772 return sLogModuleManager->CreateOrGetModule(aName);
775 void LogModule::SetLogFile(const char* aFilename) {
776 MOZ_ASSERT(sLogModuleManager);
777 sLogModuleManager->SetLogFile(aFilename);
780 uint32_t LogModule::GetLogFile(char* aBuffer, size_t aLength) {
781 MOZ_ASSERT(sLogModuleManager);
782 return sLogModuleManager->GetLogFile(aBuffer, aLength);
785 void LogModule::SetAddTimestamp(bool aAddTimestamp) {
786 sLogModuleManager->SetAddTimestamp(aAddTimestamp);
789 void LogModule::SetIsSync(bool aIsSync) {
790 sLogModuleManager->SetIsSync(aIsSync);
793 // This function is defined in gecko_logger/src/lib.rs
794 // We mirror the level in rust code so we don't get forwarded all of the
795 // rust logging and have to create an LogModule for each rust component.
796 extern "C" void set_rust_log_level(const char* name, uint8_t level);
798 void LogModule::SetLevel(LogLevel level) {
799 mLevel = level;
801 // If the log module contains `::` it is likely a rust module, so we
802 // pass the level into the rust code so it will know to forward the logging
803 // to Gecko.
804 if (strstr(mName, "::")) {
805 set_rust_log_level(mName, static_cast<uint8_t>(level));
809 void LogModule::Init(int argc, char* argv[]) {
810 // NB: This method is not threadsafe; it is expected to be called very early
811 // in startup prior to any other threads being run.
812 MOZ_DIAGNOSTIC_ASSERT(NS_IsMainThread());
814 if (sLogModuleManager) {
815 // Already initialized.
816 return;
819 // NB: We intentionally do not register for ClearOnShutdown as that happens
820 // before all logging is complete. And, yes, that means we leak, but
821 // we're doing that intentionally.
823 // Don't assign the pointer until after Init is called. This should help us
824 // detect if any of the functions called by Init somehow rely on logging.
825 auto mgr = new LogModuleManager();
826 mgr->Init(argc, argv);
827 sLogModuleManager = mgr;
830 void LogModule::Printv(LogLevel aLevel, const char* aFmt, va_list aArgs) const {
831 MOZ_ASSERT(sLogModuleManager != nullptr);
833 // Forward to LogModule manager w/ level and name
834 sLogModuleManager->Print(Name(), aLevel, aFmt, aArgs);
837 void LogModule::Printv(LogLevel aLevel, const TimeStamp* aStart,
838 const char* aFmt, va_list aArgs) const {
839 MOZ_ASSERT(sLogModuleManager != nullptr);
841 // Forward to LogModule manager w/ level and name
842 sLogModuleManager->Print(Name(), aLevel, aStart, aFmt, aArgs);
845 } // namespace mozilla
847 extern "C" {
849 // This function is called by external code (rust) to log to one of our
850 // log modules.
851 void ExternMozLog(const char* aModule, mozilla::LogLevel aLevel,
852 const char* aMsg) {
853 MOZ_ASSERT(sLogModuleManager != nullptr);
855 LogModule* m = sLogModuleManager->CreateOrGetModule(aModule);
856 if (MOZ_LOG_TEST(m, aLevel)) {
857 mozilla::detail::log_print(m, aLevel, "%s", aMsg);
861 } // extern "C"