diff --git a/score/mw/com/example/com-api-example/BUILD b/score/mw/com/example/com-api-example/BUILD index e22ae5785..b2c786890 100644 --- a/score/mw/com/example/com-api-example/BUILD +++ b/score/mw/com/example/com-api-example/BUILD @@ -16,18 +16,33 @@ load("@rules_rust//rust:defs.bzl", "rust_binary", "rust_test") rust_binary( name = "com-api-example", srcs = ["basic-consumer-producer.rs"], + data = [ + "etc/config.json", + "etc/logging.json", + ], + env = { + "MW_LOG_CONFIG_FILE": "score/mw/com/example/com-api-example/etc/logging.json", + }, features = ["link_std_cpp_lib"], visibility = ["//visibility:public"], deps = [ "//score/mw/com/example/com-api-example/com-api-gen", "//score/mw/com/impl/rust/com-api/com-api", + "@score_baselibs_rust//src/log/score_log", + "@score_logging//score/mw/log/rust/score_log_bridge", ], ) rust_test( name = "com-api-example-test", crate = ":com-api-example", - data = ["etc/config.json"], + data = [ + "etc/config.json", + "etc/logging.json", + ], + env = { + "MW_LOG_CONFIG_FILE": "score/mw/com/example/com-api-example/etc/logging.json", + }, tags = ["manual"], deps = [ ":com-api-example", diff --git a/score/mw/com/example/com-api-example/basic-consumer-producer.rs b/score/mw/com/example/com-api-example/basic-consumer-producer.rs index 6b922e223..f43dc7494 100644 --- a/score/mw/com/example/com-api-example/basic-consumer-producer.rs +++ b/score/mw/com/example/com-api-example/basic-consumer-producer.rs @@ -18,6 +18,8 @@ use com_api::{ }; use com_api_gen::{Exhaust, Tire, VehicleInterface}; +use score_log as log; +use score_log_bridge::ScoreLogBridgeBuilder; // Type aliases for generated consumer and offered producer types for the Vehicle interface // VehicleConsumer is the consumer type generated for the Vehicle interface, parameterized by the runtime R @@ -97,7 +99,7 @@ impl VehicleMonitor { let uninit_sample = self.producer.left_tire.allocate()?; let sample = uninit_sample.write(tire); sample.send()?; - println!("Tire data sent"); + log::info!("Tire data sent"); Ok(()) } } @@ -153,7 +155,7 @@ fn create_producer( // Run the example with the specified runtime fn run_with_runtime(name: &str, runtime: &R) { - println!("\n=== Running with {name} runtime ==="); + log::info!("Running with {} runtime", name); let service_id = InstanceSpecifier::new("/Vehicle/Service1/Instance") .expect("Failed to create InstanceSpecifier"); @@ -161,7 +163,7 @@ fn run_with_runtime(name: &str, runtime: &R) { let consumer = create_consumer(runtime, service_id); let monitor = VehicleMonitor::new(consumer, producer).unwrap(); let tire_pressure = 5.0; - println!("Setting tire pressure to {tire_pressure}"); + log::info!("Setting tire pressure to {}", tire_pressure); for i in 0..5 { monitor .write_tire_data(Tire { @@ -169,14 +171,14 @@ fn run_with_runtime(name: &str, runtime: &R) { }) .unwrap(); let tire_data = monitor.read_tire_data().unwrap(); - println!("{tire_data}"); + log::info!("Received tire data: {}", tire_data); } //unoffer returns producer back, so if needed it can be used further match monitor.producer.unoffer() { - Ok(_) => println!("Successfully unoffered the service"), - Err(e) => eprintln!("Failed to unoffer: {:?}", e), + Ok(_) => log::info!("Successfully unoffered the service"), + Err(e) => log::error!("Failed to unoffer: {:?}", e), } - println!("=== {name} runtime completed ===\n"); + log::info!("runtime execution completed"); } // Initialize Lola runtime builder with configuration @@ -188,7 +190,22 @@ fn init_lola_runtime_builder() -> LolaRuntimeBuilderImpl { lola_runtime_builder } +fn init_logging() { + // Try to load logging config from environment variable. + let config_path = std::env::var("MW_LOG_CONFIG_FILE") + .expect("config file not set in environment variable MW_LOG_CONFIG_FILE"); + + // Initialize ScoreLogBridge as a default logger. + ScoreLogBridgeBuilder::new() + .show_module(false) + .show_file(true) + .show_line(false) + .config(config_path.into()) + .set_as_default_logger(); +} + fn main() { + init_logging(); let lola_runtime_builder = init_lola_runtime_builder(); let lola_runtime = lola_runtime_builder.build().unwrap(); run_with_runtime("Lola", &lola_runtime); @@ -202,7 +219,8 @@ mod test { #[test] fn integration_test() { - println!("Starting integration test with Lola runtime"); + init_logging(); + log::info!("Starting integration test with Lola runtime"); let lola_runtime_builder = init_lola_runtime_builder(); let lola_runtime = lola_runtime_builder.build().unwrap(); run_with_runtime("Lola", &lola_runtime); @@ -320,10 +338,7 @@ mod test { pressure: 1.0 + i as f32, }); sample.send().unwrap(); - println!( - "[SENDER] Sent sample with pressure: {:.2} psi", - 1.0 + i as f32 - ); + log::info!("Sent tire data: {:.2}", 1.0 + i as f32); tokio::time::sleep(tokio::time::Duration::from_millis(2000)).await; } offered_producer @@ -332,17 +347,17 @@ mod test { //receiver function which use async receive to get data, it waits for new data and process it once it arrives, //it will receive data 10 times and print the received samples async fn async_data_processor_fn(subscribed: impl Subscription) { - println!("[RECEIVER] Async data processor started"); + log::info!("Async data processor started"); let mut buffer = SampleContainer::new(5); for _ in 0..5 { buffer = match subscribed.receive(buffer, 2, 3).await { Ok(returned_buf) => { let count = returned_buf.sample_count(); if count > 0 { - println!("[RECEIVER] Received {} samples", count); + log::info!("[RECEIVER] Received {} samples", count); let mut buf = returned_buf; while let Some(sample) = buf.pop_front() { - println!("[RECEIVER] Sample: {:.2} psi", sample.pressure); + log::info!("[RECEIVER] Sample: {:.2} psi", sample.pressure); } buf } else { @@ -350,7 +365,7 @@ mod test { } } Err(e) => { - println!("[RECEIVER] Error receiving data: {:?}", e); + log::error!("[RECEIVER] Error receiving data: {:?}", e); SampleContainer::new(5) } } @@ -361,7 +376,7 @@ mod test { // Use the tokio multi-threaded runtime to run async sender and receiver concurrently on separate threads #[tokio::test(flavor = "multi_thread")] async fn receive_and_send_using_multi_thread() { - println!("Starting async subscription test with Lola runtime"); + log::info!("Starting async subscription test with Lola runtime"); let service_id = InstanceSpecifier::new("/Vehicle/Service3/Instance") .expect("Failed to create InstanceSpecifier"); let service_id_clone = service_id.clone(); @@ -390,10 +405,10 @@ mod test { let producer = sender_join_handle.await.expect("Error returned from task"); match producer.unoffer() { - Ok(_) => println!("Successfully unoffered the service"), - Err(e) => eprintln!("Failed to unoffer: {:?}", e), + Ok(_) => log::info!("Successfully unoffered the service"), + Err(e) => log::error!("Failed to unoffer: {:?}", e), } - println!("=== Async subscription test with Lola runtime completed ===\n"); + log::info!("=== Async subscription test with Lola runtime completed ===\n"); } } diff --git a/score/mw/com/example/com-api-example/etc/logging.json b/score/mw/com/example/com-api-example/etc/logging.json new file mode 100644 index 000000000..113efe19c --- /dev/null +++ b/score/mw/com/example/com-api-example/etc/logging.json @@ -0,0 +1,8 @@ +{ + "ecuId": "com-api", + "appId": "EAPP", + "appDesc": "Example_Application", + "logMode": "kFile", + "logLevel": "kInfo", + "logLevelThresholdConsole": "kInfo" +} diff --git a/score/mw/com/impl/rust/com-api/com-api-concept/BUILD b/score/mw/com/impl/rust/com-api/com-api-concept/BUILD index 954a1dfe6..946984c3b 100644 --- a/score/mw/com/impl/rust/com-api/com-api-concept/BUILD +++ b/score/mw/com/impl/rust/com-api/com-api-concept/BUILD @@ -30,6 +30,7 @@ rust_library( ], deps = [ "@score_baselibs_rust//src/containers", + "@score_baselibs_rust//src/log/score_log", ], ) diff --git a/score/mw/com/impl/rust/com-api/com-api-concept/com_api_concept.rs b/score/mw/com/impl/rust/com-api/com-api-concept/com_api_concept.rs index 3c91799a5..0dd9e0e0a 100644 --- a/score/mw/com/impl/rust/com-api/com-api-concept/com_api_concept.rs +++ b/score/mw/com/impl/rust/com-api/com-api-concept/com_api_concept.rs @@ -51,10 +51,18 @@ use containers::fixed_capacity::FixedCapacityQueue; use core::fmt::Debug; use core::future::Future; use core::ops::{Deref, DerefMut}; +use score_log::ScoreDebug; use std::path::Path; /// Error enumeration for different failure cases in the Consumer/Producer/Runtime APIs. -#[derive(Debug)] +/// +/// Both `Debug` and `ScoreDebug` are derived because `score_log` macros require `ScoreDebug`, +/// while `Debug` is needed for standard Rust formatting. There is currently no blanket +/// `impl ScoreDebug for T` in `score_log_fmt`, so both must be explicitly derived +/// for any type used across both contexts. +// TODO: Need to explore if we can somehow avoid deriving both Debug and ScoreDebug for all types. +// Maybe we can add a blanket impl for ScoreDebug for all Debug types in score_log_fmt? +#[derive(Debug, ScoreDebug)] pub enum Error { /// TODO: To be replaced, dummy value for "something went wrong" Fail, diff --git a/score/mw/com/impl/rust/com-api/com-api-runtime-lola/BUILD b/score/mw/com/impl/rust/com-api/com-api-runtime-lola/BUILD index 1b5ac2a5d..d8ddba1af 100644 --- a/score/mw/com/impl/rust/com-api/com-api-runtime-lola/BUILD +++ b/score/mw/com/impl/rust/com-api/com-api-runtime-lola/BUILD @@ -30,6 +30,7 @@ rust_library( "//score/mw/com/impl/rust:mw_com", "//score/mw/com/impl/rust/com-api/com-api-concept", "//score/mw/com/impl/rust/com-api/com-api-ffi-lola:bridge_ffi_rs", + "@score_baselibs_rust//src/log/score_log", "@score_communication_crate_index//:futures", ], ) diff --git a/score/mw/com/impl/rust/com-api/com-api-runtime-lola/consumer.rs b/score/mw/com/impl/rust/com-api/com-api-runtime-lola/consumer.rs index 2ec873276..1830bb966 100644 --- a/score/mw/com/impl/rust/com-api/com-api-runtime-lola/consumer.rs +++ b/score/mw/com/impl/rust/com-api/com-api-runtime-lola/consumer.rs @@ -44,6 +44,8 @@ use com_api_concept::{ Interface, Result, SampleContainer, ServiceDiscovery, Subscriber, Subscription, }; +use score_log as log; + use bridge_ffi_rs::*; use crate::LolaRuntimeImpl; @@ -280,6 +282,11 @@ pub struct SubscribableImpl { impl Subscriber for SubscribableImpl { type Subscription = SubscriberImpl; fn new(identifier: &'static str, instance_info: LolaConsumerInfo) -> Result { + log::info!( + "Creating SubscribableImpl for identifier: {} with interface_id: {}", + identifier, + instance_info.interface_id + ); let handle = instance_info.get_handle().ok_or(Error::Fail)?; let native_proxy = NativeProxyBase::new(instance_info.interface_id, handle); let proxy_instance = ProxyInstanceManager(Arc::new(native_proxy)); @@ -291,6 +298,12 @@ impl Subscriber for SubscribableImpl { }) } fn subscribe(self, max_num_samples: usize) -> Result { + log::info!( + "Subscribing to event: {} for identifier: {} with max_num_samples: {}", + self.identifier, + self.instance_info.interface_id, + max_num_samples + ); let instance_info = self.instance_info.clone(); let event_instance = NativeProxyEventBase::new( self.proxy_instance.0.proxy, @@ -307,6 +320,11 @@ impl Subscriber for SubscribableImpl { ) }; if !status { + log::error!( + "Failed to subscribe to event: {} for identifier: {}", + self.instance_info.interface_id, + self.identifier + ); return Err(Error::Fail); } // Store in SubscriberImpl with event, max_num_samples @@ -454,6 +472,7 @@ impl SubscriberImpl { unsafe { bridge_ffi_rs::set_event_receive_handler(event_guard.deref_mut(), &fat_ptr, T::ID); } + log::debug!("Initialized async receive for event: {}", self.event_id); Ok(()) } } @@ -495,6 +514,12 @@ where ) -> impl Future>>> + 'a { async move { if max_samples > self.max_num_samples || new_samples > self.max_num_samples { + log::error!( + "Requested max_samples: {} or new_samples: {} exceeds the max_num_samples: {} for this subscription", + max_samples, + new_samples, + self.max_num_samples + ); return Err(Error::Fail); } // Get the event guard to ensure no concurrent receive calls on the same subscriber instance. @@ -505,6 +530,7 @@ where .load(std::sync::atomic::Ordering::Relaxed) { if let Err(_e) = self.init_async_receive(&mut event_guard) { + log::error!("Failed to initialize async receive for event: {}", T::ID); return Err(Error::Fail); } self.async_init_status @@ -550,7 +576,12 @@ impl<'a, T: CommData> Future for ReceiveFuture<'a, T> { // Register the current waker to be notified when new samples arrive via FFI callback self.waker_storage.register(ctx.waker()); - + log::debug!( + "Polling for samples: total_received: {}, new_samples: {}, max_samples: {}", + total_received, + new_samples, + max_samples + ); let samples_received = { // Temporarily take ownership of scratch to avoid borrow issues if let Some(mut scratch) = self.scratch.take() { @@ -564,9 +595,11 @@ impl<'a, T: CommData> Future for ReceiveFuture<'a, T> { self.scratch = Some(scratch); result } else { + log::error!("Event guard is not available for receiving samples"); Err(Error::Fail) } } else { + log::error!("Internal buffer is not available for receiving samples"); Err(Error::Fail) } }; @@ -580,6 +613,11 @@ impl<'a, T: CommData> Future for ReceiveFuture<'a, T> { self.event_guard = None; return Poll::Ready(self.scratch.take().ok_or(Error::Fail)); } + log::debug!( + "Received {} samples, total_received: {}, waiting for more...", + count, + self.total_received + ); // Have some samples but not enough yet, wait for more via waker Poll::Pending } @@ -637,6 +675,11 @@ where type ServiceEnumerator = Vec>; fn get_available_instances(&self) -> Result { + log::info!( + "Starting synchronous service discovery for interface_id: {} with instance_specifier: {}", + I::INTERFACE_ID, + format!("{:?}", self.instance_specifier) + ); //If ANY Support is added in Lola, then we need to return all available instances let instance_specifier_lola = mw_com::InstanceSpecifier::try_from(self.instance_specifier.as_ref()) @@ -644,7 +687,11 @@ where let service_handle = mw_com::proxy::find_service(instance_specifier_lola).map_err(|_| Error::Fail)?; - + log::debug!( + "Synchronous service discovery returned {} handles for interface_id: {}", + service_handle.len(), + I::INTERFACE_ID + ); let service_handle_arc = Arc::new(service_handle); let available_instances = (0..service_handle_arc.len()) .map(|handle_index| { @@ -669,7 +716,11 @@ where &self, ) -> impl Future> + Send { let instance_specifier = self.instance_specifier.clone(); - + log::info!( + "Starting asynchronous service discovery for interface_id: {} with instance_specifier: {}", + I::INTERFACE_ID, + format!("{:?}", instance_specifier) + ); // Convert to Lola InstanceSpecifier early let instance_specifier_lola = mw_com::InstanceSpecifier::try_from(instance_specifier.as_ref()) @@ -691,6 +742,11 @@ where let discovery_callback = Box::new( move |handles: mw_com::proxy::HandleContainer, _find_handle: bridge_ffi_rs::NativeFindServiceHandle| { + log::debug!( + "Service discovery callback received {} handles for interface_id: {}", + handles.len(), + I::INTERFACE_ID + ); if let Ok(mut state) = state_ref.lock() { state.handles = Some(handles); } @@ -715,10 +771,12 @@ where // stop_find_service is always called in Drop. let raw_handle = unsafe { bridge_ffi_rs::start_find_service(&fat_ptr, spec) }; if raw_handle.is_null() { + log::error!("Failed to start service discovery"); Err(Error::Fail) } else { // Single authoritative source of find_handle — return value only. // Callback's find_handle argument is ignored to prevent double-write. + log::debug!("Service discovery started successfully"); Ok(bridge_ffi_rs::NativeFindServiceHandle::new(raw_handle)) } }); @@ -771,7 +829,10 @@ impl Future for ServiceDiscoveryFuture { ) -> std::task::Poll { // Register the waker so C++ callback can wake us up self.waker_storage.register(ctx.waker()); - + log::debug!( + "Polling for service discovery results for interface_id: {}", + I::INTERFACE_ID + ); // NOTE: Lock usage in poll() is acceptable here because: // The callback (running on C++ thread) and this poll (running on executor thread) both // access the same shared mutable state (discovery_state). @@ -788,6 +849,11 @@ impl Future for ServiceDiscoveryFuture { //create Arc for service handle to share between instances let service_handle_arc = Arc::new(service_handle); // Build the response from discovered handles + log::debug!( + "Service discovery completed with {} handles for interface_id: {}, building consumer builders...", + service_handle_arc.len(), + I::INTERFACE_ID + ); let available_instances = (0..service_handle_arc.len()) .map(|handle_index| { let instance_info = LolaConsumerInfo { @@ -826,7 +892,8 @@ impl ConsumerDescriptor for SampleConsumerBuilder fn get_instance_identifier(&self) -> &InstanceSpecifier { //if InstanceSpecifier::ANY support enable by lola //then this API should get InstanceSpecifier from FFI Call - todo!() + log::error!("get_instance_identifier is not supported for SampleConsumerBuilder, as LoLa does not support ANY instance specifier."); + panic!("get_instance_identifier is not supported for SampleConsumerBuilder, as LoLa does not support ANY instance specifier."); } } @@ -847,6 +914,11 @@ fn try_receive_samples( max_samples: usize, ) -> Result { if max_samples > max_num_samples { + log::error!( + "Requested max_samples: {} exceeds the max_num_samples: {} for this subscription", + max_samples, + max_num_samples + ); return Err(Error::Fail); } // Create a callback that will be called by the C++ side for each new sample arrival @@ -867,6 +939,11 @@ fn try_receive_samples( ) }; if count > max_num_samples as u32 { + log::error!( + "Received sample count: {} exceeds the max_num_samples: {} for this subscription", + count, + max_num_samples + ); return Err(Error::Fail); } Ok(count as usize) @@ -891,6 +968,11 @@ pub fn create_sample_callback<'a, T: CommData>( ) -> impl FnMut(*mut sample_ptr_rs::SamplePtr) + 'a { move |raw_sample: *mut sample_ptr_rs::SamplePtr| { if !raw_sample.is_null() { + log::debug!( + "Received new sample pointer from FFI callback for event: {}, max_samples: {}", + T::ID, + max_samples + ); //SAFETY: It is safe to read the sample pointer because // raw_sample is valid pointer passed from FFI callback // and raw_pointer is moved from FFI to Rust ownership here @@ -911,6 +993,11 @@ pub fn create_sample_callback<'a, T: CommData>( scratch.push_back(wrapped_sample).is_ok(), "Failed to push sample after making room in buffer" ); + } else { + log::error!( + "Received null sample pointer from FFI callback for event: {}", + T::ID + ); } } } diff --git a/score/mw/com/impl/rust/com-api/com-api-runtime-lola/producer.rs b/score/mw/com/impl/rust/com-api/com-api-runtime-lola/producer.rs index 20268278b..f1835c8e1 100644 --- a/score/mw/com/impl/rust/com-api/com-api-runtime-lola/producer.rs +++ b/score/mw/com/impl/rust/com-api/com-api-runtime-lola/producer.rs @@ -39,6 +39,8 @@ use com_api_concept::{ ProviderInfo, Result, }; +use score_log as log; + use bridge_ffi_rs::*; use crate::LolaRuntimeImpl; @@ -57,8 +59,18 @@ impl ProviderInfo for LolaProviderInfo { let status = unsafe { bridge_ffi_rs::skeleton_offer_service(self.skeleton_handle.0.handle) }; if !status { + log::error!( + "Failed to offer service for interface: {} with instance specifier: {}", + self.interface_id, + self.instance_specifier.as_ref() + ); return Err(Error::Fail); } + log::info!( + "Service offered successfully for interface: {} with instance specifier: {}", + self.interface_id, + self.instance_specifier.as_ref() + ); Ok(()) } @@ -66,6 +78,11 @@ impl ProviderInfo for LolaProviderInfo { //SAFETY: it is safe as we are passing valid skeleton handle to stop offer service // the skeleton handle is created during building the provider info instance unsafe { bridge_ffi_rs::skeleton_stop_offer_service(self.skeleton_handle.0.handle) }; + log::info!( + "Service stopped successfully for interface: {} with instance specifier: {}", + self.interface_id, + self.instance_specifier.as_ref() + ); Ok(()) } } @@ -186,8 +203,10 @@ where ) }; if !status { + log::error!("Failed to send sample"); return Err(Error::Fail); } + log::debug!("Sample sent successfully"); Ok(()) } } @@ -233,7 +252,7 @@ where //It is safe to write the value because data_ptr is valid // and we are writing the value of type T which is same as allocatee_ptr type data_ptr.write(val); - + log::debug!("Sample data written successfully"); SampleMut { skeleton_event: self.skeleton_event, allocatee_ptr: self.allocatee_ptr, @@ -388,8 +407,16 @@ where T::ID, ); if !status { + log::error!( + "Failed to get allocatee pointer for event: {}", + self.identifier + ); return Err(Error::Fail); } + log::debug!( + "Allocatee pointer obtained successfully for event: {}", + self.identifier + ); sample.assume_init() }; @@ -404,6 +431,7 @@ where fn new(identifier: &str, instance_info: LolaProviderInfo) -> Result { let skeleton_event = NativeSkeletonEventBase::new(&instance_info, identifier); + log::info!("Publisher created for event: {}", identifier); Ok(Self { identifier: identifier.to_string(),