Refactor logging - all changes

[gumb0]

This PR accumulates all smaller PRs related to rewriting logging system using boost.log

• Create basic logging primitives in Log.h
• Custom operator<< for log stream to apply special formatting to logged values - this will replace LogOutputStreamBase::append() methods
• Change all logging statements to use new logging
• Rename clogSimple to clog
• Replace ThreadContext mechanism with some additional log context attributes
• setupLogging() in all executables
• Get rid of global verbosity variable (make it argument to setupLogging() instead)
• Separate global logger for critical errors, also probably remove cdebug, clog, cnote, ctrace or leave only one of them
• Handle exceptions from logging system
• new command line parameter for filtering channels (probably create program options group to handle it easily in all tools)

Summary of changes noticeable to user

• Names of many channels will be changed, all channels will have readable names to allow filtering by channel (e.g. there will be warn instead of ✘)
• Channel names won't be colored, so log will be less colorful overall
• Some special values like URLs and error messages will be not colored (those that used LogTag stream manipulator), primitive types like ints won't be colored; some others e.g. h256 stay colored though.
• Outputting std::strings won't automatically add quotation marks around; they also won't be colored.
• "AutoSpacing" feature is removed - it allowed to output to log stream not caring about spaces between values, like cwarn << "Transaction hash" << hash << "already imported"; Now spaces need to be explicit like cwarn << "Transaction hash " << hash << " already imported"; I'll try to change this in all log messages, but I might miss some.
• Some channels were supposed to be visible only in Debug build (the ones with LogChannel::debug == true) - but this was working only for Windows, where NDEBUG macro is defined in debug, for other platforms debug channels were visible in Release, too. This difference is removed, channel visibility will depend only on filtering, but not on build type.

Log message line will look like

2018-04-17 12:15:59 eth timer Block import 5123675 3184 ms

(eth is the name of the thread, timer is the name of the channel)

[codecov-io]

Codecov Report

Merging #4963 into develop will decrease coverage by 0.37%.
The diff coverage is 41.37%.

@@             Coverage Diff             @@
##           develop    #4963      +/-   ##
===========================================
- Coverage       61%   60.62%   -0.38%     
===========================================
  Files          350      350              
  Lines        28346    28352       +6     
  Branches      2883     3210     +327     
===========================================
- Hits         17293    17189     -104     
- Misses       10085    10204     +119     
+ Partials       968      959       -9

[gumb0]

There's some problem with formatting operator<< overloads.
From Host.cpp:

    cnetdetails << "Attempting connection to node " << _p->id << "@" << ep << " from " << id();

Both _p->id and id() are of type NodeID (h512) but operator<< for h512 from Log.h is called only for the second one. The first one is non-const lvalue and the second is rvalue, so I thinks operator<< is called only for const references, but not for non-const.

[gumb0]

There's some problem with formatting operator<< overloads.

This is fixed now

[gumb0]

Tests fail on macos, I need to do something with it

[gumb0]

Tests fail on macos, I need to do something with it

Should be fixed now.

[gumb0]

Rebased.

[gumb0]

Still some test failure/crashes happen sometimes on macos, I'll investigate it further

[gumb0]

Well I restarted it now 3 times and it doesn't reproduce. Also I can't reproduce it locally on mac.

I'd like to merge it now like this then @chfast

[gumb0]

Ah no, now I got it again locally, here's the Release build stack

