Merge pull request #673 from bdthomsen/logging_fixes

Logging fixes

5 files changed, 46 insertions, 28 deletions

diff --git a/daemons/maap/common/maap_log.h b/daemons/maap/common/maap_log.h
index 7d36c1a1..eb9ca01f 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)))
 
 
 #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..0db3dc36 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)))
 
 
 #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 805e2d01..846c169e 100644
--- a/lib/avtp_pipeline/include/openavb_log_pub.h
+++ b/lib/avtp_pipeline/include/openavb_log_pub.h
@@ -160,17 +160,17 @@ 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)))
 
 
 #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
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;