debug logging fixes

include/libtorrent/debug.hpp

@@ -33,6 +33,8 @@ POSSIBILITY OF SUCH DAMAGE.
 #ifndef TORRENT_DEBUG_HPP_INCLUDED
 #define TORRENT_DEBUG_HPP_INCLUDED
 
+#if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_LOGGING || defined TORRENT_ERROR_LOGGING
+
 #include <string>
 #include "libtorrent/config.hpp"
 #include "libtorrent/file.hpp"
@@ -47,16 +49,17 @@ namespace libtorrent
 {
 	// DEBUG API
 	
-#if TORRENT_USE_IOSTREAM
-	// all log streams share a single file descriptor
-	// and re-opens the file for each log line
-	static std::ofstream log_file;
-	static std::string open_filename;
-	static mutex file_mutex;
-#endif
-
 	struct logger
 	{
+#if TORRENT_USE_IOSTREAM
+		// all log streams share a single file descriptor
+		// and re-opens the file for each log line
+		// these members are defined in session_impl.cpp
+		static std::ofstream log_file;
+		static std::string open_filename;
+		static mutex file_mutex;
+#endif
+
 		logger(std::string const& logpath, std::string const& filename
 			, int instance, bool append)
 		{
@@ -102,5 +105,6 @@ namespace libtorrent
 
 }
 
+#endif // TORRENT_VERBOSE_LOGGING || TORRENT_LOGGING || TORRENT_ERROR_LOGGING
 #endif // TORRENT_DEBUG_HPP_INCLUDED
 

src/bt_peer_connection.cpp

@@ -116,7 +116,7 @@ namespace libtorrent
 #endif
 	{
 #ifdef TORRENT_VERBOSE_LOGGING
-		(*m_logger) << "*** bt_peer_connection\n";
+		(*m_logger) << time_now_string() << "*** bt_peer_connection\n";
 #endif
 
 #ifdef TORRENT_DEBUG
@@ -1499,13 +1499,13 @@ namespace libtorrent
 		if (root.type() != lazy_entry::dict_t)
 		{
 #ifdef TORRENT_VERBOSE_LOGGING
-			(*m_logger) << "invalid extended handshake\n";
+			(*m_logger) << time_now_string() << " invalid extended handshake\n";
 #endif
 			return;
 		}
 
 #ifdef TORRENT_VERBOSE_LOGGING
-		(*m_logger) << "<== EXTENDED HANDSHAKE: \n" << root;
+		(*m_logger) << time_now_string() << " <== EXTENDED HANDSHAKE: \n" << root;
 #endif
 
 #ifndef TORRENT_DISABLE_EXTENSIONS
@@ -1937,7 +1937,7 @@ namespace libtorrent
 #if defined TORRENT_VERBOSE_LOGGING && TORRENT_USE_IOSTREAM
 		std::stringstream ext;
 		handshake.print(ext);
-		(*m_logger) << "==> EXTENDED HANDSHAKE: \n" << ext.str();
+		(*m_logger) << time_now_string() << " ==> EXTENDED HANDSHAKE: \n" << ext.str();
 #endif
 
 		setup_send();
@@ -2144,7 +2144,7 @@ namespace libtorrent
 			}
 
 #ifdef TORRENT_VERBOSE_LOGGING
-			(*m_logger) << " received DH key\n";
+			(*m_logger) << time_now_string() << " received DH key\n";
 #endif
 						
 			// PadA/B can be a max of 512 bytes, and 20 bytes more for
@@ -2245,7 +2245,7 @@ namespace libtorrent
 			{
 				std::size_t bytes_processed = syncoffset + 20;
 #ifdef TORRENT_VERBOSE_LOGGING
-				(*m_logger) << " sync point (hash) found at offset " 
+				(*m_logger) << time_now_string << " sync point (hash) found at offset " 
 					<< m_sync_bytes_read + bytes_processed - 20 << "\n";
 #endif
 				m_state = read_pe_skey_vc;
@@ -2296,7 +2296,7 @@ namespace libtorrent
 
 					init_pe_RC4_handler(m_dh_key_exchange->get_secret(), ti.info_hash());
 #ifdef TORRENT_VERBOSE_LOGGING
-					(*m_logger) << " stream key found, torrent located.\n";
+					(*m_logger) << time_now_string() << " stream key found, torrent located.\n";
 #endif
 					break;
 				}
@@ -2321,7 +2321,7 @@ namespace libtorrent
 			}
 
 #ifdef TORRENT_VERBOSE_LOGGING
-			(*m_logger) << " verification constant found\n";
+			(*m_logger) << time_now_string() << " verification constant found\n";
 #endif
 			m_state = read_pe_cryptofield;
 			reset_recv_buffer(4 + 2);
@@ -2385,7 +2385,7 @@ namespace libtorrent
 			{
 				std::size_t bytes_processed = syncoffset + 8;
 #ifdef TORRENT_VERBOSE_LOGGING
-				(*m_logger) << " sync point (verification constant) found at offset " 
+				(*m_logger) << time_now_string() << " sync point (verification constant) found at offset " 
 							<< m_sync_bytes_read + bytes_processed - 8 << "\n";
 #endif
 				int transferred_used = bytes_processed - recv_buffer.left() + bytes_transferred;
@@ -2421,9 +2421,9 @@ namespace libtorrent
 
 #ifdef TORRENT_VERBOSE_LOGGING
 			if (!is_local())
-				(*m_logger) << " crypto provide : [ ";
+				(*m_logger) << time_now_string() << " crypto provide : [ ";
 			else
-				(*m_logger) << " crypto select : [ ";
+				(*m_logger) << time_now_string() << " crypto select : [ ";
 
 			if (crypto_field & 0x01)
 				(*m_logger) << "plaintext ";
@@ -2558,7 +2558,7 @@ namespace libtorrent
 				}
 
 #ifdef TORRENT_VERBOSE_LOGGING
-				(*m_logger) << " len(IA) : " << len_ia << "\n";
+				(*m_logger) << time_now_string() << " len(IA) : " << len_ia << "\n";
 #endif
 				if (len_ia == 0)
 				{
@@ -2594,14 +2594,14 @@ namespace libtorrent
 			m_RC4_handler->decrypt(wr_buf.begin, packet_size());
 
 #ifdef TORRENT_VERBOSE_LOGGING
-			(*m_logger) << " decrypted ia : " << packet_size() << " bytes\n";
+			(*m_logger) << time_now_string() << " decrypted ia : " << packet_size() << " bytes\n";
 #endif
 
 			if (!m_rc4_encrypted)
 			{
 				m_RC4_handler.reset();
 #ifdef TORRENT_VERBOSE_LOGGING
-				(*m_logger) << " destroyed rc4 keys\n";
+				(*m_logger) << time_now_string() << " destroyed rc4 keys\n";
 #endif
 			}
 
@@ -2625,14 +2625,14 @@ namespace libtorrent
 				wr_buf.begin += packet_size();
 				m_RC4_handler->decrypt(wr_buf.begin, wr_buf.left());
 #ifdef TORRENT_VERBOSE_LOGGING
-				(*m_logger) << " decrypted remaining " << wr_buf.left() << " bytes\n";
+				(*m_logger) << time_now_string() << " decrypted remaining " << wr_buf.left() << " bytes\n";
 #endif
 			}
 			else // !m_rc4_encrypted
 			{
 				m_RC4_handler.reset();
 #ifdef TORRENT_VERBOSE_LOGGING
-				(*m_logger) << " destroyed rc4 keys\n";
+				(*m_logger) << time_now_string() << " destroyed rc4 keys\n";
 #endif
 			}
 
@@ -2681,7 +2681,7 @@ namespace libtorrent
 				if (!m_encrypted && !is_local())
 				{
 #ifdef TORRENT_VERBOSE_LOGGING
- 					(*m_logger) << " attempting encrypted connection\n";
+ 					(*m_logger) << time_now_string() << " attempting encrypted connection\n";
 #endif
  					m_state = read_pe_dhkey;
 					cut_receive_buffer(0, dh_key_len);
@@ -2708,7 +2708,7 @@ namespace libtorrent
 #endif
 
 #ifdef TORRENT_VERBOSE_LOGGING
-			(*m_logger) << " BitTorrent protocol\n";
+			(*m_logger) << time_now_string() << " BitTorrent protocol\n";
 #endif
 
 			m_state = read_info_hash;
@@ -2737,11 +2737,11 @@ namespace libtorrent
 			}
 			(*m_logger) << "\n";
 			if (recv_buffer[7] & 0x01)
-				(*m_logger) << "supports DHT port message\n";
+				(*m_logger) << "    supports DHT port message\n";
 			if (recv_buffer[7] & 0x04)
-				(*m_logger) << "supports FAST extensions\n";
+				(*m_logger) << "    supports FAST extensions\n";
 			if (recv_buffer[5] & 0x10)
-				(*m_logger) << "supports extensions protocol\n";
+				(*m_logger) << "    supports extensions protocol\n";
 #endif
 
 #ifndef DISABLE_EXTENSIONS
@@ -2775,14 +2775,14 @@ namespace libtorrent
 					, (const char*)t->torrent_file().info_hash().begin()))
 				{
 #ifdef TORRENT_VERBOSE_LOGGING
-					(*m_logger) << " received invalid info_hash\n";
+					(*m_logger) << time_now_string() << " received invalid info_hash\n";
 #endif
 					disconnect(errors::invalid_info_hash, 2);
 					return;
 				}
 
 #ifdef TORRENT_VERBOSE_LOGGING
