hphp/util/logger.cpp

   1 /*
   2    +----------------------------------------------------------------------+
   3    | HipHop for PHP                                                       |
   4    +----------------------------------------------------------------------+
   5    | Copyright (c) 2010-present Facebook, Inc. (http://www.facebook.com)  |
   6    +----------------------------------------------------------------------+
   7    | This source file is subject to version 3.01 of the PHP license,      |
   8    | that is bundled with this package in the file LICENSE, and is        |
   9    | available through the world-wide-web at the following url:           |
  10    | http://www.php.net/license/3_01.txt                                  |
  11    | If you did not receive a copy of the PHP license and are unable to   |
  12    | obtain it through the world-wide-web, please send a note to          |
  13    | license@php.net so we can mail you a copy immediately.               |
  14    +----------------------------------------------------------------------+
  15 */
  16 #include "hphp/util/logger.h"
  17
  18 #include "hphp/util/assertions.h"
  19 #include "hphp/util/exception.h"
  20 #include "hphp/util/process.h"
  21 #include "hphp/util/stack-trace.h"
  22 #include "hphp/util/string-vsnprintf.h"
  23 #include "hphp/util/text-color.h"
  24
  25 #include <folly/portability/Syslog.h>
  26 #include <folly/portability/Unistd.h>
  27
  28 #include <typeinfo>
  29
  30 #define IMPLEMENT_LOGLEVEL(LOGLEVEL)                                    \
  31   void Logger::LOGLEVEL(const char *fmt, ...) {                         \
  32     if (LogLevel < Log ## LOGLEVEL) return;                             \
  33     if (!IsEnabled()) return;                                           \
  34     std::string msg;                                                    \
  35     va_list ap; va_start(ap, fmt);                                      \
  36     string_vsnprintf(msg, fmt, ap);                                     \
  37     va_end(ap);                                                         \
  38     LogImpl(Log ## LOGLEVEL, msg, nullptr);                             \
  39   }                                                                     \
  40   void Logger::LOGLEVEL(const std::string &msg) {                       \
  41     if (LogLevel < Log ## LOGLEVEL) return;                             \
  42     LogImpl(Log ## LOGLEVEL, msg, nullptr);                             \
  43   }
  44
  45 namespace HPHP {
  46
  47 ///////////////////////////////////////////////////////////////////////////////
  48
  49 IMPLEMENT_LOGLEVEL(Error);
  50 IMPLEMENT_LOGLEVEL(Warning);
  51 IMPLEMENT_LOGLEVEL(Info);
  52 IMPLEMENT_LOGLEVEL(Verbose);
  53
  54 ///////////////////////////////////////////////////////////////////////////////
  55
  56 constexpr const char* Logger::DEFAULT;
  57
  58 bool Logger::AlwaysEscapeLog = true;
  59 bool Logger::UseSyslog = false;
  60 bool Logger::UseLogFile = true;
  61 bool Logger::UseRequestLog = false;
  62 bool Logger::UseCronolog = false;
  63 Logger::LogLevelType Logger::LogLevel = LogInfo;
  64 bool Logger::LogHeader = false;
  65 bool Logger::LogNativeStackTrace = true;
  66 std::string Logger::ExtraHeader;
  67 int Logger::MaxMessagesPerRequest = -1;
  68 bool Logger::Escape = true;
  69 pid_t Logger::s_pid;
  70 ServiceData::ExportedCounter* Logger::s_errorLines =
  71     ServiceData::createCounter("errorlog_lines");
  72 // ideally this should be "errorlog_serialized_bytes" but this was
  73 // added long ago and many tools rely on it.
  74 ServiceData::ExportedCounter* Logger::s_errorSerializedBytes =
  75     ServiceData::createCounter("errorlog_bytes");
  76 ServiceData::ExportedCounter* Logger::s_errorCompressedBytes =
  77     ServiceData::createCounter("errorlog_bytes_compressed");
  78 THREAD_LOCAL(Logger::ThreadData, Logger::s_threadData);
  79
  80 std::map<std::string, Logger*> Logger::s_loggers = {
  81   {Logger::DEFAULT, new Logger()},
  82 };
  83
  84 void Logger::Log(LogLevelType level, const char* type, const Exception& e,
  85                  const char *file /* = NULL */, int line /* = 0 */) {
  86   if (!IsEnabled()) return;
  87   auto msg = type + e.getMessage();
  88   if (file && file[0]) {
  89     msg += folly::sformat(" in {} on line {}", file, line);
  90   }
  91   LogImpl(level, msg, nullptr);
  92 }
  93
  94 void Logger::OnNewRequest() {
  95   ThreadData *threadData = s_threadData.get();
  96   ++threadData->request;
  97   threadData->message = 0;
  98 }
  99
 100 void Logger::ResetRequestCount() {
 101   ThreadData *threadData = s_threadData.get();
 102   threadData->request = 0;
 103   threadData->message = 0;
 104 }
 105
 106 int64_t Logger::GetRequestId() {
 107   ThreadData *threadData = s_threadData.get();
 108   return threadData->request;
 109 }
 110
 111 void Logger::LogImpl(LogLevelType level, const std::string &msg,
 112                      const StackTrace *stackTrace,
 113                      bool escape /* = false */, bool escapeMore /* = false */) {
 114
 115   ThreadData *threadData = s_threadData.get();
 116   if (threadData->message != -1 &&
 117       ++threadData->message > MaxMessagesPerRequest &&
 118       MaxMessagesPerRequest >= 0) {
 119     return;
 120   }
 121   for (auto& l : s_loggers) {
 122     auto& logger = l.second;
 123     if (logger) {
 124       auto growth = logger->log(level, msg, stackTrace, escape, escapeMore);
 125       s_errorLines->addValue(growth.lines);
 126       s_errorSerializedBytes->addValue(growth.serializedBytes);
 127       s_errorCompressedBytes->addValue(growth.compressedBytes);
 128     }
 129   }
 130 }
 131
 132 void Logger::SetStandardOut(const std::string &name, FILE *file) {
 133   auto it = s_loggers.find(name);
 134   if (it != s_loggers.end()) {
 135     auto& logger = it->second;
 136     logger->m_standardOut = file;
 137   }
 138 }
 139
 140 void Logger::FlushAll() {
 141   for (auto& l : s_loggers) {
 142     auto& logger = l.second;
 143     if (logger) {
 144       auto growth = logger->flush();
 145       s_errorLines->addValue(growth.lines);
 146       s_errorSerializedBytes->addValue(growth.serializedBytes);
 147       s_errorCompressedBytes->addValue(growth.compressedBytes);
 148     }
 149   }
 150 }
 151
 152 void Logger::SetBatchSize(size_t bsize) {
 153   for (auto& l : s_loggers) {
 154     auto& logger = l.second;
 155     logger->setBatchSize(bsize);
 156   }
 157 }
 158
 159 void Logger::SetFlushTimeout(std::chrono::milliseconds timeoutMs) {
 160   for (auto& l : s_loggers) {
 161     auto& logger = l.second;
 162     logger->setFlushTimeout(timeoutMs);
 163   }
 164 }
 165
 166 int Logger::GetSyslogLevel(LogLevelType level) {
 167   switch (level) {
 168   case LogError:   return LOG_ERR;
 169   case LogWarning: return LOG_WARNING;
 170   case LogInfo:    return LOG_INFO;
 171   case LogVerbose: return LOG_DEBUG;
 172   default:         return LOG_NOTICE;
 173   }
 174 }
 175
 176 LogGrowth Logger::log(LogLevelType level, const std::string &msg,
 177                       const StackTrace *stackTrace,
 178                       bool escape /* = false */,
 179                       bool escapeMore /* = false */) {
 180   if (Logger::AlwaysEscapeLog && Logger::Escape) {
 181     escape = true;
 182   }
 183   assertx(!escapeMore || escape); // escape must be enabled to escapeMore
 184
 185   std::unique_ptr<StackTrace> deleter;
 186   if (LogNativeStackTrace && stackTrace == nullptr) {
 187     deleter.reset(new StackTrace());
 188     stackTrace = deleter.get();
 189   }
 190
 191   if (UseSyslog) {
 192     syslog(GetSyslogLevel(level), "%s", msg.c_str());
 193   }
 194   int bytes = 0;
 195   if (UseLogFile) {
 196     ThreadData *threadData = s_threadData.get();
 197     FILE* tf = threadData->log;
 198     FILE* f = output();
 199     std::string header, sheader;
 200     if (LogHeader) {
 201       header = GetHeader();
 202       if (LogNativeStackTrace) {
 203         sheader = header + "[" + stackTrace->hexEncode(5) + "] ";
 204       } else {
 205         sheader = header;
 206       }
 207     }
 208     const char *escaped = escape ? EscapeString(msg) : msg.c_str();
 209     const char *ending = escapeMore ? "\\n" : "\n";
 210     if (f == m_standardOut && s_stderr_color) {
 211       bytes =
 212         fprintf(f, "%s%s%s%s%s",
 213                 s_stderr_color, sheader.c_str(), msg.c_str(), ending,
 214                 ANSI_COLOR_END);
 215     } else {
 216       bytes = fprintf(f, "%s%s%s", sheader.c_str(), escaped, ending);
 217     }
 218     if (tf && tf != f) {
 219       int threadBytes =
 220         fprintf(tf, "%s%s%s", header.c_str(), escaped, ending);
 221       fflush(tf);
 222       threadData->flusher.recordWriteAndMaybeDropCaches(tf, threadBytes);
 223     }
 224     if (threadData->hook) {
 225       (*threadData->hook)(header.c_str(), msg.c_str(), ending);
 226     }
 227     if (escape) {
 228       free((void*)escaped);
 229     }
 230     fflush(f);
 231     if (UseCronolog || (m_output && !m_isPipeOutput)) {
 232       m_flusher.recordWriteAndMaybeDropCaches(f, bytes);
 233     }
 234   }
 235   return LogGrowth(1, static_cast<uint64_t>(bytes), static_cast<uint64_t>(bytes));
 236 }
 237
 238 void Logger::ResetPid() {
 239   s_pid = getpid();
 240 }
 241
 242 std::string Logger::GetHeader() {
 243   static std::string host = Process::GetHostName();
 244
 245   time_t now = time(nullptr);
 246   char snow[64];
 247   ctime_r(&now, snow);
 248   // Eliminate trailing newline from ctime_r.
 249   snow[24] = '\0';
 250
 251   char header[128];
 252   ThreadData *threadData = s_threadData.get();
 253   snprintf(header, sizeof(header), "[%s] [hphp] [%lld:%llx:%d:%06d%s] ",
 254            snow,
 255            (unsigned long long)s_pid,
 256            (unsigned long long)Process::GetThreadId(),
 257            threadData->request,
 258            (threadData->message == -1 ? 0 : threadData->message),
 259            ExtraHeader.c_str());
 260   return header;
 261 }
 262
 263 char *Logger::EscapeString(const std::string &msg) {
 264   auto new_size = msg.size() * 4 + 1;
 265   char *new_str = (char *)malloc(new_size);
 266   const char *source;
 267   const char *end;
 268   char *target;
 269   for (source = msg.c_str(), end = source + msg.size(), target = new_str;
 270        source < end && *source; source++) {
 271     char c = *source;
 272     if ((unsigned char) c < 32 || (unsigned char) c > 126) {
 273       *target++ = '\\';
 274       switch (c) {
 275       case '\n': *target++ = 'n'; break;
 276       case '\t': *target++ = 't'; break;
 277       case '\r': *target++ = 'r'; break;
 278       case '\v': *target++ = 'v'; break;
 279       case '\b': *target++ = 'b'; break;
 280       default: {
 281         auto avail = new_size - (target - new_str);
 282         target += snprintf(target, avail, "x%02x", (unsigned char)c);
 283         assertx(target < new_str + new_size); // we allocated 4x space
 284       }}
 285     } else if (c == '\\') {
 286       *target++ = c;
 287       *target++ = c;
 288     } else {
 289       *target++ = c;
 290     }
 291   }
 292   *target = 0;
 293   return new_str;
 294 }
 295
 296 bool Logger::SetThreadLog(const char *file, bool threadOnly) {
 297   if (auto log = fopen(file, "a")) {
 298     ClearThreadLog();
 299     s_threadData->log = log;
 300     s_threadData->threadLogOnly = threadOnly;
 301     return true;
 302   }
 303   return false;
 304 }
 305 void Logger::ClearThreadLog() {
 306   ThreadData *threadData = s_threadData.get();
 307   if (threadData->log) {
 308     fclose(threadData->log);
 309     threadData->log = nullptr;
 310   }
 311 }
 312
 313 void Logger::SetThreadHook(LoggerHook* hook) {
 314   s_threadData.get()->hook = hook;
 315 }
 316
 317 void Logger::SetTheLogger(const std::string &name, Logger* newLogger) {
 318   auto& logger = s_loggers[name];
 319   if (logger != nullptr) delete logger;
 320   if (newLogger) {
 321     logger = newLogger;
 322   } else {
 323     s_loggers.erase(name);
 324   }
 325 }
 326
 327 bool Logger::IsDefaultLogger(const std::string &name) {
 328   auto it = s_loggers.find(name);
 329   if (it == s_loggers.end()) return true;
 330   return typeid(*it->second) == typeid(Logger);
 331 }
 332
 333 void Logger::UnlimitThreadMessages() {
 334   ThreadData *threadData = s_threadData.get();
 335   threadData->message = -1;
 336 }
 337
 338 Cronolog *Logger::CronoOutput(const std::string &name) {
 339   auto it = s_loggers.find(name);
 340   if (it != s_loggers.end()) {
 341     auto& logger = it->second;
 342     return &logger->m_cronOutput;
 343   }
 344   return nullptr;
 345 }
 346
 347 void Logger::SetOutput(const std::string &name, FILE *output, bool isPipe) {
 348   auto it = s_loggers.find(name);
 349   if (it != s_loggers.end()) {
 350     auto& logger = it->second;
 351     if (logger->m_output && logger->m_output != output) {
 352       if (logger->m_isPipeOutput) {
 353         pclose(logger->m_output);
 354       } else {
 355         fclose(logger->m_output);
 356       }
 357     }
 358     logger->m_output = output;
 359     logger->m_isPipeOutput = isPipe;
 360   }
 361 }
 362
 363 std::pair<FILE*, bool> Logger::GetOutput(const std::string &name) {
 364   const auto it = s_loggers.find(name);
 365   if (it != s_loggers.end()) {
 366     const auto& logger = it->second;
 367     return std::make_pair(logger->m_output, logger->m_isPipeOutput);
 368   }
 369   return std::make_pair(nullptr, false);
 370 }
 371
 372 FILE* Logger::output() {
 373   ThreadData *threadData = s_threadData.get();
 374   if (threadData->log && threadData->threadLogOnly) {
 375     return threadData->log;
 376   }
 377   FILE* cronOut = m_cronOutput.getOutputFile();
 378   return cronOut != nullptr ? cronOut :
 379          m_output != nullptr ? m_output : m_standardOut;
 380 }
 381
 382 ///////////////////////////////////////////////////////////////////////////////
 383 }