2014 network limit 1.2 +utils +toc -doc -drmonero

new update of the pr with network limits

more debug options:
discarding downloaded blocks all or after given height.
trying to trigger the locking errors.

debug levels polished/tuned to sane values.
debug/logging improved.

warning: this pr should be correct code, but it could make
an existing (in master version) locking error appear more often.

it's a race on the list (map) of peers, e.g. between closing/deleting
them versus working on them in net-limit sleep in sending chunk.

the bug is not in this code/this pr, but in the master version.

the locking problem of master will be fixed in other pr.

problem is ub, and in practice is seems to usually cause program abort
(tested on debian stable with updated gcc). see --help for option
to add sleep to trigger the error faster.

5 files changed, 82 insertions, 26 deletions

diff --git a/contrib/epee/include/net/abstract_tcp_server2.inl b/contrib/epee/include/net/abstract_tcp_server2.inl
index 3dff6da56..31836fe9e 100644
--- a/contrib/epee/include/net/abstract_tcp_server2.inl
+++ b/contrib/epee/include/net/abstract_tcp_server2.inl
@@ -198,8 +198,9 @@ PRAGMA_WARNING_DISABLE_VS(4355)
   bool connection<t_protocol_handler>::add_ref()
   {
     TRY_ENTRY();
-    //_info("[sock " << socket_.native_handle() << "] add_ref");
+    //_dbg3("[sock " << socket_.native_handle() << "] add_ref, m_peer_number=" << mI->m_peer_number);
     CRITICAL_REGION_LOCAL(m_self_refs_lock);
+    //_dbg3("[sock " << socket_.native_handle() << "] add_ref 2, m_peer_number=" << mI->m_peer_number);
 
     // Use safe_shared_from_this, because of this is public method and it can be called on the object being deleted
     auto self = safe_shared_from_this();
@@ -364,8 +365,7 @@ PRAGMA_WARNING_DISABLE_VS(4355)
 			{ // LOCK: chunking
     		epee::critical_region_t<decltype(m_chunking_lock)> send_guard(m_chunking_lock); // *** critical *** 
 
-				_mark_c("net/out/size", "do_send() will SPLIT into small chunks, from packet="<<cb<<" B for ptr="<<ptr);
-				_mark("do_send() will SPLIT into small chunks, from packet="<<cb<<" B for ptr="<<ptr);
+				_dbg3_c("net/out/size", "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 
@@ -393,14 +393,13 @@ PRAGMA_WARNING_DISABLE_VS(4355)
 					ASRT(chunk_start >= ptr); // not wrapped around address?
 					//std::memcpy( (void*)buf, chunk_start, len);
 
-					_dbg1_c("net/out/size", "part of " << lenall << ": pos="<<pos << " len="<<len);
+					_dbg3_c("net/out/size", "part of " << lenall << ": pos="<<pos << " len="<<len);
 
 					bool ok = do_send_chunk(chunk_start, len); // <====== ***
 
 					all_ok = all_ok && ok;
 					if (!all_ok) {
-						_mark_c("net/out/size", "do_send() DONE ***FAILED*** from packet="<<cb<<" B for ptr="<<ptr);
-						_mark  (                "do_send() DONE ***FAILED*** from packet="<<cb<<" B for ptr="<<ptr);
+						_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 "
 							<< " (e.g. peer closed connection) but if it causes trouble tell us at #monero-dev. " << cb);
 						return false; // partial failure in sending
@@ -410,8 +409,8 @@ PRAGMA_WARNING_DISABLE_VS(4355)
 					// (in catch block, or uniq pointer) delete buf;
 				} // each chunk
 
-				_mark_c("net/out/size", "do_send() DONE SPLIT from packet="<<cb<<" B for ptr="<<ptr);
-				_mark  (                "do_send() DONE SPLIT from packet="<<cb<<" B for ptr="<<ptr);
+				_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);
 
                 _info_c("net/sleepRPC", "do_send() m_connection_type = " << m_connection_type);
 
@@ -469,7 +468,7 @@ PRAGMA_WARNING_DISABLE_VS(4355)
         if (retry > retry_limit) {
             send_guard.unlock();
             _erro("send que size is more than ABSTRACT_SERVER_SEND_QUE_MAX_COUNT(" << ABSTRACT_SERVER_SEND_QUE_MAX_COUNT << "), shutting down connection");
-            //	_mark_c("net/sleep", "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");
             close();
             return false;
         }
@@ -496,7 +495,7 @@ PRAGMA_WARNING_DISABLE_VS(4355)
         }
 
         auto size_now = m_send_que.front().size();
