worlds simplest logging to see where things are blocked by alexhancock · Pull Request #3888 · block/goose

alexhancock · 2025-08-06T15:10:19Z

A commit from @michaelneale - worlds simplest logging to see where things are blocked

Can help us diagnose where and when goose stalls in its interactions with LLMs and during tool calling

DOsinga

we should probably not write to /tmp as that doesn't exist on windows. I also wonder if we are not better off dumping to a known log file location and just dump the json we send to the LLM (we now have a central ApiClient so that should be doable) and then add a short cut to the desktop to "download" that file to share

github-actions · 2025-08-06T17:47:23Z

PR Preview Action v1.6.0
🚀 View preview at https://block.github.io/goose/pr-preview/pr-3888/
Built to branch `gh-pages` at 2025-08-06 19:25 UTC. Preview will be ready when the GitHub Pages deployment is complete.

DOsinga · 2025-08-06T17:50:49Z

/cc @baxen who mentioned he was looking at something similar

alexhancock · 2025-08-07T15:32:26Z

@DOsinga feedback addressed, and some other logging related code has been deduped. Let me know what you think.

DOsinga

+1 on simplifying this all, but am not sure why we need our own logger here rather than just going with what tracing already gives us

DOsinga · 2025-08-07T17:14:40Z

crates/goose-cli/src/logging.rs


 /// Internal function that allows specifying a custom date string for testing
+#[cfg(test)]
 fn get_log_directory_with_date(test_date: Option<String>) -> Result<PathBuf> {


I would be supportive of killing the whole with date thing here. we only use it in a test that I stared at for a bit and am not really sure about what it is trying to accomplish. I think the simplifying you are doing here is great and I'd rather double down on that and then see what we need in testing on the goose level rather than here

DOsinga · 2025-08-07T17:18:21Z

crates/goose/src/logging.rs

+    };
+
+    // Ensure log directory exists
+    fs::create_dir_all(&log_dir).context("Failed to create log directory")?;


remove the comment

DOsinga · 2025-08-07T17:27:29Z

crates/goose/src/debug_logger.rs

+///
+/// * `event` - The event string to log
+/// ```
+pub fn log_debug_event(event: &str) {


why are we rolling our own log thing here and not just rely on tracing::debug!() for this?

mostly as I don't know how/when that works (but yeah should use it) - trace can be written (unbuffered?) to a file? (really want to avoid buffering in case anything is getting lost) so you can watch it in real time

tracing is the library meant for this as far as I know. writing a good logger is not trivial, so relying on something that exist and that we already use is probably the way to go

where I think we should focus our attention is on tooling around it; we write json files to the current logs, can we have something that inspects them live? some light python tooling could be super useful

jamadeo · 2025-08-14T16:11:30Z

@alexhancock @michaelneale I'd also prefer we stick to the tracing crate for this. The subscriber config might be what's making it less useful, but if so we should fix it there.

jamadeo · 2025-08-14T16:14:47Z

crates/goose/src/agents/agent.rs

        }

+        log_debug_event(&format!("WAITING_TOOL_START: {}", tool_call.name));
+


the existing #[instrument] should in theory give us what we want here -- if we want to isolate this part of the function there can be an added span!(...) here

jamadeo · 2025-08-14T16:15:43Z

crates/goose/src/agents/reply_parts.rs

        let mut stream = if provider.supports_streaming() {
-            provider
+            log_debug_event("WAITING_LLM_STREAM_START");
+            let stream = provider


we might be missing an #[instrument] on the streaming function, although I think that would only give us time-to-first-token.

michaelneale

I think ok when you think it is ready @alexhancock - unless there is another way, we do need to dive into this one way or another

alexhancock · 2025-09-03T23:37:13Z

@michaelneale I let this one languish a bit, sorry. I agree we need it.

Let me come back and do a simpler one similar to your original shortly.

jamadeo · 2025-09-04T16:10:12Z

plan.md

@@ -0,0 +1,8 @@
+Logging


Probably didn't mean to commit this

A constant struggle, as I often use goose run -i plan.md then forget them. Will remove!

jamadeo · 2025-09-04T16:12:35Z

crates/goose/src/logging.rs

+        if cfg!(windows) {
+            env::set_var("USERPROFILE", temp_dir.path());
+        } else {
+            env::set_var("HOME", temp_dir.path());


I think tests that set env vars can cause issues, also this one doesn't seem to restore it to what it was before. At minimum probably needs a #[serial] if we must set them

if we really want to unit test these, maybe have the main one read $HOME and pass that to another fn that we actually test. get_base_log_directory looks like it doesn't need to be pub, so you'd only need to do this in one place

Folded get_base_log_directory into the other method, and simplified the testing overall

Co-authored-by: Michael Neale <michael.neale@gmail.com>

alexhancock · 2025-09-04T17:51:29Z

I think ok when you think it is ready @alexhancock - unless there is another way, we do need to dive into this one way or another

This is in now @michaelneale

* main: feat: make tests for rmcp based developer server consistent with former implementation (#4519) worlds simplest logging to see where things are blocked (#3888) docs: update quickstart and install topics (#4378) feat: Add configurable Bedrock retry parameters (#4316) remove localstorage getconfig fallbacks (#4432) chore(deps-dev): bump electron from 37.2.6 to 37.4.0 in /ui/desktop (#4516) Fix databricks streaming errors (#4506) docs: malware check for uvx and npx extensions (#4508)

* 'main' of github.com:block/goose: docs: add ampersand to link (#4560) Add video link to README for user guidance (#4553) docs: social channels (#4552) feat: simplify navigation, make reload work (#4498) docs: new recipe warning (#4545) Add AGENTS.md for AI coding assistant support (#4539) docs: non-interactive compact now (#4543) fixed css classes and added some accessibility fixes (#4492) feat(acp): Read files (#4531) Add YouTube Short to Auto Visualiser Tutorial (#4536) Fix/settings page (#4520) update to RMCP 0.6.2 (#4523) docs: nested goosehints (#4528) feat: Agent Client Protocol implementation of goose (#4511) feat: make tests for rmcp based developer server consistent with former implementation (#4519) worlds simplest logging to see where things are blocked (#3888) docs: update quickstart and install topics (#4378) feat: Add configurable Bedrock retry parameters (#4316) remove localstorage getconfig fallbacks (#4432) chore(deps-dev): bump electron from 37.2.6 to 37.4.0 in /ui/desktop (#4516)

* main: (43 commits) feat: add auto-compact threshold configuration UI (block#4178) Add container detection to developer extension (block#4559) docs: add ampersand to link (block#4560) Add video link to README for user guidance (block#4553) docs: social channels (block#4552) feat: simplify navigation, make reload work (block#4498) docs: new recipe warning (block#4545) Add AGENTS.md for AI coding assistant support (block#4539) docs: non-interactive compact now (block#4543) fixed css classes and added some accessibility fixes (block#4492) feat(acp): Read files (block#4531) Add YouTube Short to Auto Visualiser Tutorial (block#4536) Fix/settings page (block#4520) update to RMCP 0.6.2 (block#4523) docs: nested goosehints (block#4528) feat: Agent Client Protocol implementation of goose (block#4511) feat: make tests for rmcp based developer server consistent with former implementation (block#4519) worlds simplest logging to see where things are blocked (block#3888) docs: update quickstart and install topics (block#4378) feat: Add configurable Bedrock retry parameters (block#4316) ...

Co-authored-by: Michael Neale <michael.neale@gmail.com> Signed-off-by: Matt Donovan <mattddonovan@protonmail.com>

Co-authored-by: Michael Neale <michael.neale@gmail.com> Signed-off-by: HikaruEgashira <hikaru-egashira@c-fo.com>

DOsinga reviewed Aug 6, 2025

View reviewed changes

alexhancock force-pushed the micn/simple-log-wait branch 2 times, most recently from 5d2345e to 5210a91 Compare August 6, 2025 17:07

alexhancock force-pushed the micn/simple-log-wait branch 9 times, most recently from 76ddd27 to 2f22fd3 Compare August 7, 2025 15:03

alexhancock requested review from DOsinga, angelahning and michaelneale August 7, 2025 16:37

DOsinga reviewed Aug 7, 2025

View reviewed changes

noahsprent mentioned this pull request Aug 8, 2025

Extensions lead to silent errors/slowdowns #3945

Closed

jamadeo requested changes Aug 14, 2025

View reviewed changes

alexhancock force-pushed the micn/simple-log-wait branch 2 times, most recently from a74aa1a to d36423a Compare August 26, 2025 14:40

alexhancock marked this pull request as draft August 26, 2025 14:46

alexhancock force-pushed the micn/simple-log-wait branch from d36423a to 6da7a55 Compare August 27, 2025 18:44

michaelneale approved these changes Sep 3, 2025

View reviewed changes

alexhancock force-pushed the micn/simple-log-wait branch 2 times, most recently from 3da4956 to 10e003c Compare September 4, 2025 14:54

alexhancock force-pushed the micn/simple-log-wait branch 3 times, most recently from a9bb6b0 to e24eea5 Compare September 4, 2025 15:33

alexhancock requested review from jamadeo and michaelneale September 4, 2025 15:34

alexhancock marked this pull request as ready for review September 4, 2025 15:34

jamadeo approved these changes Sep 4, 2025

View reviewed changes

feat(logging): add diagnostic logging for llm and tool interactions

a4f628b

Co-authored-by: Michael Neale <michael.neale@gmail.com>

alexhancock force-pushed the micn/simple-log-wait branch from e24eea5 to a4f628b Compare September 4, 2025 17:13

alexhancock merged commit 9da3350 into main Sep 4, 2025
11 checks passed

alexhancock deleted the micn/simple-log-wait branch September 4, 2025 17:51

alexhancock mentioned this pull request Sep 4, 2025

goose gets stuck even on non-blocking requests #4513

Closed

This was referenced Sep 9, 2025

chore(release): release version 1.8.0 #4572

Closed

release/1.8.0 #4577

Merged

HikaruEgashira pushed a commit to HikaruEgashira/goose that referenced this pull request Oct 3, 2025

worlds simplest logging to see where things are blocked (block#3888)

5808091

Co-authored-by: Michael Neale <michael.neale@gmail.com> Signed-off-by: HikaruEgashira <hikaru-egashira@c-fo.com>

		}

		log_debug_event(&format!("WAITING_TOOL_START: {}", tool_call.name));

Conversation

alexhancock commented Aug 6, 2025

Uh oh!

DOsinga left a comment

Choose a reason for hiding this comment

Uh oh!

github-actions bot commented Aug 6, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Built to branch gh-pages at 2025-08-06 19:25 UTC. Preview will be ready when the GitHub Pages deployment is complete.

Uh oh!

DOsinga commented Aug 6, 2025

Uh oh!

alexhancock commented Aug 7, 2025

Uh oh!

DOsinga left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jamadeo commented Aug 14, 2025

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

michaelneale left a comment

Choose a reason for hiding this comment

Uh oh!

alexhancock commented Sep 3, 2025

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

alexhancock commented Sep 4, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

github-actions bot commented Aug 6, 2025 •

edited

Loading

Built to branch `gh-pages` at 2025-08-06 19:25 UTC.
Preview will be ready when the GitHub Pages deployment is complete.