First incarnation of the logging code

logv2.c

@@ -0,0 +1,486 @@
+/*
+  This is a reimplementation of SICS logging. The aim is to 
+  merge all the different logs within SICS to the new logging 
+  system
+
+  COPYRIGHT: see file COPYRIGHT
+
+  Mark Koennecke, February 2016
+ */
+#include <string.h>
+#include <time.h>
+#include <sys/time.h>
+#include <logv2.h>
+#include <sics.h>
+#include <splitter.h>
+#include <lld_str.h>
+#include <lld.h>
+#include <dynstring.h>
+/*==============================================================================
+  some static fields which control log file rotation
+===============================================================================*/
+static FILE *logFile = NULL;
+static unsigned int MAXFILELINES = 100000;
+static unsigned int lineCount = 0;
+static char logTemplate[1024];
+static char logFilename[1024];
+
+/*================ The default log level =======================================*/
+static unsigned int globalLogLevel = 7;
+/*========= The list of sub systems for which full logging is enabled ==========*/
+static int subList;
+/*================== Callback management =======================================*/
+typedef struct {
+  LogCallback func;
+  void *userData;
+} LogCBData;
+
+static int callbackList;
+/*----------------------------------------------------------------------------*/
+static void formatTimeStamp(char *buffer, unsigned int bufferLength, unsigned int small)
+{
+  struct timeval tv;
+  struct tm *time;
+  int year, month, day, hour, min, sec, usec;
+  char delim = '-';
+
+  gettimeofday(&tv, NULL);
+  time = localtime(&tv.tv_sec);
+  time = localtime(&tv.tv_sec);
+  year = 1900 + time->tm_year;
+  month = time->tm_mon + 1;
+  day = time->tm_mday;
+  hour = time->tm_hour;
+  min = time->tm_min;
+  sec = time->tm_sec;
+  usec = (int) tv.tv_usec;
+  if(small == 1){
+    snprintf(buffer,bufferLength, "%04d-%02d-%02dT%02d%c%02d%c%02d",
+	     year, month, day, hour, delim, min, delim, sec);
+  } else {
+    snprintf(buffer,bufferLength, "%04d-%02d-%02dT%02d%c%02d%c%02d.%06d",
+	     year, month, day, hour, delim, min, delim, sec, usec);
+  }
+}
+/*----------------------------------------------------------------------------*/
+static char *makeLogFileName(void)
+{
+  char timeStamp[256];
+  char *filename = NULL;
+  unsigned int length;
+
+  formatTimeStamp(timeStamp,sizeof(timeStamp),1);
+  length = strlen(logTemplate) + strlen(timeStamp) + 30;
+  filename = malloc(length*sizeof(char));
+  if(filename != NULL){
+    sprintf(filename,"%s-%s.log",logTemplate,timeStamp);
+  }
+
+  return filename;
+}
+/*----------------------------------------------------------------------------*/
+static void LogClose(void *data)
+{
+    if(logFile != NULL){
+      fclose(logFile);
+    }   
+    logFile = NULL;
+    lineCount = 0;
+    strcpy(logFilename,"undefined");
+}
+/*----------------------------------------------------------------------------*/
+static void checkLogFile(void)
+{
+  char *filename = NULL;
+
+  /*
+    close when full
+  */
+  if(logFile != NULL && lineCount >= MAXFILELINES){
+    LogClose(NULL);
+  }
+
+  /*
+    start a new log file
+  */
+  if(logFile == NULL){
+    filename = makeLogFileName();
+    if(filename != NULL){
+      logFile = fopen(filename,"w");
+      strncpy(logFilename,filename,sizeof(logFilename));
+      free(filename);
+    }
+  }
+}
+/*----------------------------------------------------------------------------*/
+static void writeLog(char *logMessage)
+{
+  int nChar;
+
+  if(logMessage == NULL){
+    return;
+  }
+
+
+  if(logFile != NULL){
+    nChar = fprintf(logFile,"%s\n",logMessage);
+    lineCount++;
+  }
+
+}
+/*----------------------------------------------------------------------------*/
+static unsigned int logFilter(unsigned int severity, const char *subsystem)
+{
+  int status;
+  char buffer[1024];
+
+  /*
+    If it is in the list of enabled subsystems, everything is logged
+  */
+  status = LLDnodePtr2First(subList);
+  while (status == 1) {
+    LLDstringData(subList, buffer);
+    if(strcmp(buffer,subsystem) == 0) {
+      return 0;
+    }
+    status = LLDnodePtr2Next(subList);
+  }
+
+  /*
+    test against the global log level
+  */
+  if(severity >= globalLogLevel){
+    return 1;
+  }
+  return 0;
+}
+/*=============================================================================*/
+static void formatSeverity(unsigned int severity, char *buffer, unsigned int bufferLength)
+{
+  static const char *severityText[] = {"FATAL",
+			       "ERROR",
+                               "WARNING",
+                               "INFO",
+                               "VERBOSE",
+                               "DEBUG",
+                               "INVALID"
+                                };
+
+  if(severity > DEBUG){
+    severity = INVALID;
+  }
+  strncpy(buffer,severityText[severity-1],bufferLength);
+} 
+/*----------------------------------------------------------------------------
+I wish to avoid excessive dynamic memory allocation in logging. Thus I pass 
+in generous preallocated buffers and allocate only when the passed in buffer 
+is not big enough. This trick is used througout this code. 
+  ------------------------------------------------------------------------------*/
+static char *formatLogLine(char *timeStamp,char *severityTXT,
+			  const char* subsystem,
+			  char *logData, char *logLine, 
+			  unsigned int logLineLength)
+{
+  unsigned int totalLength;
+  char *lineTxt = NULL;
+
+  totalLength = strlen(timeStamp) + strlen(severityTXT) + strlen(subsystem) 
+    + strlen(logData) + 10;
+  
+  if(totalLength > logLineLength){
+    lineTxt = malloc((totalLength+1)*sizeof(char));
+  } else {
+    lineTxt = logLine;
+  }
+  if(lineTxt != NULL){
+    sprintf(lineTxt,"%s:%s:%s:%s", 
+	    timeStamp,
+	    subsystem,
+	    severityTXT,
+	    logData);
+  }
+  return lineTxt;
+}
+/*----------------------------------------------------------------------------*/
+void RegisterLogCallback(LogCallback func, void *userData)
+{
+  LogCBData lcb;
+
+  lcb.func = func;
+  lcb.userData = userData;
+  LLDnodeAppendFrom(callbackList,&lcb);
+}
+/*---------------------------------------------------------------------------*/
+void RemoveLogCallback(LogCallback func)
+{
+  int status;
+  LogCBData lcb;
+
+  status = LLDnodePtr2First(callbackList);
+  while(status == 1){
+    LLDnodeDataTo(callbackList,&lcb);
+    if(lcb.func == func){
+      LLDnodeDelete(callbackList);
+      return;
+    }
+    status = LLDnodePtr2Next(callbackList);
+  }
+}
+/*----------------------------------------------------------------------------*/
+static void notifyListeners(unsigned int severity, const char *subsystem, 
+			    char *timeStamp, char *logData)
+{
+  int status;
+  LogCBData lcb;
+
+  status = LLDnodePtr2First(callbackList);
+  while(status == 1){
+    LLDnodeDataTo(callbackList,&lcb);
+    lcb.func(severity, timeStamp, subsystem,logData,lcb.userData);
+    status = LLDnodePtr2Next(callbackList);
+  }
+
+}
+/*----------------------------------------------------------------------------*/
+void Log(unsigned int severity, const char *subsystem,const char *format,...)
+{
+  char severityTXT[60];
+  char timeStamp[132];
+  char logData[2024], logLine[3072];
+  char *dynMessage = NULL, *logMessage, *fullMessage = NULL;
+  va_list ap;
+  int dataLength;
+
+
+  formatSeverity(severity,severityTXT,sizeof(severityTXT));
+  formatTimeStamp(timeStamp,sizeof(timeStamp),0);
+
+  checkLogFile();
+
+  /*
+    If we have enough space put the logData into our generous buffer. Else 
+    allocate a dynamic buffer. I cannot do this in a subroutine as I need to 
+    restart the vararg stuff. 
+  */
+  va_start(ap,format);
+  dataLength = vsnprintf(logData,sizeof(logData),format,ap);
+  logMessage = logData;
+  va_end(ap);
+  if(dataLength > sizeof(logData)){
+    dynMessage = malloc((dataLength+1)*sizeof(char));
+    if(dynMessage != NULL){
+      va_start(ap,format);
+      vsnprintf(dynMessage,(dataLength+1)*sizeof(char),format,ap);
+      va_end(ap);
+      logMessage = dynMessage;
+    }
+  }
+
+  notifyListeners(severity,subsystem,timeStamp, logMessage);
+
+
+  if(logFilter(severity,subsystem) == 1){
+      if(dynMessage != NULL){
+	free(dynMessage);
+      }
+      return;
+  }
+
+  fullMessage = formatLogLine(timeStamp,severityTXT,subsystem,
+			      logMessage, logLine, sizeof(logLine));
+ 
+  writeLog(fullMessage);
+
+ 
+  /*
+    clean up
+  */
+  if(dynMessage != NULL){
+    free(dynMessage);
+  }
+  if(fullMessage != logLine){
+    free(fullMessage);
+  }
+  
+}
+/*--------------------------------------------------------------------------------*/
+static unsigned int sevFromText(const char *txt)
+{
+  static const char *severityText[] = {"fatal",
+			       "error",
+                               "warn",
+                               "info",
+                               "verbose",
+                               "debug",
+                               NULL
+                                };
+  int sev = 0;
+  while(severityText[sev] != NULL){
+    if(strcmp(txt,severityText[sev]) == 0){
+      break;
+    }
+    sev++;
+  }
+  sev++; /* starting at 1 rather then 0 */
+  return sev;
+}
+/*------------------------------------------------------------------------------*/
+static void DisableSub(char *sub)
+{
+  int status;
+  char buffer[1024];
+  
+  status = LLDnodePtr2First(subList);
+  while (status == 1) {
+    LLDstringData(subList, buffer);
+    if(strcmp(buffer,sub) == 0) {
+      LLDstringDelete(subList);
+    }
+    status = LLDnodePtr2Next(subList);
+  }
+}
+/*------------------------------------------------------------------------------*/
+static pDynString ListEnabled(void)
+{
+  int status;
+  char buffer[1024];
+  pDynString result = CreateDynString(64,64);
+
+  if(result == NULL){
+    return NULL;
+  }
+  
+  status = LLDnodePtr2First(subList);
+  while (status == 1) {
+    LLDstringData(subList, buffer);
+    DynStringConcat(result,buffer);
+    DynStringConcatChar(result,':');
+    status = LLDnodePtr2Next(subList);
+  }
+  return result;
+}
+/*============================================================================
+  The Interpreter Interface
+  ==============================================================================*/
+static int LogAction(SConnection * pCon, SicsInterp * pSics,
+                            void *pData, int argc, char *argv[])
+{
+  char message[1024];
+  unsigned int sev;
+  
+  if(argc < 4) {
+    SCWrite(pCon,"ERROR: need severity subsystem message parameters", eError);
+    return 0;
+  }
+
+  /*
+    interpret severity
+  */
+  strtolower(argv[1]);
+  sev = sevFromText(argv[1]);
+  if(sev >= INVALID){
+    SCPrintf(pCon,eError,"ERROR: %s is no valid severity code", argv[1]);
+    return 0;
+  } 
+
+  Arg2Text(argc-3,&argv[3],message,sizeof(message));
+
+  Log(sev,argv[2],"%s",message);
+  
+
+  return 1;
+}
+/*----------------------------------------------------------------------------*/
+static int LogConfigAction(SConnection * pCon, SicsInterp * pSics,
+                            void *pData, int argc, char *argv[])
+{
+  unsigned int sev;
+  char buffer[64];
+  pDynString result = NULL;
+  
+  if(argc < 2) {
+    SCWrite(pCon,"ERROR: need keyword", eError);
+    return 0;  
+  }
+
+  strtolower(argv[1]);
+
+  if(strcmp(argv[1],"maxlines") == 0){
+    if(argc > 2){
+      MAXFILELINES = atoi(argv[2]);
+      SCSendOK(pCon);
+    } else {
+      SCPrintf(pCon,eValue,"logconfig.maxlines = %d", MAXFILELINES);
+    }
+  } else if(strcmp(argv[1],"logtemplate") == 0){
+    if(argc > 2){
+      strncpy(logTemplate,argv[2],sizeof(logTemplate));
+      SCSendOK(pCon);
+    } else {
+      SCPrintf(pCon,eValue,"logconfig.logtemplate = %s", logTemplate);
+    }
+  }else if(strcmp(argv[1],"flush") == 0){
+    fflush(logFile);
+    SCSendOK(pCon);
+  } else if(strcmp(argv[1],"filename") == 0) {
+    SCPrintf(pCon,eValue,"logconfig.filename = %s", logFilename);
+  } else if(strcmp(argv[1],"close") == 0) {
+    LogClose(NULL);
+    SCSendOK(pCon);
+  }else if(strcmp(argv[1],"level") == 0 ) {
+    if(argc > 2) {
+      sev = sevFromText(argv[2]);
+      if(sev >= INVALID) {
+	SCPrintf(pCon,eError,"ERROR: %s is no valid log level", argv[2]);
+	return 0;
+      }
+      globalLogLevel = sev;
+      SCSendOK(pCon);
+    } else {
+      formatSeverity(globalLogLevel,buffer,sizeof(buffer));
+      SCPrintf(pCon,eValue,"logconfig.level = %s", buffer);
+    }
+  }else if (strcmp(argv[1],"enable") == 0) {
+    if(argc > 2){
+      if(strlen(argv[2]) >= 1024) {
+	SCWrite(pCon,"ERROR: subsystem name to long",eError);
+	return 0;
+      }
+      LLDstringAppend(subList,argv[2]);
+      SCSendOK(pCon);
+    } else {
+      SCWrite(pCon,"ERROR: need subsystem argument for enable",eError);
+      return 0;
+    }
+  }else if (strcmp(argv[1],"disable") == 0) {
+    if(argc > 2){
+      DisableSub(argv[2]);
+      SCSendOK(pCon);
+    } else {
+      SCWrite(pCon,"ERROR: need subsystem argument for disable",eError);
+      return 0;
+    }
+  } else if(strcmp(argv[1],"listenabled") == 0) {
+    result = ListEnabled();
+    if(result != NULL){
+      SCWrite(pCon,GetCharArray(result),eValue);
+      DeleteDynString(result);
+    }
+  } else {
+    SCPrintf(pCon,eError,"ERROR: unknown keyword %s",argv[1]);
+    return 0;
+  }
+
+  return 1;
+}
+/*-----------------------------------------------------------------------------*/
+void Logv2Init(void)
+{
+  subList = LLDstringCreate();
+  callbackList = LLDcreate(sizeof(LogCBData));
+  strcpy(logTemplate,"unconfiguredLogTemplate");
+
+  AddCmd("log", LogAction);
+  AddCommand(pServ->pSics,"logconfig", LogConfigAction,
+               LogClose, NULL);
+}

