Further enhancements to the new logging system

I removed traceCommand because I needed a more fine grained control of what goes into
the log.
This commit is contained in:
2016-03-01 09:42:16 +01:00
parent 0da0380c8a
commit 40382b2b8c
9 changed files with 60 additions and 191 deletions

174
conman.c
View File

@ -803,9 +803,18 @@ static int isOK(const char *buffer)
/*--------------------------------------------------------------------------*/ /*--------------------------------------------------------------------------*/
static void testAndWriteLog(SConnection * self, char *buffer, int iOut) static void testAndWriteLog(SConnection * self, char *buffer, int iOut)
{ {
unsigned int severity;
/* /*
first those which allways go into the log first those which allways go into the log
*/ */
if(SCGetRights(self) > usUser) {
severity = DEBUG;
} else {
severity = INFO;
}
switch(iOut){ switch(iOut){
case eInternal: case eInternal:
Log(ERROR,"sys","%s",buffer); Log(ERROR,"sys","%s",buffer);
@ -836,24 +845,32 @@ static void testAndWriteLog(SConnection * self, char *buffer, int iOut)
Log(INFO,"notify","%s",buffer); Log(INFO,"notify","%s",buffer);
break; break;
case eLog: case eLog:
Log(INFO,"com","sock%03.3d:%s",self->sockHandle,buffer); Log(severity,"com","sock%03.3d:%s",self->sockHandle,buffer);
break; break;
case eLogError: case eLogError:
Log(ERROR,"com","sock%03.3d:%s",self->sockHandle,buffer); Log(ERROR,"com","sock%03.3d:%s",self->sockHandle,buffer);
break; break;
case eError: case eError:
if(!SCinMacro(self)){ if(!SCinMacro(self)){
if(severity == DEBUG){
Log(DEBUG,"com","sock%03.3d:%s",self->sockHandle,buffer);
} else {
Log(ERROR,"com","sock%03.3d:%s",self->sockHandle,buffer); Log(ERROR,"com","sock%03.3d:%s",self->sockHandle,buffer);
} }
}
break; break;
case eWarning: case eWarning:
if(!SCinMacro(self)){ if(!SCinMacro(self)){
if(severity == DEBUG){
Log(DEBUG,"com","sock%03.3d:%s",self->sockHandle,buffer);
} else {
Log(WARN,"com","sock%03.3d:%s",self->sockHandle,buffer); Log(WARN,"com","sock%03.3d:%s",self->sockHandle,buffer);
} }
}
break; break;
case eValue: case eValue:
if(!SCinMacro(self)){ if(!SCinMacro(self)){
Log(INFO,"com","sock%03.3d:%s",self->sockHandle,buffer); Log(severity,"com","sock%03.3d:%s",self->sockHandle,buffer);
} }
break; break;
default: default:
@ -1223,7 +1240,7 @@ int SCWriteUUencoded(SConnection * pCon, char *pName, void *pData,
ANETwrite(pCon->sockHandle, pPtr, iLength); ANETwrite(pCon->sockHandle, pPtr, iLength);
} }
traceCommand(ConID(pCon),"out:UUData %s %d", pName, iLength); Log(DEBUG,"com","%s:out:UUData %s %d",ConID(pCon) ,pName, iLength);
#ifdef UUDEB #ifdef UUDEB
@ -1326,7 +1343,7 @@ int SCWriteZipped(SConnection * self, char *pName, void *pData,
SCWrite(self, "ERROR: out of memory in SCWriteZipped", eError); SCWrite(self, "ERROR: out of memory in SCWriteZipped", eError);
return 0; return 0;
} }
traceCommand(ConID(self),"out:SICSBIN ZIP %s %d", pName, compressedLength); Log(DEBUG,"com", "%s:out:SICSBIN ZIP %s %d", ConID(self), pName, compressedLength);
iRet = ANETwrite(self->sockHandle, pHeader, strlen(pHeader)); iRet = ANETwrite(self->sockHandle, pHeader, strlen(pHeader));
@ -1401,7 +1418,7 @@ int SCWriteBinary(SConnection * self, char *pName, void *pData,
SCWrite(self, "ERROR: out of memory in SCWriteBinary", eError); SCWrite(self, "ERROR: out of memory in SCWriteBinary", eError);
return 0; return 0;
} }
traceCommand(ConID(self),"out:SICSBIN BIN %s %d", pName, iDataLen); Log(DEBUG,"com","%s:out:SICSBIN BIN %s %d", ConID(self), pName, iDataLen);
iRet = ANETwrite(self->sockHandle, pHeader, strlen(pHeader)); iRet = ANETwrite(self->sockHandle, pHeader, strlen(pHeader));
iRet = ANETwrite(self->sockHandle, pData, iDataLen); iRet = ANETwrite(self->sockHandle, pData, iDataLen);
@ -1416,147 +1433,6 @@ int SCWriteBinary(SConnection * self, char *pName, void *pData,
return 1; return 1;
} }
/*--------------------------------------------------------------
* left in for documentation............
*/
int SCWriteZippedOld(SConnection * self, char *pName, void *pData,
int iDataLen)
{
char outBuf[65546], *pBuf = NULL, noutBuf[ZIPBUF], *pHeader = NULL;
int compressedLength, iRet, iRet2, iCount, protocolID;
z_stream compStream;
commandContext cc;
/* check for a valid connection */
if (!VerifyConnection(self)) {
return 0;
}
/* a telnet connection will corrupt the compressed stream, so
stop it!
*/
if (self->iTelnet) {
SCWrite(self,
"ERROR: the telnet protocoll will corrupt compressed data!",
eError);
return 0;
}
/*
do nothing if no data
*/
if (pName == NULL || pData == NULL) {
SCWrite(self, "ERROR: no data to write in SCWriteZiped", eError);
return 0;
}
/* initialize the compression stuff */
compStream.zalloc = (alloc_func) NULL;
compStream.zfree = (free_func) NULL;
compStream.opaque = (voidpf) NULL;
iRet = deflateInit(&compStream, Z_DEFAULT_COMPRESSION);
if (iRet != Z_OK) {
sprintf(outBuf, "ERROR: zlib error: %d", iRet);
SCWrite(self, outBuf, eError);
return 0;
}
/* first pass: find out how the long the compressed buffer will be */
compressedLength = 0;
compStream.next_in = (Bytef *) pData;
compStream.next_out = (Bytef *) outBuf;
compStream.avail_in = iDataLen;
compStream.avail_out = 65536;
while (compStream.total_in < iDataLen) {
iRet = deflate(&compStream, Z_NO_FLUSH);
if (iRet != Z_OK) {
sprintf(outBuf, "ERROR: zlib error: %d", iRet);
SCWrite(self, outBuf, eError);
return 0;
}
compStream.next_out = (Bytef *) outBuf;
compStream.avail_out = 65536;
}
for (;;) {
iRet = deflate(&compStream, Z_FINISH);
if (iRet == Z_STREAM_END)
break;
if (iRet != Z_OK) {
sprintf(outBuf, "ERROR: zlib error: %d", iRet);
SCWrite(self, outBuf, eError);
return 0;
}
}
compressedLength = compStream.total_out;
deflateEnd(&compStream);
/* write header line */
memset(outBuf, 0, 65536);
protocolID = GetProtocolID(self);
if (protocolID == PROTACT) {
cc = SCGetContext(self);
sprintf(outBuf, "SICSBIN ZIP %s %d %d\r\n", pName,
compressedLength, cc.transID);
} else {
sprintf(outBuf, "SICSBIN ZIP %s %d \r\n", pName, compressedLength);
}
pHeader = strdup(outBuf);
if (pHeader == NULL) {
SCWrite(self, "ERROR: out of memory in SCWriteZipped", eError);
return 0;
}
traceCommand(ConID(self),"out:SICSBIN ZIP %s %d", pName, compressedLength);
/* now reset the deflater and do the same with writing data */
compStream.zalloc = (alloc_func) NULL;
compStream.zfree = (free_func) NULL;
compStream.opaque = (voidpf) NULL;
/*
This is writing everything in one go as I found that writing in
several chunks did not ensure that all the data arrived at the
Java side.
*/
iRet = deflateInit(&compStream, Z_DEFAULT_COMPRESSION);
if (iRet != Z_OK) {
sprintf(outBuf, "ERROR: zlib error: %d", iRet);
SCWrite(self, outBuf, eError);
return 0;
}
pBuf = (char *) malloc((iDataLen + iDataLen / 10 + 50) * sizeof(char));
memset(pBuf, 0, (iDataLen + iDataLen / 10 + 50) * sizeof(char));
compStream.next_in = (Bytef *) pData;
compStream.next_out = (Bytef *) pBuf;
compStream.avail_in = iDataLen;
compStream.avail_out = iDataLen + iDataLen / 10 + 50;
iRet = deflate(&compStream, Z_FINISH);
if (iRet != Z_STREAM_END) {
sprintf(outBuf, "ERROR: zlib error: %d", iRet);
SCWrite(self, outBuf, eError);
return 0;
}
iRet = ANETwrite(self->sockHandle, pHeader, strlen(pHeader));
iRet = ANETwrite(self->sockHandle, pBuf, compStream.total_out);
if (iRet != 1) {
sprintf(outBuf, "ERROR: network error %d on zipped send", iRet);
SCWrite(self, outBuf, eError);
return 0;
}
/* printf("Sent zipped data: %s with %d\n", pHeader, iRet); */
deflateEnd(&compStream);
free(pHeader);
free(pBuf);
return 1;
}
/*-------------------------------------------------------------------------*/ /*-------------------------------------------------------------------------*/
int SCSendOK(SConnection * self) int SCSendOK(SConnection * self)
{ {
@ -1831,7 +1707,11 @@ int SCInvoke(SConnection * self, SicsInterp * pInter, char *pCommand)
return 0; return 0;
} }
strlcpy(pCopy->deviceID, pBueffel, SCDEVIDLEN); strlcpy(pCopy->deviceID, pBueffel, SCDEVIDLEN);
traceCommand(ConID(self),"in:%s", pCommand); if(SCGetRights(self) > usUser){
Log(DEBUG,"com","%s:in:%s", ConID(self),pCommand);
} else {
Log(INFO,"com", "%s:in:%s", ConID(self),pCommand);
}
iRet = InterpExecute(pInter, pCopy, pCommand); iRet = InterpExecute(pInter, pCopy, pCommand);
SCDeleteConnection(pCopy); SCDeleteConnection(pCopy);
StatusFileTask(NULL); /* save changed parameters */ StatusFileTask(NULL); /* save changed parameters */

