ADD notification payload in INFO log traces

CHANGES_NEXT_RELEASE

@@ -1,5 +1,6 @@
 - Add: servicePath field to builtin attributes (#2877)
 - Add: notification.mqtt.retain and notification.mqttCustom.retain flag for MQTT retain in notifications (#4388)
+- Add: notification payload in INFO log traces (#4449)
 - Fix: correctly detect JSON attribute and metadata value changes in subscription triggering logic (#4211, #4434, #643)
 - Fix: DateTime and geo:json types were not supported in custom notifications using ngsi patching (#4435)
 - Fix: logDeprecate not working correctly (`geo:json` wrongly considered as deprecated)

src/lib/common/logTracing.cpp

@@ -42,6 +42,28 @@ inline bool isNgsiV1Url(const char* url)
 
 
 
+/* ****************************************************************************
+*
+* truncatePayload -
+*
+* NOTE: this function allocated dynamic memory, be careful with memory leaks!
+*/
+static char* truncatePayload(const char* payload)
+{
+  // +5 due to "(...)"
+  // +1 due to '\0'
+  unsigned int truncatedPayloadLengh = logInfoPayloadMaxSize + 5 + 1;
+
+  char* truncatedPayload = (char*) malloc(logInfoPayloadMaxSize + 5 + 1);
+  strncpy(truncatedPayload, payload, logInfoPayloadMaxSize);
+  strncpy(truncatedPayload + logInfoPayloadMaxSize, "(...)", 5);
+  truncatedPayload[truncatedPayloadLengh - 1] = '\0';
+
+  return truncatedPayload;
+}
+
+
+
 /* ****************************************************************************
 *
 * logInfoNotification - rc as int
@@ -52,12 +74,13 @@ void logInfoHttpNotification
   const char*  endpoint,
   const char*  verb,
   const char*  resource,
+  const char*  payload,
   int          rc
 )
 {
   char buffer[STRING_SIZE_FOR_INT];
   snprintf(buffer, sizeof(buffer), "%d", rc);
-  logInfoHttpNotification(subId, endpoint, verb, resource, buffer);
+  logInfoHttpNotification(subId, endpoint, verb, resource, payload, buffer);
 }
 
 
@@ -72,10 +95,29 @@ void logInfoHttpNotification
   const char*  endpoint,
   const char*  verb,
   const char*  resource,
+  const char*  payload,
   const char*  rc
 )
 {
-  LM_I(("Notif delivered (subId: %s): %s %s%s, response code: %s", subId, verb, endpoint, resource, rc));
+  bool cleanAfterUse = false;
+  char* effectivePayload;
+
+  if (strlen(payload) > logInfoPayloadMaxSize)
+  {
+    effectivePayload = truncatePayload(payload);
+    cleanAfterUse = true;
+  }
+  else
+  {
+    effectivePayload = (char*) payload;
+  }
+
+  LM_I(("Notif delivered (subId: %s): %s %s%s, payload (%d bytes): %s, response code: %s", subId, verb, endpoint, resource, strlen(payload), effectivePayload, rc));
+
+  if (cleanAfterUse)
+  {
+    free(effectivePayload);
+  }
 }
 
 
@@ -88,10 +130,29 @@ void logInfoMqttNotification
 (
   const char*  subId,
   const char*  endpoint,
-  const char*  resource
+  const char*  resource,
+  const char*  payload
 )
 {
-  LM_I(("MQTT Notif delivered (subId: %s): broker: %s, topic: %s", subId, endpoint, resource));
+  bool cleanAfterUse = false;
+  char* effectivePayload;
+
+  if (strlen(payload) > logInfoPayloadMaxSize)
+  {
+    effectivePayload = truncatePayload(payload);
+    cleanAfterUse = true;
+  }
+  else
+  {
+    effectivePayload = (char*) payload;
+  }
+
+  LM_I(("MQTT Notif delivered (subId: %s): broker: %s, topic: %s, payload (%d bytes): %s", subId, endpoint, resource, strlen(payload), effectivePayload));
+
+  if (cleanAfterUse)
+  {
+    free(effectivePayload);
+  }
 }
 
 
@@ -117,28 +178,6 @@ void logInfoRequestWithoutPayload
 
 
 
-/* ****************************************************************************
-*
-* truncatePayload -
-*
-* NOTE: this function allocated dynamic memory, be careful with memory leaks!
-*/
-static char* truncatePayload(const char* payload)
-{
-  // +5 due to "(...)"
-  // +1 due to '\0'
-  unsigned int truncatedPayloadLengh = logInfoPayloadMaxSize + 5 + 1;
-
-  char* truncatedPayload = (char*) malloc(logInfoPayloadMaxSize + 5 + 1);
-  strncpy(truncatedPayload, payload, logInfoPayloadMaxSize);
-  strncpy(truncatedPayload + logInfoPayloadMaxSize, "(...)", 5);
-  truncatedPayload[truncatedPayloadLengh - 1] = '\0';
-
-  return truncatedPayload;
-}
-
-
-
 /* ****************************************************************************
 *
 * logInfoRequestWithPayload -

src/lib/common/logTracing.h

@@ -32,29 +32,31 @@
 
 /* ****************************************************************************
 *
-* logInfoNotification - rc as int
+* logInfoHttpNotification - rc as int
 */
 extern void logInfoHttpNotification
 (
   const char*  subId,
   const char*  endpoint,
   const char*  verb,
   const char*  resource,
+  const char*  payload,
   int          rc
 );
 
 
 
 /* ****************************************************************************
 *
-* logInfoNotification - rc as string
+* logInfoHttpNotification - rc as string
 */
 extern void logInfoHttpNotification
 (
   const char*  subId,
   const char*  endpoint,
   const char*  verb,
   const char*  resource,
+  const char*  payload,
   const char*  rc
 );
 
@@ -68,7 +70,8 @@ extern void logInfoMqttNotification
 (
   const char*  subId,
   const char*  endpoint,
-  const char*  resource
+  const char*  resource,
+  const char*  payload
 );
 
 

src/lib/ngsiNotify/doNotify.cpp

@@ -127,11 +127,11 @@ static void doNotifyHttp(SenderThreadParams* params, CURL* curl, SyncQOverflow<S
   // Add notificacion result summary in log INFO level
   if (statusCode != -1)
   {
-    logInfoHttpNotification(params->subscriptionId.c_str(), endpoint.c_str(), params->verb.c_str(), params->resource.c_str(), statusCode);
+    logInfoHttpNotification(params->subscriptionId.c_str(), endpoint.c_str(), params->verb.c_str(), params->resource.c_str(), params->content.c_str(), statusCode);
   }
   else
   {
-    logInfoHttpNotification(params->subscriptionId.c_str(), endpoint.c_str(), params->verb.c_str(), params->resource.c_str(), out.c_str());
+    logInfoHttpNotification(params->subscriptionId.c_str(), endpoint.c_str(), params->verb.c_str(), params->resource.c_str(), params->content.c_str(), out.c_str());
   }
 }
 
@@ -164,7 +164,7 @@ static void doNotifyMqtt(SenderThreadParams* params)
     // mqttOnPublishCallback is called (by the moment we are not doing nothing there, just printing in
     // DEBUG log level). Note however that even if mqttOnPublishCallback() is called there is no actual
     // guarantee if MQTT QoS is 0
-    logInfoMqttNotification(params->subscriptionId.c_str(), endpoint.c_str(), params->resource.c_str());
+    logInfoMqttNotification(params->subscriptionId.c_str(), endpoint.c_str(), params->resource.c_str(), params->content.c_str());
     subNotificationErrorStatus(params->tenant, params->subscriptionId, false, -1, "");
   }
   else

test/functionalTest/cases/0000_deprecated_checkings/log_deprecate_warning.test

@@ -31,7 +31,7 @@ brokerStart CB 0 IPV4 -logDeprecate
 
 #
 # 01. Query E1-T1
-# 02. GET /v1/contextEntities/E
+# 02. GET /v1/contextEntities/E/attributes/A
 # 03. Create entity using NGSIv1 metadata location
 # 04. Create entity using NGSIv1 and geo:point
 # 05. Create entity using NGSIv2 and geo:point

test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_none.test

@@ -61,6 +61,7 @@ orionCurl --url /v2/subscriptions --payload "$payload"
 echo
 echo
 
+SUB_ID=$(echo "$_responseHeaders" | grep Location | awk -F/ '{ print $4 }' | tr -d "\r\n")
 
 echo "02. Upsert three times to trigger three MQTT notifications"
 echo "=========================================================="
@@ -85,7 +86,7 @@ echo
 
 echo "03. Check logs and see three MQTT notifications and no alarms"
 echo "============================================================="
-cat /tmp/contextBroker.log | grep -v 'corr=N/A' | awk -F 'msg=' '{print $2}'
+cat /tmp/contextBroker.log | grep -v 'corr=N/A' | awk -F 'msg=' '{print $2}' | sed -e "s/$SUB_ID/SUB_ID/g"
 echo
 echo
 
@@ -129,11 +130,11 @@ Location: /v2/entities/E?type=T
 #SORT_START
 Request received: POST /v2/subscriptions, request payload (142 bytes): { "subject": { "entities": [ { "id": "E", "type": "T" } ] }, "notification": { "mqtt": { "url": "mqtt://localhost:1883", "topic": "sub1" } } }, response code: 201
 Request received: POST /v2/entities?options=forcedUpdate,upsert, request payload (64 bytes): { "id": "E", "type": "T", "A": { "value": 1, "type": "Float" } }, response code: 204
-MQTT Notif delivered REGEX(.*): broker: localhost:1883, topic: sub1
+MQTT Notif delivered (subId: SUB_ID): broker: localhost:1883, topic: sub1, payload (121 bytes): {"subscriptionId":"SUB_ID","data":[{"id":"E","type":"T","A":{"type":"Float","value":1,"metadata":{}}}]}
 Request received: POST /v2/entities?options=forcedUpdate,upsert, request payload (64 bytes): { "id": "E", "type": "T", "A": { "value": 1, "type": "Float" } }, response code: 204
-MQTT Notif delivered REGEX(.*): broker: localhost:1883, topic: sub1
+MQTT Notif delivered (subId: SUB_ID): broker: localhost:1883, topic: sub1, payload (121 bytes): {"subscriptionId":"SUB_ID","data":[{"id":"E","type":"T","A":{"type":"Float","value":1,"metadata":{}}}]}
 Request received: POST /v2/entities?options=forcedUpdate,upsert, request payload (64 bytes): { "id": "E", "type": "T", "A": { "value": 1, "type": "Float" } }, response code: 204
-MQTT Notif delivered REGEX(.*): broker: localhost:1883, topic: sub1
+MQTT Notif delivered (subId: SUB_ID): broker: localhost:1883, topic: sub1, payload (121 bytes): {"subscriptionId":"SUB_ID","data":[{"id":"E","type":"T","A":{"type":"Float","value":1,"metadata":{}}}]}
 #SORT_END
 
 

test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_raise_and_release.test

@@ -162,7 +162,7 @@ echo
 
 echo "09. Check logs and see 1 raised alarm and 1 released alarm"
 echo "=========================================================="
-cat /tmp/contextBroker.log | grep -v 'corr=N/A' | awk -F 'msg=' '{print $2}'
+cat /tmp/contextBroker.log | grep -v 'corr=N/A' | awk -F 'msg=' '{print $2}' | sed -e "s/$SUB_ID/SUB_ID/g"
 echo
 echo
 
@@ -360,10 +360,10 @@ Raising alarm MqttConnectionError mqtt.flespi.io:1883: Connection Refused: bad u
 Request received: GET /v2/subscriptions, response code: 200
 Request received: POST /v2/entities?options=forcedUpdate,upsert, request payload (64 bytes): { "id": "E", "type": "T", "A": { "value": 1, "type": "Float" } }, response code: 204
 Request received: GET /v2/subscriptions, response code: 200
-Request received: PATCH /v2/subscriptions/REGEX(.*): { "notification": { "mqtt": { "url": "mqtt://mqtt.flespi.io:1883", "user": "SeY7oD5XPa1UENBiOLPHqWXmj4r4OZHu4tsgWn1AmTkQuMW6lCDCmqMvi1oURVfJ", "passwd": "xxxx", "topic": "sub1" } } }, response code: 204
+Request received: PATCH /v2/subscriptions/SUB_ID, request payload (182 bytes): { "notification": { "mqtt": { "url": "mqtt://mqtt.flespi.io:1883", "user": "SeY7oD5XPa1UENBiOLPHqWXmj4r4OZHu4tsgWn1AmTkQuMW6lCDCmqMvi1oURVfJ", "passwd": "xxxx", "topic": "sub1" } } }, response code: 204
 Request received: POST /v2/entities?options=forcedUpdate,upsert, request payload (64 bytes): { "id": "E", "type": "T", "A": { "value": 1, "type": "Float" } }, response code: 204
 Releasing alarm MqttConnectionError mqtt.flespi.io:1883
-MQTT Notif delivered REGEX(.*): broker: mqtt.flespi.io:1883, topic: sub1
+MQTT Notif delivered (subId: SUB_ID): broker: mqtt.flespi.io:1883, topic: sub1, payload (121 bytes): {"subscriptionId":"SUB_ID","data":[{"id":"E","type":"T","A":{"type":"Float","value":1,"metadata":{}}}]}
 Request received: GET /v2/subscriptions, response code: 200
 #SORT_END
 

test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_raise_repeat_and_release.test

@@ -162,7 +162,7 @@ echo
 
 echo "09. Check logs and see 1 raised alarm, 1 repeat alarm and 1 released alarm"
 echo "=========================================================================="
-cat /tmp/contextBroker.log | grep -v 'corr=N/A' | awk -F 'msg=' '{print $2}'
+cat /tmp/contextBroker.log | grep -v 'corr=N/A' | awk -F 'msg=' '{print $2}' | sed -e "s/$SUB_ID/SUB_ID/g"
 echo
 echo
 
@@ -361,10 +361,10 @@ Request received: GET /v2/subscriptions, response code: 200
 Request received: POST /v2/entities?options=forcedUpdate,upsert, request payload (64 bytes): { "id": "E", "type": "T", "A": { "value": 1, "type": "Float" } }, response code: 204
 Request received: GET /v2/subscriptions, response code: 200
 Repeated MqttConnectionError mqtt.flespi.io:1883: Connection Refused: bad user name or password.
-Request received: PATCH /v2/subscriptions/REGEX(.*): { "notification": { "mqtt": { "url": "mqtt://mqtt.flespi.io:1883", "user": "SeY7oD5XPa1UENBiOLPHqWXmj4r4OZHu4tsgWn1AmTkQuMW6lCDCmqMvi1oURVfJ", "passwd": "xxxx", "topic": "sub1" } } }, response code: 204
+Request received: PATCH /v2/subscriptions/SUB_ID, request payload (182 bytes): { "notification": { "mqtt": { "url": "mqtt://mqtt.flespi.io:1883", "user": "SeY7oD5XPa1UENBiOLPHqWXmj4r4OZHu4tsgWn1AmTkQuMW6lCDCmqMvi1oURVfJ", "passwd": "xxxx", "topic": "sub1" } } }, response code: 204
 Request received: POST /v2/entities?options=forcedUpdate,upsert, request payload (64 bytes): { "id": "E", "type": "T", "A": { "value": 1, "type": "Float" } }, response code: 204
 Releasing alarm MqttConnectionError mqtt.flespi.io:1883
-MQTT Notif delivered REGEX(.*): broker: mqtt.flespi.io:1883, topic: sub1
+MQTT Notif delivered (subId: SUB_ID): broker: mqtt.flespi.io:1883, topic: sub1, payload (121 bytes): {"subscriptionId":"SUB_ID","data":[{"id":"E","type":"T","A":{"type":"Float","value":1,"metadata":{}}}]}
 Request received: GET /v2/subscriptions, response code: 200
 #SORT_END
 

test/functionalTest/cases/3694_logs_improvements/log_notifications.test

@@ -35,7 +35,7 @@ accumulatorStart --pretty-print localhost $LISTENER_PORT
 # 02. Create subscription SUB2 for E (to nowhere)
 # 03. Create E entity (triggering 2 notifications)
 # 04. POST /v2/op/update updating twice E (triggering 4 notifications)
-# 05. Check notification logs (sorted by url)
+# 05. Check notification logs (sorted by sub id)
 # 06. Check notification correlators (two blocks, corresponding to each update)
 #
 
@@ -61,6 +61,7 @@ orionCurl --url /v2/subscriptions --payload "$payload"
 echo
 echo
 
+SUB_ID1=$(echo "$_responseHeaders" | grep Location | awk -F/ '{ print $4 }' | tr -d "\r\n")
 
 echo "02. Create subscription SUB2 for E (to nowhere)"
 echo "==============================================="
@@ -83,6 +84,7 @@ orionCurl --url /v2/subscriptions --payload "$payload"
 echo
 echo
 
+SUB_ID2=$(echo "$_responseHeaders" | grep Location | awk -F/ '{ print $4 }' | tr -d "\r\n")
 
 echo "03. Create E entity (triggering 2 notifications)"
 echo "================================================"
@@ -130,14 +132,9 @@ echo
 echo
 
 
-# Example log trace for notifications (to help understanding the awk/cut stuff :)
-#
-# msg=Notif delivered (subId: 5f904fb3e970f217bde75f98): POST localhost:9997/notify, response code: 200
-
-
-echo "05. Check notification logs (sorted by url)"
-echo "==========================================="
-cat /tmp/contextBroker.log | grep INFO | grep 'Notif' | awk -F '|' '{print $10}' | cut -c 57- | sort
+echo "05. Check notification logs (sorted by sub id)"
+echo "=============================================="
+cat /tmp/contextBroker.log | grep INFO | grep 'Notif' | awk -F '|' '{print $10}' | sed -e "s/$SUB_ID1/SUB_ID1/g" | sed -e "s/$SUB_ID2/SUB_ID2/g" | sort
 echo
 echo
 
@@ -188,14 +185,14 @@ Fiware-Correlator: REGEX([0-9a-f\-]{36})
 
 
 
-05. Check notification logs (sorted by url)
-===========================================
-POST localhost:12345/notify, response code: Couldn't connect to server
-POST localhost:12345/notify, response code: Couldn't connect to server
-POST localhost:12345/notify, response code: Couldn't connect to server
-POST localhost:9997/notify, response code: 200
-POST localhost:9997/notify, response code: 200
-POST localhost:9997/notify, response code: 200
+05. Check notification logs (sorted by sub id)
+==============================================
+ msg=Notif delivered (subId: SUB_ID1): POST localhost:9997/notify, payload (125 bytes): {"subscriptionId":"SUB_ID1","data":[{"id":"E","type":"T","A1":{"type":"Text","value":"foo","metadata":{}}}]}, response code: 200
+ msg=Notif delivered (subId: SUB_ID1): POST localhost:9997/notify, payload (173 bytes): {"subscriptionId":"SUB_ID1","data":[{"id":"E","type":"T","A":{"type":"Text","value":"foo","metadata":{}},"A1":{"type":"Text","value":"foo","metadata":{}}}]}, response code: 200
+ msg=Notif delivered (subId: SUB_ID1): POST localhost:9997/notify, payload (173 bytes): {"subscriptionId":"SUB_ID1","data":[{"id":"E","type":"T","A1":{"type":"Text","value":"foo","metadata":{}},"A":{"type":"Text","value":"foo","metadata":{}}}]}, response code: 200
+ msg=Notif delivered (subId: SUB_ID2): POST localhost:12345/notify, payload (125 bytes): {"subscriptionId":"SUB_ID2","data":[{"id":"E","type":"T","A1":{"type":"Text","value":"foo","metadata":{}}}]}, response code: Couldn't connect to server
+ msg=Notif delivered (subId: SUB_ID2): POST localhost:12345/notify, payload (173 bytes): {"subscriptionId":"SUB_ID2","data":[{"id":"E","type":"T","A":{"type":"Text","value":"foo","metadata":{}},"A1":{"type":"Text","value":"foo","metadata":{}}}]}, response code: Couldn't connect to server
+ msg=Notif delivered (subId: SUB_ID2): POST localhost:12345/notify, payload (173 bytes): {"subscriptionId":"SUB_ID2","data":[{"id":"E","type":"T","A1":{"type":"Text","value":"foo","metadata":{}},"A":{"type":"Text","value":"foo","metadata":{}}}]}, response code: Couldn't connect to server
 
 
 06. Check notification correlators (two blocks, corresponding to each update)