From 314abdf97b6eaa70174e0678a41c3adfa79eea47 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ferm=C3=ADn=20Gal=C3=A1n=20M=C3=A1rquez?= Date: Tue, 19 Dec 2023 17:11:21 +0100 Subject: [PATCH] ADD notification payload in INFO log traces --- CHANGES_NEXT_RELEASE | 1 + src/lib/common/logTracing.cpp | 91 +++++++++++++------ src/lib/common/logTracing.h | 9 +- src/lib/ngsiNotify/doNotify.cpp | 6 +- .../log_deprecate_warning.test | 2 +- .../3001_mqtt_alarms/mqtt_alarms_none.test | 9 +- .../mqtt_alarms_raise_and_release.test | 6 +- .../mqtt_alarms_raise_repeat_and_release.test | 6 +- .../log_notifications.test | 31 +++---- 9 files changed, 101 insertions(+), 60 deletions(-) diff --git a/CHANGES_NEXT_RELEASE b/CHANGES_NEXT_RELEASE index 0c8dcd255b..d478714491 100644 --- a/CHANGES_NEXT_RELEASE +++ b/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) diff --git a/src/lib/common/logTracing.cpp b/src/lib/common/logTracing.cpp index 26904d5628..3ecd573bf8 100644 --- a/src/lib/common/logTracing.cpp +++ b/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 - diff --git a/src/lib/common/logTracing.h b/src/lib/common/logTracing.h index 4e3c7aac8c..939e2beb66 100644 --- a/src/lib/common/logTracing.h +++ b/src/lib/common/logTracing.h @@ -32,7 +32,7 @@ /* **************************************************************************** * -* logInfoNotification - rc as int +* logInfoHttpNotification - rc as int */ extern void logInfoHttpNotification ( @@ -40,6 +40,7 @@ extern void logInfoHttpNotification const char* endpoint, const char* verb, const char* resource, + const char* payload, int rc ); @@ -47,7 +48,7 @@ extern void logInfoHttpNotification /* **************************************************************************** * -* logInfoNotification - rc as string +* logInfoHttpNotification - rc as string */ extern void logInfoHttpNotification ( @@ -55,6 +56,7 @@ extern void logInfoHttpNotification 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 ); diff --git a/src/lib/ngsiNotify/doNotify.cpp b/src/lib/ngsiNotify/doNotify.cpp index 7598643047..25f25b384f 100644 --- a/src/lib/ngsiNotify/doNotify.cpp +++ b/src/lib/ngsiNotify/doNotify.cpp @@ -127,11 +127,11 @@ static void doNotifyHttp(SenderThreadParams* params, CURL* curl, SyncQOverflowsubscriptionId.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 diff --git a/test/functionalTest/cases/0000_deprecated_checkings/log_deprecate_warning.test b/test/functionalTest/cases/0000_deprecated_checkings/log_deprecate_warning.test index baf5d43988..a0a0704263 100644 --- a/test/functionalTest/cases/0000_deprecated_checkings/log_deprecate_warning.test +++ b/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 diff --git a/test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_none.test b/test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_none.test index 00ad02a854..35ee20c7c3 100644 --- a/test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_none.test +++ b/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 diff --git a/test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_raise_and_release.test b/test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_raise_and_release.test index 0877eb5d53..f531b4247f 100644 --- a/test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_raise_and_release.test +++ b/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 diff --git a/test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_raise_repeat_and_release.test b/test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_raise_repeat_and_release.test index caf1d9af57..c60bf280d5 100644 --- a/test/functionalTest/cases/3001_mqtt_alarms/mqtt_alarms_raise_repeat_and_release.test +++ b/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 diff --git a/test/functionalTest/cases/3694_logs_improvements/log_notifications.test b/test/functionalTest/cases/3694_logs_improvements/log_notifications.test index 8483b3f495..81a922c5bc 100644 --- a/test/functionalTest/cases/3694_logs_improvements/log_notifications.test +++ b/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)