X-Git-Url: https://git.sesse.net/?a=blobdiff_plain;f=common%2Flog.cpp;h=31a34577617694555741f1e021b5d342bb45bca8;hb=7e7ef09558efdd89c3168017592978e90531f76d;hp=afbed41a845b0f4e7c0f384269c84f40960e7c8d;hpb=5aa967a16529cbaebf6528a75bc79f241f7b096e;p=casparcg

diff --git a/common/log.cpp b/common/log.cpp
index afbed41a8..31a345776 100644
--- a/common/log.cpp
+++ b/common/log.cpp
@@ -21,60 +21,50 @@
 
 #include "stdafx.h"
 
-#if defined(_MSC_VER)
-#pragma warning (disable : 4100) // 'identifier' : unreferenced formal parameter
-#pragma warning (disable : 4512) // 'class' : assignment operator could not be generated
-#endif
-
 #include "log.h"
 
 #include "except.h"
 #include "utf.h"
-#include "compiler/vs/stack_walker.h"
 
 #include <ios>
 #include <iomanip>
 #include <string>
 #include <ostream>
 
-#include <boost/bind.hpp>
 #include <boost/shared_ptr.hpp>
 #include <boost/make_shared.hpp>
 #include <boost/filesystem/convenience.hpp>
 #include <boost/date_time/posix_time/posix_time.hpp>
 #include <boost/algorithm/string.hpp>
 
-#include <boost/log/core/core.hpp>
-
-#include <boost/log/formatters/stream.hpp>
-#include <boost/log/formatters/attr.hpp>
-#include <boost/log/formatters/date_time.hpp>
-#include <boost/log/formatters/message.hpp>
-
-#include <boost/log/filters/attr.hpp>
-
-#include <boost/log/sinks/text_file_backend.hpp>
-
-#include <boost/log/detail/universal_path.hpp>
+#include <boost/log/core.hpp>
+#include <boost/log/trivial.hpp>
+#include <boost/log/expressions.hpp>
 
 #include <boost/log/sinks/text_file_backend.hpp>
 #include <boost/log/sinks/text_ostream_backend.hpp>
 #include <boost/log/sinks/sync_frontend.hpp>
 #include <boost/log/sinks/async_frontend.hpp>
 #include <boost/log/core/record.hpp>
-#include <boost/log/utility/attribute_value_extractor.hpp>
+#include <boost/log/attributes/attribute_value.hpp>
+#include <boost/log/attributes/current_thread_id.hpp>
+#include <boost/log/utility/setup/common_attributes.hpp>
 
-#include <boost/log/utility/init/common_attributes.hpp>
-#include <boost/log/utility/empty_deleter.hpp>
+#include <boost/core/null_deleter.hpp>
 #include <boost/lambda/lambda.hpp>
+#include <boost/bind.hpp>
+#include <boost/lexical_cast.hpp>
+#include <boost/property_tree/ptree.hpp>
+#include <boost/thread/mutex.hpp>
 
