birkeh/o3de
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity
Files
4a1d713227af339b2fbb86eb02c936cc079863c5
o3de/Code/CryEngine/CrySystem/Log.cpp
T
lumberyard-employee-dm 4a1d713227 Fix recursive attempts to open the log file in the GameLauncher (#1114) 
* Fix recursive attempts to open the log file in the GameLauncher

The AzFramework Application has been updated to default the @user@ and
@log@ aliases to the <engine-root>/user and <engine-root>/user/log
folder respectively if a project isn't set.

Fixed the SystemFile class to support negative offsets if Seek() as per
standard seek function such as fseek

Updated the CrySystem CLog class to use SystemFile instead of FileIOBase
to avoid any asserts that would cause CLog::OpenFile to be recursively
called infinitely

* Removing unused Force Closed variable

* AZ::IO::SystemFile build fixes for Unix platforms. Added a copy constructor for LUAEditorContextInterface.h to fix the LuaEditor build

* Adding missing includes to the WindowsAPI and Android SystemFile headers
2021-06-03 22:36:34 -05:00

1552 lines
44 KiB
C++
Raw Blame History

/*
* All or portions of this file Copyright (c) Amazon.com, Inc. or its affiliates or
* its licensors.
*
* For complete copyright and license terms please see the LICENSE at the root of this
* distribution (the "License"). All use of this software is governed by the License,
* or, if provided, by the license below or the license accompanying this file. Do not
* remove or modify any license notices. This file is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
*
*/
// Original file Copyright Crytek GMBH or its affiliates, used under license.
// Description : Log related functions
#include "CrySystem_precompiled.h"
#include "Log.h"
//this should not be included here
#include <IConsole.h>
#include <ISystem.h>
#include "System.h"
#include "CryPath.h" // PathUtil::ReplaceExtension()
#include "UnicodeFunctions.h"
#include <AzFramework/IO/FileOperations.h>
#include <AzCore/IO/FileIO.h>
#include <AzCore/IO/Path/Path.h>
#ifdef WIN32
#include <time.h>
#endif
#if defined(LINUX) || defined(APPLE)
#include <syslog.h>
#endif
// Only accept logging from the main thread.
#ifdef WIN32
#define THREAD_SAFE_LOG
//#define THREAD_SAFE_LOG CryAutoCriticalSection scope_lock(m_logCriticalSection);
#else
#define THREAD_SAFE_LOG
#endif //WIN32
#define LOG_BACKUP_PATH "@log@/LogBackups"
#if defined(IOS)
#include <AzFramework/Utils/SystemUtilsApple.h>
#endif
//////////////////////////////////////////////////////////////////////
namespace LogCVars
{
float s_log_tick = 0;
int max_backup_directory_size_mb = 200; //200MB default
};
#ifndef _RELEASE
static CLog::LogStringType indentString (" ");
#endif
//////////////////////////////////////////////////////////////////////
CLog::CLog(ISystem* pSystem)
{
memset(m_szFilename, 0, MAX_FILENAME_SIZE);
memset(m_sBackupFilename, 0, MAX_FILENAME_SIZE);
//memset(m_szTemp,0,MAX_TEMP_LENGTH_SIZE);
m_pSystem = pSystem;
m_pLogVerbosity = 0;
m_pLogWriteToFile = 0;
m_pLogWriteToFileVerbosity = 0;
m_pLogVerbosityOverridesWriteToFile = 0;
m_pLogIncludeTime = 0;
m_pLogSpamDelay = 0;
m_pLogModule = 0;
m_fLastLoadingUpdateTime = -1.f; // for streaming engine update
m_backupLogs = true;
#if defined(SUPPORT_LOG_IDENTER)
m_indentation = 0;
BuildIndentString();
m_topIndenter = NULL;
#endif
m_nMainThreadId = CryGetCurrentThreadId();
#if defined(KEEP_LOG_FILE_OPEN)
m_bFirstLine = true;
#endif
m_iLastHistoryItem = 0;
memset(m_history, 0, sizeof(m_history));
CheckAndPruneBackupLogs();
}
void CLog::RegisterConsoleVariables()
{
IConsole* console = m_pSystem->GetIConsole();
#ifdef _RELEASE
#if defined(RELEASE_LOGGING)
#define DEFAULT_VERBOSITY 0
#else
#define DEFAULT_VERBOSITY -1
#endif
#else
#define DEFAULT_VERBOSITY 3
#endif
if (console)
{
m_pLogVerbosity = REGISTER_INT("log_Verbosity", DEFAULT_VERBOSITY, VF_DUMPTODISK,
"defines the verbosity level for log messages written to console\n"
"-1=suppress all logs (including eAlways)\n"
"0=suppress all logs(except eAlways)\n"
"1=additional errors\n"
"2=additional warnings\n"
"3=additional messages\n"
"4=additional comments");
//writing to game.log during game play causes stalls on consoles
m_pLogWriteToFile = REGISTER_INT("log_WriteToFile", 1, VF_DUMPTODISK, "toggle whether to write log to file (game.log)");
m_pLogWriteToFileVerbosity = REGISTER_INT("log_WriteToFileVerbosity", DEFAULT_VERBOSITY, VF_DUMPTODISK,
"defines the verbosity level for log messages written to files\n"
"-1=suppress all logs (including eAlways)\n"
"0=suppress all logs(except eAlways)\n"
"1=additional errors\n"
"2=additional warnings\n"
"3=additional messages\n"
"4=additional comments");
m_pLogVerbosityOverridesWriteToFile = REGISTER_INT("log_VerbosityOverridesWriteToFile", 1, VF_DUMPTODISK, "when enabled, setting log_verbosity to 0 will stop all logging including writing to file");
// put time into begin of the string if requested by cvar
m_pLogIncludeTime = REGISTER_INT("log_IncludeTime", 0, 0,
"Toggles time stamping of log entries.\n"
"Usage: log_IncludeTime [0/1/2/3/4/5]\n"
" 0=off (default)\n"
" 1=current time\n"
" 2=relative time\n"
" 3=current+relative time\n"
" 4=absolute time in seconds since this mode was started\n"
" 5=current time+server time"
" 6=current date+current time");
m_pLogSpamDelay = REGISTER_FLOAT("log_SpamDelay", 0.0f, 0, "Sets the minimum time interval between messages classified as spam");
m_pLogModule = REGISTER_STRING("log_Module", "", VF_NULL, "Only show warnings from specified module");
REGISTER_CVAR2("log_tick", &LogCVars::s_log_tick, LogCVars::s_log_tick, 0, "When not 0, writes tick log entry into the log file, every N seconds");
REGISTER_CVAR2("max_log_backup_mb", &LogCVars::max_backup_directory_size_mb, LogCVars::max_backup_directory_size_mb, 0, "Maximum size of backup logs to keep on disk (in MB)");
#if defined(KEEP_LOG_FILE_OPEN)
REGISTER_COMMAND("log_flush", &LogFlushFile, 0, "Flush the log file");
#endif
}
#undef DEFAULT_VERBOSITY
}
//////////////////////////////////////////////////////////////////////
CLog::~CLog()
{
#if defined(SUPPORT_LOG_IDENTER)
while (m_topIndenter)
{
m_topIndenter->Enable(false);
}
assert (m_indentation == 0);
#endif
CreateBackupFile();
UnregisterConsoleVariables();
CloseLogFile();
}
void CLog::UnregisterConsoleVariables()
{
m_pLogVerbosity = 0;
m_pLogWriteToFile = 0;
m_pLogWriteToFileVerbosity = 0;
m_pLogVerbosityOverridesWriteToFile = 0;
m_pLogIncludeTime = 0;
m_pLogSpamDelay = 0;
}
//////////////////////////////////////////////////////////////////////////
void CLog::CloseLogFile()
{
m_logFileHandle.Close();
}
//////////////////////////////////////////////////////////////////////////
bool CLog::OpenLogFile(const char* filename, int mode)
{
if (m_logFileHandle.IsOpen())
{
// Can only AZ_Assert if a file is open, otherwise the AZ_Assert
// would eventually lead to OpenLogFile being opened up again
AZ_Assert(false, "Attempt to open log file when one is already open. This would lead to a handle leak.");
return false;
}
if (filename == nullptr || filename[0] == '\0')
{
return false;
}
// it is assumed that @log@ points at the appropriate place (so for apple, to the user profile dir)
AZ::IO::FileIOBase* fileSystem = AZ::IO::FileIOBase::GetDirectInstance();
if (AZ::IO::FixedMaxPath logFilePath; fileSystem->ReplaceAlias(logFilePath, filename))
{
logFilePath = logFilePath.LexicallyNormal();
m_logFileHandle.Open(logFilePath.c_str(), mode);
}
if (m_logFileHandle.IsOpen())
{
#if defined(KEEP_LOG_FILE_OPEN)
m_bFirstLine = true;
#endif
}
else
{
#if defined(LINUX) || defined(APPLE)
syslog(LOG_NOTICE, "Failed to open log file [%s], mode [%d]", filename, mode);
#endif
}
return m_logFileHandle.IsOpen();
}
//////////////////////////////////////////////////////////////////////////
void CLog::SetVerbosity(int verbosity)
{
if (m_pLogVerbosity)
{
m_pLogVerbosity->Set(verbosity);
}
}
bool CLog::CheckLogFormatter(const char* formatter)
{
if (!formatter)
{
AZ_Assert(false, "code problem - A message was sent to the log system with nullptr as the formatting string.");
return false;
}
if (formatter[0] == 0)
{
// if there's nothing to log, we don't log anything. Blank lines at least contain a carriage return or something.
return false;
}
return true;
}
//////////////////////////////////////////////////////////////////////////
#if !defined(EXCLUDE_NORMAL_LOG)
void CLog::LogWarning(const char* szFormat, ...)
{
if (!CheckLogFormatter(szFormat))
{
return;
}
va_list ArgList;
char szBuffer[MAX_WARNING_LENGTH];
va_start(ArgList, szFormat);
vsnprintf_s(szBuffer, sizeof(szBuffer), sizeof(szBuffer) - 1, szFormat, ArgList);
szBuffer[sizeof(szBuffer) - 1] = '\0';
va_end(ArgList);
va_start(ArgList, szFormat);
LogV(eWarning, szFormat, ArgList);
va_end(ArgList);
}
//////////////////////////////////////////////////////////////////////////
void CLog::LogError(const char* szFormat, ...)
{
if (!CheckLogFormatter(szFormat))
{
return;
}
va_list ArgList;
char szBuffer[MAX_WARNING_LENGTH];
va_start(ArgList, szFormat);
vsnprintf_s(szBuffer, sizeof(szBuffer), sizeof(szBuffer) - 1, szFormat, ArgList);
szBuffer[sizeof(szBuffer) - 1] = '\0';
va_end(ArgList);
va_start(ArgList, szFormat);
LogV(eError, szFormat, ArgList);
va_end(ArgList);
}
//////////////////////////////////////////////////////////////////////////
void CLog::Log(const char* szFormat, ...)
{
if (!CheckLogFormatter(szFormat))
{
return;
}
va_list arg;
va_start(arg, szFormat);
LogV (eMessage, szFormat, arg);
va_end(arg);
}
//////////////////////////////////////////////////////////////////////////
void CLog::LogAlways(const char* szFormat, ...)
{
if (!CheckLogFormatter(szFormat))
{
return;
}
va_list arg;
va_start(arg, szFormat);
LogV (eAlways, szFormat, arg);
va_end(arg);
}
#endif // !defined(EXCLUDE_NORMAL_LOG)
int MatchStrings(const char* str0, const char* str1)
{
const char* str[] = { str0, str1 };
int i, bSkipWord, bAlpha[2], bWS[2], bStop = 0, nDiffs = 0, nWordDiffs, len = 0;
do
{
for (i = 0; i < 2; i++) // skip the spaces, stop at 0
{
while (*str[i] == ' ')
{
if (!*str[i]++)
{
goto break2;
}
}
}
bWS[0] = bWS[1] = nWordDiffs = bSkipWord = 0;
do
{
for (i = bAlpha[0] = bAlpha[1] = 0; i < 2; i++)
{
if (!bWS[i])
{
do
{
int chr = *str[i]++;
bSkipWord |= iszero(chr - '\\') | iszero(chr - '/') | iszero(chr - '_'); // ignore different words with \,_,/
bAlpha[i] = inrange(chr, 'A' - 1, 'Z' + 1) | inrange(chr, 'a' - 1, 'z' + 1);
bWS[i] = iszero(chr - ' ');
bStop |= iszero(chr);
} while (!(bAlpha[i] | bWS[i] | bStop)); // wait for a letter or a space in each input string
}
}
len += bAlpha[0] & bAlpha[1];
nWordDiffs += 1 - iszero((int)(*str[0] - *str[1])) & - (bAlpha[0] & bAlpha[1]); // count diffs in this word
} while ((1 - bWS[0] | 1 - bWS[1]) & 1 - bStop); // wait for space (word end) in both strings
nDiffs += nWordDiffs & ~-bSkipWord;
} while (!bStop);
break2:
return nDiffs * 10 < len;
}
//will log the text both to file and console
//////////////////////////////////////////////////////////////////////
void CLog::LogV(const ELogType type, const char* szFormat, va_list args)
{
// this is here in case someone called LogV directly, with an invalid formatter.
if (!CheckLogFormatter(szFormat))
{
return;
}
LogV(type, 0, szFormat, args);
}
void CLog::LogV(const ELogType type, [[maybe_unused]]int flags, const char* szFormat, va_list args)
{
// this is here in case someone called LogV directly, with an invalid formatter.
if (!CheckLogFormatter(szFormat))
{
return;
}
if (!szFormat)
{
return;
}
if (m_pLogVerbosityOverridesWriteToFile && m_pLogVerbosityOverridesWriteToFile->GetIVal())
{
if (m_pLogVerbosity && m_pLogVerbosity->GetIVal() < 0)
{
return;
}
}
FUNCTION_PROFILER(GetISystem(), PROFILE_SYSTEM);
LOADING_TIME_PROFILE_SECTION(GetISystem());
bool bfile = false, bconsole = false;
const char* szCommand = szFormat;
uint8 DefaultVerbosity = 0; // 0 == Always log (except for special -1 verbosity overrides)
switch (type)
{
case eAlways:
DefaultVerbosity = 0;
break;
case eWarningAlways:
DefaultVerbosity = 0;
break;
case eErrorAlways:
DefaultVerbosity = 0;
break;
case eInput:
DefaultVerbosity = 0;
break;
case eInputResponse:
DefaultVerbosity = 0;
break;
case eError:
DefaultVerbosity = 1;
break;
case eWarning:
DefaultVerbosity = 2;
break;
case eMessage:
DefaultVerbosity = 3;
break;
case eComment:
DefaultVerbosity = 4;
break;
default:
assert(0);
}
szCommand = CheckAgainstVerbosity(szFormat, bfile, bconsole, DefaultVerbosity);
if (!bfile && !bconsole)
{
return;
}
LogStringType tempString;
char szBuffer[MAX_WARNING_LENGTH + 32];
char* szString = szBuffer;
char* szAfterColour = szString;
size_t prefixSize = 0;
switch (type)
{
case eWarning:
case eWarningAlways:
cry_strcpy(szString, MAX_WARNING_LENGTH, "$6[Warning] ");
szString += 12; // strlen("$6[Warning] ");
szAfterColour += 2;
prefixSize = 12;
break;
case eError:
case eErrorAlways:
cry_strcpy(szString, MAX_WARNING_LENGTH, "$4[Error] ");
szString += 10; // strlen("$4[Error] ");
szAfterColour += 2;
prefixSize = 10;
break;
default:
break;
}
int bufferlen = sizeof(szBuffer) - prefixSize;
if (bufferlen > 0)
{
#if defined(AZ_RESTRICTED_PLATFORM)
#include AZ_RESTRICTED_FILE(Log_cpp)
#endif
#if defined(AZ_RESTRICTED_SECTION_IMPLEMENTED)
#undef AZ_RESTRICTED_SECTION_IMPLEMENTED
#else
int count = vsnprintf_s(szString, bufferlen, bufferlen - 1, szCommand, args);
#endif
if (count == -1 || count >= bufferlen)
{
szBuffer[sizeof(szBuffer) - 1] = '\0';
}
}
if (type == eWarningAlways || type == eWarning || type == eError || type == eErrorAlways)
{
const char* sAssetScope = GetAssetScopeString();
if (*sAssetScope)
{
stack_string s = szBuffer;
s += "\t<Scope> ";
s += sAssetScope;
cry_strcpy(szBuffer, s.c_str());
}
}
float dt;
const char* szSpamCheck = *szFormat == '%' ? szString : szFormat;
if (m_pLogSpamDelay && (dt = m_pLogSpamDelay->GetFVal()) > 0.0f && type != eAlways && type != eInputResponse)
{
const int sz = sizeof(m_history) / sizeof(m_history[0]);
int i, j;
float time = m_pSystem->GetITimer()->GetCurrTime();
for (i = m_iLastHistoryItem, j = 0; m_history[i].time > time - dt && j < sz; j++, i = i - 1 & sz - 1)
{
if (m_history[i].type != type)
{
continue;
}
if (m_history[i].ptr == szSpamCheck && *(int*)m_history[i].str == *(int*)szFormat || MatchStrings(m_history[i].str, szSpamCheck))
{
return;
}
}
i = m_iLastHistoryItem = m_iLastHistoryItem + 1 & sz - 1;
cry_strcpy(m_history[i].str, m_history[i].ptr = szSpamCheck);
m_history[i].type = type;
m_history[i].time = time;
}
LogString(szAfterColour, type);
if (bfile)
{
LogStringToFile(szAfterColour, type, false, MessageQueueState::NotQueued);
}
if (bconsole)
{
LogStringToConsole(szBuffer, ELogType::eAlways, false);
}
switch (type)
{
case eAlways:
case eInput:
case eInputResponse:
case eComment:
case eMessage:
GetISystem()->GetIRemoteConsole()->AddLogMessage(szString);
break;
case eWarning:
case eWarningAlways:
GetISystem()->GetIRemoteConsole()->AddLogWarning(szString);
break;
case eError:
case eErrorAlways:
GetISystem()->GetIRemoteConsole()->AddLogError(szString);
break;
}
}
//will log the text both to the end of file and console
//////////////////////////////////////////////////////////////////////
#if !defined(EXCLUDE_NORMAL_LOG)
void CLog::LogPlus(const char* szFormat, ...)
{
if (!CheckLogFormatter(szFormat))
{
return;
}
if (m_pLogVerbosity && m_pLogVerbosity->GetIVal() < 0)
{
return;
}
if (m_pLogSpamDelay && m_pLogSpamDelay->GetFVal())
{ // Vlad: SpamDelay does not work correctly with LogPlus
return;
}
LOADING_TIME_PROFILE_SECTION(GetISystem());
if (!szFormat)
{
return;
}
bool bfile = false, bconsole = false;
const char* szCommand = CheckAgainstVerbosity(szFormat, bfile, bconsole);
if (!bfile && !bconsole)
{
return;
}
va_list arglist;
char szTemp[MAX_TEMP_LENGTH_SIZE];
va_start(arglist, szFormat);
vsnprintf_s(szTemp, sizeof(szTemp), sizeof(szTemp) - 1, szCommand, arglist);
szTemp[sizeof(szTemp) - 1] = 0;
va_end(arglist);
if (bfile)
{
LogToFilePlus(szTemp);
}
if (bconsole)
{
LogToConsolePlus(szTemp);
}
}
//log to console only
//////////////////////////////////////////////////////////////////////
void CLog::LogStringToConsole(const char* szString, ELogType logType, bool bAdd)
{
#if defined(_RELEASE) && defined(EXCLUDE_NORMAL_LOG) // no console logging in release
return;
#endif
if (LogToMainThread(szString, logType, bAdd, SLogMsg::Destination::Console))
{
return;
}
if (!szString)
{
return;
}
if (!m_pSystem)
{
return;
}
IConsole* console = m_pSystem->GetIConsole();
if (!console)
{
return;
}
LogStringType tempString;
tempString = szString;
if (tempString.length() > MAX_TEMP_LENGTH_SIZE)
{
tempString.erase(MAX_TEMP_LENGTH_SIZE);
}
// add \n at end.
if (tempString.length() > 0 && tempString[tempString.length() - 1] != '\n')
{
tempString += '\n';
}
if (bAdd)
{
console->PrintLinePlus(tempString.c_str());
}
else
{
console->PrintLine(tempString.c_str());
}
// Call callback function.
if (!m_callbacks.empty())
{
for (Callbacks::iterator it = m_callbacks.begin(); it != m_callbacks.end(); ++it)
{
(*it)->OnWriteToConsole(tempString.c_str(), !bAdd);
}
}
}
//log to console only
//////////////////////////////////////////////////////////////////////
void CLog::LogToConsole(const char* szFormat, ...)
{
if (!CheckLogFormatter(szFormat))
{
return;
}
if (m_pLogVerbosity && m_pLogVerbosity->GetIVal() < 0)
{
return;
}
if (!szFormat)
{
return;
}
bool bfile = false, bconsole = false;
const char* szCommand = CheckAgainstVerbosity(szFormat, bfile, bconsole);
if (!bconsole)
{
return;
}
va_list arglist;
char szBuffer[MAX_WARNING_LENGTH];
va_start(arglist, szFormat);
vsnprintf_s(szBuffer, sizeof(szBuffer), sizeof(szBuffer) - 1, szCommand, arglist);
szBuffer[sizeof(szBuffer) - 1] = 0;
va_end(arglist);
LogStringToConsole(szBuffer, ELogType::eAlways, false);
}
//////////////////////////////////////////////////////////////////////
void CLog::LogToConsolePlus(const char* szFormat, ...)
{
if (!CheckLogFormatter(szFormat))
{
return;
}
if (m_pLogVerbosity && m_pLogVerbosity->GetIVal() < 0)
{
return;
}
if (!szFormat)
{
return;
}
bool bfile = false, bconsole = false;
const char* szCommand = CheckAgainstVerbosity(szFormat, bfile, bconsole);
if (!bconsole)
{
return;
}
va_list arglist;
char szTemp[MAX_TEMP_LENGTH_SIZE];
va_start(arglist, szFormat);
vsnprintf_s(szTemp, sizeof(szTemp), sizeof(szTemp) - 1, szCommand, arglist);
szTemp[sizeof(szTemp) - 1] = 0;
va_end(arglist);
if (!m_pSystem)
{
return;
}
LogStringToConsole(szTemp, ELogType::eAlways, true);
}
#endif // !defined(EXCLUDE_NORMAL_LOG)
//////////////////////////////////////////////////////////////////////
static void RemoveColorCodeInPlace(CLog::LogStringType& rStr)
{
char* s = (char*)rStr.c_str();
char* d = s;
while (*s != 0)
{
if (*s == '$' && *(s + 1) >= '0' && *(s + 1) <= '9')
{
s += 2;
continue;
}
*d++ = *s++;
}
*d = 0;
rStr.resize(d - rStr.c_str());
}
#if defined(SUPPORT_LOG_IDENTER)
//////////////////////////////////////////////////////////////////////
void CLog::BuildIndentString()
{
m_indentWithString = "";
for (uint8 i = 0; i < m_indentation; ++i)
{
m_indentWithString = indentString + m_indentWithString;
}
}
//////////////////////////////////////////////////////////////////////
void CLog::Indent(CLogIndenter* indenter)
{
indenter->SetNextIndenter(m_topIndenter);
m_topIndenter = indenter;
++m_indentation;
BuildIndentString();
}
//////////////////////////////////////////////////////////////////////
void CLog::Unindent(CLogIndenter* indenter)
{
assert (indenter == m_topIndenter);
assert (m_indentation);
m_topIndenter = m_topIndenter->GetNextIndenter();
--m_indentation;
BuildIndentString();
}
//////////////////////////////////////////////////////////////////////////
void CLog::PushAssetScopeName(const char* sAssetType, const char* sName)
{
assert(sAssetType);
assert(sName);
SAssetScopeInfo as;
as.sType = sAssetType;
as.sName = sName;
CryAutoCriticalSection scope_lock(m_assetScopeQueueLock);
m_assetScopeQueue.push_back(as);
}
void CLog::PopAssetScopeName()
{
CryAutoCriticalSection scope_lock(m_assetScopeQueueLock);
assert(!m_assetScopeQueue.empty());
if (!m_assetScopeQueue.empty())
{
m_assetScopeQueue.pop_back();
}
}
//////////////////////////////////////////////////////////////////////////
const char* CLog::GetAssetScopeString()
{
CryAutoCriticalSection scope_lock(m_assetScopeQueueLock);
m_assetScopeString.clear();
for (size_t i = 0; i < m_assetScopeQueue.size(); i++)
{
m_assetScopeString += "[";
m_assetScopeString += m_assetScopeQueue[i].sType;
m_assetScopeString += "]";
m_assetScopeString += m_assetScopeQueue[i].sName;
if (i < m_assetScopeQueue.size() - 1)
{
m_assetScopeString += " > ";
}
}
return m_assetScopeString.c_str();
};
#endif
bool CLog::LogToMainThread(const char* szString, ELogType logType, bool bAdd, SLogMsg::Destination destination)
{
if (CryGetCurrentThreadId() != m_nMainThreadId)
{
// When logging from other thread then main, push all log strings to queue.
SLogMsg msg;
cry_strcpy(msg.msg, szString);
msg.bAdd = bAdd;
msg.destination = destination;
msg.logType = logType;
m_threadSafeMsgQueue.push(msg);
return true;
}
return false;
}
//////////////////////////////////////////////////////////////////////
#if !defined(EXCLUDE_NORMAL_LOG)
void CLog::LogStringToFile(const char* szString, ELogType logType, bool bAdd, [[maybe_unused]] MessageQueueState queueState)
{
#if defined(_RELEASE) && defined(EXCLUDE_NORMAL_LOG) // no file logging in release
return;
#endif
if (!szString)
{
return;
}
if (!m_pSystem)
{
return;
}
LogStringType tempString;
tempString = szString;
// this is a temp timeStr, it is reused in many branches(moved here to reduce stack usage)
LogStringType timeStr;
// Skip any non character.
if (tempString.length() > 0 && tempString.at(0) < 32)
{
tempString.erase(0, 1);
}
RemoveColorCodeInPlace(tempString);
bool bIsMainThread = LogToMainThread(szString, logType, bAdd, SLogMsg::Destination::File) == false;
#if defined(_RELEASE)
if (!bIsMainThread)
{
return;
}
#endif
#if defined(SUPPORT_LOG_IDENTER)
if (bIsMainThread)
{
if (m_topIndenter)
{
m_topIndenter->DisplaySectionText();
}
tempString = m_indentWithString + tempString;
}
#endif
if (m_pLogIncludeTime && gEnv && gEnv->pTimer)
{
uint32 dwCVarState = m_pLogIncludeTime->GetIVal();
// char szTemp[MAX_TEMP_LENGTH_SIZE];
if (dwCVarState == 1) // Log_IncludeTime
{
char sTime[128];
time_t ltime;
time(&ltime);
#ifdef AZ_COMPILER_MSVC
struct tm today;
localtime_s(&today, &ltime);
strftime(sTime, 20, "<%H:%M:%S> ", &today);
#else
auto today = localtime(&ltime);
strftime(sTime, 20, "<%H:%M:%S> ", today);
#endif
timeStr.clear();
timeStr.assign(sTime);
tempString = timeStr + tempString;
}
else if (dwCVarState == 2) // Log_IncludeTime
{
static CTimeValue lasttime;
CTimeValue currenttime = gEnv->pTimer->GetAsyncTime();
if (lasttime != CTimeValue())
{
timeStr.clear();
uint32 dwMs = (uint32)((currenttime - lasttime).GetMilliSeconds());
timeStr.Format("<%3d.%.3d>: ", dwMs / 1000, dwMs % 1000);
tempString = timeStr + tempString;
}
lasttime = currenttime;
}
else if (dwCVarState == 3) // Log_IncludeTime
{
char sTime[128];
time_t ltime;
time(&ltime);
#ifdef AZ_COMPILER_MSVC
struct tm today;
localtime_s(&today, &ltime);
strftime(sTime, 20, "<%H:%M:%S> ", &today);
#else
auto today = localtime(&ltime);
strftime(sTime, 20, "<%H:%M:%S> ", today);
#endif
tempString = LogStringType(sTime) + tempString;
static CTimeValue lasttime;
CTimeValue currenttime = gEnv->pTimer->GetAsyncTime();
if (lasttime != CTimeValue())
{
timeStr.clear();
uint32 dwMs = (uint32)((currenttime - lasttime).GetMilliSeconds());
timeStr.Format("<%3d.%.3d>: ", dwMs / 1000, dwMs % 1000);
tempString = timeStr + tempString;
}
lasttime = currenttime;
}
else if (dwCVarState == 4) // Log_IncludeTime
{
static bool bFirst = true;
if (gEnv->pTimer)
{
static CTimeValue lasttime;
CTimeValue currenttime = gEnv->pTimer->GetAsyncTime();
if (lasttime != CTimeValue())
{
timeStr.clear();
uint32 dwMs = (uint32)((currenttime - lasttime).GetMilliSeconds());
timeStr.Format("<%3d.%.3d>: ", dwMs / 1000, dwMs % 1000);
tempString = timeStr + tempString;
}
if (bFirst)
{
lasttime = currenttime;
bFirst = false;
}
}
}
else if (dwCVarState == 5) // Log_IncludeTime
{
char sTime[128];
time_t ltime;
time(&ltime);
#ifdef AZ_COMPILER_MSVC
struct tm today;
localtime_s(&today, &ltime);
strftime(sTime, 20, "<%H:%M:%S> ", &today);
#else
auto today = localtime(&ltime);
strftime(sTime, 20, "<%H:%M:%S> ", today);
#endif
tempString = LogStringType(sTime) + tempString;
}
else if (dwCVarState == 6) // Log_IncludeTime
{
char sTime[128];
time_t ltime;
time(&ltime);
#ifdef AZ_COMPILER_MSVC
struct tm today;
localtime_s(&today, &ltime);
strftime(sTime, 40, "<%Y-%m-%d %H:%M:%S> ", &today);
#else
auto today = localtime(&ltime);
strftime(sTime, 40, "<%Y-%m-%d %H:%M:%S> ", today);
#endif
tempString = LogStringType(sTime) + tempString;
}
}
if (tempString.empty() || tempString[tempString.length() - 1] != '\n')
{
tempString += '\n';
}
// do not OutputDebugString in release.
#if !defined(_RELEASE)
if (queueState == MessageQueueState::NotQueued)
{
// Note: OutputDebugString(A) only accepts current ANSI code-page, and the W variant will call the A variant internally.
// Here we replace non-ASCII characters with '?', which is the same as OutputDebugStringW will do for non-ANSI.
// Thus, we discard slightly more characters (ie, those inside the current ANSI code-page, but outside ASCII).
// In exchange, we save double-converting that would have happened otherwise (UTF-8 -> UTF-16 -> ANSI).
LogStringType asciiString;
Unicode::ConvertSafe<Unicode::EErrorRecovery::eErrorRecovery_FallbackLatin1ThenDiscard, Unicode::eEncoding_ASCII, Unicode::eEncoding_UTF8>(asciiString, tempString);
OutputDebugString(asciiString.c_str());
}
if (!bIsMainThread)
{
return;
}
#endif // !defined(_RELEASE)
//////////////////////////////////////////////////////////////////////////
// Call callback function.
if (!m_callbacks.empty())
{
for (Callbacks::iterator it = m_callbacks.begin(); it != m_callbacks.end(); ++it)
{
(*it)->OnWriteToFile(tempString.c_str(), !bAdd);
}
}
//////////////////////////////////////////////////////////////////////////
//////////////////////////////////////////////////////////////////////////
// Write to file.
//////////////////////////////////////////////////////////////////////////
int logToFile = m_pLogWriteToFile ? m_pLogWriteToFile->GetIVal() : 1;
if (logToFile)
{
if (!m_logFileHandle.IsOpen())
{
constexpr auto openMode = AZ::IO::SystemFile::OpenMode::SF_OPEN_APPEND
| AZ::IO::SystemFile::OpenMode::SF_OPEN_CREATE
| AZ::IO::SystemFile::OpenMode::SF_OPEN_WRITE_ONLY;
OpenLogFile(m_szFilename, openMode);
}
if (m_logFileHandle.IsOpen())
{
#if defined(KEEP_LOG_FILE_OPEN)
if (m_bFirstLine)
{
m_bFirstLine = false;
}
#endif
if (bAdd)
{
// if adding to a prior line erase the \n at the end.
m_logFileHandle.Seek(-2, AZ::IO::SystemFile::SeekMode::SF_SEEK_END);
}
m_logFileHandle.Write(tempString.c_str(), tempString.size());
#if !defined(KEEP_LOG_FILE_OPEN)
CloseLogFile();
#endif
// do not use FLUSH on log files. Doing so will slow the engine down greatly when logging.
// (the log is flushed automatically when an unhandled exception occurs)
}
}
}
void CLog::LogString(const char* szString, ELogType logType)
{
if (LogToMainThread(szString, logType, false, SLogMsg::Destination::Default))
{
return;
}
for (auto callback : m_callbacks)
{
callback->OnWrite(szString, logType);
}
}
//same as above but to a file
//////////////////////////////////////////////////////////////////////
void CLog::LogToFilePlus(const char* szFormat, ...)
{
if (!CheckLogFormatter(szFormat))
{
return;
}
if (m_pLogVerbosity && m_pLogVerbosity->GetIVal() < 0)
{
return;
}
if (!m_szFilename[0] || !szFormat)
{
return;
}
bool bfile = false, bconsole = false;
const char* szCommand = CheckAgainstVerbosity(szFormat, bfile, bconsole);
if (!bfile)
{
return;
}
char szTemp[MAX_TEMP_LENGTH_SIZE];
va_list arglist;
va_start(arglist, szFormat);
vsnprintf_s(szTemp, sizeof(szTemp), sizeof(szTemp) - 1, szCommand, arglist);
szTemp[sizeof(szTemp) - 1] = 0;
va_end(arglist);
LogStringToFile(szTemp, ELogType::eAlways, true, MessageQueueState::NotQueued);
}
//log to the file specified in setfilename
//////////////////////////////////////////////////////////////////////
void CLog::LogToFile(const char* szFormat, ...)
{
if (!CheckLogFormatter(szFormat))
{
return;
}
if (m_pLogVerbosity && m_pLogVerbosity->GetIVal() < 0)
{
return;
}
if (!m_szFilename[0] || !szFormat)
{
return;
}
bool bfile = false, bconsole = false;
const char* szCommand = CheckAgainstVerbosity(szFormat, bfile, bconsole);
if (!bfile)
{
return;
}
char szTemp[MAX_TEMP_LENGTH_SIZE];
va_list arglist;
va_start(arglist, szFormat);
vsnprintf_s(szTemp, sizeof(szTemp), sizeof(szTemp) - 1, szCommand, arglist);
szTemp[sizeof(szTemp) - 1] = 0;
va_end(arglist);
LogStringToFile(szTemp, ELogType::eAlways, false, MessageQueueState::NotQueued);
}
#endif // !defined(EXCLUDE_NORMAL_LOG)
//////////////////////////////////////////////////////////////////////
void CLog::CreateBackupFile() const
{
LOADING_TIME_PROFILE_SECTION;
if (!m_backupLogs)
{
return;
}
#if AZ_LEGACY_CRYSYSTEM_TRAIT_ALLOW_CREATE_BACKUP_LOG_FILE
// simple:
// string bakpath = PathUtil::ReplaceExtension(m_szFilename,"bak");
// CopyFile(m_szFilename,bakpath.c_str(),false);
// boswej: only create a backup if logging to the engine root, otherwise the
// log output has been overridden and the user is responsible
string logDir = PathUtil::RemoveSlash(PathUtil::ToUnixPath(PathUtil::GetParentDirectory(m_szFilename)));
string sExt = PathUtil::GetExt(m_szFilename);
string sFileWithoutExt = PathUtil::GetFileName(m_szFilename);
{
assert(::strstr(sFileWithoutExt, ":") == 0);
assert(::strstr(sFileWithoutExt, "\\") == 0);
}
PathUtil::RemoveExtension(sFileWithoutExt);
AZ::IO::FileIOBase* fileSystem = AZ::IO::FileIOBase::GetDirectInstance();
AZ::IO::HandleType inFileHandle = AZ::IO::InvalidHandle;
fileSystem->Open(m_szFilename, AZ::IO::OpenMode::ModeRead | AZ::IO::OpenMode::ModeBinary, inFileHandle);
string sBackupNameAttachment;
// parse backup name attachment
// e.g. BackupNameAttachment="attachment name"
if (inFileHandle != AZ::IO::InvalidHandle)
{
bool bKeyFound = false;
string sName;
while (!fileSystem->Eof(inFileHandle))
{
uint8 c = AZ::IO::GetC(inFileHandle);
if (c == '\"')
{
if (!bKeyFound)
{
bKeyFound = true;
if (sName.find("BackupNameAttachment=") == string::npos)
{
#ifdef WIN32
OutputDebugString("Log::CreateBackupFile ERROR '");
OutputDebugString(sName.c_str());
OutputDebugString("' not recognized \n");
#endif
assert(0); // broken log file? - first line should include this name - written by LogVersion()
return;
}
sName.clear();
}
else
{
sBackupNameAttachment = sName;
break;
}
continue;
}
if (c >= ' ')
{
sName += c;
}
else
{
break;
}
}
fileSystem->Close(inFileHandle);
}
string bakdest = PathUtil::Make(LOG_BACKUP_PATH, sFileWithoutExt + sBackupNameAttachment + "." + sExt);
fileSystem->CreatePath(LOG_BACKUP_PATH);
cry_strcpy(m_sBackupFilename, bakdest.c_str());
// Remove any existing backup file with the same name first since the copy will fail otherwise.
fileSystem->Remove(m_sBackupFilename);
fileSystem->Copy(m_szFilename, bakdest);
#endif // AZ_LEGACY_CRYSYSTEM_TRAIT_ALLOW_CREATE_BACKUP_LOG_FILE
}
void CLog::CheckAndPruneBackupLogs() const
{
AZ::IO::FileIOBase* fileSystem = AZ::IO::FileIOBase::GetDirectInstance();
AZ::u64 totalBackupDirectorySize = 0;
struct fileInfo
{
time_t modTime;
AZStd::string filename;
AZ::u64 filesize;
fileInfo(time_t _modTime, const char* _name, AZ::u64 _size)
{
modTime = _modTime;
filename = _name;
filesize = _size;
}
};
AZStd::list<fileInfo> fileInfoList;
// Now that we've copied the new log over, lets check the size of the backup folder and trim it as necessary to keep it within appropriate limits
AZ::IO::Result res = fileSystem->FindFiles(LOG_BACKUP_PATH, "*",
[&totalBackupDirectorySize, &fileSystem, &fileInfoList](const char* fileName)
{
AZ::u64 size;
fileSystem->Size(fileName, size);
AZ::u64 modTime = fileSystem->ModificationTime(fileName);
fileInfoList.push_back(fileInfo(modTime, fileName, size));
totalBackupDirectorySize += size;
return true;
});
AZ::u64 max_size = LogCVars::max_backup_directory_size_mb;
max_size = max_size << 20; // Convert from MB to bytes
if (totalBackupDirectorySize > max_size)
{
// Sort the list from lowest to highest modtime (oldest to newest logs)
fileInfoList.sort([](const fileInfo &a, const fileInfo&b) { return a.modTime < b.modTime; });
while (totalBackupDirectorySize > max_size && fileInfoList.size() > 0)
{
fileSystem->Remove(fileInfoList.front().filename.c_str());
totalBackupDirectorySize -= fileInfoList.front().filesize;
fileInfoList.pop_front();
}
}
}
//set the file used to log to disk
//////////////////////////////////////////////////////////////////////
bool CLog::SetFileName(const char* fileNameOrAbsolutePath, bool backupLogs)
{
m_backupLogs = backupLogs;
if (!fileNameOrAbsolutePath)
{
return false;
}
azstrncpy(m_szFilename, AZ_ARRAY_SIZE(m_szFilename), fileNameOrAbsolutePath, sizeof(m_szFilename));
CreateBackupFile();
AZ::IO::FileIOBase* fileSystem = AZ::IO::FileIOBase::GetDirectInstance();
AZ::IO::FixedMaxPath newLogFilePath;
if (fileSystem->ReplaceAlias(newLogFilePath, m_szFilename))
{
newLogFilePath = newLogFilePath.LexicallyNormal();
}
if (m_logFileHandle.IsOpen() && newLogFilePath != m_logFileHandle.Name())
{
constexpr auto openMode = AZ::IO::SystemFile::OpenMode::SF_OPEN_APPEND
| AZ::IO::SystemFile::OpenMode::SF_OPEN_CREATE
| AZ::IO::SystemFile::OpenMode::SF_OPEN_WRITE_ONLY;
if(AZ::IO::SystemFile newLogFile; newLogFile.Open(m_szFilename, openMode))
{
m_logFileHandle = AZStd::move(newLogFile);
}
}
return true;
}
//////////////////////////////////////////////////////////////////////////
const char* CLog::GetFileName()
{
return m_szFilename;
}
const char* CLog::GetBackupFileName()
{
return m_sBackupFilename;
}
//////////////////////////////////////////////////////////////////////
void CLog::UpdateLoadingScreen(const char* szFormat, ...)
{
#if !defined(EXCLUDE_NORMAL_LOG)
if (szFormat)
{
// This function is OK to call with nullptr, but then it does not log anything.
va_list args;
va_start(args, szFormat);
LogV(ILog::eMessage, szFormat, args);
va_end(args);
}
#endif
}
//////////////////////////////////////////////////////////////////////////
int CLog::GetVerbosityLevel()
{
if (m_pLogVerbosity)
{
return (m_pLogVerbosity->GetIVal());
}
return (0);
}
//////////////////////////////////////////////////////////////////////////////////////////////////
// Checks the verbosity of the message and returns NULL if the message must NOT be
// logged, or the pointer to the part of the message that should be logged
// NOTE:
// Normally, this is either the pText pointer itself, or the pText+1, meaning
// the first verbosity character may be cut off)
// This is done in order to avoid modification of const char*, which may cause GPF
// sometimes, or kill the verbosity qualifier in the text that's gonna be passed next time.
const char* CLog::CheckAgainstVerbosity(const char* pText, bool& logtofile, bool& logtoconsole, const uint8 DefaultVerbosity)
{
// the max verbosity (most detailed level)
#if defined(RELEASE)
const unsigned char nMaxVerbosity = 0;
#else // #if defined(RELEASE)
const unsigned char nMaxVerbosity = 8;
#endif // #if defined(RELEASE)
// the current verbosity of the log
int nLogVerbosityConsole = m_pLogVerbosity ? m_pLogVerbosity->GetIVal() : nMaxVerbosity;
int nLogVerbosityFile = m_pLogWriteToFileVerbosity ? m_pLogWriteToFileVerbosity->GetIVal() : nMaxVerbosity;
logtoconsole = (nLogVerbosityConsole >= DefaultVerbosity);
//to preserve logging to TTY, logWriteToFile logic has been moved to inside logStringToFile
//int logToFileCVar = m_pLogWriteToFile ? m_pLogWriteToFile->GetIVal() : 1;
logtofile = (nLogVerbosityFile >= DefaultVerbosity);
return pText;
}
//////////////////////////////////////////////////////////////////////////
void CLog::AddCallback(ILogCallback* pCallback)
{
stl::push_back_unique(m_callbacks, pCallback);
}
//////////////////////////////////////////////////////////////////////////
void CLog::RemoveCallback(ILogCallback* pCallback)
{
m_callbacks.remove(pCallback);
}
//////////////////////////////////////////////////////////////////////////
void CLog::Update()
{
FUNCTION_PROFILER_FAST(m_pSystem, PROFILE_SYSTEM, g_bProfilerEnabled);
if (CryGetCurrentThreadId() == m_nMainThreadId)
{
if (!m_threadSafeMsgQueue.empty())
{
CryAutoCriticalSection lock(m_threadSafeMsgQueue.get_lock()); // Get the lock and hold onto it until we clear the entire queue (prevents other threads adding more things in while we clear it)
// Must be called from main thread
SLogMsg msg;
while (m_threadSafeMsgQueue.try_pop(msg))
{
if (msg.destination == SLogMsg::Destination::Console)
{
LogStringToConsole(msg.msg, msg.logType, msg.bAdd);
}
else if (msg.destination == SLogMsg::Destination::File)
{
LogStringToFile(msg.msg, msg.logType, msg.bAdd, MessageQueueState::Queued);
}
else
{
LogString(msg.msg, msg.logType);
}
}
stl::free_container(m_threadSafeMsgQueue);
}
if (LogCVars::s_log_tick != 0)
{
static CTimeValue t0 = GetISystem()->GetITimer()->GetAsyncTime();
CTimeValue t1 = GetISystem()->GetITimer()->GetAsyncTime();
if (fabs((t1 - t0).GetSeconds()) > LogCVars::s_log_tick)
{
t0 = t1;
char sTime[128];
time_t ltime;
time(&ltime);
#ifdef AZ_COMPILER_MSVC
struct tm today;
localtime_s(&today, &ltime);
strftime(sTime, sizeof(sTime) - 1, "<%H:%M:%S> ", &today);
#else
auto today = localtime(&ltime);
strftime(sTime, sizeof(sTime) - 1, "<%H:%M:%S> ", today);
#endif
LogAlways("<tick> %s", sTime);
}
}
}
}
//////////////////////////////////////////////////////////////////////////
const char* CLog::GetModuleFilter()
{
if (m_pLogModule)
{
return m_pLogModule->GetString();
}
return "";
}
void CLog::FlushAndClose()
{
#if defined(KEEP_LOG_FILE_OPEN)
if (m_logFileHandle.IsOpen())
{
CloseLogFile();
}
#endif
}
#if defined(KEEP_LOG_FILE_OPEN)
void CLog::LogFlushFile([[maybe_unused]] IConsoleCmdArgs* pArgs)
{
if ((gEnv) && (gEnv->pLog))
{
gEnv->pLog->FlushAndClose();
}
}
#endif
Reference in New Issue View Git Blame Copy Permalink