516 lines
14 KiB
C
516 lines
14 KiB
C
/*
|
|
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];
|
|
static unsigned int logDisabled = 0;
|
|
static int unsigned logConfigured = 0;
|
|
|
|
/*================ The default log level =======================================*/
|
|
static unsigned int globalLogLevel = 4;
|
|
/*========= 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;
|
|
}
|
|
/*----------------------------------------------------------------------------*/
|
|
void LogClose(void *data)
|
|
{
|
|
if(logFile != NULL){
|
|
fclose(logFile);
|
|
}
|
|
logFile = NULL;
|
|
lineCount = 0;
|
|
strcpy(logFilename,"undefined");
|
|
}
|
|
/*----------------------------------------------------------------------------*/
|
|
static void checkLogFile(void)
|
|
{
|
|
char *filename = NULL;
|
|
|
|
if(logDisabled || logConfigured == 0){
|
|
return;
|
|
}
|
|
|
|
/*
|
|
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;
|
|
unsigned int end;
|
|
char *pPtr;
|
|
const char delim = '\n';
|
|
|
|
if(logMessage == NULL){
|
|
return;
|
|
}
|
|
|
|
/*
|
|
remove a trailing newline
|
|
*/
|
|
end = strlen(logMessage);
|
|
if(logMessage[end-1] == delim){
|
|
logMessage[end-1] = '\0';
|
|
}
|
|
|
|
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(logDisabled || logConfigured == 0){
|
|
return 1;
|
|
}
|
|
|
|
|
|
/*
|
|
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], *pPtr = NULL;
|
|
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));
|
|
logConfigured = 1;
|
|
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 DisableLog(void)
|
|
{
|
|
logDisabled = 1;
|
|
}
|
|
/*-----------------------------------------------------------------------------*/
|
|
void Logv2Init(void)
|
|
{
|
|
subList = LLDstringCreate();
|
|
callbackList = LLDcreate(sizeof(LogCBData));
|
|
strcpy(logTemplate,"unconfiguredLogTemplate");
|
|
|
|
AddCmd("log", LogAction);
|
|
AddCommand(pServ->pSics,"logconfig", LogConfigAction,
|
|
LogClose, NULL);
|
|
}
|