[camera] Add low-frequency client state logging
This change adds INFO-level logging for most low-frequency client
methods on the Device and Stream protocol. It also adds a util template
extension for fsl::Get[Related]Koid that accepts any of the fidl library
types that derive from zx::channels.
Bug: b/223483476
Test: ran product scenarios and observed expected log messages
Change-Id: I77bf7633e7f3306b927e64484f6c06c4a85d73e9
Reviewed-on: https://fuchsia-review.googlesource.com/c/fuchsia/+/657593
Reviewed-by: Marcus Jang <marcusjang@google.com>
Reviewed-by: Ernest Hua <ernesthua@google.com>
Commit-Queue: Matt Sandy <msandy@google.com>
diff --git a/src/camera/bin/device/device_impl.cc b/src/camera/bin/device/device_impl.cc
index c3e5223..f83945ec 100644
--- a/src/camera/bin/device/device_impl.cc
+++ b/src/camera/bin/device/device_impl.cc
@@ -233,10 +233,19 @@
void DeviceImpl::UpdateControllerStreamingState() {
if (mute_state_.muted() && controller_streaming_) {
+ std::string detail = "hardware + software";
+ if (!mute_state_.hardware_muted) {
+ detail = "software";
+ }
+ if (!mute_state_.software_muted) {
+ detail = "hardware";
+ }
+ FX_LOGS(INFO) << "disabling streaming because device is muted (" << detail << ")";
controller_->DisableStreaming();
controller_streaming_ = false;
}
if (!mute_state_.muted() && !controller_streaming_) {
+ FX_LOGS(INFO) << "enabling streaming because device is unmuted";
controller_->EnableStreaming();
controller_streaming_ = true;
}
@@ -356,6 +365,10 @@
buffers.buffer_count - configs_[current_configuration_index_]
.stream_configs[index]
.constraints.min_buffer_count_for_camping;
+ FX_LOGS(INFO) << "c" << current_configuration_index_ << "s" << index
+ << ": collection resolved: at most " << max_camping_buffers << " of "
+ << buffers.buffer_count
+ << " buffers will be made available to clients concurrently";
max_camping_buffers_callback(max_camping_buffers);
};
diff --git a/src/camera/bin/device/device_impl.h b/src/camera/bin/device/device_impl.h
index caebff6..0082126 100644
--- a/src/camera/bin/device/device_impl.h
+++ b/src/camera/bin/device/device_impl.h
@@ -128,6 +128,7 @@
void Rebind(fidl::InterfaceRequest<fuchsia::camera3::Device> request) override;
DeviceImpl& device_;
+ std::string log_prefix_;
uint64_t id_;
fidl::Binding<fuchsia::camera3::Device> binding_;
HangingGetHelper<uint32_t> configuration_;
diff --git a/src/camera/bin/device/device_impl_client.cc b/src/camera/bin/device/device_impl_client.cc
index 4fc3e27..3a571a5 100644
--- a/src/camera/bin/device/device_impl_client.cc
+++ b/src/camera/bin/device/device_impl_client.cc
@@ -15,7 +15,8 @@
DeviceImpl::Client::Client(DeviceImpl& device, uint64_t id,
fidl::InterfaceRequest<fuchsia::camera3::Device> request)
: device_(device), id_(id), binding_(this, std::move(request)) {
- FX_LOGS(INFO) << "Device client " << id << " connected.";
+ log_prefix_ = "device client (koid = " + std::to_string(GetRelatedKoid(binding_)) + "): ";
+ FX_LOGS(INFO) << log_prefix_ << "new device client, id = " << id_;
binding_.set_error_handler(fit::bind_member(this, &DeviceImpl::Client::OnClientDisconnected));
}
@@ -26,7 +27,7 @@
void DeviceImpl::Client::MuteUpdated(MuteState mute_state) { mute_state_.Set(mute_state); }
void DeviceImpl::Client::OnClientDisconnected(zx_status_t status) {
- FX_PLOGS(INFO, status) << "Device client " << id_ << " disconnected.";
+ FX_PLOGS(INFO, status) << log_prefix_ << "closed connection";
device_.RemoveClient(id_);
}
@@ -36,6 +37,7 @@
}
void DeviceImpl::Client::GetIdentifier(GetIdentifierCallback callback) {
+ FX_LOGS(INFO) << log_prefix_ << "called GetIdentifier()";
if (!device_.device_info_.has_vendor_id() || !device_.device_info_.has_product_id()) {
callback(cpp17::nullopt);
return;
@@ -49,6 +51,7 @@
}
void DeviceImpl::Client::GetConfigurations(GetConfigurationsCallback callback) {
+ FX_LOGS(INFO) << log_prefix_ << "called GetConfigurations()";
std::vector<fuchsia::camera3::Configuration> configurations;
for (const auto& configuration : device_.configurations_) {
std::vector<fuchsia::camera3::StreamProperties> streams;
@@ -61,16 +64,19 @@
}
void DeviceImpl::Client::GetConfigurations2(GetConfigurations2Callback callback) {
+ FX_LOGS(INFO) << log_prefix_ << "called GetConfigurations2()";
callback(fidl::Clone(device_.configurations_));
}
void DeviceImpl::Client::WatchCurrentConfiguration(WatchCurrentConfigurationCallback callback) {
+ FX_LOGS(INFO) << log_prefix_ << "called WatchCurrentConfiguration()";
if (configuration_.Get(std::move(callback))) {
CloseConnection(ZX_ERR_BAD_STATE);
}
}
void DeviceImpl::Client::SetCurrentConfiguration(uint32_t index) {
+ FX_LOGS(INFO) << log_prefix_ << "called SetCurrentConfiguration(" << index << ")";
if (index < 0 || index >= device_.configurations_.size()) {
CloseConnection(ZX_ERR_OUT_OF_RANGE);
return;
@@ -80,6 +86,7 @@
}
void DeviceImpl::Client::WatchMuteState(WatchMuteStateCallback callback) {
+ FX_LOGS(INFO) << log_prefix_ << "called WatchMuteState()";
if (mute_state_.Get([callback = std::move(callback)](MuteState mute_state) {
callback(mute_state.software_muted, mute_state.hardware_muted);
})) {
@@ -88,6 +95,7 @@
}
void DeviceImpl::Client::SetSoftwareMuteState(bool muted, SetSoftwareMuteStateCallback callback) {
+ FX_LOGS(INFO) << log_prefix_ << "called SetSoftwareMuteState(" << muted << ")";
if (!muted) {
callback();
callback = [] {};
@@ -97,10 +105,12 @@
void DeviceImpl::Client::ConnectToStream(uint32_t index,
fidl::InterfaceRequest<fuchsia::camera3::Stream> request) {
+ FX_LOGS(INFO) << log_prefix_ << "called ConnectToStream(" << index << ")";
device_.ConnectToStream(index, std::move(request));
}
void DeviceImpl::Client::Rebind(fidl::InterfaceRequest<fuchsia::camera3::Device> request) {
+ FX_LOGS(INFO) << log_prefix_ << "called Rebind(koid = " << GetRelatedKoid(request) << ")";
device_.Bind(std::move(request));
}
diff --git a/src/camera/bin/device/stream_impl.h b/src/camera/bin/device/stream_impl.h
index d0f9d886..3422521 100644
--- a/src/camera/bin/device/stream_impl.h
+++ b/src/camera/bin/device/stream_impl.h
@@ -129,6 +129,20 @@
void Rebind(fidl::InterfaceRequest<Stream> request) override;
StreamImpl& stream_;
+ std::string log_prefix_;
+ // Tracking for whether a message has already been logged for the named stage of client
+ // progress. This is used to ensure that only one such message is logged per transition per
+ // client, as they are high-frequency events that would otherwise spam syslog.
+ struct {
+ // The client has called camera3::Stream::GetNextFrame.
+ bool requested = false;
+ // The parent stream has added a frame to this client's available frame queue by calling
+ // AddFrame.
+ bool available = false;
+ // A frame has been sent to the client by invoking the callback provided in a previous call to
+ // GetNextFrame.
+ bool sent = false;
+ } frame_logging_state_;
uint64_t id_;
fidl::Binding<fuchsia::camera3::Stream> binding_;
HangingGetHelper<fidl::InterfaceHandle<fuchsia::sysmem::BufferCollectionToken>> buffers_;
diff --git a/src/camera/bin/device/stream_impl_client.cc b/src/camera/bin/device/stream_impl_client.cc
index 214fc9b..6b0945e 100644
--- a/src/camera/bin/device/stream_impl_client.cc
+++ b/src/camera/bin/device/stream_impl_client.cc
@@ -19,7 +19,9 @@
StreamImpl::Client::Client(StreamImpl& stream, uint64_t id,
fidl::InterfaceRequest<fuchsia::camera3::Stream> request)
: stream_(stream), id_(id), binding_(this, std::move(request)), resolution_(SizeEqual) {
- FX_LOGS(INFO) << stream_.description_ << ": Stream client " << id << " connected.";
+ log_prefix_ = "stream " + stream_.description_ +
+ " client (koid = " + std::to_string(GetRelatedKoid(binding_)) + "): ";
+ FX_LOGS(INFO) << log_prefix_ << "new stream client, id = " << id_;
binding_.set_error_handler(fit::bind_member(this, &StreamImpl::Client::OnClientDisconnected));
}
@@ -28,6 +30,10 @@
void StreamImpl::Client::AddFrame(fuchsia::camera3::FrameInfo2 frame) {
TRACE_DURATION("camera", "StreamImpl::Client::AddFrame");
frames_.push(std::move(frame));
+ if (!frame_logging_state_.available) {
+ FX_LOGS(INFO) << log_prefix_ << "frame available";
+ frame_logging_state_.available = true;
+ }
MaybeSendFrame();
}
@@ -41,6 +47,12 @@
// into the client.
TRACE_FLOW_BEGIN("camera", "camera3::Stream::GetNextFrame",
fsl::GetKoid(frame.release_fence().get()));
+ // Note: this message is logged immediately prior to invoking the frame callback to ensure that no
+ // client logs emitted as a result will have earlier timestamps than this message.
+ if (!frame_logging_state_.sent) {
+ FX_LOGS(INFO) << log_prefix_ << "sent frame";
+ frame_logging_state_.sent = true;
+ }
frame_callback_(std::move(frame));
frames_.pop();
frame_callback_ = nullptr;
@@ -74,7 +86,7 @@
}
void StreamImpl::Client::OnClientDisconnected(zx_status_t status) {
- FX_PLOGS(INFO, status) << stream_.description_ << ": Stream client " << id_ << " disconnected.";
+ FX_PLOGS(INFO, status) << log_prefix_ << "closed connection";
stream_.RemoveClient(id_);
}
@@ -85,11 +97,13 @@
void StreamImpl::Client::GetProperties(GetPropertiesCallback callback) {
TRACE_DURATION("camera", "StreamImpl::Client::GetProperties");
+ FX_LOGS(INFO) << log_prefix_ << "called GetProperties()";
callback(Convert(stream_.properties_));
}
void StreamImpl::Client::GetProperties2(GetProperties2Callback callback) {
TRACE_DURATION("camera", "StreamImpl::Client::GetProperties2");
+ FX_LOGS(INFO) << log_prefix_ << "called GetProperties2()";
callback(fidl::Clone(stream_.properties_));
}
@@ -134,11 +148,14 @@
void StreamImpl::Client::SetBufferCollection(
fidl::InterfaceHandle<fuchsia::sysmem::BufferCollectionToken> token) {
TRACE_DURATION("camera", "StreamImpl::Client::SetBufferCollection");
+ FX_LOGS(INFO) << log_prefix_ << "called SetBufferCollection(koid = " << GetRelatedKoid(token)
+ << ")";
stream_.SetBufferCollection(id_, std::move(token));
}
void StreamImpl::Client::WatchBufferCollection(WatchBufferCollectionCallback callback) {
TRACE_DURATION("camera", "StreamImpl::Client::WatchBufferCollection");
+ FX_LOGS(INFO) << log_prefix_ << "called WatchBufferCollection()";
if (buffers_.Get(std::move(callback))) {
CloseConnection(ZX_ERR_BAD_STATE);
}
@@ -177,6 +194,10 @@
void StreamImpl::Client::GetNextFrame2(GetNextFrame2Callback callback) {
TRACE_DURATION("camera", "StreamImpl::Client::GetNextFrame2");
+ if (!frame_logging_state_.requested) {
+ FX_LOGS(INFO) << log_prefix_ << "called GetNextFrame2()";
+ frame_logging_state_.requested = true;
+ }
if (frame_callback_) {
FX_LOGS(INFO) << stream_.description_ << ": " << id_
<< ": Client called GetNextFrame while a previous call was still pending.";
@@ -188,6 +209,7 @@
}
void StreamImpl::Client::Rebind(fidl::InterfaceRequest<Stream> request) {
+ FX_LOGS(INFO) << log_prefix_ << "called Rebind(koid = " << GetRelatedKoid(request) << ")";
stream_.OnNewRequest(std::move(request));
}
diff --git a/src/camera/bin/device/util.h b/src/camera/bin/device/util.h
index 5a149a0..386a9dfe 100644
--- a/src/camera/bin/device/util.h
+++ b/src/camera/bin/device/util.h
@@ -10,12 +10,19 @@
#include <lib/async/cpp/task.h>
#include <lib/async/cpp/wait.h>
#include <lib/async/default.h>
+#include <lib/fidl/cpp/binding.h>
#include <lib/fidl/cpp/interface_ptr.h>
+#include <lib/fpromise/promise.h>
#include <lib/fpromise/result.h>
#include <lib/syslog/cpp/macros.h>
+#include <lib/trace/event.h>
#include <zircon/status.h>
#include <zircon/types.h>
+#include "src/lib/fsl/handles/object_info.h"
+
+namespace camera {
+
// Safely unbinds a client connection, doing so on the connection's thread if it differs from the
// caller's thread.
template <class T>
@@ -127,4 +134,48 @@
fit::closure signaled_;
};
+template <typename T, typename Enable = void>
+struct IsFidlChannelWrapper : std::false_type {};
+
+template <typename T>
+struct IsFidlChannelWrapper<fidl::InterfaceHandle<T>> : std::true_type {};
+
+template <typename T>
+struct IsFidlChannelWrapper<fidl::InterfacePtr<T>> : std::true_type {};
+
+template <typename T>
+struct IsFidlChannelWrapper<fidl::SynchronousInterfacePtr<T>> : std::true_type {};
+
+template <typename T>
+struct IsFidlChannelWrapper<fidl::InterfaceRequest<T>> : std::true_type {};
+
+template <typename T>
+struct IsFidlChannelWrapper<fidl::Binding<T>> : std::true_type {};
+
+template <typename T>
+inline constexpr bool IsFidlChannelWrapperV = IsFidlChannelWrapper<T>::value;
+
+template <typename T>
+inline zx_handle_t GetFidlChannelHandle(const T& fidl) {
+ static_assert(IsFidlChannelWrapperV<T>, "'fidl' must be one one of the fidl channel wrappers");
+ return fidl.channel().get();
+}
+
+template <typename T>
+inline zx_koid_t GetKoid(const T& fidl) {
+ return fsl::GetKoid(GetFidlChannelHandle(fidl));
+}
+
+template <typename T>
+inline zx_koid_t GetRelatedKoid(const T& fidl) {
+ return fsl::GetRelatedKoid(GetFidlChannelHandle(fidl));
+}
+
+template <typename T>
+inline std::pair<zx_koid_t, zx_koid_t> GetKoids(const T& fidl) {
+ return fsl::GetKoids(GetFidlChannelHandle(fidl));
+}
+
+} // namespace camera
+
#endif // SRC_CAMERA_BIN_DEVICE_UTIL_H_
