diff --git a/src/core/common/loghelper_client.cpp b/src/core/common/loghelper_client.cpp index 0dba8ddc..21ffc851 100644 --- a/src/core/common/loghelper_client.cpp +++ b/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; } diff --git a/src/core/common/loghelper_server.cpp b/src/core/common/loghelper_server.cpp index 5b06b7f1..d6d0bf92 100644 --- a/src/core/common/loghelper_server.cpp +++ b/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 (!o.fail()) - o << second_clock::local_time() << " MSG: " << msg; + if (!g_logFile.empty()) + { + 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; + } } } diff --git a/src/core/loghelper.h b/src/core/loghelper.h index b75eff86..5a89d0b8 100644 --- a/src/core/loghelper.h +++ b/src/core/loghelper.h @@ -24,10 +24,11 @@ #include #include -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 diff --git a/src/net/common/servergamethread.cpp b/src/net/common/servergamethread.cpp index fb7554a4..f8d2ffe2 100644 --- a/src/net/common/servergamethread.cpp +++ b/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 diff --git a/src/net/common/serverlobbythread.cpp b/src/net/common/serverlobbythread.cpp index 96b30aca..06457e47 100644 --- a/src/net/common/serverlobbythread.cpp +++ b/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 connData) boost::shared_ptr 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 s, int errorCode) { + LOG_VERBOSE("Sending error code " << errorCode << " to session #" << s->GetId() << "."); boost::shared_ptr 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) diff --git a/src/pokerth_server.cpp b/src/pokerth_server.cpp index 0cb45644..6216f7bf 100644 --- a/src/pokerth_server.cpp +++ b/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(), "set log level (0=minimal, 1=default, 2=verbose)") ("pid-file,p", po::value(), "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(); + 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(); if (vm.count("readonly-config")) @@ -117,7 +128,7 @@ main(int argc, char *argv[]) auto_ptr 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