zoneminder/src/zm_logger.cpp

579 lines
16 KiB
C++
Raw Normal View History

/*
* ZoneMinder Logger Implementation, $Date$, $Revision$
* Copyright (C) 2001-2008 Philip Coombes
*
* This program is free software; you can redistribute it and/or
* modify it under the terms of the GNU General Public License
* as published by the Free Software Foundation; either version 2
* of the License, or (at your option) any later version.
*
* This program is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU General Public License for more details.
*
* You should have received a copy of the GNU General Public License
* along with this program; if not, write to the Free Software
* Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
*/
#include "zm_logger.h"
#include "zm_config.h"
#include "zm_utils.h"
#include "zm_db.h"
2013-04-30 00:51:46 +08:00
#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sys/time.h>
#include <syslog.h>
#include <signal.h>
#include <stdarg.h>
#include <errno.h>
2017-01-31 16:10:25 +08:00
#include <libgen.h>
2015-02-24 22:22:08 +08:00
#ifdef __FreeBSD__
#include <sys/thr.h>
#endif
bool Logger::smInitialised = false;
Logger *Logger::smInstance = 0;
Logger::StringMap Logger::smCodes;
Logger::IntMap Logger::smSyslogPriorities;
2013-03-17 07:45:21 +08:00
#if 0
2017-05-20 00:57:43 +08:00
static void subtractTime( struct timeval * const tp1, struct timeval * const tp2 ) {
tp1->tv_sec -= tp2->tv_sec;
2017-05-20 00:57:43 +08:00
if ( tp1->tv_usec <= tp2->tv_usec ) {
tp1->tv_sec--;
tp1->tv_usec = 1000000 - (tp2->tv_usec - tp1->tv_usec);
2017-05-20 00:57:43 +08:00
} else {
tp1->tv_usec = tp1->tv_usec - tp2->tv_usec;
}
}
2013-03-17 07:45:21 +08:00
#endif
2017-05-20 00:57:43 +08:00
void Logger::usrHandler( int sig ) {
Logger *logger = fetch();
if ( sig == SIGUSR1 )
logger->level( logger->level()+1 );
else if ( sig == SIGUSR2 )
logger->level( logger->level()-1 );
Info( "Logger - Level changed to %d", logger->level() );
}
Logger::Logger() :
mLevel( INFO ),
mTermLevel( NOLOG ),
mDatabaseLevel( NOLOG ),
mFileLevel( NOLOG ),
mSyslogLevel( NOLOG ),
mEffectiveLevel( NOLOG ),
//mLogPath( staticConfig.PATH_LOGS.c_str() ),
//mLogFile( mLogPath+"/"+mId+".log" ),
mDbConnected( false ),
mLogFileFP( NULL ),
mHasTerm( false ),
2017-05-20 00:57:43 +08:00
mFlush( false ) {
if ( smInstance ) {
Panic( "Attempt to create second instance of Logger class" );
}
2017-05-20 00:57:43 +08:00
if ( !smInitialised ) {
smCodes[INFO] = "INF";
smCodes[WARNING] = "WAR";
smCodes[ERROR] = "ERR";
smCodes[FATAL] = "FAT";
smCodes[PANIC] = "PNC";
smCodes[NOLOG] = "OFF";
smSyslogPriorities[INFO] = LOG_INFO;
smSyslogPriorities[WARNING] = LOG_WARNING;
smSyslogPriorities[ERROR] = LOG_ERR;
smSyslogPriorities[FATAL] = LOG_ERR;
smSyslogPriorities[PANIC] = LOG_ERR;
char code[4] = "";
2017-05-20 00:57:43 +08:00
for ( int i = DEBUG1; i <= DEBUG9; i++ ) {
snprintf( code, sizeof(code), "DB%d", i );
smCodes[i] = code;
smSyslogPriorities[i] = LOG_DEBUG;
}
smInitialised = true;
}
if ( fileno(stderr) && isatty(fileno(stderr)) )
mHasTerm = true;
}
2017-05-20 00:57:43 +08:00
Logger::~Logger() {
terminate();
smCodes.clear();
smSyslogPriorities.clear();
2017-08-12 00:03:37 +08:00
#if 0
2017-08-11 03:44:20 +08:00
for ( StringMap::iterator itr = smCodes.begin(); itr != smCodes.end(); itr ++ ) {
smCodes.erase( itr );
}
2017-08-12 00:03:37 +08:00
for ( IntMap::iterator itr = smSyslogPriorities.begin(); itr != smSyslogPriorities.end(); itr ++ ) {
smSyslogPriorities.erase(itr);
}
#endif
}
2017-05-20 00:57:43 +08:00
void Logger::initialise( const std::string &id, const Options &options ) {
char *envPtr;
if ( !id.empty() )
this->id( id );
std::string tempLogFile;
2017-10-19 01:22:15 +08:00
if ( (envPtr = getTargettedEnv( "LOG_FILE" )) )
tempLogFile = envPtr;
2017-10-19 01:22:15 +08:00
else if ( options.mLogFile.size() )
tempLogFile = options.mLogFile;
else {
if ( options.mLogPath.size() ) {
mLogPath = options.mLogPath;
}
tempLogFile = mLogPath+"/"+mId+".log";
}
Level tempLevel = INFO;
Level tempTermLevel = mTermLevel;
Level tempDatabaseLevel = mDatabaseLevel;
Level tempFileLevel = mFileLevel;
Level tempSyslogLevel = mSyslogLevel;
if ( options.mTermLevel != NOOPT )
tempTermLevel = options.mTermLevel;
if ( options.mDatabaseLevel != NOOPT )
tempDatabaseLevel = options.mDatabaseLevel;
else
tempDatabaseLevel = config.log_level_database >= DEBUG1 ? DEBUG9 : config.log_level_database;
if ( options.mFileLevel != NOOPT )
tempFileLevel = options.mFileLevel;
else
tempFileLevel = config.log_level_file >= DEBUG1 ? DEBUG9 : config.log_level_file;
if ( options.mSyslogLevel != NOOPT )
tempSyslogLevel = options.mSyslogLevel;
else
tempSyslogLevel = config.log_level_syslog >= DEBUG1 ? DEBUG9 : config.log_level_syslog;
// Legacy
if ( (envPtr = getenv( "LOG_PRINT" )) )
tempTermLevel = atoi(envPtr) ? DEBUG9 : NOLOG;
if ( (envPtr = getTargettedEnv( "LOG_LEVEL" )) )
tempLevel = atoi(envPtr);
if ( (envPtr = getTargettedEnv( "LOG_LEVEL_TERM" )) )
tempTermLevel = atoi(envPtr);
if ( (envPtr = getTargettedEnv( "LOG_LEVEL_DATABASE" )) )
tempDatabaseLevel = atoi(envPtr);
if ( (envPtr = getTargettedEnv( "LOG_LEVEL_FILE" )) )
tempFileLevel = atoi(envPtr);
if ( (envPtr = getTargettedEnv( "LOG_LEVEL_SYSLOG" )) )
tempSyslogLevel = atoi(envPtr);
2017-05-20 00:57:43 +08:00
if ( config.log_debug ) {
StringVector targets = split( config.log_debug_target, "|" );
2017-05-20 00:57:43 +08:00
for ( unsigned int i = 0; i < targets.size(); i++ ) {
const std::string &target = targets[i];
2017-11-17 20:52:26 +08:00
if ( target == mId || target == "_"+mId || target == "_"+mIdRoot || target == "" ) {
2017-05-20 00:57:43 +08:00
if ( config.log_debug_level > NOLOG ) {
tempLevel = config.log_debug_level;
2017-05-20 00:57:43 +08:00
if ( config.log_debug_file[0] ) {
tempLogFile = config.log_debug_file;
tempFileLevel = tempLevel;
}
}
}
2017-05-20 20:53:27 +08:00
} // end foreach target
} else {
// if we don't have debug turned on, then the max effective log level is INFO
if ( tempSyslogLevel > INFO ) tempSyslogLevel = INFO;
if ( tempFileLevel > INFO ) tempFileLevel = INFO;
if ( tempTermLevel > INFO ) tempTermLevel = INFO;
if ( tempDatabaseLevel > INFO ) tempDatabaseLevel = INFO;
if ( tempLevel > INFO ) tempLevel = INFO;
2017-05-20 20:53:27 +08:00
} // end if config.log_debug
logFile( tempLogFile );
termLevel( tempTermLevel );
databaseLevel( tempDatabaseLevel );
fileLevel( tempFileLevel );
syslogLevel( tempSyslogLevel );
level( tempLevel );
mFlush = false;
if ( (envPtr = getenv("LOG_FLUSH")) ) {
mFlush = atoi( envPtr );
} else if ( config.log_debug ) {
mFlush = true;
}
//mRuntime = (envPtr = getenv( "LOG_RUNTIME")) ? atoi( envPtr ) : false;
{
struct sigaction action;
memset( &action, 0, sizeof(action) );
action.sa_handler = usrHandler;
action.sa_flags = SA_RESTART;
2017-05-20 00:57:43 +08:00
if ( sigaction( SIGUSR1, &action, 0 ) < 0 ) {
Fatal( "sigaction(), error = %s", strerror(errno) );
}
2017-05-20 00:57:43 +08:00
if ( sigaction( SIGUSR2, &action, 0 ) < 0) {
Fatal( "sigaction(), error = %s", strerror(errno) );
}
}
mInitialised = true;
2017-05-20 00:57:43 +08:00
Debug( 1, "LogOpts: level=%s/%s, screen=%s, database=%s, logfile=%s->%s, syslog=%s",
smCodes[mLevel].c_str(),
smCodes[mEffectiveLevel].c_str(),
smCodes[mTermLevel].c_str(),
smCodes[mDatabaseLevel].c_str(),
smCodes[mFileLevel].c_str(),
mLogFile.c_str(),
smCodes[mSyslogLevel].c_str()
);
}
2017-05-20 00:57:43 +08:00
void Logger::terminate() {
Debug(1, "Terminating Logger" );
if ( mFileLevel > NOLOG )
closeFile();
if ( mSyslogLevel > NOLOG )
closeSyslog();
2014-11-15 05:17:44 +08:00
if ( mDatabaseLevel > NOLOG )
closeDatabase();
}
2017-05-20 00:57:43 +08:00
bool Logger::boolEnv( const std::string &name, bool defaultValue ) {
const char *envPtr = getenv( name.c_str() );
return( envPtr ? atoi( envPtr ) : defaultValue );
}
2017-05-20 00:57:43 +08:00
int Logger::intEnv( const std::string &name, bool defaultValue ) {
const char *envPtr = getenv( name.c_str() );
return( envPtr ? atoi( envPtr ) : defaultValue );
}
2017-10-20 05:12:36 +08:00
std::string Logger::strEnv( const std::string &name, const std::string &defaultValue ) {
const char *envPtr = getenv( name.c_str() );
return( envPtr ? envPtr : defaultValue );
}
2017-05-20 00:57:43 +08:00
char *Logger::getTargettedEnv( const std::string &name ) {
std::string envName;
envName = name+"_"+mId;
2017-11-17 20:52:26 +08:00
char *envPtr = getenv( envName.c_str() );
2017-05-20 00:57:43 +08:00
if ( !envPtr && mId != mIdRoot ) {
envName = name+"_"+mIdRoot;
envPtr = getenv( envName.c_str() );
}
if ( !envPtr )
envPtr = getenv( name.c_str() );
return( envPtr );
}
2017-05-20 00:57:43 +08:00
const std::string &Logger::id( const std::string &id ) {
std::string tempId = id;
size_t pos;
// Remove whitespace
2017-05-20 00:57:43 +08:00
while ( (pos = tempId.find_first_of( " \t" )) != std::string::npos ) {
tempId.replace( pos, 1, "" );
}
// Replace non-alphanum with underscore
2017-05-20 00:57:43 +08:00
while ( (pos = tempId.find_first_not_of( "abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789_" )) != std::string::npos ) {
tempId.replace( pos, 1, "_" );
}
2017-05-20 00:57:43 +08:00
if ( mId != tempId ) {
mId = tempId;
pos = mId.find( '_' );
2017-05-20 00:57:43 +08:00
if ( pos != std::string::npos ) {
mIdRoot = mId.substr( 0, pos );
if ( ++pos < mId.size() )
mIdArgs = mId.substr( pos );
}
}
return( mId );
}
2017-05-20 00:57:43 +08:00
Logger::Level Logger::level( Logger::Level level ) {
if ( level > NOOPT ) {
level = limit(level);
if ( mLevel != level )
mLevel = level;
mEffectiveLevel = NOLOG;
if ( mTermLevel > mEffectiveLevel )
mEffectiveLevel = mTermLevel;
if ( mDatabaseLevel > mEffectiveLevel )
mEffectiveLevel = mDatabaseLevel;
if ( mFileLevel > mEffectiveLevel )
mEffectiveLevel = mFileLevel;
if ( mSyslogLevel > mEffectiveLevel )
mEffectiveLevel = mSyslogLevel;
if ( mEffectiveLevel > mLevel)
mEffectiveLevel = mLevel;
}
return( mLevel );
}
2017-05-20 00:57:43 +08:00
Logger::Level Logger::termLevel( Logger::Level termLevel ) {
if ( termLevel > NOOPT ) {
if ( !mHasTerm )
termLevel = NOLOG;
termLevel = limit(termLevel);
if ( mTermLevel != termLevel )
mTermLevel = termLevel;
}
return( mTermLevel );
}
2017-05-20 00:57:43 +08:00
Logger::Level Logger::databaseLevel( Logger::Level databaseLevel ) {
if ( databaseLevel > NOOPT ) {
databaseLevel = limit(databaseLevel);
2017-05-20 00:57:43 +08:00
if ( mDatabaseLevel != databaseLevel ) {
if ( databaseLevel > NOLOG && mDatabaseLevel <= NOLOG ) {
zmDbConnect();
2017-05-20 00:57:43 +08:00
} // end if ( databaseLevel > NOLOG && mDatabaseLevel <= NOLOG )
mDatabaseLevel = databaseLevel;
2017-05-20 00:57:43 +08:00
} // end if ( mDatabaseLevel != databaseLevel )
} // end if ( databaseLevel > NOOPT )
return( mDatabaseLevel );
}
2017-05-20 00:57:43 +08:00
Logger::Level Logger::fileLevel( Logger::Level fileLevel ) {
if ( fileLevel > NOOPT ) {
fileLevel = limit(fileLevel);
2017-05-20 00:57:43 +08:00
if ( mFileLevel != fileLevel ) {
if ( mFileLevel > NOLOG )
closeFile();
mFileLevel = fileLevel;
if ( mFileLevel > NOLOG )
openFile();
}
}
return( mFileLevel );
}
2017-05-20 00:57:43 +08:00
Logger::Level Logger::syslogLevel( Logger::Level syslogLevel ) {
if ( syslogLevel > NOOPT ) {
syslogLevel = limit(syslogLevel);
2017-05-20 00:57:43 +08:00
if ( mSyslogLevel != syslogLevel ) {
if ( mSyslogLevel > NOLOG )
closeSyslog();
mSyslogLevel = syslogLevel;
if ( mSyslogLevel > NOLOG )
openSyslog();
}
}
return( mSyslogLevel );
}
2017-05-20 00:57:43 +08:00
void Logger::logFile( const std::string &logFile ) {
bool addLogPid = false;
std::string tempLogFile = logFile;
2017-05-20 00:57:43 +08:00
if ( tempLogFile[tempLogFile.length()-1] == '+' ) {
tempLogFile.resize(tempLogFile.length()-1);
addLogPid = true;
}
if ( addLogPid )
mLogFile = stringtf( "%s.%05d", tempLogFile.c_str(), getpid() );
else
mLogFile = tempLogFile;
}
2017-05-20 00:57:43 +08:00
void Logger::openFile() {
2018-02-15 00:56:54 +08:00
if ( mLogFile.size() ) {
if ( (mLogFileFP = fopen(mLogFile.c_str() ,"a")) == (FILE *)NULL ) {
mFileLevel = NOLOG;
Fatal( "fopen() for %s, error = %s", mLogFile.c_str(), strerror(errno) );
2018-02-15 00:56:54 +08:00
}
} else {
puts("Called Logger::openFile() without a filename");
}
}
2017-05-20 00:57:43 +08:00
void Logger::closeFile() {
if ( mLogFileFP ) {
fflush( mLogFileFP );
2017-05-20 00:57:43 +08:00
if ( fclose( mLogFileFP ) < 0 ) {
Fatal( "fclose(), error = %s",strerror(errno) );
}
mLogFileFP = (FILE *)NULL;
}
}
2017-05-20 00:57:43 +08:00
void Logger::closeDatabase() {
2014-11-15 05:17:44 +08:00
}
2017-05-20 00:57:43 +08:00
void Logger::openSyslog() {
(void) openlog( mId.c_str(), LOG_PID|LOG_NDELAY, LOG_LOCAL1 );
}
2017-05-20 00:57:43 +08:00
void Logger::closeSyslog() {
(void) closelog();
}
2017-05-20 00:57:43 +08:00
void Logger::logPrint( bool hex, const char * const filepath, const int line, const int level, const char *fstring, ... ) {
2017-08-12 00:03:37 +08:00
if ( level > mEffectiveLevel )
return;
char timeString[64];
char logString[8192];
va_list argPtr;
struct timeval timeVal;
2015-08-22 07:28:50 +08:00
2017-08-12 00:03:37 +08:00
char *filecopy = strdup(filepath);
const char * const file = basename(filecopy);
const char *classString = smCodes[level].c_str();
2017-01-31 16:10:25 +08:00
2017-08-12 00:03:37 +08:00
if ( level < PANIC || level > DEBUG9 )
Panic( "Invalid logger level %d", level );
2017-08-12 00:03:37 +08:00
gettimeofday( &timeVal, NULL );
2017-05-20 00:57:43 +08:00
#if 0
2017-08-12 00:03:37 +08:00
if ( logRuntime ) {
static struct timeval logStart;
2017-08-12 00:03:37 +08:00
subtractTime( &timeVal, &logStart );
2017-08-12 00:03:37 +08:00
snprintf( timeString, sizeof(timeString), "%ld.%03ld", timeVal.tv_sec, timeVal.tv_usec/1000 );
} else {
2017-05-20 00:57:43 +08:00
#endif
2017-08-12 00:03:37 +08:00
char *timePtr = timeString;
timePtr += strftime( timePtr, sizeof(timeString), "%x %H:%M:%S", localtime(&timeVal.tv_sec) );
snprintf( timePtr, sizeof(timeString)-(timePtr-timeString), ".%06ld", timeVal.tv_usec );
2017-05-20 00:57:43 +08:00
#if 0
2017-08-12 00:03:37 +08:00
}
2017-05-20 00:57:43 +08:00
#endif
2017-08-12 00:03:37 +08:00
pid_t tid;
2015-02-24 22:22:08 +08:00
#ifdef __FreeBSD__
2017-08-12 00:03:37 +08:00
long lwpid;
thr_self(&lwpid);
tid = lwpid;
2015-02-24 22:22:08 +08:00
2017-08-12 00:03:37 +08:00
if (tid < 0 ) // Thread/Process id
2015-02-24 22:22:08 +08:00
#else
#ifdef HAVE_SYSCALL
2017-05-20 00:57:43 +08:00
#ifdef __FreeBSD_kernel__
2017-08-12 00:03:37 +08:00
if ( (syscall(SYS_thr_self, &tid)) < 0 ) // Thread/Process id
2017-05-20 00:57:43 +08:00
# else
2017-08-12 00:03:37 +08:00
// SOLARIS doesn't have SYS_gettid; don't assume
2017-05-20 00:57:43 +08:00
#ifdef SYS_gettid
2017-08-12 00:03:37 +08:00
if ( (tid = syscall(SYS_gettid)) < 0 ) // Thread/Process id
2017-05-20 00:57:43 +08:00
#endif // SYS_gettid
#endif
#endif // HAVE_SYSCALL
2015-02-24 22:22:08 +08:00
#endif
2017-08-12 00:03:37 +08:00
tid = getpid(); // Process id
char *logPtr = logString;
logPtr += snprintf( logPtr, sizeof(logString), "%s %s[%d].%s-%s/%d [",
timeString,
mId.c_str(),
tid,
classString,
file,
line
);
char *syslogStart = logPtr;
va_start( argPtr, fstring );
if ( hex ) {
unsigned char *data = va_arg( argPtr, unsigned char * );
int len = va_arg( argPtr, int );
int i;
logPtr += snprintf( logPtr, sizeof(logString)-(logPtr-logString), "%d:", len );
for ( i = 0; i < len; i++ ) {
logPtr += snprintf( logPtr, sizeof(logString)-(logPtr-logString), " %02x", data[i] );
}
2017-08-12 00:03:37 +08:00
} else {
logPtr += vsnprintf( logPtr, sizeof(logString)-(logPtr-logString), fstring, argPtr );
}
va_end(argPtr);
char *syslogEnd = logPtr;
strncpy( logPtr, "]\n", sizeof(logString)-(logPtr-logString) );
2017-08-12 00:03:37 +08:00
if ( level <= mTermLevel ) {
puts( logString );
fflush( stdout );
}
if ( level <= mFileLevel ) {
if ( mLogFileFP ) {
fputs( logString, mLogFileFP );
if ( mFlush )
fflush( mLogFileFP );
2017-08-12 00:03:37 +08:00
} else {
puts("Logging to file, but file not open\n");
}
2018-02-15 00:56:54 +08:00
} else {
puts("Not logging to file because level <= mFileLevel");
2017-08-12 00:03:37 +08:00
}
*syslogEnd = '\0';
if ( level <= mDatabaseLevel ) {
char sql[ZM_SQL_MED_BUFSIZ];
char escapedString[(strlen(syslogStart)*2)+1];
mysql_real_escape_string( &dbconn, escapedString, syslogStart, strlen(syslogStart) );
snprintf( sql, sizeof(sql), "insert into Logs ( TimeKey, Component, ServerId, Pid, Level, Code, Message, File, Line ) values ( %ld.%06ld, '%s', %d, %d, %d, '%s', '%s', '%s', %d )", timeVal.tv_sec, timeVal.tv_usec, mId.c_str(), staticConfig.SERVER_ID, tid, level, classString, escapedString, file, line );
if ( mysql_query( &dbconn, sql ) ) {
Level tempDatabaseLevel = mDatabaseLevel;
databaseLevel( NOLOG );
Error( "Can't insert log entry: sql(%s) error(%s)", sql, mysql_error( &dbconn ) );
databaseLevel(tempDatabaseLevel);
}
2017-08-12 00:03:37 +08:00
}
if ( level <= mSyslogLevel ) {
int priority = smSyslogPriorities[level];
//priority |= LOG_DAEMON;
syslog( priority, "%s [%s] [%s]", classString, mId.c_str(), syslogStart );
}
2017-08-12 00:03:37 +08:00
free(filecopy);
if ( level <= FATAL ) {
logTerm();
zmDbClose();
if ( level <= PANIC )
abort();
exit( -1 );
}
}
2017-05-20 00:57:43 +08:00
void logInit( const char *name, const Logger::Options &options ) {
if ( !Logger::smInstance )
Logger::smInstance = new Logger();
Logger::Options tempOptions = options;
2017-10-19 01:22:15 +08:00
tempOptions.mLogPath = staticConfig.PATH_LOGS;
Logger::smInstance->initialise( name, tempOptions );
}
2017-05-20 00:57:43 +08:00
void logTerm() {
2017-08-12 00:03:37 +08:00
if ( Logger::smInstance ) {
delete Logger::smInstance;
2017-08-12 00:03:37 +08:00
Logger::smInstance = NULL;
}
}