LogOutputStream.cpp
Go to the documentation of this file.
00001 // this is for emacs file handling -*- mode: c++; indent-tabs-mode: nil -*-
00002 
00003 // -- BEGIN LICENSE BLOCK ----------------------------------------------
00004 // This file is part of FZIs ic_workspace.
00005 //
00006 // This program is free software licensed under the LGPL
00007 // (GNU LESSER GENERAL PUBLIC LICENSE Version 3).
00008 // You can find a copy of this license in LICENSE folder in the top
00009 // directory of the source code.
00010 //
00011 // © Copyright 2016 FZI Forschungszentrum Informatik, Karlsruhe, Germany
00012 //
00013 // -- END LICENSE BLOCK ------------------------------------------------
00014 
00015 //----------------------------------------------------------------------
00023 //----------------------------------------------------------------------
00024 #include "LogOutputStream.h"
00025 
00026 #include <assert.h>
00027 #include <cctype>
00028 #include <cstring>
00029 #include <iostream>
00030 
00031 #include <icl_core/internal_raw_debug.h>
00032 #include <icl_core/os.h>
00033 #include <icl_core/os_lxrt.h>
00034 #include <icl_core/os_string.h>
00035 #include <icl_core_config/Config.h>
00036 
00037 #include "LoggingManager.h"
00038 #include "ThreadStream.h"
00039 
00040 namespace icl_core {
00041 namespace logging {
00042 
00043 const icl_core::String LogOutputStream::m_default_log_format = "<~T.~3M> ~S(~L)~ C~(O~::D: ~E";
00044 const icl_core::ThreadPriority LogOutputStream::m_default_worker_thread_priority = 5;
00045 
00046 LogOutputStream::LogOutputStream(const icl_core::String& name,
00047                                  const icl_core::String& config_prefix,
00048                                  icl_core::logging::LogLevel log_level,
00049                                  bool use_worker_thread)
00050   : m_name(name),
00051     m_log_level(log_level),
00052     m_time_format("%Y-%m-%d %H:%M:%S"),
00053     m_use_worker_thread(use_worker_thread),
00054     m_no_worker_thread_push_mutex(1),
00055     m_format_mutex(1)
00056 {
00057   LoggingManager::instance().assertInitialized();
00058 
00059   icl_core::String log_format = m_default_log_format;
00060   icl_core::config::get<icl_core::String>(config_prefix + "/Format", log_format);
00061   changeLogFormat(log_format.c_str());
00062 
00063   if (m_use_worker_thread)
00064   {
00065     icl_core::ThreadPriority priority = m_default_worker_thread_priority;
00066     icl_core::config::get<icl_core::ThreadPriority>(config_prefix + "/ThreadPriority", priority);
00067 
00068 #ifdef ICL_CORE_LOG_OUTPUT_STREAM_USE_FIXED_QUEUE
00069     size_t message_queue_size = cDEFAULT_FIXED_OUTPUT_STREAM_QUEUE_SIZE;
00070     icl_core::config::get<size_t>(config_prefix + "/MesageQueueSize", message_queue_size);
00071 
00072     m_worker_thread = new WorkerThread(this, message_queue_size, priority);
00073 #else
00074     m_worker_thread = new WorkerThread(this, priority);
00075 #endif
00076   }
00077   else
00078   {
00079     m_worker_thread = NULL;
00080   }
00081 }
00082 
00083 LogOutputStream::LogOutputStream(const icl_core::String& name,
00084                                  icl_core::logging::LogLevel log_level,
00085                                  bool use_worker_thread)
00086   : m_name(name),
00087     m_log_level(log_level),
00088     m_time_format("%Y-%m-%d %H:%M:%S"),
00089     m_use_worker_thread(use_worker_thread),
00090     m_no_worker_thread_push_mutex(1),
00091     m_format_mutex(1)
00092 {
00093   LoggingManager::instance().assertInitialized();
00094   changeLogFormat(m_default_log_format.c_str());
00095   if (m_use_worker_thread)
00096   {
00097 #ifdef ICL_CORE_LOG_OUTPUT_STREAM_USE_FIXED_QUEUE
00098     m_worker_thread = new WorkerThread(this, cDEFAULT_FIXED_OUTPUT_STREAM_QUEUE_SIZE,
00099                                        m_default_worker_thread_priority);
00100 #else
00101     m_worker_thread = new WorkerThread(this, m_default_worker_thread_priority);
00102 #endif
00103   }
00104   else
00105   {
00106     m_worker_thread = NULL;
00107   }
00108 }
00109 
00110 LogOutputStream::~LogOutputStream()
00111 {
00112   if (m_use_worker_thread)
00113   {
00114     if (m_worker_thread->running())
00115     {
00116       std::cerr << "WARNING: Destroyed LogOutputStream while thread is still alive. "
00117                 << "Please call Shutdown() before destruction." << std::endl;
00118     }
00119 
00120     delete m_worker_thread;
00121     m_worker_thread = NULL;
00122   }
00123 }
00124 
00125 void LogOutputStream::changeLogFormat(const char *format)
00126 {
00127   // Stop processing at the end of the format string.
00128   if (format[0] != 0)
00129   {
00130     parseLogFormat(format);
00131 
00132     if (m_format_mutex.wait())
00133     {
00134       m_log_format.clear();
00135       m_log_format = m_new_log_format;
00136       m_new_log_format.clear();
00137 
00138       m_format_mutex.post();
00139     }
00140   }
00141 }
00142 
00143 void LogOutputStream::push(icl_core::logging::LogLevel log_level,
00144                            const char* log_stream_description, const char *filename,
00145                            int line, const char *classname, const char *objectname,
00146                            const char *function, const char *text)
00147 {
00148   if (log_level >= getLogLevel())
00149   {
00150     LogMessage new_entry(icl_core::TimeStamp::now(), log_level, log_stream_description,
00151                          filename, line, classname, objectname, function, text);
00152 
00153     if (m_use_worker_thread)
00154     {
00155       // Hand the log text over to the output implementation.
00156       if (m_worker_thread->m_mutex->wait())
00157       {
00158 #ifdef ICL_CORE_LOG_OUTPUT_STREAM_USE_FIXED_QUEUE
00159         if (!m_worker_thread->isMessageQueueFull())
00160         {
00161           m_worker_thread->m_message_queue[m_worker_thread->m_message_queue_write_index] = new_entry;
00162           m_worker_thread->incrementIndex(m_worker_thread->m_message_queue_write_index);
00163         }
00164 #else
00165         m_worker_thread->m_message_queue.push(new_entry);
00166 #endif
00167         m_worker_thread->m_mutex->post();
00168         m_worker_thread->m_fill_count->post();
00169       }
00170     }
00171     else
00172     {
00173       if (m_no_worker_thread_push_mutex.wait())
00174       {
00175         pushImpl(new_entry);
00176         m_no_worker_thread_push_mutex.post();
00177       }
00178     }
00179   }
00180 }
00181 
00182 void LogOutputStream::pushImpl(const LogMessage& log_message)
00183 {
00184   if (m_format_mutex.wait())
00185   {
00186     std::stringstream msg;
00187     for (icl_core::List<LogFormatEntry>::const_iterator it = m_log_format.begin();
00188          it != m_log_format.end(); ++it)
00189     {
00190       switch (it->type)
00191       {
00192       case LogFormatEntry::eT_TEXT:
00193       {
00194         msg << it->text;
00195         break;
00196       }
00197       case LogFormatEntry::eT_CLASSNAME:
00198       {
00199         if (std::strcmp(log_message.class_name, "") != 0)
00200         {
00201           msg << it->text << log_message.class_name;
00202         }
00203         break;
00204       }
00205       case LogFormatEntry::eT_OBJECTNAME:
00206       {
00207         if (std::strcmp(log_message.object_name, "") != 0)
00208         {
00209           msg << it->text << log_message.object_name << it->suffix;
00210         }
00211         break;
00212       }
00213       case LogFormatEntry::eT_FUNCTION:
00214       {
00215         if (std::strcmp(log_message.function_name, "") != 0)
00216         {
00217           msg << it->text << log_message.function_name;
00218         }
00219         break;
00220       }
00221       case LogFormatEntry::eT_MESSAGE:
00222       {
00223         msg << log_message.message_text;
00224         break;
00225       }
00226       case LogFormatEntry::eT_FILENAME:
00227       {
00228         msg << log_message.filename;
00229         break;
00230       }
00231       case LogFormatEntry::eT_LINE:
00232       {
00233         msg << log_message.line;
00234         break;
00235       }
00236       case LogFormatEntry::eT_LEVEL:
00237       {
00238         msg << logLevelDescription(log_message.log_level);
00239         break;
00240       }
00241       case LogFormatEntry::eT_STREAM:
00242       {
00243         msg << log_message.log_stream;
00244         break;
00245       }
00246       case LogFormatEntry::eT_TIMESTAMP:
00247       {
00248         char time_buffer[100];
00249         memset(time_buffer, 0, 100);
00250 
00251 #ifdef _SYSTEM_LXRT_
00252         // Don't use strfLocaltime() in a hard realtime LXRT task, because
00253         // it might use a POSIX mutex!
00254         if (icl_core::os::isThisLxrtTask() && icl_core::os::isThisHRT())
00255         {
00256           icl_core::os::snprintf(time_buffer, 99, "%d %02d:%02d:%02d(HRT)",
00257                                  int(log_message.timestamp.days()),
00258                                  int(log_message.timestamp.hours()),
00259                                  int(log_message.timestamp.minutes()),
00260                                  int(log_message.timestamp.seconds()));
00261         }
00262         else
00263 #endif
00264         {
00265           log_message.timestamp.strfLocaltime(time_buffer, 100, m_time_format);
00266         }
00267 
00268         msg << time_buffer;
00269         break;
00270       }
00271       case LogFormatEntry::eT_TIMESTAMP_MS:
00272       {
00273         int32_t msec = log_message.timestamp.tsNSec() / 1000000;
00274         size_t msec_len = 1;
00275         if (msec >= 10)
00276         {
00277           msec_len = 2;
00278         }
00279         if (msec >= 100)
00280         {
00281           msec_len = 3;
00282         }
00283         for (size_t i = it->width; i > msec_len; --i)
00284         {
00285           msg << "0";
00286         }
00287         msg << msec;
00288         break;
00289       }
00290       }
00291     }
00292     m_format_mutex.post();
00293 
00294     pushImpl(msg.str());
00295   }
00296 }
00297 
00298 void LogOutputStream::pushImpl(const icl_core::String&)
00299 {
00300   std::cerr << "LOG OUTPUT STREAM ERROR: pushImpl() is not implemented!!!" << std::endl;
00301 }
00302 
00303 void LogOutputStream::printConfiguration() const
00304 {
00305   std::cerr << "    " << name() << " : " << logLevelDescription(m_log_level) << std::endl;
00306 }
00307 
00308 
00310 #ifdef _IC_BUILDER_DEPRECATED_STYLE_
00311 
00315 void LogOutputStream::ChangeTimeFormat(const char* format)
00316 {
00317   changeTimeFormat(format);
00318 }
00319 
00323 void LogOutputStream::ChangeLogFormat(const char *format)
00324 {
00325   changeLogFormat(format);
00326 }
00327 
00331 void LogOutputStream::Push(icl_core::logging::LogLevel log_level,
00332                            const char *log_stream_description, const char *filename,
00333                            int line, const char *classname, const char *objectname,
00334                            const char *function, const char *text)
00335 {
00336   push(log_level, log_stream_description, filename, line, classname, objectname, function, text);
00337 }
00338 
00342 void LogOutputStream::Start()
00343 {
00344   start();
00345 }
00346 
00351 void LogOutputStream::Shutdown()
00352 {
00353   shutdown();
00354 }
00355 
00359 ICL_CORE_VC_DEPRECATE_STYLE_USE(LogOutputStream::getLogLevel)
00360 icl_core::logging::LogLevel LogOutputStream::LogLevel() const
00361 {
00362   return getLogLevel();
00363 }
00364 
00368 void LogOutputStream::SetLogLevel(icl_core::logging::LogLevel log_level)
00369 {
00370   setLogLevel(log_level);
00371 }
00372 
00376 icl_core::String LogOutputStream::Name() const
00377 {
00378   return name();
00379 }
00380 
00385 void LogOutputStream::PrintConfiguration() const
00386 {
00387   printConfiguration();
00388 }
00389 
00390 #endif
00391 
00392 
00393 void LogOutputStream::parseLogFormat(const char *format)
00394 {
00395   LogFormatEntry new_entry;
00396 
00397   // The format string starts with a field specifier.
00398   if (format[0] == '~')
00399   {
00400     ++format;
00401 
00402     // Read the field width.
00403     while (format[0] != 0 && std::isdigit(format[0]))
00404     {
00405       new_entry.width = 10 * new_entry.width + (format[0] - '0');
00406       ++format;
00407     }
00408 
00409     // Read optional prefix text.
00410     char *prefix_ptr = new_entry.text;
00411     while (format[0] != 0 && format[0] != 'C' && format[0] != 'O' && format[0] != 'D'
00412            && format[0] != 'E' && format[0] != 'F' && format[0] != 'G' && format[0] != 'L'
00413            && format[0] != 'S' && format[0] != 'T' && format[0] != 'M')
00414     {
00415       *prefix_ptr = format[0];
00416       ++prefix_ptr;
00417       ++format;
00418     }
00419 
00420     // Read the field type.
00421     if (format[0] == 'C')
00422     {
00423       new_entry.type = LogFormatEntry::eT_CLASSNAME;
00424     }
00425     else if (format[0] == 'O')
00426     {
00427       new_entry.type = LogFormatEntry::eT_OBJECTNAME;
00428       if (new_entry.text[0] == '(')
00429       {
00430         std::strncpy(new_entry.suffix, ")", 100);
00431       }
00432       else if (new_entry.text[0] == '[')
00433       {
00434         std::strncpy(new_entry.suffix, "]", 100);
00435       }
00436       else if (new_entry.text[0] == '{')
00437       {
00438         std::strncpy(new_entry.suffix, "}", 100);
00439       }
00440     }
00441     else if (format[0] == 'D')
00442     {
00443       new_entry.type = LogFormatEntry::eT_FUNCTION;
00444     }
00445     else if (format[0] == 'E')
00446     {
00447       new_entry.type = LogFormatEntry::eT_MESSAGE;
00448     }
00449     else if (format[0] == 'F')
00450     {
00451       new_entry.type = LogFormatEntry::eT_FILENAME;
00452     }
00453     else if (format[0] == 'G')
00454     {
00455       new_entry.type = LogFormatEntry::eT_LINE;
00456     }
00457     else if (format[0] == 'L')
00458     {
00459       new_entry.type = LogFormatEntry::eT_LEVEL;
00460     }
00461     else if (format[0] == 'S')
00462     {
00463       new_entry.type = LogFormatEntry::eT_STREAM;
00464     }
00465     else if (format[0] == 'T')
00466     {
00467       new_entry.type = LogFormatEntry::eT_TIMESTAMP;
00468     }
00469     else if (format[0] == 'M')
00470     {
00471       new_entry.type = LogFormatEntry::eT_TIMESTAMP_MS;
00472     }
00473 
00474     if (format[0] != 0)
00475     {
00476       m_new_log_format.push_back(new_entry);
00477     }
00478 
00479     ++format;
00480   }
00481   else
00482   {
00483     char *text_ptr = new_entry.text;
00484     while (format[0] != '~' && format[0] != 0)
00485     {
00486       *text_ptr = format[0];
00487       ++text_ptr;
00488       ++format;
00489     }
00490 
00491     if (new_entry.text[0] != 0)
00492     {
00493       m_new_log_format.push_back(new_entry);
00494     }
00495   }
00496 
00497   // Stop processing at the end of the format string.
00498   if (format[0] == 0)
00499   {
00500     return;
00501   }
00502   else
00503   {
00504     parseLogFormat(format);
00505   }
00506 }
00507 
00508 void LogOutputStream::start()
00509 {
00510   if (m_use_worker_thread)
00511   {
00512     m_worker_thread->start();
00513   }
00514 }
00515 
00516 void LogOutputStream::shutdown()
00517 {
00518   if (m_use_worker_thread)
00519   {
00520     if (m_worker_thread->running())
00521     {
00522       m_worker_thread->stop();
00523       m_worker_thread->m_fill_count->post();
00524       m_worker_thread->join();
00525     }
00526   }
00527 }
00528 
00529 #ifdef ICL_CORE_LOG_OUTPUT_STREAM_USE_FIXED_QUEUE
00530 LogOutputStream::WorkerThread::WorkerThread(LogOutputStream *output_stream, size_t message_queue_size,
00531                                             icl_core::ThreadPriority priority)
00532   : Thread(priority),
00533     m_output_stream(output_stream),
00534     m_message_queue_size(message_queue_size),
00535     m_message_queue_write_index(0),
00536     m_message_queue_read_index(0)
00537 {
00538   m_message_queue = new LogMessage[message_queue_size+1];
00539 
00540   m_mutex = new Semaphore(1);
00541   m_fill_count = new Semaphore(0);
00542 }
00543 #else
00544 LogOutputStream::WorkerThread::WorkerThread(LogOutputStream *output_stream, icl_core::ThreadPriority priority)
00545   : Thread(priority),
00546     m_output_stream(output_stream)
00547 {
00548   m_mutex = new Semaphore(1);
00549   m_fill_count = new Semaphore(0);
00550 }
00551 #endif
00552 
00553 LogOutputStream::WorkerThread::~WorkerThread()
00554 {
00555   delete m_mutex;
00556   delete m_fill_count;
00557 #ifdef ICL_CORE_LOG_OUTPUT_STREAM_USE_FIXED_QUEUE
00558   delete[] m_message_queue;
00559 #endif
00560 }
00561 
00562 void LogOutputStream::WorkerThread::run()
00563 {
00564   m_output_stream->onStart();
00565 
00566   // Wait for new messages to arrive.
00567   while (execute())
00568   {
00569     if (m_fill_count->wait())
00570     {
00571 #ifdef ICL_CORE_LOG_OUTPUT_STREAM_USE_FIXED_QUEUE
00572       if (!isMessageQueueEmpty())
00573 #else
00574       if (!m_message_queue.empty())
00575 #endif
00576       {
00577         if (m_mutex->wait())
00578         {
00579           LogMessage log_message;
00580           bool push = false;
00581 #ifdef ICL_CORE_LOG_OUTPUT_STREAM_USE_FIXED_QUEUE
00582           if (!isMessageQueueEmpty())
00583           {
00584             log_message = m_message_queue[m_message_queue_read_index];
00585             incrementIndex(m_message_queue_read_index);
00586             push = true;
00587           }
00588 #else
00589           if (!m_message_queue.empty())
00590           {
00591             log_message = m_message_queue.front();
00592             m_message_queue.pop();
00593             push = true;
00594           }
00595 #endif
00596 
00597           m_mutex->post();
00598 
00599           if (push)
00600           {
00601             m_output_stream->pushImpl(log_message);
00602           }
00603         }
00604       }
00605     }
00606     else if (execute())
00607     {
00608       PRINTF("LogOutputStream(%s)::run: semaphore wait failed\n", m_output_stream->m_name.c_str());
00609       icl_core::os::usleep(10000);
00610     }
00611   }
00612 
00613   // Write out all remaining log messages.
00614   if (m_mutex->wait())
00615   {
00616 #ifdef ICL_CORE_LOG_OUTPUT_STREAM_USE_FIXED_QUEUE
00617     while (!isMessageQueueEmpty())
00618     {
00619       LogMessage log_message = m_message_queue[m_message_queue_read_index];
00620       incrementIndex(m_message_queue_read_index);
00621       m_output_stream->pushImpl(log_message);
00622     }
00623 #else
00624     while (!m_message_queue.empty())
00625     {
00626       LogMessage log_message = m_message_queue.front();
00627       m_message_queue.pop();
00628       m_output_stream->pushImpl(log_message);
00629     }
00630 #endif
00631 
00632     m_mutex->post();
00633   }
00634 
00635   m_output_stream->onShutdown();
00636 }
00637 
00638 
00639 #ifdef ICL_CORE_LOG_OUTPUT_STREAM_USE_FIXED_QUEUE
00640 void LogOutputStream::WorkerThread::incrementIndex(size_t& index)
00641 {
00642   ++index;
00643   if (index >= m_message_queue_size)
00644   {
00645     index = 0;
00646   }
00647 }
00648 
00649 bool LogOutputStream::WorkerThread::isMessageQueueEmpty()
00650 {
00651   return m_message_queue_read_index == m_message_queue_write_index;
00652 }
00653 
00654 bool LogOutputStream::WorkerThread::isMessageQueueFull()
00655 {
00656   return ((m_message_queue_write_index == m_message_queue_read_index - 1)
00657           || (m_message_queue_write_index == m_message_queue_size - 1
00658               && m_message_queue_read_index == 0));
00659 }
00660 #endif
00661 
00662 LogOutputStream::LogMessage::LogMessage(const icl_core::TimeStamp& timestamp,
00663                                         icl_core::logging::LogLevel log_level,
00664                                         const char *log_stream, const char *filename,
00665                                         size_t line, const char *class_name,
00666                                         const char *object_name, const char *function_name,
00667                                         const char *message_text)
00668   : timestamp(timestamp),
00669     log_level(log_level),
00670     line(line)
00671 {
00672   std::strncpy(LogMessage::log_stream, log_stream, cMAX_IDENTIFIER_LENGTH+1);
00673   std::strncpy(LogMessage::filename, filename, cMAX_DESCRIPTION_LENGTH+1);
00674   std::strncpy(LogMessage::class_name, class_name, cMAX_IDENTIFIER_LENGTH+1);
00675   std::strncpy(LogMessage::object_name, object_name, cMAX_DESCRIPTION_LENGTH+1);
00676   std::strncpy(LogMessage::function_name, function_name, cMAX_IDENTIFIER_LENGTH+1);
00677   std::strncpy(LogMessage::message_text, message_text, cDEFAULT_LOG_SIZE+1);
00678 }
00679 
00680 }
00681 }


fzi_icl_core
Author(s):
autogenerated on Thu Jun 6 2019 20:22:24