More verbose logging for the server.

src/core/common/loghelper_client.cpp

@@ -27,21 +27,33 @@
 
 using namespace std;
 
+
+static int g_logLevel = 1;
+
 void
-loghelper_init(const std::string & /*logDir*/)
+loghelper_init(const std::string & /*logDir*/, int logLevel)
 {
 	// Do not log to file as client.
+	g_logLevel = logLevel;
 }
 
 void
 internal_log_err(const string &msg)
 {
-	cout << msg;
+	cerr << msg;
 }
 
 void
 internal_log_msg(const std::string &msg)
 {
-	cout << msg;
+	if (g_logLevel)
+		cout << msg;
+}
+
+void
+internal_log_level(const std::string &msg, int logLevel)
+{
+	if (g_logLevel >= logLevel)
+		cout << msg;
 }
 

src/core/common/loghelper_server.cpp

@@ -39,14 +39,16 @@ using namespace boost::posix_time;
 #define SERVER_MSG_LOG_FILE_NAME				"server_messages.log"
 
 static string g_logFile;
+static int g_logLevel = 1;
 
 void
-loghelper_init(const string &logDir)
+loghelper_init(const string &logDir, int logLevel)
 {
 	path tmpLogFile(logDir);
 	tmpLogFile /= SERVER_MSG_LOG_FILE_NAME;
 
 	g_logFile = tmpLogFile.directory_string();
+	g_logLevel = logLevel;
 }
 
 void
@@ -63,11 +65,28 @@ internal_log_err(const string &msg)
 void
 internal_log_msg(const std::string &msg)
 {
-	if (!g_logFile.empty())
+	if (g_logLevel)
 	{
-		ofstream o(g_logFile.c_str(), ios_base::out | ios_base::app);
+		if (!g_logFile.empty())
-		if (!o.fail())
+		{
-			o << second_clock::local_time() << " MSG: " << msg;
+			ofstream o(g_logFile.c_str(), ios_base::out | ios_base::app);
+			if (!o.fail())
+				o << second_clock::local_time() << " MSG: " << msg;
+		}
+	}
+}
+
+void
+internal_log_level(const std::string &msg, int logLevel)
+{
+	if (g_logLevel >= logLevel)
+	{
+		if (!g_logFile.empty())
+		{
+			ofstream o(g_logFile.c_str(), ios_base::out | ios_base::app);
+			if (!o.fail())
+				o << second_clock::local_time() << " OUT: " << msg;
+		}
 	}
 }
 

src/core/loghelper.h

@@ -24,10 +24,11 @@
 #include <string>
 #include <sstream>
 
-void loghelper_init(const std::string &logDir);
+void loghelper_init(const std::string &logDir, int logLevel);
 
 void internal_log_err(const std::string &msg);
 void internal_log_msg(const std::string &msg);
+void internal_log_level(const std::string &msg, int logLevel);
 
 #define LOG_ERROR(e) \
 	do \
@@ -45,6 +46,14 @@ void internal_log_msg(const std::string &msg);
 		internal_log_msg(outStream.str()); \
 	} \
 	while(false)
+#define LOG_VERBOSE(e) \
+	do \
+	{ \
+		std::ostringstream outStream; \
+		outStream << e << std::endl; \
+		internal_log_level(outStream.str(), 2); \
+	} \
+	while(false)
 
 #endif
 

src/net/common/servergamethread.cpp

