| /openbmc/bmcweb/ |
| H A D | meson.build | 75e8e218 Thu Nov 30 14:53:46 CST 2023 Myung Bae <myungbae@us.ibm.com> Use MonotonicTimeStamp for bmc log id
/redfish/v1/Managers/bmc/LogServices/Journal/Entries gives the system
journal entries whose ID is based on the realtime timestmap. However,
the system realtime may go backward if the system time is changed either
manually or via NTP.
If that happens, those entries may not found via redfish GET as
`sd_journal_seek_realtime_usec()`[1] may not always work on the entries
which are not sorted in time-order.
This may cause the inconsistency between the content of
`/redfish/v1/Managers/bmc/LogServices/Journal/Entries/`
and /redfish/v1/Managers/bmc/LogServices/Journal/Entries/<bmc_journal_id>`.
For example,
```
sudo journalctl --vacuum-time=1s
<wait for a while to clear up journal>
date -s "<backward-time>"
date -s "<forward-time>"
```
Run redfish journal entries and get each entry id from the output
```
curl -k -X GET https://${bmc}/redfish/v1/Managers/bmc/LogServices/Journal/Entries > rj.out
```
Take some logEntry Id that its time going backward like
```
grep "@odata.id" rj.out
```
Run redfish query for each id, and some of them can't be successful.
```
% curl -k -X GET https://${bmc}/redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701604800002075
{
"error": {
"@Message.ExtendedInfo": [
{
"@odata.type": "#Message.v1_1_1.Message",
"Message": "The requested resource of type LogEntry named '1701604800002075' was not found.",
"MessageArgs": [
"LogEntry",
"1701604800002075"
],
"MessageId": "Base.1.13.0.ResourceNotFound",
"MessageSeverity": "Critical",
"Resolution": "Provide a valid resource identifier and resubmit the request."
}
],
"code": "Base.1.13.0.ResourceNotFound",
"message": "The requested resource of type LogEntry named '1701604800002075' was not found."
}
}%
```
This can also be verified by checking the failure of Redfish Validator run
```
python3 RedfishServiceValidator.py --auth Session -i https://${bmc} -u admin -p 0penBmc0 --payload Tree /redfish/v1/Managers/bmc/LogServices/Journal/Entries
```
For example,
```
ERROR - Members: GET of resource at URI /redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701604800002075 returned HTTP error. Check URI.
ERROR - Members: GET of resource at URI /redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701604800065949 returned HTTP error. Check URI.
ERROR - Members: GET of resource at URI /redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701607680003048 returned HTTP error. Check URI.
```
```
--Time goes backwrd
{
"@odata.id": "/redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701604800002075",
"@odata.type": "#LogEntry.v1_9_0.LogEntry",
"Created": "2023-12-03T12:00:00+00:00",
"EntryType": "Oem",
"Id": "1701604800002075",
"Message": "systemd-resolved: Clock change detected. Flushing caches.",
"Name": "BMC Journal Entry",
"OemRecordFormat": "BMC Journal Entry",
"Severity": "OK"
},
...
{
"@odata.id": "/redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701607680003048",
"@odata.type": "#LogEntry.v1_9_0.LogEntry",
"Created": "2023-12-03T12:48:00+00:00",
"EntryType": "Oem",
"Id": "1701607680003048",
"Message": "systemd-resolved: Clock change detected. Flushing caches.",
"Name": "BMC Journal Entry",
"OemRecordFormat": "BMC Journal Entry",
"Severity": "OK"
},
-- Time comes back to the previous moment
```
The solution is proposed to use <bootid> + <monototic timestamp> as the
redfish journal entry id instead of realtime timestamp.
Unlike realtime timestamp which may go backward, <monotonic timestamp>
is monotonically increasing.
Tested:
- Redfish Validator passes
- GET Journal Entry ID will be found even if its time goes backward.
[1] https://github.com/openbmc/bmcweb/blob/7164bc62dd26ec92b01985aaae97ecc48276dea5/redfish-core/lib/log_services.hpp#L2690
Change-Id: I83bfb1ed88c9cf036f594757aa4a00d2709dd196
Signed-off-by: Myung Bae <myungbae@us.ibm.com>
|
| /openbmc/bmcweb/redfish-core/lib/ |
| H A D | log_services.hpp | 75e8e218 Thu Nov 30 14:53:46 CST 2023 Myung Bae <myungbae@us.ibm.com> Use MonotonicTimeStamp for bmc log id
/redfish/v1/Managers/bmc/LogServices/Journal/Entries gives the system
journal entries whose ID is based on the realtime timestmap. However,
the system realtime may go backward if the system time is changed either
manually or via NTP.
If that happens, those entries may not found via redfish GET as
`sd_journal_seek_realtime_usec()`[1] may not always work on the entries
which are not sorted in time-order.
This may cause the inconsistency between the content of
`/redfish/v1/Managers/bmc/LogServices/Journal/Entries/`
and /redfish/v1/Managers/bmc/LogServices/Journal/Entries/<bmc_journal_id>`.
For example,
```
sudo journalctl --vacuum-time=1s
<wait for a while to clear up journal>
date -s "<backward-time>"
date -s "<forward-time>"
```
Run redfish journal entries and get each entry id from the output
```
curl -k -X GET https://${bmc}/redfish/v1/Managers/bmc/LogServices/Journal/Entries > rj.out
```
Take some logEntry Id that its time going backward like
```
grep "@odata.id" rj.out
```
Run redfish query for each id, and some of them can't be successful.
```
% curl -k -X GET https://${bmc}/redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701604800002075
{
"error": {
"@Message.ExtendedInfo": [
{
"@odata.type": "#Message.v1_1_1.Message",
"Message": "The requested resource of type LogEntry named '1701604800002075' was not found.",
"MessageArgs": [
"LogEntry",
"1701604800002075"
],
"MessageId": "Base.1.13.0.ResourceNotFound",
"MessageSeverity": "Critical",
"Resolution": "Provide a valid resource identifier and resubmit the request."
}
],
"code": "Base.1.13.0.ResourceNotFound",
"message": "The requested resource of type LogEntry named '1701604800002075' was not found."
}
}%
```
This can also be verified by checking the failure of Redfish Validator run
```
python3 RedfishServiceValidator.py --auth Session -i https://${bmc} -u admin -p 0penBmc0 --payload Tree /redfish/v1/Managers/bmc/LogServices/Journal/Entries
```
For example,
```
ERROR - Members: GET of resource at URI /redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701604800002075 returned HTTP error. Check URI.
ERROR - Members: GET of resource at URI /redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701604800065949 returned HTTP error. Check URI.
ERROR - Members: GET of resource at URI /redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701607680003048 returned HTTP error. Check URI.
```
```
--Time goes backwrd
{
"@odata.id": "/redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701604800002075",
"@odata.type": "#LogEntry.v1_9_0.LogEntry",
"Created": "2023-12-03T12:00:00+00:00",
"EntryType": "Oem",
"Id": "1701604800002075",
"Message": "systemd-resolved: Clock change detected. Flushing caches.",
"Name": "BMC Journal Entry",
"OemRecordFormat": "BMC Journal Entry",
"Severity": "OK"
},
...
{
"@odata.id": "/redfish/v1/Managers/bmc/LogServices/Journal/Entries/1701607680003048",
"@odata.type": "#LogEntry.v1_9_0.LogEntry",
"Created": "2023-12-03T12:48:00+00:00",
"EntryType": "Oem",
"Id": "1701607680003048",
"Message": "systemd-resolved: Clock change detected. Flushing caches.",
"Name": "BMC Journal Entry",
"OemRecordFormat": "BMC Journal Entry",
"Severity": "OK"
},
-- Time comes back to the previous moment
```
The solution is proposed to use <bootid> + <monototic timestamp> as the
redfish journal entry id instead of realtime timestamp.
Unlike realtime timestamp which may go backward, <monotonic timestamp>
is monotonically increasing.
Tested:
- Redfish Validator passes
- GET Journal Entry ID will be found even if its time goes backward.
[1] https://github.com/openbmc/bmcweb/blob/7164bc62dd26ec92b01985aaae97ecc48276dea5/redfish-core/lib/log_services.hpp#L2690
Change-Id: I83bfb1ed88c9cf036f594757aa4a00d2709dd196
Signed-off-by: Myung Bae <myungbae@us.ibm.com>
|