Write SSU2 session creation results to file

daemon/i2pd.cpp

@@ -23,12 +23,74 @@ int main( int argc, char* argv[] )
 	return i2p::qt::RunQT (argc, argv);
 }
 #else
+
+#include <fstream>
+#include <thread>
+#include <ctime>
+#include <chrono>
+#include <mutex>
+#include <vector>
+#include <iomanip>
+
+bool timeThreadExiting = false;
+time_t lastRequestTime = 0;
+const int dumpInterval = 30;
+std::shared_ptr<std::thread> timeThread;
+
+namespace i2p
+{
+	extern std::mutex g_TcResultsMutex;
+	extern std::vector<std::string> g_TcResults;
+}
+
+void StartProfiling()
+{
+	lastRequestTime = std::time(nullptr);
+	timeThread = std::make_shared<std::thread>([] 
+	{
+		std::ofstream crstatfs;
+#ifdef _WIN32
+		crstatfs.open("tcstat.txt", std::ios::app);
+#else
+		crstatfs.open("/tmp/tcstat.txt", std::ios::app);
+#endif
+		for (;;)
+		{
+			time_t now = std::time(nullptr);
+			if (now / dumpInterval > lastRequestTime / dumpInterval)
+			{
+				lastRequestTime = now;
+				std::unique_lock<std::mutex> l(i2p::g_TcResultsMutex);
+				for (size_t i = 0; i < i2p::g_TcResults.size(); i++)
+					crstatfs << i2p::g_TcResults[i] << std::endl;
+				i2p::g_TcResults.clear();
+				crstatfs << std::flush;
+			}
+			std::this_thread::sleep_for(std::chrono::milliseconds(250));
+			if (timeThreadExiting)
+				break;
+		}
+		crstatfs.close();
+	});
+}
+
+void StopProfiling()
+{
+	timeThreadExiting = true;
+	timeThread->join();
+	timeThread = nullptr;
+}
+
 int main( int argc, char* argv[] )
 {
 	if (Daemon.init(argc, argv))
 	{
 		if (Daemon.start())
+		{
+			StartProfiling();
 			Daemon.run ();
+			StopProfiling();
+		}
 		else
 			return EXIT_FAILURE;
 		Daemon.stop();
@@ -47,6 +109,7 @@ int CALLBACK WinMain(
 	_In_ int       nCmdShow
 	)
 {
-	return main(__argc, __argv);
+	int r = main(__argc, __argv);
+	return r;
 }
 #endif

libi2pd/SSU2Session.cpp

@@ -14,8 +14,14 @@
 #include "NetDb.hpp"
 #include "SSU2.h"
 
+#include <mutex>
+#include <vector>
+
 namespace i2p
 {
+	std::mutex g_TcResultsMutex;
+	std::vector<std::string> g_TcResults;
+
 namespace transport
 {
 	void SSU2IncompleteMessage::AttachNextFragment (const uint8_t * fragment, size_t fragmentSize)
@@ -110,6 +116,18 @@ namespace transport
 	{
 	}
 
+	void LogResult(std::shared_ptr<const i2p::data::IdentityEx> id, bool outgoing, const char* result)
+	{
+		std::stringstream ss;
+		time_t now = std::time(nullptr);
+		ss << "[" << std::put_time(std::gmtime(&now), "%Y.%m.%d %H:%M:%S") << "]: ";
+		ss << (outgoing ? 'O' : 'I') << ' ';
+		ss << result << ' ';
+		ss << id->GetIdentHash().ToBase64();
+		std::unique_lock<std::mutex> l(i2p::g_TcResultsMutex);
+		g_TcResults.push_back(ss.str());
+	}
+
 	void SSU2Session::Connect ()
 	{
 		if (m_State == eSSU2SessionStateUnknown || m_State == eSSU2SessionStateTokenReceived)
@@ -140,9 +158,15 @@ namespace transport
 		{
 			// timeout expired
 			if (m_State == eSSU2SessionStateIntroduced) // WaitForIntroducer
-				LogPrint (eLogWarning, "SSU2: Session was not introduced after ", SSU2_CONNECT_TIMEOUT, " seconds");
+			{
+				LogResult(GetRemoteIdentity(), IsOutgoing(), "TI");
+				LogPrint(eLogWarning, "SSU2: Session was not introduced after ", SSU2_CONNECT_TIMEOUT, " seconds");
+			}
 			else
-				LogPrint (eLogWarning, "SSU2: Session with ", m_RemoteEndpoint, " was not established after ", SSU2_CONNECT_TIMEOUT, " seconds");
+			{
+				LogResult(GetRemoteIdentity(), IsOutgoing(), "T");
+				LogPrint(eLogWarning, "SSU2: Session with ", m_RemoteEndpoint, " was not established after ", SSU2_CONNECT_TIMEOUT, " seconds");
+			}
 			Terminate ();
 		}
 	}
@@ -285,6 +309,7 @@ namespace transport
 
 	void SSU2Session::Established ()
 	{
+		LogResult(GetRemoteIdentity(), IsOutgoing(), "E");
 		m_State = eSSU2SessionStateEstablished;
 		m_EphemeralKeys = nullptr;
 		m_NoiseState.reset (nullptr);