// snfLOGmgr.cpp // // (C) Copyright 2006 - 2009 ARM Research Labs, LLC. // See www.armresearch.com for the copyright terms. // // Log Manager implementations see snfLOGmgr.hpp for details. #include "snfLOGmgr.hpp" #include "../CodeDweller/threading.hpp" #include "../CodeDweller/timing.hpp" #include #include #include using namespace std; //// DiscLogger //////////////////////////////////////////////////////////////// const ThreadType DiscLogger::Type("DiscLogger"); // The thread's type. const ThreadState DiscLogger::DiscLogger_Flush("Flushing"); // Flushing state. const ThreadState DiscLogger::DiscLogger_Wait("Waiting"); // Waiting state. DiscLogger::DiscLogger(string N) : // When it is time to start... Thread(DiscLogger::Type, N), // DiscLogger Type and Name. UseANotB(true), // Set all of the flags to their isDirty(false), // appropriate initial state isBad(false), // then start the thread. isTimeToStop(false), inAppendMode(true), isEnabled(true) { run(); } DiscLogger::~DiscLogger() { // When it is time to go away... isTimeToStop = true; // Set the stop flag. flush(); // Flush if we should. join(); // Wait for the thread to stop. } void DiscLogger::post(const string Input, const string NewPath) { // Post Input to log. if(!isEnabled) return; // If we're not enabled, eat it. ScopeMutex PostingNewDataNobodyMove(BufferControlMutex); // Keep things static while posting. if(0 < NewPath.length()) { myPath = NewPath; } // Reset the path if provided. string& Buffer = PostingBuffer(); // Grab the posting buffer. if(!inAppendMode) Buffer.clear(); // If overwriting, clear the old. Buffer.append(Input); // Add the new data. isDirty = true; // We're dirty now. } // The DiscLogger flush() method is designed to lose data if it is unable to // write the data to the file. The alternative would allow an unlimited amount // of data to build up in the buffers and that would be bad. void DiscLogger::flush() { // Flush right now! string FilePath; // Local copy of the path. ScopeMutex FlushingNow(FlushMutex); // We're flushing. if(isDirty) { // Nothing to do if not dirty. BufferControlMutex.lock(); // Lock the buffer controls. FlushingBuffer().clear(); // Clear the old flushing buffer. UseANotB = (!UseANotB); // Flip the buffers. isDirty = false; // We are not dirty anymore. string& Buffer = FlushingBuffer(); // Grab the new flushing buffer. FilePath = myPath; // Grab the current file path. BufferControlMutex.unlock(); // Unlock the buffer controls. try { // Insulate against exceptions. ofstream File( // Open the file. FilePath.c_str(), // Use the path we have. (inAppendMode) ? (ios::app) : (ios::trunc) // Append or Truncate appropriately. ); File << Buffer; // Write the buffer. if(File.bad()) throw false; // If someting went wrong, throw. File.close(); // Close the file. } catch(...) { // If we had an exception then isBad = true; // make sure the bad bit is on and return; // we are done. } isBad = false; // If nothing went wrong we're good! } } void DiscLogger::myTask() { // Main thread task Sleeper WaitASecond(1000); // How to wait for 1 second. while(!isTimeToStop) { // Until it is time to stop: CurrentThreadState(DiscLogger_Wait); // post our waiting and WaitASecond(); // we wait a second, then CurrentThreadState(DiscLogger_Flush); // post our activity and flush(); // flush our data to disc } // then do it again. } //// snfScanData /////////////////////////////////////////////////////////////// snfScanData::snfScanData(int ScanHorizon) : // How to create. ReadyToClear(true), // Make sure initial clear will happen. FilteredData(ScanHorizon, 0) { // Allocate the Filtered Data buffer. clear(); // Start with no data. } snfScanData::~snfScanData() { // Cleans up lists etc. ReadyToClear = true; // Make sure the clear will happen. clear(); // Say we have no data. } void snfScanData::clear() { // Clear the data for the next message. if(!ReadyToClear) return; // Don't double clear. ReadyToClear = false; // No clearing now until logged. // Clear the IP scan data memset(MyIPScanData, 0, sizeof(MyIPScanData)); // Clear the IP scan data and MyIPCount = 0; // the count of scanned IPs. memset(DrillDownFlags, 0, sizeof(DrillDownFlags)); // Clear all DrillDown flags. SourceIPOrdinal = -1; // There is no source IP because it SourceIPFoundFlag = false; // has not yet been found. SourceIPRangeFlag = snfIPRange::Unknown; // Range flag is not yet known. SourceIPEvaluation.clear(); // No eval yet. myHeaderDirectiveSourceIP = 0UL; // Header directive source is empty now. myCallerForcedSourceIP = 0UL; // Caller forced source is empty now. // Clear basic message stats & id info. StartOfJobUTC = 0; // Clear the start of job clock. SetupTime = 0; // Time in ms spent setting up to scan. ScanName.clear(); // Identifying name or message file name. /** The Timer ScanTime is explicitely NOT reset during clear() operations. *** Instead, the ScanTime Timer is controlled as a ScopeTimer() during the *** scan() operation exclusively. **/ ScanSize = 0; // Scan size is zero. ScanDepth = 0; // Scan depth is zero. // Log entries and X- headers ClassicLogText.clear(); // Classic log entry text if any. XMLLogText.clear(); // XML log entry text if any. XHDRsText.clear(); // XHeaders text if any. XHeaderInjectOn = false; // True if injecting headers is on. XHeaderFileOn = false; // True if creating .xhdr file is on. // Clear the GBUdb Event Tracking Flags GBUdbNormalTriggered = false; // True if GBUdb indeterminate IP source. GBUdbWhiteTriggered = false; // True if GBUdb found source IP white. GBUdbWhiteSymbolForced = false; // True if white was on and symbol was set. GBUdbPatternSourceConflict = false; // True if a pattern was found with a white IP. GBUdbAutoPanicTriggered = false; // True if autopanic was triggered. GBUdbAutoPanicExecuted = false; // True if an autopanic was added. GBUdbBlackTriggered = false; // True if GBUdb found source IP black. GBUdbBlackSymbolForced = false; // True if black was on and symbol was set. GBUdbTruncateTriggered = false; // True if Truncate was possible. GBUdbPeekTriggered = false; // True if we could peek. GBUdbSampleTriggered = false; // True if we could sample. GBUdbTruncateExecuted = false; // True if we actually did truncate. GBUdbPeekExecuted = false; // True if we peeked instead of truncating. GBUdbSampleExecuted = false; // True if we sampled. GBUdbCautionTriggered = false; // True if GBUdb found source IP suspicous. GBUdbCautionSymbolForced = false; // True if caution was on and symbol was set. // Clear the rule panic tracking list RulePanics.clear(); // Remove all entries. // Pattern Engine Scan Result Data HeaderDirectiveFlags = 0UL; // Flags set by header directives. PatternWasFound = false; // True if a pattern was found. PatternID = 0; // Rule ID of the pattern. PatternSymbol = 0; // Symbol of the pattern. MatchRecords.clear(); // Clear the match records list. MatchRecordsCursor = MatchRecords.end(); // Init the cursor to nowhere. CompositeFinalResult = -1; } //// snfCounterPack //////////////////////////////////////////////////////////// snfCounterPack::snfCounterPack() { // When constructing a counter pack reset(); // reset it. } void snfCounterPack::reset() { // When asked to reset we do this: memset(&Events, 0, sizeof(Events)); // Fill them with zeros. } //// IntervalTimer ///////////////////////////////////////////////////////////// Timer& IntervalTimer::Active() { // Return the active timer. return ((ANotB)?A:B); // If A is active, return A } // otherwise return B. Timer& IntervalTimer::Inactive() { // Return the inactive timer. return ((ANotB)?B:A); // If A is active, return B } // otherwise return A. msclock IntervalTimer::hack() { // Chop off a new interval & return it. Inactive().start(Active().stop()); // Stop the active clock and reference ANotB = ~ANotB; // it to start the new Active clock. return Interval(); // Flip the bit and return the Interval. } msclock IntervalTimer::Interval() { // Return the last interval. return Inactive().getElapsedTime(); // Return the Inactive elapsed time. } msclock IntervalTimer::Elapsed() { // Return the time since last hack. return Active().getElapsedTime(); // Return the Active elapsed time. } //// snfLOGmgr ///////////////////////////////////////////////////////////////// const ThreadType snfLOGmgr::Type("snfLOGmgr"); // The thread's type. snfLOGmgr::snfLOGmgr() : // Constructor for the LOG manager Thread(snfLOGmgr::Type, "Log Manager"), // snfLOGmgr Type and Name. Configured(false), // Not yet configured. TimeToDie(false), // Not yet time to die. PeekEnableCounter(0), // No peeking yet. SampleEnableCounter(0), // No sampling yet. myNETmgr(NULL), // No NET mgr yet. myGBUdb(NULL), // No GBUdb yet. NewerRulebaseIsAvailable(false), // No newer rulebase yet. SecondStatusLogger("Second Status Logger"), // Lazy writer for Second status. MinuteStatusLogger("Minute Status Logger"), // Lazy writer for Minute status. HourStatusLogger("Hour Status Logger"), // Lazy writer for Hour status. XMLScanLogger("XML Scan Logger"), // Lazy writer for XML Scan log. ClassicScanLogger("Classic Scan Logger") { // Lazy writer for Classic Scan log. StartupTime = Timestamp(); // Record when did we start. CurrentCounters = &CounterPackA; // Assign the active CounterPack. ReportingCounters = &CounterPackB; // Assign the reporting CounterPack. Timestamp(SecondReportTimestamp); // Set the basetime for the Second, Timestamp(MinuteReportTimestamp); // Minute, and Hour status reports. Timestamp(HourReportTimestamp); run(); // Run the thread. } snfLOGmgr::~snfLOGmgr() { // When we go away we must stop(); // stop if we haven't already. if(Configured) Status.store(PersistentFileName); // If safe, store our persistent data. } void snfLOGmgr::linkNETmgr(snfNETmgr& N) { myNETmgr = &N; } // Link in my NETmgr void snfLOGmgr::linkGBUdb(GBUdb& G) { myGBUdb = &G; } // Link in my GBUdb void snfLOGmgr::stop() { // When we want to stop if(!TimeToDie) { // check that we didn't already, then TimeToDie = true; // we set time to die and join(); // join the thread; } } //// Here are some functions for creating status reports. // Handy subroutine to encapsulate status log posting logic. void snfLOGmgr::postStatusLog( // Post a Status log if required. const string& LogData, // Here's the log entry's data. const string& LogFileName, // Here is where it should go. const bool LogEnabled, // This is true if we should write it. const bool AppendNotOverwrite, // True=Append, False=Overwrite. DiscLogger& Logger // The logger to use. ) { if(!LogEnabled) return; // If we're not supposed to, don't! string TFN = LogFileName; // Tagged File Name if(AppendNotOverwrite) { // If we're appending, rotate per day. TFN.append("."); // Put a timestamp on the file name. if(Rotate_LocalTime) { LocalTimestamp(TFN); } // Use either the local timestamp or else { Timestamp(TFN); } // the utc timestamp as configured. TFN = TFN.substr(0, TFN.length() - 6); // Stip off the Hours, Minutes, Seconds. } TFN.append(".log.xml"); // Tack on the extension. // Now feed this to the lazy logger. Logger.Enabled(LogEnabled); // Set the enable flag. Logger.AppendMode(AppendNotOverwrite); // Set the append mode. Logger.post(LogData, TFN); // Post data and update the name. } // Handy function to normalize data to a base. // Also, a collection of handy bases to normalize to ;-) const int MillisecondsInASecond = 1000; // Second const int MillisecondsInAMinute = MillisecondsInASecond * 60; // Minute const int MillisecondsInAnHour = MillisecondsInAMinute * 60; // Hour const int MillisecondsInADay = MillisecondsInAnHour * 24; // Day double snf_rationalize(double Count, double Base, double NewBase) { // Cross multiply to convert bases. if(0.0 == Base) return 0.0; // Handle division by zero like this. return (Count * NewBase) / Base; // Do the math. } double snf_AveragePerSecond(snf_SMHDMY_Counter& D, snf_SMHDMY_Counter& T) { // Avg Data/sec given Data & Time Counters. return snf_rationalize( D.SEC6SUM, T.SEC6SUM, MillisecondsInASecond); } double snf_AveragePerMinute(snf_SMHDMY_Counter& D, snf_SMHDMY_Counter& T) { // Avg Data/min given Data & Time Counters. return snf_rationalize( D.SumThru1Minute(), T.SumThru1Minute(), MillisecondsInAMinute); } double snf_AveragePerHour(snf_SMHDMY_Counter& D, snf_SMHDMY_Counter& T) { // Avg Data/min given Data & Time Counters. return snf_rationalize( D.SumThru1Hour(), T.SumThru1Hour(), MillisecondsInAnHour); } double snf_AveragePerDay(snf_SMHDMY_Counter& D, snf_SMHDMY_Counter& T) { // Avg Data/min given Data & Time Counters. return snf_rationalize( D.SumThru1Day(), T.SumThru1Day(), MillisecondsInADay); } void AppendRatesElement( // Format & output a rates element. const char* Name, // The name of the element (usually 1 char). snf_SMHDMY_Counter& D, // Data counter snf_SMHDMY_Counter& T, // Time counter ostringstream& S) { // Where to append the formatted output. S << "\t\t<" << Name << " " << "s=\'" << snf_AveragePerSecond(D, T) << "\' " << "m=\'" << snf_AveragePerMinute(D, T) << "\' " << "h=\'" << snf_AveragePerHour(D, T) << "\' " << "d=\'" << snf_AveragePerDay(D, T) << "\'/>" << endl; } void AppendHistogramElements(Histogram& H, ostringstream& S) { // Format & output a histogram. if(0 < H.size()) { // Don't output empty histograms. S << "\t\t" << endl; // Open tag w/ hits count. set::iterator iH; // Use an iterator to for(iH = H.begin(); iH != H.end(); iH++) { // loop through all of the groups. S << "\t\t\t" << endl; // the count of hits. } S << "\t\t" << endl; // Close tag. } } // This gets called once per second. It is responsible for inputting the base // data into all of the histograms and counter mechnisms. After that, the minute // and hour reports are triggered when a full cycle of lower order data has // been collected. bool snfLOGmgr::do_SecondReport() { // Send our 1 second status report. // First thing - we always update the summaries for everybody :-) snfCounterPack& Counters = (*(getSnapshot())); // Get and swap the counters. TimeCounter.input(Counters.ActiveTime.getElapsedTime()); // Add the time interval. MessageCounter.input(Counters.Events.Scans); // Add the number of scans (messages). SpamCounter.input(Counters.Events.Spam); // Add the number of Spam events. HamCounter.input(Counters.Events.Ham); // Add the number of Ham events. WhiteCounter.input(Counters.Events.GBUdbWhiteSymbolForced); // Add the number of White events. CautionCounter.input(Counters.Events.GBUdbCautionSymbolForced); // Add the number of Caution events. BlackCounter.input(Counters.Events.GBUdbBlackSymbolForced); // Add the number of Black events. TruncateCounter.input(Counters.Events.GBUdbTruncateExecuted); // Add the number of Truncate events. SampleCounter.input(Counters.Events.GBUdbSampleExecuted); // Add the number of Sample events. AutoPanicCounter.input(Counters.Events.GBUdbAutoPanicTriggered); // Add the number of AutoPanic events. RulePanicCounter.input(Counters.Events.RulePanicFound); // Add the number of RulePanic events. // Next we produce our "Second" status report. ostringstream Report; //-- Report the stats element -- Report << "" << endl; SecondReportTimestamp = ""; Timestamp(SecondReportTimestamp); // Reset the timestamp for next time. //-- Version data -- Report << "\t" << endl << "\t\t" << SNF_ENGINE_VERSION << "" << endl; if(0 < myPlatformVersion.length()) { Report << "\t\t" << myPlatformVersion << "" << endl; } Report << "\t" << endl; //-- Timers section -- Report << "\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t" << endl; //-- GBUdb section -- Report << "\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t" << endl; //-- Counters -- Report << "\t" << endl; if(0 < Counters.Events.Scans) { Report << "\t\t" << endl; } if(0 < Counters.Events.Spam) { Report << "\t\t" << endl; } if(0 < Counters.Events.Ham) { Report << "\t\t" << endl; } if(0 < Counters.Events.GBUdbTruncateExecuted) { Report << "\t\t" << endl; } if(0 < Counters.Events.GBUdbBlackSymbolForced) { Report << "\t\t" << endl; } if(0 < Counters.Events.GBUdbCautionSymbolForced) { Report << "\t\t" << endl; } if(0 < Counters.Events.GBUdbWhiteSymbolForced) { Report << "\t\t" << endl; } if(0 < Counters.Events.GBUdbAutoPanicExecuted) { Report << "\t\t" << endl; } if(0 < Counters.Events.RulePanicFound) { Report << "\t\t" << endl; } Report << "\t" << endl; Counters.reset(); // When done, clear the counters. //-- Rates --- Report << "\t" << endl; AppendRatesElement("m", MessageCounter, TimeCounter, Report); AppendRatesElement("s", SpamCounter, TimeCounter, Report); AppendRatesElement("h", HamCounter, TimeCounter, Report); AppendRatesElement("w", WhiteCounter, TimeCounter, Report); AppendRatesElement("c", CautionCounter, TimeCounter, Report); AppendRatesElement("b", BlackCounter, TimeCounter, Report); AppendRatesElement("t", TruncateCounter, TimeCounter, Report); AppendRatesElement("a", AutoPanicCounter, TimeCounter, Report); AppendRatesElement("r", RulePanicCounter, TimeCounter, Report); Report << "\t" << endl; //-- Results --- Report << "\t" << endl; AppendHistogramElements(ResultsSecond, Report); ResultsSecond.reset(); Report << "\t" << endl; //-- Rules --- Report << "\t" << endl; string RBUTC; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; AppendHistogramElements(RulesSecond, Report); RulesSecond.reset(); Report << "\t" << endl; //-- Panics --- Report << "\t" << endl; AppendHistogramElements(PanicsSecond, Report); PanicsSecond.reset(); Report << "\t" << endl; //-- Close the stats element -- Report << "" << endl; // Now that we've built the report we need to store it and send it to // the network manager. ConfigMutex.lock(); // Freeze while we get our settings. bool LogEnabled = SecondReport_Log_OnOff; // To log or not to log? bool AppendNotOverwrite = SecondReport_Append_OnOff; // To append or overwrite? string LogFileName = SecondReport_Log_Filename; // What file name? ConfigMutex.unlock(); // Ok, done with that. postStatusLog( // Post a Status log if required. Report.str(), // Here's the log entry's data. LogFileName, // Here is where it should go. LogEnabled, // This is true if we should write it. AppendNotOverwrite, // True=Append, False=Overwrite. SecondStatusLogger // Lazy log writer to use. ); // Just before we go we save our stat for others to see. ScopeMutex HoldForStatusUpdate(StatusReportMutex); // Hold the mutex just long enough SecondReportText = Report.str(); // to post our status and return // Finally we return the test - Do we have a complete cycle in Seconds? return(TimeCounter.Cycled60Seconds()); // True on a full cycle of seconds. } bool snfLOGmgr::do_MinuteReport() { // Send our 1 minute status report. // Produce our "Minute" status report. ostringstream Report; //-- Report the stats element -- Report << "" << endl; MinuteReportTimestamp = ""; Timestamp(MinuteReportTimestamp); // Reset the timestamp for next time. //-- Version data -- Report << "\t" << endl << "\t\t" << SNF_ENGINE_VERSION << "" << endl; if(0 < myPlatformVersion.length()) { Report << "\t\t" << myPlatformVersion << "" << endl; } Report << "\t" << endl; //-- Timers section -- Report << "\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t" << endl; //-- GBUdb section -- Report << "\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t" << endl; //-- Counters -- Report << "\t" << endl; if(0 < MessageCounter.Sum60Seconds()) { Report << "\t\t" << endl; } if(0 < SpamCounter.Sum60Seconds()) { Report << "\t\t" << endl; } if(0 < HamCounter.Sum60Seconds()) { Report << "\t\t" << endl; } if(0 < TruncateCounter.Sum60Seconds()) { Report << "\t\t" << endl; } if(0 < BlackCounter.Sum60Seconds()) { Report << "\t\t" << endl; } if(0 < CautionCounter.Sum60Seconds()) { Report << "\t\t" << endl; } if(0 < WhiteCounter.Sum60Seconds()) { Report << "\t\t" << endl; } if(0 < AutoPanicCounter.Sum60Seconds()) { Report << "\t\t" << endl; } if(0 < RulePanicCounter.Sum60Seconds()) { Report << "\t\t" << endl; } Report << "\t" << endl; //-- Rates --- Report << "\t" << endl; AppendRatesElement("m", MessageCounter, TimeCounter, Report); AppendRatesElement("s", SpamCounter, TimeCounter, Report); AppendRatesElement("h", HamCounter, TimeCounter, Report); AppendRatesElement("w", WhiteCounter, TimeCounter, Report); AppendRatesElement("c", CautionCounter, TimeCounter, Report); AppendRatesElement("b", BlackCounter, TimeCounter, Report); AppendRatesElement("t", TruncateCounter, TimeCounter, Report); AppendRatesElement("a", AutoPanicCounter, TimeCounter, Report); AppendRatesElement("r", RulePanicCounter, TimeCounter, Report); Report << "\t" << endl; //-- Results --- Report << "\t" << endl; AppendHistogramElements(ResultsMinute, Report); ResultsMinute.reset(); Report << "\t" << endl; //-- Rules --- Report << "\t" << endl; string RBUTC; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; AppendHistogramElements(RulesMinute, Report); RulesMinute.reset(); Report << "\t" << endl; //-- Panics --- Report << "\t" << endl; AppendHistogramElements(PanicsMinute, Report); PanicsMinute.reset(); Report << "\t" << endl; //-- Close the stats element -- Report << "" << endl; // Now that we've built the report we need to store it and send it to // the network manager. ConfigMutex.lock(); // Freeze while we get our settings. bool LogEnabled = MinuteReport_Log_OnOff; // To log or not to log? bool AppendNotOverwrite = MinuteReport_Append_OnOff; // To append or overwrite? string LogFileName = MinuteReport_Log_Filename; // What file name? ConfigMutex.unlock(); // Ok, done with that. postStatusLog( // Post a Status log if required. Report.str(), // Here's the log entry's data. LogFileName, // Here is where it should go. LogEnabled, // This is true if we should write it. AppendNotOverwrite, // True=Append, False=Overwrite. MinuteStatusLogger // Lazy log writer to use. ); (*myNETmgr).sendReport(Report.str()); // Send the status report to the net. // Just before we go we save our stat for others to see. ScopeMutex HoldForStatusUpdate(StatusReportMutex); // Hold the mutex just long enough MinuteReportText = Report.str(); // to post our status and return return(TimeCounter.Cycled60Minutes()); // True at a full cycle of minutes. } bool snfLOGmgr::do_HourReport() { // Send our 1 hour status report. // Produce our "Hour" status report. ostringstream Report; //-- Report the stats element -- Report << "" << endl; HourReportTimestamp = ""; Timestamp(HourReportTimestamp); // Reset the timestamp for next time. //-- Version data -- Report << "\t" << endl << "\t\t" << SNF_ENGINE_VERSION << "" << endl; if(0 < myPlatformVersion.length()) { Report << "\t\t" << myPlatformVersion << "" << endl; } Report << "\t" << endl; //-- Timers section -- Report << "\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t" << endl; //-- GBUdb section -- Report << "\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t" << endl; //-- Counters -- Report << "\t" << endl; if(0 < MessageCounter.Sum60Minutes()) { Report << "\t\t" << endl; } if(0 < SpamCounter.Sum60Minutes()) { Report << "\t\t" << endl; } if(0 < HamCounter.Sum60Minutes()) { Report << "\t\t" << endl; } if(0 < TruncateCounter.Sum60Minutes()) { Report << "\t\t" << endl; } if(0 < BlackCounter.Sum60Minutes()) { Report << "\t\t" << endl; } if(0 < CautionCounter.Sum60Minutes()) { Report << "\t\t" << endl; } if(0 < WhiteCounter.Sum60Minutes()) { Report << "\t\t" << endl; } if(0 < AutoPanicCounter.Sum60Minutes()) { Report << "\t\t" << endl; } if(0 < RulePanicCounter.Sum60Minutes()) { Report << "\t\t" << endl; } Report << "\t" << endl; //-- Rates --- Report << "\t" << endl; AppendRatesElement("m", MessageCounter, TimeCounter, Report); AppendRatesElement("s", SpamCounter, TimeCounter, Report); AppendRatesElement("h", HamCounter, TimeCounter, Report); AppendRatesElement("w", WhiteCounter, TimeCounter, Report); AppendRatesElement("c", CautionCounter, TimeCounter, Report); AppendRatesElement("b", BlackCounter, TimeCounter, Report); AppendRatesElement("t", TruncateCounter, TimeCounter, Report); AppendRatesElement("a", AutoPanicCounter, TimeCounter, Report); AppendRatesElement("r", RulePanicCounter, TimeCounter, Report); Report << "\t" << endl; //-- Results --- Report << "\t" << endl; AppendHistogramElements(ResultsHour, Report); ResultsHour.reset(); Report << "\t" << endl; //-- Rules --- Report << "\t" << endl; string RBUTC; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; Report << "\t\t" << endl; AppendHistogramElements(RulesHour, Report); RulesHour.reset(); Report << "\t" << endl; //-- Panics --- Report << "\t" << endl; AppendHistogramElements(PanicsHour, Report); PanicsHour.reset(); Report << "\t" << endl; //-- Close the stats element -- Report << "" << endl; // Now that we've built the report we need to store it and send it to // the network manager. ConfigMutex.lock(); // Freeze while we get our settings. bool LogEnabled = HourReport_Log_OnOff; // To log or not to log? bool AppendNotOverwrite = HourReport_Append_OnOff; // To append or overwrite? string LogFileName = HourReport_Log_Filename; // What file name? ConfigMutex.unlock(); // Ok, done with that. postStatusLog( // Post a Status log if required. Report.str(), // Here's the log entry's data. LogFileName, // Here is where it should go. LogEnabled, // This is true if we should write it. AppendNotOverwrite, // True=Append, False=Overwrite. HourStatusLogger // Lazy log writer to use. ); // Just before we go we save our stat for others to see. ScopeMutex HoldForStatusUpdate(StatusReportMutex); // Hold the mutex just long enough HourReportText = Report.str(); // to post our status and return return(TimeCounter.Cycled24Hours()); // True at a full cycle of hours. } void snfLOGmgr::do_StatusReports() { // Do the status reports. ScopeMutex PauseWhileITotalThis(MyMutex); // Everybody stop for a bit. Each report if(do_SecondReport()) // returns true if it has cycled so if(do_MinuteReport()) // that the next report can be checked do_HourReport(); // to see if it has cycled. } void snfLOGmgr::myTask() { // Thread: Live stats & reports. Sleeper WaitATic(MillisecondsInASecond); // One second sleeper. while(!TimeToDie) { // Do this until it's time to die. if(Configured) { // If we are configured do our work. do_StatusReports(); // Make our status reports (chained). } WaitATic(); } } // Note about snfLOGmgr::configure() and Status.restore() // store() and restore() watch the Status.Ready flag. If // Status is ready, restore() won't. If Status is not ready // store() won't. Also, if restore() doesn't find a file, it // just clears everything and goes ready, assuming that this // is a new persistent state. void snfLOGmgr::configure(snfCFGData& CFGData) { // Update the configuration. ScopeMutex HoldOnWhileITweakThisThing(ConfigMutex); PersistentFileName = CFGData.paths_workspace_path + ".state"; // Build the persistent state path. Status.restore(PersistentFileName); // Load our persistent state. NodeId = CFGData.node_licenseid; // Grab the node id for reports. // Copy the logging configuration info from CFGData Rotate_LocalTime = CFGData.Logs_Rotation_LocalTime_OnOff; // Rotate using local time? XML_Log_Mode = CFGData.Scan_XML_Mode; // What is the XML log mode. Classic_Log_Mode = CFGData.Scan_Classic_Mode; // What is the Classic log mode. LogsPath = CFGData.paths_log_path; // Path to logs directory. ClassicLogRotate = CFGData.Scan_Classic_Rotate; // True = Rotate Classic Log. XMLLogRotate = CFGData.Scan_XML_Rotate; // True = Rotate XML Log. SecondReport_Log_OnOff = CFGData.Status_SecondReport_Log_OnOff; SecondReport_Append_OnOff = CFGData.Status_SecondReport_Append_OnOff; SecondReport_Log_Filename = CFGData.paths_log_path + NodeId + ".status.second"; MinuteReport_Log_OnOff = CFGData.Status_MinuteReport_Log_OnOff; MinuteReport_Append_OnOff = CFGData.Status_MinuteReport_Append_OnOff; MinuteReport_Log_Filename = CFGData.paths_log_path + NodeId + ".status.minute"; HourReport_Log_OnOff = CFGData.Status_HourReport_Log_OnOff; HourReport_Append_OnOff = CFGData.Status_HourReport_Append_OnOff; HourReport_Log_Filename = CFGData.paths_log_path + NodeId + ".status.hour"; // Sanity check if(NULL != myNETmgr && NULL != myGBUdb) { // If we are fully linked then Configured = true; // we are now configured. } } void snfLOGmgr::doXHDRs(snfCFGData& CFGData, snfScanData& ScanData) { // XHDR sub routine for LogThisScan() ostringstream O; // Setup the output stream. const string SMTPENDL = "\r\n"; // Make a hard-coded SMTP endline. // Version header if(CFGData.XHDRVersion_OnOff) { // If the Version XHDR is on then O << CFGData.XHDRVersion_Header << ": " // emit the Version XHDR. << SMTPENDL << "\t" << SNF_ENGINE_VERSION; if(0 < myPlatformVersion.length()) { // Optional Platform Version. O << SMTPENDL << "\t" << myPlatformVersion; } O << SMTPENDL; } // License header if(CFGData.XHDRLicense_OnOff) { // If the license XHDR is on then O << CFGData.XHDRLicense_Header << ": " // emit the License XHRD. << CFGData.node_licenseid << SMTPENDL; } // Rulebase header if(CFGData.XHDRRulebase_OnOff) { // If the rulebase utc XHDR is on string RBUTC; // then make a string to capture it O << CFGData.XHDRRulebase_Header << ": " // then emit the rulebase utc XHDR. << (*myNETmgr).RulebaseUTC(RBUTC) << SMTPENDL; } // Identifier header if(CFGData.XHDRIdentifier_OnOff) { // If the identifier XHDR is on O << CFGData.XHDRIdentifier_Header << ": " // then emit the scan identifier. << ScanData.ScanName << SMTPENDL; } // GBUdb header if(CFGData.XHDRGBUdb_OnOff) { // If the GBUdb XHDR is on then O << CFGData.XHDRGBUdb_Header << ": "; // then emit the GBUdb XHDR. if(!ScanData.FoundSourceIP()) { // If no source was identified O << "Unknown" // then we emit "Unknown". << SMTPENDL; } else { // If the source was identified O << ScanData.SourceIPRecord().Ordinal << ", " // then we emit the ordial, << (string) IP4Address(ScanData.SourceIPRecord().IP) << ", " // the IP, and then << ScanData.SourceIPEvaluation // the IP evaluation that was << SMTPENDL; // sent to the scanner. } } // Result header if(CFGData.XHDRResult_OnOff) { // If the Result XHDR is on then O << CFGData.XHDRResult_Header << ": " // emit the scan result code XHDR. << ScanData.CompositeFinalResult << SMTPENDL; } // Matches header if(CFGData.XHDRMatches_OnOff) { // If the Matches XHDR is on then O << CFGData.XHDRMatches_Header << ":" << SMTPENDL; // emit the Matches XHDR with matches. for( list::iterator iM = ScanData.MatchRecords.begin(); // Loop through the match list iM != ScanData.MatchRecords.end(); iM++ // one by one. ) { snf_match& M = (*iM); // Emit each match record as a O << "\t" // folded entry in the header. << M.symbol << "-" // symbol-ruleid-index-endex-flag << M.ruleid << "-" << M.index << "-" << M.endex << "-" << M.flag << SMTPENDL; } } // Black header const int AboveBandRange = 64; if( CFGData.XHDRBlack_OnOff && // If the Black XHDR is on and 0 < ScanData.CompositeFinalResult && // We have a nonzero result and AboveBandRange > ScanData.CompositeFinalResult && // it is not an above-band code and !CFGData.TrainingWhiteRuleHandler.isListed( // it is not found in the training ScanData.CompositeFinalResult) // white list then... ) { O << CFGData.XHDRBlack_Header // Emit the Black XHDR. << SMTPENDL; } // White header if( // If the White XHDR is on and CFGData.XHDRWhite_OnOff && // the result was listed in the CFGData.TrainingWhiteRuleHandler.isListed( // training white list then... ScanData.CompositeFinalResult) ) { O << CFGData.XHDRWhite_Header // Emit the White XHDR. << SMTPENDL; } // Clean header if( CFGData.XHDRClean_OnOff && // If the Clean XHDR is on and !ScanData.PatternWasFound && // no pattern was found and 0 == ScanData.CompositeFinalResult // the scan result is zero then... ) { O << CFGData.XHDRClean_Header // Emit the Clean XHDR << SMTPENDL; } // Symbol headers string SH = CFGData.XHDRSymbolHeaders.HeaderForSymbol( // Check for a Symbol XHDR ScanData.CompositeFinalResult // matching this result. ); if(0 < SH.length()) { // If we have an XHDR for this O << SH // result then emit the header. << SMTPENDL; } ScanData.XHDRsText = O.str(); // Save the formatted XHeaders. } void snfLOGmgr::doXMLLogs(snfCFGData& CFGData, snfScanData& ScanData) { // XML sub routine for LogThisScan() ostringstream O; // Set up the output stream. bool WeHaveSubordinates = false; // Expect no subordinates at first. // We do the match sections together because it allows us to scan through // the match results once and pick up the final result for the section. // This way, even if no atch elements are emitted we will have the // final result without having to scan the data twice. // -- Scan Log Entry (always on if modes is not none) // -- Scan Match Entry (controlled by matches attribute) ostringstream R; // Match (R)ecords output. set Duplicates; // Set up to track duplicates. list::iterator MatchRecordsCursor; // Set up a cursor to the results. for( MatchRecordsCursor = ScanData.MatchRecords.begin(); // Loop through the scan results MatchRecordsCursor != ScanData.MatchRecords.end(); MatchRecordsCursor++ ) { snf_match& M = (*MatchRecordsCursor); // Grab the current match record. if( ScanLogMatches_None != CFGData.Scan_XML_Matches && // If match records are requested ('f' != M.flag && 'c' != M.flag) // and this record is not the (f)inal ) { // then evaluate it and log (??) it. if(ScanLogMatches_Unique == CFGData.Scan_Classic_Matches) { // If only unique matches are required if(Duplicates.end() != Duplicates.find(M.ruleid)) { // check for a duplicate rule id. continue; // If the rule id was found then skip. } else { // If the rule id was not found then Duplicates.insert(M.ruleid); // remember it for next time. } } // At this point we've skipped duplicate match records, but we // still want to emit some (all?) of them so it's time to do it. // R << "\t" << endl; } else if('f' == M.flag || 'c' == M.flag) { // If this record is final, emit it! WeHaveSubordinates = ( ((ScanLogMatches_None != CFGData.Scan_XML_Matches) && ('f' == M.flag)) || (true == CFGData.Scan_XML_GBUdb) || (true == CFGData.Scan_XML_Performance) ); // O << "can element << "u=\'" << Timestamp(ScanData.StartOfJobUTC) << "\' " << "m=\'" << ScanData.ScanName << "\' " << "s=\'" << M.symbol << "\' " << "r=\'" << M.ruleid << "\'" << ((WeHaveSubordinates)? ">" : "/>") << endl; } } if(ScanLogMatches_None != CFGData.Scan_XML_Matches) O << R.str(); // Emit the match records if any. //

