server logging update

scripts/install-server.sh

@@ -117,6 +117,7 @@ WantedBy=multi-user.target
 UNIT
 
 echo "==> 6c. Systemd units - initialization"
+sudo truncate -s 0 /tmp/lesavka-server.log
 sudo systemctl daemon-reload
 sudo systemctl enable --now lesavka-core
 sudo systemctl restart lesavka-core

server/src/main.rs

@@ -1,4 +1,4 @@
-//! lesavka-server — receive HidReport and write to /dev/hidg0
+//! lesavka-server
 // sever/src/main.rs
 #![forbid(unsafe_code)]
 
@@ -27,7 +27,7 @@ use lesavka_common::lesavka::{
 fn init_tracing() -> anyhow::Result<WorkerGuard> {
     // 1. create file writer + guard
     let file = std::fs::OpenOptions::new()
-        .create(true).write(true).truncate(true)
+        .create(true).write(true).append(true)
         .open("/tmp/lesavka-server.log")?;
     let (file_writer, guard) = non_blocking(file);
 
@@ -53,8 +53,9 @@ fn init_tracing() -> anyhow::Result<WorkerGuard> {
 async fn open_with_retry(
     path: &str,
     retries: usize,
-    delay_ms: u64,
+    base_delay_ms: u64,
 ) -> anyhow::Result<tokio::fs::File> {
+    let start = std::time::Instant::now();
     for attempt in 0..=retries {
         match OpenOptions::new()
             .write(true)
@@ -63,15 +64,24 @@ async fn open_with_retry(
             .await
         {
             Ok(f) => {
-                info!("✅ opened {path} ✅ after {attempt} attempt(s)");
+                info!("✅ opened {path} (attempt {attempt}, {} ms)",
+                      start.elapsed().as_millis());
                 return Ok(f);
             }
             Err(e) if attempt < retries => {
-                warn!("🕒 {path} not ready ({e:?}); retry {attempt}/{retries}");
+                let delay = base_delay_ms * 2u64.saturating_pow(attempt as u32);
-                tokio::time::sleep(Duration::from_millis(delay_ms)).await;
+                warn!(
+                    "🕒 {path} busy: {e:?}; holders=[{}]; retry {attempt}/{retries} in {delay} ms",
+                    owners_of(path)
+                );
+                tokio::time::sleep(Duration::from_millis(delay)).await;
             }
             Err(e) => {
-                error!("💥 giving up on {path}: {e:?}");
+                error!(
+                    "💥 all retries exhausted for {path} ({} ms): {e:?}; holders=[{}]",
+                    start.elapsed().as_millis(),
+                    owners_of(path)
+                );
                 return Err(e).with_context(|| format!("opening {path}"));
             }
         }
@@ -79,6 +89,32 @@ async fn open_with_retry(
     unreachable!()
 }
 
+fn owners_of(path: &str) -> String {
+    use std::{fs, os::unix::fs::MetadataExt};
+
+    let Ok(target_ino) = fs::metadata(path).map(|m| m.ino()) else { return "-".into() };
+
+    let mut pids = Vec::new();
+    if let Ok(entries) = fs::read_dir("/proc") {
+        for e in entries.flatten() {
+            let file_name = e.file_name();
+            let pid = file_name.to_string_lossy().into_owned();
+            if !pid.chars().all(|c| c.is_ascii_digit()) { continue }
+
+            let fd_dir = e.path().join("fd");
+            for fd in fs::read_dir(fd_dir).into_iter().flatten().flatten() {
+                if let Ok(meta) = fd.metadata() {
+                    if meta.ino() == target_ino {
+                        pids.push(pid.to_string());
+                        break;
+                    }
+                }
+            }
+        }
+    }
+    if pids.is_empty() { "-".into() } else { pids.join(",") }
+}
+
 /*─────────────────── tonic service ─────────────────────*/
 struct Handler {
     kb: Arc<Mutex<tokio::fs::File>>,
@@ -91,7 +127,7 @@ impl Handler {
     async fn make(gadget: UsbGadget) -> anyhow::Result<Self> {
         info!("🛠️  Handler::make - cycling gadget ...");
         gadget.cycle()?;
-        tokio::time::sleep(Duration::from_millis(500)).await;
+        tokio::time::sleep(Duration::from_millis(1000)).await;
 
         info!("🛠️  opening HID endpoints ...");
         let kb = open_with_retry("/dev/hidg0", 20, 50).await?;
@@ -211,7 +247,7 @@ impl Relay for Handler {
         }
         .to_string();
 
-        info!("🎥 streaming {dev} at ≤{} kb/s", r.max_bitrate);
+        info!("🎥 streaming {dev} at ≤{} kb/s", r.max_bitrate);
 
         let s = video::spawn_camera(&dev, r.id, r.max_bitrate)
             .await
@@ -250,7 +286,7 @@ async fn main() -> anyhow::Result<()> {
     //         loop {
     //             tokio::time::sleep(Duration::from_secs(4)).await;
     //             if LAST_HID_WRITE.elapsed().as_secs() > 3 {
-    //                 warn!("no HID traffic in 3 s - cycling UDC");
+    //                 warn!("no HID traffic in 3 s - cycling UDC");
     //                 let _ = gadget.cycle();
     //             }
     //         }

server/src/usb_gadget.rs

@@ -17,7 +17,7 @@ impl UsbGadget {
 
     /// Force the host to re‑enumerate our HID gadget.
     pub fn cycle(&self) -> Result<()> {
-        info!("UDC‑cycle: detaching gadget");
+        info!("🔌 UDC‑cycle: detaching gadget");
         OpenOptions::new().write(true).open(self.udc_file)?.write_all(b"")?;
         thread::sleep(Duration::from_millis(200));
 
@@ -26,10 +26,10 @@ impl UsbGadget {
             .transpose()?
             .context("no UDC present")?
             .file_name();
-        info!("UDC‑cycle: re‑attaching to {}", udc_name.to_string_lossy());
+        info!("🔌 UDC‑cycle: re‑attaching to {}", udc_name.to_string_lossy());
         OpenOptions::new().write(true).open(self.udc_file)?
             .write_all(udc_name.to_str().unwrap().as_bytes())?;
-        info!("USB‑gadget cycled");
+        info!("🔌 USB‑gadget cycled");
         Ok(())
     }
 }