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     char *text;                                                                \
  73                                                                                \
  74     if (log_level_cim_ < level)                                                \
  75       return; /* Do not show this message. */                                  \
  76                                                                                \
  77     va_start(args, fmt);                                                       \
  78     text = g_strdup_vprintf(fmt, args);                                        \
  79     va_end(args);                                                              \
  80                                                                                \
  81     write(TYPE_CIM, level, text);                                              \
  82     g_free(text);                                                              \
  83   }
  84
  85 WRITE_METHOD(error, LEVEL_ERROR)
  86 WRITE_METHOD(critical, LEVEL_CRITICAL)
  87 WRITE_METHOD(warning, LEVEL_WARNING)
  88 WRITE_METHOD(message, LEVEL_MESSAGE)
  89 WRITE_METHOD(info, LEVEL_INFO)
  90 WRITE_METHOD(debug, LEVEL_DEBUG)
  91
  92 #undef WRITE_METHOD
  93
  94 void Log::clearAllBufferedMessages()
  95 {
  96   // Delete all buffered messages.
  97   clearBufferedMessages(init_log_items_);
  98   clearBufferedMessages(log_items_);
  99 }
 100
 101 Log::LogWindow::LogWindow() : Window(0, 0, 80, 24, nullptr, TYPE_NON_FOCUSABLE)
 102 {
 103   setColorScheme(CenterIM::SCHEME_LOG);
 104
 105   auto lbox = new CppConsUI::HorizontalListBox(AUTOSIZE, AUTOSIZE);
 106   addWidget(*lbox, 1, 1);
 107
 108   lbox->appendWidget(*(new CppConsUI::Spacer(1, AUTOSIZE)));
 109   textview_ = new CppConsUI::TextView(AUTOSIZE, AUTOSIZE, true);
 110   lbox->appendWidget(*textview_);
 111   lbox->appendWidget(*(new CppConsUI::Spacer(1, AUTOSIZE)));
 112
 113   onScreenResized();
 114 }
 115
 116 void Log::LogWindow::onScreenResized()
 117 {
 118   moveResizeRect(CENTERIM->getScreenArea(CenterIM::LOG_AREA));
 119 }
 120
 121 void Log::LogWindow::append(const char *text)
 122 {
 123   textview_->append(text);
 124
 125   // Shorten the window text.
 126   std::size_t lines_num = textview_->getLinesNumber();
 127
 128   if (lines_num > LOG_WINDOW_MAX_LINES) {
 129     // Remove some lines.
 130     textview_->erase(
 131       0, lines_num - LOG_WINDOW_MAX_LINES + LOG_WINDOW_DELETE_COUNT);
 132   }
 133 }
 134
 135 Log::LogBufferItem::LogBufferItem(Type type, Level level, const char *text)
 136   : type_(type), level_(level)
 137 {
 138   text_ = g_strdup(text);
 139 }
 140
 141 Log::LogBufferItem::~LogBufferItem()
 142 {
 143   g_free(text_);
 144 }
 145
 146 Log::Log()
 147   : phase_(PHASE_INITIALIZATION), log_window_(nullptr), logfile_(nullptr),
 148     log_level_cim_(LEVEL_DEBUG), log_level_glib_(LEVEL_DEBUG),
 149     log_level_purple_(LEVEL_DEBUG)
 150 {
 151 #define REGISTER_G_LOG_HANDLER(name, handler)                                  \
 152   g_log_set_handler((name), (GLogLevelFlags)G_LOG_LEVEL_MASK, (handler), this)
 153
 154   // Register the glib log handlers.
 155   default_handler_ = REGISTER_G_LOG_HANDLER(nullptr, default_log_handler_);
 156   glib_handler_ = REGISTER_G_LOG_HANDLER("GLib", glib_log_handler_);
 157   gmodule_handler_ = REGISTER_G_LOG_HANDLER("GModule", glib_log_handler_);
 158   glib_gobject_handler_ =
 159     REGISTER_G_LOG_HANDLER("GLib-GObject", glib_log_handler_);
 160   gthread_handler_ = REGISTER_G_LOG_HANDLER("GThread", glib_log_handler_);
 161 }
 162
 163 Log::~Log()
 164 {
 165   g_log_remove_handler(nullptr, default_handler_);
 166   g_log_remove_handler("GLib", glib_handler_);
 167   g_log_remove_handler("GModule", gmodule_handler_);
 168   g_log_remove_handler("GLib-GObject", glib_gobject_handler_);
 169   g_log_remove_handler("GThread", gthread_handler_);
 170
 171   outputAllBufferedMessages();
 172   clearAllBufferedMessages();
 173 }
 174
 175 void Log::init()
 176 {
 177   g_assert(my_instance_ == nullptr);
 178
 179   my_instance_ = new Log;
 180 }
 181
 182 void Log::finalize()
 183 {
 184   g_assert(my_instance_ != nullptr);
 185
 186   delete my_instance_;
 187   my_instance_ = nullptr;
 188 }
 189
 190 void Log::initNormalPhase()
 191 {
 192   // Normal phase is called after CppConsUI and libpurple has been initialized.
 193   // Logging to file is part of the normal phase.
 194   g_assert(phase_ == PHASE_INITIALIZATION);
 195
 196   // Init preferences.
 197   purple_prefs_add_none(CONF_PREFIX "/log");
 198   purple_prefs_add_bool(CONF_PREFIX "/log/debug", false);
 199   purple_prefs_add_string(CONF_PREFIX "/log/filename", "debug.log");
 200   purple_prefs_add_string(CONF_PREFIX "/log/log_level_cim", "info");
 201   purple_prefs_add_string(CONF_PREFIX "/log/log_level_purple", "critical");
 202   purple_prefs_add_string(CONF_PREFIX "/log/log_level_glib", "warning");
 203
 204   updateCachedPreference(CONF_PREFIX "/log/debug");
 205   updateCachedPreference(CONF_PREFIX "/log/log_level_cim");
 206   updateCachedPreference(CONF_PREFIX "/log/log_level_purple");
 207   updateCachedPreference(CONF_PREFIX "/log/log_level_glib");
 208
 209   // Connect callbacks.
 210   purple_prefs_connect_callback(
 211     this, CONF_PREFIX "/log", log_pref_change_, this);
 212
 213   // Create the log window.
 214   g_assert(log_window_ == nullptr);
 215   log_window_ = new LogWindow;
 216   log_window_->show();
 217
 218   // Normal phase is now active.
 219   phase_ = PHASE_NORMAL;
 220
 221   // Output buffered messages from the initialization phase.
 222   for (LogBufferItem *item : init_log_items_) {
 223     // Determine if this message should be displayed.
 224     Level loglevel = getLogLevel(item->getType());
 225
 226     if (loglevel >= item->getLevel())
 227       write(item->getType(), item->getLevel(), item->getText(), false);
 228
 229     delete item;
 230   }
 231   init_log_items_.clear();
 232 }
 233
 234 void Log::finalizeNormalPhase()
 235 {
 236   // Normal phase finalization is done before CppConsUI and libpurple is
 237   // finalized. Note that log levels are unchanged after the normal phase
 238   // finishes.
 239   g_assert(phase_ == PHASE_NORMAL);
 240
 241   // Delete the log window.
 242   g_assert(log_window_ != nullptr);
 243   delete log_window_;
 244   log_window_ = nullptr;
 245
 246   purple_prefs_disconnect_by_handle(this);
 247
 248   // Close the log file (if it is opened).
 249   if (logfile_ != nullptr)
 250     g_io_channel_unref(logfile_);
 251
 252   // Done with the normal phase.
 253   phase_ = PHASE_FINALIZATION;
 254 }
 255
 256 void Log::purple_print(
 257   PurpleDebugLevel purplelevel, const char *category, const char *arg_s)
 258 {
 259   Level level = convertPurpleDebugLevel(purplelevel);
 260   if (log_level_purple_ < level)
 261     return; // Do not show this message.
 262
 263   if (category == nullptr) {
 264     category = "misc";
 265     warning(_("centerim/log: purple_print() parameter category was "
 266               "not defined."));
 267   }
 268
 269   char *text = g_strdup_printf("libpurple/%s: %s", category, arg_s);
 270   write(TYPE_PURPLE, level, text);
 271   g_free(text);
 272 }
 273
 274 gboolean Log::purple_is_enabled(
 275   PurpleDebugLevel purplelevel, const char * /*category*/)
 276 {
 277   Level level = convertPurpleDebugLevel(purplelevel);
 278
 279   if (log_level_purple_ < level)
 280     return FALSE;
 281
 282   return TRUE;
 283 }
 284
 285 void Log::default_log_handler(
 286   const char *domain, GLogLevelFlags flags, const char *msg)
 287 {
 288   if (msg == nullptr)
 289     return;
 290
 291   Level level = convertGLibDebugLevel(flags);
 292   if (log_level_glib_ < level)
 293     return; // Do not show this message.
 294
 295   char *text = g_strdup_printf("%s: %s", domain ? domain : "g_log", msg);
 296   write(TYPE_GLIB, level, text);
 297   g_free(text);
 298 }
 299
 300 void Log::glib_log_handler(
 301   const char *domain, GLogLevelFlags flags, const char *msg)
 302 {
 303   if (msg == nullptr)
 304     return;
 305
 306   Level level = convertGLibDebugLevel(flags);
 307   if (log_level_glib_ < level)
 308     return; // Do not show this message.
 309
 310   char *text = g_strdup_printf("%s: %s", domain ? domain : "g_log", msg);
 311   write(TYPE_GLIB, level, text);
 312   g_free(text);
 313 }
 314
 315 void Log::log_pref_change(
 316   const char *name, PurplePrefType /*type*/, gconstpointer /*val*/)
 317 {
 318   // log/* preference changed.
 319   updateCachedPreference(name);
 320 }
 321
 322 void Log::updateCachedPreference(const char *name)
 323 {
 324   if (std::strcmp(name, CONF_PREFIX "/log/debug") == 0) {
 325     bool logfile_enabled = purple_prefs_get_bool(name);
 326
 327     if (logfile_enabled && logfile_ == nullptr) {
 328       char *filename = g_build_filename(purple_user_dir(),
 329         purple_prefs_get_string(CONF_PREFIX "/log/filename"), nullptr);
 330       GError *err = nullptr;
 331
 332       logfile_ = g_io_channel_new_file(filename, "a", &err);
 333       if (logfile_ == nullptr) {
 334         error(_("centerim/log: Error opening logfile '%s' (%s)."), filename,
 335           err->message);
 336         g_clear_error(&err);
 337       }
 338       g_free(filename);
 339     }
 340     else if (!logfile_enabled && logfile_ != nullptr) {
 341       // Debug was disabled so close logfile if it is opened.
 342       g_io_channel_unref(logfile_);
 343       logfile_ = nullptr;
 344     }
 345   }
 346   else if (std::strcmp(name, CONF_PREFIX "/log/log_level_cim") == 0)
 347     log_level_cim_ = stringToLevel(purple_prefs_get_string(name));
 348   else if (std::strcmp(name, CONF_PREFIX "/log/log_level_purple") == 0)
 349     log_level_purple_ = stringToLevel(purple_prefs_get_string(name));
 350   else if (std::strcmp(name, CONF_PREFIX "/log/log_level_glib") == 0)
 351     log_level_glib_ = stringToLevel(purple_prefs_get_string(name));
 352 }
 353
 354 void Log::write(Type type, Level level, const char *text, bool buffer)
 355 {
 356   if (buffer)
 357     bufferMessage(type, level, text);
 358
 359   // If the normal phase is not active then only buffer the message.
 360   if (phase_ != PHASE_NORMAL)
 361     return;
 362
 363   g_assert(log_window_ != nullptr);
 364   log_window_->append(text);
 365   writeToFile(text);
 366 }
 367
 368 void Log::writeErrorToWindow(const char *fmt, ...)
 369 {
 370   // Can be called only if the normal phase is active.
 371   g_assert(phase_ == PHASE_NORMAL);
 372   g_assert(log_window_ != nullptr);
 373
 374   va_list args;
 375
 376   if (log_level_cim_ < LEVEL_ERROR)
 377     return; // Do not show this message.
 378
 379   va_start(args, fmt);
 380   char *text = g_strdup_vprintf(fmt, args);
 381   va_end(args);
 382
 383   log_window_->append(text);
 384   g_free(text);
 385 }
 386
 387 void Log::writeToFile(const char *text)
 388 {
 389   // Writing to a file is possible only in the normal phase.
 390   g_assert(phase_ == PHASE_NORMAL);
 391
 392   if (text == nullptr || logfile_ == nullptr)
 393     return;
 394
 395   // Write text into logfile.
 396   GError *err = nullptr;
 397
 398   if (g_io_channel_write_chars(logfile_, text, -1, nullptr, &err) !=
 399     G_IO_STATUS_NORMAL) {
 400     writeErrorToWindow(
 401       _("centerim/log: Error writing to logfile (%s)."), err->message);
 402     g_clear_error(&err);
 403   }
 404   else {
 405     // If necessary write missing EOL character.
 406     std::size_t len = std::strlen(text);
 407     if (len > 0 && text[len - 1] != '\n') {
 408       // Ignore all errors.
 409       g_io_channel_write_chars(logfile_, "\n", -1, nullptr, nullptr);
 410     }
 411   }
 412
 413   if (g_io_channel_flush(logfile_, &err) != G_IO_STATUS_NORMAL) {
 414     writeErrorToWindow(
 415       _("centerim/log: Error flushing logfile (%s)."), err->message);
 416     g_clear_error(&err);
 417   }
 418 }
 419
 420 void Log::bufferMessage(Type type, Level level, const char *text)
 421 {
 422   auto item = new LogBufferItem(type, level, text);
 423   if (phase_ == PHASE_INITIALIZATION)
 424     init_log_items_.push_back(item);
 425   else
 426     log_items_.push_back(item);
 427
 428   if (phase_ != PHASE_NORMAL)
 429     return;
 430
 431   // Reduce a number of buffered messages if the normal phase is active.
 432   std::size_t size = log_items_.size();
 433   if (size <= LOG_MAX_BUFFERED_MESSAGES)
 434     return;
 435
 436   // There can never be more than one message to remove.
 437   g_assert(size == LOG_MAX_BUFFERED_MESSAGES + 1);
 438   delete log_items_.front();
 439   log_items_.pop_front();
 440 }
 441
 442 void Log::clearBufferedMessages(LogBufferItems &items)
 443 {
 444   for (LogBufferItem *item : items)
 445     delete item;
 446   items.clear();
 447 }
 448
 449 void Log::outputBufferedMessages(LogBufferItems &items)
 450 {
 451   for (LogBufferItem *item : items) {
 452     // Determine if this message should be displayed.
 453     Level loglevel = getLogLevel(item->getType());
 454
 455     if (loglevel >= item->getLevel()) {
 456       const char *text = item->getText();
 457       g_assert(text != nullptr);
 458
 459       std::fprintf(stderr, "%s", text);
 460
 461       // If necessary write missing EOL character.
 462       std::size_t len = std::strlen(text);
 463       if (len > 0 && text[len - 1] != '\n')
 464         std::fprintf(stderr, "\n");
 465     }
 466   }
 467 }
 468
 469 void Log::outputAllBufferedMessages()
 470 {
 471   // Output all buffered messages on stderr.
 472   outputBufferedMessages(init_log_items_);
 473   outputBufferedMessages(log_items_);
 474
 475   std::fflush(stderr);
 476 }
 477
 478 Log::Level Log::convertPurpleDebugLevel(PurpleDebugLevel purplelevel)
 479 {
 480   switch (purplelevel) {
 481   case PURPLE_DEBUG_MISC:
 482     return LEVEL_DEBUG;
 483   case PURPLE_DEBUG_INFO:
 484     return LEVEL_INFO;
 485   case PURPLE_DEBUG_WARNING:
 486     return LEVEL_WARNING;
 487   case PURPLE_DEBUG_ERROR:
 488     return LEVEL_CRITICAL;
 489   case PURPLE_DEBUG_FATAL:
 490     return LEVEL_ERROR;
 491   case PURPLE_DEBUG_ALL:
 492     return LEVEL_ERROR; // Use error level so this message is always printed.
 493   }
 494
 495   warning(
 496     _("centerim/log: Unknown libpurple logging level '%d'."), purplelevel);
 497   return LEVEL_DEBUG;
 498 }
 499
 500 Log::Level Log::convertGLibDebugLevel(GLogLevelFlags gliblevel)
 501 {
 502   if (gliblevel & G_LOG_LEVEL_DEBUG)
 503     return LEVEL_DEBUG;
 504   if (gliblevel & G_LOG_LEVEL_INFO)
 505     return LEVEL_INFO;
 506   if (gliblevel & G_LOG_LEVEL_MESSAGE)
 507     return LEVEL_MESSAGE;
 508   if (gliblevel & G_LOG_LEVEL_WARNING)
 509     return LEVEL_WARNING;
 510   if (gliblevel & G_LOG_LEVEL_CRITICAL)
 511     return LEVEL_CRITICAL;
 512   if (gliblevel & G_LOG_LEVEL_ERROR)
 513     return LEVEL_ERROR;
 514
 515   warning(_("centerim/log: Unknown GLib logging level '%d'."), gliblevel);
 516   return LEVEL_DEBUG;
 517 }
 518
 519 Log::Level Log::stringToLevel(const char *slevel)
 520 {
 521   if (std::strcmp(slevel, "none") == 0)
 522     return LEVEL_NONE;
 523   else if (std::strcmp(slevel, "debug") == 0)
 524     return LEVEL_DEBUG;
 525   else if (std::strcmp(slevel, "info") == 0)
 526     return LEVEL_INFO;
 527   else if (std::strcmp(slevel, "message") == 0)
 528     return LEVEL_MESSAGE;
 529   else if (std::strcmp(slevel, "warning") == 0)
 530     return LEVEL_WARNING;
 531   else if (std::strcmp(slevel, "critical") == 0)
 532     return LEVEL_CRITICAL;
 533   else if (std::strcmp(slevel, "error") == 0)
 534     return LEVEL_ERROR;
 535   return LEVEL_NONE;
 536 }
 537
 538 Log::Level Log::getLogLevel(Type type)
 539 {
 540   switch (type) {
 541   case TYPE_CIM:
 542     return log_level_cim_;
 543   case TYPE_GLIB:
 544     return log_level_glib_;
 545   case TYPE_PURPLE:
 546     return log_level_purple_;
 547   default:
 548     g_assert_not_reached();
 549   }
 550 }
 551
 552 // vim: set tabstop=2 shiftwidth=2 textwidth=80 expandtab: