Merge pull request 'Add timestamp to SimRequest' (#140) from add-timestamp-to-sim-request into main

Reviewed-on: #140

.gitignore

@@ -2,6 +2,7 @@ target/
 
 output.log
 /Cargo.lock
+output.log
 
 output.log
 

satrs-minisim/Cargo.toml

@@ -10,9 +10,14 @@ serde = { version = "1", features = ["derive"] }
 serde_json = "1"
 log = "0.4"
 thiserror = "1"
+fern = "0.5"
+humantime = "2"
 
 [dependencies.asynchronix]
 version = "0.2.1"
+git = "https://github.com/asynchronics/asynchronix.git"
+branch = "main"
+features = ["serde"]
 
 [dependencies.satrs]
 path = "../satrs"

satrs-minisim/src/acs.rs

@@ -189,11 +189,11 @@ pub mod tests {
     #[test]
     fn test_basic_mgm_request() {
         let mut sim_testbench = SimTestbench::new();
-        let request = SimRequest::new(MgmRequest::RequestSensorData);
+        let request = SimRequest::new_with_epoch_time(MgmRequest::RequestSensorData);
         sim_testbench
             .send_request(request)
             .expect("sending MGM request failed");
-        sim_testbench.handle_sim_requests();
+        sim_testbench.handle_sim_requests_time_agnostic();
         sim_testbench.step();
         let sim_reply = sim_testbench.try_receive_next_reply();
         assert!(sim_reply.is_some());
@@ -212,11 +212,11 @@ pub mod tests {
         let mut sim_testbench = SimTestbench::new();
         switch_device_on(&mut sim_testbench, PcduSwitch::Mgm);
 
-        let mut request = SimRequest::new(MgmRequest::RequestSensorData);
+        let mut request = SimRequest::new_with_epoch_time(MgmRequest::RequestSensorData);
         sim_testbench
             .send_request(request)
             .expect("sending MGM request failed");
-        sim_testbench.handle_sim_requests();
+        sim_testbench.handle_sim_requests_time_agnostic();
         sim_testbench.step();
         let mut sim_reply_res = sim_testbench.try_receive_next_reply();
         assert!(sim_reply_res.is_some());
@@ -226,11 +226,11 @@ pub mod tests {
             .expect("failed to deserialize MGM sensor values");
         sim_testbench.step_by(Duration::from_millis(50));
 
-        request = SimRequest::new(MgmRequest::RequestSensorData);
+        request = SimRequest::new_with_epoch_time(MgmRequest::RequestSensorData);
         sim_testbench
             .send_request(request)
             .expect("sending MGM request failed");
-        sim_testbench.handle_sim_requests();
+        sim_testbench.handle_sim_requests_time_agnostic();
         sim_testbench.step();
         sim_reply_res = sim_testbench.try_receive_next_reply();
         assert!(sim_reply_res.is_some());
@@ -245,11 +245,11 @@ pub mod tests {
     #[test]
     fn test_basic_mgt_request_is_off() {
         let mut sim_testbench = SimTestbench::new();
-        let request = SimRequest::new(MgtRequest::RequestHk);
+        let request = SimRequest::new_with_epoch_time(MgtRequest::RequestHk);
         sim_testbench
             .send_request(request)
             .expect("sending MGM request failed");
-        sim_testbench.handle_sim_requests();
+        sim_testbench.handle_sim_requests_time_agnostic();
         sim_testbench.step();
         let sim_reply_res = sim_testbench.try_receive_next_reply();
         assert!(sim_reply_res.is_none());
@@ -259,12 +259,12 @@ pub mod tests {
     fn test_basic_mgt_request_is_on() {
         let mut sim_testbench = SimTestbench::new();
         switch_device_on(&mut sim_testbench, PcduSwitch::Mgt);
-        let request = SimRequest::new(MgtRequest::RequestHk);
+        let request = SimRequest::new_with_epoch_time(MgtRequest::RequestHk);
 
         sim_testbench
             .send_request(request)
             .expect("sending MGM request failed");
-        sim_testbench.handle_sim_requests();
+        sim_testbench.handle_sim_requests_time_agnostic();
         sim_testbench.step();
         let sim_reply_res = sim_testbench.try_receive_next_reply();
         assert!(sim_reply_res.is_some());
@@ -281,11 +281,11 @@ pub mod tests {
     }
 
     fn check_mgt_hk(sim_testbench: &mut SimTestbench, expected_hk_set: MgtHkSet) {
-        let request = SimRequest::new(MgtRequest::RequestHk);
+        let request = SimRequest::new_with_epoch_time(MgtRequest::RequestHk);
         sim_testbench
             .send_request(request)
             .expect("sending MGM request failed");
-        sim_testbench.handle_sim_requests();
+        sim_testbench.handle_sim_requests_time_agnostic();
         sim_testbench.step();
         let sim_reply_res = sim_testbench.try_receive_next_reply();
         assert!(sim_reply_res.is_some());
@@ -309,14 +309,14 @@ pub mod tests {
             y: 200,
             z: 1000,
         };
-        let request = SimRequest::new(MgtRequest::ApplyTorque {
+        let request = SimRequest::new_with_epoch_time(MgtRequest::ApplyTorque {
             duration: Duration::from_millis(100),
             dipole: commanded_dipole,
         });
         sim_testbench
             .send_request(request)
             .expect("sending MGM request failed");
-        sim_testbench.handle_sim_requests();
+        sim_testbench.handle_sim_requests_time_agnostic();
         sim_testbench.step_by(Duration::from_millis(5));
 
         check_mgt_hk(

satrs-minisim/src/controller.rs

@@ -49,25 +49,27 @@ impl SimController {
     }
 
     pub fn run(&mut self, start_time: MonotonicTime, udp_polling_interval_ms: u64) {
-        let mut t = start_time + Duration::from_millis(udp_polling_interval_ms);
-        self.sys_clock.synchronize(t);
+        let mut t = start_time;
         loop {
+            let t_old = t;
             // Check for UDP requests every millisecond. Shift the simulator ahead here to prevent
             // replies lying in the past.
             t += Duration::from_millis(udp_polling_interval_ms);
+            self.sys_clock.synchronize(t);
+            self.handle_sim_requests(t_old);
             self.simulation
                 .step_until(t)
                 .expect("simulation step failed");
-            self.handle_sim_requests();
-
-            self.sys_clock.synchronize(t);
         }
     }
 
-    pub fn handle_sim_requests(&mut self) {
+    pub fn handle_sim_requests(&mut self, old_timestamp: MonotonicTime) {
         loop {
             match self.request_receiver.try_recv() {
                 Ok(request) => {
+                    if request.timestamp < old_timestamp {
+                        log::warn!("stale data with timestamp {:?} received", request.timestamp);
+                    }
                     if let Err(e) = match request.target() {
                         SimTarget::SimCtrl => self.handle_ctrl_request(&request),
                         SimTarget::Mgm => self.handle_mgm_request(&request),
@@ -172,11 +174,11 @@ mod tests {
     #[test]
     fn test_basic_ping() {
         let mut sim_testbench = SimTestbench::new();
-        let request = SimRequest::new(SimCtrlRequest::Ping);
+        let request = SimRequest::new_with_epoch_time(SimCtrlRequest::Ping);
         sim_testbench
             .send_request(request)
             .expect("sending sim ctrl request failed");
-        sim_testbench.handle_sim_requests();
+        sim_testbench.handle_sim_requests_time_agnostic();
         sim_testbench.step();
         let sim_reply = sim_testbench.try_receive_next_reply();
         assert!(sim_reply.is_some());

satrs-minisim/src/eps.rs

@@ -86,14 +86,14 @@ pub(crate) mod tests {
         switch: PcduSwitch,
         target: SwitchStateBinary,
     ) {
-        let request = SimRequest::new(PcduRequest::SwitchDevice {
+        let request = SimRequest::new_with_epoch_time(PcduRequest::SwitchDevice {
             switch,
             state: target,
         });
         sim_testbench
             .send_request(request)
             .expect("sending MGM switch request failed");
-        sim_testbench.handle_sim_requests();
+        sim_testbench.handle_sim_requests_time_agnostic();
         sim_testbench.step();
     }
 
@@ -113,11 +113,11 @@ pub(crate) mod tests {
     }
 
     fn check_switch_state(sim_testbench: &mut SimTestbench, expected_switch_map: &SwitchMap) {
-        let request = SimRequest::new(PcduRequest::RequestSwitchInfo);
+        let request = SimRequest::new_with_epoch_time(PcduRequest::RequestSwitchInfo);
         sim_testbench
             .send_request(request)
             .expect("sending MGM request failed");
-        sim_testbench.handle_sim_requests();
+        sim_testbench.handle_sim_requests_time_agnostic();
         sim_testbench.step();
         let sim_reply = sim_testbench.try_receive_next_reply();
         assert!(sim_reply.is_some());
@@ -143,11 +143,11 @@ pub(crate) mod tests {
     #[test]
     fn test_pcdu_switcher_request() {
         let mut sim_testbench = SimTestbench::new();
-        let request = SimRequest::new(PcduRequest::RequestSwitchInfo);
+        let request = SimRequest::new_with_epoch_time(PcduRequest::RequestSwitchInfo);
         sim_testbench
             .send_request(request)
             .expect("sending MGM request failed");
-        sim_testbench.handle_sim_requests();
+        sim_testbench.handle_sim_requests_time_agnostic();
         sim_testbench.step_by(Duration::from_millis(1));
 
         let sim_reply = sim_testbench.try_receive_next_reply();

satrs-minisim/src/lib.rs

@@ -1,5 +1,8 @@
+use asynchronix::time::MonotonicTime;
 use serde::{de::DeserializeOwned, Deserialize, Serialize};
 
+pub const SIM_CTRL_UDP_PORT: u16 = 7303;
+
 #[derive(Debug, Copy, Clone, PartialEq, Eq, Serialize, Deserialize)]
 pub enum SimTarget {
     SimCtrl,
@@ -19,6 +22,7 @@ pub struct SimMessage {
 #[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)]
 pub struct SimRequest {
     inner: SimMessage,
+    pub timestamp: MonotonicTime,
 }
 
 #[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)]
@@ -53,12 +57,22 @@ pub trait SimMessageProvider: Serialize + DeserializeOwned + Clone + Sized {
 }
 
 impl SimRequest {
-    pub fn new<T: SerializableSimMsgPayload<SimRequest>>(serializable_request: T) -> Self {
+    pub fn new_with_epoch_time<T: SerializableSimMsgPayload<SimRequest>>(
+        serializable_request: T,
+    ) -> Self {
+        Self::new(serializable_request, MonotonicTime::EPOCH)
+    }
+
+    pub fn new<T: SerializableSimMsgPayload<SimRequest>>(
+        serializable_request: T,
+        timestamp: MonotonicTime,
+    ) -> Self {
         Self {
             inner: SimMessage {
                 target: T::TARGET,
                 payload: serde_json::to_string(&serializable_request).unwrap(),
             },
+            timestamp,
         }
     }
 }
@@ -363,7 +377,7 @@ pub mod tests {
 
     #[test]
     fn test_basic_request() {
-        let sim_request = SimRequest::new(DummyRequest::Ping);
+        let sim_request = SimRequest::new_with_epoch_time(DummyRequest::Ping);
         assert_eq!(sim_request.target(), SimTarget::SimCtrl);
         assert_eq!(sim_request.msg_type(), SimMessageType::Request);
         let dummy_request =

satrs-minisim/src/main.rs

@@ -3,7 +3,7 @@ use asynchronix::simulation::{Mailbox, SimInit};
 use asynchronix::time::{MonotonicTime, SystemClock};
 use controller::SimController;
 use eps::PcduModel;
-use satrs_minisim::{SimReply, SimRequest};
+use satrs_minisim::{SimReply, SimRequest, SIM_CTRL_UDP_PORT};
 use std::sync::mpsc;
 use std::thread;
 use std::time::{Duration, SystemTime};
@@ -83,14 +83,38 @@ fn main() {
     let t0 = MonotonicTime::EPOCH;
     let mut sim_ctrl =
         create_sim_controller(ThreadingModel::Default, t0, reply_sender, request_receiver);
+    // Configure logger at runtime
+    fern::Dispatch::new()
+        // Perform allocation-free log formatting
+        .format(|out, message, record| {
+            out.finish(format_args!(
+                "[{} {} {}] {}",
+                humantime::format_rfc3339(std::time::SystemTime::now()),
+                record.level(),
+                record.target(),
+                message
+            ))
+        })
+        // Add blanket level filter -
+        .level(log::LevelFilter::Debug)
+        // - and per-module overrides
+        // Output to stdout, files, and other Dispatch configurations
+        .chain(std::io::stdout())
+        .chain(fern::log_file("output.log").expect("could not open log output file"))
+        // Apply globally
+        .apply()
+        .expect("could not apply logger configuration");
 
+    log::info!("starting simulation thread");
     // This thread schedules the simulator.
     let sim_thread = thread::spawn(move || {
         sim_ctrl.run(t0, 1);
     });
 
-    let mut udp_server = SimUdpServer::new(0, request_sender, reply_receiver, 200, None)
-        .expect("could not create UDP request server");
+    let mut udp_server =
+        SimUdpServer::new(SIM_CTRL_UDP_PORT, request_sender, reply_receiver, 200, None)
+            .expect("could not create UDP request server");
+    log::info!("starting UDP server on port {}", SIM_CTRL_UDP_PORT);
     // This thread manages the simulator UDP server.
     let udp_tc_thread = thread::spawn(move || {
         udp_server.run();

satrs-minisim/src/test_helpers.rs

@@ -26,10 +26,13 @@ impl SimTestbench {
             request_sender,
         }
     }
+    pub fn handle_sim_requests_time_agnostic(&mut self) {
+        self.handle_sim_requests(MonotonicTime::EPOCH);
+    }
 
     delegate! {
         to self.sim_controller {
-            pub fn handle_sim_requests(&mut self);
+            pub fn handle_sim_requests(&mut self, old_timestamp: MonotonicTime);
         }
         to self.sim_controller.simulation {
             pub fn step(&mut self);

satrs-minisim/src/udp.rs

@@ -270,7 +270,7 @@ mod tests {
             UdpTestbench::new(true, Some(SERVER_WAIT_TIME_MS), 10)
                 .expect("could not create testbench");
         let server_thread = std::thread::spawn(move || udp_server.run());
-        let sim_request = SimRequest::new(PcduRequest::RequestSwitchInfo);
+        let sim_request = SimRequest::new_with_epoch_time(PcduRequest::RequestSwitchInfo);
         udp_testbench
             .send_request(&sim_request)
             .expect("sending request failed");
@@ -292,7 +292,7 @@ mod tests {
                 .expect("could not create testbench");
         let server_thread = std::thread::spawn(move || udp_server.run());
         udp_testbench
-            .send_request(&SimRequest::new(SimCtrlRequest::Ping))
+            .send_request(&SimRequest::new_with_epoch_time(SimCtrlRequest::Ping))
             .expect("sending request failed");
 
         let sim_reply = SimReply::new(PcduReply::SwitchInfo(get_all_off_switch_map()));
@@ -316,7 +316,7 @@ mod tests {
         // Send a ping so that the server knows the address of the client.
         // Do not check that the request arrives on the receiver side, is done by other test.
         udp_testbench
-            .send_request(&SimRequest::new(SimCtrlRequest::Ping))
+            .send_request(&SimRequest::new_with_epoch_time(SimCtrlRequest::Ping))
             .expect("sending request failed");
 
         // Send a reply to the server, ensure it gets forwarded to the client.
@@ -347,7 +347,7 @@ mod tests {
 
         // Connect by sending a ping.
         udp_testbench
-            .send_request(&SimRequest::new(SimCtrlRequest::Ping))
+            .send_request(&SimRequest::new_with_epoch_time(SimCtrlRequest::Ping))
             .expect("sending request failed");
         std::thread::sleep(Duration::from_millis(SERVER_WAIT_TIME_MS));
 
@@ -376,7 +376,7 @@ mod tests {
 
         // Connect by sending a ping.
         udp_testbench
-            .send_request(&SimRequest::new(SimCtrlRequest::Ping))
+            .send_request(&SimRequest::new_with_epoch_time(SimCtrlRequest::Ping))
             .expect("sending request failed");
         std::thread::sleep(Duration::from_millis(SERVER_WAIT_TIME_MS));