hl2_src-leak-2017/src/engine/sv_log.cpp

898 lines
19 KiB
C++

//========= Copyright Valve Corporation, All rights reserved. ============//
//
// Purpose:
//
// $Header: $
// $NoKeywords: $
//=============================================================================//
#include "server_pch.h"
#include <time.h>
#include "server.h"
#include "sv_log.h"
#include "filesystem.h"
#include "filesystem_engine.h"
#include "tier0/vcrmode.h"
#include "sv_main.h"
#include "tier0/icommandline.h"
#include <proto_oob.h>
#include "GameEventManager.h"
#include "netadr.h"
#include "zlib/zlib.h"
// memdbgon must be the last include file in a .cpp file!!!
#include "tier0/memdbgon.h"
static ConVar sv_logsdir( "sv_logsdir", "logs", FCVAR_ARCHIVE, "Folder in the game directory where server logs will be stored." );
static ConVar sv_logfile( "sv_logfile", "1", FCVAR_ARCHIVE, "Log server information in the log file." );
static ConVar sv_logflush( "sv_logflush", "0", FCVAR_ARCHIVE, "Flush the log file to disk on each write (slow)." );
static ConVar sv_logecho( "sv_logecho", "1", FCVAR_ARCHIVE, "Echo log information to the console." );
static ConVar sv_log_onefile( "sv_log_onefile", "0", FCVAR_ARCHIVE, "Log server information to only one file." );
static ConVar sv_logbans( "sv_logbans", "0", FCVAR_ARCHIVE, "Log server bans in the server logs." ); // should sv_banid() calls be logged in the server logs?
static ConVar sv_logsecret( "sv_logsecret", "0", 0, "If set then include this secret when doing UDP logging (will use 0x53 as packet type, not usual 0x52)" );
static ConVar sv_logfilename_format( "sv_logfilename_format", "", FCVAR_ARCHIVE, "Log filename format. See strftime for formatting codes." );
static ConVar sv_logfilecompress( "sv_logfilecompress", "0", FCVAR_ARCHIVE, "Gzip compress logfile and rename to logfilename.log.gz on close." );
CLog g_Log; // global Log object
CON_COMMAND( log, "Enables logging to file, console, and udp < on | off >." )
{
if ( args.ArgC() != 2 )
{
ConMsg( "Usage: log < on | off >\n" );
if ( g_Log.IsActive() )
{
bool bHaveFirst = false;
ConMsg( "currently logging to: " );
if ( sv_logfile.GetInt() )
{
ConMsg( "file" );
bHaveFirst = true;
}
if ( sv_logecho.GetInt() )
{
if ( bHaveFirst )
{
ConMsg( ", console" );
}
else
{
ConMsg( "console" );
bHaveFirst = true;
}
}
if ( g_Log.UsingLogAddress() )
{
if ( bHaveFirst )
{
ConMsg( ", udp" );
}
else
{
ConMsg( "udp" );
bHaveFirst = true;
}
}
if ( !bHaveFirst )
{
ConMsg( "no destinations! (file, console, or udp)\n" );
ConMsg( "check \"sv_logfile\", \"sv_logecho\", and \"logaddress_list\"" );
}
ConMsg( "\n" );
}
else
{
ConMsg( "not currently logging\n" );
}
return;
}
if ( !Q_stricmp( args[1], "off" ) || !Q_stricmp( args[1], "0" ) )
{
if ( g_Log.IsActive() )
{
g_Log.Close();
g_Log.SetLoggingState( false );
ConMsg( "Server logging disabled.\n" );
}
}
else if ( !Q_stricmp( args[1], "on" ) || !Q_stricmp( args[1], "1" ) )
{
g_Log.SetLoggingState( true );
ConMsg( "Server logging enabled.\n" );
g_Log.Open();
}
else
{
ConMsg( "log: unknown parameter %s, 'on' and 'off' are valid\n", args[1] );
}
}
// changed log_addaddress back to logaddress_add to be consistent with GoldSrc
CON_COMMAND( logaddress_add, "Set address and port for remote host <ip:port>." )
{
netadr_t adr;
const char *pszIP, *pszPort;
if ( args.ArgC() != 4 && args.ArgC() != 2 )
{
ConMsg( "Usage: logaddress_add ip:port\n" );
return;
}
pszIP = args[1];
if ( args.ArgC() == 4 )
{
pszPort = args[3];
}
else
{
pszPort = Q_strstr( pszIP, ":" );
// if we have "IP:port" as one argument inside quotes
if ( pszPort )
{
// add one to remove the :
pszPort++;
}
else
{
// default port
pszPort = "27015";
}
}
if ( !Q_atoi( pszPort ) )
{
ConMsg( "logaddress_add: must specify a valid port\n" );
return;
}
if ( !pszIP || !pszIP[0] )
{
ConMsg( "logaddress_add: unparseable address\n" );
return;
}
char szAdr[32];
Q_snprintf( szAdr, sizeof( szAdr ), "%s:%s", pszIP, pszPort );
if ( NET_StringToAdr( szAdr, &adr ) )
{
if ( g_Log.AddLogAddress( adr ) )
{
ConMsg( "logaddress_add: %s\n", adr.ToString() );
}
else
{
ConMsg( "logaddress_add: %s is already in the list\n", adr.ToString() );
}
}
else
{
ConMsg( "logaddress_add: unable to resolve %s\n", szAdr );
}
}
CON_COMMAND( logaddress_delall, "Remove all udp addresses being logged to" )
{
g_Log.DelAllLogAddress();
}
CON_COMMAND( logaddress_del, "Remove address and port for remote host <ip:port>." )
{
netadr_t adr;
const char *pszIP, *pszPort;
if ( args.ArgC() != 4 && args.ArgC() != 2 )
{
ConMsg( "Usage: logaddress_del ip:port\n" );
return;
}
pszIP = args[1];
if ( args.ArgC() == 4 )
{
pszPort = args[3];
}
else
{
pszPort = Q_strstr( pszIP, ":" );
// if we have "IP:port" as one argument inside quotes
if ( pszPort )
{
// add one to remove the :
pszPort++;
}
else
{
// default port
pszPort = "27015";
}
}
if ( !Q_atoi( pszPort ) )
{
ConMsg( "logaddress_del: must specify a valid port\n" );
return;
}
if ( !pszIP || !pszIP[0] )
{
ConMsg( "logaddress_del: unparseable address\n" );
return;
}
char szAdr[32];
Q_snprintf( szAdr, sizeof( szAdr ), "%s:%s", pszIP, pszPort );
if ( NET_StringToAdr( szAdr, &adr ) )
{
if ( g_Log.DelLogAddress( adr ) )
{
ConMsg( "logaddress_del: %s\n", adr.ToString() );
}
else
{
ConMsg( "logaddress_del: address %s not found in the list\n", adr.ToString() );
}
}
else
{
ConMsg( "logaddress_del: unable to resolve %s\n", szAdr );
}
}
CON_COMMAND( logaddress_list, "List all addresses currently being used by logaddress." )
{
g_Log.ListLogAddress();
}
CLog::CLog()
{
Reset();
}
CLog::~CLog()
{
}
void CLog::Reset( void ) // reset all logging streams
{
m_LogAddresses.RemoveAll();
m_hLogFile = FILESYSTEM_INVALID_HANDLE;
m_LogFilename = NULL;
m_bActive = false;
m_flLastLogFlush = realtime;
m_bFlushLog = false;
#ifndef _XBOX
if ( CommandLine()->CheckParm( "-flushlog" ) )
{
m_bFlushLog = true;
}
#endif
}
void CLog::Init( void )
{
Reset();
// listen to these events
g_GameEventManager.AddListener( this, "server_spawn", true );
g_GameEventManager.AddListener( this, "server_shutdown", true );
g_GameEventManager.AddListener( this, "server_cvar", true );
g_GameEventManager.AddListener( this, "server_message", true );
g_GameEventManager.AddListener( this, "server_addban", true );
g_GameEventManager.AddListener( this, "server_removeban", true );
}
void CLog::Shutdown()
{
Close();
Reset();
g_GameEventManager.RemoveListener( this );
}
void CLog::SetLoggingState( bool state )
{
m_bActive = state;
}
void CLog::RunFrame()
{
if ( m_bFlushLog && m_hLogFile != FILESYSTEM_INVALID_HANDLE && ( realtime - m_flLastLogFlush ) > 1.0f )
{
m_flLastLogFlush = realtime;
g_pFileSystem->Flush( m_hLogFile );
}
}
bool CLog::AddLogAddress(netadr_t addr)
{
int i = 0;
for ( i = 0; i < m_LogAddresses.Count(); ++i )
{
if ( m_LogAddresses.Element(i).CompareAdr(addr, false) )
{
// found!
break;
}
}
if ( i < m_LogAddresses.Count() )
{
// already in the list
return false;
}
m_LogAddresses.AddToTail( addr );
return true;
}
bool CLog::DelLogAddress(netadr_t addr)
{
int i = 0;
for ( i = 0; i < m_LogAddresses.Count(); ++i )
{
if ( m_LogAddresses.Element(i).CompareAdr(addr, false) )
{
// found!
break;
}
}
if ( i < m_LogAddresses.Count() )
{
m_LogAddresses.Remove(i);
return true;
}
return false;
}
void CLog::ListLogAddress( void )
{
netadr_t *pElement;
const char *pszAdr;
int count = m_LogAddresses.Count();
if ( count <= 0 )
{
ConMsg( "logaddress_list: no addresses in the list\n" );
}
else
{
if ( count == 1 )
{
ConMsg( "logaddress_list: %i entry\n", count );
}
else
{
ConMsg( "logaddress_list: %i entries\n", count );
}
for ( int i = 0 ; i < count ; ++i )
{
pElement = &m_LogAddresses.Element(i);
pszAdr = pElement->ToString();
ConMsg( "%s\n", pszAdr );
}
}
}
bool CLog::UsingLogAddress( void )
{
return ( m_LogAddresses.Count() > 0 );
}
void CLog::DelAllLogAddress( void )
{
if ( m_LogAddresses.Count() > 0 )
{
ConMsg( "logaddress_delall: all addresses cleared\n" );
m_LogAddresses.RemoveAll();
}
else
{
ConMsg( "logaddress_delall: no addresses in the list\n" );
}
}
/*
==================
Log_PrintServerVars
==================
*/
void CLog::PrintServerVars( void )
{
const ConCommandBase *var; // Temporary Pointer to cvars
if ( !IsActive() )
{
return;
}
Printf( "server cvars start\n" );
// Loop through cvars...
for ( var= g_pCVar->GetCommands() ; var ; var=var->GetNext() )
{
if ( var->IsCommand() )
continue;
if ( !( var->IsFlagSet( FCVAR_NOTIFY ) ) )
continue;
Printf( "\"%s\" = \"%s\"\n", var->GetName(), ((ConVar*)var)->GetString() );
}
Printf( "server cvars end\n" );
}
bool CLog::IsActive( void )
{
return m_bActive;
}
/*
==================
Log_Printf
Prints a log message to the server's log file, console, and possible a UDP address
==================
*/
void CLog::Printf( const char *fmt, ... )
{
va_list argptr;
static char string[1024];
if ( !IsActive() )
{
return;
}
va_start ( argptr, fmt );
Q_vsnprintf ( string, sizeof( string ), fmt, argptr );
va_end ( argptr );
Print( string );
}
void CLog::Print( const char * text )
{
if ( !IsActive() || !text || !text[0] )
{
return;
}
tm today;
VCRHook_LocalTime( &today );
if ( Q_strlen( text ) > 1024 )
{
// Spew a warning, but continue and print the truncated stuff we have.
DevMsg( 1, "CLog::Print: string too long (>1024 bytes)." );
}
static char string[1100];
V_sprintf_safe( string, "L %02i/%02i/%04i - %02i:%02i:%02i: %s",
today.tm_mon+1, today.tm_mday, 1900 + today.tm_year,
today.tm_hour, today.tm_min, today.tm_sec, text );
// Echo to server console
if ( sv_logecho.GetInt() )
{
ConMsg( "%s", string );
}
// Echo to log file
if ( sv_logfile.GetInt() && ( m_hLogFile != FILESYSTEM_INVALID_HANDLE ) )
{
g_pFileSystem->FPrintf( m_hLogFile, "%s", string );
if ( sv_logflush.GetBool() )
{
g_pFileSystem->Flush( m_hLogFile );
}
}
// Echo to UDP port
if ( m_LogAddresses.Count() > 0 )
{
// out of band sending
for ( int i = 0 ; i < m_LogAddresses.Count() ; i++ )
{
if ( sv_logsecret.GetInt() != 0 )
NET_OutOfBandPrintf(NS_SERVER, m_LogAddresses.Element(i), "%c%s%s", S2A_LOGSTRING2, sv_logsecret.GetString(), string );
else
NET_OutOfBandPrintf(NS_SERVER, m_LogAddresses.Element(i), "%c%s", S2A_LOGSTRING, string );
}
}
}
void CLog::FireGameEvent( IGameEvent *event )
{
if ( !IsActive() )
return;
// log server events
const char * name = event->GetName();
if ( !name || !name[0])
return;
if ( Q_strcmp(name, "server_spawn") == 0 )
{
Printf( "Started map \"%s\" (CRC \"%s\")\n", sv.GetMapName(), MD5_Print( sv.worldmapMD5.bits, MD5_DIGEST_LENGTH ) );
}
else if ( Q_strcmp(name, "server_shutdown") == 0 )
{
Printf( "server_message: \"%s\"\n", event->GetString("reason") );
}
else if ( Q_strcmp(name, "server_cvar") == 0 )
{
Printf( "server_cvar: \"%s\" \"%s\"\n", event->GetString("cvarname"), event->GetString("cvarvalue") );
}
else if ( Q_strcmp(name, "server_message") == 0 )
{
Printf( "server_message: \"%s\"\n", event->GetString("text") );
}
else if ( Q_strcmp(name, "server_addban") == 0 )
{
if ( sv_logbans.GetInt() > 0 )
{
const int userid = event->GetInt( "userid" );
const char *pszName = event->GetString( "name" );
const char *pszNetworkid = event->GetString( "networkid" );
const char *pszIP = event->GetString( "ip" );
const char *pszDuration = event->GetString( "duration" );
const char *pszCmdGiver = event->GetString( "by" );
const char *pszResult = NULL;
if ( Q_strlen( pszIP ) > 0 )
{
pszResult = event->GetInt( "kicked" ) > 0 ? "was kicked and banned by IP" : "was banned by IP";
if ( userid > 0 )
{
Printf( "Addip: \"%s<%i><%s><>\" %s \"%s\" by \"%s\" (IP \"%s\")\n",
pszName,
userid,
pszNetworkid,
pszResult,
pszDuration,
pszCmdGiver,
pszIP );
}
else
{
Printf( "Addip: \"<><><>\" %s \"%s\" by \"%s\" (IP \"%s\")\n",
pszResult,
pszDuration,
pszCmdGiver,
pszIP );
}
}
else
{
pszResult = event->GetInt( "kicked" ) > 0 ? "was kicked and banned" : "was banned";
if ( userid > 0 )
{
Printf( "Banid: \"%s<%i><%s><>\" %s \"%s\" by \"%s\"\n",
pszName,
userid,
pszNetworkid,
pszResult,
pszDuration,
pszCmdGiver );
}
else
{
Printf( "Banid: \"<><%s><>\" %s \"%s\" by \"%s\"\n",
pszNetworkid,
pszResult,
pszDuration,
pszCmdGiver );
}
}
}
}
else if ( Q_strcmp(name, "server_removeban") == 0 )
{
if ( sv_logbans.GetInt() > 0 )
{
const char *pszNetworkid = event->GetString( "networkid" );
const char *pszIP = event->GetString( "ip" );
const char *pszCmdGiver = event->GetString( "by" );
if ( Q_strlen( pszIP ) > 0 )
{
Printf( "Removeip: \"<><><>\" was unbanned by \"%s\" (IP \"%s\")\n",
pszCmdGiver,
pszIP );
}
else
{
Printf( "Removeid: \"<><%s><>\" was unbanned by \"%s\"\n",
pszNetworkid,
pszCmdGiver );
}
}
}
}
struct TempFilename_t
{
bool IsGzip;
CUtlString Filename;
union
{
FileHandle_t file;
gzFile gzfile;
} fh;
};
// Given a base filename and an extension, try to find a file that doesn't exist which we can use. This is
// accomplished by appending 000, 001, etc. Set IsGzip to use gzopen instead of filesystem open.
static bool CreateTempFilename( TempFilename_t &info, const char *filenameBase, const char *ext, bool IsGzip )
{
// Check if a logfilename format has been specified - if it has, kick in new behavior.
const char *logfilename_format = sv_logfilename_format.GetString();
bool bHaveLogfilenameFormat = logfilename_format && logfilename_format[ 0 ];
info.fh.file = NULL;
info.fh.gzfile = 0;
info.IsGzip = IsGzip;
CUtlString fname = CUtlString( filenameBase ).StripExtension();
for ( int i = 0; i < 1000; i++ )
{
if ( bHaveLogfilenameFormat )
{
// For the first pass, let's try not adding the index.
if ( i == 0 )
info.Filename.Format( "%s.%s", fname.Get(), ext );
else
info.Filename.Format( "%s_%03i.%s", fname.Get(), i - 1, ext );
}
else
{
info.Filename.Format( "%s%03i.%s", fname.Get(), i, ext );
}
// Make sure the path exists.
info.Filename.FixSlashes();
COM_CreatePath( info.Filename );
if ( !g_pFileSystem->FileExists( info.Filename, "LOGDIR" ) )
{
// If the path doesn't exist, try opening the file. If that succeeded, return our filehandle and filename.
if ( !IsGzip )
{
info.fh.file = g_pFileSystem->Open( info.Filename, "wt", "LOGDIR" );
if ( info.fh.file )
return true;
}
else
{
info.fh.gzfile = gzopen( info.Filename, "wb6" );
if ( info.fh.gzfile )
return true;
}
}
}
info.Filename = NULL;
return false;
}
// Gzip Filename to Filename.gz.
static bool gzip_file_compress( const CUtlString &Filename )
{
bool bRet = false;
// Try to find a unique temp filename.
TempFilename_t info;
bRet = CreateTempFilename( info, Filename, "log.gz", true );
if ( !bRet )
return false;
Msg( "Compressing %s to %s...\n", Filename.Get(), info.Filename.Get() );
FILE *in = fopen( Filename, "rb" );
if ( in )
{
for (;;)
{
char buf[ 16384 ];
size_t len = fread( buf, 1, sizeof( buf ), in );
if ( ferror( in ) )
{
Msg( "%s: fread failed.\n", __FUNCTION__ );
break;
}
if (len == 0)
{
bRet = true;
break;
}
if ( (size_t)gzwrite( info.fh.gzfile, buf, len ) != len )
{
Msg( "%s: gzwrite failed.\n", __FUNCTION__ );
break;
}
}
if ( gzclose( info.fh.gzfile ) != Z_OK )
{
Msg( "%s: gzclose failed.\n", __FUNCTION__ );
bRet = false;
}
fclose( in );
}
return bRet;
}
static void FixupInvalidPathChars( char *filename )
{
if ( !filename )
return;
for ( ; filename[ 0 ]; filename++ )
{
switch ( filename[ 0 ] )
{
case ':':
case '\n':
case '\r':
case '\t':
case '.':
case '\\':
case '/':
filename[ 0 ] = '_';
break;
}
}
}
/*
====================
Log_Close
Close logging file
====================
*/
void CLog::Close( void )
{
if ( m_hLogFile != FILESYSTEM_INVALID_HANDLE )
{
Printf( "Log file closed.\n" );
g_pFileSystem->Close( m_hLogFile );
if ( sv_logfilecompress.GetBool() )
{
// Try to compress m_LogFilename to m_LogFilename.gz.
if ( gzip_file_compress( m_LogFilename ) )
{
Msg( " Success. Removing %s.\n", m_LogFilename.Get() );
g_pFileSystem->RemoveFile( m_LogFilename, "LOGDIR" );
}
}
}
m_hLogFile = FILESYSTEM_INVALID_HANDLE;
m_LogFilename = NULL;
}
/*
====================
Log_Flush
Flushes the log file to disk
====================
*/
void CLog::Flush( void )
{
if ( m_hLogFile != FILESYSTEM_INVALID_HANDLE )
{
g_pFileSystem->Flush( m_hLogFile );
}
}
/*
====================
Log_Open
Open logging file
====================
*/
void CLog::Open( void )
{
if ( !m_bActive || !sv_logfile.GetBool() )
return;
// Do we already have a log file (and we only want one)?
if ( m_hLogFile && sv_log_onefile.GetBool() )
return;
Close();
// Find a new log file slot.
tm today;
VCRHook_LocalTime( &today );
// safety check for invalid paths
const char *pszLogsDir = sv_logsdir.GetString();
if ( !COM_IsValidPath( pszLogsDir ) )
pszLogsDir = "logs";
// Get the logfilename format string.
char szLogFilename[ MAX_OSPATH ];
szLogFilename[ 0 ] = 0;
const char *logfilename_format = sv_logfilename_format.GetString();
if ( logfilename_format && logfilename_format[ 0 ] )
{
// Call strftime with the logfilename format.
strftime( szLogFilename, sizeof( szLogFilename ), logfilename_format, &today );
// Make sure it's nil terminated.
szLogFilename[ sizeof( szLogFilename ) - 1 ] = 0;
// Trim any leading and trailing whitespace.
Q_AggressiveStripPrecedingAndTrailingWhitespace( szLogFilename );
}
if ( !szLogFilename[ 0 ] )
{
// If we got nothing, default to old month / day of month behavior.
V_sprintf_safe( szLogFilename, "L%02i%02i", today.tm_mon + 1, today.tm_mday );
}
// Replace any screwy characters with underscores.
FixupInvalidPathChars( szLogFilename );
char szFileBase[ MAX_OSPATH ];
V_sprintf_safe( szFileBase, "%s/%s", pszLogsDir, szLogFilename );
// Try to get a free file.
TempFilename_t info;
if ( !CreateTempFilename( info, szFileBase, "log", false ) )
{
ConMsg( "Unable to open logfiles under %s\nLogging disabled\n", szFileBase );
return;
}
m_hLogFile = info.fh.file;
m_LogFilename = info.Filename;
ConMsg( "Server logging data to file %s\n", m_LogFilename.Get() );
Printf( "Log file started (file \"%s\") (game \"%s\") (version \"%i\")\n", m_LogFilename.Get(), com_gamedir, build_number() );
}