src/syncevo/Logging.cpp

   1 /*
   2  * Copyright (C) 2009 Patrick Ohly <patrick.ohly@gmx.de>
   3  * Copyright (C) 2009 Intel Corporation
   4  *
   5  * This library is free software; you can redistribute it and/or
   6  * modify it under the terms of the GNU Lesser General Public
   7  * License as published by the Free Software Foundation; either
   8  * version 2.1 of the License, or (at your option) version 3.
   9  *
  10  * This library is distributed in the hope that it will be useful,
  11  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  12  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
  13  * Lesser General Public License for more details.
  14  *
  15  * You should have received a copy of the GNU Lesser General Public
  16  * License along with this library; if not, write to the Free Software
  17  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
  18  * 02110-1301  USA
  19  */
  20
  21 #include <syncevo/Logging.h>
  22 #include <syncevo/LogStdout.h>
  23 #include <syncevo/LogRedirect.h>
  24
  25 #include <vector>
  26 #include <string.h>
  27
  28 #include <syncevo/declarations.h>
  29 SE_BEGIN_CXX
  30
  31 static RecMutex logMutex;
  32 /**
  33  * POD to have it initialized without relying on a constructor to run.
  34  */
  35 static std::string *logProcessName;
  36
  37 void Logger::setProcessName(const std::string &name)
  38 {
  39     RecMutex::Guard guard = logMutex.lock();
  40     if (!logProcessName) {
  41         logProcessName = new std::string(name);
  42     } else {
  43         *logProcessName = name;
  44     }
  45 }
  46
  47 std::string Logger::getProcessName()
  48 {
  49     RecMutex::Guard guard = logMutex.lock();
  50     return logProcessName ? *logProcessName : "";
  51 }
  52
  53 RecMutex::Guard Logger::lock()
  54 {
  55     return logMutex.lock();
  56 }
  57
  58 Logger::Logger() :
  59     m_level(INFO)
  60 {
  61 }
  62
  63 Logger::~Logger()
  64 {
  65 }
  66
  67 /**
  68  * Create (if necessary) and return the logger stack.
  69  * It has at least one entry.
  70  *
  71  * logMutex must be locked when calling this.
  72  */
  73 static std::vector<Logger::Handle> &LoggersSingleton()
  74 {
  75     // allocate array once and never free it because it might be needed till
  76     // the very end of the application life cycle
  77     static std::vector<Logger::Handle> *loggers;
  78     if (!loggers) {
  79         loggers = new std::vector<Logger::Handle>;
  80         // Ensure that the array is never empty.
  81         boost::shared_ptr<Logger> logger(new LoggerStdout);
  82         loggers->push_back(logger);
  83     }
  84     return *loggers;
  85 }
  86
  87 Logger::Handle Logger::instance()
  88 {
  89     RecMutex::Guard guard = logMutex.lock();
  90     std::vector<Handle> &loggers = LoggersSingleton();
  91     return loggers.back();
  92 }
  93
  94 void Logger::addLogger(const Handle &logger)
  95 {
  96     RecMutex::Guard guard = logMutex.lock();
  97     std::vector<Handle> &loggers = LoggersSingleton();
  98
  99     loggers.push_back(logger);
 100 }
 101
 102 void Logger::removeLogger(Logger *logger)
 103 {
 104     RecMutex::Guard guard = logMutex.lock();
 105     std::vector<Handle> &loggers = LoggersSingleton();
 106
 107     for (ssize_t i = loggers.size() - 1;
 108          i >= 0;
 109          --i) {
 110         if (loggers[i] == logger) {
 111             loggers[i].remove();
 112             loggers.erase(loggers.begin() + i);
 113             break;
 114         }
 115     }
 116 }
 117
 118 void Logger::formatLines(Level msglevel,
 119                              Level outputlevel,
 120                              const std::string *processName,
 121                              const std::string *prefix,
 122                              const char *format,
 123                              va_list args,
 124                              boost::function<void (std::string &buffer, size_t expectedTotal)> print)
 125 {
 126     std::string tag;
 127
 128     // in case of 'SHOW' level, don't print level and prefix information
 129     if (msglevel != SHOW) {
 130         std::string reltime;
 131         std::string procname;
 132         std::string firstLine;
 133
 134         // Run non-blocking operations on shared data while
 135         // holding the mutex.
 136         {
 137             RecMutex::Guard guard = logMutex.lock();
 138             const std::string *realProcname;
 139
 140             if (processName) {
 141                 realProcname = processName;
 142             } else {
 143                 if (!logProcessName) {
 144                     logProcessName = new std::string;
 145                 }
 146                 realProcname = logProcessName;
 147             }
 148             if (!realProcname->empty()) {
 149                 procname.reserve(realProcname->size() + 1);
 150                 procname += " ";
 151                 procname += *realProcname;
 152             }
 153
 154             if (outputlevel >= DEBUG) {
 155                 // add relative time stamp
 156                 Timespec now = Timespec::monotonic();
 157                 if (!m_startTime) {
 158                     // first message, start counting time
 159                     m_startTime = now;
 160                     time_t nowt = time(NULL);
 161                     struct tm tm_gm, tm_local;
 162                     char buffer[2][80];
 163                     gmtime_r(&nowt, &tm_gm);
 164                     localtime_r(&nowt, &tm_local);
 165                     reltime = " 00:00:00";
 166                     strftime(buffer[0], sizeof(buffer[0]),
 167                              "%a %Y-%m-%d %H:%M:%S",
 168                              &tm_gm);
 169                     strftime(buffer[1], sizeof(buffer[1]),
 170                              "%H:%M %z %Z",
 171                              &tm_local);
 172                     std::string line =
 173                         StringPrintf("[DEBUG%s%s] %s UTC = %s\n",
 174                                      procname.c_str(),
 175                                      reltime.c_str(),
 176                                      buffer[0],
 177                                      buffer[1]);
 178                 } else {
 179                     if (now >= m_startTime) {
 180                         Timespec delta = now - m_startTime;
 181                         reltime = StringPrintf(" %02ld:%02ld:%02ld",
 182                                                delta.tv_sec / (60 * 60),
 183                                                (delta.tv_sec % (60 * 60)) / 60,
 184                                                delta.tv_sec % 60);
 185                     } else {
 186                         reltime = " ??:??:??";
 187                     }
 188                 }
 189             }
 190         }
 191
 192         if (!firstLine.empty()) {
 193             print(firstLine, 1);
 194         }
 195         tag = StringPrintf("[%s%s%s] %s%s",
 196                            levelToStr(msglevel),
 197                            procname.c_str(),
 198                            reltime.c_str(),
 199                            prefix ? prefix->c_str() : "",
 200                            prefix ? ": " : "");
 201     }
 202
 203     std::string output = StringPrintfV(format, args);
 204
 205     if (!tag.empty()) {
 206         // Print individual lines.
 207         //
 208         // Total size is guessed by assuming an average line length of
 209         // around 40 characters to predict number of lines.
 210         size_t expectedTotal = (output.size() / 40 + 1) * tag.size() + output.size();
 211         size_t pos = 0;
 212         while (true) {
 213             size_t next = output.find('\n', pos);
 214             if (next != output.npos) {
 215                 std::string line;
 216                 line.reserve(tag.size() + next + 1 - pos);
 217                 line.append(tag);
 218                 line.append(output, pos, next + 1 - pos);
 219                 print(line, expectedTotal);
 220                 pos = next + 1;
 221             } else {
 222                 break;
 223             }
 224         }
 225         if (pos < output.size() || output.empty()) {
 226             // handle dangling last line or empty chunk (don't
 227             // want empty line for that, print at least the tag)
 228             std::string line;
 229             line.reserve(tag.size() + output.size() - pos + 1);
 230             line.append(tag);
 231             line.append(output, pos, output.size() - pos);
 232             line += '\n';
 233             print(line, expectedTotal);
 234         }
 235     } else {
 236         if (!boost::ends_with(output, "\n")) {
 237             // append newline if necessary
 238             output += '\n';
 239         }
 240         print(output, 0);
 241     }
 242 }
 243
 244 Logger::MessageOptions::MessageOptions(Level level) :
 245     m_level(level),
 246     m_prefix(NULL),
 247     m_file(NULL),
 248     m_line(0),
 249     m_function(NULL),
 250     m_processName(NULL)
 251 {
 252 }
 253
 254 Logger::MessageOptions::MessageOptions(Level level,
 255                                        const std::string *prefix,
 256                                        const char *file,
 257                                        int line,
 258                                        const char *function,
 259                                        int flags) :
 260     m_level(level),
 261     m_prefix(prefix),
 262     m_file(file),
 263     m_line(line),
 264     m_function(function),
 265     m_processName(NULL),
 266     m_flags(flags)
 267 {
 268 }
 269
 270 Logger::Handle::Handle() throw ()
 271 {
 272 }
 273
 274 Logger::Handle::Handle(Logger *logger) throw ()
 275 {
 276     m_logger.reset(logger);
 277 }
 278
 279 Logger::Handle::Handle(const Handle &other) throw ()
 280 {
 281     m_logger = other.m_logger;
 282 }
 283
 284 Logger::Handle & Logger::Handle::operator = (const Handle &other) throw ()
 285 {
 286     if (this != &other) {
 287         m_logger = other.m_logger;
 288     }
 289     return *this;
 290 }
 291
 292 Logger::Handle::~Handle() throw ()
 293 {
 294     m_logger.reset();
 295 }
 296
 297 void Logger::Handle::message(Level level,
 298                              const std::string *prefix,
 299                              const char *file,
 300                              int line,
 301                              const char *function,
 302                              const char *format,
 303                              ...)
 304 {
 305     va_list args;
 306     va_start(args, format);
 307     m_logger->messagev(MessageOptions(level, prefix, file, line, function), format, args);
 308     va_end(args);
 309 }
 310
 311 void Logger::Handle::message(Level level,
 312                              const std::string &prefix,
 313                              const char *file,
 314                              int line,
 315                              const char *function,
 316                              const char *format,
 317                              ...)
 318 {
 319     va_list args;
 320     va_start(args, format);
 321     m_logger->messagev(MessageOptions(level, &prefix, file, line, function), format, args);
 322     va_end(args);
 323 }
 324
 325 void Logger::Handle::messageWithOptions(const MessageOptions &options,
 326                                         const char *format,
 327                                         ...)
 328 {
 329     va_list args;
 330     va_start(args, format);
 331     m_logger->messagev(options, format, args);
 332     va_end(args);
 333 }
 334
 335 const char *Logger::levelToStr(Level level)
 336 {
 337     switch (level) {
 338     case SHOW: return "SHOW";
 339     case ERROR: return "ERROR";
 340     case WARNING: return "WARNING";
 341     case INFO: return "INFO";
 342     case DEV: return "DEVELOPER";
 343     case DEBUG: return "DEBUG";
 344     default: return "???";
 345     }
 346 }
 347
 348 Logger::Level Logger::strToLevel(const char *str)
 349 {
 350     // order is based on a rough estimate of message frequency of the
 351     // corresponding type
 352     if (!str || !strcmp(str, "DEBUG")) {
 353         return DEBUG;
 354     } else if (!strcmp(str, "INFO")) {
 355         return INFO;
 356     } else if (!strcmp(str, "SHOW")) {
 357         return SHOW;
 358     } else if (!strcmp(str, "ERROR")) {
 359         return ERROR;
 360     } else if (!strcmp(str, "WARNING")) {
 361         return WARNING;
 362     } else if (!strcmp(str, "DEV")) {
 363         return DEV;
 364     } else {
 365         return DEBUG;
 366     }
 367 }
 368
 369 #ifdef HAVE_GLIB
 370 void Logger::glogFunc(const gchar *logDomain,
 371                       GLogLevelFlags logLevel,
 372                       const gchar *message,
 373                       gpointer userData)
 374 {
 375     Level level =
 376         (logLevel & (G_LOG_LEVEL_ERROR|G_LOG_LEVEL_CRITICAL)) ? ERROR :
 377         (logLevel & G_LOG_LEVEL_WARNING) ? WARNING :
 378         (logLevel & (G_LOG_LEVEL_MESSAGE|G_LOG_LEVEL_INFO)) ? SHOW :
 379         DEBUG;
 380
 381     // Downgrade some know error messages as registered with
 382     // the LogRedirect helper class. That messages are registered
 383     // there is a historic artifact.
 384     if (level != DEBUG &&
 385         LogRedirect::ignoreError(message)) {
 386         level = DEBUG;
 387     }
 388
 389     Logger::instance().message(level,
 390                                NULL,
 391                                NULL,
 392                                0,
 393                                NULL,
 394                                "%s%s%s",
 395                                logDomain ? logDomain : "",
 396                                logDomain ? ": " : "",
 397                                message);
 398 }
 399
 400 #endif
 401
 402 int Logger::sysyncPrintf(FILE *stream,
 403                          const char *format,
 404                          ...)
 405 {
 406     va_list args;
 407     va_start(args, format);
 408     static const std::string prefix("SYSYNC");
 409     if (boost::starts_with(format, prefix) &&
 410         format[prefix.size()] == ' ') {
 411         // Skip initial "SYSYNC " prefix, because it will get re-added
 412         // in a better way (= to each line) via the prefix parameter.
 413         format += prefix.size() + 1;
 414     }
 415     Logger::instance().messagev(MessageOptions(DEBUG, &prefix, NULL, 0, NULL), format, args);
 416     va_end(args);
 417
 418     return 0;
 419 }
 420
 421 SE_END_CXX