-				(*m_logger) << " info_hash received\n";
+				(*m_logger) << time_now_string() << " info_hash received\n";
 #endif
 			}
 

src/peer_connection.cpp

@@ -191,7 +191,7 @@ namespace libtorrent
 		error_code ec;
 		m_logger = m_ses.create_log(m_remote.address().to_string(ec) + "_"
 			+ to_string(m_remote.port()).elems, m_ses.listen_port());
-		(*m_logger) << "*** OUTGOING CONNECTION\n";
+		(*m_logger) << time_now_string() << " *** OUTGOING CONNECTION\n";
 #endif
 #ifdef TORRENT_DEBUG
 		piece_failed = false;
@@ -327,7 +327,7 @@ namespace libtorrent
 		TORRENT_ASSERT(m_socket->remote_endpoint(ec) == m_remote || ec);
 		m_logger = m_ses.create_log(remote().address().to_string(ec) + "_"
 			+ to_string(remote().port()).elems, m_ses.listen_port());
-		(*m_logger) << "*** INCOMING CONNECTION\n";
+		(*m_logger) << time_now_string() << " *** INCOMING CONNECTION\n";
 #endif
 		
 #ifndef TORRENT_DISABLE_GEO_IP
@@ -744,7 +744,7 @@ namespace libtorrent
 		if (m_num_pieces == int(m_have_piece.size()))
 		{
 #ifdef TORRENT_VERBOSE_LOGGING
-			(*m_logger) << " *** THIS IS A SEED ***\n";
+			(*m_logger) << time_now_string() << " *** THIS IS A SEED ***\n";
 #endif
 			// if this is a web seed. we don't have a peer_info struct
 			t->get_policy().set_seed(m_peer_info, true);
@@ -1057,7 +1057,7 @@ namespace libtorrent
 		if (t && t->is_aborted())
 		{
 #if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_ERROR_LOGGING
-			(*m_logger) << " *** the torrent has been aborted\n";
+			(*m_logger) << time_now_string() << " *** the torrent has been aborted\n";
 #endif
 			t.reset();
 		}
@@ -1066,7 +1066,8 @@ namespace libtorrent
 		{
 			// we couldn't find the torrent!
 #if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_ERROR_LOGGING
-			(*m_logger) << " *** couldn't find a torrent with the given info_hash: " << ih << "\n";
+			(*m_logger) << time_now_string()
+				<< " *** couldn't find a torrent with the given info_hash: " << ih << "\n";
 			(*m_logger) << " torrents:\n";
 			session_impl::torrent_map const& torrents = m_ses.m_torrents;
 			for (session_impl::torrent_map::const_iterator i = torrents.begin()
@@ -1089,7 +1090,7 @@ namespace libtorrent
 			// torrents that have errors should always reject
 			// incoming peers
 #if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_ERROR_LOGGING
-			(*m_logger) << " rejected connection to paused torrent\n";
+			(*m_logger) << time_now_string() << " rejected connection to paused torrent\n";
 #endif
 			disconnect(errors::torrent_paused, 2);
 			return;
@@ -1102,7 +1103,7 @@ namespace libtorrent
 			// the torrent is an i2p torrent, the peer is a regular peer
 			// and we don't allow mixed mode. Disconnect the peer.
 #if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_ERROR_LOGGING
-			(*m_logger) << " rejected regular connection to i2p torrent\n";
+			(*m_logger) << time_now_string() << " rejected regular connection to i2p torrent\n";
 #endif
 			disconnect(errors::peer_banned, 2);
 			return;
@@ -1726,7 +1727,7 @@ namespace libtorrent
 		if (num_pieces == int(m_have_piece.size()))
 		{
 #ifdef TORRENT_VERBOSE_LOGGING
-			(*m_logger) << " *** THIS IS A SEED ***\n";
+			(*m_logger) << time_now_string() << " *** THIS IS A SEED ***\n";
 #endif
 			// if this is a web seed. we don't have a peer_info struct
 			t->get_policy().set_seed(m_peer_info, true);
@@ -2059,7 +2060,7 @@ namespace libtorrent
 						, m_peer_id, b.block_index, b.piece_index));
 				}
 #if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_ERROR_LOGGING
-				(*m_logger) << " *** The block we just got was not in the "
+				(*m_logger) << "          *** The block we just got was not in the "
 					"request queue ***\n";
 #endif
 			}
