2 * Copyright (c) 2011 Sveriges Television AB <info@casparcg.com>
4 * This file is part of CasparCG (www.casparcg.com).
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.
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.
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/>.
19 * Author: Robert Nagy, ronag89@gmail.com
26 #include "os/threading.h"
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>
43 #include <boost/log/core.hpp>
44 #include <boost/log/trivial.hpp>
45 #include <boost/log/expressions.hpp>
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>
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>
62 #include <tbb/atomic.h>
64 namespace caspar { namespace log {
66 using namespace boost;
68 template<typename Stream>
69 void append_timestamp(Stream& stream, boost::posix_time::ptime timestamp)
71 auto date = timestamp.date();
72 auto time = timestamp.time_of_day();
73 auto milliseconds = time.fractional_seconds() / 1000; // microseconds to milliseconds
75 std::wstringstream buffer;
80 << std::setw(4) << date.year() << L"-" << std::setw(2) << date.month().as_number() << "-" << std::setw(2) << date.day().as_number()
82 << std::setw(2) << time.hours() << L":" << std::setw(2) << time.minutes() << L":" << std::setw(2) << time.seconds()
84 << std::setw(3) << milliseconds
87 stream << buffer.str();
92 tbb::atomic<int> column_width_;
94 column_writer(int initial_width = 0)
96 column_width_ = initial_width;
99 template<typename Stream, typename Val>
100 void write(Stream& out, const Val& value)
102 std::wstring to_string = boost::lexical_cast<std::wstring>(value);
103 int length = static_cast<int>(to_string.size());
106 while ((read_width = column_width_) < length && column_width_.compare_and_swap(length, read_width) != read_width);
107 read_width = column_width_;
109 out << L"[" << to_string << L"] ";
111 for (int n = 0; n < read_width - length; ++n)
116 template<typename Stream>
117 void my_formatter(bool print_all_characters, const boost::log::record_view& rec, Stream& strm)
119 static column_writer thread_id_column;
120 static column_writer severity_column(7);
121 namespace expr = boost::log::expressions;
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));
128 auto pre_message = pre_message_stream.str();
132 auto line_break_replacement = L"\n" + pre_message;
134 if (print_all_characters)
136 strm << boost::replace_all_copy(rec[expr::message].get<std::wstring>(), "\n", line_break_replacement);
140 strm << boost::replace_all_copy(replace_nonprintable_copy(rec[expr::message].get<std::wstring>(), L'?'), L"\n", line_break_replacement);
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([]
152 return boost::posix_time::microsec_clock::local_time();
154 typedef boost::log::sinks::asynchronous_sink<boost::log::sinks::wtext_ostream_backend> stream_sink_type;
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);
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);
164 bool print_all_characters = false;
165 stream_sink->set_formatter(boost::bind(&my_formatter<boost::log::wformatting_ostream>, print_all_characters, _1, _2));
167 boost::log::core::get()->add_sink(stream_sink);
170 std::string current_exception_diagnostic_information()
172 auto e = boost::current_exception_cast<const char*>();
175 return std::string("[char *] = ") + *e + "\n";
177 return boost::current_exception_diagnostic_information();
182 void add_file_sink(const std::wstring& file, const boost::log::filter& filter)
184 typedef boost::log::sinks::synchronous_sink<boost::log::sinks::text_file_backend> file_sink_type;
188 if (!boost::filesystem::is_directory(boost::filesystem::path(file).parent_path()))
189 CASPAR_THROW_EXCEPTION(directory_not_found());
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
198 bool print_all_characters = true;
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);
206 std::wcerr << L"Failed to Setup File Logging Sink" << std::endl << std::endl;
210 std::shared_ptr<void> add_preformatted_line_sink(std::function<void(std::string line)> formatted_line_sink)
212 class sink_backend : public boost::log::sinks::basic_formatted_sink_backend<char>
214 std::function<void(std::string line)> formatted_line_sink_;
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))
223 void consume(const boost::log::record_view& rec, const std::string& formatted_message)
227 formatted_line_sink_(formatted_message);
231 std::cerr << "[sink_backend] Error while consuming formatted message: " << formatted_message << std::endl << std::endl;
236 typedef boost::log::sinks::synchronous_sink<sink_backend> sink_type;
238 auto sink = boost::make_shared<sink_type>(std::move(formatted_line_sink), 0);
239 bool print_all_characters = true;
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);
244 boost::log::core::get()->add_sink(sink);
246 return std::shared_ptr<void>(nullptr, [=](void*)
248 boost::log::core::get()->remove_sink(sink);
252 std::mutex& get_filter_mutex()
254 static std::mutex instance;
259 boost::log::trivial::severity_level& get_level()
261 static boost::log::trivial::severity_level instance;
266 log_category& get_disabled_categories()
268 static log_category instance = log_category::calltrace;
273 void set_log_filter()
275 auto severity_filter = boost::log::trivial::severity >= get_level();
276 auto disabled_categories = get_disabled_categories();
278 boost::log::core::get()->set_filter([=](const boost::log::attribute_value_set& attributes)
280 return severity_filter(attributes)
281 && static_cast<int>(disabled_categories & attributes["Channel"].extract<log_category>().get()) == 0;
285 void set_log_level(const std::wstring& lvl)
287 std::lock_guard<std::mutex> lock(get_filter_mutex());
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;
305 void set_log_category(const std::wstring& cat, bool enabled)
307 log_category category_to_set;
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;
316 std::lock_guard<std::mutex> lock(get_filter_mutex());
317 auto& disabled_categories = get_disabled_categories();
320 disabled_categories &= ~category_to_set;
322 disabled_categories |= category_to_set;
328 boost::log::trivial::severity_level level,
329 const std::wstring& indent,
330 const std::wstring& elem,
331 const boost::property_tree::wptree& tree)
333 auto& data = tree.data();
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;
340 for (auto& child : tree)
341 print_child(level, indent + (elem.empty() ? L"" : elem + L"."), child.first, child.second);
344 const char* remove_source_prefix(const char* file)
346 auto found = boost::ifind_first(file, get_source_prefix().c_str());