ds@1952: /**
ds@1952:  * vim: set ts=4 :
ds@1952:  * =============================================================================
ds@1952:  * SourceMod
ds@1952:  * Copyright (C) 2004-2008 AlliedModders LLC.  All rights reserved.
ds@1952:  * =============================================================================
ds@1952:  *
ds@1952:  * This program is free software; you can redistribute it and/or modify it under
ds@1952:  * the terms of the GNU General Public License, version 3.0, as published by the
ds@1952:  * Free Software Foundation.
ds@1952:  * 
ds@1952:  * This program is distributed in the hope that it will be useful, but WITHOUT
ds@1952:  * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
ds@1952:  * FOR A PARTICULAR PURPOSE.  See the GNU General Public License for more
ds@1952:  * details.
ds@1952:  *
ds@1952:  * You should have received a copy of the GNU General Public License along with
ds@1952:  * this program.  If not, see <http://www.gnu.org/licenses/>.
ds@1952:  *
ds@1952:  * As a special exception, AlliedModders LLC gives you permission to link the
ds@1952:  * code of this program (as well as its derivative works) to "Half-Life 2," the
ds@1952:  * "Source Engine," the "SourcePawn JIT," and any Game MODs that run on software
ds@1952:  * by the Valve Corporation.  You must obey the GNU General Public License in
ds@1952:  * all respects for all other code used.  Additionally, AlliedModders LLC grants
ds@1952:  * this exception to all derivative works.  AlliedModders LLC defines further
ds@1952:  * exceptions, found in LICENSE.txt (as of this writing, version JULY-31-2007),
ds@1952:  * or <http://www.sourcemod.net/license.php>.
ds@1952:  *
ds@1952:  * Version: $Id$
ds@1952:  */
ds@1952: 
ds@1952: #include <time.h>
ds@1952: #include "sourcemod.h"
ds@1952: #include "sourcemm_api.h"
ds@1952: #include "sm_stringutil.h"
ds@1952: #include "Logger.h"
ds@1952: #include "systems/LibrarySys.h"
ds@1952: #include "TimerSys.h"
ds@1952: #include "sm_version.h"
ds@1952: 
ds@1952: Logger g_Logger;
ds@1952: 
ds@1952: /**
ds@1952:  * :TODO: This should be creating the log folder if it doesn't exist
ds@1952:  */
ds@1952: 
ds@1952: ConfigResult Logger::OnSourceModConfigChanged(const char *key, 
ds@1952: 									  const char *value, 
ds@1952: 									  ConfigSource source,
ds@1952: 									  char *error, 
ds@1952: 									  size_t maxlength)
ds@1952: {
ds@1952: 	if (strcasecmp(key, "Logging") == 0)
ds@1952: 	{
ds@1952: 		bool state;
ds@1952: 
ds@1952: 		if (strcasecmp(value, "on") == 0)
ds@1952: 		{
ds@1952: 			state = true;
ds@1952: 		} else if (strcasecmp(value, "off") == 0) {
ds@1952: 			state = false;
ds@1952: 		} else {
ds@1952: 			UTIL_Format(error, maxlength, "Invalid value: must be \"on\" or \"off\"");
ds@1952: 			return ConfigResult_Reject;
ds@1952: 		}
ds@1952: 
ds@1952: 		if (source == ConfigSource_Console)
ds@1952: 		{
ds@1952: 			state ? EnableLogging() : DisableLogging();
ds@1952: 		} else {
ds@1952: 			m_InitialState = state;
ds@1952: 		}
ds@1952: 
ds@1952: 		return ConfigResult_Accept;
ds@1952: 	} else if (strcasecmp(key, "LogMode") == 0) {
ds@1952: 		if (strcasecmp(value, "daily") == 0) 
ds@1952: 		{
ds@1952: 			m_Mode = LoggingMode_Daily;
ds@1952: 		} else if (strcasecmp(value, "map") == 0) {
ds@1952: 			m_Mode = LoggingMode_PerMap;
ds@1952: 		} else if (strcasecmp(value, "game") == 0) {
ds@1952: 			m_Mode = LoggingMode_Game;
ds@1952: 		} else {
ds@1952: 			UTIL_Format(error, maxlength, "Invalid value: must be [daily|map|game]");
ds@1952: 			return ConfigResult_Reject;
ds@1952: 		}
ds@1952: 
ds@1952: 		return ConfigResult_Accept;
ds@1952: 	}
ds@1952: 
ds@1952: 	return ConfigResult_Ignore;
ds@1952: }
ds@1952: 
ds@1952: void Logger::OnSourceModStartup(bool late)
ds@1952: {
ds@1952: 	InitLogger(m_Mode);
ds@1952: }
ds@1952: 
ds@1952: void Logger::OnSourceModAllShutdown()
ds@1952: {
ds@1952: 	CloseLogger();
ds@1952: }
ds@1952: 
ds@1952: void Logger::OnSourceModLevelChange(const char *mapName)
ds@1952: {
ds@1952: 	MapChange(mapName);
ds@1952: }
ds@1952: 
ds@1952: void Logger::_NewMapFile()
ds@1952: {
ds@1952: 	if (!m_Active)
ds@1952: 	{
ds@1952: 		return;
ds@1952: 	}
ds@1952: 
ds@1952: 	/* Append "Log file closed" to previous log file */
ds@1952: 	_CloseFile();
ds@1952: 	
ds@1952: 	char _filename[256];
ds@1952: 	int i = 0;
ds@1952: 
ds@1952: 	time_t t;
ds@1952: 	GetAdjustedTime(&t);
ds@1952: 	tm *curtime = localtime(&t);
ds@1952: 
ds@1952: 	while (true)
ds@1952: 	{
ds@1952: 		g_SourceMod.BuildPath(Path_SM, _filename, sizeof(_filename), "logs/L%02d%02d%03d.log", curtime->tm_mon + 1, curtime->tm_mday, i);
ds@1952: 		FILE *fp = fopen(_filename, "r");
ds@1952: 		if (!fp)
ds@1952: 		{
ds@1952: 			break;
ds@1952: 		}
ds@1952: 		fclose(fp);
ds@1952: 		i++;
ds@1952: 	}
ds@1952: 	m_NrmFileName.assign(_filename);
ds@1952: 
ds@1952: 	FILE *fp = fopen(m_NrmFileName.c_str(), "w");
ds@1952: 	if (!fp)
ds@1952: 	{
ds@1952: 		char error[255];
ds@1952: 		g_LibSys.GetPlatformError(error, sizeof(error));
ds@1952: 		LogFatal("[SM] Unexpected fatal logging error (file \"%s\")", m_NrmFileName.c_str());
ds@1952: 		LogFatal("[SM] Platform returned error: \"%s\"", error);
ds@1952: 		LogFatal("[SM] Logging has been disabled.");
ds@1952: 		m_Active = false;
ds@1952: 		return;
ds@1952: 	} else {
ds@1952: 		char date[32];
ds@1952: 		strftime(date, sizeof(date), "%m/%d/%Y - %H:%M:%S", curtime);
ds@1952: 		fprintf(fp, "L %s: SourceMod log file started (file \"L%02d%02d%03d.log\") (Version \"%s\")\n", date, curtime->tm_mon + 1, curtime->tm_mday, i, SVN_FULL_VERSION);
ds@1952: 		fclose(fp);
ds@1952: 	}
ds@1952: }
ds@1952: 
ds@1952: void Logger::_CloseFile()
ds@1952: {
ds@1952: 	if (!m_Active)
ds@1952: 	{
ds@1952: 		return;
ds@1952: 	}
ds@1952: 
ds@1952: 	FILE *fp = NULL;
ds@1952: 	if (!m_NrmFileName.empty())
ds@1952: 	{
ds@1952: 		fp = fopen(m_NrmFileName.c_str(), "r+");
ds@1952: 		if (fp)
ds@1952: 		{
ds@1952: 			fseek(fp, 0, SEEK_END);
ds@1952: 			LogMessage("Log file closed.");
ds@1952: 			fclose(fp);
ds@1952: 		}
ds@1952: 		m_NrmFileName.clear();
ds@1952: 	}
ds@1952: 
ds@1952: 	if (!m_ErrMapStart)
ds@1952: 	{
ds@1952: 		return;
ds@1952: 	}
ds@1952: 	fp = fopen(m_ErrFileName.c_str(), "r+");
ds@1952: 	if (fp)
ds@1952: 	{
ds@1952: 		fseek(fp, 0, SEEK_END);
ds@1952: 		LogError("Error log file session closed.");
ds@1952: 		fclose(fp);
ds@1952: 	}
ds@1952: 	m_ErrFileName.clear();
ds@1952: }
ds@1952: 
ds@1952: void Logger::InitLogger(LoggingMode mode)
ds@1952: {
ds@1952: 	m_Mode = mode;
ds@1952: 	m_Active = m_InitialState;
ds@1952: 
ds@1952: 	time_t t;
ds@1952: 	GetAdjustedTime(&t);
ds@1952: 	tm *curtime = localtime(&t);
ds@1952: 	m_CurDay = curtime->tm_mday;
ds@1952: 
ds@1952: 	char _filename[256];
ds@1952: 	g_SourceMod.BuildPath(Path_SM, _filename, sizeof(_filename), "logs/errors_%04d%02d%02d.log", curtime->tm_year + 1900, curtime->tm_mon + 1, curtime->tm_mday);
ds@1952: 	m_ErrFileName.assign(_filename);
ds@1952: 
ds@1952: 	switch (m_Mode)
ds@1952: 	{
ds@1952: 	case LoggingMode_PerMap:
ds@1952: 		{
ds@1952: 			if (!m_Active)
ds@1952: 			{
ds@1952: 				m_DelayedStart = true;
ds@1952: 			}
ds@1952: 			break;
ds@1952: 		}
ds@1952: 	case LoggingMode_Daily:
ds@1952: 		{
ds@1952: 			g_SourceMod.BuildPath(Path_SM, _filename, sizeof(_filename), "logs/L%04d%02d%02d.log", curtime->tm_year + 1900, curtime->tm_mon + 1, curtime->tm_mday);
ds@1952: 			m_NrmFileName.assign(_filename);
ds@1952: 			m_DailyPrintHdr = true;
ds@1952: 			break;
ds@1952: 		}
ds@1952: 	default:
ds@1952: 		{
ds@1952: 			/* do nothing... */
ds@1952: 			break;
ds@1952: 		}
ds@1952: 	}
ds@1952: }
ds@1952: 
ds@1952: void Logger::CloseLogger()
ds@1952: {
ds@1952: 	_CloseFile();
ds@1952: }
ds@1952: 
ds@1952: void Logger::LogToOpenFile(FILE *fp, const char *msg, ...)
ds@1952: {
ds@1952: 	if (!m_Active)
ds@1952: 	{
ds@1952: 		return;
ds@1952: 	}
ds@1952: 
ds@1952: 	va_list ap;
ds@1952: 	va_start(ap, msg);
ds@1952: 	LogToOpenFileEx(fp, msg, ap);
ds@1952: 	va_end(ap);
ds@1952: }
ds@1952: 
ds@1952: void Logger::LogToOpenFileEx(FILE *fp, const char *msg, va_list ap)
ds@1952: {
ds@1952: 	if (!m_Active)
ds@1952: 	{
ds@1952: 		return;
ds@1952: 	}
ds@1952: 
ds@1952: 	char buffer[3072];
ds@1952: 	UTIL_FormatArgs(buffer, sizeof(buffer), msg, ap);
ds@1952: 
ds@1952: 	char date[32];
ds@1952: 	time_t t;
ds@1952: 	GetAdjustedTime(&t);
ds@1952: 	tm *curtime = localtime(&t);
ds@1952: 	strftime(date, sizeof(date), "%m/%d/%Y - %H:%M:%S", curtime);
ds@1952: 
ds@1952: 	fprintf(fp, "L %s: %s\n", date, buffer);
ds@1952: 	g_SMAPI->ConPrintf("L %s: %s\n", date, buffer);
ds@1952: }
ds@1952: 
ds@1952: void Logger::LogMessage(const char *vafmt, ...)
ds@1952: {
ds@1952: 	if (!m_Active)
ds@1952: 	{
ds@1952: 		return;
ds@1952: 	}
ds@1952: 
ds@1952: 	if (m_Mode == LoggingMode_Game)
ds@1952: 	{
ds@1952: 		va_list ap;
ds@1952: 		va_start(ap, vafmt);
ds@1952: 		_PrintToGameLog(vafmt, ap);
ds@1952: 		va_end(ap);
ds@1952: 		return;
ds@1952: 	}
ds@1952: 
ds@1952: 	if (m_DelayedStart)
ds@1952: 	{
ds@1952: 		m_DelayedStart = false;
ds@1952: 		_NewMapFile();
ds@1952: 	}
ds@1952: 
ds@1952: 	time_t t;
ds@1952: 	GetAdjustedTime(&t);
ds@1952: 	tm *curtime = localtime(&t);
ds@1952: 
ds@1952: 	FILE *fp = NULL;
ds@1952: 	if (m_Mode == LoggingMode_PerMap)
ds@1952: 	{
ds@1952: 		fp = fopen(m_NrmFileName.c_str(), "a+");
ds@1952: 		if (!fp)
ds@1952: 		{
ds@1952: 			_NewMapFile();
ds@1952: 			fp = fopen(m_NrmFileName.c_str(), "a+");
ds@1952: 			if (!fp)
ds@1952: 			{
ds@1952: 				goto print_error;
ds@1952: 			}
ds@1952: 		}
ds@1952: 	} else {
ds@1952: 		if (m_CurDay != curtime->tm_mday)
ds@1952: 		{
ds@1952: 			char _filename[256];
ds@1952: 			g_SourceMod.BuildPath(Path_SM, _filename, sizeof(_filename), "logs/L%04d%02d%02d.log", curtime->tm_year + 1900, curtime->tm_mon + 1, curtime->tm_mday);
ds@1952: 			m_NrmFileName.assign(_filename);
ds@1952: 			m_CurDay = curtime->tm_mday;
ds@1952: 			m_DailyPrintHdr = true;
ds@1952: 		}
ds@1952: 		fp = fopen(m_NrmFileName.c_str(), "a+");
ds@1952: 	}
ds@1952: 
ds@1952: 	if (fp)
ds@1952: 	{
ds@1952: 		if (m_DailyPrintHdr)
ds@1952: 		{
ds@1952: 			char date[32];
ds@1952: 			m_DailyPrintHdr = false;
ds@1952: 			strftime(date, sizeof(date), "%m/%d/%Y - %H:%M:%S", curtime);
ds@1952: 			fprintf(fp, "L %s: SourceMod log file session started (file \"L%04d%02d%02d.log\") (Version \"%s\")\n", date, curtime->tm_year + 1900, curtime->tm_mon + 1, curtime->tm_mday, SVN_FULL_VERSION);
ds@1952: 	 	}
ds@1952: 		va_list ap;
ds@1952: 		va_start(ap, vafmt);
ds@1952: 		LogToOpenFileEx(fp, vafmt, ap);
ds@1952: 		va_end(ap);
ds@1952: 		fclose(fp);
ds@1952: 	} else {
ds@1952: 		goto print_error;
ds@1952: 	}
ds@1952: 
ds@1952: 	return;
ds@1952: print_error:
ds@1952: 	char error[255];
ds@1952: 	g_LibSys.GetPlatformError(error, sizeof(error));
ds@1952: 	LogFatal("[SM] Unexpected fatal logging error (file \"%s\")", m_NrmFileName.c_str());
ds@1952: 	LogFatal("[SM] Platform returned error: \"%s\"", error);
ds@1952: 	LogFatal("[SM] Logging has been disabled.");
ds@1952: 	m_Active = false;
ds@1952: }
ds@1952: 
ds@1952: void Logger::LogError(const char *vafmt, ...)
ds@1952: {
ds@1952: 	if (!m_Active)
ds@1952: 	{
ds@1952: 		return;
ds@1952: 	}
ds@1952: 
ds@1952: 	time_t t;
ds@1952: 	GetAdjustedTime(&t);
ds@1952: 	tm *curtime = localtime(&t);
ds@1952: 
ds@1952: 	if (curtime->tm_mday != m_CurDay)
ds@1952: 	{
ds@1952: 		char _filename[256];
ds@1952: 		g_SourceMod.BuildPath(Path_SM, _filename, sizeof(_filename), "logs/errors_%04d%02d%02d.log", curtime->tm_year + 1900, curtime->tm_mon + 1, curtime->tm_mday);
ds@1952: 		m_ErrFileName.assign(_filename);
ds@1952: 		m_CurDay = curtime->tm_mday;
ds@1952: 		m_ErrMapStart = false;
ds@1952: 	}
ds@1952: 
ds@1952: 	FILE *fp = fopen(m_ErrFileName.c_str(), "a+");
ds@1952: 	if (fp)
ds@1952: 	{
ds@1952: 		if (!m_ErrMapStart)
ds@1952: 		{
ds@1952: 			char date[32];
ds@1952: 			strftime(date, sizeof(date), "%m/%d/%Y - %H:%M:%S", curtime);
ds@1952: 			fprintf(fp, "L %s: SourceMod error session started\n", date);
ds@1952: 			fprintf(fp, "L %s: Info (map \"%s\") (file \"errors_%04d%02d%02d.log\")\n", date, m_CurMapName.c_str(), curtime->tm_year + 1900, curtime->tm_mon + 1, curtime->tm_mday);
ds@1952: 			m_ErrMapStart = true;
ds@1952: 		}
ds@1952: 		va_list ap;
ds@1952: 		va_start(ap, vafmt);
ds@1952: 		LogToOpenFileEx(fp, vafmt, ap);
ds@1952: 		va_end(ap);
ds@1952: 		fclose(fp);
ds@1952: 	}
ds@1952: 	else
ds@1952: 	{
ds@1952: 		char error[255];
ds@1952: 		g_LibSys.GetPlatformError(error, sizeof(error));
ds@1952: 		LogFatal("[SM] Unexpected fatal logging error (file \"%s\")", m_NrmFileName.c_str());
ds@1952: 		LogFatal("[SM] Platform returned error: \"%s\"", error);
ds@1952: 		LogFatal("[SM] Logging has been disabled.");
ds@1952: 		m_Active = false;
ds@1952: 		return;
ds@1952: 	}
ds@1952: }
ds@1952: 
ds@1952: void Logger::MapChange(const char *mapname)
ds@1952: {
ds@1952: 	m_CurMapName.assign(mapname);
ds@1952: 
ds@1952: 	switch (m_Mode)
ds@1952: 	{
ds@1952: 	case LoggingMode_Daily:
ds@1952: 		{
ds@1952: 			LogMessage("-------- Mapchange to %s --------", mapname);
ds@1952: 			break;
ds@1952: 		}
ds@1952: 	case LoggingMode_PerMap:
ds@1952: 		{
ds@1952: 			_NewMapFile();
ds@1952: 			break;
ds@1952: 		}
ds@1952: 	default:
ds@1952: 		{
ds@1952: 			/* Do nothing... */
ds@1952: 			break;
ds@1952: 		}
ds@1952: 	}
ds@1952: 
ds@1952: 	if (m_ErrMapStart)
ds@1952: 	{
ds@1952: 		LogError("Error log file session closed.");
ds@1952: 	}
ds@1952: 	m_ErrMapStart = false;
ds@1952: }
ds@1952: 
ds@1952: void Logger::_PrintToGameLog(const char *fmt, va_list ap)
ds@1952: {
ds@1952: 	char msg[3072];
ds@1952: 	size_t len;
ds@1952: 
ds@1952: 	len = vsnprintf(msg, sizeof(msg)-2, fmt, ap);
ds@1952: 	len = (len >= sizeof(msg)) ? (sizeof(msg) - 2) : len;
ds@1952: 
ds@1952: 	msg[len++] = '\n';
ds@1952: 	msg[len] = '\0';
ds@1952: 
ds@1952: 	Engine_LogPrintWrapper(msg);
ds@1952: }
ds@1952: 
ds@1952: const char *Logger::GetLogFileName(LogType type) const
ds@1952: {
ds@1952: 	switch (type)
ds@1952: 	{
ds@1952: 	case LogType_Normal:
ds@1952: 		{
ds@1952: 			return m_NrmFileName.c_str();
ds@1952: 		}
ds@1952: 	case LogType_Error:
ds@1952: 		{
ds@1952: 			return m_ErrFileName.c_str();
ds@1952: 		}
ds@1952: 	default:
ds@1952: 		{
ds@1952: 			return "";
ds@1952: 		}
ds@1952: 	}
ds@1952: }
ds@1952: 
ds@1952: LoggingMode Logger::GetLoggingMode() const
ds@1952: {
ds@1952: 	return m_Mode;
ds@1952: }
ds@1952: 
ds@1952: void Logger::EnableLogging()
ds@1952: {
ds@1952: 	if (m_Active)
ds@1952: 	{
ds@1952: 		return;
ds@1952: 	}
ds@1952: 	m_Active = true;
ds@1952: 	LogMessage("[SM] Logging enabled manually by user.");
ds@1952: }
ds@1952: 
ds@1952: void Logger::DisableLogging()
ds@1952: {
ds@1952: 	if (!m_Active)
ds@1952: 	{
ds@1952: 		return;
ds@1952: 	}
ds@1952: 	LogMessage("[SM] Logging disabled manually by user.");
ds@1952: 	m_Active = false;
ds@1952: }
ds@1952: 
ds@1952: void Logger::LogFatal(const char *msg, ...)
ds@1952: {
ds@1952: 	/* :TODO: make this print all pretty-like
ds@1952: 	 * In fact, the pretty log printing function should be abstracted. 
ds@1952: 	 * It's already implemented twice which is bad.
ds@1952: 	 */
ds@1952: 
ds@1952: 	va_list ap;
ds@1952: 	char path[PLATFORM_MAX_PATH];
ds@1952: 
ds@1952: 	g_SourceMod.BuildPath(Path_Game, path, sizeof(path), "sourcemod_fatal.log");
ds@1952: 
ds@1952: 	FILE *fp = fopen(path, "at");
ds@1952: 	if (fp)
ds@1952: 	{
ds@1952: 		m_Active = true;
ds@1952: 		va_start(ap, msg);
ds@1952: 		LogToOpenFileEx(fp, msg, ap);
ds@1952: 		va_end(ap);
ds@1952: 		m_Active = false;
ds@1952: 		fclose(fp);
ds@1952: 	}
ds@1952: }
ds@1952: 
ds@1952: bool g_in_game_log_hook = false;
ds@1952: 
ds@1952: void Engine_LogPrintWrapper(const char *msg)
ds@1952: {
ds@1952: 	if (g_in_game_log_hook)
ds@1952: 	{
ds@1952: 		ENGINE_CALL(LogPrint)(msg);
ds@1952: 	}
ds@1952: 	else
ds@1952: 	{
ds@1952: 		engine->LogPrint(msg);
ds@1952: 	}
ds@1952: }