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/Logging.h"
8
9 #include <algorithm>
10
11 #include "mozilla/ClearOnShutdown.h"
12 #include "mozilla/FileUtils.h"
13 #include "mozilla/Mutex.h"
14 #include "mozilla/StaticPtr.h"
15 #include "mozilla/Printf.h"
16 #include "mozilla/Atomics.h"
17 #include "mozilla/Sprintf.h"
18 #include "mozilla/UniquePtrExtensions.h"
19 #include "MainThreadUtils.h"
20 #include "nsClassHashtable.h"
21 #include "nsDebug.h"
22 #include "NSPRLogModulesParser.h"
23
24 #include "prenv.h"
25 #ifdef XP_WIN
26 #include <process.h>
27 #else
28 #include <sys/types.h>
29 #include <unistd.h>
30 #endif
31
32 // NB: Initial amount determined by auditing the codebase for the total amount
33 // of unique module names and padding up to the next power of 2.
34 const uint32_t kInitialModuleCount = 256;
35 // When rotate option is added to the modules list, this is the hardcoded
36 // number of files we create and rotate. When there is rotate:40,
37 // we will keep four files per process, each limited to 10MB. Sum is 40MB,
38 // the given limit.
39 //
40 // (Note: When this is changed to be >= 10, SandboxBroker::LaunchApp must add
41 // another rule to allow logfile.?? be written by content processes.)
42 const uint32_t kRotateFilesNumber = 4;
43
44 namespace mozilla {
45
operator LogModule*()46 LazyLogModule::operator LogModule*() {
47 // NB: The use of an atomic makes the reading and assignment of mLog
48 // thread-safe. There is a small chance that mLog will be set more
49 // than once, but that's okay as it will be set to the same LogModule
50 // instance each time. Also note LogModule::Get is thread-safe.
51 LogModule* tmp = mLog;
52 if (MOZ_UNLIKELY(!tmp)) {
53 tmp = LogModule::Get(mLogName);
54 mLog = tmp;
55 }
56
57 return tmp;
58 }
59
60 namespace detail {
61
log_print(const LogModule * aModule,LogLevel aLevel,const char * aFmt,...)62 void log_print(const LogModule* aModule, LogLevel aLevel, const char* aFmt,
63 ...) {
64 va_list ap;
65 va_start(ap, aFmt);
66 aModule->Printv(aLevel, aFmt, ap);
67 va_end(ap);
68 }
69
70 } // namespace detail
71
ToLogLevel(int32_t aLevel)72 LogLevel ToLogLevel(int32_t aLevel) {
73 aLevel = std::min(aLevel, static_cast<int32_t>(LogLevel::Verbose));
74 aLevel = std::max(aLevel, static_cast<int32_t>(LogLevel::Disabled));
75 return static_cast<LogLevel>(aLevel);
76 }
77
ToLogStr(LogLevel aLevel)78 const char* ToLogStr(LogLevel aLevel) {
79 switch (aLevel) {
80 case LogLevel::Error:
81 return "E";
82 case LogLevel::Warning:
83 return "W";
84 case LogLevel::Info:
85 return "I";
86 case LogLevel::Debug:
87 return "D";
88 case LogLevel::Verbose:
89 return "V";
90 case LogLevel::Disabled:
91 default:
92 MOZ_CRASH("Invalid log level.");
93 return "";
94 }
95 }
96
97 namespace detail {
98
99 /**
100 * A helper class providing reference counting for FILE*.
101 * It encapsulates the following:
102 * - the FILE handle
103 * - the order number it was created for when rotating (actual path)
104 * - number of active references
105 */
106 class LogFile {
107 FILE* mFile;
108 uint32_t mFileNum;
109
110 public:
LogFile(FILE * aFile,uint32_t aFileNum)111 LogFile(FILE* aFile, uint32_t aFileNum)
112 : mFile(aFile), mFileNum(aFileNum), mNextToRelease(nullptr) {}
113
~LogFile()114 ~LogFile() {
115 fclose(mFile);
116 delete mNextToRelease;
117 }
118
File() const119 FILE* File() const { return mFile; }
Num() const120 uint32_t Num() const { return mFileNum; }
121
122 LogFile* mNextToRelease;
123 };
124
ExpandPIDMarker(const char * aFilename,char (& buffer)[2048])125 const char* ExpandPIDMarker(const char* aFilename, char (&buffer)[2048]) {
126 MOZ_ASSERT(aFilename);
127 static const char kPIDToken[] = "%PID";
128 const char* pidTokenPtr = strstr(aFilename, kPIDToken);
129 if (pidTokenPtr &&
130 SprintfLiteral(
131 buffer, "%.*s%s%d%s", static_cast<int>(pidTokenPtr - aFilename),
132 aFilename, XRE_IsParentProcess() ? "-main." : "-child.",
133 base::GetCurrentProcId(), pidTokenPtr + strlen(kPIDToken)) > 0) {
134 return buffer;
135 }
136
137 return aFilename;
138 }
139
140 } // namespace detail
141
142 namespace {
143 // Helper method that initializes an empty va_list to be empty.
empty_va(va_list * va,...)144 void empty_va(va_list* va, ...) {
145 va_start(*va, va);
146 va_end(*va);
147 }
148 } // namespace
149
150 class LogModuleManager {
151 public:
LogModuleManager()152 LogModuleManager()
153 : mModulesLock("logmodules"),
154 mModules(kInitialModuleCount),
155 mPrintEntryCount(0),
156 mOutFile(nullptr),
157 mToReleaseFile(nullptr),
158 mOutFileNum(0),
159 mOutFilePath(strdup("")),
160 mMainThread(PR_GetCurrentThread()),
161 mSetFromEnv(false),
162 mAddTimestamp(false),
163 mIsSync(false),
164 mRotate(0),
165 mInitialized(false) {}
166
~LogModuleManager()167 ~LogModuleManager() {
168 detail::LogFile* logFile = mOutFile.exchange(nullptr);
169 delete logFile;
170 }
171
172 /**
173 * Loads config from env vars if present.
174 *
175 * Notes:
176 *
177 * 1) This function is only intended to be called once per session.
178 * 2) None of the functions used in Init should rely on logging.
179 */
Init()180 void Init() {
181 MOZ_DIAGNOSTIC_ASSERT(!mInitialized);
182 mInitialized = true;
183
184 bool shouldAppend = false;
185 bool addTimestamp = false;
186 bool isSync = false;
187 int32_t rotate = 0;
188 const char* modules = PR_GetEnv("MOZ_LOG");
189 if (!modules || !modules[0]) {
190 modules = PR_GetEnv("MOZ_LOG_MODULES");
191 if (modules) {
192 NS_WARNING(
193 "MOZ_LOG_MODULES is deprecated."
194 "\nPlease use MOZ_LOG instead.");
195 }
196 }
197 if (!modules || !modules[0]) {
198 modules = PR_GetEnv("NSPR_LOG_MODULES");
199 if (modules) {
200 NS_WARNING(
201 "NSPR_LOG_MODULES is deprecated."
202 "\nPlease use MOZ_LOG instead.");
203 }
204 }
205
206 // Need to capture `this` since `sLogModuleManager` is not set until after
207 // initialization is complete.
208 NSPRLogModulesParser(modules, [this, &shouldAppend, &addTimestamp, &isSync,
209 &rotate](const char* aName, LogLevel aLevel,
210 int32_t aValue) mutable {
211 if (strcmp(aName, "append") == 0) {
212 shouldAppend = true;
213 } else if (strcmp(aName, "timestamp") == 0) {
214 addTimestamp = true;
215 } else if (strcmp(aName, "sync") == 0) {
216 isSync = true;
217 } else if (strcmp(aName, "rotate") == 0) {
218 rotate = (aValue << 20) / kRotateFilesNumber;
219 } else {
220 this->CreateOrGetModule(aName)->SetLevel(aLevel);
221 }
222 });
223
224 // Rotate implies timestamp to make the files readable
225 mAddTimestamp = addTimestamp || rotate > 0;
226 mIsSync = isSync;
227 mRotate = rotate;
228
229 if (rotate > 0 && shouldAppend) {
230 NS_WARNING("MOZ_LOG: when you rotate the log, you cannot use append!");
231 }
232
233 const char* logFile = PR_GetEnv("MOZ_LOG_FILE");
234 if (!logFile || !logFile[0]) {
235 logFile = PR_GetEnv("NSPR_LOG_FILE");
236 }
237
238 if (logFile && logFile[0]) {
239 char buf[2048];
240 logFile = detail::ExpandPIDMarker(logFile, buf);
241 mOutFilePath.reset(strdup(logFile));
242
243 if (mRotate > 0) {
244 // Delete all the previously captured files, including non-rotated
245 // log files, so that users don't complain our logs eat space even
246 // after the rotate option has been added and don't happen to send
247 // us old large logs along with the rotated files.
248 remove(mOutFilePath.get());
249 for (uint32_t i = 0; i < kRotateFilesNumber; ++i) {
250 RemoveFile(i);
251 }
252 }
253
254 mOutFile = OpenFile(shouldAppend, mOutFileNum);
255 mSetFromEnv = true;
256 }
257 }
258
SetLogFile(const char * aFilename)259 void SetLogFile(const char* aFilename) {
260 // For now we don't allow you to change the file at runtime.
261 if (mSetFromEnv) {
262 NS_WARNING(
263 "LogModuleManager::SetLogFile - Log file was set from the "
264 "MOZ_LOG_FILE environment variable.");
265 return;
266 }
267
268 const char* filename = aFilename ? aFilename : "";
269 char buf[2048];
270 filename = detail::ExpandPIDMarker(filename, buf);
271
272 // Can't use rotate at runtime yet.
273 MOZ_ASSERT(mRotate == 0,
274 "We don't allow rotate for runtime logfile changes");
275 mOutFilePath.reset(strdup(filename));
276
277 // Exchange mOutFile and set it to be released once all the writes are done.
278 detail::LogFile* newFile = OpenFile(false, 0);
279 detail::LogFile* oldFile = mOutFile.exchange(newFile);
280
281 // Since we don't allow changing the logfile if MOZ_LOG_FILE is already set,
282 // and we don't allow log rotation when setting it at runtime,
283 // mToReleaseFile will be null, so we're not leaking.
284 DebugOnly<detail::LogFile*> prevFile = mToReleaseFile.exchange(oldFile);
285 MOZ_ASSERT(!prevFile, "Should be null because rotation is not allowed");
286
287 // If we just need to release a file, we must force print, in order to
288 // trigger the closing and release of mToReleaseFile.
289 if (oldFile) {
290 va_list va;
291 empty_va(&va);
292 Print("Logger", LogLevel::Info, "Flushing old log files\n", va);
293 }
294 }
295
GetLogFile(char * aBuffer,size_t aLength)296 uint32_t GetLogFile(char* aBuffer, size_t aLength) {
297 uint32_t len = strlen(mOutFilePath.get());
298 if (len + 1 > aLength) {
299 return 0;
300 }
301 snprintf(aBuffer, aLength, "%s", mOutFilePath.get());
302 return len;
303 }
304
SetIsSync(bool aIsSync)305 void SetIsSync(bool aIsSync) { mIsSync = aIsSync; }
306
SetAddTimestamp(bool aAddTimestamp)307 void SetAddTimestamp(bool aAddTimestamp) { mAddTimestamp = aAddTimestamp; }
308
OpenFile(bool aShouldAppend,uint32_t aFileNum)309 detail::LogFile* OpenFile(bool aShouldAppend, uint32_t aFileNum) {
310 FILE* file;
311
312 if (mRotate > 0) {
313 char buf[2048];
314 SprintfLiteral(buf, "%s.%d", mOutFilePath.get(), aFileNum);
315
316 // rotate doesn't support append.
317 file = fopen(buf, "w");
318 } else {
319 file = fopen(mOutFilePath.get(), aShouldAppend ? "a" : "w");
320 }
321
322 if (!file) {
323 return nullptr;
324 }
325
326 return new detail::LogFile(file, aFileNum);
327 }
328
RemoveFile(uint32_t aFileNum)329 void RemoveFile(uint32_t aFileNum) {
330 char buf[2048];
331 SprintfLiteral(buf, "%s.%d", mOutFilePath.get(), aFileNum);
332 remove(buf);
333 }
334
CreateOrGetModule(const char * aName)335 LogModule* CreateOrGetModule(const char* aName) {
336 OffTheBooksMutexAutoLock guard(mModulesLock);
337 LogModule* module = nullptr;
338 if (!mModules.Get(aName, &module)) {
339 module = new LogModule(aName, LogLevel::Disabled);
340 mModules.Put(aName, module);
341 }
342
343 return module;
344 }
345
Print(const char * aName,LogLevel aLevel,const char * aFmt,va_list aArgs)346 void Print(const char* aName, LogLevel aLevel, const char* aFmt,
347 va_list aArgs) MOZ_FORMAT_PRINTF(4, 0) {
348 // We don't do nuwa-style forking anymore, so our pid can't change.
349 static long pid = static_cast<long>(base::GetCurrentProcId());
350 const size_t kBuffSize = 1024;
351 char buff[kBuffSize];
352
353 char* buffToWrite = buff;
354 SmprintfPointer allocatedBuff;
355
356 va_list argsCopy;
357 va_copy(argsCopy, aArgs);
358 int charsWritten = VsprintfLiteral(buff, aFmt, argsCopy);
359 va_end(argsCopy);
360
361 if (charsWritten < 0) {
362 // Print out at least something. We must copy to the local buff,
363 // can't just assign aFmt to buffToWrite, since when
364 // buffToWrite != buff, we try to release it.
365 MOZ_ASSERT(false, "Probably incorrect format string in LOG?");
366 strncpy(buff, aFmt, kBuffSize - 1);
367 buff[kBuffSize - 1] = '\0';
368 charsWritten = strlen(buff);
369 } else if (static_cast<size_t>(charsWritten) >= kBuffSize - 1) {
370 // We may have maxed out, allocate a buffer instead.
371 allocatedBuff = mozilla::Vsmprintf(aFmt, aArgs);
372 buffToWrite = allocatedBuff.get();
373 charsWritten = strlen(buffToWrite);
374 }
375
376 // Determine if a newline needs to be appended to the message.
377 const char* newline = "";
378 if (charsWritten == 0 || buffToWrite[charsWritten - 1] != '\n') {
379 newline = "\n";
380 }
381
382 FILE* out = stderr;
383
384 // In case we use rotate, this ensures the FILE is kept alive during
385 // its use. Increased before we load mOutFile.
386 ++mPrintEntryCount;
387
388 detail::LogFile* outFile = mOutFile;
389 if (outFile) {
390 out = outFile->File();
391 }
392
393 // This differs from the NSPR format in that we do not output the
394 // opaque system specific thread pointer (ie pthread_t) cast
395 // to a long. The address of the current PR_Thread continues to be
396 // prefixed.
397 //
398 // Additionally we prefix the output with the abbreviated log level
399 // and the module name.
400 PRThread* currentThread = PR_GetCurrentThread();
401 const char* currentThreadName = (mMainThread == currentThread)
402 ? "Main Thread"
403 : PR_GetThreadName(currentThread);
404
405 char noNameThread[40];
406 if (!currentThreadName) {
407 SprintfLiteral(noNameThread, "Unnamed thread %p", currentThread);
408 currentThreadName = noNameThread;
409 }
410
411 if (!mAddTimestamp) {
412 fprintf_stderr(out, "[%ld:%s]: %s/%s %s%s", pid, currentThreadName,
413 ToLogStr(aLevel), aName, buffToWrite, newline);
414 } else {
415 PRExplodedTime now;
416 PR_ExplodeTime(PR_Now(), PR_GMTParameters, &now);
417 fprintf_stderr(
418 out, "%04d-%02d-%02d %02d:%02d:%02d.%06d UTC - [%ld:%s]: %s/%s %s%s",
419 now.tm_year, now.tm_month + 1, now.tm_mday, now.tm_hour, now.tm_min,
420 now.tm_sec, now.tm_usec, pid, currentThreadName, ToLogStr(aLevel),
421 aName, buffToWrite, newline);
422 }
423
424 if (mIsSync) {
425 fflush(out);
426 }
427
428 if (mRotate > 0 && outFile) {
429 int32_t fileSize = ftell(out);
430 if (fileSize > mRotate) {
431 uint32_t fileNum = outFile->Num();
432
433 uint32_t nextFileNum = fileNum + 1;
434 if (nextFileNum >= kRotateFilesNumber) {
435 nextFileNum = 0;
436 }
437
438 // And here is the trick. The current out-file remembers its order
439 // number. When no other thread shifted the global file number yet,
440 // we are the thread to open the next file.
441 if (mOutFileNum.compareExchange(fileNum, nextFileNum)) {
442 // We can work with mToReleaseFile because we are sure the
443 // mPrintEntryCount can't drop to zero now - the condition
444 // to actually delete what's stored in that member.
445 // And also, no other thread can enter this piece of code
446 // because mOutFile is still holding the current file with
447 // the non-shifted number. The compareExchange() above is
448 // a no-op for other threads.
449 outFile->mNextToRelease = mToReleaseFile;
450 mToReleaseFile = outFile;
451
452 mOutFile = OpenFile(false, nextFileNum);
453 }
454 }
455 }
456
457 if (--mPrintEntryCount == 0 && mToReleaseFile) {
458 // We were the last Print() entered, if there is a file to release
459 // do it now. exchange() is atomic and makes sure we release the file
460 // only once on one thread.
461 detail::LogFile* release = mToReleaseFile.exchange(nullptr);
462 delete release;
463 }
464 }
465
466 private:
467 OffTheBooksMutex mModulesLock;
468 nsClassHashtable<nsCharPtrHashKey, LogModule> mModules;
469
470 // Print() entry counter, actually reflects concurrent use of the current
471 // output file. ReleaseAcquire ensures that manipulation with mOutFile
472 // and mToReleaseFile is synchronized by manipulation with this value.
473 Atomic<uint32_t, ReleaseAcquire> mPrintEntryCount;
474 // File to write to. ReleaseAcquire because we need to sync mToReleaseFile
475 // with this.
476 Atomic<detail::LogFile*, ReleaseAcquire> mOutFile;
477 // File to be released when reference counter drops to zero. This member
478 // is assigned mOutFile when the current file has reached the limit.
479 // It can be Relaxed, since it's synchronized with mPrintEntryCount
480 // manipulation and we do atomic exchange() on it.
481 Atomic<detail::LogFile*, Relaxed> mToReleaseFile;
482 // The next file number. This is mostly only for synchronization sake.
483 // Can have relaxed ordering, since we only do compareExchange on it which
484 // is atomic regardless ordering.
485 Atomic<uint32_t, Relaxed> mOutFileNum;
486 // Just keeps the actual file path for further use.
487 UniqueFreePtr<char[]> mOutFilePath;
488
489 PRThread* mMainThread;
490 bool mSetFromEnv;
491 Atomic<bool, Relaxed> mAddTimestamp;
492 Atomic<bool, Relaxed> mIsSync;
493 int32_t mRotate;
494 bool mInitialized;
495 };
496
497 StaticAutoPtr<LogModuleManager> sLogModuleManager;
498
Get(const char * aName)499 LogModule* LogModule::Get(const char* aName) {
500 // This is just a pass through to the LogModuleManager so
501 // that the LogModuleManager implementation can be kept internal.
502 MOZ_ASSERT(sLogModuleManager != nullptr);
503 return sLogModuleManager->CreateOrGetModule(aName);
504 }
505
SetLogFile(const char * aFilename)506 void LogModule::SetLogFile(const char* aFilename) {
507 MOZ_ASSERT(sLogModuleManager);
508 sLogModuleManager->SetLogFile(aFilename);
509 }
510
GetLogFile(char * aBuffer,size_t aLength)511 uint32_t LogModule::GetLogFile(char* aBuffer, size_t aLength) {
512 MOZ_ASSERT(sLogModuleManager);
513 return sLogModuleManager->GetLogFile(aBuffer, aLength);
514 }
515
SetAddTimestamp(bool aAddTimestamp)516 void LogModule::SetAddTimestamp(bool aAddTimestamp) {
517 sLogModuleManager->SetAddTimestamp(aAddTimestamp);
518 }
519
SetIsSync(bool aIsSync)520 void LogModule::SetIsSync(bool aIsSync) {
521 sLogModuleManager->SetIsSync(aIsSync);
522 }
523
Init()524 void LogModule::Init() {
525 // NB: This method is not threadsafe; it is expected to be called very early
526 // in startup prior to any other threads being run.
527 MOZ_DIAGNOSTIC_ASSERT(NS_IsMainThread());
528
529 if (sLogModuleManager) {
530 // Already initialized.
531 return;
532 }
533
534 // NB: We intentionally do not register for ClearOnShutdown as that happens
535 // before all logging is complete. And, yes, that means we leak, but
536 // we're doing that intentionally.
537
538 // Don't assign the pointer until after Init is called. This should help us
539 // detect if any of the functions called by Init somehow rely on logging.
540 auto mgr = new LogModuleManager();
541 mgr->Init();
542 sLogModuleManager = mgr;
543 }
544
Printv(LogLevel aLevel,const char * aFmt,va_list aArgs) const545 void LogModule::Printv(LogLevel aLevel, const char* aFmt, va_list aArgs) const {
546 MOZ_ASSERT(sLogModuleManager != nullptr);
547
548 // Forward to LogModule manager w/ level and name
549 sLogModuleManager->Print(Name(), aLevel, aFmt, aArgs);
550 }
551
552 } // namespace mozilla
553