logv2.h

@@ -0,0 +1,60 @@
+/*
+  This is a reimplementation of SICS logging. The aim is to 
+  merge all the different logs within SICS to the new logging 
+  system
+
+  COPYRIGHT: see file COPYRIGHT
+
+  Mark Koennecke, February 2016
+ */
+
+#ifndef __LOGV2
+#define __LOGV2
+#include <stdarg.h>
+
+#define FATAL   1
+#define ERROR   2
+#define WARN    3
+#define INFO    4
+#define VERBOSE 5
+#define DEBUG   6
+#define INVALID 7 /* internal olny, do not use, means invalid severity passed */
+
+/* write a log message
+ * \param severity The message severity. Must be one of the defines given above
+ * \param subsystem The subsystem reporting the log messages
+ * \param format The format string for the message
+ * \param ... The data to format
+ */
+void Log(unsigned int severity, const char *subsystem,const char *format,...); 
+
+/* The callback functio which is called by the logging system on log events
+ * \param severity The message severity
+ * \param timeStamp The time stamp of the log message
+ * \param subsystem The subsystem of the log message
+ * \param message The log message
+ * \param userData A pointer to a user define ddata structure passed through 
+ *        transparantly from RegisterLogCallback
+*/
+
+/*
+At this time LogCallback do not do any filtering. Thus, they see every message.
+The idea is that suitable filtering functions ought to be implemented as helper 
+functions once the exact usage of the log \callbacks becomes clearer. 
+ */
+
+typedef void (*LogCallback)(unsigned int severity, const char *timeStamp, 
+			    const char *subsystem, 
+			    const char *message, void *userData);
+
+/* register a LogCallback
+ * \param func The function to call whena suitable log message has been found
+ * \param userData A pointer to user defined data which is passed through to the 
+ *  callback function. The log system does not free that pointer; this is up to the caller
+ * \return An callback ID which can be used for RemoveLogCallback
+ */  
+
+void RegisterLogCallback(LogCallback func, void *userData);
+void RemoveLogCallback(LogCallback func);
+
+#endif

make_gen

@@ -47,7 +47,7 @@ SOBJ =  network.o ifile.o conman.o SCinter.o splitter.o passwd.o \
        histmemsec.o sansbc.o sicsutil.o strlutil.o genbinprot.o trace.o\
        singlebinb.o taskobj.o sctcomtask.o tasmono.o multicountersec.o \
        messagepipe.o sicsget.o remoteobject.o pmacprot.o charbychar.o binprot.o \
-       cnvrt.o tclClock.o tclDate.o tclUnixTime.o stack_trace.o 	     
+       cnvrt.o tclClock.o tclDate.o tclUnixTime.o stack_trace.o logv2.o 	     
  
 MOTOROBJ = motor.o  simdriv.o  
 COUNTEROBJ =  countdriv.o simcter.o counter.o

ofac.c

@@ -55,6 +55,7 @@ static void InitGeneral(void)
   INIT(MakeTrace);
   INIT(InitTaskOBJ);
   INIT(RemoteObjectInit);
+  INIT(Logv2Init);
   INIT(SiteInit);               /* site specific initializations */
 }