privacore-open-source-search-engine/Log.cpp

#include "Log.h"
#include "Mem.h"
#if defined(__linux__)
#include <sys/types.h>
#include <sys/syscall.h>
#endif
#include "Loop.h"
#include "Conf.h"
#include "Process.h"
#include "Hostdb.h"
#include "File.h"
#include "fctypes.h"
#include "utf8_fast.h"
#include "GbMutex.h"
#include "ScopedLock.h"
#include <fcntl.h>
#include <unistd.h>
#include <stdio.h>

// a global class extern'd in Log.h
Log g_log;

//'s_lock' really should be a nice instance but due to the undefined destruction
//order of global objects we can easily end up using it after it has been destroyed
//so for now we just use a plain old pthread_mtuex_t and never destroy it.
//static GbMutex s_lock;
static pthread_mutex_t s_lock = PTHREAD_MUTEX_INITIALIZER;


Log::Log () { 
	m_fd = -1; 
	m_filename = NULL;
	m_disabled = false;
	m_logTimestamps = true;
	m_logReadableTimestamps = true;
	m_logPrefix = true;
}

Log::~Log () { 
	//reset(); }
	if ( m_fd >= 0 ) ::close ( m_fd );
}	

// close file if it's open
void Log::reset ( ) {
	// comment this out otherwise we dont log the memleaks in Mem.cpp!!
	//if ( m_fd >= 0 ) ::close ( m_fd );
}

// for example, RENAME log000 to log000-bak20131104-181932
static bool renameCurrentLogFile ( ) {
	File f;
	char tmp[16];
	sprintf(tmp,"log%03" PRId32,g_hostdb.m_myHostId);
	f.set ( g_hostdb.m_dir , tmp );
	// make new filename like log000-bak20131104-181932
	time_t now = time(NULL);
	struct tm tm_buf;
	tm *tm1 = gmtime_r(&now,&tm_buf);
	char tmp2[64];
	strftime(tmp2,64,"%Y%m%d-%H%M%S",tm1);
	SafeBuf newName;
	if ( ! newName.safePrintf ( "%slog%03" PRId32"-bak%s",
				    g_hostdb.m_dir,
				    g_hostdb.m_myHostId,
				    tmp2 ) ) {
		fprintf(stderr,"log rename failed\n");
		return false;
	}
	// rename log000 to log000-2013_11_04-18:19:32
	if ( f.doesExist() ) {
		//fprintf(stdout,"renaming file\n");
		f.rename ( newName.getBufStart() );
	}
	return true;
}


bool Log::init ( const char *filename ) {
	// init these
	m_fd        = -1;
	m_disabled  = false;

	// is there a filename to log our errors to?
	m_filename = filename;
	if ( ! m_filename ) return true;

	//
	// RENAME log000 to log000-20131104-181932
	//
	if ( g_conf.m_logToFile ) {
		// returns false on error
		if ( ! renameCurrentLogFile() ) return false;
	}

	if ( strcmp(m_filename,"/dev/stderr") == 0 ) {
		m_fd = STDERR_FILENO; // 2; // stderr
		return true;
	}

	// open it for appending.
	// create with -rw-rw-r-- permissions if it's not there.
	m_fd = open ( m_filename , 
		      O_APPEND | O_CREAT | O_RDWR ,
		      getFileCreationFlags() );
	if ( m_fd >= 0 ) return true;
	// bitch to stderr and return false on error
	fprintf(stderr,"could not open log file %s for appending\n",
		m_filename);
	return false;
}


static const char *getTypeString ( int32_t type ) ;

const char *getTypeString ( int32_t type ) {
	switch ( type ) {
	case LOG_INFO  : return "INF";
	case LOG_WARN  : return "WRN";
	case LOG_ERROR : return "ERR";
	case LOG_TRACE : return "TRC";
	case LOG_LOGIC : return "LOG";
	case LOG_REMIND: return "REM";
	case LOG_DEBUG : return "DBG";
	case LOG_TIMING: return "TIM";
	case LOG_INIT  : return "INI";
	case LOG_LIMIT : return "LIM";
	default: return "UNK";
	}
}


#define MAX_LINE_LEN 20048

