git.sesse.net Git - casparcg/blob - common/log.cpp

   1 /*
   2 * Copyright (c) 2011 Sveriges Television AB <info@casparcg.com>
   3 *
   4 * This file is part of CasparCG (www.casparcg.com).
   5 *
   6 * CasparCG 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 3 of the License, or
   9 * (at your option) any later version.
  10 *
  11 * CasparCG 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 CasparCG. If not, see <http://www.gnu.org/licenses/>.
  18 *
  19 * Author: Robert Nagy, ronag89@gmail.com
  20 */
  21
  22 #include "stdafx.h"
  23
  24 #include "log.h"
  25
  26 #include "os/threading.h"
  27 #include "except.h"
  28 #include "utf.h"
  29
  30 #include <ios>
  31 #include <iomanip>
  32 #include <mutex>
  33 #include <string>
  34 #include <thread>
  35 #include <ostream>
  36
  37 #include <boost/shared_ptr.hpp>
  38 #include <boost/make_shared.hpp>
  39 #include <boost/filesystem/convenience.hpp>
  40 #include <boost/date_time/posix_time/posix_time.hpp>
  41 #include <boost/algorithm/string.hpp>
  42
  43 #include <boost/log/core.hpp>
  44 #include <boost/log/trivial.hpp>
  45 #include <boost/log/expressions.hpp>
  46
  47 #include <boost/log/sinks/text_file_backend.hpp>
  48 #include <boost/log/sinks/text_ostream_backend.hpp>
  49 #include <boost/log/sinks/sync_frontend.hpp>
  50 #include <boost/log/sinks/async_frontend.hpp>
  51 #include <boost/log/core/record.hpp>
  52 #include <boost/log/attributes/attribute_value.hpp>
  53 #include <boost/log/attributes/function.hpp>
  54 #include <boost/log/utility/setup/common_attributes.hpp>
  55
  56 #include <boost/core/null_deleter.hpp>
  57 #include <boost/lambda/lambda.hpp>
  58 #include <boost/bind.hpp>
  59 #include <boost/lexical_cast.hpp>
  60 #include <boost/property_tree/ptree.hpp>
  61
  62 #include <tbb/atomic.h>
  63
  64 namespace caspar { namespace log {
  65
  66 using namespace boost;
  67
  68 template<typename Stream>
  69 void append_timestamp(Stream& stream, boost::posix_time::ptime timestamp)
  70 {
  71         auto date = timestamp.date();
  72         auto time = timestamp.time_of_day();
  73         auto milliseconds = time.fractional_seconds() / 1000; // microseconds to milliseconds
  74
  75         std::wstringstream buffer;
  76
  77         buffer
  78                 << std::setfill(L'0')
  79                 << L"["
  80                 << std::setw(4) << date.year() << L"-" << std::setw(2) << date.month().as_number() << "-" << std::setw(2) << date.day().as_number()
  81                 << L" "
  82                 << std::setw(2) << time.hours() << L":" << std::setw(2) << time.minutes() << L":" << std::setw(2) << time.seconds()
  83                 << L"."
  84                 << std::setw(3) << milliseconds
  85                 << L"] ";
  86
  87         stream << buffer.str();
  88 }
  89
  90 class column_writer
  91 {
  92         tbb::atomic<int> column_width_;
  93 public:
  94         column_writer(int initial_width = 0)
  95         {
  96                 column_width_ = initial_width;
  97         }
  98
  99         template<typename Stream, typename Val>
 100         void write(Stream& out, const Val& value)
 101         {
 102                 std::wstring to_string = boost::lexical_cast<std::wstring>(value);
 103                 int length = static_cast<int>(to_string.size());
 104                 int read_width;
 105
 106                 while ((read_width = column_width_) < length && column_width_.compare_and_swap(length, read_width) != read_width);
 107                 read_width = column_width_;
 108
 109                 out << L"[" << to_string << L"] ";
 110
 111                 for (int n = 0; n < read_width - length; ++n)
 112                         out << L" ";
 113         }
 114 };
 115
 116 template<typename Stream>
 117 void my_formatter(bool print_all_characters, const boost::log::record_view& rec, Stream& strm)
 118 {
 119         static column_writer thread_id_column;
 120         static column_writer severity_column(7);
 121         namespace expr = boost::log::expressions;
 122
 123         std::wstringstream pre_message_stream;
 124         append_timestamp(pre_message_stream, boost::log::extract<boost::posix_time::ptime>("TimestampMillis", rec).get());
 125         thread_id_column.write(pre_message_stream, boost::log::extract<std::int64_t>("NativeThreadId", rec));
 126         severity_column.write(pre_message_stream, boost::log::extract<boost::log::trivial::severity_level>("Severity", rec));
 127
 128         auto pre_message = pre_message_stream.str();
 129
 130         strm << pre_message;
 131
 132         auto line_break_replacement = L"\n" + pre_message;
 133
 134         if (print_all_characters)
 135         {
 136                 strm << boost::replace_all_copy(rec[expr::message].get<std::wstring>(), "\n", line_break_replacement);
 137         }
 138         else
 139         {
 140                 strm << boost::replace_all_copy(replace_nonprintable_copy(rec[expr::message].get<std::wstring>(), L'?'), L"\n", line_break_replacement);
 141         }
 142 }
 143
 144 namespace internal{
 145
 146 void init()
 147 {
 148         boost::log::add_common_attributes();
 149         boost::log::core::get()->add_global_attribute("NativeThreadId", boost::log::attributes::make_function(&get_current_thread_id));
 150         boost::log::core::get()->add_global_attribute("TimestampMillis", boost::log::attributes::make_function([]
 151         {
 152                 return boost::posix_time::microsec_clock::local_time();
 153         }));
 154         typedef boost::log::sinks::asynchronous_sink<boost::log::sinks::wtext_ostream_backend> stream_sink_type;
 155
 156         auto stream_backend = boost::make_shared<boost::log::sinks::wtext_ostream_backend>();
 157         stream_backend->add_stream(boost::shared_ptr<std::wostream>(&std::wcout, boost::null_deleter()));
 158         stream_backend->auto_flush(true);
 159
 160         auto stream_sink = boost::make_shared<stream_sink_type>(stream_backend);
 161         // Never log calltrace to console. The terminal is too slow, so the log queue will build up faster than consumed.
 162         stream_sink->set_filter(category != log_category::calltrace);
 163
 164         bool print_all_characters = false;
 165         stream_sink->set_formatter(boost::bind(&my_formatter<boost::log::wformatting_ostream>, print_all_characters, _1, _2));
 166
 167         boost::log::core::get()->add_sink(stream_sink);
 168 }
 169
 170 std::string current_exception_diagnostic_information()
 171 {
 172         auto e = boost::current_exception_cast<const char*>();
 173
 174         if (e)
 175                 return std::string("[char *] = ") + *e + "\n";
 176         else
 177                 return boost::current_exception_diagnostic_information();
 178 }
 179
 180 }
 181
 182 void add_file_sink(const std::wstring& file, const boost::log::filter& filter)
 183 {
 184         typedef boost::log::sinks::synchronous_sink<boost::log::sinks::text_file_backend> file_sink_type;
 185
 186         try
 187         {
 188                 if (!boost::filesystem::is_directory(boost::filesystem::path(file).parent_path()))
 189                         CASPAR_THROW_EXCEPTION(directory_not_found());
 190
 191                 auto file_sink = boost::make_shared<file_sink_type>(
 192                         boost::log::keywords::file_name = (file + L"_%Y-%m-%d.log"),
 193                         boost::log::keywords::time_based_rotation = boost::log::sinks::file::rotation_at_time_point(0, 0, 0),
 194                         boost::log::keywords::auto_flush = true,
 195                         boost::log::keywords::open_mode = std::ios::app
 196                         );
 197
 198                 bool print_all_characters = true;
 199
 200                 file_sink->set_formatter(boost::bind(&my_formatter<boost::log::formatting_ostream>, print_all_characters, _1, _2));
 201                 file_sink->set_filter(filter);
 202                 boost::log::core::get()->add_sink(file_sink);
 203         }
 204         catch (...)
 205         {
 206                 std::wcerr << L"Failed to Setup File Logging Sink" << std::endl << std::endl;
 207         }
 208 }
 209
 210 std::shared_ptr<void> add_preformatted_line_sink(std::function<void(std::string line)> formatted_line_sink)
 211 {
 212         class sink_backend : public boost::log::sinks::basic_formatted_sink_backend<char>
 213         {
 214                 std::function<void(std::string line)> formatted_line_sink_;
 215         public:
 216                 // The dummy parameter is to work around a bug in newer Boost.Log, where single-argument
 217                 // constructor forwarders are not recognized unless the parameter uses Boost.Parameter.
 218                 sink_backend(std::function<void(std::string line)> formatted_line_sink, int)
 219                         : formatted_line_sink_(std::move(formatted_line_sink))
 220                 {
 221                 }
 222
 223                 void consume(const boost::log::record_view& rec, const std::string& formatted_message)
 224                 {
 225                         try
 226                         {
 227                                 formatted_line_sink_(formatted_message);
 228                         }
 229                         catch (...)
 230                         {
 231                                 std::cerr << "[sink_backend] Error while consuming formatted message: " << formatted_message << std::endl << std::endl;
 232                         }
 233                 }
 234         };
 235
 236         typedef boost::log::sinks::synchronous_sink<sink_backend> sink_type;
 237
 238         auto sink = boost::make_shared<sink_type>(std::move(formatted_line_sink), 0);
 239         bool print_all_characters = true;
 240
 241         sink->set_formatter(boost::bind(&my_formatter<boost::log::formatting_ostream>, print_all_characters, _1, _2));
 242         sink->set_filter(category != log_category::calltrace);
 243
 244         boost::log::core::get()->add_sink(sink);
 245
 246         return std::shared_ptr<void>(nullptr, [=](void*)
 247         {
 248                 boost::log::core::get()->remove_sink(sink);
 249         });
 250 }
 251
 252 std::mutex& get_filter_mutex()
 253 {
 254         static std::mutex instance;
 255
 256         return instance;
 257 }
 258
 259 boost::log::trivial::severity_level& get_level()
 260 {
 261         static boost::log::trivial::severity_level instance;
 262
 263         return instance;
 264 }
 265
 266 log_category& get_disabled_categories()
 267 {
 268         static log_category instance = log_category::calltrace;
 269
 270         return instance;
 271 }
 272
 273 void set_log_filter()
 274 {
 275         auto severity_filter            = boost::log::trivial::severity >= get_level();
 276         auto disabled_categories        = get_disabled_categories();
 277
 278         boost::log::core::get()->set_filter([=](const boost::log::attribute_value_set& attributes)
 279         {
 280                 return severity_filter(attributes)
 281                         && static_cast<int>(disabled_categories & attributes["Channel"].extract<log_category>().get()) == 0;
 282         });
 283 }
 284
 285 void set_log_level(const std::wstring& lvl)
 286 {
 287         std::lock_guard<std::mutex> lock(get_filter_mutex());
 288
 289         if (boost::iequals(lvl, L"trace"))
 290                 get_level() = boost::log::trivial::trace;
 291         else if (boost::iequals(lvl, L"debug"))
 292                 get_level() = boost::log::trivial::debug;
 293         else if (boost::iequals(lvl, L"info"))
 294                 get_level() = boost::log::trivial::info;
 295         else if (boost::iequals(lvl, L"warning"))
 296                 get_level() = boost::log::trivial::warning;
 297         else if (boost::iequals(lvl, L"error"))
 298                 get_level() = boost::log::trivial::error;
 299         else if (boost::iequals(lvl, L"fatal"))
 300                 get_level() = boost::log::trivial::fatal;
 301
 302         set_log_filter();
 303 }
 304
 305 void set_log_category(const std::wstring& cat, bool enabled)
 306 {
 307         log_category category_to_set;
 308
 309         if (boost::iequals(cat, L"calltrace"))
 310                 category_to_set = log_category::calltrace;
 311         else if (boost::iequals(cat, L"communication"))
 312                 category_to_set = log_category::communication;
 313         else
 314                 return; // Ignore
 315
 316         std::lock_guard<std::mutex> lock(get_filter_mutex());
 317         auto& disabled_categories = get_disabled_categories();
 318
 319         if (enabled)
 320                 disabled_categories &= ~category_to_set;
 321         else
 322                 disabled_categories |= category_to_set;
 323
 324         set_log_filter();
 325 }
 326
 327 void print_child(
 328                 boost::log::trivial::severity_level level,
 329                 const std::wstring& indent,
 330                 const std::wstring& elem,
 331                 const boost::property_tree::wptree& tree)
 332 {
 333         auto& data = tree.data();
 334
 335         if (!data.empty())
 336                 BOOST_LOG_STREAM_WITH_PARAMS(log::logger::get(), (boost::log::keywords::severity = level)) << indent << elem << L" " << replace_nonprintable_copy(data, L'?');
 337         else if (tree.size() == 0)
 338                 BOOST_LOG_STREAM_WITH_PARAMS(log::logger::get(), (boost::log::keywords::severity = level)) << indent << elem;
 339
 340         for (auto& child : tree)
 341                 print_child(level, indent + (elem.empty() ? L"" : elem + L"."), child.first, child.second);
 342 }
 343
 344 const char* remove_source_prefix(const char* file)
 345 {
 346         auto found = boost::ifind_first(file, get_source_prefix().c_str());
 347
 348         if (found)
 349                 return found.end();
 350         else
 351                 return file;
 352 }
 353
 354 }}