Change logging to easylogging++

This replaces the epee and data_loggers logging systems with
a single one, and also adds filename:line and explicit severity
levels. Categories may be defined, and logging severity set
by category (or set of categories). epee style 0-4 log level
maps to a sensible severity configuration. Log files now also
rotate when reaching 100 MB.

To select which logs to output, use the MONERO_LOGS environment
variable, with a comma separated list of categories (globs are
supported), with their requested severity level after a colon.
If a log matches more than one such setting, the last one in
the configuration string applies. A few examples:

This one is (mostly) silent, only outputting fatal errors:

MONERO_LOGS=*:FATAL

This one is very verbose:

MONERO_LOGS=*:TRACE

This one is totally silent (logwise):

MONERO_LOGS=""

This one outputs all errors and warnings, except for the
"verify" category, which prints just fatal errors (the verify
category is used for logs about incoming transactions and
blocks, and it is expected that some/many will fail to verify,
hence we don't want the spam):

MONERO_LOGS=*:WARNING,verify:FATAL

Log levels are, in decreasing order of priority:
FATAL, ERROR, WARNING, INFO, DEBUG, TRACE

Subcategories may be added using prefixes and globs. This
example will output net.p2p logs at the TRACE level, but all
other net* logs only at INFO:

MONERO_LOGS=*:ERROR,net*:INFO,net.p2p:TRACE

Logs which are intended for the user (which Monero was using
a lot through epee, but really isn't a nice way to go things)
should use the "global" category. There are a few helper macros
for using this category, eg: MGINFO("this shows up by default")
or MGINFO_RED("this is red"), to try to keep a similar look
and feel for now.

Existing epee log macros still exist, and map to the new log
levels, but since they're used as a "user facing" UI element
as much as a logging system, they often don't map well to log
severities (ie, a log level 0 log may be an error, or may be
something we want the user to see, such as an important info).
In those cases, I tried to use the new macros. In other cases,
I left the existing macros in. When modifying logs, it is
probably best to switch to the new macros with explicit levels.

The --log-level options and set_log commands now also accept
category settings, in addition to the epee style log levels.

1 files changed, 39 insertions, 46 deletions

diff --git a/contrib/epee/include/net/abstract_tcp_server2.inl b/contrib/epee/include/net/abstract_tcp_server2.inl
index 834b5a7a6..75a9c5be9 100644
--- a/contrib/epee/include/net/abstract_tcp_server2.inl
+++ b/contrib/epee/include/net/abstract_tcp_server2.inl
@@ -51,9 +51,8 @@
 
 #include "../../../../src/cryptonote_core/cryptonote_core.h" // e.g. for the send_stop_signal()
 
-#include "../../../../contrib/otshell_utils/utils.hpp"
-#include "../../../../src/p2p/data_logger.hpp"
-using namespace nOT::nUtils; // TODO
+#undef MONERO_DEFAULT_LOG_CATEGORY
+#define MONERO_DEFAULT_LOG_CATEGORY "net"
 
 #define CONNECTION_CLEANUP_TIME 30 // seconds
 
@@ -83,7 +82,7 @@ PRAGMA_WARNING_DISABLE_VS(4355)
 		m_throttle_speed_in("speed_in", "throttle_speed_in"),
 		m_throttle_speed_out("speed_out", "throttle_speed_out")
   {
-    _info_c("net/sleepRPC", "test, connection constructor set m_connection_type="<<m_connection_type);
+    MINFO("test, connection constructor set m_connection_type="<<m_connection_type);
   }
 PRAGMA_WARNING_DISABLE_VS(4355)
   //---------------------------------------------------------------------------------
@@ -229,7 +228,7 @@ PRAGMA_WARNING_DISABLE_VS(4355)
   {
     TRY_ENTRY();
     boost::shared_ptr<connection<t_protocol_handler> >  back_connection_copy;
-    LOG_PRINT_L4("[sock " << socket_.native_handle() << "] release");
+    LOG_TRACE_CC(context, "[sock " << socket_.native_handle() << "] release");
     CRITICAL_REGION_BEGIN(m_self_refs_lock);
     CHECK_AND_ASSERT_MES(m_self_refs.size(), false, "[sock " << socket_.native_handle() << "] m_self_refs empty at connection<t_protocol_handler>::release() call");
     //erasing from container without additional copy can cause start deleting object, including m_self_refs
@@ -266,8 +265,7 @@ PRAGMA_WARNING_DISABLE_VS(4355)
       address = endpoint.address().to_string();
       port = boost::lexical_cast<std::string>(endpoint.port());
     }
-    _mark_c("net/kind" ,
-        " connection type " << to_string( m_connection_type ) << " "
+    MINFO(" connection type " << to_string( m_connection_type ) << " "
         << socket_.local_endpoint().address().to_string() << ":" << socket_.local_endpoint().port()
         << " <--> " << address << ":" << port);
   }
@@ -306,7 +304,6 @@ PRAGMA_WARNING_DISABLE_VS(4355)
 				delay *= 0.5;
 				if (delay > 0) {
 					long int ms = (long int)(delay * 100);
-					epee::net_utils::data_logger::get_instance().add_data("sleep_down", ms);
 					boost::this_thread::sleep_for(boost::chrono::milliseconds(ms));
 				}
 			} while(delay > 0);
@@ -397,14 +394,14 @@ PRAGMA_WARNING_DISABLE_VS(4355)
         const t_safe chunksize_max = chunksize_good * 2 ;
 		const bool allow_split = (m_connection_type == e_connection_type_RPC) ? false : true; // do not split RPC data
 
-        ASRT(! (chunksize_max<0) ); // make sure it is unsigned before removin sign with cast:
+        CHECK_AND_ASSERT_MES(! (chunksize_max<0), false, "Negative chunksize_max" ); // make sure it is unsigned before removin sign with cast:
         long long unsigned int chunksize_max_unsigned = static_cast<long long unsigned int>( chunksize_max ) ;
 
         if (allow_split && (cb > chunksize_max_unsigned)) {
 			{ // LOCK: chunking
     		epee::critical_region_t<decltype(m_chunking_lock)> send_guard(m_chunking_lock); // *** critical *** 
 
-				_dbg3_c("net/out/size", "do_send() will SPLIT into small chunks, from packet="<<cb<<" B for ptr="<<ptr);
+				MDEBUG("do_send() will SPLIT into small chunks, from packet="<<cb<<" B for ptr="<<ptr);
 				t_safe all = cb; // all bytes to send 
 				t_safe pos = 0; // current sending position
 				// 01234567890 
@@ -419,39 +416,39 @@ PRAGMA_WARNING_DISABLE_VS(4355)
 				while (pos < all) {
 					t_safe lenall = all-pos; // length from here to end
 					t_safe len = std::min( chunksize_good , lenall); // take a smaller part
-					ASRT(len<=chunksize_good);
+					CHECK_AND_ASSERT_MES(len<=chunksize_good, false, "len too large");
 					// pos=8; len=4; all=10;	len=3;
 
-                    ASRT(! (len<0) ); // check before we cast away sign:
+                    CHECK_AND_ASSERT_MES(! (len<0), false, "negative len"); // check before we cast away sign:
                     unsigned long long int len_unsigned = static_cast<long long int>( len );
-                    ASRT(len>0); // (redundand)
-                    ASRT(len_unsigned < std::numeric_limits<size_t>::max());   // yeap we want strong < then max size, to be sure
+                    CHECK_AND_ASSERT_MES(len>0, false, "len not strictly positive"); // (redundant)
+                    CHECK_AND_ASSERT_MES(len_unsigned < std::numeric_limits<size_t>::max(), false, "Invalid len_unsigned");   // yeap we want strong < then max size, to be sure
 					
 					void *chunk_start = ((char*)ptr) + pos;
-					_fact_c("net/out/size","chunk_start="<<chunk_start<<" ptr="<<ptr<<" pos="<<pos);
-					ASRT(chunk_start >= ptr); // not wrapped around address?
+					MDEBUG("chunk_start="<<chunk_start<<" ptr="<<ptr<<" pos="<<pos);
+					CHECK_AND_ASSERT_MES(chunk_start >= ptr, false, "Pointer wraparound"); // not wrapped around address?
 					//std::memcpy( (void*)buf, chunk_start, len);
 
-					_dbg3_c("net/out/size", "part of " << lenall << ": pos="<<pos << " len="<<len);
+					MDEBUG("part of " << lenall << ": pos="<<pos << " len="<<len);
 
 					bool ok = do_send_chunk(chunk_start, len); // <====== ***
 
 					all_ok = all_ok && ok;
 					if (!all_ok) {
-						_dbg1_c("net/out/size", "do_send() DONE ***FAILED*** from packet="<<cb<<" B for ptr="<<ptr);
-						_dbg1("do_send() SEND was aborted in middle of big package - this is mostly harmless "
+						MDEBUG("do_send() DONE ***FAILED*** from packet="<<cb<<" B for ptr="<<ptr);
+						MDEBUG("do_send() SEND was aborted in middle of big package - this is mostly harmless "
 							<< " (e.g. peer closed connection) but if it causes trouble tell us at #monero-dev. " << cb);
 						return false; // partial failure in sending
 					}
-					pos = pos+len; ASRT(pos >0);
+					pos = pos+len;
+					CHECK_AND_ASSERT_MES(pos >0, false, "pos <= 0");
 
 					// (in catch block, or uniq pointer) delete buf;
 				} // each chunk
 
-				_dbg3_c("net/out/size", "do_send() DONE SPLIT from packet="<<cb<<" B for ptr="<<ptr);
-				_dbg3  (                "do_send() DONE SPLIT from packet="<<cb<<" B for ptr="<<ptr);
+				MDEBUG("do_send() DONE SPLIT from packet="<<cb<<" B for ptr="<<ptr);
 
-                _info_c("net/sleepRPC", "do_send() m_connection_type = " << m_connection_type);
+                MDEBUG("do_send() m_connection_type = " << m_connection_type);
 
 				return all_ok; // done - e.g. queued - all the chunks of current do_send call
 			} // LOCK: chunking
@@ -505,15 +502,14 @@ PRAGMA_WARNING_DISABLE_VS(4355)
         }*/
 
         long int ms = 250 + (rand()%50);
-        _info_c("net/sleep", "Sleeping because QUEUE is FULL, in " << __FUNCTION__ << " for " << ms << " ms before packet_size="<<cb); // XXX debug sleep
+        MDEBUG("Sleeping because QUEUE is FULL, in " << __FUNCTION__ << " for " << ms << " ms before packet_size="<<cb); // XXX debug sleep
         m_send_que_lock.unlock();
         boost::this_thread::sleep(boost::posix_time::milliseconds( ms ) );
         m_send_que_lock.lock();
         _dbg1("sleep for queue: " << ms);
 
         if (retry > retry_limit) {
-            _erro("send que size is more than ABSTRACT_SERVER_SEND_QUE_MAX_COUNT(" << ABSTRACT_SERVER_SEND_QUE_MAX_COUNT << "), shutting down connection");
-            //	_dbg1_c("net/sleep", "send que size is more than ABSTRACT_SERVER_SEND_QUE_MAX_COUNT(" << ABSTRACT_SERVER_SEND_QUE_MAX_COUNT << "), shutting down connection");
+            MWARNING("send que size is more than ABSTRACT_SERVER_SEND_QUE_MAX_COUNT(" << ABSTRACT_SERVER_SEND_QUE_MAX_COUNT << "), shutting down connection");
             shutdown();
             return false;
         }
@@ -525,10 +521,10 @@ PRAGMA_WARNING_DISABLE_VS(4355)
     if(m_send_que.size() > 1)
     { // active operation should be in progress, nothing to do, just wait last operation callback
         auto size_now = cb;
-        _info_c("net/out/size", "do_send() NOW just queues: packet="<<size_now<<" B, is added to queue-size="<<m_send_que.size());
+        MDEBUG("do_send() NOW just queues: packet="<<size_now<<" B, is added to queue-size="<<m_send_que.size());
         //do_send_handler_delayed( ptr , size_now ); // (((H))) // empty function
       
-      LOG_PRINT_L4("[sock " << socket_.native_handle() << "] Async send requested " << m_send_que.front().size());
+      LOG_TRACE_CC(context, "[sock " << socket_.native_handle() << "] Async send requested " << m_send_que.front().size());
     }
     else
     { // no active operation
@@ -540,11 +536,11 @@ PRAGMA_WARNING_DISABLE_VS(4355)
         }
 
         auto size_now = m_send_que.front().size();
-        _dbg1_c("net/out/size", "do_send() NOW SENSD: packet="<<size_now<<" B");
+        MDEBUG("do_send() NOW SENSD: packet="<<size_now<<" B");
         if (speed_limit_is_enabled())
 			do_send_handler_write( ptr , size_now ); // (((H)))
 
-        ASRT( size_now == m_send_que.front().size() );
+        CHECK_AND_ASSERT_MES( size_now == m_send_que.front().size(), false, "Unexpected queue size");
         boost::asio::async_write(socket_, boost::asio::buffer(m_send_que.front().data(), size_now ) ,
                                  //strand_.wrap(
                                  boost::bind(&connection<t_protocol_handler>::handle_write, self, _1, _2)
@@ -602,7 +598,7 @@ PRAGMA_WARNING_DISABLE_VS(4355)
   void connection<t_protocol_handler>::handle_write(const boost::system::error_code& e, size_t cb)
   {
     TRY_ENTRY();
-    LOG_PRINT_L4("[sock " << socket_.native_handle() << "] Async send calledback " << cb);
+    LOG_TRACE_CC(context, "[sock " << socket_.native_handle() << "] Async send calledback " << cb);
 
     if (e)
     {
@@ -635,10 +631,10 @@ PRAGMA_WARNING_DISABLE_VS(4355)
     {
       //have more data to send
 		auto size_now = m_send_que.front().size();
-		_dbg1_c("net/out/size", "handle_write() NOW SENDS: packet="<<size_now<<" B" <<", from  queue size="<<m_send_que.size());
+		MDEBUG("handle_write() NOW SENDS: packet="<<size_now<<" B" <<", from  queue size="<<m_send_que.size());
 		if (speed_limit_is_enabled())
 			do_send_handler_write_from_queue(e, m_send_que.front().size() , m_send_que.size()); // (((H)))
-		ASRT( size_now == m_send_que.front().size() );
+		CHECK_AND_ASSERT_MES( size_now == m_send_que.front().size(), void(), "Unexpected queue size");
 		boost::asio::async_write(socket_, boost::asio::buffer(m_send_que.front().data(), size_now) , 
         // strand_.wrap(
           boost::bind(&connection<t_protocol_handler>::handle_write, connection<t_protocol_handler>::shared_from_this(), _1, _2)
@@ -660,8 +656,7 @@ PRAGMA_WARNING_DISABLE_VS(4355)
   void connection<t_protocol_handler>::setRpcStation()
   {
     m_connection_type = e_connection_type_RPC; 
-    _fact_c("net/sleepRPC", "set m_connection_type = RPC ");
-    _info_c("net/kind", "set m_connection_type = RPC ");
+    MDEBUG("set m_connection_type = RPC ");
   }
 
 
@@ -735,7 +730,7 @@ PRAGMA_WARNING_DISABLE_VS(4355)
     acceptor_.listen();
     boost::asio::ip::tcp::endpoint binded_endpoint = acceptor_.local_endpoint();
     m_port = binded_endpoint.port();
-    _fact_c("net/RPClog", "start accept");
+    MDEBUG("start accept");
     new_connection_.reset(new connection<t_protocol_handler>(io_service_, m_config, m_sock_count, m_sock_number, m_pfilter, m_connection_type));
     acceptor_.async_accept(new_connection_->socket(),
       boost::bind(&boosted_tcp_server<t_protocol_handler>::handle_accept, this,
@@ -753,7 +748,7 @@ DISABLE_GCC_WARNING(maybe-uninitialized)
     uint32_t p = 0;
 
     if (port.size() && !string_tools::get_xtype_from_string(p, port)) {
-      LOG_ERROR("Failed to convert port no = " << port);
+      MERROR("Failed to convert port no = " << port);
       return false;
     }
     return this->init_server(p, address);
@@ -767,7 +762,7 @@ POP_WARNINGS
     uint32_t local_thr_index = boost::interprocess::ipcdetail::atomic_inc32(&m_thread_index); 
     std::string thread_name = std::string("[") + m_thread_name_prefix;
     thread_name += boost::to_string(local_thr_index) + "]";
-    log_space::log_singletone::set_thread_log_prefix(thread_name);
+    MLOG_SET_THREAD_NAME(thread_name);
     //   _fact("Thread name: " << m_thread_name_prefix);
     while(!m_stop_signal_sent)
     {
@@ -796,8 +791,7 @@ POP_WARNINGS
 		auto it = server_type_map.find(m_thread_name_prefix);
 		if (it==server_type_map.end()) throw std::runtime_error("Unknown prefix/server type:" + std::string(prefix_name));
     auto connection_type = it->second; // the value of type
-    _info_c("net/RPClog", "Set server type to: " << connection_type << " from name: " << m_thread_name_prefix);
-    _info_c("net/RPClog", "prefix_name = " << prefix_name);
+    MINFO("Set server type to: " << connection_type << " from name: " << m_thread_name_prefix << ", prefix_name = " << prefix_name);
   }
   //---------------------------------------------------------------------------------
   template<class t_protocol_handler>
@@ -812,7 +806,7 @@ POP_WARNINGS
     TRY_ENTRY();
     m_threads_count = threads_count;
     m_main_thread_id = boost::this_thread::get_id();
-    log_space::log_singletone::set_thread_log_prefix("[SRV_MAIN]");
+    MLOG_SET_THREAD_NAME("[SRV_MAIN]");
     add_idle_handler(boost::bind(&boosted_tcp_server::cleanup_connections, this), 5000);
     while(!m_stop_signal_sent)
     {
@@ -933,13 +927,12 @@ POP_WARNINGS
   template<class t_protocol_handler>
   void boosted_tcp_server<t_protocol_handler>::handle_accept(const boost::system::error_code& e)
   {
-	_fact_c("net/RPClog", "handle_accept");
+    MDEBUG("handle_accept");
     TRY_ENTRY();
     if (!e)
     {
 		if (m_connection_type == e_connection_type_RPC) {
-			_note_c("net/rpc", "New server for RPC connections");
-			_fact_c("net/RPClog", "New server for RPC connections");
+			MDEBUG("New server for RPC connections");
 			new_connection_->setRpcStation(); // hopefully this is not needed actually
 		}
 		connection_ptr conn(std::move(new_connection_));
@@ -965,7 +958,7 @@ POP_WARNINGS
     connection_ptr new_connection_l(new connection<t_protocol_handler>(io_service_, m_config, m_sock_count, m_sock_number, m_pfilter, m_connection_type) );
     connections_mutex.lock();
     connections_.push_back(std::make_pair(boost::get_system_time(), new_connection_l));
-    LOG_PRINT_L2("connections_ size now " << connections_.size());
+    MDEBUG("connections_ size now " << connections_.size());
     connections_mutex.unlock();
     boost::asio::ip::tcp::socket&  sock_ = new_connection_l->socket();
     
@@ -1069,7 +1062,7 @@ POP_WARNINGS
     connection_ptr new_connection_l(new connection<t_protocol_handler>(io_service_, m_config, m_sock_count, m_sock_number, m_pfilter, m_connection_type) );
     connections_mutex.lock();
     connections_.push_back(std::make_pair(boost::get_system_time(), new_connection_l));
-    LOG_PRINT_L2("connections_ size now " << connections_.size());
+    MDEBUG("connections_ size now " << connections_.size());
     connections_mutex.unlock();
     boost::asio::ip::tcp::socket&  sock_ = new_connection_l->socket();