* thread #2, name = 'p2p', stop reason = EXC_BAD_ACCESS (code=2, address=0x102c02760)
  * frame #0: 0x0000000102c02760
    frame #1: 0x000000010091008d testeth`boost::log::v2s_mt_posix::attribute_value_set::implementation::freeze_node(boost::log::v2s_mt_posix::attribute_name, boost::log::v2s_mt_posix::attribute_value_set::implementation::bucket&, boost::log::v2s_mt_posix::attribute_value_set::node*) [inlined] boost::log::v2s_mt_posix::attribute::get_value() const at attribute_get_value_impl.hpp:34 [opt]
    frame #2: 0x000000010091007f testeth`boost::log::v2s_mt_posix::attribute_value_set::implementation::freeze_node(this=0x0000000103054000, key=(m_id = 0), b=0x0000000103054040, where=0x0000000000000000) at attribute_value_set.cpp:350 [opt]
    frame #3: 0x000000010090fe27 testeth`boost::log::v2s_mt_posix::attribute_value_set::find(boost::log::v2s_mt_posix::attribute_name) const [inlined] boost::log::v2s_mt_posix::attribute_value_set::implementation::find(this=<unavailable>) at attribute_value_set.cpp:278 [opt]
    frame #4: 0x000000010090fddc testeth`boost::log::v2s_mt_posix::attribute_value_set::find(this=0x000070000e61cab0, key=<unavailable>) const at attribute_value_set.cpp:549 [opt]
    frame #5: 0x000000010063f647 testeth`boost::log::v2s_mt_posix::aux::light_function<bool (boost::log::v2s_mt_posix::attribute_value_set const&)>::impl<dev::setupLogging(int)::$_0>::invoke_impl(void*, boost::log::v2s_mt_posix::attribute_value_set const&) + 55
    frame #6: 0x000000010063c898 testeth`boost::log::v2s_mt_posix::sinks::basic_sink_frontend::will_consume(boost::log::v2s_mt_posix::attribute_value_set const&) + 40
    frame #7: 0x0000000100918039 testeth`boost::log::v2s_mt_posix::core::implementation::apply_sink_filter(this=0x0000000102f3a000, sink=0x0000000102c02170, rec_impl=0x000070000e61cac8, attr_values=0x000070000e61cab8, remaining_capacity=1) at core.cpp:440 [opt]
    frame #8: 0x0000000100915a65 testeth`boost::log::v2s_mt_posix::core::open_record(boost::log::v2s_mt_posix::attribute_set const&) at core.cpp:335 [opt]
    frame #9: 0x000000010091598a testeth`boost::log::v2s_mt_posix::core::open_record(this=<unavailable>, source_attributes=<unavailable>) at core.cpp:645 [opt]
    frame #10: 0x0000000100810f35 testeth`std::__1::__function::__func<dev::p2p::NodeTable::doDiscover(dev::FixedHash<64u>, unsigned int, std::__1::shared_ptr<std::__1::set<std::__1::shared_ptr<dev::p2p::NodeEntry>, std::__1::less<std::__1::shared_ptr<dev::p2p::NodeEntry> >, std::__1::allocator<std::__1::shared_ptr<dev::p2p::NodeEntry> > > >)::$_0, std::__1::allocator<dev::p2p::NodeTable::doDiscover(dev::FixedHash<64u>, unsigned int, std::__1::shared_ptr<std::__1::set<std::__1::shared_ptr<dev::p2p::NodeEntry>, std::__1::less<std::__1::shared_ptr<dev::p2p::NodeEntry> >, std::__1::allocator<std::__1::shared_ptr<dev::p2p::NodeEntry> > > >)::$_0>, void (boost::system::error_code const&)>::operator()(boost::system::error_code const&) + 117
    frame #11: 0x00000001007e2d9c testeth`boost::asio::detail::wait_handler<std::__1::function<void (boost::system::error_code const&)> >::do_complete(boost::asio::detail::task_io_service*, boost::asio::detail::task_io_service_operation*, boost::system::error_code const&, unsigned long) + 204
    frame #12: 0x000000010040c0ab testeth`boost::asio::detail::task_io_service::do_poll_one(boost::asio::detail::scoped_lock<boost::asio::detail::posix_mutex>&, boost::asio::detail::task_io_service_thread_info&, boost::system::error_code const&) + 555
    frame #13: 0x000000010040bca5 testeth`boost::asio::detail::task_io_service::poll(boost::system::error_code&) + 405
    frame #14: 0x00000001007e7f1f testeth`dev::p2p::Host::doneWorking() + 335
    frame #15: 0x0000000100653d4e testeth`void* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, dev::Worker::startWorking()::$_0> >(void*) + 414
    frame #16: 0x00007fff526ef661 libsystem_pthread.dylib`_pthread_body + 340
    frame #17: 0x00007fff526ef50d libsystem_pthread.dylib`_pthread_start + 377
    frame #18: 0x00007fff526eebf9 libsystem_pthread.dylib`thread_start + 13

[gumb0]

This should fix it #4992

[gumb0]

I created an issue to track the rest of the tasks here after we merge #4984

[chfast]

clang 6 out-of-memory.

[chfast]

Can't we hide boost headers somehow and compile them in single compilation unit only? This seem to be a beast.