Improve subscriptions logging
If the event is not sent to the destination it
was supposed to be sent to, it's hard to find
out why it was not sent, and what was the message
content the code was working with. Having additional
logging (mostly debug) helps with troubleshooting.
Tested:
Built an image with these changes, ran in QEMU,
enabled debug logging, setup subscription:
```
{
"@odata.id": "/redfish/v1/EventService/Subscriptions/3489160873",
"@odata.type": "#EventDestination.v1_14_1.EventDestination",
"Context": "127.0.0.1",
"DeliveryRetryPolicy": "RetryForever",
"Destination": "http://127.0.0.1:8888/events",
"EventFormatType": "Event",
"HeartbeatIntervalMinutes": 10,
"HttpHeaders": [],
"Id": "3489160873",
"MessageIds": [],
"MetricReportDefinitions": [],
"Name": "Event Destination 3489160873",
"Protocol": "Redfish",
"RegistryPrefixes": [],
"ResourceTypes": [],
"SendHeartbeat": false,
"SubscriptionType": "RedfishEvent",
"VerifyCertificate": true
}
```
and sent a message:
```
root@bmc:~# busctl call xyz.openbmc_project.Logging \
/xyz/openbmc_project/logging \
xyz.openbmc_project.Logging.Create \
Create 'ssa{ss}' \
OpenBMC.0.1.PowerButtonPressed \
xyz.openbmc_project.Logging.Entry.Level.Error 0
o "/xyz/openbmc_project/logging/entry/16"
```
Got this in the log:
```
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG dbus_log_watcher.cpp:65]
Handling new DBus Event Log Entry
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG dbus_log_watcher.cpp:74] Found
dbus interface org.freedesktop.DBus.Peer
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG dbus_log_watcher.cpp:74] Found
dbus interface org.freedesktop.DBus.Introspectable
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG dbus_log_watcher.cpp:74] Found
dbus interface org.freedesktop.DBus.Properties
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG dbus_log_watcher.cpp:74] Found
dbus interface xyz.openbmc_project.Common.FilePath
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG dbus_log_watcher.cpp:74] Found
dbus interface xyz.openbmc_project.Software.Version
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG dbus_log_watcher.cpp:74] Found
dbus interface xyz.openbmc_project.Association.Definitions
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG dbus_log_watcher.cpp:74] Found
dbus interface xyz.openbmc_project.Object.Delete
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG dbus_log_watcher.cpp:74] Found
dbus interface xyz.openbmc_project.Logging.Entry
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG dbus_log_watcher.cpp:59] Found
Event Log Entry Id=16, Timestamp=, Message=
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG subscription.cpp:283]
Processing logEntry: 16, ''
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG event_log.cpp:134]
formatEventLogEntry: could not find messageID '' for log entry 16 in
registry
Jan 13 04:13:13 bmc bmcwebd[823]: [WARNING subscription.cpp:292] Read
eventLog entry failed
Jan 13 04:13:13 bmc bmcwebd[823]: [DEBUG subscription.cpp:317] No log
entries available to be transferred.
```
Change-Id: I5cc8d48a0258f2419a7bd4f726f185abbd628110
Signed-off-by: Igor Kanyuka <ifelmail@gmail.com>
diff --git a/redfish-core/src/event_log.cpp b/redfish-core/src/event_log.cpp
index cada5b7..d7cd2f2 100644
--- a/redfish-core/src/event_log.cpp
+++ b/redfish-core/src/event_log.cpp
@@ -130,6 +130,9 @@
if (message == nullptr)
{
+ BMCWEB_LOG_DEBUG(
+ "{}: could not find messageID '{}' for log entry {} in registry",
+ __func__, messageID, logEntryID);
return -1;
}
@@ -137,6 +140,8 @@
redfish::registries::fillMessageArgs(messageArgs, message->message);
if (msg.empty())
{
+ BMCWEB_LOG_DEBUG("{}: message is empty after filling fillMessageArgs",
+ __func__);
return -1;
}
diff --git a/redfish-core/src/subscription.cpp b/redfish-core/src/subscription.cpp
index 5f4bf0f..1ca8a5e 100644
--- a/redfish-core/src/subscription.cpp
+++ b/redfish-core/src/subscription.cpp
@@ -281,6 +281,8 @@
nlohmann::json::array_t logEntryArray;
for (const EventLogObjectsType& logEntry : eventRecords)
{
+ BMCWEB_LOG_DEBUG("Processing logEntry: {}, {} '{}'", logEntry.id,
+ logEntry.timestamp, logEntry.messageId);
std::vector<std::string_view> messageArgsView(
logEntry.messageArgs.begin(), logEntry.messageArgs.end());
@@ -289,7 +291,7 @@
logEntry.id, logEntry.messageId, messageArgsView,
logEntry.timestamp, userSub->customText, bmcLogEntry) != 0)
{
- BMCWEB_LOG_DEBUG("Read eventLog entry failed");
+ BMCWEB_LOG_WARNING("Read eventLog entry failed");
continue;
}