From 1d6a9589dee5c98c09ef2156ea68d800714c0837 Mon Sep 17 00:00:00 2001 From: Boris Zbarsky Date: Tue, 14 Feb 2023 13:22:17 -0500 Subject: [PATCH] Fix timestamps in Diagnostic Logs cluster to follow the spec. (#24830) * Fix timestamps in Diagnostic Logs cluster to follow the spec. There were a few issues here: 1. We were using a monotonic timestamp, but setting the UTCTimeStamp in the response payload. 2. We were using a millisecond timestamp, whereas the spec has microsecond ones. Switch to using "time since server init" for the timestamp, put it in the TimeSinceBoot field, and make sure it has the right units. Also fixes the timestamps to actually be optional, per spec. Fixes https://github.com/project-chip/connectedhomeip/issues/24265 * Address review comment. --- .../log-source-common/log-source-app.matter | 4 +- .../diagnostic-logs-server.cpp | 30 +++++++++------ src/app/server/Server.cpp | 2 + src/app/server/Server.h | 8 ++++ src/app/zap-templates/common/override.js | 1 + .../chip/diagnostic-logs-cluster.xml | 4 +- .../data_model/controller-clusters.matter | 4 +- .../zap-generated/CHIPInvokeCallbacks.cpp | 38 ++++++++++++++----- .../chip/devicecontroller/ChipClusters.java | 6 ++- .../devicecontroller/ClusterInfoMapping.java | 9 +++-- .../python/chip/clusters/Objects.py | 8 ++-- .../CHIP/zap-generated/MTRCallbackBridge.mm | 12 +++++- .../zap-generated/MTRCommandPayloadsObjc.h | 6 +-- .../zap-generated/MTRCommandPayloadsObjc.mm | 8 ++-- .../app-common/zap-generated/callback.h | 4 +- .../zap-generated/cluster-objects.h | 8 ++-- 16 files changed, 102 insertions(+), 50 deletions(-) diff --git a/examples/log-source-app/log-source-common/log-source-app.matter b/examples/log-source-app/log-source-common/log-source-app.matter index 5b4c483a3b8ae3..78a88db578c5e1 100644 --- a/examples/log-source-app/log-source-common/log-source-app.matter +++ b/examples/log-source-app/log-source-common/log-source-app.matter @@ -320,8 +320,8 @@ server cluster DiagnosticLogs = 50 { response struct RetrieveLogsResponse = 1 { LogsStatus status = 0; OCTET_STRING logContent = 1; - epoch_s UTCTimeStamp = 2; - INT32U timeSinceBoot = 3; + optional epoch_us UTCTimeStamp = 2; + optional systime_us timeSinceBoot = 3; } command RetrieveLogsRequest(RetrieveLogsRequestRequest): RetrieveLogsResponse = 0; diff --git a/src/app/clusters/diagnostic-logs-server/diagnostic-logs-server.cpp b/src/app/clusters/diagnostic-logs-server/diagnostic-logs-server.cpp index 1d0db1b975c880..9464d9c355235a 100644 --- a/src/app/clusters/diagnostic-logs-server/diagnostic-logs-server.cpp +++ b/src/app/clusters/diagnostic-logs-server/diagnostic-logs-server.cpp @@ -20,15 +20,20 @@ #include #include #include +#include #include #include +#include #include +// We store our times as millisecond times, to save space. +using TimeInBufferType = chip::System::Clock::Milliseconds32::rep; + CHIP_ERROR DiagnosticLogsCommandHandler::PushLog(const chip::ByteSpan & payload) { - chip::System::Clock::Milliseconds32 now = chip::System::SystemClock().GetMonotonicTimestamp(); - uint32_t timeMs = now.count(); + auto now = std::chrono::duration_cast(chip::Server::GetInstance().TimeSinceInit()); + TimeInBufferType timeMs = now.count(); chip::ByteSpan payloadTime(reinterpret_cast(&timeMs), sizeof(timeMs)); return mBuffer.Push(payloadTime, payload); } @@ -56,12 +61,11 @@ void DiagnosticLogsCommandHandler::InvokeCommand(HandlerContext & handlerContext } size_t logSize = mBuffer.GetFrontSize(); - chip::System::Clock::Milliseconds32::rep timeMs; - VerifyOrDie(logSize > sizeof(timeMs)); + TimeInBufferType timeFromBuffer; + VerifyOrDie(logSize > sizeof(timeFromBuffer)); - std::unique_ptr buf( - reinterpret_cast(chip::Platform::MemoryAlloc(logSize)), &chip::Platform::MemoryFree); - if (!buf) + chip::Platform::ScopedMemoryBuffer buf; + if (!buf.Calloc(logSize)) { response.status = chip::app::Clusters::DiagnosticLogs::LogsStatus::kBusy; handlerContext.mCommandHandler.AddResponse(handlerContext.mRequestPath, response); @@ -69,14 +73,16 @@ void DiagnosticLogsCommandHandler::InvokeCommand(HandlerContext & handlerContext } // The entry is | time (4 bytes) | content (var size) | - chip::MutableByteSpan entry(buf.get(), logSize); + chip::MutableByteSpan entry(buf.Get(), logSize); CHIP_ERROR err = mBuffer.ReadFront(entry); VerifyOrDie(err == CHIP_NO_ERROR); - timeMs = *reinterpret_cast(buf.get()); + memcpy(&timeFromBuffer, buf.Get(), sizeof(timeFromBuffer)); + + auto timestamp = chip::System::Clock::Milliseconds32(timeFromBuffer); - response.status = chip::app::Clusters::DiagnosticLogs::LogsStatus::kSuccess; - response.logContent = chip::ByteSpan(buf.get() + sizeof(timeMs), logSize - sizeof(timeMs)); - response.UTCTimeStamp = timeMs; + response.status = chip::app::Clusters::DiagnosticLogs::LogsStatus::kSuccess; + response.logContent = chip::ByteSpan(buf.Get() + sizeof(timeFromBuffer), logSize - sizeof(timeFromBuffer)); + response.timeSinceBoot.SetValue(chip::System::Clock::Microseconds64(timestamp).count()); handlerContext.mCommandHandler.AddResponse(handlerContext.mRequestPath, response); } break; diff --git a/src/app/server/Server.cpp b/src/app/server/Server.cpp index c3fd69e80817e0..56c02358b0ec97 100644 --- a/src/app/server/Server.cpp +++ b/src/app/server/Server.cpp @@ -108,6 +108,8 @@ CHIP_ERROR Server::Init(const ServerInitParams & initParams) ChipLogProgress(AppServer, "Server initializing..."); assertChipStackLockedByCurrentThread(); + mInitTimestamp = System::SystemClock().GetMonotonicMicroseconds64(); + CASESessionManagerConfig caseSessionManagerConfig; DeviceLayer::DeviceInfoProvider * deviceInfoprovider = nullptr; diff --git a/src/app/server/Server.h b/src/app/server/Server.h index 9318ae71232dc2..638c918cb46ca1 100644 --- a/src/app/server/Server.h +++ b/src/app/server/Server.h @@ -55,6 +55,7 @@ #include #endif #include +#include #include #include #include @@ -369,6 +370,11 @@ class Server void ScheduleFactoryReset(); + System::Clock::Microseconds64 TimeSinceInit() const + { + return System::SystemClock().GetMonotonicMicroseconds64() - mInitTimestamp; + } + static Server & GetInstance() { return sServer; } private: @@ -566,6 +572,8 @@ class Server uint16_t mOperationalServicePort; uint16_t mUserDirectedCommissioningPort; Inet::InterfaceId mInterfaceId; + + System::Clock::Microseconds64 mInitTimestamp; }; } // namespace chip diff --git a/src/app/zap-templates/common/override.js b/src/app/zap-templates/common/override.js index 381db17a5ebae3..57275493fb3764 100644 --- a/src/app/zap-templates/common/override.js +++ b/src/app/zap-templates/common/override.js @@ -71,6 +71,7 @@ function atomicType(arg) case 'percent100ths': return 'chip::Percent100ths'; case 'epoch_us': + case 'systime_us': return 'uint64_t'; case 'epoch_s': case 'utc': diff --git a/src/app/zap-templates/zcl/data-model/chip/diagnostic-logs-cluster.xml b/src/app/zap-templates/zcl/data-model/chip/diagnostic-logs-cluster.xml index 2f5f9874c29c1e..269db2f66573a8 100644 --- a/src/app/zap-templates/zcl/data-model/chip/diagnostic-logs-cluster.xml +++ b/src/app/zap-templates/zcl/data-model/chip/diagnostic-logs-cluster.xml @@ -53,8 +53,8 @@ limitations under the License. Response to the RetrieveLogsRequest - - + + diff --git a/src/controller/data_model/controller-clusters.matter b/src/controller/data_model/controller-clusters.matter index 3b1e0f994f72b4..ac7c8dd5b6b5ad 100644 --- a/src/controller/data_model/controller-clusters.matter +++ b/src/controller/data_model/controller-clusters.matter @@ -1317,8 +1317,8 @@ client cluster DiagnosticLogs = 50 { response struct RetrieveLogsResponse = 1 { LogsStatus status = 0; OCTET_STRING logContent = 1; - epoch_s UTCTimeStamp = 2; - INT32U timeSinceBoot = 3; + optional epoch_us UTCTimeStamp = 2; + optional systime_us timeSinceBoot = 3; } command RetrieveLogsRequest(RetrieveLogsRequestRequest): RetrieveLogsResponse = 0; diff --git a/src/controller/java/zap-generated/CHIPInvokeCallbacks.cpp b/src/controller/java/zap-generated/CHIPInvokeCallbacks.cpp index 3625bafd95a607..a5a30ce1c62a99 100644 --- a/src/controller/java/zap-generated/CHIPInvokeCallbacks.cpp +++ b/src/controller/java/zap-generated/CHIPInvokeCallbacks.cpp @@ -1783,7 +1783,7 @@ void CHIPDiagnosticLogsClusterRetrieveLogsResponseCallback::CallbackFn( VerifyOrReturn(javaCallbackRef != nullptr); err = JniReferences::GetInstance().FindMethod(env, javaCallbackRef, "onSuccess", - "(Ljava/lang/Integer;[BLjava/lang/Long;Ljava/lang/Long;)V", &javaMethod); + "(Ljava/lang/Integer;[BLjava/util/Optional;Ljava/util/Optional;)V", &javaMethod); VerifyOrReturn(err == CHIP_NO_ERROR, ChipLogError(Zcl, "Error invoking Java callback: %s", ErrorStr(err))); jobject Status; @@ -1797,15 +1797,35 @@ void CHIPDiagnosticLogsClusterRetrieveLogsResponseCallback::CallbackFn( reinterpret_cast(dataResponse.logContent.data())); LogContent = LogContentByteArray; jobject UTCTimeStamp; - std::string UTCTimeStampClassName = "java/lang/Long"; - std::string UTCTimeStampCtorSignature = "(J)V"; - chip::JniReferences::GetInstance().CreateBoxedObject(UTCTimeStampClassName.c_str(), UTCTimeStampCtorSignature.c_str(), - dataResponse.UTCTimeStamp, UTCTimeStamp); + if (!dataResponse.UTCTimeStamp.HasValue()) + { + chip::JniReferences::GetInstance().CreateOptional(nullptr, UTCTimeStamp); + } + else + { + jobject UTCTimeStampInsideOptional; + std::string UTCTimeStampInsideOptionalClassName = "java/lang/Long"; + std::string UTCTimeStampInsideOptionalCtorSignature = "(J)V"; + chip::JniReferences::GetInstance().CreateBoxedObject( + UTCTimeStampInsideOptionalClassName.c_str(), UTCTimeStampInsideOptionalCtorSignature.c_str(), + dataResponse.UTCTimeStamp.Value(), UTCTimeStampInsideOptional); + chip::JniReferences::GetInstance().CreateOptional(UTCTimeStampInsideOptional, UTCTimeStamp); + } jobject TimeSinceBoot; - std::string TimeSinceBootClassName = "java/lang/Long"; - std::string TimeSinceBootCtorSignature = "(J)V"; - chip::JniReferences::GetInstance().CreateBoxedObject( - TimeSinceBootClassName.c_str(), TimeSinceBootCtorSignature.c_str(), dataResponse.timeSinceBoot, TimeSinceBoot); + if (!dataResponse.timeSinceBoot.HasValue()) + { + chip::JniReferences::GetInstance().CreateOptional(nullptr, TimeSinceBoot); + } + else + { + jobject TimeSinceBootInsideOptional; + std::string TimeSinceBootInsideOptionalClassName = "java/lang/Long"; + std::string TimeSinceBootInsideOptionalCtorSignature = "(J)V"; + chip::JniReferences::GetInstance().CreateBoxedObject( + TimeSinceBootInsideOptionalClassName.c_str(), TimeSinceBootInsideOptionalCtorSignature.c_str(), + dataResponse.timeSinceBoot.Value(), TimeSinceBootInsideOptional); + chip::JniReferences::GetInstance().CreateOptional(TimeSinceBootInsideOptional, TimeSinceBoot); + } env->CallVoidMethod(javaCallbackRef, javaMethod, Status, LogContent, UTCTimeStamp, TimeSinceBoot); } diff --git a/src/controller/java/zap-generated/chip/devicecontroller/ChipClusters.java b/src/controller/java/zap-generated/chip/devicecontroller/ChipClusters.java index 0db1c9810b95a5..31a068473a3b97 100644 --- a/src/controller/java/zap-generated/chip/devicecontroller/ChipClusters.java +++ b/src/controller/java/zap-generated/chip/devicecontroller/ChipClusters.java @@ -7225,7 +7225,11 @@ private native void retrieveLogsRequest( @Nullable Integer timedInvokeTimeoutMs); public interface RetrieveLogsResponseCallback { - void onSuccess(Integer status, byte[] logContent, Long UTCTimeStamp, Long timeSinceBoot); + void onSuccess( + Integer status, + byte[] logContent, + Optional UTCTimeStamp, + Optional timeSinceBoot); void onError(Exception error); } diff --git a/src/controller/java/zap-generated/chip/devicecontroller/ClusterInfoMapping.java b/src/controller/java/zap-generated/chip/devicecontroller/ClusterInfoMapping.java index aea7e309553ab0..6888762a60590b 100644 --- a/src/controller/java/zap-generated/chip/devicecontroller/ClusterInfoMapping.java +++ b/src/controller/java/zap-generated/chip/devicecontroller/ClusterInfoMapping.java @@ -3223,17 +3223,20 @@ public void setCallbackDelegate(ClusterCommandCallback callback) { @Override public void onSuccess( - Integer Status, byte[] LogContent, Long UTCTimeStamp, Long TimeSinceBoot) { + Integer Status, + byte[] LogContent, + Optional UTCTimeStamp, + Optional TimeSinceBoot) { Map responseValues = new LinkedHashMap<>(); CommandResponseInfo StatusResponseValue = new CommandResponseInfo("Status", "Integer"); responseValues.put(StatusResponseValue, Status); CommandResponseInfo LogContentResponseValue = new CommandResponseInfo("LogContent", "byte[]"); responseValues.put(LogContentResponseValue, LogContent); CommandResponseInfo UTCTimeStampResponseValue = - new CommandResponseInfo("UTCTimeStamp", "Long"); + new CommandResponseInfo("UTCTimeStamp", "Optional"); responseValues.put(UTCTimeStampResponseValue, UTCTimeStamp); CommandResponseInfo TimeSinceBootResponseValue = - new CommandResponseInfo("TimeSinceBoot", "Long"); + new CommandResponseInfo("TimeSinceBoot", "Optional"); responseValues.put(TimeSinceBootResponseValue, TimeSinceBoot); callback.onSuccess(responseValues); } diff --git a/src/controller/python/chip/clusters/Objects.py b/src/controller/python/chip/clusters/Objects.py index ffb731f8636a5a..047f3e07203ce7 100644 --- a/src/controller/python/chip/clusters/Objects.py +++ b/src/controller/python/chip/clusters/Objects.py @@ -7845,14 +7845,14 @@ def descriptor(cls) -> ClusterObjectDescriptor: Fields = [ ClusterObjectFieldDescriptor(Label="status", Tag=0, Type=DiagnosticLogs.Enums.LogsStatus), ClusterObjectFieldDescriptor(Label="logContent", Tag=1, Type=bytes), - ClusterObjectFieldDescriptor(Label="UTCTimeStamp", Tag=2, Type=uint), - ClusterObjectFieldDescriptor(Label="timeSinceBoot", Tag=3, Type=uint), + ClusterObjectFieldDescriptor(Label="UTCTimeStamp", Tag=2, Type=typing.Optional[uint]), + ClusterObjectFieldDescriptor(Label="timeSinceBoot", Tag=3, Type=typing.Optional[uint]), ]) status: 'DiagnosticLogs.Enums.LogsStatus' = 0 logContent: 'bytes' = b"" - UTCTimeStamp: 'uint' = 0 - timeSinceBoot: 'uint' = 0 + UTCTimeStamp: 'typing.Optional[uint]' = None + timeSinceBoot: 'typing.Optional[uint]' = None class Attributes: diff --git a/src/darwin/Framework/CHIP/zap-generated/MTRCallbackBridge.mm b/src/darwin/Framework/CHIP/zap-generated/MTRCallbackBridge.mm index 95dc740322a4b1..a066f49234286b 100644 --- a/src/darwin/Framework/CHIP/zap-generated/MTRCallbackBridge.mm +++ b/src/darwin/Framework/CHIP/zap-generated/MTRCallbackBridge.mm @@ -14388,10 +14388,18 @@ response.logContent = [NSData dataWithBytes:data.logContent.data() length:data.logContent.size()]; } { - response.utcTimeStamp = [NSNumber numberWithUnsignedInt:data.UTCTimeStamp]; + if (data.UTCTimeStamp.HasValue()) { + response.utcTimeStamp = [NSNumber numberWithUnsignedLongLong:data.UTCTimeStamp.Value()]; + } else { + response.utcTimeStamp = nil; + } } { - response.timeSinceBoot = [NSNumber numberWithUnsignedInt:data.timeSinceBoot]; + if (data.timeSinceBoot.HasValue()) { + response.timeSinceBoot = [NSNumber numberWithUnsignedLongLong:data.timeSinceBoot.Value()]; + } else { + response.timeSinceBoot = nil; + } } DispatchSuccess(context, response); }; diff --git a/src/darwin/Framework/CHIP/zap-generated/MTRCommandPayloadsObjc.h b/src/darwin/Framework/CHIP/zap-generated/MTRCommandPayloadsObjc.h index cde5e7183900ac..a79680b794a088 100644 --- a/src/darwin/Framework/CHIP/zap-generated/MTRCommandPayloadsObjc.h +++ b/src/darwin/Framework/CHIP/zap-generated/MTRCommandPayloadsObjc.h @@ -2837,9 +2837,9 @@ API_AVAILABLE(ios(16.1), macos(13.0), watchos(9.1), tvos(16.1)) @property (nonatomic, copy) NSData * _Nonnull logContent API_AVAILABLE(ios(16.4), macos(13.3), watchos(9.4), tvos(16.4)); -@property (nonatomic, copy) NSNumber * _Nonnull utcTimeStamp API_AVAILABLE(ios(16.4), macos(13.3), watchos(9.4), tvos(16.4)); +@property (nonatomic, copy) NSNumber * _Nullable utcTimeStamp API_AVAILABLE(ios(16.4), macos(13.3), watchos(9.4), tvos(16.4)); -@property (nonatomic, copy) NSNumber * _Nonnull timeSinceBoot API_AVAILABLE(ios(16.1), macos(13.0), watchos(9.1), tvos(16.1)); +@property (nonatomic, copy) NSNumber * _Nullable timeSinceBoot API_AVAILABLE(ios(16.1), macos(13.0), watchos(9.1), tvos(16.1)); /** * Controls whether the command is a timed command (using Timed Invoke). * @@ -2864,7 +2864,7 @@ API_AVAILABLE(ios(16.1), macos(13.0), watchos(9.1), tvos(16.1)) @property (nonatomic, copy) NSData * _Nonnull content API_DEPRECATED( "Please use logContent", ios(16.1, 16.4), macos(13.0, 13.3), watchos(9.1, 9.4), tvos(16.1, 16.4)); -@property (nonatomic, copy) NSNumber * _Nonnull timeStamp API_DEPRECATED( +@property (nonatomic, copy) NSNumber * _Nullable timeStamp API_DEPRECATED( "Please use utcTimeStamp", ios(16.1, 16.4), macos(13.0, 13.3), watchos(9.1, 9.4), tvos(16.1, 16.4)); @end diff --git a/src/darwin/Framework/CHIP/zap-generated/MTRCommandPayloadsObjc.mm b/src/darwin/Framework/CHIP/zap-generated/MTRCommandPayloadsObjc.mm index afc4fd9d807ac7..8012d6a3ea9dee 100644 --- a/src/darwin/Framework/CHIP/zap-generated/MTRCommandPayloadsObjc.mm +++ b/src/darwin/Framework/CHIP/zap-generated/MTRCommandPayloadsObjc.mm @@ -3484,9 +3484,9 @@ - (instancetype)init _logContent = [NSData data]; - _utcTimeStamp = @(0); + _utcTimeStamp = nil; - _timeSinceBoot = @(0); + _timeSinceBoot = nil; _timedInvokeTimeoutMs = nil; } return self; @@ -3527,12 +3527,12 @@ - (NSData * _Nonnull)content return self.logContent; } -- (void)setTimeStamp:(NSNumber * _Nonnull)timeStamp +- (void)setTimeStamp:(NSNumber * _Nullable)timeStamp { self.utcTimeStamp = timeStamp; } -- (NSNumber * _Nonnull)timeStamp +- (NSNumber * _Nullable)timeStamp { return self.utcTimeStamp; } diff --git a/zzz_generated/app-common/app-common/zap-generated/callback.h b/zzz_generated/app-common/app-common/zap-generated/callback.h index 4f8e3743198027..3abc23c2ed8cde 100644 --- a/zzz_generated/app-common/app-common/zap-generated/callback.h +++ b/zzz_generated/app-common/app-common/zap-generated/callback.h @@ -8042,8 +8042,8 @@ bool emberAfDiagnosticLogsClusterRetrieveLogsRequestCallback( * @brief Diagnostic Logs Cluster RetrieveLogsResponse Command callback (from server) */ bool emberAfDiagnosticLogsClusterRetrieveLogsResponseCallback(chip::EndpointId endpoint, chip::app::CommandSender * commandObj, - uint8_t Status, chip::ByteSpan LogContent, uint32_t UTCTimeStamp, - uint32_t TimeSinceBoot); + uint8_t Status, chip::ByteSpan LogContent, uint64_t UTCTimeStamp, + uint64_t TimeSinceBoot); /** * @brief General Diagnostics Cluster TestEventTrigger Command callback (from client) */ diff --git a/zzz_generated/app-common/app-common/zap-generated/cluster-objects.h b/zzz_generated/app-common/app-common/zap-generated/cluster-objects.h index 29d35c573d02e5..f227922c8ac748 100644 --- a/zzz_generated/app-common/app-common/zap-generated/cluster-objects.h +++ b/zzz_generated/app-common/app-common/zap-generated/cluster-objects.h @@ -7774,8 +7774,8 @@ struct Type LogsStatus status = static_cast(0); chip::ByteSpan logContent; - uint32_t UTCTimeStamp = static_cast(0); - uint32_t timeSinceBoot = static_cast(0); + Optional UTCTimeStamp; + Optional timeSinceBoot; CHIP_ERROR Encode(TLV::TLVWriter & writer, TLV::Tag tag) const; @@ -7792,8 +7792,8 @@ struct DecodableType LogsStatus status = static_cast(0); chip::ByteSpan logContent; - uint32_t UTCTimeStamp = static_cast(0); - uint32_t timeSinceBoot = static_cast(0); + Optional UTCTimeStamp; + Optional timeSinceBoot; CHIP_ERROR Decode(TLV::TLVReader & reader); }; }; // namespace RetrieveLogsResponse