-- Scan Performance Monitoring (performance='yes') //

if(CFGData.Scan_XML_Performance) { // Post performance data if needed. O << "\t

" << endl; } // -- GBUdb Activity For This Scan (gbudb='yes') // if(CFGData.Scan_XML_GBUdb && ScanData.FoundSourceIP()) { // Post gbudb data if needed & ready. O << "\t" << endl; } // If this wasn't a one-liner then we need to close the element if(WeHaveSubordinates) O << "" << endl; // If was open then close it. ScanData.XMLLogText = O.str(); // Save the formatted log text. // Now that we've produced the appropriate log entries let's send them // out to the log file. if(LogOutputMode_File == CFGData.Scan_XML_Mode) { // If we are writing to file, string TFN = CFGData.paths_log_path; // build an appropriate log file TFN.append(CFGData.node_licenseid); // name. if(CFGData.Scan_XML_Rotate) { // If we're rotating per day: TFN.append("."); // Put a timestamp on the file name. if(Rotate_LocalTime) { LocalTimestamp(TFN); } // Use either the local timestamp or else { Timestamp(TFN); } // the utc timestamp as configured. TFN = TFN.substr(0, TFN.length() - 6); // Stip off the Hours, Minutes, Seconds. } TFN.append(".log.xml"); // Tack on the extension. XMLScanLogger.post(ScanData.XMLLogText, TFN); // Post the log with the file name. } } void snfLOGmgr::doClassicLogs(snfCFGData& CFGData, snfScanData& ScanData) { // Classic sub routine for LogThisScan() ostringstream O; // Set up the output stream. set Duplicates; // Set up to track duplicates. list::iterator MatchRecordsCursor; // Set up a cursor to the results. for( MatchRecordsCursor = ScanData.MatchRecords.begin(); // Loop through the scan results MatchRecordsCursor != ScanData.MatchRecords.end(); MatchRecordsCursor++ ) { snf_match& M = (*MatchRecordsCursor); // Grab the current match record. if( ScanLogMatches_None != CFGData.Scan_Classic_Matches && // If match records are requested ('f' != M.flag && 'c' != M.flag) // and this record is not the (f)inal ) { // then evaluate it and log (??) it. if(ScanLogMatches_Unique == CFGData.Scan_Classic_Matches) { // If only unique matches are required if(Duplicates.end() != Duplicates.find(M.ruleid)) { // check for a duplicate rule id. continue; // If the rule id was found then skip. } else { // If the rule id was not found then Duplicates.insert(M.ruleid); // remember it for next time. } } // At this point we've skipped duplicate match records, but we // still want to emit some (all?) of them so it's time to do it. O << CFGData.node_licenseid << "\t" << Timestamp(ScanData.StartOfJobUTC) << "\t" << ScanData.ScanName << "\t" << ScanData.SetupTime << "\t" << ScanData.ScanTime.getElapsedTime() << "\t" << (('m' == M.flag) ? "Match\t" : (('w' == M.flag) ? "White\t" : (('p' == M.flag) ? "Panic\t" : "Fault\t"))) << M.ruleid << "\t" << M.symbol << "\t" << M.index << "\t" << M.endex << "\t" << ScanData.ScanDepth << endl; } else { // If this record is final, emit it! O << CFGData.node_licenseid << "\t" << Timestamp(ScanData.StartOfJobUTC) << "\t" << ScanData.ScanName << "\t" << ScanData.SetupTime << "\t" << ScanData.ScanTime.getElapsedTime() << "\t" << (('f' == M.flag) ? "Final\t" : (('c' == M.flag) ? "Clean\t" : "Fault\t")) << M.ruleid << "\t" << M.symbol << "\t" << M.index << "\t" << M.endex << "\t" << ScanData.ScanDepth << endl; } } ScanData.ClassicLogText = O.str(); // Save the formatted log text. // Now that we've produced the appropriate log entries let's send them // out to the log file. if(LogOutputMode_File == CFGData.Scan_Classic_Mode) { // If we are writing to file, string TFN = CFGData.paths_log_path; // build an appropriate log file TFN.append(CFGData.node_licenseid); // name. if(CFGData.Scan_Classic_Rotate) { // If we're rotating per day: TFN.append("."); // Put a timestamp on the file name. if(Rotate_LocalTime) { LocalTimestamp(TFN); } // Use either the local timestamp or else { Timestamp(TFN); } // the utc timestamp as configured. TFN = TFN.substr(0, TFN.length() - 6); // Stip off the Hours, Minutes, Seconds. } TFN.append(".log"); // Tack on the extension. ClassicScanLogger.post(ScanData.ClassicLogText, TFN); // Post the log with the file name. } } //// LogThisScan() is broken into two sections. The first section happens with //// the snfLOGmgr mutex locked and must happen as quickly as possible so that //// the chance for contention over those resources is minimized. This amounts //// to some raw CPU work adjusting counters and so forth. //// //// The second section handles any additional work such as formatting log //// entries. Essentially, anything that doesn't NEED to happen while the mutex //// is locked should happen in the second section. //// //// The two subroutines for LogThisScan are: //// captureLTSMetrics() -- Mutex locked, first section //// performLTSLogging() -- Mutex NOT locked, second section void snfLOGmgr::captureLTSMetrics(snfCFGData& CFGData, snfScanData& ScanData) { // LogThisScan section 1 ScopeMutex FreezeRightThereWhileITakeThisPicture(MyMutex); // Lock the object for this update. if(Status.LatestRuleID < ScanData.PatternID) { // If we have a new latest rule id Status.LatestRuleID = ScanData.PatternID; // then capture it. } // keep histograms--- // Second, Minute, and Hour histograms are reset() by the appropriate // reporting functions. That is, when a Second report is made, the Second // histograms are reset; likewise Minutes and Hours. As a result we simply // hit them all the same way when we log a scan. ResultsSecond.hit(ScanData.CompositeFinalResult); // Histogram the result codes. ResultsMinute.hit(ScanData.CompositeFinalResult); ResultsHour.hit(ScanData.CompositeFinalResult); if(ScanData.PatternWasFound) { // Histogram pattern IDs. RulesSecond.hit(ScanData.PatternID); RulesMinute.hit(ScanData.PatternID); RulesHour.hit(ScanData.PatternID); } if(0 < ScanData.RulePanics.size()) { // Histogram any rule panic hits. set::iterator iP; for( // Dump the set of rule panic iP = ScanData.RulePanics.begin(); // IDs from beginning to end iP != ScanData.RulePanics.end(); // into our histogram set. iP++) { PanicsSecond.hit((*iP)); PanicsMinute.hit((*iP)); PanicsHour.hit((*iP)); } } // count up these things--- ++(*CurrentCounters).Events.Scans; // Number of messages scanned. const int HamResult = 0; // A result of 0 is "clean" or "white" if( // If we have identified Ham HamResult == ScanData.CompositeFinalResult || // either by the conventional result or CFGData.TrainingWhiteRuleHandler.isListed(ScanData.CompositeFinalResult) // some known white-rule symbol ) { ++(*CurrentCounters).Events.Ham; // then we will bump the Ham counter. } else { // For any other result we will bump ++(*CurrentCounters).Events.Spam; // the spam counter. } if(ScanData.GBUdbNormalTriggered) { // Count of GBUdb indetermineta IPs. ++(*CurrentCounters).Events.GBUdbNormalTriggered; } if(ScanData.GBUdbWhiteTriggered) { // Count of GBUdb found source IP white. ++(*CurrentCounters).Events.GBUdbWhiteTriggered; } if(ScanData.GBUdbWhiteSymbolForced) { // Count of white was on and symbol was set. ++(*CurrentCounters).Events.GBUdbWhiteSymbolForced; } if(ScanData.GBUdbPatternSourceConflict) { // Count of pattern was found with white IP. ++(*CurrentCounters).Events.GBUdbPatternSourceConflict; } if(ScanData.GBUdbAutoPanicTriggered) { // Count of autopanic was triggered. ++(*CurrentCounters).Events.GBUdbAutoPanicTriggered; } if(ScanData.GBUdbAutoPanicExecuted) { // Count of an autopanic was added. ++(*CurrentCounters).Events.GBUdbAutoPanicExecuted; } if(ScanData.GBUdbBlackTriggered) { // Count of GBUdb found source IP black. ++(*CurrentCounters).Events.GBUdbBlackTriggered; } if(ScanData.GBUdbBlackSymbolForced) { // Count of black was on and symbol was set. ++(*CurrentCounters).Events.GBUdbBlackSymbolForced; } if(ScanData.GBUdbTruncateTriggered) { // Count of Truncate was possible. ++(*CurrentCounters).Events.GBUdbTruncateTriggered; } if(ScanData.GBUdbPeekTriggered) { // Count of we could peek. ++(*CurrentCounters).Events.GBUdbPeekTriggered; } if(ScanData.GBUdbSampleTriggered) { // Count of we could sample. ++(*CurrentCounters).Events.GBUdbSampleTriggered; } if(ScanData.GBUdbTruncateExecuted) { // Count of if we actually did truncate. ++(*CurrentCounters).Events.GBUdbTruncateExecuted; } if(ScanData.GBUdbPeekExecuted) { // Count of we peeked instead of truncating. ++(*CurrentCounters).Events.GBUdbPeekExecuted; } if(ScanData.GBUdbSampleExecuted) { // Count of we sampled. ++(*CurrentCounters).Events.GBUdbSampleExecuted; } if(ScanData.GBUdbCautionTriggered) { // Count of GBUdb found source IP suspicous. ++(*CurrentCounters).Events.GBUdbCautionTriggered; } if(ScanData.GBUdbCautionSymbolForced) { // Count of caution was on and symbol was set. ++(*CurrentCounters).Events.GBUdbCautionSymbolForced; } if(ScanData.PatternWasFound) { // Count of scanner matches. ++(*CurrentCounters).Events.PatternWasFound; } if(0 < ScanData.RulePanics.size()) { // Count of rule panics. ++(*CurrentCounters).Events.RulePanicFound; } } void snfLOGmgr::performLTSLogging(snfCFGData& CFGData, snfScanData& ScanData) { // LogThisScan section 2 // Build X- Headers, XML Log, and Classic Log as needed... if(LogOutputMode_None != CFGData.XHDROutput_Mode) { // If XHeaders are turned on then doXHDRs(CFGData, ScanData); // call the XHeaders subroutine. } if(LogOutputMode_None != CFGData.Scan_XML_Mode) { // If XML scan logs are turned on then doXMLLogs(CFGData, ScanData); // call the XML scan log subroutine. } if(LogOutputMode_None != CFGData.Scan_Classic_Mode) { // If Classic scan logs are turned on doClassicLogs(CFGData, ScanData); // then call the Classic log subroutine. } } void snfLOGmgr::logThisScan(snfCFGData& CFGData, snfScanData& ScanData) { // How to log a scan event... captureLTSMetrics(CFGData, ScanData); // Lock the mutex and do the math. performLTSLogging(CFGData, ScanData); // Unlock the mutex and write it down. if(0 < ScanData.XHDRsText.length()) { // If we have XHeader data then switch(CFGData.XHDROutput_Mode) { // set the appropriate output mode. case LogOutputMode_Inject: ScanData.XHeaderInjectOn = true; break; // We will either inject the headers case LogOutputMode_File: ScanData.XHeaderFileOn = true; break; // or we will create a .xhdr file. } // The actual inject/file operation } // happens in ScanMessageFile(). ScanData.ReadyToClear = true; // This can be cleared now once } // the ScanData has been consumed. // logThisError(CFGData, ScanData) - for scanning errors (message context) void snfLOGmgr::logThisError(snfScanData& ScanData, const string ContextName, // Inject an error log entry for this const int Code, const string Text // scan using this number & message. ) { // Check for each type of log and create an appropriate entry for // each log type that is activated in the configuration. //// Handle XML Log Scan Error Reports if(LogOutputMode_None != XML_Log_Mode) { // If XML logs are on emit the error. // Produce Error Log Entry and store in XMLLogText stringstream O; // Stringstream for formatting. O << "can error element << "u=\'" << Timestamp(ScanData.StartOfJobUTC) << "\' " << "context=\'" << ContextName << "\' " << "m=\'" << ScanData.ScanName << "\' " << "code=\'" << Code << "\' " << "text=\'" << Text << "\'" << "/>" << endl; ScanData.XMLLogText = O.str(); // Save the formatted log text. // Now that we've produced the appropriate log entries let's send them // out to the log file. if(LogOutputMode_File == XML_Log_Mode) { // If we are writing to file, string TFN = LogsPath; // build an appropriate log file TFN.append(NodeId); // name. if(XMLLogRotate) { // If we're rotating per day: TFN.append("."); // Put a timestamp on the file name. if(Rotate_LocalTime) { LocalTimestamp(TFN); } // Use either the local timestamp or else { Timestamp(TFN); } // the utc timestamp as configured. TFN = TFN.substr(0, TFN.length() - 6); // Stip off the Hours, Minutes, Seconds. } TFN.append(".log.xml"); // Tack on the extension. XMLScanLogger.post(ScanData.XMLLogText, TFN); // Post the log with the file name. } } //// Handle Clasic Log Scan Error Reports if(LogOutputMode_None != Classic_Log_Mode) { // If Classic logs are on emit the error. // Produce an appropriate Error log entry in ClassicLogText stringstream O; // Stringstream for formatting. O << NodeId << "\t" // Format the scan error entry. << Timestamp(ScanData.StartOfJobUTC) << "\t" << ScanData.ScanName << "\t" << ScanData.SetupTime << "\t" << ScanData.ScanTime.getElapsedTime() << "\t" << Text << "\t" << "0\t" << Code << "\t" << "0\t" << ScanData.ScanSize << "\t" << ScanData.ScanDepth << endl; ScanData.ClassicLogText = O.str(); // Save the formatted log text. // Now that we've produced the appropriate log entries let's send them // out to the log file. if(LogOutputMode_File == Classic_Log_Mode) { // If we are writing to file, string TFN = LogsPath; // build an appropriate log file TFN.append(NodeId); // name. if(ClassicLogRotate) { // If we're rotating per day: TFN.append("."); // Put a timestamp on the file name. if(Rotate_LocalTime) { LocalTimestamp(TFN); } // Use either the local timestamp or else { Timestamp(TFN); } // the utc timestamp as configured. TFN = TFN.substr(0, TFN.length() - 6); // Stip off the Hours, Minutes, Seconds. } TFN.append(".log"); // Tack on the extension. ClassicScanLogger.post(ScanData.ClassicLogText, TFN); // Post the log with the file name. } } } // logThisIPTest w/ Action void snfLOGmgr::logThisIPTest(IPTestRecord& I, string Action) { // Log an IPTest and action. if(!Configured) return; // Do nothing if not configured. stringstream O; // Stringstream to format the entry. string tmp; // String for use getting timestamp. O << "" << endl; XMLScanLogger.post(O.str()); // Post the log, use existing path. } // logThisError(Context, Code, Text) - for non-message errors. void snfLOGmgr::logThisError(string ContextName, int Code, string Text) { // Log an error message. if(!Configured) return; // Do nothing if not configured. ScopeMutex LockCFG(MyMutex); // Don't change CFG. I'm using it! if(LogOutputMode_File == XML_Log_Mode) { // If XML logs are turned on: stringstream O; // Stringstream to format the entry. string tmp; // String for use getting timestamp. O << "rror element. << "u=\'" << Timestamp(tmp) << "\' " << "context=\'" << ContextName << "\' " << "code=\'" << Code << "\' " << "text=\'" << Text << "\'/>" << endl; // Now that we've produced the appropriate log entries let's send them // out to the log file. string TFN = LogsPath; // build an appropriate log file TFN.append(NodeId); // name. if(XMLLogRotate) { // If we're rotating per day: TFN.append("."); // Put a timestamp on the file name. if(Rotate_LocalTime) { LocalTimestamp(TFN); } // Use either the local timestamp or else { Timestamp(TFN); } // the utc timestamp as configured. TFN = TFN.substr(0, TFN.length() - 6); // Stip off the Hours, Minutes, Seconds. } TFN.append(".log.xml"); // Tack on the extension. XMLScanLogger.post(O.str(), TFN); // Post the log with the file name. } if(LogOutputMode_File == Classic_Log_Mode) { // If Classic logs are turned on: stringstream O; // Stringstream to format the entry. string tmp; // String for use getting timestamp. O << NodeId << "\t" // Format the error entry. << Timestamp(tmp) << "\t" << ContextName << "\t" << "0\t" << "0\t" << Text << "\t" << "0\t" << Code << "\t" << "0\t" << "0\t" << "0\t" << endl; // Now that we've produced the appropriate log entries let's send them // out to the log file. string TFN = LogsPath; // build an appropriate log file TFN.append(NodeId); // name. if(ClassicLogRotate) { // If we're rotating per day: TFN.append("."); // Put a timestamp on the file name. if(Rotate_LocalTime) { LocalTimestamp(TFN); } // Use either the local timestamp or else { Timestamp(TFN); } // the utc timestamp as configured. TFN = TFN.substr(0, TFN.length() - 6); // Stip off the Hours, Minutes, Seconds. } TFN.append(".log"); // Tack on the extension. ClassicScanLogger.post(O.str(), TFN); // Post the log with the file name. } } // logThisInfo(Context, Code, Text) - for generic non-errors. void snfLOGmgr::logThisInfo(string ContextName, int Code, string Text) { // Log an informational message. if(!Configured) return; // Do nothing if not configured. ScopeMutex LockCFG(MyMutex); // Don't change CFG. I'm using it! if(LogOutputMode_File == XML_Log_Mode) { // If XML logs are turned on: stringstream O; // Stringstream to format the entry. string tmp; // String for use getting timestamp. O << "nfo element. << "u=\'" << Timestamp(tmp) << "\' " << "context=\'" << ContextName << "\' " << "code=\'" << Code << "\' " << "text=\'" << Text << "\'/>" << endl; // Now that we've produced the appropriate log entries let's send them // out to the log file. string TFN = LogsPath; // build an appropriate log file TFN.append(NodeId); // name. if(XMLLogRotate) { // If we're rotating per day: TFN.append("."); // Put a timestamp on the file name. if(Rotate_LocalTime) { LocalTimestamp(TFN); } // Use either the local timestamp or else { Timestamp(TFN); } // the utc timestamp as configured. TFN = TFN.substr(0, TFN.length() - 6); // Stip off the Hours, Minutes, Seconds. } TFN.append(".log.xml"); // Tack on the extension. XMLScanLogger.post(O.str(), TFN); // Post the log with the file name. } if(LogOutputMode_File == Classic_Log_Mode) { // If Classic logs are turned on: stringstream O; // Stringstream to format the entry. string tmp; // String for use getting timestamp. O << NodeId << "\t" // Format the informational entry. << Timestamp(tmp) << "\t" << ContextName << "\t" << "0\t" << "0\t" << Text << "\t" << "0\t" << Code << "\t" << "0\t" << "0\t" << "0\t" << endl; // Now that we've produced the appropriate log entries let's send them // out to the log file. string TFN = LogsPath; // build an appropriate log file TFN.append(NodeId); // name. if(ClassicLogRotate) { // If we're rotating per day: TFN.append("."); // Put a timestamp on the file name. if(Rotate_LocalTime) { LocalTimestamp(TFN); } // Use either the local timestamp or else { Timestamp(TFN); } // the utc timestamp as configured. TFN = TFN.substr(0, TFN.length() - 6); // Stip off the Hours, Minutes, Seconds. } TFN.append(".log"); // Tack on the extension. ClassicScanLogger.post(O.str(), TFN); // Post the log with the file name. } } string snfLOGmgr::PlatformVersion(string NewPlatformVersion) { // Set platform version info. ScopeMutex FreezeForNewData(MyMutex); // Get the ball and myPlatformVersion = NewPlatformVersion; // set the data. return myPlatformVersion; // return the new data. } string snfLOGmgr::PlatformVersion() { // Get platform version info. ScopeMutex DontChangeOnMe(MyMutex); // Get the ball and return myPlatformVersion; // get the data. } string snfLOGmgr::EngineVersion() { // Get engine version info. return string(SNF_ENGINE_VERSION); // Return the engine version string. } //// The caller to getSpamshot promises to reset() the counters when it is done //// with the data and before getSnapshot() gets called again. snfCounterPack* snfLOGmgr::getSnapshot() { // Get a copy of the current counters. snfCounterPack* Snapshot = CurrentCounters; // Grab the active counters. CurrentCounters = ReportingCounters; // Swap the reporting counters in. CurrentCounters->ActiveTime.start(Snapshot->ActiveTime.stop()); // (De)Activate the activity timers. ReportingCounters = Snapshot; // Put the old ActiveCounters into return Snapshot; // reporting mode and return a ptr. } bool snfLOGmgr::OkToPeek(int PeekOneInX) { // Test to see if it's ok to peek. ScopeMutex JustMe(PeekMutex); // Protect the peek enable counter. ++PeekEnableCounter; // Bump the counter by one. if(PeekEnableCounter >= PeekOneInX) { // If we've made the threshold then PeekEnableCounter = 0; // reset the counter and return true; // return true. } // If not then return false; // return false. } bool snfLOGmgr::OkToSample(int SampleOneInX) { // Test to see if it's ok to sample. ScopeMutex JustMe(SampleMutex); // Protect the sample enable counter. ++SampleEnableCounter; // Bump the counter by one. if(SampleEnableCounter >= SampleOneInX) { // If we've made the threshold then SampleEnableCounter = 0; // reset the counter and return true; // return true. } // If not then return return false; // false. } time_t snfLOGmgr::Timestamp() { // Get an ordinary timestamp. time_t rawtime; rawtime = time(NULL); return rawtime; } string snfLOGmgr::Timestamp(time_t t) { // Convert time_t to a timestamp s. stringstream TimestampBfr; const string EmptyTimestamp = "00000000000000"; string theTimeStamp = EmptyTimestamp; tm* gmt; // Get a ptr to a tm structure. gmt = gmtime(&t); // Fill it with UTC. bool isValidGMT = (0 != gmt); if(isValidGMT) { TimestampBfr << setw(4) << (gmt->tm_year+1900) << setw(2) << setfill('0') << (gmt->tm_mon+1) << setw(2) << setfill('0') << (gmt->tm_mday) << setw(2) << setfill('0') << (gmt->tm_hour) << setw(2) << setfill('0') << (gmt->tm_min) << setw(2) << setfill('0') << (gmt->tm_sec) ; theTimeStamp = TimestampBfr.str(); } return theTimeStamp; // Return a string. } string& snfLOGmgr::Timestamp(string& s) { // Returns a current timestamp in s. s.append(Timestamp(Timestamp())); // Append the timestamp to s and return s; // return it. } string snfLOGmgr::LocalTimestamp(time_t t) { // Convert time_t to a local timestamp s. char TimestampBfr[20]; // Create a small buffer. tm* localt; // Get a ptr to a tm structure. localt = localtime(&t); // Fill it with local time. sprintf(TimestampBfr,"%04d%02d%02d%02d%02d%02d", // Format yyyymmddhhmmss localt->tm_year+1900, localt->tm_mon+1, localt->tm_mday, localt->tm_hour, localt->tm_min, localt->tm_sec ); return string(TimestampBfr); // Return a string. } string& snfLOGmgr::LocalTimestamp(string& s) { // Returns a local timestamp in s. s.append(LocalTimestamp(Timestamp())); // Append the timestamp to s and return s; // return it. } unsigned int snfLOGmgr::SerialNumber() { // Returns the next serial number. ScopeMutex AtomicOperation(SerialNumberMutex); // Lock the serial number mutex. ++Status.SerialNumberCounter; // Increment the serial number. unsigned int result = Status.SerialNumberCounter; // Capture the new value. return result; // Return the unique result. } string& snfLOGmgr::SerialNumber(string& s) { // Appends the next serial number. char SerialNumberBuffer[9]; // 8 hex digits and a null terminator. sprintf( // Format the serial number and SerialNumberBuffer, // place it into the buffer. "%08X", SerialNumber() ); s.append(SerialNumberBuffer); // Append the buffer to s. return s; // Return s. } // Persistent State Functions // The Persistent State object is slightly smart. It won't try to restore // itself from disk if it has already been restored. It won't write itself // to disk unless it was first loaded or there was no original file to load. // This leaves open the possibility that a disk problem when opening the // engine could cause a persistent state problem - but the alternative is to // have the persistent state unprotected. If there is a problem, then clearing // the problem and re-opening the engine will load the persistent state. If // that's not the best solution then it's always possible to destroy the // existing persistent state and start over -- at least then it will be a // conscious decision and not a "side effect" void snfLOGPersistentState::store(string& FileNameToStore) { // Write the whole thing to a file. if(Ready) { // If it is safe to overwrite then try { // Try... to ofstream P(FileNameToStore.c_str(), ios::trunc | ios::binary); // Open and overwrite the file and P.write((char*)this, sizeof(snfLOGPersistentState)); // store our bytes in binary format. P.close(); } catch (...) {} // Ignore any errors for now. } } void snfLOGPersistentState::restore(string& FileNameToRestore) { // Read the whole thing from a file. if(!Ready) { // If we have not already loaded... if(0 > access(FileNameToRestore.c_str(), R_OK)) { // If the file cannot be read we Ready = true; // will assume it doesn't exist and } // set our Ready flag to allow writing. else { // If the file does exist we load it. try { // Try this... ifstream P(FileNameToRestore.c_str(), ios::binary); // Create a binary input stream and P.read((char*)this, sizeof(snfLOGPersistentState)); // read the bytes into this object. P.close(); // Then, close the file. Ready = true; // Set the Ready flag to allow writes. } catch(...) {} // Ignore any errors for now. } } } // 20090730_M - Moved persistent state aux saves to RecordSyncEvent. It makes // sense for the persistent state to match the latext external record of state // info. If SNFServer dies uncerimoneusly that is what we will remember. int snfLOGmgr::SecsSinceStartup() { return (int) difftime(Timestamp(), StartupTime); } void snfLOGmgr::RecordSyncEvent() { // Sets timestamp of latest Sync. Status.LastSyncTime = Timestamp(); // Set the Sync time. if(Configured) Status.store(PersistentFileName); // Store our persistent data. } int snfLOGmgr::SecsSinceLastSync() { // Gets seconds since latest Sync. return (int) difftime(Timestamp(), Status.LastSyncTime); } void snfLOGmgr::RecordSaveEvent() { // Sets timestamp of latest Save. Status.LastSaveTime = Timestamp(); } int snfLOGmgr::SecsSinceLastSave() { // Gets seconds since latest Save. return (int) difftime(Timestamp(), Status.LastSaveTime); } void snfLOGmgr::RecordCondenseEvent() { // Sets timestamp of latest Condense. Status.LastCondenseTime = Timestamp(); } int snfLOGmgr::SecsSinceLastCondense() { // Gets seconds since latest Condense. return (int) difftime(Timestamp(), Status.LastCondenseTime); } // Data in the multi-range sliding window is tracked in circular buffers. // The snf_SMHDMY_Counter::do_input() function encapsuates the input operation. bool snf_SMHDMY_Counter::do_input( // Subroutine for new data input. int X, // Given new data X, int& SUM, // the SUM being tracked, int* DATA, // the array of DATA, int& ORDINAL, // the current ORDINAL, int SIZE) { // and the SIZE of the array... SUM -= DATA[ORDINAL]; // Subtract the old data from the SUM += (DATA[ORDINAL] = X); // SUM and replace it with X. ++ORDINAL; // Move to the next slot and if(SIZE <= ORDINAL) ORDINAL = 0; // rotate back around if needed. return (0 == ORDINAL); // Return true if time to carry. } void snf_SMHDMY_Counter::input(int X) { if(do_input(X, SEC6SUM, SEC6DATA, SEC6ORDINAL, 6)) // 6 second sum if(do_input(SEC6SUM, SEC10SUM, SEC10DATA, SEC10ORDINAL, 10)) // 60 second sum if(do_input(SEC10SUM, MIN6SUM, MIN6DATA, MIN6ORDINAL, 6)) // 6 minute sum if(do_input(MIN6SUM, MIN10SUM, MIN10DATA, MIN10ORDINAL, 10)) // 60 minute sum if(do_input(MIN10SUM, HOUR4SUM, HOUR4DATA, HOUR4ORDINAL, 4)) // 4 hour sum if(do_input(HOUR4SUM, HOUR6SUM, HOUR6DATA, HOUR6ORDINAL, 6)) { // 24 hour sum do_input(HOUR6SUM, WEEK7SUM, WEEK7DATA, WEEK7ORDINAL, 7); // 7 day sum do_input(HOUR6SUM, YEAR365SUM, YEAR365DATA, YEAR365ORDINAL, 365); // 365 day sum if(do_input(HOUR6SUM, MONTH5SUM, MONTH5DATA, MONTH5ORDINAL, 5)) // 5 day sum if(do_input(MONTH5SUM, MONTH6SUM, MONTH6DATA, MONTH6ORDINAL, 6)) // 30 day sum if(do_input(MONTH6SUM, YEAR3SUM, YEAR3DATA, YEAR3ORDINAL, 3)) // 3 month sum do_input(YEAR3SUM, YEAR4SUM, YEAR4DATA, YEAR4ORDINAL, 4); // 12 month sum } } double snf_SMHDMY_AveragePerMinute( // Get mornalized minute avg of X snf_SMHDMY_Counter& X, // Input the Units in the period. snf_SMHDMY_Counter& M) { // Input the Milliseconds in the period. int Units = X.SEC6SUM + X.SEC10SUM; // Get the count. int Milliseconds = M.SEC6SUM + M.SEC10SUM; // Get the time. return snf_rationalize(Units, Milliseconds, MillisecondsInAMinute); // Normalize to a minute. } double snfLOGmgr::MessagesPerMinute() { // Avg Msgs/Minute. return snf_SMHDMY_AveragePerMinute(MessageCounter, TimeCounter); } double snfLOGmgr::HamPerMinute() { // Avg Ham/Minute. return snf_SMHDMY_AveragePerMinute(HamCounter, TimeCounter); } double snfLOGmgr::SpamPerMinute() { // Avg Spam/Minute. return snf_SMHDMY_AveragePerMinute(SpamCounter, TimeCounter); } double snfLOGmgr::WhitePerMinute() { // Avg White/Minute. return snf_SMHDMY_AveragePerMinute(WhiteCounter, TimeCounter); } double snfLOGmgr::CautionPerMinute() { // Avg Caution/Minute. return snf_SMHDMY_AveragePerMinute(CautionCounter, TimeCounter); } double snfLOGmgr::BlackPerMinute() { // Avg Black/Minute. return snf_SMHDMY_AveragePerMinute(BlackCounter, TimeCounter); } double snfLOGmgr::TruncatePerMinute() { // Avg Truncate/Minute. return snf_SMHDMY_AveragePerMinute(TruncateCounter, TimeCounter); } double snfLOGmgr::SamplePerMinute() { // Avg Sample/Minute. return snf_SMHDMY_AveragePerMinute(SampleCounter, TimeCounter); } const string EmptyStatusSecondReport = ""; // Empty Status.Second looks like this. string snfLOGmgr::getStatusSecondReport() { // Get latest status.second report. ScopeMutex FlashBulb(StatusReportMutex); // Take a safe snapshot of the report. if(0 < SecondReportText.length()) return SecondReportText; // If it's posted then send it. If not return EmptyStatusSecondReport; // then send the empty version. } const string EmptyStatusMinuteReport = ""; // Empty Status.Minute looks like this. string snfLOGmgr::getStatusMinuteReport() { // Get latest status.minute report. ScopeMutex FlashBulb(StatusReportMutex); // Take a safe snapshot of the report. if(0 < MinuteReportText.length()) return MinuteReportText; // If it's posted then send it. If not return EmptyStatusMinuteReport; // then send the empty version. } const string EmptyStatusHourReport = ""; // Empty Status.Hour looks like this. string snfLOGmgr::getStatusHourReport() { // Get latest status.hour report. ScopeMutex FlashBulb(StatusReportMutex); // Take a safe snapshot of the report. if(0 < HourReportText.length()) return HourReportText; // If it's posted then send it. If not return EmptyStatusHourReport; // then send the empty version. }