-#include <tbb/enumerable_thread_specific.h>
+#include <tbb/atomic.h>
 
 namespace caspar { namespace log {
 
 using namespace boost;
 
-void append_timestamp(std::wostream& stream)
+template<typename Stream>
+void append_timestamp(Stream& stream)
 {
 	auto timestamp = boost::posix_time::microsec_clock::local_time();
 	auto date = timestamp.date();
@@ -96,35 +86,57 @@ void append_timestamp(std::wostream& stream)
 	stream << buffer.str();
 }
 
-void my_formatter(bool print_all_characters, std::wostream& strm, boost::log::basic_record<wchar_t> const& rec)
+class column_writer
 {
-    namespace lambda = boost::lambda;
-	
-	#pragma warning(disable : 4996)
-	
-	append_timestamp(strm);
-		
-    boost::log::attributes::current_thread_id::held_type thread_id;
-    if(boost::log::extract<boost::log::attributes::current_thread_id::held_type>(L"ThreadID", rec.attribute_values(), lambda::var(thread_id) = lambda::_1))
-        strm << L"[" << thread_id << L"] ";
-	
-    severity_level severity;
-    if(boost::log::extract<severity_level>(boost::log::sources::aux::severity_attribute_name<wchar_t>::get(), rec.attribute_values(), lambda::var(severity) = lambda::_1))
+	tbb::atomic<int> column_width_;
+public:
+	column_writer(int initial_width = 0)
 	{
-		std::stringstream ss;
-		ss << severity;
-        strm << L"[" << severity << L"] ";
-		for(int n = 0; n < 7-static_cast<int>(ss.str().size()); ++n)
-			strm << L" ";
+		column_width_ = initial_width;
 	}
 
+	template<typename Stream, typename Val>
+	void write(Stream& out, const Val& value)
+	{
+		std::wstring to_string = boost::lexical_cast<std::wstring>(value);
+		int length = static_cast<int>(to_string.size());
+		int read_width;
+
+		while ((read_width = column_width_) < length && column_width_.compare_and_swap(length, read_width) != read_width);
+		read_width = column_width_;
+
+		out << L"[" << to_string << L"] ";
+
+		for (int n = 0; n < read_width - length; ++n)
+			out << L" ";
+	}
+};
+
+template<typename Stream>
+void my_formatter(bool print_all_characters, const boost::log::record_view& rec, Stream& strm)
+{
+	static column_writer thread_id_column;
+	static column_writer severity_column(7);
+	namespace expr = boost::log::expressions;
+
+	std::wstringstream pre_message_stream;
+	append_timestamp(pre_message_stream);
+	thread_id_column.write(pre_message_stream, boost::log::extract<boost::log::attributes::current_thread_id::value_type>("ThreadID", rec).get().native_id());
+	severity_column.write(pre_message_stream, boost::log::extract<boost::log::trivial::severity_level>("Severity", rec));
+
+	auto pre_message = pre_message_stream.str();
+
+	strm << pre_message;
+
+	auto line_break_replacement = L"\n" + pre_message;
+
 	if (print_all_characters)
 	{
-		strm << rec.message();
+		strm << boost::replace_all_copy(rec[expr::message].get<std::wstring>(), "\n", line_break_replacement);
 	}
 	else
 	{
-	    strm << replace_nonprintable_copy(rec.message(), L'?');
+		strm << boost::replace_all_copy(replace_nonprintable_copy(rec[expr::message].get<std::wstring>(), L'?'), L"\n", line_break_replacement);
 	}
 }
 
@@ -132,124 +144,183 @@ namespace internal{
 	
 void init()
 {	
-	boost::log::add_common_attributes<wchar_t>();
-	typedef boost::log::aux::add_common_attributes_constants<wchar_t> traits_t;
-
-	typedef boost::log::sinks::synchronous_sink<boost::log::sinks::wtext_file_backend> file_sink_type;
-
+	boost::log::add_common_attributes();
 	typedef boost::log::sinks::asynchronous_sink<boost::log::sinks::wtext_ostream_backend> stream_sink_type;
 
 	auto stream_backend = boost::make_shared<boost::log::sinks::wtext_ostream_backend>();
-	stream_backend->add_stream(boost::shared_ptr<std::wostream>(&std::wcout, boost::log::empty_deleter()));
+	stream_backend->add_stream(boost::shared_ptr<std::wostream>(&std::wcout, boost::null_deleter()));
 	stream_backend->auto_flush(true);
 
 	auto stream_sink = boost::make_shared<stream_sink_type>(stream_backend);
-	
-//#ifdef NDEBUG
-//	stream_sink->set_filter(boost::log::filters::attr<severity_level>(boost::log::sources::aux::severity_attribute_name<wchar_t>::get()) >= debug);
-//#else
-//	stream_sink->set_filter(boost::log::filters::attr<severity_level>(boost::log::sources::aux::severity_attribute_name<wchar_t>::get()) >= debug);
-//#endif
+	// Never log calltrace to console. The terminal is too slow, so the log queue will build up faster than consumed.
+	stream_sink->set_filter(category != log_category::calltrace);
+
+	bool print_all_characters = false;
+	stream_sink->set_formatter(boost::bind(&my_formatter<boost::log::wformatting_ostream>, print_all_characters, _1, _2));
 
-	stream_sink->locked_backend()->set_formatter(boost::bind(my_formatter, false, _1, _2));
+	boost::log::core::get()->add_sink(stream_sink);
+}
 
-	boost::log::wcore::get()->add_sink(stream_sink);
 }
 
-std::wstring get_call_stack()
+void add_file_sink(const std::wstring& file, const boost::log::filter& filter)
 {
-	class log_call_stack_walker : public stack_walker
+	typedef boost::log::sinks::synchronous_sink<boost::log::sinks::text_file_backend> file_sink_type;
+
+	try
 	{
-		std::string str_;
-	public:
-		log_call_stack_walker() : stack_walker() {}
+		if (!boost::filesystem::is_directory(boost::filesystem::path(file).parent_path()))
+			CASPAR_THROW_EXCEPTION(directory_not_found());
 
-		std::string flush()
-		{
-			return std::move(str_);
-		}
-	protected:		
-		virtual void OnSymInit(LPCSTR szSearchPath, DWORD symOptions, LPCSTR szUserName)
-		{
-		}
-		virtual void OnLoadModule(LPCSTR img, LPCSTR mod, DWORD64 baseAddr, DWORD size, DWORD result, LPCSTR symType, LPCSTR pdbName, ULONGLONG fileVersion)
-		{
-		}
-		virtual void OnDbgHelpErr(LPCSTR szFuncName, DWORD gle, DWORD64 addr)
+		auto file_sink = boost::make_shared<file_sink_type>(
+			boost::log::keywords::file_name = (file + L"_%Y-%m-%d.log"),
+			boost::log::keywords::time_based_rotation = boost::log::sinks::file::rotation_at_time_point(0, 0, 0),
+			boost::log::keywords::auto_flush = true,
+			boost::log::keywords::open_mode = std::ios::app
+			);
+
+		bool print_all_characters = true;
+
+		file_sink->set_formatter(boost::bind(&my_formatter<boost::log::formatting_ostream>, print_all_characters, _1, _2));
+		file_sink->set_filter(filter);
+		boost::log::core::get()->add_sink(file_sink);
+	}
+	catch (...)
+	{
+		std::wcerr << L"Failed to Setup File Logging Sink" << std::endl << std::endl;
+	}
+}
+
+std::shared_ptr<void> add_preformatted_line_sink(std::function<void(std::string line)> formatted_line_sink)
+{
+	class sink_backend : public boost::log::sinks::basic_formatted_sink_backend<char>
+	{
+		std::function<void(std::string line)> formatted_line_sink_;
+	public:
+		sink_backend(std::function<void(std::string line)> formatted_line_sink)
+			: formatted_line_sink_(std::move(formatted_line_sink))
 		{
 		}
-		virtual void OnOutput(LPCSTR szText)
-		{
-			std::string str = szText;
 
-			if(str.find("internal::get_call_stack") == std::string::npos && str.find("stack_walker::ShowCallstack") == std::string::npos)
-				str_ += std::move(str);
+		void consume(const boost::log::record_view& rec, const std::string& formatted_message)
+		{
+			try
+			{
+				formatted_line_sink_(formatted_message);
+			}
+			catch (...)
+			{
+				std::cerr << "[sink_backend] Error while consuming formatted message: " << formatted_message << std::endl << std::endl;
+			}
 		}
 	};
 
-	static tbb::enumerable_thread_specific<log_call_stack_walker> walkers;
-	try
-	{
-		auto& walker = walkers.local();
-		walker.ShowCallstack();
-		return u16(walker.flush());
-	}
-	catch(...)
+	typedef boost::log::sinks::synchronous_sink<sink_backend> sink_type;
+
+	auto sink = boost::make_shared<sink_type>(std::move(formatted_line_sink));
+	bool print_all_characters = true;
+
+	sink->set_formatter(boost::bind(&my_formatter<boost::log::formatting_ostream>, print_all_characters, _1, _2));
+	sink->set_filter(category != log_category::calltrace);
+
+	boost::log::core::get()->add_sink(sink);
+
+	return std::shared_ptr<void>(nullptr, [=](void*)
 	{
-		return L"!!!";
-	}
+		boost::log::core::get()->remove_sink(sink);
+	});
 }
 
+boost::mutex& get_filter_mutex()
+{
+	static boost::mutex instance;
+
+	return instance;
 }
 
-void add_file_sink(const std::wstring& folder)
-{	
-	boost::log::add_common_attributes<wchar_t>();
-	typedef boost::log::aux::add_common_attributes_constants<wchar_t> traits_t;
+boost::log::trivial::severity_level& get_level()
+{
+	static boost::log::trivial::severity_level instance;
 
-	typedef boost::log::sinks::synchronous_sink<boost::log::sinks::wtext_file_backend> file_sink_type;
+	return instance;
+}
 
-	try
-	{
-		if(!boost::filesystem::is_directory(folder))
-			CASPAR_THROW_EXCEPTION(directory_not_found());
+log_category& get_disabled_categories()
+{
+	static log_category instance = log_category::calltrace;
 
-		auto file_sink = boost::make_shared<file_sink_type>(
-			boost::log::keywords::file_name = (folder + L"caspar_%Y-%m-%d.log"),
-			boost::log::keywords::time_based_rotation = boost::log::sinks::file::rotation_at_time_point(0, 0, 0),
-			boost::log::keywords::auto_flush = true,
-			boost::log::keywords::open_mode = std::ios::app
-		);
-		
-		file_sink->locked_backend()->set_formatter(boost::bind(my_formatter, true, _1, _2));
-
-//#ifdef NDEBUG
-//		file_sink->set_filter(boost::log::filters::attr<severity_level>(boost::log::sources::aux::severity_attribute_name<wchar_t>::get()) >= debug);
-//#else
-//		file_sink->set_filter(boost::log::filters::attr<severity_level>(boost::log::sources::aux::severity_attribute_name<wchar_t>::get()) >= debug);
-//#endif
-		boost::log::wcore::get()->add_sink(file_sink);
-	}
-	catch(...)
+	return instance;
+}
+
+void set_log_filter()
+{
+	auto severity_filter		= boost::log::trivial::severity >= get_level();
+	auto disabled_categories	= get_disabled_categories();
+
+	boost::log::core::get()->set_filter([=](const boost::log::attribute_value_set& attributes)
 	{
-		std::wcerr << L"Failed to Setup File Logging Sink" << std::endl << std::endl;
-	}
+		return severity_filter(attributes)
+			&& static_cast<int>(disabled_categories & attributes["Channel"].extract<log_category>().get()) == 0;
+	});
 }
 
 void set_log_level(const std::wstring& lvl)
-{	
-	if(boost::iequals(lvl, L"trace"))
-		boost::log::wcore::get()->set_filter(boost::log::filters::attr<severity_level>(boost::log::sources::aux::severity_attribute_name<wchar_t>::get()) >= trace);
-	else if(boost::iequals(lvl, L"debug"))
-		boost::log::wcore::get()->set_filter(boost::log::filters::attr<severity_level>(boost::log::sources::aux::severity_attribute_name<wchar_t>::get()) >= debug);
-	else if(boost::iequals(lvl, L"info"))
-		boost::log::wcore::get()->set_filter(boost::log::filters::attr<severity_level>(boost::log::sources::aux::severity_attribute_name<wchar_t>::get()) >= info);
-	else if(boost::iequals(lvl, L"warning"))
-		boost::log::wcore::get()->set_filter(boost::log::filters::attr<severity_level>(boost::log::sources::aux::severity_attribute_name<wchar_t>::get()) >= warning);
-	else if(boost::iequals(lvl, L"error"))
-		boost::log::wcore::get()->set_filter(boost::log::filters::attr<severity_level>(boost::log::sources::aux::severity_attribute_name<wchar_t>::get()) >= error);
-	else if(boost::iequals(lvl, L"fatal"))
-		boost::log::wcore::get()->set_filter(boost::log::filters::attr<severity_level>(boost::log::sources::aux::severity_attribute_name<wchar_t>::get()) >= fatal);
+{
+	boost::lock_guard<boost::mutex> lock(get_filter_mutex());
+
+	if (boost::iequals(lvl, L"trace"))
+		get_level() = boost::log::trivial::trace;
+	else if (boost::iequals(lvl, L"debug"))
+		get_level() = boost::log::trivial::debug;
+	else if (boost::iequals(lvl, L"info"))
+		get_level() = boost::log::trivial::info;
+	else if (boost::iequals(lvl, L"warning"))
+		get_level() = boost::log::trivial::warning;
+	else if (boost::iequals(lvl, L"error"))
+		get_level() = boost::log::trivial::error;
+	else if (boost::iequals(lvl, L"fatal"))
+		get_level() = boost::log::trivial::fatal;
+
+	set_log_filter();
+}
+
+void set_log_category(const std::wstring& cat, bool enabled)
+{
+	log_category category_to_set;
+
+	if (boost::iequals(cat, L"calltrace"))
+		category_to_set = log_category::calltrace;
+	else if (boost::iequals(cat, L"communication"))
+		category_to_set = log_category::communication;
+	else
+		return; // Ignore
+
+	boost::lock_guard<boost::mutex> lock(get_filter_mutex());
+	auto& disabled_categories = get_disabled_categories();
+
+	if (enabled)
+		disabled_categories &= ~category_to_set;
+	else
+		disabled_categories |= category_to_set;
+
+	set_log_filter();
+}
+
+void print_child(
+		boost::log::trivial::severity_level level,
+		const std::wstring& indent,
+		const std::wstring& elem,
+		const boost::property_tree::wptree& tree)
+{
+	auto& data = tree.data();
+
+	if (!data.empty())
+		BOOST_LOG_STREAM_WITH_PARAMS(log::logger::get(), (boost::log::keywords::severity = level)) << indent << elem << L" " << replace_nonprintable_copy(data, L'?');
+	else if (tree.size() == 0)
+		BOOST_LOG_STREAM_WITH_PARAMS(log::logger::get(), (boost::log::keywords::severity = level)) << indent << elem;
+
+	for (auto& child : tree)
+		print_child(level, indent + (elem.empty() ? L"" : elem + L"."), child.first, child.second);
 }
 
-}}
\ No newline at end of file
+}}