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