View File

@ -301,7 +301,7 @@ int exeBufProcess(pExeBuf self, SicsInterp * pSics,
} }
} }
traceCommand(ConID(pCon),"batch:%s", cmd); Log(INFO,"com","%s:batch:%s", ConID(pCon), cmd);
status = Tcl_Eval(pTcl, cmd); status = Tcl_Eval(pTcl, cmd);
if (status != TCL_OK) { if (status != TCL_OK) {
if (pCon->sicsError == 0) { if (pCon->sicsError == 0) {

View File

@ -145,7 +145,7 @@ static void writeLog(char *logMessage)
} }
/*----------------------------------------------------------------------------*/ /*----------------------------------------------------------------------------*/
static unsigned int logFilter(unsigned int severity, const char *subsystem) unsigned int logFilter(unsigned int severity, const char *subsystem)
{ {
int status; int status;
char buffer[1024]; char buffer[1024];
@ -178,7 +178,7 @@ static unsigned int logFilter(unsigned int severity, const char *subsystem)
return 0; return 0;
} }
/*=============================================================================*/ /*=============================================================================*/
static void formatSeverity(unsigned int severity, char *buffer, unsigned int bufferLength) void formatSeverity(unsigned int severity, char *buffer, unsigned int bufferLength)
{ {
static const char *severityText[] = {"FATAL", static const char *severityText[] = {"FATAL",
"ERROR", "ERROR",

16
logv2.h
View File

@ -57,6 +57,13 @@ typedef void (*LogCallback)(unsigned int severity, const char *timeStamp,
void RegisterLogCallback(LogCallback func, void *userData); void RegisterLogCallback(LogCallback func, void *userData);
void RemoveLogCallback(LogCallback func); void RemoveLogCallback(LogCallback func);
/* test if this log entry is filtered. Made a part of the API in support of
* log listeners
* \param severity the severity of the message
* \param subsystem the subsystem of the message
* \return 1 when filtered, 0 else
*/
unsigned int logFilter(unsigned int severity, const char *subsystem);
/* /*
*Disable logging in support of the nolog option in SICSmain.c *Disable logging in support of the nolog option in SICSmain.c
*/ */
@ -66,4 +73,13 @@ void DisableLog(void);
*/ */
void LogClose(void *data); void LogClose(void *data);
/*
* internal use in other logging functions
* \param severity The severity to encode
* \param buffer The buffer to write the severity as text too
* \param bufferLengh The length of buffer in order to prevent buffer overwrites
*/
void formatSeverity(unsigned int severity,
char *buffer, unsigned int bufferLength);
#endif #endif

View File

@ -33,7 +33,7 @@ LIBS = -L$(HDFROOT)/lib $(SUBLIBS) $(NILIB) $(EPICSLIBS) \
-ltcl -lNeXus $(HDFROOT)/lib/libhdf5.a \ -ltcl -lNeXus $(HDFROOT)/lib/libhdf5.a \
$(HDFROOT)/lib/libsz.a \ $(HDFROOT)/lib/libsz.a \
$(HDFROOT)/lib/libjson.a \ $(HDFROOT)/lib/libjson.a \
-ldl -lz $(HDFROOT)/lib/libmxml.a $(HDFROOT)/lib/libghttp.a -lm -lc -lpthread -ldl -lz $(HDFROOT)/lib/libmxml.a $(HDFROOT)/lib/libghttp.a -lm -lc -lpthread -lsqlite3 -lbson-1.0 -lmongoc-1.0
include make_gen include make_gen

View File

@ -262,7 +262,6 @@ static int NetReadRead(pNetRead self, pNetItem pItem)
if (pPtr) { if (pPtr) {
sscanf(pPtr, "%s %d", pMuell, &iInt); sscanf(pPtr, "%s %d", pMuell, &iInt);
if (SCMatchRights(pItem->pCon, usUser)) { if (SCMatchRights(pItem->pCon, usUser)) {
traceCommand(ConID(pItem->pCon),"interrupt: %d",iInt);
TaskSignal(self->pMain->pTasker, SICSINT, &iInt); TaskSignal(self->pMain->pTasker, SICSINT, &iInt);
Log(ERROR,"com","sock%03.3d:INTERRUPT", pItem->pCon->pSock->sockid); Log(ERROR,"com","sock%03.3d:INTERRUPT", pItem->pCon->pSock->sockid);
if (iInt == eEndServer) { if (iInt == eEndServer) {
@ -461,7 +460,7 @@ static int TelnetRead(pNetRead self, pNetItem pItem)
} }
} }
TaskSignal(self->pMain->pTasker, SICSINT, &iInt); TaskSignal(self->pMain->pTasker, SICSINT, &iInt);
traceCommand(ConID(pItem->pCon),"interrupt: %d",iInt); Log(ERROR,"com","%s:interrupt: %d", ConID(pItem->pCon),iInt);
if (iInt == eEndServer) { if (iInt == eEndServer) {
TaskStop(self->pMain->pTasker); TaskStop(self->pMain->pTasker);
} }
@ -1031,7 +1030,7 @@ static int testAndInvokeInterrupt(pCommandCBData self, int handle)
if ((pInt = strstr(pPtr, "INT1712")) != NULL) { if ((pInt = strstr(pPtr, "INT1712")) != NULL) {
sscanf(pInt, "%s %d", buffer, &iInt); sscanf(pInt, "%s %d", buffer, &iInt);
if (SCMatchRights(self->pCon, usUser)) { if (SCMatchRights(self->pCon, usUser)) {
traceCommand(ConID(self->pCon),"interrupt:%d",iInt); Log(INFO, "com","%s:interrupt:%d", ConID(self->pCon), iInt);
TaskSignal(pServ->pTasker, SICSINT, &iInt); TaskSignal(pServ->pTasker, SICSINT, &iInt);
snprintf(buffer, 512, "INTERRUPT %d issued on sock %d", snprintf(buffer, 512, "INTERRUPT %d issued on sock %d",
iInt, handle); iInt, handle);

39
trace.c
View File

@ -288,32 +288,6 @@ void traceDevice(char *id, char *format, ...)
} }
} }
/*-----------------------------------------------------------------*/ /*-----------------------------------------------------------------*/
void traceCommand(char *id, char *format, ...)
{
va_list argptr;
char buffer[1024], *buf = NULL;
int len;
if(logFD != NULL && filter("com","id")){
va_start(argptr,format);
len = vsnprintf(buffer, sizeof(buffer),format,argptr);
va_end(argptr);
if(len >= sizeof(buffer)){
buf = malloc(len+1);
if(buf != NULL){
memset(buf,0,len+1);
va_start(argptr,format);
len = vsnprintf(buf, len+1,format,argptr);
va_end(argptr);
traceprint("com",id,buf);
free(buf);
}
} else {
traceprint("com",id,buffer);
}
}
}
/*-----------------------------------------------------------------*/
void tracePar(char *id, char *format, ...) void tracePar(char *id, char *format, ...)
{ {
va_list argptr; va_list argptr;
@ -557,12 +531,13 @@ static int TraceFilter(pSICSOBJ ccmd, SConnection * con,
/*-----------------------------------------------------------------------------*/ /*-----------------------------------------------------------------------------*/
static void KillTrace(void *data) static void KillTrace(void *data)
{ {
if(logFD != NULL){
fclose(logFD); /* if(logFD != NULL){ */
free(logfile); /* fclose(logFD); */
logFD = NULL; /* free(logfile); */
logfile = NULL; /* logFD = NULL; */
} /* logfile = NULL; */
/* } */
} }
/*-----------------------------------------------------------------------------------------*/ /*-----------------------------------------------------------------------------------------*/
void MakeTrace(void) void MakeTrace(void)

View File

@ -26,7 +26,6 @@
#endif #endif
void traceIO(char *id, char *format, ...) G_GNUC_PRINTF (2, 3); void traceIO(char *id, char *format, ...) G_GNUC_PRINTF (2, 3);
void traceDevice(char *id, char *format, ...) G_GNUC_PRINTF (2, 3); void traceDevice(char *id, char *format, ...) G_GNUC_PRINTF (2, 3);
void traceCommand(char *id, char *format, ...) G_GNUC_PRINTF (2, 3);
void tracePar(char *id, char *format, ...) G_GNUC_PRINTF (2, 3); void tracePar(char *id, char *format, ...) G_GNUC_PRINTF (2, 3);
void traceSys(char *id, char *format, ...) G_GNUC_PRINTF (2, 3); void traceSys(char *id, char *format, ...) G_GNUC_PRINTF (2, 3);
void traceprint(char *sub, char *id,char *data); void traceprint(char *sub, char *id,char *data);