From 7908809a96518396fd6bbb8bd021889d432675dd Mon Sep 17 00:00:00 2001 From: Eran Date: Thu, 14 Dec 2023 09:25:21 +0200 Subject: [PATCH] device debug name in log messages --- third-party/realdds/src/dds-device-impl.cpp | 39 ++++++++++++--------- third-party/realdds/src/dds-device-impl.h | 1 + third-party/realdds/src/dds-device.cpp | 2 +- 3 files changed, 24 insertions(+), 18 deletions(-) diff --git a/third-party/realdds/src/dds-device-impl.cpp b/third-party/realdds/src/dds-device-impl.cpp index f78f9686396..454bacfada8 100644 --- a/third-party/realdds/src/dds-device-impl.cpp +++ b/third-party/realdds/src/dds-device-impl.cpp @@ -101,19 +101,19 @@ void dds_device::impl::set_state( state_t new_state ) nlohmann::json md_settings = rsutils::json::nested( _device_settings, "metadata" ); if( ! md_settings.is_null() && ! md_settings.is_object() ) // not found is null { - LOG_DEBUG( "... metadata is available but device/metadata is disabled" ); + LOG_DEBUG( "[" << debug_name() << "] ... metadata is available but device/metadata is disabled" ); _metadata_reader.reset(); } else { - LOG_DEBUG( "... metadata is enabled" ); + LOG_DEBUG( "[" << debug_name() << "] ... metadata is enabled" ); dds_topic_reader::qos rqos( eprosima::fastdds::dds::BEST_EFFORT_RELIABILITY_QOS ); rqos.history().depth = 10; // Support receive metadata from multiple streams rqos.override_from_json( md_settings ); _metadata_reader->run( rqos ); } } - LOG_DEBUG( "device '" << _info.debug_name() << "' (" << _participant->print( guid() ) << ") is ready" ); + LOG_DEBUG( "[" << debug_name() << "] device is ready" ); } _state = new_state; @@ -153,17 +153,22 @@ dds_guid const & dds_device::impl::guid() const } +std::string dds_device::impl::debug_name() const +{ + return rsutils::string::from() << _info.debug_name() << _participant->print( guid() ); +} + + void dds_device::impl::wait_until_ready( size_t timeout_ms ) { if( is_ready() ) return; - LOG_DEBUG( "waiting for '" << _info.debug_name() << "' ..." ); rsutils::time::timer timer{ std::chrono::milliseconds( timeout_ms ) }; do { if( timer.has_expired() ) - DDS_THROW( runtime_error, "timeout waiting for '" << _info.debug_name() << "'" ); + DDS_THROW( runtime_error, "timeout waiting for '" << debug_name() << "'" ); std::this_thread::sleep_for( std::chrono::milliseconds( 500 ) ); } while( ! is_ready() ); @@ -175,7 +180,7 @@ void dds_device::impl::handle_notification( nlohmann::json const & j, { try { - // First handle the notification + // First handle the notification: first priority to notification callbacks auto id = rsutils::json::get< std::string >( j, id_key ); auto it = _notification_handlers.find( id ); if( it != _notification_handlers.end() ) @@ -185,11 +190,11 @@ void dds_device::impl::handle_notification( nlohmann::json const & j, } catch( std::exception const & e ) { - LOG_DEBUG( "notification error: " << e.what() << " " << j ); + LOG_DEBUG( "[" << debug_name() << "] notification error: " << e.what() << "\n " << j ); } catch( ... ) { - LOG_DEBUG( "notification error: unknown exception " << j ); + LOG_DEBUG( "[" << debug_name() << "] notification error: unknown exception\n " << j ); } try @@ -220,11 +225,11 @@ void dds_device::impl::handle_notification( nlohmann::json const & j, } catch( std::exception const & e ) { - LOG_DEBUG( "reply error: " << e.what() << " " << j ); + LOG_DEBUG( "[" << debug_name() << "] reply error: " << e.what() << " " << j ); } catch( ... ) { - LOG_DEBUG( "reply error: unknown exception " << j ); + LOG_DEBUG( "[" << debug_name() << "] reply error: unknown exception " << j ); } } @@ -275,7 +280,7 @@ void dds_device::impl::on_option_value( nlohmann::json const & j, eprosima::fast return; } } - LOG_DEBUG( "option '" << option_name << "': not found" ); + LOG_DEBUG( "[" << debug_name() << "] option '" << option_name << "': not found" ); }; rsutils::json::nested value_j( j, value_key ); @@ -363,7 +368,7 @@ void dds_device::impl::on_log( nlohmann::json const & j, eprosima::fastdds::dds: if( _on_device_log ) _on_device_log( timestamp, type, text, data ); else - LOG_DEBUG( "[" << _info.debug_name() << "][" << timestr( timestamp ) << "][" << type << "] " << text + LOG_DEBUG( "[" << debug_name() << "][" << timestr( timestamp ) << "][" << type << "] " << text << " [" << data << "]" ); } catch( std::exception const & e ) @@ -547,7 +552,7 @@ void dds_device::impl::create_metadata_reader() } catch( std::exception const & e ) { - LOG_DEBUG( "metadata exception: " << e.what() ); + LOG_DEBUG( "[" << debug_name() << "] metadata exception: " << e.what() ); } } } @@ -580,7 +585,7 @@ void dds_device::impl::on_device_header( nlohmann::json const & j, eprosima::fas eprosima::fastrtps::rtps::iHandle2GUID( _server_guid, sample.publication_handle ); _n_streams_expected = rsutils::json::get< size_t >( j, "n-streams" ); - LOG_DEBUG( "... " << id_device_header << ": " << _n_streams_expected << " streams expected" ); + LOG_DEBUG( "[" << debug_name() << "] ... " << id_device_header << ": " << _n_streams_expected << " streams expected" ); if( rsutils::json::has( j, "extrinsics" ) ) { @@ -588,7 +593,7 @@ void dds_device::impl::on_device_header( nlohmann::json const & j, eprosima::fas { std::string from_name = rsutils::json::get< std::string >( ex, 0 ); std::string to_name = rsutils::json::get< std::string >( ex, 1 ); - LOG_DEBUG( " ... got extrinsics from " << from_name << " to " << to_name ); + LOG_DEBUG( "[" << debug_name() << "] ... got extrinsics from " << from_name << " to " << to_name ); extrinsics extr = extrinsics::from_json( rsutils::json::get< nlohmann::json >( ex, 2 ) ); _extrinsics_map[std::make_pair( from_name, to_name )] = std::make_shared< extrinsics >( extr ); } @@ -605,7 +610,7 @@ void dds_device::impl::on_device_options( nlohmann::json const & j, eprosima::fa if( rsutils::json::has( j, "options" ) ) { - LOG_DEBUG( "... " << id_device_options << ": " << j["options"].size() << " options received" ); + LOG_DEBUG( "[" << debug_name() << "] ... " << id_device_options << ": " << j["options"].size() << " options received" ); for( auto & option_json : j["options"] ) { @@ -674,7 +679,7 @@ void dds_device::impl::on_stream_header( nlohmann::json const & j, eprosima::fas "failed to instantiate stream type '" << stream_type << "' (instead, got '" << stream->type_string() << "')" ); - LOG_DEBUG( "... stream " << _streams.size() << "/" << _n_streams_expected << " '" << stream_name + LOG_DEBUG( "[" << debug_name() << "] ... stream " << _streams.size() << "/" << _n_streams_expected << " '" << stream_name << "' received with " << profiles.size() << " profiles" << ( stream->metadata_enabled() ? " and metadata" : "" ) ); diff --git a/third-party/realdds/src/dds-device-impl.h b/third-party/realdds/src/dds-device-impl.h index 82d7db94cb7..a0e81d82432 100644 --- a/third-party/realdds/src/dds-device-impl.h +++ b/third-party/realdds/src/dds-device-impl.h @@ -75,6 +75,7 @@ class dds_device::impl topics::device_info const & info ); dds_guid const & guid() const; + std::string debug_name() const; void wait_until_ready( size_t timeout_ms ); bool is_ready() const { return state_t::READY == _state; } diff --git a/third-party/realdds/src/dds-device.cpp b/third-party/realdds/src/dds-device.cpp index eb2d7fa1406..25f10fc723a 100644 --- a/third-party/realdds/src/dds-device.cpp +++ b/third-party/realdds/src/dds-device.cpp @@ -13,7 +13,7 @@ namespace realdds { dds_device::dds_device( std::shared_ptr< dds_participant > const & participant, topics::device_info const & info ) : _impl( std::make_shared< dds_device::impl >( participant, info ) ) { - LOG_DEBUG( "+device '" << info.debug_name() << "' on " << info.topic_root ); + LOG_DEBUG( "+device '" << _impl->debug_name() << "' on " << info.topic_root ); }