-        _mark_c("net/out/size", "do_send() NOW SENSD: packet="<<size_now<<" B");
+        _dbg1_c("net/out/size", "do_send() NOW SENSD: packet="<<size_now<<" B");
         do_send_handler_write( ptr , size_now ); // (((H)))
 
         ASRT( size_now == m_send_que.front().size() );
@@ -580,7 +579,7 @@ PRAGMA_WARNING_DISABLE_VS(4355)
     {
       //have more data to send
 		auto size_now = m_send_que.front().size();
-		_mark_c("net/out/size", "handle_write() NOW SENDS: packet="<<size_now<<" B" <<", from  queue size="<<m_send_que.size());
+		_dbg1_c("net/out/size", "handle_write() NOW SENDS: packet="<<size_now<<" B" <<", from  queue size="<<m_send_que.size());
 		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() );
 		boost::asio::async_write(socket_, boost::asio::buffer(m_send_que.front().data(), size_now) , 
diff --git a/contrib/epee/include/syncobj.h b/contrib/epee/include/syncobj.h
index b7273da8e..b81eb43a9 100644
--- a/contrib/epee/include/syncobj.h
+++ b/contrib/epee/include/syncobj.h
@@ -35,10 +35,14 @@
 #include <boost/thread/locks.hpp>
 #include <boost/thread/mutex.hpp>
 #include <boost/thread/recursive_mutex.hpp>
+#include <thread>
+#include <chrono>
 
 namespace epee
 {
 
+  extern unsigned int g_test_dbg_lock_sleep;
+  
   struct simple_event
   {
     simple_event() : m_rised(false)
@@ -215,10 +219,10 @@ namespace epee
 #define  SHARED_CRITICAL_REGION_BEGIN(x) { shared_guard   critical_region_var(x)
 #define  EXCLUSIVE_CRITICAL_REGION_BEGIN(x) { exclusive_guard   critical_region_var(x)
 
-#define  CRITICAL_REGION_LOCAL(x) epee::critical_region_t<decltype(x)>   critical_region_var(x)
-#define  CRITICAL_REGION_BEGIN(x) { epee::critical_region_t<decltype(x)>   critical_region_var(x)
-#define  CRITICAL_REGION_LOCAL1(x) epee::critical_region_t<decltype(x)>   critical_region_var1(x)
-#define  CRITICAL_REGION_BEGIN1(x) { epee::critical_region_t<decltype(x)>   critical_region_var1(x)
+#define  CRITICAL_REGION_LOCAL(x) {std::this_thread::sleep_for(std::chrono::milliseconds(epee::g_test_dbg_lock_sleep));}   epee::critical_region_t<decltype(x)>   critical_region_var(x)
+#define  CRITICAL_REGION_BEGIN(x) { std::this_thread::sleep_for(std::chrono::milliseconds(epee::g_test_dbg_lock_sleep)); epee::critical_region_t<decltype(x)>   critical_region_var(x)
+#define  CRITICAL_REGION_LOCAL1(x) {std::this_thread::sleep_for(std::chrono::milliseconds(epee::g_test_dbg_lock_sleep));} epee::critical_region_t<decltype(x)>   critical_region_var1(x)
+#define  CRITICAL_REGION_BEGIN1(x) {  std::this_thread::sleep_for(std::chrono::milliseconds(epee::g_test_dbg_lock_sleep)); epee::critical_region_t<decltype(x)>   critical_region_var1(x)
 
 #define  CRITICAL_REGION_END() }
 
diff --git a/contrib/otshell_utils/lib_common1.hpp b/contrib/otshell_utils/lib_common1.hpp
index 108b1847c..456e63fbb 100644
--- a/contrib/otshell_utils/lib_common1.hpp
+++ b/contrib/otshell_utils/lib_common1.hpp
@@ -20,6 +20,7 @@
 #include <functional>
 #include <memory>
 #include <thread>
+#include <atomic>
 #include <mutex>
 
 
diff --git a/contrib/otshell_utils/utils.cpp b/contrib/otshell_utils/utils.cpp
index 1d26075c4..043260807 100644
--- a/contrib/otshell_utils/utils.cpp
+++ b/contrib/otshell_utils/utils.cpp
@@ -112,7 +112,22 @@ std::string get_current_time() {
 
 cNullstream g_nullstream; // extern a stream that does nothing (eats/discards data)
 
-std::mutex gLoggerGuard; // extern
+std::recursive_mutex gLoggerGuard; // extern
+std::atomic<int> gLoggerGuardDepth; // extern
+
+std::atomic<int> & gLoggerGuardDepth_Get() {
+	// TODO std::once would be nicer here
+
+	static bool once=0;
+
+	if (!once) { // initialize it once
+		once=1;
+		gLoggerGuardDepth=0;	
+	}
+
+	return gLoggerGuardDepth; // global, atomic counter
+}
+
 
 // ====================================================================
 
diff --git a/contrib/otshell_utils/utils.hpp b/contrib/otshell_utils/utils.hpp
index bb984320b..83e6b822d 100644
--- a/contrib/otshell_utils/utils.hpp
+++ b/contrib/otshell_utils/utils.hpp
@@ -65,18 +65,55 @@ extern cNullstream g_nullstream; // a stream that does nothing (eats/discards da
 
 // TODO make _dbg_ignore thread-safe everywhere
 
-extern std::mutex gLoggerGuard;
-
-
+extern std::recursive_mutex gLoggerGuard; // the mutex guarding logging/debugging code e.g. protecting streams, files, etc
+
+std::atomic<int> & gLoggerGuardDepth_Get(); // getter for the global singleton of counter (it guarantees initializing it to 0). This counter shows the current recursion (re-entrant) level of debug macros.
+
+// TODO more debug of the debug system:
+// detect lock() error e.g. recursive limit
+// detect stream e.g. operator<< error
+
+#define _debug_level(LEVEL,VAR) do { if (_dbg_ignore< LEVEL) { \
+	auto level=LEVEL; short int part=0; \
+	try { \
+		std::lock_guard<std::recursive_mutex> mutex_guard( nOT::nUtils::gLoggerGuard ); \
+		part=1; \
+		try { \
+			++nOT::nUtils::gLoggerGuardDepth_Get(); \
+/* int counter = nOT::nUtils::gLoggerGuardDepth_Get();  if (counter!=1) gCurrentLogger.write_stream(100,"")<<"DEBUG-ERROR: recursion, counter="<<counter<<gCurrentLogger.endline(); */ \
+			gCurrentLogger.write_stream(LEVEL,"") << nOT::nUtils::get_current_time() << ' ' << OT_CODE_STAMP << ' ' << VAR << gCurrentLogger.endline() << std::flush; \
+			part=9; \
+		} catch(...) { \
+			gCurrentLogger.write_stream(std::max(level,90),"") << nOT::nUtils::get_current_time() << ' ' << OT_CODE_STAMP << ' ' << "(ERROR IN DEBUG)" << gCurrentLogger.endline(); \
+			--nOT::nUtils::gLoggerGuardDepth_Get(); throw ; \
+		} \
+		--nOT::nUtils::gLoggerGuardDepth_Get(); \
+	} catch(...) { if (part<8) gCurrentLogger.write_stream(100,"")<<"DEBUG-ERROR: problem in debug mechanism e.g. in locking." <<gCurrentLogger.endline();   throw ; } \
+	} } while(0)
 
+// info for code below: oss object is normal stack variable, using it does not need lock protection
 #define _debug_level_c(CHANNEL,LEVEL,VAR) do { if (_dbg_ignore< LEVEL) { \
-	nOT::nUtils::gLoggerGuard.try_lock(); \
-	gCurrentLogger.write_stream(LEVEL,CHANNEL) << nOT::nUtils::get_current_time() << ' ' << OT_CODE_STAMP << ' ' << VAR << gCurrentLogger.endline() << std::flush; \
-	nOT::nUtils::gLoggerGuard.unlock(); \
+	auto level=LEVEL; short int part=0; \
+	try { \
+		std::lock_guard<std::recursive_mutex> mutex_guard( nOT::nUtils::gLoggerGuard ); \
+		part=1; \
+		try { \
+			++nOT::nUtils::gLoggerGuardDepth_Get(); \
+			std::ostringstream oss; \
+			oss << nOT::nUtils::get_current_time() << ' ' << OT_CODE_STAMP << ' ' << VAR << gCurrentLogger.endline() << std::flush; \
+			std::string as_string = oss.str(); \
+/* int counter = nOT::nUtils::gLoggerGuardDepth_Get();  if (counter!=1) gCurrentLogger.write_stream(100,"")<<"DEBUG-ERROR: recursion, counter="<<counter<<gCurrentLogger.endline(); */ \
+			gCurrentLogger.write_stream(LEVEL,""     ) << as_string << gCurrentLogger.endline() << std::flush; \
+			gCurrentLogger.write_stream(LEVEL,CHANNEL) << as_string << gCurrentLogger.endline() << std::flush; \
+			part=9; \
+		} catch(...) { \
+			gCurrentLogger.write_stream(std::max(level,90),CHANNEL) << nOT::nUtils::get_current_time() << ' ' << OT_CODE_STAMP << ' ' << "(ERROR IN DEBUG)" << gCurrentLogger.endline(); \
+			--nOT::nUtils::gLoggerGuardDepth_Get(); throw ; \
+		} \
+		--nOT::nUtils::gLoggerGuardDepth_Get(); \
+	} catch(...) { if (part<8) gCurrentLogger.write_stream(100,CHANNEL)<<"DEBUG-ERROR: problem in debug mechanism e.g. in locking." <<gCurrentLogger.endline();   throw ; } \
 	} } while(0)
 
-#define _debug_level(LEVEL,VAR) _debug_level_c("",LEVEL,VAR)
-
 #define _dbg3(VAR) _debug_level( 20,VAR)
 #define _dbg2(VAR) _debug_level( 30,VAR)
 #define _dbg1(VAR) _debug_level( 40,VAR) // details
@@ -98,10 +135,10 @@ extern std::mutex gLoggerGuard;
 #define _warn_c(C,VAR) _debug_level_c(C, 90,VAR) // some problem
 #define _erro_c(C,VAR) _debug_level_c(C,100,VAR) // error - report
 
-// lock // because od VAR
+// lock // because of VAR
 #define _scope_debug_level_c(CHANNEL,LEVEL,VAR) \
 	std::ostringstream debug_detail_oss; \
-	nOT::nUtils::gLoggerGuard.try_lock(); \
+	nOT::nUtils::gLoggerGuard.lock(); \
 	debug_detail_oss << OT_CODE_STAMP << ' ' << VAR ; \
 	nOT::nUtils::nDetail::cDebugScopeGuard debugScopeGuard; \
 	if (_dbg_ignore<LEVEL) debugScopeGuard.Assign(CHANNEL,LEVEL, debug_detail_oss.str()); \