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