bool Log::shouldLog ( int32_t type , const char *msg ) {
	// always log errors/warnings/logic/trace (if trace gets through to here, it is enabled)
	if ( (type == LOG_WARN) || (type == LOG_LOGIC) || (type == LOG_ERROR) || (type == LOG_TRACE)) {
		return true;
	}

	if ( type == LOG_INFO ) return g_conf.m_logInfo;

	if ( type == LOG_LIMIT  ) return g_conf.m_logLimits;
	if ( type == LOG_REMIND ) return g_conf.m_logReminders ;
	if ( type == LOG_TIMING ) {
		if ( msg[0] == 'a' && msg[2] == 'd' )
			return g_conf.m_logTimingAddurl;
		if ( msg[0] == 'a' && msg[2] == 'm' )
			return g_conf.m_logTimingAdmin;
		if ( msg[0] == 'b' ) return g_conf.m_logTimingBuild;
		if ( msg[0] == 'd' ) return g_conf.m_logTimingDb;
		if ( msg[0] == 'n' ) return g_conf.m_logTimingNet;
		if ( msg[0] == 'q' ) return g_conf.m_logTimingQuery;
		if ( msg[0] == 'r' ) return g_conf.m_logTimingRobots;
		if ( msg[0] == 'l' ) return g_conf.m_logTimingLinkInfo;
		return false;
	}
	if ( type != LOG_DEBUG ) return true;
		
	if (msg[0]=='a'&&msg[2]=='d' ) return g_conf.m_logDebugAddurl ;
	if (msg[0]=='a'&&msg[2]=='m' ) return g_conf.m_logDebugAdmin  ;
	if (msg[0]=='b'&&msg[1]=='u' ) return g_conf.m_logDebugBuild  ;
	if (msg[0]=='d'&&msg[1]=='b' ) return g_conf.m_logDebugDb     ;
	if (msg[0]=='d'&&msg[1]=='i' ) return g_conf.m_logDebugDisk   ;
	if (msg[0]=='d'&&msg[1]=='n' ) return g_conf.m_logDebugDns    ;
	if (msg[0]=='d'&&msg[1]=='o' ) return g_conf.m_logDebugDownloads;
	if (msg[0]=='h'&&msg[1]=='t' ) return g_conf.m_logDebugHttp   ;
	if (msg[0]=='i'&&msg[1]=='m' ) return g_conf.m_logDebugImage  ;
	if (msg[0]=='l'&&msg[1]=='o' ) return g_conf.m_logDebugLoop   ;
	if (msg[0]=='l'&&msg[1]=='a' ) return g_conf.m_logDebugLang   ;
	if (msg[0]=='m'&&msg[2]=='m' ) return g_conf.m_logDebugMem    ;
	if (msg[0]=='m'&&msg[2]=='r' ) return g_conf.m_logDebugMerge  ;
	if (msg[0]=='n'&&msg[1]=='e' ) return g_conf.m_logDebugNet    ;
	if (msg[0]=='q'&&msg[1]=='u'&&msg[2]=='e' ) 
		return g_conf.m_logDebugQuery  ;
	if (msg[0]=='r'&&msg[1]=='o' ) return g_conf.m_logDebugRobots ;
	if (msg[0]=='s'&&msg[1]=='e' ) return g_conf.m_logDebugSEO;
	if (msg[0]=='s'&&msg[2]=='e' ) return g_conf.m_logDebugSpeller;
	if (msg[0]=='s'&&msg[2]=='a' ) return g_conf.m_logDebugStats  ;
	if (msg[0]=='s'&&msg[1]=='u' ) return g_conf.m_logDebugSummary;
	if (msg[0]=='s'&&msg[2]=='i' ) return g_conf.m_logDebugSpider ;
	if (msg[0]=='t'&&msg[1]=='a' ) return g_conf.m_logDebugTagdb  ;
	if (msg[0]=='t'&&msg[1]=='c' ) return g_conf.m_logDebugTcp    ;
	if (msg[0]=='t'&&msg[1]=='i' ) return g_conf.m_logDebugTitle  ;
	if (msg[0]=='r'&&msg[1]=='e'&&msg[2]=='p' ) return g_conf.m_logDebugRepair ;
	if (msg[0]=='r'&&msg[1]=='e'&&msg[2]=='i' ) return g_conf.m_logDebugReindex ;
	if (msg[0]=='u'&&msg[1]=='d' ) return g_conf.m_logDebugUdp    ;
	if (msg[0]=='u'&&msg[1]=='n' ) return g_conf.m_logDebugUnicode;
	if (msg[0]=='t'&&msg[1]=='o'&&msg[3]=='D' ) 
		return g_conf.m_logDebugTopDocs;
	if (msg[0]=='d'&&msg[1]=='a' ) return g_conf.m_logDebugDate;
	if (msg[0]=='d'&&msg[1]=='d' ) return g_conf.m_logDebugDetailed;
		
	return true;
}

static bool g_loggingEnabled = true;

// 1GB max log file size
#define MAXLOGFILESIZE 1000000000

bool Log::logR ( int64_t now, int32_t type, const char *msg, bool forced ) {
	if ( ! g_loggingEnabled ) {
		return true;
	}

	// return true if we should not log this
	if ( ! forced && ! shouldLog ( type , msg ) ) {
		return true;
	}

	// get "msg"'s length
	int32_t msgLen = strlen ( msg );

	ScopedLock sl(s_lock);

	// do a timestamp, too. use the time synced with host #0 because
	// it is easier to debug because all log timestamps are in sync.
	if ( now == 0 ) now = gettimeofdayInMilliseconds();

	// chop off any spaces at the end of the msg.
	while ( is_wspace_a ( msg [ msgLen - 1 ] ) && msgLen > 0 ) msgLen--;

	// a tmp buffer
	char tt [ MAX_LINE_LEN ];
	char *p    = tt;


	if (m_logPrefix) {
		if ( m_logTimestamps ) {
			if( m_logReadableTimestamps ) {
				time_t now_t = (time_t)(now / 1000);
				struct tm tm_buf;
				struct tm *stm = gmtime_r(&now_t,&tm_buf);

				p += sprintf ( p , "%04d%02d%02d-%02d%02d%02d-%03d %04" PRId32" ", stm->tm_year+1900,stm->tm_mon+1,stm->tm_mday,stm->tm_hour,stm->tm_min,stm->tm_sec,(int)(now%1000), g_hostdb.m_myHostId );
			} else {
				if ( g_hostdb.getNumHosts() <= 999 )
					p += sprintf ( p , "%" PRIu64 " %03" PRId32 " ", (uint64_t)now , g_hostdb.m_myHostId );
				else if ( g_hostdb.getNumHosts() <= 9999 )
					p += sprintf ( p , "%" PRIu64" %04" PRId32" ", (uint64_t)now , g_hostdb.m_myHostId );
				else if ( g_hostdb.getNumHosts() <= 99999 )
					p += sprintf ( p , "%" PRIu64" %05" PRId32" ", (uint64_t)now , g_hostdb.m_myHostId );
			}
		}

		// Get thread id. pthread_self instead?
		unsigned tid=(unsigned)syscall(SYS_gettid);
		p += sprintf(p, "%06u ", tid);

		// Log level
		p += sprintf(p, "%s ", getTypeString(type));
	}

	// then message itself
	const char *x = msg;
	int32_t avail = (MAX_LINE_LEN) - (p - tt) - 1;
	if ( msgLen > avail ) msgLen = avail;
	if ( *x == ':' ) x++;
	if ( *x == ' ' ) x++;
	strncpy ( p , x , avail );
	// capitalize for consistency. no, makes grepping log msgs harder.
	//if ( is_alpha_a(*p) ) *p = to_upper_a(*p);
	p += strlen(p);
	// back up over spaces
	while ( p[-1] == ' ' ) p--;
	// end in period or ? or !
	//if ( p[-1] != '?' && p[-1] != '.' && p[-1] != '!' )
	//	*p++ = '.';
	*p ='\0';
	// the total length, not including the \0
	int32_t tlen = p - tt;



	if ( m_fd >= 0 ) {
		write ( m_fd , tt , tlen );
		write ( m_fd , "\n", 1 );
	} else {
		// print it out for now
		fprintf ( stderr, "%s\n", tt );
	}

	return false;
}

void Log::rotateLog(int fd, void *state) {
	if (!g_conf.m_logToFile) {
		return;
	}

	Log *that = static_cast<Log*>(state);
	auto fileSize = getFileSize(that->m_filename);

	// . if filesize would be too big then make a new log file
	// . should make a new m_fd
	if (fileSize > MAXLOGFILESIZE) {
		that->makeNewLogFile();
	}
}

bool Log::registerLogRotation() {
	return g_loop.registerSleepCallback(10000, this, rotateLog, "Log::rotateLog");
}

bool Log::makeNewLogFile() {
	ScopedLock sl(s_lock);

	// prevent deadlock. don't log since we are in the middle of logging.
	// otherwise, safebuf, which is used when renaming files, might
	// call logR().
	g_loggingEnabled = false;

	// . rename old log file like log000 to log000-2013_11_04-18:19:32
	// . returns false on error
	bool status = renameCurrentLogFile();

	// re-enable logging since nothing below should call logR() indirectly
	g_loggingEnabled = true;

	if (!status) {
		return false;
	}

	// close old fd
	if (m_fd >= 0) {
		::close(m_fd);
	}

	// invalidate
	m_fd = -1;

	// open it for appending.
	// create with -rw-rw-r-- permissions if it's not there.
	m_fd = open(m_filename, O_APPEND | O_CREAT | O_RDWR, getFileCreationFlags());
	if (m_fd >= 0) {
		return true;
	}

	// bitch to stderr and return false on error
	fprintf(stderr, "could not open new log file %s for appending\n", m_filename);
	return false;
}


void log ( int32_t type , const char *formatString , ...) {
	if ( g_log.m_disabled ) {
		return;
	}

	// do not log it if we should not
	if ( ! g_log.shouldLog ( type , formatString ) ) {
		return;
	}

	// this is the argument list (variable list)
	va_list   ap;

	// can we log if we're a sig handler? don't take changes
	// print msg into this buf
	char buf[1024*10];

	// copy the error into the buffer space
	va_start ( ap, formatString);

	// print it into our buf now
	vsnprintf ( buf , 1024*10 , formatString , ap );

	va_end(ap);

	// pass buf to g_log
	g_log.logR ( 0, type, buf );
}

void log ( const char *formatString , ... ) {
	if ( g_log.m_disabled ) {
		return;
	}

	// do not log it if we should not
	if ( ! g_log.shouldLog ( LOG_WARN , formatString ) ) {
		return;
	}

	// this is the argument list (variable list)
	va_list   ap;

	// can we log if we're a sig handler? don't take changes
	// print msg into this buf
	char buf[1024*10];

	// copy the error into the buffer space
	va_start ( ap, formatString);

	// print it into our buf now
	vsnprintf ( buf , 1024*10 , formatString , ap );

	va_end(ap);
	
	// pass buf to g_log
	// ### BR 20151217: Default to DEBUG if no log level given
	/// @todo ALC shouldn't this be LOG_WARN?
	g_log.logR ( 0 , LOG_DEBUG , buf , false );
}

void logf ( int32_t type , const char *formatString , ...) {
	if ( g_log.m_disabled ) {
		return;
	}

	// this is the argument list (variable list)
	va_list   ap;

	// can we log if we're a sig handler? don't take changes
	// print msg into this buf
	char buf[1024*10];

	// copy the error into the buffer space
	va_start ( ap, formatString);

	// print it into our buf now
	vsnprintf ( buf , 1024*10 , formatString , ap );

	va_end(ap);

	// pass buf to g_log
	g_log.logR ( 0, type, buf, true );
}



static void hexdump(void const *data, const unsigned int len, char *dest, const int dest_len)
{
	unsigned int i;
	unsigned int r,c;


	if (!data || len <= 0)
	{
		return;
	}

	int	dest_used = 0;
	char *destptr = dest;


	char line[80]; // line length is actually 78 + null terminator
	char *lptr;

	for (r=0,i=0; (r<(len/16+(len%16!=0))) && (dest_len - (dest_used+80)>= 0); r++,i+=16)
	{
		lptr = line;
			lptr += sprintf(lptr, "\n%04X:   ",i); 

		for (c=i; c<i+8; c++) /* left half of hex dump */
		{
			if (c<len)
			{
				lptr += sprintf(lptr, "%02X ",((unsigned char const *)data)[c]);
			}
			else
			{
				lptr += sprintf(lptr, "   "); /* pad if short line */
			}
		}

		lptr += sprintf(lptr, "  ");

		
		for (c=i+8; c<i+16; c++) /* right half of hex dump */
		{
			if (c<len)
			{
				lptr += sprintf(lptr, "%02X ",((unsigned char const *)data)[c]);
			}
			else
			{
				lptr += sprintf(lptr, "   "); /* pad if short line */
			}
		}
		
		lptr += sprintf(lptr, "   ");
		
		for (c=i; c<i+16; c++) /* ASCII dump */
		{
			if (c<len)
			{
				if (((unsigned char const *)data)[c]>=32 &&
				    ((unsigned char const *)data)[c]<127)
				{
					lptr += sprintf(lptr, "%c",((char const *)data)[c]);
				}
				else
				{
					lptr += sprintf(lptr, "."); /* put this for non-printables */
				}
			}
			else
			{
				lptr += sprintf(lptr, " "); /* pad if short line */
			}
		}
		
		destptr += sprintf(destptr, "%s", line);
		dest_used = destptr - dest;
	}

	destptr += sprintf(destptr, "\n");
}


void loghex( int32_t type, void const *data, const unsigned int len, const char *formatString , ...) {
	if ( g_log.m_disabled ) {
		return;
	}

	// this is the argument list (variable list)
	va_list   ap;
	// can we log if we're a sig handler? don't take changes
	// print msg into this buf
	char buf[1024*10];
	// copy the error into the buffer space
	va_start ( ap, formatString);
	// print it into our buf now
	vsnprintf ( buf , 1024*10 , formatString , ap );
	va_end(ap);
	
	int written = strlen(buf);
	hexdump(data, len, &buf[written], (1024*10)-written);
	
	// pass buf to g_log
	g_log.logR ( 0 , type , buf );
}