@@ -41,11 +41,14 @@ ServerGameThread::ServerGameThread(ServerLobbyThread &lobbyThread, u_int32_t id,
   m_stateTimer(boost::posix_time::time_duration(0, 0, 0), boost::timers::portable::microsec_timer::manual_start),
   m_stateTimerFlag(0)
 {
+	LOG_VERBOSE("Game object " << GetId() << " created.");
+
 	m_receiver.reset(new ReceiverHelper);
 }
 
 ServerGameThread::~ServerGameThread()
 {
+	LOG_VERBOSE("Game object " << GetId() << " destructed.");
 }
 
 u_int32_t
@@ -106,6 +109,8 @@ ServerGameThread::RemoveAllSessions()
 void
 ServerGameThread::Main()
 {
+	LOG_VERBOSE("Game thread " << GetId() << "started.");
+
 	SetState(SERVER_INITIAL_STATE::Instance());
 
 	try
@@ -138,6 +143,8 @@ ServerGameThread::Main()
 
 	ResetComputerPlayerList();
 	GetLobbyThread().RemoveGame(GetId());
+
+	LOG_VERBOSE("Game thread " << GetId() << "terminating.");
 }
 
 void

src/net/common/serverlobbythread.cpp

@@ -148,6 +148,8 @@ ServerLobbyThread::RemoveSessionFromGame(SessionWrapper session)
 void
 ServerLobbyThread::CloseSession(SessionWrapper session)
 {
+	LOG_VERBOSE("Closing session #" << session.sessionData->GetId() << ".");
+
 	m_sessionManager.RemoveSession(session.sessionData->GetId());
 	m_gameSessionManager.RemoveSession(session.sessionData->GetId());
 
@@ -363,7 +365,9 @@ ServerLobbyThread::ProcessLoop()
 			CloseSession(session);
 			return;
 		}
-		if (packet.get())
+		if (!packet.get())
+			LOG_VERBOSE("Select successful but no packet received for session #" << session.sessionData->GetId() << ".");
+		else
 		{
 			if (packet->IsClientActivity())
 				session.sessionData->ResetActivityTimer();
@@ -640,6 +644,8 @@ ServerLobbyThread::HandleNetPacketRetrieveAvatar(SessionWrapper session, const N
 void
 ServerLobbyThread::HandleNetPacketCreateGame(SessionWrapper session, const NetPacketCreateGame &tmpPacket)
 {
+	LOG_VERBOSE("Creating new game, initiated by session #" << session.sessionData->GetId() << ".");
+
 	// Create a new game.
 	NetPacketCreateGame::Data createGameData;
 	tmpPacket.GetData(createGameData);
@@ -851,6 +857,8 @@ ServerLobbyThread::CleanupAvatarCache()
 	if (m_cacheCleanupTimer.elapsed().total_seconds() >= SERVER_CACHE_CLEANUP_INTERVAL_SEC
 		&& !m_sessionManager.HasSessions() && !m_gameSessionManager.HasSessions())
 	{
+		LOG_VERBOSE("Cleaning up avatar cache.");
+
 		m_avatarManager.RemoveOldAvatarCacheEntries();
 		m_cacheCleanupTimer.reset();
 		m_cacheCleanupTimer.start();
@@ -946,6 +954,8 @@ ServerLobbyThread::HandleNewConnection(boost::shared_ptr<ConnectData> connData)
 	boost::shared_ptr<SessionData> sessionData(new SessionData(connData->ReleaseSocket(), m_curSessionId++));
 	m_sessionManager.AddSession(sessionData);
 
+	LOG_VERBOSE("Accepted connection - session #" << sessionData->GetId() << ".");
+
 	if (m_sessionManager.GetRawSessionCount() <= SERVER_MAX_NUM_SESSIONS)
 	{
 		char tmpAddress[MAX_ADDR_STRING_LEN];
@@ -992,7 +1002,10 @@ ServerLobbyThread::InternalCheckSessionTimeouts(SessionWrapper session)
 	if (session.sessionData.get() && session.playerData.get())
 	{
 		if (session.sessionData->GetState() == SessionData::Init && session.sessionData->GetAutoDisconnectTimerElapsedSec() >= SERVER_INIT_SESSION_TIMEOUT_SEC)
+		{
+			LOG_VERBOSE("Session init timeout, removing session #" << session.sessionData->GetId() << ".");
 			closeSession = true;
+		}
 		else if (session.sessionData->GetActivityTimerElapsedSec() >= SERVER_SESSION_ACTIVITY_TIMEOUT_SEC - SERVER_TIMEOUT_WARNING_REMAINING_SEC
 				&& !session.sessionData->HasActivityNoticeBeenSent())
 		{
@@ -1006,15 +1019,19 @@ ServerLobbyThread::InternalCheckSessionTimeouts(SessionWrapper session)
 		}
 		else if (session.sessionData->GetActivityTimerElapsedSec() >= SERVER_SESSION_ACTIVITY_TIMEOUT_SEC)
 		{
+			LOG_VERBOSE("Activity timeout, removing session #" << session.sessionData->GetId() << ".");
 			closeSession = true;
 		}
 		else if (session.sessionData->GetAutoDisconnectTimerElapsedSec() >= SERVER_SESSION_FORCED_TIMEOUT_SEC)
 		{
+			LOG_VERBOSE("Auto disconnect timeout, removing session #" << session.sessionData->GetId() << ".");
 			closeSession = true;
 		}
 	}
 	if (closeSession)
+	{
 		RemovePlayer(session.playerData->GetUniqueId(), ERR_NET_SESSION_TIMED_OUT);
+	}
 }
 
 void
@@ -1039,6 +1056,7 @@ ServerLobbyThread::SessionError(SessionWrapper session, int errorCode)
 void
 ServerLobbyThread::SendError(boost::shared_ptr<SessionData> s, int errorCode)
 {
+	LOG_VERBOSE("Sending error code " << errorCode << " to session #" << s->GetId() << ".");
 	boost::shared_ptr<NetPacket> packet(new NetPacketError);
 	NetPacketError::Data errorData;
 	errorData.errorCode = errorCode;
@@ -1140,6 +1158,7 @@ ServerLobbyThread::SaveStatisticsFile()
 {
 	if (m_saveStatisticsTimer.elapsed().total_seconds() >= SERVER_SAVE_STATISTICS_INTERVAL_SEC)
 	{
+		LOG_VERBOSE("Saving statistics.");
 		{
 			boost::mutex::scoped_lock lock(m_statMutex);
 			if (m_statDataChanged)

src/pokerth_server.cpp

@@ -83,12 +83,14 @@ main(int argc, char *argv[])
 
 	bool readonlyConfig = false;
 	string pidFile;
+	int logLevel = 1;
 	{
 		// Check command line options.
 		po::options_description desc("Allowed options");
 		desc.add_options()
 			("help,h", "produce help message")
 			("version,v", "print version string")
+			("log-level,l", po::value<int>(), "set log level (0=minimal, 1=default, 2=verbose)")
 			("pid-file,p", po::value<string>(), "create pid-file in different location")
 			("readonly-config", "treat config file as read-only")
 			;
@@ -108,6 +110,15 @@ main(int argc, char *argv[])
 				 << "Network protocol version " << NET_VERSION_MAJOR << "." << NET_VERSION_MINOR << endl;
 			return 1;
 		}
+		if (vm.count("log-level"))
+		{
+			logLevel = vm["log-level"].as<int>();
+			if (logLevel < 0 || logLevel > 2)
+			{
+				cout << "Invalid log-level: \"" << logLevel << "\", allowed range 1-2." << endl;
+				return 1;
+			}
+		}
 		if (vm.count("pid-file"))
 			pidFile = vm["pid-file"].as<string>();
 		if (vm.count("readonly-config"))
@@ -117,7 +128,7 @@ main(int argc, char *argv[])
 	auto_ptr<QtToolsInterface> myQtToolsInterface(CreateQtToolsWrapper());
 	//create defaultconfig
 	ConfigFile *myConfig = new ConfigFile(argv[0], readonlyConfig);
-	loghelper_init(myQtToolsInterface->stringFromUtf8(myConfig->readConfigString("LogDir")));
+	loghelper_init(myQtToolsInterface->stringFromUtf8(myConfig->readConfigString("LogDir")), logLevel);
 
 	// TODO: Hack
 #ifndef _WIN32