@@ -2226,7 +2227,7 @@ namespace libtorrent
 					, m_peer_id, block_finished.block_index, block_finished.piece_index));
 			}
 #if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_ERROR_LOGGING
-			(*m_logger) << " *** The block we just got was not in the "
+			(*m_logger) << "        *** The block we just got was not in the "
 				"request queue ***\n";
 #endif
 #ifdef TORRENT_DEBUG
@@ -4571,7 +4572,7 @@ namespace libtorrent
 		do
 		{
 #ifdef TORRENT_VERBOSE_LOGGING
-			(*m_logger) << "read " << bytes_transferred << " bytes\n";
+			(*m_logger) << time_now_string() << " <<< read " << bytes_transferred << " bytes\n";
 #endif
 			// correct the dl quota usage, if not all of the buffer was actually read
 			TORRENT_ASSERT(int(bytes_transferred) <= m_quota[download_channel]);
@@ -4900,7 +4901,7 @@ namespace libtorrent
 		m_statistics.trancieve_ip_packet(bytes_transferred, m_remote.address().is_v6());
 
 #ifdef TORRENT_VERBOSE_LOGGING
-		(*m_logger) << "wrote " << bytes_transferred << " bytes\n";
+		(*m_logger) << time_now_string() << " >>> wrote " << bytes_transferred << " bytes\n";
 #endif
 
 		if (error)

src/session_impl.cpp

@@ -50,18 +50,6 @@ POSSIBILITY OF SUCH DAMAGE.
 #pragma warning(pop)
 #endif
 
-// for logging the size of DHT structures
-#if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_LOGGING || defined TORRENT_ERROR_LOGGING
-#ifndef TORRENT_DISABLE_DHT
-
-#include <libtorrent/kademlia/find_data.hpp>
-#include <libtorrent/kademlia/refresh.hpp>
-#include <libtorrent/kademlia/node.hpp>
-#include <libtorrent/kademlia/observer.hpp>
-
-#endif
-#endif
-
 #include "libtorrent/peer_id.hpp"
 #include "libtorrent/torrent_info.hpp"
 #include "libtorrent/tracker_manager.hpp"
@@ -92,6 +80,28 @@ POSSIBILITY OF SUCH DAMAGE.
 #include <sys/resource.h>
 #endif
 
+#if defined TORRENT_VERBOSE_LOGGING || defined TORRENT_LOGGING || defined TORRENT_ERROR_LOGGING
+
+// for logging the size of DHT structures
+#ifndef TORRENT_DISABLE_DHT
+#include <libtorrent/kademlia/find_data.hpp>
+#include <libtorrent/kademlia/refresh.hpp>
+#include <libtorrent/kademlia/node.hpp>
+#include <libtorrent/kademlia/observer.hpp>
+#endif // TORRENT_DISABLE_DHT
+
+#include "libtorrent/debug.hpp"
+
+#if TORRENT_USE_IOSTREAM
+namespace libtorrent {
+std::ofstream logger::log_file;
+std::string logger::open_filename;
+mutex logger::file_mutex;
+}
+#endif // TORRENT_USE_IOSTREAM
+
+#endif
+
 #ifdef TORRENT_USE_GCRYPT
 
 extern "C" {