diff --git a/asyncqueue.c b/asyncqueue.c index 74b18538..4b949afc 100644 --- a/asyncqueue.c +++ b/asyncqueue.c @@ -22,7 +22,7 @@ #include "asyncqueue.h" #include "nwatch.h" #include - +#include typedef struct __async_command AQ_Cmd, *pAQ_Cmd; @@ -394,6 +394,7 @@ static int StartCommand(pAsyncQueue self) struct timeval tv; gettimeofday(&tv, NULL); Log(ERROR, "asquio","%d unsolicited chars in AsyncQueue %s",iRet, self->queue_name); + LogHex(&tv,ERROR,SASQIO,reply,iRet); } } } @@ -502,6 +503,7 @@ static int CommandTimeout(void *cntx, int mode) struct timeval tv; gettimeofday(&tv, NULL); Log(DEBUG,"asquio", "Timeout Trace on AsyncQueue %s", self->queue_name); + LogHex(&tv,DEBUG,SASQIO,myCmd->tran->inp_buf,myCmd->tran->inp_idx); } if (myCmd->retries > 0) { --myCmd->retries; @@ -532,6 +534,17 @@ static int DelayedStart(void *cntx, int mode) return 1; } +static void LogHexPrefix(struct timeval *tv, unsigned int severity, char *prefix, char *buffer, int bufferLength) +{ + char *hexData = NULL; + + hexData = bytesToHexString((uint8_t *)buffer,(size_t)bufferLength); + if(hexData != NULL){ + LogTS(tv,severity,SASQIO,"%s:%s", prefix,hexData); + free(hexData); + } +} + static int MyCallback(void *context, int mode) { pAsyncQueue self = (pAsyncQueue) context; @@ -567,8 +580,8 @@ static int MyCallback(void *context, int mode) if (self->trace) { struct timeval tv; gettimeofday(&tv, NULL); - Log(INFO, "asquio", - "Received:%s:%s", self->queue_name,myCmd->tran->inp_buf); + Log(INFO, "asquio","Input Trace on AsyncQueue %s", self->queue_name); + LogHex(&tv,INFO,SASQIO,myCmd->tran->inp_buf, myCmd->tran->inp_idx); } PopCommand(self); break; @@ -579,7 +592,10 @@ static int MyCallback(void *context, int mode) Log(ERROR,"asquio", "Protocol error %d in AsyncQueue %s", iRet, self->queue_name); - Log(ERROR,"asquio","SENT:%s:Received:%s",myCmd->tran->out_buf, myCmd->tran->inp_buf); + LogHexPrefix(&tv,ERROR,"Sent", myCmd->tran->out_buf,myCmd->tran->out_len); + LogHexPrefix(&tv,ERROR,"Received", myCmd->tran->inp_buf,myCmd->tran->inp_len); + LogHexPrefix(&tv,ERROR,"Processed", &reply[0],i); + LogHexPrefix(&tv,ERROR,"Unprocessed", &reply[i],excess); break; } } @@ -813,8 +829,7 @@ int AsyncUnitWrite(pAsyncUnit unit, void *buffer, int buflen) if (unit->queue->trace) { struct timeval tv; gettimeofday(&tv, NULL); - Log(DEBUG,"asquio" - "Output Trace on AsyncQueue %s:%s", unit->queue->queue_name, buffer); + LogHexPrefix(&tv,DEBUG,"Output Trace on AsyncQueue", buffer, buflen); } sock = AsyncUnitGetSocket(unit); iRet = NETWrite(sock, buffer, buflen); diff --git a/hexString.c b/hexString.c new file mode 100644 index 00000000..8b67b826 --- /dev/null +++ b/hexString.c @@ -0,0 +1,65 @@ +/* + * hexString.c + * byteutils + * + * Created by Richard Murphy on 3/7/10. + * Copyright 2010 McKenzie-Murphy. All rights reserved. + * + */ + +#include "hexString.h" + +/* utility function to convert hex character representation to their nibble (4 bit) values */ +static uint8_t +nibbleFromChar(char c) +{ + if(c >= '0' && c <= '9') return c - '0'; + if(c >= 'a' && c <= 'f') return c - 'a' + 10; + if(c >= 'A' && c <= 'F') return c - 'A' + 10; + return 255; +} + +/* Convert a string of characters representing a hex buffer into a series of bytes of that real value */ +uint8_t +*hexStringToBytes(char *inhex) +{ + uint8_t *retval; + uint8_t *p; + int len, i; + + len = strlen(inhex) / 2; + retval = malloc(len+1); + for(i=0, p = (uint8_t *) inhex; i> 4); + retval[i*2+1] = nibbleToChar(bytes[i] & 0x0f); + } + retval[i] = '\0'; + return retval; +} diff --git a/hexString.h b/hexString.h new file mode 100644 index 00000000..d72a25dd --- /dev/null +++ b/hexString.h @@ -0,0 +1,18 @@ +/* + * hexString.h + * byteutils + * + * Created by Richard Murphy on 3/7/10. + * Copyright 2010 McKenzie-Murphy. All rights reserved. + * + */ + +#include +#include +#include + +uint8_t +*hexStringToBytes(char *inhex); + +char +*bytesToHexString(uint8_t *bytes, size_t buflen); diff --git a/logv2.c b/logv2.c index 6023f760..8ac06b87 100644 --- a/logv2.c +++ b/logv2.c @@ -15,6 +15,7 @@ #include #include #include +#include /*============================================================================== some static fields which control log file rotation ===============================================================================*/ @@ -456,6 +457,22 @@ void LogTS(struct timeval *tv, unsigned int severity, unsigned int subsystem,con } +} +/*----------------------------------------------------------------------------*/ +void LogHex(struct timeval*tv, unsigned int severity, unsigned int subsystem, + char *buffer, int bufferLength) +{ + char subText[30], timeStamp[256], *hexData; + + formatSubsystem(subsystem,subText,sizeof(subText)); + formatTimeStamp(tv, timeStamp,sizeof(timeStamp),0); + + hexData = bytesToHexString((uint8_t *)buffer,(size_t)bufferLength); + + if(hexData != NULL){ + LogInternal((char *)timeStamp, severity, subText,hexData); + free(hexData); + } } /*----------------------------------------------------------------------------*/ void Log(unsigned int severity, const char *subsystem,const char *format,...) diff --git a/logv2.h b/logv2.h index dc523bba..4220ab81 100644 --- a/logv2.h +++ b/logv2.h @@ -64,7 +64,15 @@ void LogIS(unsigned int severity, unsigned int subsystem,const char *format,...) * \param ... The data to format */ void LogTS(struct timeval *tv, unsigned int severity, unsigned int subsystem,const char *format,...); - +/* + * write a log entry in hex + * \param timeStamp A user supplied timestamp. Can be NULL, then the current time is used + * \param severity The message severity. Must be one of the defines given above + * \param subsystem The subsystem reporting the log messages + * \param buffer the bytes to log as hex + * \param bufferLength The length of buffer + */ +void LogHex(struct timeval*tv, unsigned int severity, unsigned int subsystem,char *buffer, int bufferLength); /* The callback functio which is called by the logging system on log events