sal/osl/all/log.cxx

   1 /* -*- Mode: C++; tab-width: 4; indent-tabs-mode: nil; c-basic-offset: 4 -*- */
   2 /*
   3  * This file is part of the LibreOffice project.
   4  *
   5  * This Source Code Form is subject to the terms of the Mozilla Public
   6  * License, v. 2.0. If a copy of the MPL was not distributed with this
   7  * file, You can obtain one at http://mozilla.org/MPL/2.0/.
   8  */
   9
  10 #include <sal/config.h>
  11
  12 #include <cassert>
  13 #include <cstdarg>
  14 #include <cstdio>
  15 #include <cstdlib>
  16 #include <cstring>
  17
  18 #include <fstream>
  19
  20 #include <config_global.h>
  21 #include <osl/thread.hxx>
  22 #include <rtl/string.h>
  23 #include <sal/detail/log.h>
  24 #include <sal/log.hxx>
  25 #include <sal/types.h>
  26 #include <backtraceasstring.hxx>
  27 #include <salusesyslog.hxx>
  28
  29 #if defined ANDROID
  30 #include <android/log.h>
  31 #elif defined _WIN32
  32 #include <process.h>
  33 #include <windows.h>
  34 #define OSL_DETAIL_GETPID _getpid()
  35 #else
  36 #include <unistd.h>
  37 #define OSL_DETAIL_GETPID getpid()
  38 #endif
  39
  40 #if HAVE_SYSLOG_H
  41 #include <syslog.h>
  42 // sal/osl/unx/salinit.cxx::sal_detail_initialize updates this:
  43 bool sal_use_syslog;
  44 #else
  45 bool const sal_use_syslog = false;
  46 #endif
  47
  48 // Avoid the use of other sal code in this file as much as possible, so that
  49 // this code can be called from other sal code without causing endless
  50 // recursion.
  51
  52 namespace {
  53
  54 struct TimeContainer
  55 {
  56     TimeValue aTime;
  57     TimeContainer()
  58     {
  59         osl_getSystemTime(&aTime);
  60     }
  61 };
  62
  63 TimeContainer aStartTime;
  64
  65 bool equalStrings(
  66     char const * string1, std::size_t length1, char const * string2,
  67     std::size_t length2)
  68 {
  69     return length1 == length2 && std::memcmp(string1, string2, length1) == 0;
  70 }
  71
  72 #if !defined ANDROID
  73 char const * toString(sal_detail_LogLevel level) {
  74     switch (level) {
  75     case SAL_DETAIL_LOG_LEVEL_INFO:
  76         return "info";
  77     case SAL_DETAIL_LOG_LEVEL_WARN:
  78         return "warn";
  79     case SAL_DETAIL_LOG_LEVEL_DEBUG:
  80         return "debug";
  81     default:
  82         assert(false); // this cannot happen
  83         return "broken";
  84     }
  85 }
  86 #endif
  87
  88 #ifdef _WIN32
  89
  90 char const* setEnvFromLoggingIniFile(const char* env, const char* key)
  91 {
  92     char const* sResult = nullptr;
  93     wchar_t buffer[MAX_PATH];
  94     GetModuleFileNameW(nullptr, buffer, MAX_PATH);
  95     std::wstring sProgramDirectory(buffer);
  96     std::wstring::size_type pos = sProgramDirectory.find_last_of(L"\\/");
  97     sProgramDirectory = sProgramDirectory.substr(0, pos+1);
  98     sProgramDirectory += L"logging.ini";
  99
 100     std::ifstream logFileStream(sProgramDirectory);
 101     if (!logFileStream.good())
 102         return sResult;
 103
 104     std::size_t n;
 105     std::string aKey;
 106     std::string sWantedKey(key);
 107     std::string sLine;
 108     while (std::getline(logFileStream, sLine)) {
 109         if (sLine.find('#') == 0)
 110             continue;
 111         if ( ( n = sLine.find('=') ) != std::string::npos) {
 112             aKey = sLine.substr(0, n);
 113             if (aKey != sWantedKey)
 114                 continue;
 115             _putenv_s(env, sLine.substr(n+1, sLine.length()).c_str());
 116             sResult = std::getenv(env);
 117             break;
 118         }
 119     }
 120     return sResult;
 121 }
 122 #endif
 123
 124 char const* pLogSelector = nullptr;
 125
 126 char const* getLogLevelEnvVar() {
 127     static char const* const pLevel = [] {
 128         char const* pResult = nullptr;
 129
 130         // First check the environment variable, then the setting in logging.ini
 131         char const* env = std::getenv("SAL_LOG");
 132
 133 #ifdef _WIN32
 134         if (!env)
 135             env = setEnvFromLoggingIniFile("SAL_LOG", "LogLevel");
 136 #endif
 137
 138         if (env)
 139         {
 140             // Make a copy from the string in environment block
 141             static std::string sLevel(env);
 142             pResult = sLevel.c_str();
 143         }
 144         return pResult;
 145     }();
 146
 147     return pLevel;
 148 }
 149
 150 #if !defined ANDROID
 151
 152 std::ofstream * getLogFile() {
 153     static std::ofstream* const pFile = [] {
 154         std::ofstream* pResult = nullptr;
 155
 156         // First check the environment variable, then the setting in logging.ini
 157         char const* logFile = std::getenv("SAL_LOG_FILE");
 158
 159 #ifdef _WIN32
 160         if (!logFile)
 161             logFile = setEnvFromLoggingIniFile("SAL_LOG_FILE", "LogFilePath");
 162 #endif
 163
 164         if (logFile)
 165         {
 166             // stays until process exits
 167             static std::ofstream file(logFile, std::ios::app | std::ios::out);
 168             pResult = &file;
 169         }
 170
 171         return pResult;
 172     }();
 173
 174     return pFile;
 175 }
 176
 177
 178 std::pair<bool, bool> getTimestampFlags(char const *selector)
 179 {
 180     bool outputTimestamp = false;
 181     bool outputRelativeTimer = false;
 182     for (char const* p = selector; p && *p;)
 183     {
 184             if (*p++ == '+')
 185             {
 186                 char const * p1 = p;
 187                 while (*p1 != '.' && *p1 != '+' && *p1 != '-' && *p1 != '\0') {
 188                     ++p1;
 189                 }
 190                 if (equalStrings(p, p1 - p, RTL_CONSTASCII_STRINGPARAM("TIMESTAMP")))
 191                     outputTimestamp = true;
 192                 else if (equalStrings(p, p1 - p, RTL_CONSTASCII_STRINGPARAM("RELATIVETIMER")))
 193                     outputRelativeTimer = true;
 194                 char const * p2 = p1;
 195                 while (*p2 != '+' && *p2 != '-' && *p2 != '\0') {
 196                     ++p2;
 197                 }
 198                 p = p2;
 199             }
 200     }
 201     return std::pair(outputTimestamp, outputRelativeTimer);
 202 }
 203
 204 void maybeOutputTimestamp(std::ostringstream &s) {
 205     static const std::pair<bool, bool> aEnvFlags = getTimestampFlags(getLogLevelEnvVar());
 206     const auto& [outputTimestamp, outputRelativeTimer] = (pLogSelector == nullptr ? aEnvFlags : getTimestampFlags(pLogSelector));
 207
 208     if (!(outputTimestamp || outputRelativeTimer)) {
 209         return;
 210     }
 211     TimeValue now;
 212     osl_getSystemTime(&now);
 213
 214     if (outputTimestamp)
 215     {
 216         char ts[100];
 217         TimeValue localTime;
 218         osl_getLocalTimeFromSystemTime(&now, &localTime);
 219         oslDateTime dateTime;
 220         osl_getDateTimeFromTimeValue(&localTime, &dateTime);
 221         struct tm tm;
 222         tm.tm_sec = dateTime.Seconds;
 223         tm.tm_min = dateTime.Minutes;
 224         tm.tm_hour = dateTime.Hours;
 225         tm.tm_mday = dateTime.Day;
 226         tm.tm_wday = dateTime.DayOfWeek;
 227         tm.tm_mon = dateTime.Month - 1;
 228         tm.tm_year = dateTime.Year - 1900;
 229         tm.tm_yday = 0;
 230         strftime(ts, sizeof(ts), "%Y-%m-%d:%H:%M:%S", &tm);
 231         char milliSecs[11];
 232         snprintf(milliSecs, sizeof(milliSecs), "%03u",
 233                  static_cast<unsigned>(dateTime.NanoSeconds / 1000000));
 234         s << ts << '.' << milliSecs << ':';
 235     }
 236
 237     if (outputRelativeTimer)
 238     {
 239         int seconds = now.Seconds - aStartTime.aTime.Seconds;
 240         int milliSeconds;
 241         if (now.Nanosec < aStartTime.aTime.Nanosec)
 242         {
 243             seconds--;
 244             milliSeconds = 1000 - (aStartTime.aTime.Nanosec - now.Nanosec) / 1000000;
 245         }
 246         else
 247             milliSeconds = (now.Nanosec - aStartTime.aTime.Nanosec) / 1000000;
 248         char relativeTimestamp[100];
 249         snprintf(relativeTimestamp, sizeof(relativeTimestamp), "%d.%03d", seconds, milliSeconds);
 250         s << relativeTimestamp << ':';
 251     }
 252 }
 253
 254 #endif
 255
 256 }
 257
 258 void sal_detail_log(
 259     sal_detail_LogLevel level, char const * area, char const * where,
 260     char const * message, sal_uInt32 backtraceDepth)
 261 {
 262     std::ostringstream s;
 263 #if !defined ANDROID
 264     // On Android, the area will be used as the "tag," and log info already
 265     // contains timestamp and PID.
 266     if (!sal_use_syslog) {
 267         maybeOutputTimestamp(s);
 268         s << toString(level) << ':';
 269     }
 270     if (level != SAL_DETAIL_LOG_LEVEL_DEBUG) {
 271         s << area << ':';
 272     }
 273     s << OSL_DETAIL_GETPID << ':';
 274 #endif
 275     s << osl::Thread::getCurrentIdentifier() << ':';
 276     if (level == SAL_DETAIL_LOG_LEVEL_DEBUG) {
 277         s << ' ';
 278     } else {
 279         const size_t nStrLen(std::strlen(SRCDIR "/"));
 280         s << (where
 281               + (std::strncmp(where, SRCDIR "/", nStrLen) == 0
 282                  ? nStrLen : 0));
 283     }
 284     s << message;
 285     if (backtraceDepth != 0) {
 286         s << " at:\n" << osl::detail::backtraceAsString(backtraceDepth);
 287     }
 288
 289 #if defined ANDROID
 290     int android_log_level;
 291     switch (level) {
 292     case SAL_DETAIL_LOG_LEVEL_INFO:
 293         android_log_level = ANDROID_LOG_INFO;
 294         break;
 295     case SAL_DETAIL_LOG_LEVEL_WARN:
 296         android_log_level = ANDROID_LOG_WARN;
 297         break;
 298     case SAL_DETAIL_LOG_LEVEL_DEBUG:
 299         android_log_level = ANDROID_LOG_DEBUG;
 300         break;
 301     default:
 302         android_log_level = ANDROID_LOG_INFO;
 303         break;
 304     }
 305     __android_log_print(
 306         android_log_level, area == 0 ? "LibreOffice" : area, "%s",
 307         s.str().c_str());
 308 #else
 309     if (sal_use_syslog) {
 310 #if HAVE_SYSLOG_H
 311         int prio;
 312         switch (level) {
 313         case SAL_DETAIL_LOG_LEVEL_INFO:
 314             prio = LOG_INFO;
 315             break;
 316         case SAL_DETAIL_LOG_LEVEL_WARN:
 317             prio = LOG_WARNING;
 318             break;
 319         case SAL_DETAIL_LOG_LEVEL_DEBUG:
 320             prio = LOG_DEBUG;
 321             break;
 322         default:
 323             assert(false); // this cannot happen
 324             prio = LOG_WARNING;
 325         }
 326         syslog(prio, "%s", s.str().c_str());
 327 #endif
 328     } else {
 329         // avoid calling getLogFile() more than once
 330         static std::ofstream * logFile = getLogFile();
 331         if (logFile) {
 332             *logFile << s.str() << std::endl;
 333         }
 334         else {
 335             s << '\n';
 336 #ifdef _WIN32
 337             // write to Windows debugger console, too
 338             OutputDebugStringA(s.str().c_str());
 339 #endif
 340             std::fputs(s.str().c_str(), stderr);
 341             std::fflush(stderr);
 342         }
 343     }
 344 #endif
 345 }
 346
 347 void sal_detail_set_log_selector(char const *logSelector)
 348 {
 349     pLogSelector = logSelector;
 350 }
 351
 352 void sal_detail_logFormat(
 353     sal_detail_LogLevel level, char const * area, char const * where,
 354     char const * format, ...)
 355 {
 356     const sal_detail_LogAction eAction
 357         = static_cast<sal_detail_LogAction>(sal_detail_log_report(level, area));
 358     if (eAction == SAL_DETAIL_LOG_ACTION_IGNORE)
 359         return;
 360
 361     std::va_list args;
 362     va_start(args, format);
 363     char buf[1024];
 364     int const len = sizeof buf - RTL_CONSTASCII_LENGTH("...");
 365     int n = vsnprintf(buf, len, format, args);
 366     if (n < 0) {
 367         std::strcpy(buf, "???");
 368     } else if (n >= len) {
 369         std::strcpy(buf + len - 1, "...");
 370     }
 371     sal_detail_log(level, area, where, buf, 0);
 372     va_end(args);
 373
 374     if (eAction == SAL_DETAIL_LOG_ACTION_FATAL)
 375         std::abort();
 376 }
 377
 378 unsigned char sal_detail_log_report(sal_detail_LogLevel level, char const * area)
 379 {
 380     if (level == SAL_DETAIL_LOG_LEVEL_DEBUG) {
 381         return SAL_DETAIL_LOG_ACTION_LOG;
 382     }
 383     assert(area != nullptr);
 384     static char const* const envEnv = [] {
 385         char const* pResult =  getLogLevelEnvVar();
 386         if (!pResult)
 387             pResult = "+WARN";
 388         return pResult;
 389     }();
 390     char const* const env = (pLogSelector == nullptr ? envEnv : pLogSelector);
 391     std::size_t areaLen = std::strlen(area);
 392     enum Sense { POSITIVE = 0, NEGATIVE = 1 };
 393     std::size_t senseLen[2] = { 0, 1 };
 394         // initial senseLen[POSITIVE] < senseLen[NEGATIVE], so that if there are
 395         // no matching switches at all, the result will be negative (and
 396         // initializing with 1 is safe as the length of a valid switch, even
 397         // without the "+"/"-" prefix, will always be > 1)
 398     bool senseFatal[2] = { false, false };
 399     bool seenWarn = false;
 400     bool bFlagFatal = false;
 401     for (char const * p = env;;) {
 402         Sense sense;
 403         switch (*p++) {
 404         case '\0':
 405         {
 406             if (level == SAL_DETAIL_LOG_LEVEL_WARN && !seenWarn)
 407                 return sal_detail_log_report(SAL_DETAIL_LOG_LEVEL_INFO, area);
 408
 409             sal_detail_LogAction eAction = SAL_DETAIL_LOG_ACTION_IGNORE;
 410             // if a specific item is positive and negative (==), default to positive
 411             if (senseLen[POSITIVE] >= senseLen[NEGATIVE])
 412             {
 413                 if (senseFatal[POSITIVE]) eAction = SAL_DETAIL_LOG_ACTION_FATAL;
 414                 else eAction = SAL_DETAIL_LOG_ACTION_LOG;
 415             }
 416             return eAction;
 417         }
 418         case '+':
 419             sense = POSITIVE;
 420             break;
 421         case '-':
 422             sense = NEGATIVE;
 423             break;
 424         default:
 425             return SAL_DETAIL_LOG_ACTION_LOG; // upon an illegal SAL_LOG value, enable everything
 426         }
 427         char const * p1 = p;
 428         while (*p1 != '.' && *p1 != '+' && *p1 != '-' && *p1 != '\0') {
 429             ++p1;
 430         }
 431         bool match;
 432         if (equalStrings(p, p1 - p, RTL_CONSTASCII_STRINGPARAM("INFO"))) {
 433             match = level == SAL_DETAIL_LOG_LEVEL_INFO;
 434         } else if (equalStrings(p, p1 - p, RTL_CONSTASCII_STRINGPARAM("WARN")))
 435         {
 436             match = level == SAL_DETAIL_LOG_LEVEL_WARN;
 437             seenWarn = true;
 438         } else if (equalStrings(p, p1 - p, RTL_CONSTASCII_STRINGPARAM("FATAL")))
 439         {
 440             bFlagFatal = (sense == POSITIVE);
 441             match = false;
 442         } else if (equalStrings(p, p1 - p, RTL_CONSTASCII_STRINGPARAM("TIMESTAMP")) ||
 443                    equalStrings(p, p1 - p, RTL_CONSTASCII_STRINGPARAM("RELATIVETIMER")))
 444         {
 445             // handled later
 446             match = false;
 447         } else {
 448             return SAL_DETAIL_LOG_ACTION_LOG;
 449                 // upon an illegal SAL_LOG value, everything is considered
 450                 // positive
 451         }
 452         char const * p2 = p1;
 453         while (*p2 != '+' && *p2 != '-' && *p2 != '\0') {
 454             ++p2;
 455         }
 456         if (match) {
 457             if (*p1 == '.') {
 458                 ++p1;
 459                 std::size_t n = p2 - p1;
 460                 if ((n == areaLen && equalStrings(p1, n, area, areaLen))
 461                     || (n < areaLen && area[n] == '.'
 462                         && equalStrings(p1, n, area, n)))
 463                 {
 464                     senseLen[sense] = p2 - p;
 465                     senseFatal[sense] = bFlagFatal;
 466                 }
 467             } else {
 468                 senseLen[sense] = p1 - p;
 469                 senseFatal[sense] = bFlagFatal;
 470             }
 471         }
 472         p = p2;
 473     }
 474 }
 475
 476 /* vim:set shiftwidth=4 softtabstop=4 expandtab: */