src/Log.cpp

   1 // Copyright (C) 2007 Mark Pustjens <pustjens@dds.nl>
   2 // Copyright (C) 2010-2015 Petr Pavlu <setup@dagobah.cz>
   3 //
   4 // This file is part of CenterIM.
   5 //
   6 // CenterIM is free software; you can redistribute it and/or modify
   7 // it under the terms of the GNU General Public License as published by
   8 // the Free Software Foundation; either version 2 of the License, or
   9 // (at your option) any later version.
  10 //
  11 // CenterIM is distributed in the hope that it will be useful,
  12 // but WITHOUT ANY WARRANTY; without even the implied warranty of
  13 // MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  14 // GNU General Public License for more details.
  15 //
  16 // You should have received a copy of the GNU General Public License
  17 // along with CenterIM.  If not, see <http://www.gnu.org/licenses/>.
  18
  19 // Logging facility collects all messages from the program itself and libraries
  20 // (mainly GLib and libpurple). It filters them by severity and then outputs
  21 // them to the Log window, a file or on the standard error output (stderr).
  22 //
  23 // Processing consists of three phases: initialization -> normal phase ->
  24 // finalization, and is tightly tied to the CenterIM class. The program can exit
  25 // in any of these phases.
  26 //
  27 // 1) Initialization: All messages are being buffered. If an error occurs
  28 //    during this phase, the recorded messages are printed on stderr before the
  29 //    program exits.
  30 // 2) Normal phase: When processing reaches this phase (implying no critical
  31 //    error occurred during the initialization phase), messages recorded by
  32 //    the initialization phase are output to the Log window and optionally to a
  33 //    file. New messages coming from the normal processing of the program are
  34 //    then output in the same way. A limited number of the most recent messages
  35 //    is also being buffered by this phase. If the program exists from the main
  36 //    loop normally, the recorded messages are cleared.
  37 // 3) Finalization: All messages are being buffered and when the program is
  38 //    about to exit, they will get printed on stderr together with any buffered
  39 //    messages from the previous stage.
  40 //
  41 // This mechanism ensures that if a non-recoverable error occurs during
  42 // execution of the program and it must exit abnormally, the error will always
  43 // get printed on stderr.
  44
  45 #include "Log.h"
  46
  47 #include "gettext.h"
  48 #include <cppconsui/HorizontalListBox.h>
  49 #include <cppconsui/Spacer.h>
  50 #include <cstdio>
  51 #include <cstring>
  52
  53 // Maximum number of lines in the Log window.
  54 #define LOG_WINDOW_MAX_LINES 200
  55 // Number of deleted lines when the line limit in the Log window is reached.
  56 #define LOG_WINDOW_DELETE_COUNT 40
  57
  58 // Maximum number of buffered messages in the normal phase.
  59 #define LOG_MAX_BUFFERED_MESSAGES 200
  60
  61 Log *Log::my_instance_ = nullptr;
  62
  63 Log *Log::instance()
  64 {
  65   return my_instance_;
  66 }
  67
  68 #define WRITE_METHOD(name, level)                                              \
  69   void Log::name(const char *fmt, ...)                                         \
  70   {                                                                            \
  71     va_list args;                                                              \
  72                                                                                \
  73     if (log_level_cim_ < level)                                                \
  74       return; /* Do not show this message. */                                  \
  75                                                                                \
  76     va_start(args, fmt);                                                       \
  77     logv(level, fmt, args);                                                    \
  78     va_end(args);                                                              \
  79   }
  80
  81 WRITE_METHOD(error, LEVEL_ERROR)
  82 WRITE_METHOD(critical, LEVEL_CRITICAL)
  83 WRITE_METHOD(warning, LEVEL_WARNING)
  84 WRITE_METHOD(message, LEVEL_MESSAGE)
  85 WRITE_METHOD(info, LEVEL_INFO)
  86 WRITE_METHOD(debug, LEVEL_DEBUG)
  87
  88 #undef WRITE_METHOD
  89
  90 static const char *now_formatted( void )
  91 {
  92     time_t now;
  93     struct tm nowtm;
  94     const char *formatted_time;
  95
  96     now = time( nullptr );
  97     if( now != 0 && localtime_r(&now, &nowtm) != nullptr )
  98       formatted_time = purple_date_format_long(&nowtm);
  99     else
 100       formatted_time = _("Unknown");
 101
 102     return formatted_time;
 103 }
 104
 105 void Log::logv( enum Level level, const char *fmt, va_list args )
 106 {
 107     char *text, *all;
 108
 109     text = g_strdup_vprintf(fmt, args);
 110     all = g_strconcat( now_formatted(), " ", text, NULL );
 111
 112     write(TYPE_CIM, level, all);
 113     g_free(text);
 114     g_free(all);
 115 }
 116
 117 void Log::clearAllBufferedMessages()
 118 {
 119   // Delete all buffered messages.
 120   clearBufferedMessages(init_log_items_);
 121   clearBufferedMessages(log_items_);
 122 }
 123
 124 Log::LogWindow::LogWindow() : Window(0, 0, 80, 24, nullptr, TYPE_NON_FOCUSABLE)
 125 {
 126   setColorScheme(CenterIM::SCHEME_LOG);
 127
 128   auto lbox = new CppConsUI::HorizontalListBox(AUTOSIZE, AUTOSIZE);
 129   addWidget(*lbox, 1, 1);
 130
 131   lbox->appendWidget(*(new CppConsUI::Spacer(1, AUTOSIZE)));
 132   textview_ = new CppConsUI::TextView(AUTOSIZE, AUTOSIZE, true);
 133   lbox->appendWidget(*textview_);
 134   lbox->appendWidget(*(new CppConsUI::Spacer(1, AUTOSIZE)));
 135
 136   onScreenResized();
 137 }
 138
 139 void Log::LogWindow::onScreenResized()
 140 {
 141   moveResizeRect(CENTERIM->getScreenArea(CenterIM::LOG_AREA));
 142 }
 143
 144 void Log::LogWindow::append(const char *text)
 145 {
 146   textview_->append(text);
 147
 148   // Shorten the window text.
 149   std::size_t lines_num = textview_->getLinesNumber();
 150
 151   if (lines_num > LOG_WINDOW_MAX_LINES) {
 152     // Remove some lines.
 153     textview_->erase(
 154       0, lines_num - LOG_WINDOW_MAX_LINES + LOG_WINDOW_DELETE_COUNT);
 155   }
 156 }
 157
 158 Log::LogBufferItem::LogBufferItem(Type type, Level level, const char *text)
 159   : type_(type), level_(level)
 160 {
 161   text_ = g_strdup(text);
 162 }
 163
 164 Log::LogBufferItem::~LogBufferItem()
 165 {
 166   g_free(text_);
 167 }
 168
 169 Log::Log()
 170   : phase_(PHASE_INITIALIZATION), log_window_(nullptr), logfile_(nullptr),
 171     log_level_cim_(LEVEL_DEBUG), log_level_glib_(LEVEL_DEBUG),
 172     log_level_purple_(LEVEL_DEBUG)
 173 {
 174 #define REGISTER_G_LOG_HANDLER(name, handler)                                  \
 175   g_log_set_handler((name), (GLogLevelFlags)G_LOG_LEVEL_MASK, (handler), this)
 176
 177   // Register the glib log handlers.
 178   default_handler_ = REGISTER_G_LOG_HANDLER(nullptr, default_log_handler_);
 179   glib_handler_ = REGISTER_G_LOG_HANDLER("GLib", glib_log_handler_);
 180   gmodule_handler_ = REGISTER_G_LOG_HANDLER("GModule", glib_log_handler_);
 181   glib_gobject_handler_ =
 182     REGISTER_G_LOG_HANDLER("GLib-GObject", glib_log_handler_);
 183   gthread_handler_ = REGISTER_G_LOG_HANDLER("GThread", glib_log_handler_);
 184 }
 185
 186 Log::~Log()
 187 {
 188   g_log_remove_handler(nullptr, default_handler_);
 189   g_log_remove_handler("GLib", glib_handler_);
 190   g_log_remove_handler("GModule", gmodule_handler_);
 191   g_log_remove_handler("GLib-GObject", glib_gobject_handler_);
 192   g_log_remove_handler("GThread", gthread_handler_);
 193
 194   outputAllBufferedMessages();
 195   clearAllBufferedMessages();
 196 }
 197
 198 void Log::init()
 199 {
 200   g_assert(my_instance_ == nullptr);
 201
 202   my_instance_ = new Log;
 203 }
 204
 205 void Log::finalize()
 206 {
 207   g_assert(my_instance_ != nullptr);
 208
 209   delete my_instance_;
 210   my_instance_ = nullptr;
 211 }
 212
 213 void Log::initNormalPhase()
 214 {
 215   // Normal phase is called after CppConsUI and libpurple has been initialized.
 216   // Logging to file is part of the normal phase.
 217   g_assert(phase_ == PHASE_INITIALIZATION);
 218
 219   // Init preferences.
 220   purple_prefs_add_none(CONF_PREFIX "/log");
 221   purple_prefs_add_bool(CONF_PREFIX "/log/debug", false);
 222   purple_prefs_add_string(CONF_PREFIX "/log/filename", "debug.log");
 223   purple_prefs_add_string(CONF_PREFIX "/log/log_level_cim", "info");
 224   purple_prefs_add_string(CONF_PREFIX "/log/log_level_purple", "critical");
 225   purple_prefs_add_string(CONF_PREFIX "/log/log_level_glib", "warning");
 226
 227   updateCachedPreference(CONF_PREFIX "/log/debug");
 228   updateCachedPreference(CONF_PREFIX "/log/log_level_cim");
 229   updateCachedPreference(CONF_PREFIX "/log/log_level_purple");
 230   updateCachedPreference(CONF_PREFIX "/log/log_level_glib");
 231
 232   // Connect callbacks.
 233   purple_prefs_connect_callback(
 234     this, CONF_PREFIX "/log", log_pref_change_, this);
 235
 236   // Create the log window.
 237   g_assert(log_window_ == nullptr);
 238   log_window_ = new LogWindow;
 239   log_window_->show();
 240
 241   // Normal phase is now active.
 242   phase_ = PHASE_NORMAL;
 243
 244   // Output buffered messages from the initialization phase.
 245   for (LogBufferItem *item : init_log_items_) {
 246     // Determine if this message should be displayed.
 247     Level loglevel = getLogLevel(item->getType());
 248
 249     if (loglevel >= item->getLevel())
 250       write(item->getType(), item->getLevel(), item->getText(), false);
 251
 252     delete item;
 253   }
 254   init_log_items_.clear();
 255 }
 256
 257 void Log::finalizeNormalPhase()
 258 {
 259   // Normal phase finalization is done before CppConsUI and libpurple is
 260   // finalized. Note that log levels are unchanged after the normal phase
 261   // finishes.
 262   g_assert(phase_ == PHASE_NORMAL);
 263
 264   // Delete the log window.
 265   g_assert(log_window_ != nullptr);
 266   delete log_window_;
 267   log_window_ = nullptr;
 268
 269   purple_prefs_disconnect_by_handle(this);
 270
 271   // Close the log file (if it is opened).
 272   if (logfile_ != nullptr)
 273     g_io_channel_unref(logfile_);
 274
 275   // Done with the normal phase.
 276   phase_ = PHASE_FINALIZATION;
 277 }
 278
 279 void Log::purple_print(
 280   PurpleDebugLevel purplelevel, const char *category, const char *arg_s)
 281 {
 282   Level level = convertPurpleDebugLevel(purplelevel);
 283   if (log_level_purple_ < level)
 284     return; // Do not show this message.
 285
 286   if (category == nullptr) {
 287     category = "misc";
 288     warning(_("centerim/log: purple_print() parameter category was "
 289               "not defined."));
 290   }
 291
 292   char *text = g_strdup_printf("%s libpurple/%s: %s",
 293       now_formatted(), category, arg_s);
 294   write(TYPE_PURPLE, level, text);
 295   g_free(text);
 296 }
 297
 298 gboolean Log::purple_is_enabled(
 299   PurpleDebugLevel purplelevel, const char * /*category*/)
 300 {
 301   Level level = convertPurpleDebugLevel(purplelevel);
 302
 303   if (log_level_purple_ < level)
 304     return FALSE;
 305
 306   return TRUE;
 307 }
 308
 309 void Log::default_log_handler(
 310   const char *domain, GLogLevelFlags flags, const char *msg)
 311 {
 312   if (msg == nullptr)
 313     return;
 314
 315   Level level = convertGLibDebugLevel(flags);
 316   if (log_level_glib_ < level)
 317     return; // Do not show this message.
 318
 319   char *text = g_strdup_printf("%s %s: %s",
 320       now_formatted(), domain ? domain : "g_log", msg);
 321   write(TYPE_GLIB, level, text);
 322   g_free(text);
 323 }
 324
 325 void Log::glib_log_handler(
 326   const char *domain, GLogLevelFlags flags, const char *msg)
 327 {
 328   if (msg == nullptr)
 329     return;
 330
 331   Level level = convertGLibDebugLevel(flags);
 332   if (log_level_glib_ < level)
 333     return; // Do not show this message.
 334
 335   char *text = g_strdup_printf("%s %s: %s",
 336       now_formatted(), domain ? domain : "g_log", msg);
 337   write(TYPE_GLIB, level, text);
 338   g_free(text);
 339 }
 340
 341 void Log::log_pref_change(
 342   const char *name, PurplePrefType /*type*/, gconstpointer /*val*/)
 343 {
 344   // log/* preference changed.
 345   updateCachedPreference(name);
 346 }
 347
 348 void Log::updateCachedPreference(const char *name)
 349 {
 350   if (std::strcmp(name, CONF_PREFIX "/log/debug") == 0) {
 351     bool logfile_enabled = purple_prefs_get_bool(name);
 352
 353     if (logfile_enabled && logfile_ == nullptr) {
 354       char *filename = g_build_filename(purple_user_dir(),
 355         purple_prefs_get_string(CONF_PREFIX "/log/filename"), nullptr);
 356       GError *err = nullptr;
 357
 358       logfile_ = g_io_channel_new_file(filename, "a", &err);
 359       if (logfile_ == nullptr) {
 360         error(_("centerim/log: Error opening logfile '%s' (%s)."), filename,
 361           err->message);
 362         g_clear_error(&err);
 363       }
 364       g_free(filename);
 365     }
 366     else if (!logfile_enabled && logfile_ != nullptr) {
 367       // Debug was disabled so close logfile if it is opened.
 368       g_io_channel_unref(logfile_);
 369       logfile_ = nullptr;
 370     }
 371   }
 372   else if (std::strcmp(name, CONF_PREFIX "/log/log_level_cim") == 0)
 373     log_level_cim_ = stringToLevel(purple_prefs_get_string(name));
 374   else if (std::strcmp(name, CONF_PREFIX "/log/log_level_purple") == 0)
 375     log_level_purple_ = stringToLevel(purple_prefs_get_string(name));
 376   else if (std::strcmp(name, CONF_PREFIX "/log/log_level_glib") == 0)
 377     log_level_glib_ = stringToLevel(purple_prefs_get_string(name));
 378 }
 379
 380 void Log::write(Type type, Level level, const char *text, bool buffer)
 381 {
 382   if (buffer)
 383     bufferMessage(type, level, text);
 384
 385   // If the normal phase is not active then only buffer the message.
 386   if (phase_ != PHASE_NORMAL)
 387     return;
 388
 389   g_assert(log_window_ != nullptr);
 390   log_window_->append(text);
 391   writeToFile(text);
 392 }
 393
 394 void Log::writeErrorToWindow(const char *fmt, ...)
 395 {
 396   // Can be called only if the normal phase is active.
 397   g_assert(phase_ == PHASE_NORMAL);
 398   g_assert(log_window_ != nullptr);
 399
 400   va_list args;
 401
 402   if (log_level_cim_ < LEVEL_ERROR)
 403     return; // Do not show this message.
 404
 405   va_start(args, fmt);
 406   char *text = g_strdup_vprintf(fmt, args);
 407   va_end(args);
 408
 409   log_window_->append(text);
 410   g_free(text);
 411 }
 412
 413 void Log::writeToFile(const char *text)
 414 {
 415   // Writing to a file is possible only in the normal phase.
 416   g_assert(phase_ == PHASE_NORMAL);
 417
 418   if (text == nullptr || logfile_ == nullptr)
 419     return;
 420
 421   // Write text into logfile.
 422   GError *err = nullptr;
 423
 424   if (g_io_channel_write_chars(logfile_, text, -1, nullptr, &err) !=
 425     G_IO_STATUS_NORMAL) {
 426     writeErrorToWindow(
 427       _("centerim/log: Error writing to logfile (%s)."), err->message);
 428     g_clear_error(&err);
 429   }
 430   else {
 431     // If necessary write missing EOL character.
 432     std::size_t len = std::strlen(text);
 433     if (len > 0 && text[len - 1] != '\n') {
 434       // Ignore all errors.
 435       g_io_channel_write_chars(logfile_, "\n", -1, nullptr, nullptr);
 436     }
 437   }
 438
 439   if (g_io_channel_flush(logfile_, &err) != G_IO_STATUS_NORMAL) {
 440     writeErrorToWindow(
 441       _("centerim/log: Error flushing logfile (%s)."), err->message);
 442     g_clear_error(&err);
 443   }
 444 }
 445
 446 void Log::bufferMessage(Type type, Level level, const char *text)
 447 {
 448   auto item = new LogBufferItem(type, level, text);
 449   if (phase_ == PHASE_INITIALIZATION)
 450     init_log_items_.push_back(item);
 451   else
 452     log_items_.push_back(item);
 453
 454   if (phase_ != PHASE_NORMAL)
 455     return;
 456
 457   // Reduce a number of buffered messages if the normal phase is active.
 458   std::size_t size = log_items_.size();
 459   if (size <= LOG_MAX_BUFFERED_MESSAGES)
 460     return;
 461
 462   // There can never be more than one message to remove.
 463   g_assert(size == LOG_MAX_BUFFERED_MESSAGES + 1);
 464   delete log_items_.front();
 465   log_items_.pop_front();
 466 }
 467
 468 void Log::clearBufferedMessages(LogBufferItems &items)
 469 {
 470   for (LogBufferItem *item : items)
 471     delete item;
 472   items.clear();
 473 }
 474
 475 void Log::outputBufferedMessages(LogBufferItems &items)
 476 {
 477   for (LogBufferItem *item : items) {
 478     // Determine if this message should be displayed.
 479     Level loglevel = getLogLevel(item->getType());
 480
 481     if (loglevel >= item->getLevel()) {
 482       const char *text = item->getText();
 483       g_assert(text != nullptr);
 484
 485       std::fprintf(stderr, "%s", text);
 486
 487       // If necessary write missing EOL character.
 488       std::size_t len = std::strlen(text);
 489       if (len > 0 && text[len - 1] != '\n')
 490         std::fprintf(stderr, "\n");
 491     }
 492   }
 493 }
 494
 495 void Log::outputAllBufferedMessages()
 496 {
 497   // Output all buffered messages on stderr.
 498   outputBufferedMessages(init_log_items_);
 499   outputBufferedMessages(log_items_);
 500
 501   std::fflush(stderr);
 502 }
 503
 504 Log::Level Log::convertPurpleDebugLevel(PurpleDebugLevel purplelevel)
 505 {
 506   switch (purplelevel) {
 507   case PURPLE_DEBUG_MISC:
 508     return LEVEL_DEBUG;
 509   case PURPLE_DEBUG_INFO:
 510     return LEVEL_INFO;
 511   case PURPLE_DEBUG_WARNING:
 512     return LEVEL_WARNING;
 513   case PURPLE_DEBUG_ERROR:
 514     return LEVEL_CRITICAL;
 515   case PURPLE_DEBUG_FATAL:
 516     return LEVEL_ERROR;
 517   case PURPLE_DEBUG_ALL:
 518     return LEVEL_ERROR; // Use error level so this message is always printed.
 519   }
 520
 521   warning(
 522     _("centerim/log: Unknown libpurple logging level '%d'."), purplelevel);
 523   return LEVEL_DEBUG;
 524 }
 525
 526 Log::Level Log::convertGLibDebugLevel(GLogLevelFlags gliblevel)
 527 {
 528   if (gliblevel & G_LOG_LEVEL_DEBUG)
 529     return LEVEL_DEBUG;
 530   if (gliblevel & G_LOG_LEVEL_INFO)
 531     return LEVEL_INFO;
 532   if (gliblevel & G_LOG_LEVEL_MESSAGE)
 533     return LEVEL_MESSAGE;
 534   if (gliblevel & G_LOG_LEVEL_WARNING)
 535     return LEVEL_WARNING;
 536   if (gliblevel & G_LOG_LEVEL_CRITICAL)
 537     return LEVEL_CRITICAL;
 538   if (gliblevel & G_LOG_LEVEL_ERROR)
 539     return LEVEL_ERROR;
 540
 541   warning(_("centerim/log: Unknown GLib logging level '%d'."), gliblevel);
 542   return LEVEL_DEBUG;
 543 }
 544
 545 Log::Level Log::stringToLevel(const char *slevel)
 546 {
 547   if (std::strcmp(slevel, "none") == 0)
 548     return LEVEL_NONE;
 549   else if (std::strcmp(slevel, "debug") == 0)
 550     return LEVEL_DEBUG;
 551   else if (std::strcmp(slevel, "info") == 0)
 552     return LEVEL_INFO;
 553   else if (std::strcmp(slevel, "message") == 0)
 554     return LEVEL_MESSAGE;
 555   else if (std::strcmp(slevel, "warning") == 0)
 556     return LEVEL_WARNING;
 557   else if (std::strcmp(slevel, "critical") == 0)
 558     return LEVEL_CRITICAL;
 559   else if (std::strcmp(slevel, "error") == 0)
 560     return LEVEL_ERROR;
 561   return LEVEL_NONE;
 562 }
 563
 564 Log::Level Log::getLogLevel(Type type)
 565 {
 566   switch (type) {
 567   case TYPE_CIM:
 568     return log_level_cim_;
 569   case TYPE_GLIB:
 570     return log_level_glib_;
 571   case TYPE_PURPLE:
 572     return log_level_purple_;
 573   default:
 574     g_assert_not_reached();
 575   }
 576 }
 577
 578 // vim: set tabstop=2 shiftwidth=2 textwidth=80 expandtab: