#include "gb-include.h" #include "Mem.h" #include // pid_t/getpid() #include "Loop.h" #include "Conf.h" #include "Process.h" #include "Threads.h" // getpidtid() // a global class extern'd in Log.h Log g_log; #ifdef PTHREADS #include // the thread lock static pthread_mutex_t s_lock = PTHREAD_MUTEX_INITIALIZER; #endif // . g_pbuf points to the parser buffer // . we store text to be printed to html page in g_pbufPtr // . we store normalized words/phrases into g_pterms // . they are referenced by the TermTable's m_termPtrs[] buckets // char *g_pbuf = NULL; // char *g_pbufPtr = NULL; // char *g_pterms = NULL; // char *g_ptermPtr = NULL; // char *g_pend = NULL; char *g_dbuf = NULL; long g_dbufSize = 0; // main process id static pid_t s_pid = -1; void Log::setPid ( ) { s_pid = getpidtid(); } Log::Log () { m_fd = -1; m_filename = NULL; m_hostname = NULL; m_port = 777; m_needsPrinting = false; m_disabled = false; m_logTimestamps = false; } 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 ); #ifdef DEBUG if (g_dbuf) mfree(g_dbuf,g_dbufSize,"Log: DebugBuffer"); g_dbuf = NULL; #endif } bool Log::init ( char *filename ) { // set the main process id //s_pid = getpidtid(); setPid(); // init these m_numErrors = 0; m_bufPtr = 0; m_fd = -1; m_disabled = false; #ifdef DEBUG g_dbufSize = 4096; g_dbuf = (char*)mmalloc(g_dbufSize,"Log: DebugBuffer"); if (!g_dbuf) fprintf(stderr, "Unable to init debug buffer"); #endif // m_hostname = g_conf.m_hostname; // m_port = port; // is there a filename to log our errors to? m_filename = filename; if ( ! m_filename ) return true; // skip this for now //return true; // // RENAME log000 to log000-2013_11_04-18:19:32 // if ( g_conf.m_runAsDaemon ) { File f; char tmp[16]; sprintf(tmp,"log%03li",g_hostdb.m_hostId); f.set ( g_hostdb.m_dir , tmp ); // make new filename like log000-2013_11_04-18:19:32 time_t now = getTimeLocal(); tm *tm1 = gmtime((const time_t *)&now); char tmp2[64]; strftime(tmp2,64,"%Y_%m_%d-%T",tm1); SafeBuf newName; if ( ! newName.safePrintf ( "%slog%03li-%s", g_hostdb.m_dir, g_hostdb.m_hostId, 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() ); } } // 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 , S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP | S_IROTH ); 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 ( long type ) ; const char *getTypeString ( long type ) { switch ( type ) { case LOG_INFO : return "INFO "; case LOG_WARN : return "WARN "; case LOG_LOGIC : return "LOGIC"; case LOG_REMIND: return "REMND"; case LOG_DEBUG : return "DEBUG"; case LOG_TIMING: return "TIME "; case LOG_INIT : return "INIT "; case LOG_LIMIT : return "LIMIT"; default: return " "; } } */ #define MAX_LINE_LEN 20048 bool Log::shouldLog ( long type , char *msg ) { // always log warnings if ( type == LOG_WARN ) return true; if ( type == LOG_INFO ) return g_conf.m_logInfo; // treat INIT as INFO //if ( type == LOG_INIT && ! g_conf.m_logInfo ) return true; 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] == 's' ) return g_conf.m_logTimingSpcache; if ( msg[0] == 't' ) return g_conf.m_logTimingTopics; 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]=='p'&&msg[1]=='q' ) return g_conf.m_logDebugPQR ; if (msg[0]=='q'&&msg[1]=='u'&&msg[2]=='e' ) return g_conf.m_logDebugQuery ; if (msg[0]=='q'&&msg[1]=='u'&&msg[2]=='o' ) return g_conf.m_logDebugQuota ; if (msg[0]=='r'&&msg[1]=='o' ) return g_conf.m_logDebugRobots ; //if (msg[0]=='s'&&msg[2]=='c' ) return g_conf.m_logDebugSpcache; 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]=='h' ) return g_conf.m_logDebugThread ; if (msg[0]=='t'&&msg[1]=='i' ) return g_conf.m_logDebugTitle ; if (msg[0]=='r'&&msg[1]=='e' ) return g_conf.m_logDebugRepair ; 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]=='t'&&msg[1]=='o'&&msg[3]!='D' ) return g_conf.m_logDebugTopics; if (msg[0]=='d'&&msg[1]=='a' ) return g_conf.m_logDebugDate; return true; } bool Log::logR ( long long now , long type , char *msg , bool asterisk , bool forced ) { // filter if we should //if ( forced ) goto skipfilter; // return true if we should not log this if ( ! forced && ! shouldLog ( type , msg ) ) return true; // skipfilter: // can we log if we're a sig handler? don't take changes if ( g_inSigHandler ) return logLater ( now , type , msg , NULL ); //if ( g_inSigHandler ) return false; // get "msg"'s length long msgLen = gbstrlen ( msg ); #ifdef PTHREADS // lock for threads pthread_mutex_lock ( &s_lock ); #endif // 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 = gettimeofdayInMillisecondsGlobalNoCore(); // . skip all logging if power out, we do not want to screw things up // . allow logging for 10 seconds after power out though if ( ! g_process.m_powerIsOn && now - g_process.m_powerOffTime >10000){ #ifdef PTHREADS pthread_mutex_unlock ( &s_lock ); #endif return false; } //if ( now == 0 ) now = g_nowApprox; // chop off any spaces at the end of the msg. while ( is_wspace_a ( msg [ msgLen - 1 ] ) && msgLen > 0 ) msgLen--; // get this pid pid_t pid = getpidtid(); // a tmp buffer char tt [ MAX_LINE_LEN ]; char *p = tt; char *pend = tt + MAX_LINE_LEN; /* // print timestamp, hostid, type if ( g_hostdb.m_numHosts <= 999 ) sprintf ( p , "%llu %03li %s ", now , g_hostdb.m_hostId , getTypeString(type) ); else if ( g_hostdb.m_numHosts <= 9999 ) sprintf ( p , "%llu %04li %s ", now , g_hostdb.m_hostId , getTypeString(type) ); else if ( g_hostdb.m_numHosts <= 99999 ) sprintf ( p , "%llu %05li %s ", now , g_hostdb.m_hostId , getTypeString(type) ); */ // print timestamp, hostid, type if ( m_logTimestamps ) { if ( g_hostdb.m_numHosts <= 999 ) sprintf ( p , "%llu %03li ", now , g_hostdb.m_hostId ); else if ( g_hostdb.m_numHosts <= 9999 ) sprintf ( p , "%llu %04li ", now , g_hostdb.m_hostId ); else if ( g_hostdb.m_numHosts <= 99999 ) sprintf ( p , "%llu %05li ", now , g_hostdb.m_hostId ); p += gbstrlen ( p ); } // msg resource char *x = msg; long cc = 7; // the first 7 bytes or up to the : must be ascii //while ( p < pend && *x && is_alnum_a(*x) ) { *p++ = *x++; cc--; } // space pad //while ( cc-- > 0 ) *p++ = ' '; // ignore the label for now... while ( p < pend && *x && is_alnum_a(*x) ) { x++; cc--; } // thread id if in "thread" if ( pid != s_pid && s_pid != -1 ) { //sprintf ( p , "[%li] " , (long)getpid() ); sprintf ( p , "[%lu] " , (unsigned long)pid ); p += gbstrlen ( p ); } // then message itself long 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 += gbstrlen(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 long tlen = p - tt; // call sprintf, but first make sure we have room in m_buf and in // the arrays. who know how much room the sprintf is going to need??? // NOTE: TODO: this is shaky -- fix it! if ( m_bufPtr + tlen >= 1024 * 32 || m_numErrors >= MAX_LOG_MSGS){ // this sets m_bufPtr to 0 if ( ! dumpLog ( ) ) { fprintf(stderr,"Log::log: could not dump to file!\n"); #ifdef PTHREADS pthread_mutex_unlock ( &s_lock ); #endif return false; } } // . filter out nasty chars from the message // . replace with ~'s char cs; char *ttp = tt; char *ttpend = tt + tlen; for ( ; ttp < ttpend ; ttp += cs ) { cs = getUtf8CharSize ( ttp ); if ( is_binary_utf8 ( ttp ) ) { for ( long k = 0 ; k < cs ; k++ ) *ttp++ = '.'; // careful not to skip the already skipped bytes cs = 0; continue; } // convert \n's and \r's to spaces if ( *ttp == '\n' ) *ttp = ' '; if ( *ttp == '\r' ) *ttp = ' '; if ( *ttp == '\t' ) *ttp = ' '; } 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 ); } // set the stuff in the array m_errorMsg [m_numErrors] = msg; m_errorMsgLen [m_numErrors] = msgLen; m_errorTime [m_numErrors] = now; m_errorType [m_numErrors] = type; // increase the # of errors m_numErrors++; #ifdef PTHREADS // unlock for threads pthread_mutex_unlock ( &s_lock ); #endif return false; } // keep a special buf static char s_buf[1024*64]; static char *s_bufEnd = s_buf + 1024*64; static char *s_ptr = s_buf; static bool s_overflow = false; static char s_problem = '\0'; // . if we're in a sig handler come here // . store: // . 4 bytes = size of string space // . X bytes = NULL terminated format string // . X bytes = 0-3 bytes word-alignment padding bool Log::logLater ( long long now, long type, char *format, va_list ap ) { //return false; // we have to be in a sig handler //if ( ! g_inSigHandler ) // fprintf(stderr,"Log::logLater: this should not have been called\n"); // was it set before us? //bool queueSig = ! m_needsPrinting; // set the signal to print this out later m_needsPrinting = true; // save old s_ptr in case we have error char *start = s_ptr; // size of format string we must store long flen = gbstrlen ( format ) + 1; // do we have room to store the stuff? if ( s_ptr + 4 + 4 + flen > s_bufEnd ) { s_overflow = true; return false; } // first 4 bytes are the size of the string space, write later long stringSizes = 0; s_ptr += 4; // the priorty is the 2nd 4 bytes memcpy_ass ( s_ptr , (char *)&type , 4 ); s_ptr += 4; // store the format string first memcpy_ass ( s_ptr , format , flen ); s_ptr += flen; // the type of each arg is given by format char *p = format; // point to the variable args data char *pap = (char *)ap; // loop looking for %s, %li, etc. loop: while ( *p && *p != '%' ) p++; // bail if done if ( ! *p ) goto done; // skip the percent p++; // skip if back to back if ( *p == '%' ) { p++; goto loop; } // skip following numbers, those are part of format while ( *p && is_digit(*p) ) p++; // is it a long, half or int? if so, leave as is. if ( *p == 'l' ) { pap += 4; // it could be a long long if ( (*p+1) == 'l' ) pap += 4; goto loop; } if ( *p == 'h' ) { pap += 4; goto loop; } if ( *p == 'i' ) { pap += 4; goto loop; } if ( *p == 'c' ) { pap += 4; goto loop; } // . it it a string? // . if so store it on s_ptr if ( *p == 's' ) { char *s = *(char **)pap; long slen = gbstrlen(s) + 1; if ( s_ptr + slen >= s_bufEnd ) { s_ptr = start; s_overflow = true; return false; } memcpy_ass ( s_ptr , s , slen ); *(char **)pap = s_ptr; // replace old char ptr to use ours now s_ptr += slen; stringSizes += slen; pap += 4; // skip over a char ptr arg goto loop; } // panic if we don't know the type!!! s_ptr = start; s_problem = *p; return false; // save the args themselves and the time done: // how big were the strings we stored, if any memcpy_ass ( start , (char *)&stringSizes , 4 ); // size of args we must store long apsize = pap - (char *)ap; // bail if not enough room if ( s_ptr + 8 + 4 + 3 + apsize >= s_bufEnd ) { s_ptr = start; s_overflow = true; return false; } // store the time stamp in milliseconds memcpy_ass ( s_ptr , (char *)&now , 8 ); s_ptr += 8; // store arg sizes memcpy_ass ( s_ptr , (char *)&apsize , 4 ); s_ptr += 4; // dword align long rem = ((unsigned long)s_ptr) % 4; if ( rem > 0 ) s_ptr += 4 - rem; // store the args themselves memcpy_ass ( s_ptr , (char *)ap , apsize ); s_ptr += apsize; // queue a signal if we need to //if ( ! queueSig ) return false; // queue the signal //sigval_t svt; //svt.sival_int = 1; //if ( sigqueue ( s_pid, GB_SIGRTMIN + 1 + 0, svt ) < 0) // g_loop.m_needToPoll = true; return false; } // once we're no longer in a sig handler this is called by Loop.cpp // if g_log.needsPrinting() is true void Log::printBuf ( ) { // not in sig handler if ( g_inSigHandler ) return; // was there a problem? if ( s_problem ) fprintf(stderr,"Log::printBuf: had problem. '%c'\n", s_problem); // or overflow? if ( s_overflow ) fprintf(stderr,"Log::printBuf: had overflow.\n"); // point to the buf char *p = s_buf; char *pend = s_ptr; // reset everything s_overflow = false; s_problem = '\0'; m_needsPrinting = false; // bail if nothing to print, maybe first msg overflowed? if ( s_buf == s_ptr ) return; // we cannot be interrupted in here //bool flipped = false; //if ( g_interruptsOn ) { // flipped = true; // g_loop.interruptsOff(); //} // reset buffer here s_ptr = s_buf; // now print all log msgs we got while in a signal handler loop: // sanity check if ( p + 8 > pend ) { fprintf(stderr,"Had error in Log.cpp: breech of log buffer4."); s_ptr = s_buf; return; } // first 4 bytes are the size of the string arguments long stringSizes; memcpy ( (char *)&stringSizes , p , 4 ); p += 4; // then the type of the msg long type; memcpy ( (char *)&type , p , 4 ); p += 4; // then the format string char *format = p; // its length including the \0 //long flen = gbstrlen ( format ) + 1; long flen = 0; char *q = format; while ( q < pend && *q ) q++; if ( q >= pend ) { fprintf(stderr,"Had error in Log.cpp: breech of log buffer3."); s_ptr = s_buf; return; } flen = q - p + 1; p += flen; // skip the string arguments now p += stringSizes; // sanity check if ( p + 8 + 4 > pend || p < s_buf ) { fprintf(stderr,"Had error in Log.cpp: breech of log buffer2."); s_ptr = s_buf; return; } // get time long long now ; memcpy ( (char *)&now , p , 8 ); p += 8; // get size of args long apsize ; memcpy ( (char *)&apsize , p , 4 ); p += 4; // dword align long rem = ((unsigned long)p) % 4; if ( rem > 0 ) p += 4 - rem; // get va_list... needs to be word aligned!! va_list ap = (char*)(void*)p; p += apsize; // . sanity check // . i've seen this happen a lot lately since i started logging cancel // acks perhaps? if ( p > pend || p < s_buf ) { fprintf(stderr,"Had error in Log.cpp: breech of log buffer."); s_ptr = s_buf; return; } // print msg into this buf char buf[1024*4]; // print it into our buf now vsnprintf ( buf , 1024*4 , format , ap ); // pass buf to g_log logR ( now , type , buf , true ); // if not done loop back if ( p < pend ) goto loop; // turn 'em back on if we turned them off //if ( flipped ) g_loop.interruptsOn(); } #include // isascii() // . IMPORTANT: should be called while the lock is on! // . we just re-write to the file bool Log::dumpLog ( ) { // . usually g_errno is set to something // . save it in case we set g_errno long errnum = g_errno; // for now don't dump m_numErrors = 0; m_bufPtr = 0; // just return true if no file open if ( m_fd < 0 ) return true; // for now just return true always return true; // . remove half the error from our memory buffer. // . log then shift the first half outta the picture... bye bye // . we add one because its safe to assume we have 1 more msg than // we do..???? TODO // now shift over the old stuff in the arrays... // be sure to record it in the file if we can before we shift over it. for ( int i=0; i < m_numErrors ; i++ ) { // get time in seconds time_t t = m_errorTime[i] / 1000; // hack off ctime's appended \n //char *ct = ctime ( &t ); char *ct = asctime(gmtime ( &t )); ct[gbstrlen(ct)-1] = '\0'; char tmp[1024 * 2]; snprintf ( tmp , 1024*2 , "%s(UTC):%s" , ct , m_errorMsg[i] ); // TODO: add port # long tmpLen = gbstrlen(tmp); // filter out garbage for ( long j=0; j < tmpLen ; j++ ) if ( !isascii(tmp[j]) ) tmp[j]='X'; long n = write ( m_fd , tmp , tmpLen ); if ( n == tmpLen ) continue; fprintf(stderr,"Log::dumpLog: %s\n",mstrerror(g_errno)); // reload the original g_errno g_errno = errnum; break; } // reset everything m_numErrors = 0; m_bufPtr = 0; return true; } bool log ( long type , char *formatString , ...) { if ( g_log.m_disabled ) return false; // do not log it if we should not if ( ! g_log.shouldLog ( type , formatString ) ) return false; // do not log it if we should not //if ( type == LOG_WARN && ! g_conf.m_logWarnings ) return false; // is it congestion? if ( g_errno == ENOSLOTS && ! g_conf.m_logNetCongestion ) return false; // 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); // debug hack for testing if ( g_inSigHandler ) return g_log.logLater ( g_now , type , formatString , ap); // 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 , false ); // always return false return false; } bool log ( char *formatString , ... ) { if ( g_log.m_disabled ) return false; // do not log it if we should not if ( ! g_log.shouldLog ( LOG_WARN , formatString ) ) return false; // is it congestion? if ( g_errno == ENOSLOTS && ! g_conf.m_logNetCongestion ) return false; // 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); // debug hack for testing if ( g_inSigHandler ) return g_log.logLater ( g_now , LOG_WARN , formatString , ap); // print it into our buf now vsnprintf ( buf , 1024*10 , formatString , ap ); va_end(ap); // pass buf to g_log g_log.logR ( 0 , LOG_WARN , buf , false ); // always return false return false; } bool logf ( long type , char *formatString , ...) { if ( g_log.m_disabled ) return false; // do not log it if we should not //if ( type == LOG_WARN && ! g_conf.m_logWarnings ) return false; // is it congestion? if ( g_errno == ENOSLOTS && ! g_conf.m_logNetCongestion ) return false; // 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); // debug hack for testing if ( g_inSigHandler ) return g_log.logLater ( g_now , type , formatString , ap); // 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 , false , true /*forced?*/ ); // always return false return false; }