Add a live Logs window and a Verbose logging switch

crates/chatd/src/blobs.rs

@@ -9,8 +9,8 @@
 //!   shell sends for what is on screen; nothing is fetched ahead.
 //! - A picture asked for as a row's (its avatar, while the row is in `Watching.rows`) waits,
 //!   unfetched, once the row has scrolled away, and goes back in line when it is on screen again.
-//! - Each account's own picture (the rail's) is fetched when the account is signed in or starts,
-//!   and again on each connect if it is not on disk, without the shell asking.
+//! - Each account's own picture (the rail's) is fetched once the link is up, and again on each
+//!   connect if it is not on disk, without the shell asking. Not while the link is still down.
 //! - A picker's previews (stickers, GIF stills: ids made with [`pick`]) go to
 //!   `media/<network>/pick/<account>/`, are fetched only while the picker asks for them, and are
 //!   deleted when it closes ([`Blobs::picker_closed`], or [`PICK_IDLE`] without a request).
@@ -623,10 +623,11 @@ impl Cache {
         generation <= closed && !queue.picked.contains_key(account)
     }
 
-    /// Fetches each account's own picture (the rail's) when the account signs in or starts,
-    /// and on each connect if it is not on disk. Looks at the links every [`OWN_EVERY`] (one
-    /// lock); the store only while an account that just started or connected has not had its
-    /// picture asked for, for at most [`OWN_FOR`], since the adapter records us a little after.
+    /// Fetches each account's own picture (the rail's) once the link is up, and on each connect
+    /// if it is not on disk. Not while the link is still down: the adapter records who we are as
+    /// it connects and can replace the id the store already had. Looks at the links every
+    /// [`OWN_EVERY`] (one lock); the store only while an account that just connected has not had
+    /// its picture asked for, for at most [`OWN_FOR`], since the adapter records us a little after.
     fn own_pictures(&self) {
         struct Own {
             connected: bool,
@@ -660,6 +661,14 @@ impl Cache {
                 continue;
             };
             for (account, own) in seen.iter_mut().filter(|(_, own)| own.until.is_some()) {
+                // Offline, the store can still hold the picture from the last session, or from a
+                // test that seeded one. The adapter replaces that id as it connects (Discord's
+                // READY does). Fetching now takes the stale picture, and the connect that follows
+                // takes the real one: two downloads of "the" picture. Wait until the link is up,
+                // which is also when that id is the one the rail will show.
+                if !own.connected {
+                    continue;
+                }
                 let Some(avatar) = accounts.iter().find(|row| row.key == *account).and_then(|row| row.avatar.clone()) else {
                     continue;
                 };

crates/chatd/src/media.rs

@@ -800,6 +800,21 @@ impl Calls {
         }
     }
 
+    /// Verbose logging changed: the call's mediad, or the test's, logs at the new ceiling from
+    /// its next line. A mediad started later reads it from its environment (`share_session`).
+    pub fn relevel(&self) {
+        let Some(guard) = protocol::log_policy::current() else {
+            return;
+        };
+        let level = MediaRequest::LogLevel { level: guard.policy().level_word().to_owned() };
+        if let Some(active) = crate::hub::lock(&self.slot).running() {
+            let _ = active.request(&level);
+        }
+        if let Some(tester) = crate::hub::lock(&self.tester).as_mut() {
+            let _ = tester.send(&level);
+        }
+    }
+
     /// V1 or V2 changed: the call's mediad, or the test's, opens the new choice at once, and
     /// the next call starts with it too.
     pub fn redevice(&self, hub: &Hub) {

crates/chatd/src/server.rs

@@ -420,6 +420,8 @@ impl Chat {
             | settings::NOISE_SUPPRESSION
             | settings::AUTO_GAIN => self.hub.calls.retune(&self.hub),
             settings::INPUT | settings::OUTPUT => self.hub.calls.redevice(&self.hub),
+            // `set_setting` has already moved chatd's own ceiling.
+            settings::LOG_LEVEL => self.hub.calls.relevel(),
             _ => {}
         }
         Response::Ok
@@ -434,6 +436,7 @@ impl Chat {
         self.hub.prune_soon();
         self.hub.calls.retune(&self.hub);
         self.hub.calls.redevice(&self.hub);
+        self.hub.calls.relevel();
         Response::Ok
     }
 

crates/chatd/tests/playback.rs

@@ -213,7 +213,10 @@ fn a_pause_lets_the_process_go_and_play_goes_on_from_there() {
     sleep(Duration::from_millis(400));
     world.ask(PlayRequest::Pause).unwrap();
     let paused = world.until_state(PlayState::Paused);
-    assert!((250..=600).contains(&paused.at), "paused at {}", paused.at);
+    // 400 ms asleep, plus where mediad already was, plus a little scheduler slack. 600 was two
+    // milliseconds short on a loaded macOS runner (paused at 602). Still well before the end of
+    // the one-second file.
+    assert!((250..=750).contains(&paused.at), "paused at {}", paused.at);
     until_no_mediad();
     let at = world.shown().unwrap().at;
     assert_eq!(world.shown().unwrap().position(u64::MAX), at, "a paused position does not move");

crates/mediad/src/lib.rs

@@ -58,3 +58,11 @@ pub const CHANNELS: usize = 2;
 pub const FRAME: usize = 960;
 /// Interleaved samples in one frame.
 pub const FRAME_SAMPLES: usize = FRAME * CHANNELS;
+
+/// chatd's Verbose logging changed while this mediad runs (`MediaRequest::LogLevel`): the file
+/// takes the new ceiling from the next line. An unknown word leaves it as it was.
+pub fn relevel(level: &str) {
+    if let Some(guard) = protocol::log_policy::current() {
+        guard.apply(guard.policy().overlay_stored(Some(level), None, None));
+    }
+}

crates/mediad/src/probe.rs

@@ -90,6 +90,7 @@ pub fn run() {
                             out::send(&MediaResponse::LogsSaved { path });
                             continue;
                         }
+                        MediaRequest::LogLevel { level } => crate::relevel(&level),
                         _ => {
                             out::send(&MediaResponse::Refused { detail: "There is no call.".to_owned() });
                             continue;

crates/mediad/src/serve.rs

@@ -314,6 +314,10 @@ impl Call {
                     .unwrap_or_default();
                 return MediaResponse::LogsSaved { path };
             }
+            MediaRequest::LogLevel { level } => {
+                crate::relevel(&level);
+                return MediaResponse::Done;
+            }
         }
         MediaResponse::Streams { video: self.video.streams() }
     }

crates/protocol/src/call.rs

@@ -429,6 +429,10 @@ pub enum MediaRequest {
     Loopback { on: bool },
     /// Write mediad's debug ring. Answered `LogsSaved`.
     SaveLogs,
+    /// The log ceiling changed in chatd's settings (Verbose logging): `error`, `warn`, `info`,
+    /// `debug` or `trace`, as `settings::LOG_LEVEL` holds it. Answered `Done`; an unknown word
+    /// changes nothing.
+    LogLevel { level: String },
 }
 
 /// The loudest one participant may be set, in percent.

crates/protocol/src/log_policy.rs

@@ -149,6 +149,16 @@ impl LogPolicy {
         self.operator
     }
 
+    /// The operator ceiling as a stored setting would name it: `debug`, `info`, ...
+    pub fn level_word(&self) -> &'static str {
+        level_name(self.operator)
+    }
+
+    /// Whether the files carry debug lines: Verbose logging, or `TINYCLIENT_LOG_LEVEL=debug`.
+    pub fn verbose(&self) -> bool {
+        self.operator >= Level::DEBUG
+    }
+
     pub fn ring_enabled(&self) -> bool {
         self.ring
     }
@@ -297,9 +307,14 @@ pub fn adopt_session(id: &str) {
 }
 
 /// Puts this process's session on a child. chatd generates the id in memory when nothing
-/// set the variable, so inheritance alone would give mediad and login a different one.
+/// set the variable, so inheritance alone would give mediad and login a different one. The
+/// ceiling goes too: a stored Verbose logging lives in chatd's settings, which a helper never
+/// reads, so a mediad started after it was turned on starts at debug.
 pub fn share_session(command: &mut std::process::Command) {
     command.env("TINYCLIENT_SESSION", session_id());
+    if let Some(guard) = current() {
+        command.env("TINYCLIENT_LOG_LEVEL", guard.policy().level_word());
+    }
 }
 
 fn load_session() -> String {
@@ -623,8 +638,19 @@ pub struct LogGuard {
 
 impl LogGuard {
     /// Replaces the ceilings and the export flag. The open file stays open.
+    /// A new operator ceiling is written to the file, so the Logs window shows Verbose logging
+    /// taking hold in each process.
     pub fn apply(&self, policy: LogPolicy) {
-        *self.policy.lock().unwrap_or_else(|err| err.into_inner()) = policy;
+        let before = std::mem::replace(&mut *self.policy.lock().unwrap_or_else(|err| err.into_inner()), policy);
+        if before.operator != policy.operator {
+            // Under the new ceiling, so at warn when that is quieter than info.
+            let line = format!("{}: log level is now {}", self.process, policy.level_word());
+            if policy.operator >= Level::INFO {
+                tracing::info!("{line}");
+            } else {
+                tracing::warn!("{line}");
+            }
+        }
     }
 
     pub fn policy(&self) -> LogPolicy {
@@ -887,6 +913,26 @@ mod tests {
         assert!(!off.export_enabled());
     }
 
+    #[test]
+    fn verbose_is_debug_or_more_and_the_word_round_trips() {
+        for (word, verbose) in [("error", false), ("warn", false), ("info", false), ("debug", true), ("trace", true)] {
+            let policy = LogPolicy::policy_from_values(Some(word), None, None);
+            assert_eq!(policy.verbose(), verbose, "{word}");
+            assert_eq!(policy.level_word(), word);
+        }
+        let raised = LogPolicy::default().overlay_stored(Some("debug"), None, None);
+        assert!(raised.verbose() && raised.ring_enabled());
+    }
+
+    #[test]
+    fn a_log_level_request_reads_and_an_older_frame_still_does() {
+        let request = crate::MediaRequest::LogLevel { level: "debug".to_owned() };
+        let text = serde_json::to_string(&request).unwrap_or_default();
+        assert_eq!(text, r#"{"media":"log_level","level":"debug"}"#);
+        assert_eq!(serde_json::from_str::<crate::MediaRequest>(&text).ok(), Some(request));
+        assert_eq!(serde_json::from_str::<crate::MediaRequest>(r#"{"media":"save_logs"}"#).ok(), Some(crate::MediaRequest::SaveLogs));
+    }
+
     #[test]
     fn log_settings_default_and_reject_garbage() {
         assert_eq!(LogPolicy::apply_settings("", "", "").operator_level(), Level::INFO);

crates/tinyclient/src/gui/app/menubar.rs

@@ -128,6 +128,7 @@ pub fn menus(places: &[(String, usize)], open_network: Option<Network>, update_i
         Menu::new("Help").items([
             MenuItem::action("Keyboard Shortcuts", KeyboardShortcuts),
             MenuItem::action("Copy Diagnostics", CopyDiagnostics),
+            MenuItem::action("Logs", ShowLogs),
         ]),
     ]
 }
@@ -152,7 +153,9 @@ pub fn bind_keys(cx: &mut App) {
         KeyBinding::new("alt-secondary-o", OpenInNetwork, None),
         KeyBinding::new("secondary-m", Minimize, None),
         KeyBinding::new("secondary-/", KeyboardShortcuts, None),
+        KeyBinding::new("secondary-shift-l", ShowLogs, None),
     ]);
+    super::super::logs::bind_keys(cx);
     // Hiding is macOS's. Linux ignores it, and GPUI on Windows panics at Hide Others.
     if cfg!(target_os = "macos") {
         cx.bind_keys([KeyBinding::new("secondary-h", Hide, None), KeyBinding::new("alt-secondary-h", HideOthers, None)]);
@@ -222,6 +225,7 @@ pub fn app_actions(cx: &mut App) {
         .detach();
     });
     cx.on_action(|_: &KeyboardShortcuts, cx| settings::open(settings::Section::Shortcuts, cx));
+    cx.on_action(|_: &ShowLogs, cx| super::super::logs::open(cx));
 }
 
 impl Shell {