From d4299de653d3c892380e9d27a7ae51319f4ce7b3 Mon Sep 17 00:00:00 2001 From: Brant Thomsen Date: Mon, 31 Jul 2017 13:38:23 -0600 Subject: Logging Clean-Up StreamId always logged with a non-negative number. Logging messages shown if file logging value greater than global logging value. Check local logging level before calling avbLogBuffer. --- lib/avtp_pipeline/include/openavb_log_pub.h | 16 +++++++++++----- .../platform/Linux/endpoint/openavb_endpoint_osal_srp.c | 2 +- 2 files changed, 12 insertions(+), 6 deletions(-) diff --git a/lib/avtp_pipeline/include/openavb_log_pub.h b/lib/avtp_pipeline/include/openavb_log_pub.h index 805e2d01..1e3a6d69 100644 --- a/lib/avtp_pipeline/include/openavb_log_pub.h +++ b/lib/avtp_pipeline/include/openavb_log_pub.h @@ -170,7 +170,7 @@ typedef enum { #define ETH_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x" #define ETH_OCTETS(a) (a)[0],(a)[1],(a)[2],(a)[3],(a)[4],(a)[5] -#define STREAMID_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x/%d" +#define STREAMID_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x/%u" #define STREAMID_ARGS(s) (s)->addr[0],(s)->addr[1],(s)->addr[2],(s)->addr[3],(s)->addr[4],(s)->addr[5],(s)->uniqueID #define ENTITYID_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x:%02x:%02x" @@ -206,15 +206,21 @@ void avbLogBuffer( #define avbLogFn2(level, tag, company, component, path, line, fmt, ...) \ - ({\ + {\ if (level <= AVB_LOG_LEVEL) \ avbLogFn(0, tag, company, component, path, line, fmt, __VA_ARGS__); \ - }) + } #define avbLogRT2(level, bBegin, bItem, bEnd, pFormat, dataType, pVar) \ {\ if (level <= AVB_LOG_LEVEL) \ - avbLogRT(level, bBegin, bItem, bEnd, pFormat, dataType, pVar); \ + avbLogRT(0, bBegin, bItem, bEnd, pFormat, dataType, pVar); \ + } + +#define avbLogBuffer2(level, pData, dataLen, lineLen, company, component, path, line) \ + {\ + if (level <= AVB_LOG_LEVEL) \ + avbLogBuffer(0, pData, dataLen, lineLen, company, component, path, line); \ } #ifdef AVB_LOG_ON @@ -238,7 +244,7 @@ void avbLogBuffer( #define AVB_LOGRT_STATUS(BEGIN, ITEM, END, FMT, TYPE, VAL) avbLogRT2(AVB_LOG_LEVEL_STATUS, BEGIN, ITEM, END, FMT, TYPE, VAL) #define AVB_LOGRT_DEBUG(BEGIN, ITEM, END, FMT, TYPE, VAL) avbLogRT2(AVB_LOG_LEVEL_DEBUG, BEGIN, ITEM, END, FMT, TYPE, VAL) #define AVB_LOGRT_VERBOSE(BEGIN, ITEM, END, FMT, TYPE, VAL) avbLogRT2(AVB_LOG_LEVEL_VERBOSE, BEGIN, ITEM, END, FMT, TYPE, VAL) -#define AVB_LOG_BUFFER(LEVEL, DATA, DATALEN, LINELINE) avbLogBuffer(LEVEL, DATA, DATALEN, LINELINE, AVB_LOG_COMPANY, AVB_LOG_COMPONENT, __FILE__, __LINE__) +#define AVB_LOG_BUFFER(LEVEL, DATA, DATALEN, LINELINE) avbLogBuffer2(LEVEL, DATA, DATALEN, LINELINE, AVB_LOG_COMPANY, AVB_LOG_COMPONENT, __FILE__, __LINE__) #else #define AVB_LOGF_DEV(LEVEL, FMT, ...) #define AVB_LOGF_ERROR(FMT, ...) diff --git a/lib/avtp_pipeline/platform/Linux/endpoint/openavb_endpoint_osal_srp.c b/lib/avtp_pipeline/platform/Linux/endpoint/openavb_endpoint_osal_srp.c index 9a7e42f3..9a7d2b33 100644 --- a/lib/avtp_pipeline/platform/Linux/endpoint/openavb_endpoint_osal_srp.c +++ b/lib/avtp_pipeline/platform/Linux/endpoint/openavb_endpoint_osal_srp.c @@ -67,7 +67,7 @@ typedef struct { openavb_list_t strElemList; -#define SID_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x/%d" +#define SID_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x/%u" #define SID_OCTETS(a) (a)[0],(a)[1],(a)[2],(a)[3],(a)[4],(a)[5],(a)[6]<<8|(a)[7] // Callback for SRP to notify AVTP Talker that a Listener Declaration has been -- cgit v1.2.1 From fc5227217143e0ca6a85e2fcabecb22aef46fd11 Mon Sep 17 00:00:00 2001 From: Brant Thomsen Date: Mon, 31 Jul 2017 14:11:41 -0600 Subject: More logging fixes Fixed description for IF_LOG_ONCE and IF_LOG_INTERVAL. Make sure logging static variables are initialized to 0. MAAP and Shaper test buffer logging level before calling shaperLogBuffer. --- daemons/maap/common/maap_log.h | 10 +++++----- daemons/shaper/src/shaper_log.h | 20 +++++++++++++------- lib/avtp_pipeline/include/openavb_log_pub.h | 8 ++++---- 3 files changed, 22 insertions(+), 16 deletions(-) diff --git a/daemons/maap/common/maap_log.h b/daemons/maap/common/maap_log.h index 7d36c1a1..bb421c7b 100644 --- a/daemons/maap/common/maap_log.h +++ b/daemons/maap/common/maap_log.h @@ -162,11 +162,11 @@ typedef enum { #define LOG_VARX(x, y) x ## y #define LOG_VAR(x, y) LOG_VARX(x, y) -// Log a message once. Technically once every 4.2 billion attempts. Usage: LOG_ONCE MAAP_LOG_INFO(...) -#define IF_LOG_ONCE() static uint32_t LOG_VAR(logOnce,__LINE__); if (!LOG_VAR(logOnce,__LINE__)++) +// Log a message once. Technically once every 4.2 billion attempts. Usage: IF_LOG_ONCE() MAAP_LOG_INFO(...) +#define IF_LOG_ONCE() static uint32_t LOG_VAR(logOnce,__LINE__) = 0; if (!LOG_VAR(logOnce,__LINE__)++) -// Log a message at an interval. Usage: LOG_INTERVAL(100) MAAP_LOG_INFO(...) -#define IF_LOG_INTERVAL(x) static uint32_t LOG_VAR(logOnce,__LINE__); if (!(LOG_VAR(logOnce,__LINE__)++ % (x - 1))) +// Log a message at an interval. Usage: IF_LOG_INTERVAL(100) MAAP_LOG_INFO(...) +#define IF_LOG_INTERVAL(x) static uint32_t LOG_VAR(logOnce,__LINE__) = 0; if (!(LOG_VAR(logOnce,__LINE__)++ % (x - 1))) #define ETH_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x" @@ -221,7 +221,7 @@ void maapLogBuffer( #define MAAP_LOGRT_STATUS(BEGIN, ITEM, END, FMT, TYPE, VAL) maapLogRT(MAAP_LOG_LEVEL_STATUS, BEGIN, ITEM, END, FMT, TYPE, VAL) #define MAAP_LOGRT_DEBUG(BEGIN, ITEM, END, FMT, TYPE, VAL) maapLogRT(MAAP_LOG_LEVEL_DEBUG, BEGIN, ITEM, END, FMT, TYPE, VAL) #define MAAP_LOGRT_VERBOSE(BEGIN, ITEM, END, FMT, TYPE, VAL) maapLogRT(MAAP_LOG_LEVEL_VERBOSE, BEGIN, ITEM, END, FMT, TYPE, VAL) -#define MAAP_LOG_BUFFER(LEVEL, DATA, DATALEN, LINELINE) maapLogBuffer(LEVEL, DATA, DATALEN, LINELINE, MAAP_LOG_COMPANY, MAAP_LOG_COMPONENT, __FILE__, __LINE__) +#define MAAP_LOG_BUFFER(LEVEL, DATA, DATALEN, LINELINE) do { if (LEVEL <= MAAP_LOG_LEVEL) maapLogBuffer(0, DATA, DATALEN, LINELINE, MAAP_LOG_COMPANY, MAAP_LOG_COMPONENT, __FILE__, __LINE__); } while(0) #else #define MAAP_LOGF_DEV(LEVEL, FMT, ...) #define MAAP_LOGF_ERROR(FMT, ...) diff --git a/daemons/shaper/src/shaper_log.h b/daemons/shaper/src/shaper_log.h index 2b97726d..6c7d987b 100644 --- a/daemons/shaper/src/shaper_log.h +++ b/daemons/shaper/src/shaper_log.h @@ -162,11 +162,11 @@ typedef enum { #define LOG_VARX(x, y) x ## y #define LOG_VAR(x, y) LOG_VARX(x, y) -// Log a message once. Technically once every 4.2 billion attempts. Usage: LOG_ONCE SHAPER_LOG_INFO(...) -#define IF_LOG_ONCE() static uint32_t LOG_VAR(logOnce,__LINE__); if (!LOG_VAR(logOnce,__LINE__)++) +// Log a message once. Technically once every 4.2 billion attempts. Usage: IF_LOG_ONCE() SHAPER_LOG_INFO(...) +#define IF_LOG_ONCE() static uint32_t LOG_VAR(logOnce,__LINE__) = 0; if (!LOG_VAR(logOnce,__LINE__)++) -// Log a message at an interval. Usage: LOG_INTERVAL(100) SHAPER_LOG_INFO(...) -#define IF_LOG_INTERVAL(x) static uint32_t LOG_VAR(logOnce,__LINE__); if (!(LOG_VAR(logOnce,__LINE__)++ % (x - 1))) +// Log a message at an interval. Usage: IF_LOG_INTERVAL(100) SHAPER_LOG_INFO(...) +#define IF_LOG_INTERVAL(x) static uint32_t LOG_VAR(logOnce,__LINE__) = 0; if (!(LOG_VAR(logOnce,__LINE__)++ % (x - 1))) #define ETH_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x" @@ -203,10 +203,16 @@ void shaperLogBuffer( #define shaperLogFn2(level, tag, company, component, path, line, fmt, ...) \ - ({\ + {\ if (level <= SHAPER_LOG_LEVEL) \ shaperLogFn(0, tag, company, component, path, line, fmt, __VA_ARGS__); \ - }) + } + +#define shaperLogBuffer2(level, pData, dataLen, lineLen, company, component, path, line) \ + {\ + if (level <= AVB_LOG_LEVEL) \ + shaperLogBuffer(0, pData, dataLen, lineLen, company, component, path, line); \ + } #ifdef SHAPER_LOG_ON #define SHAPER_LOGF_DEV(LEVEL, FMT, ...) shaperLogFn2(LEVEL, "DEV", SHAPER_LOG_COMPANY, SHAPER_LOG_COMPONENT, __FILE__, __LINE__, FMT, __VA_ARGS__) @@ -229,7 +235,7 @@ void shaperLogBuffer( #define SHAPER_LOGRT_STATUS(BEGIN, ITEM, END, FMT, TYPE, VAL) shaperLogRT(SHAPER_LOG_LEVEL_STATUS, BEGIN, ITEM, END, FMT, TYPE, VAL) #define SHAPER_LOGRT_DEBUG(BEGIN, ITEM, END, FMT, TYPE, VAL) shaperLogRT(SHAPER_LOG_LEVEL_DEBUG, BEGIN, ITEM, END, FMT, TYPE, VAL) #define SHAPER_LOGRT_VERBOSE(BEGIN, ITEM, END, FMT, TYPE, VAL) shaperLogRT(SHAPER_LOG_LEVEL_VERBOSE, BEGIN, ITEM, END, FMT, TYPE, VAL) -#define SHAPER_LOG_BUFFER(LEVEL, DATA, DATALEN, LINELINE) shaperLogBuffer(LEVEL, DATA, DATALEN, LINELINE, SHAPER_LOG_COMPANY, SHAPER_LOG_COMPONENT, __FILE__, __LINE__) +#define SHAPER_LOG_BUFFER(LEVEL, DATA, DATALEN, LINELINE) shaperLogBuffer2(LEVEL, DATA, DATALEN, LINELINE, SHAPER_LOG_COMPANY, SHAPER_LOG_COMPONENT, __FILE__, __LINE__) #else #define SHAPER_LOGF_DEV(LEVEL, FMT, ...) #define SHAPER_LOGF_ERROR(FMT, ...) diff --git a/lib/avtp_pipeline/include/openavb_log_pub.h b/lib/avtp_pipeline/include/openavb_log_pub.h index 1e3a6d69..47b0bbbe 100644 --- a/lib/avtp_pipeline/include/openavb_log_pub.h +++ b/lib/avtp_pipeline/include/openavb_log_pub.h @@ -160,11 +160,11 @@ typedef enum { #define LOG_VARX(x, y) x ## y #define LOG_VAR(x, y) LOG_VARX(x, y) -// Log a message once. Technically once every 4.2 billion attempts. Usage: LOG_ONCE AVB_LOG_INFO(...) -#define IF_LOG_ONCE() static U32 LOG_VAR(logOnce,__LINE__); if (!LOG_VAR(logOnce,__LINE__)++) +// Log a message once. Technically once every 4.2 billion attempts. Usage: IF_LOG_ONCE() AVB_LOG_INFO(...) +#define IF_LOG_ONCE() static U32 LOG_VAR(logOnce,__LINE__) = 0; if (!LOG_VAR(logOnce,__LINE__)++) -// Log a message at an interval. Usage: LOG_INTERVAL(100) AVB_LOG_INFO(...) -#define IF_LOG_INTERVAL(x) static U32 LOG_VAR(logOnce,__LINE__); if (!(LOG_VAR(logOnce,__LINE__)++ % (x - 1))) +// Log a message at an interval. Usage: IF_LOG_INTERVAL(100) AVB_LOG_INFO(...) +#define IF_LOG_INTERVAL(x) static U32 LOG_VAR(logOnce,__LINE__) = 0; if (!(LOG_VAR(logOnce,__LINE__)++ % (x - 1))) #define ETH_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x" -- cgit v1.2.1 From b6910749684f3604d91da15f334379c0d2eaf932 Mon Sep 17 00:00:00 2001 From: Brant Thomsen Date: Mon, 31 Jul 2017 14:15:00 -0600 Subject: Rawsock ring logging Changes to the verbose Rawsock ring logging to make its behavior easier to follow. --- .../platform/Linux/rawsock/ring_rawsock.c | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) diff --git a/lib/avtp_pipeline/platform/Linux/rawsock/ring_rawsock.c b/lib/avtp_pipeline/platform/Linux/rawsock/ring_rawsock.c index 64d222fe..f66878c1 100644 --- a/lib/avtp_pipeline/platform/Linux/rawsock/ring_rawsock.c +++ b/lib/avtp_pipeline/platform/Linux/rawsock/ring_rawsock.c @@ -219,9 +219,9 @@ U8* ringRawsockGetTxFrame(void *pvRawsock, bool blocking, unsigned int *len) // And pointer to portion of buffer to be filled with frame volatile U8 *pBuffer = (U8*)pHdr + rawsock->bufHdrSize; - AVB_LOGF_VERBOSE("block=%d, buffer=%d, out=%d, pHdr=%p, pBuffer=%p", + AVB_LOGF_VERBOSE("block=%d, buffer=%d, out=%d, pBuffer=%p, pHdr=%p", rawsock->blockIndex, rawsock->bufferIndex, rawsock->buffersOut, - pHdr, pBuffer); + pBuffer, pHdr); // Check if buffer ready for user // In send mode, we want to see TP_STATUS_AVAILABLE @@ -485,9 +485,9 @@ U8* ringRawsockGetRxFrame(void *pvRawsock, U32 timeout, unsigned int *offset, un + (rawsock->bufferIndex * rawsock->bufferSize)); volatile U8 *pBuffer = (U8*)pHdr + rawsock->bufHdrSize; - AVB_LOGF_VERBOSE("block=%d, buffer=%d, out=%d, pHdr=%p, pBuffer=%p", + AVB_LOGF_VERBOSE("block=%d, buffer=%d, out=%d, pBuffer=%p, pHdr=%p", rawsock->blockIndex, rawsock->bufferIndex, rawsock->buffersOut, - pHdr, pBuffer); + pBuffer, pHdr); // Check if buffer ready for user // In receive mode, we want TP_STATUS_USER flag set @@ -601,7 +601,12 @@ U8* ringRawsockGetRxFrame(void *pvRawsock, U32 timeout, unsigned int *offset, un rawsock->buffersOut += 1; if (pHdr->tp_snaplen < pHdr->tp_len) { +#if (AVB_LOG_LEVEL >= AVB_LOG_LEVEL_VERBOSE) + AVB_LOGF_WARNING("Getting RX frame; partial frame ignored (len %d, snaplen %d)", pHdr->tp_len, pHdr->tp_snaplen); + AVB_LOG_BUFFER(AVB_LOG_LEVEL_VERBOSE, (const U8 *) pBuffer + (pHdr->tp_mac - rawsock->bufHdrSize), pHdr->tp_len, 16); +#else IF_LOG_INTERVAL(1000) AVB_LOGF_WARNING("Getting RX frame; partial frame ignored (len %d, snaplen %d)", pHdr->tp_len, pHdr->tp_snaplen); +#endif ringRawsockRelRxFrame(rawsock, (U8*)pBuffer); AVB_TRACE_EXIT(AVB_TRACE_RAWSOCK_DETAIL); return NULL; @@ -610,6 +615,7 @@ U8* ringRawsockGetRxFrame(void *pvRawsock, U32 timeout, unsigned int *offset, un // Return pointer to the buffer and length *offset = pHdr->tp_mac - rawsock->bufHdrSize; *len = pHdr->tp_snaplen; + AVB_LOGF_VERBOSE("Good RX frame (len %d, snaplen %d)", pHdr->tp_len, pHdr->tp_snaplen); AVB_TRACE_EXIT(AVB_TRACE_RAWSOCK_DETAIL); return (U8*)pBuffer; @@ -628,7 +634,7 @@ int ringRawsockRxParseHdr(void *pvRawsock, U8 *pBuffer, hdr_info_t *pInfo) } volatile struct tpacket2_hdr *pHdr = (struct tpacket2_hdr*)(pBuffer - rawsock->bufHdrSize); - AVB_LOGF_VERBOSE("pBuffer=%p, pHdr=%p", pBuffer, pHdr); + AVB_LOGF_VERBOSE("ringRawsockRxParseHdr: pBuffer=%p, pHdr=%p", pBuffer, pHdr); memset(pInfo, 0, sizeof(hdr_info_t)); @@ -665,7 +671,7 @@ bool ringRawsockRelRxFrame(void *pvRawsock, U8 *pBuffer) } volatile struct tpacket2_hdr *pHdr = (struct tpacket2_hdr*)(pBuffer - rawsock->bufHdrSize); - AVB_LOGF_VERBOSE("pBuffer=%p, pHdr=%p", pBuffer, pHdr); + AVB_LOGF_VERBOSE("ringRawsockRelRxFrame: pBuffer=%p, pHdr=%p", pBuffer, pHdr); pHdr->tp_status = TP_STATUS_KERNEL; rawsock->buffersOut -= 1; -- cgit v1.2.1 From 2fadfc06453cdd363c7038e2549a7b210ad5bcae Mon Sep 17 00:00:00 2001 From: Brant Thomsen Date: Tue, 22 Aug 2017 09:18:31 -0600 Subject: IF_LOG_INTERVAL interval count fix. --- daemons/maap/common/maap_log.h | 2 +- daemons/shaper/src/shaper_log.h | 2 +- lib/avtp_pipeline/include/openavb_log_pub.h | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/daemons/maap/common/maap_log.h b/daemons/maap/common/maap_log.h index bb421c7b..eb9ca01f 100644 --- a/daemons/maap/common/maap_log.h +++ b/daemons/maap/common/maap_log.h @@ -166,7 +166,7 @@ typedef enum { #define IF_LOG_ONCE() static uint32_t LOG_VAR(logOnce,__LINE__) = 0; if (!LOG_VAR(logOnce,__LINE__)++) // Log a message at an interval. Usage: IF_LOG_INTERVAL(100) MAAP_LOG_INFO(...) -#define IF_LOG_INTERVAL(x) static uint32_t LOG_VAR(logOnce,__LINE__) = 0; if (!(LOG_VAR(logOnce,__LINE__)++ % (x - 1))) +#define IF_LOG_INTERVAL(x) static uint32_t LOG_VAR(logOnce,__LINE__) = 0; if (!(LOG_VAR(logOnce,__LINE__)++ % (x))) #define ETH_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x" diff --git a/daemons/shaper/src/shaper_log.h b/daemons/shaper/src/shaper_log.h index 6c7d987b..0db3dc36 100644 --- a/daemons/shaper/src/shaper_log.h +++ b/daemons/shaper/src/shaper_log.h @@ -166,7 +166,7 @@ typedef enum { #define IF_LOG_ONCE() static uint32_t LOG_VAR(logOnce,__LINE__) = 0; if (!LOG_VAR(logOnce,__LINE__)++) // Log a message at an interval. Usage: IF_LOG_INTERVAL(100) SHAPER_LOG_INFO(...) -#define IF_LOG_INTERVAL(x) static uint32_t LOG_VAR(logOnce,__LINE__) = 0; if (!(LOG_VAR(logOnce,__LINE__)++ % (x - 1))) +#define IF_LOG_INTERVAL(x) static uint32_t LOG_VAR(logOnce,__LINE__) = 0; if (!(LOG_VAR(logOnce,__LINE__)++ % (x))) #define ETH_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x" diff --git a/lib/avtp_pipeline/include/openavb_log_pub.h b/lib/avtp_pipeline/include/openavb_log_pub.h index 47b0bbbe..846c169e 100644 --- a/lib/avtp_pipeline/include/openavb_log_pub.h +++ b/lib/avtp_pipeline/include/openavb_log_pub.h @@ -164,7 +164,7 @@ typedef enum { #define IF_LOG_ONCE() static U32 LOG_VAR(logOnce,__LINE__) = 0; if (!LOG_VAR(logOnce,__LINE__)++) // Log a message at an interval. Usage: IF_LOG_INTERVAL(100) AVB_LOG_INFO(...) -#define IF_LOG_INTERVAL(x) static U32 LOG_VAR(logOnce,__LINE__) = 0; if (!(LOG_VAR(logOnce,__LINE__)++ % (x - 1))) +#define IF_LOG_INTERVAL(x) static U32 LOG_VAR(logOnce,__LINE__) = 0; if (!(LOG_VAR(logOnce,__LINE__)++ % (x))) #define ETH_FORMAT "%02x:%02x:%02x:%02x:%02x:%02x" -- cgit v1.2.1