DAP logging: Allow sending `tracing` data to DAP client Debug Console #2457

noppej · 2024-05-10T18:55:06Z

The mechanism of passing messages from the dap_server to the client via stderr is replaced with writing dap_server messages and tracing output to the DAP client's Debug Console, using the DAP Output event.

In addition to making message delivery more reliable, this also paves the way for a multi-session debugger, where each session can log their own messages to the corresponding client console.
Cleanup of messages relating to when PR Improve dap server logging #2331 changed the logging to be driven by log-file parameter.
To facilitate better testing, I took the liberty of downgrading some of our logging verbosity where calls such as Core::status were using tracing instrument spans with a default level of INFO (obviously caused a lot of noise).

bugadani · 2024-05-10T18:59:35Z

I'm not agains cleaning this up but I think it would be nice if we could figure out @Yatekii's difficulties logging probe-rs events to vscode in this same PR.

Reading through the changes, maybe this addresses the technicalities, but we should probably address the expectations, too.

noppej · 2024-05-10T19:14:50Z

As far as I know, there are two problems:

Improve dap server logging #2331 changed logging to depend on the --log-file command line parameter, but there was never any attempt to add support for this to the VSCode extension. I have just added Add support for --log-file and --log-dir options from probe-rs. vscode#91.
The error message was not updated and so it sends the user looking for RUST_LOG when the code is not driven by that. This PR will fix that.

noppej · 2024-05-10T19:42:10Z

but we should probably address the expectations, too.

@bugadani Can you clarify what you mean by this please?

bugadani · 2024-05-10T19:45:36Z

but we should probably address the expectations, too.

@bugadani Can you clarify what you mean by this please?

My (and Noah's and maybe more people's) expectation is that setting RUST_LOG will result in debug logs to be printed to Debug Console. The code currently hard-codes LogLevel::Error to stderr regardless of RUST_LOG. Should we add a third tracing subscriber that logs to stdout if the env variable is set?

noppej · 2024-05-10T20:05:16Z

but we should probably address the expectations, too.

@bugadani Can you clarify what you mean by this please?

My (and Noah's and maybe more people's) expectation is that setting RUST_LOG will result in debug logs to be printed to Debug Console. The code currently hard-codes LogLevel::Error to stderr regardless of RUST_LOG. Should we add a third tracing subscriber that logs to stdout if the env variable is set?

There are two tracing subscribers.

The stderr one which we need to pass essential errors to VSCode.
Whatever is set by RUST_LOG. It won't write that to Console Log, but it will write one of two things ...
a) Log output will be written to: "/Users/the_rock/dev/log.txt" if the user uses the --log-file option.
b) No logging data will be written because no log-file destination was specified. if the user uses the --log-dir option. I will fix this here
c) No logging data will be written because no log-file destination was specified. if neither the above are set.

Before the log to file was introduced, we used to log to the Debug Console. We can revert to that for (c) ... what do you think?

bugadani · 2024-05-10T20:11:52Z

Before the log to file was introduced, we used to log to the Debug Console. We can revert to that for (c) ... what do you think?

I think that sounds reasonable, especially if we document that setting any of the options disables log-to-console

noppej · 2024-05-20T20:55:49Z

@bugadani If you want to manually test this during review, please use the VS Code changes from probe-rs/vscode#94. Older versions should still work, but some messages will be duplicated.

probe-rs-debugger-0.23.0.vsix.zip

bugadani · 2024-05-21T07:04:38Z

probe-rs-tools/src/bin/probe-rs/cmd/dap_server/server/logger.rs

+        let read_from_log = self.buffer_file_handle()?;
+        let mut tracing_log_handle = BufReader::new(read_from_log.try_clone()?);
+        std::io::Seek::seek(&mut tracing_log_handle, self.seek_pointer)?;
+        let mut buffer_lines = tracing_log_handle.lines();
+        while let Some(Ok(next_line)) = buffer_lines.next() {


I think I understand what this wants to be, but I also think this is worth factoring out into its own function. The difference between flush and flush_to_dap is (or... seems to be) what happens with the log lines, and that single line could be passed in as a closure.

I tried that, but it means that I have to pass an Option<DebugAdapter<P>> to the combined flush function. That isn't a problem in itself, but the compiler wants you to add a type when you pass a None value, and for the life of me I couldn't make the syntax work. If you can make it work (you probably can), I'd appreciate the solution.

None::<type> :)

That being said I'm not sure we understand each other here, so this can go in as-is, and we can tackle this part later.

It requires all the generics in the type, and I can't remember what the error was, but it doesn't like None::<DapAdapter<P>> ... or any of the variants I could come up with :)

As I've said, I'm not sure at all what you're planning or why it needs a None. If you pass in a closure as I've suggested, the closure captures debug_adapter for you if you need to use it.

bugadani · 2024-05-21T07:07:54Z

probe-rs-tools/src/bin/probe-rs/cmd/dap_server/server/logger.rs

+    /// and will be automatically removed by the OS when the last handle to it is closed.
+    ///  - When the DAP server is running, the tracing messages are sent to the console.
+    ///  - When the DAP server exits, the remaining messages in this buffer are sent to `stderr`.
+    buffer_file: Mutex<File>,


Why does this have to be inside a mutex, if we're just cloning the file descriptor? We could save a lock, a try_clone and a bunch of error handling if this was just a File and if buffer_file_handle returned a &File.

The buffer file is used by the tracing implementation to write the logs to, as well as by the DebugLogger for both writing and reading. I need the lock so that I can write to the file, and then update the read pointer to make sure a future flush() knows where the last 'un-read' data was.

I need the lock

But you don't! The only .lock() here is when you clone the FD and the lock is immediately released. What am I not seeing?

That was not the intention. The intention was to hold onto the lock until I've finished updating the read pointers, but I see now that it is being released. Let me work with it a bit more before we merge.

A few things:

I think we should prefer parking_lot::Mutex, that does not return an error from lock. I'm not convinced we need to deal with poisoning here.

If you need the lock to stick for a bit, you can return impl Deref<Target = File>. That way the user (even if it's just us) doesn't have to know about the lock's internals, but the lock will be held as long as it's needed.

@bugadani I've made the changes to hold onto the MutexGuard until after I've updated the file pointers. I've done some manual testing with excessive amounts of log data being written to the Debug Console, and all seems to be in order. That said, I'd really appreciate if you can do a sanity check for me.

bugadani

The implementation looks to be on the more-complex-than-necessary side at points, but it also seems to be working well, so thanks!

I'm not sure this change deserves about 15 PR's worth of changelog, though 😅

noppej · 2024-05-21T13:09:07Z

The implementation looks to be on the more-complex-than-necessary side at points, but it also seems to be working well, so thanks!

It took a lot of wrangling to get the tracing implementation to share the file it write to. They take ownership of anything you pass in as a impl Write. I started off thinking this will be simple, and then had to build out complexity to avoid ownership and reference and runtime access collisions. As always, I'd be happy to incorporate suggestions.

I'm not sure this change deserves about 15 PR's worth of changelog, though 😅

Haha ... you know me, I can get a little verbose. I will trim the changelog :)

bugadani · 2024-05-21T14:37:51Z

probe-rs-tools/src/bin/probe-rs/cmd/dap_server/server/logger.rs

+    /// Try to clone the buffer file handle, so that it can be used by either
+    /// the DebugAdapter to send messages to the DAP client, or the `tracing` module to record log data.
+    pub(crate) fn buffer_file_handle(&self) -> Result<File, DebuggerError> {
+        self.locked_buffer_file()?.try_clone().map_err(|_| {


This will still allow racy access. If you really think we need the mutex, we should be working with an Arc<Mutex<File>> and clone the Arc, not the file.

…rements.

noppej · 2024-05-21T20:38:35Z

@bugadani Thank you very much for taking the time to collaborate on this. I feel much better about the quality of this.

Fix DAP logging message.

ef76bb7

noppej added the skip-changelog This PR does not require a changelog entry on release label May 10, 2024

noppej requested a review from bugadani May 10, 2024 18:55

noppej marked this pull request as draft May 10, 2024 20:12

noppej added 4 commits May 18, 2024 15:36

DAP server "tracing" output to Debug Console

ca0872b

Adjust expected messages for debugger tests plus cleanup.

2780a63

Move code from 'debugger' to 'configuration'.

f096524

Final cleanup after testing.

83fad00

noppej changed the title ~~Fix DAP logging message.~~ DAP logging: Allow sending tracing data to DAP client Debug Console May 20, 2024

noppej mentioned this pull request May 20, 2024

Adjust to dap_server changes to send errors via DAP vs stderr. probe-rs/vscode#94

Merged

noppej marked this pull request as ready for review May 20, 2024 20:56

bugadani reviewed May 21, 2024

View reviewed changes

bugadani approved these changes May 21, 2024

View reviewed changes

Trim changelog entry

4d000b2

noppej force-pushed the fix_dap_logging_message branch from c8abb66 to 4d000b2 Compare May 21, 2024 13:12

Merge branch 'master' into fix_dap_logging_message

ca784d0

noppej removed the skip-changelog This PR does not require a changelog entry on release label May 21, 2024

Hold onto the MutexGuard until after file pointer updates.

901b640

bugadani reviewed May 21, 2024

View reviewed changes

noppej added 2 commits May 21, 2024 11:05

Use parking_lot::Mutex and update comments to clarify locking requi…

3a5ca1d

…rements.

Change DebugLogger::buffer_file to Arc<Mutex<File>>

8756bf1

bugadani and others added 3 commits May 21, 2024 21:08

Pass a Mutex-wrapped handle to tracing_subscriber

dba6a1e

Don't lock around the callback, log to memory

987f7e2

Remove writing to log everytime we write a log :)

f36e5a7

noppej added 2 commits May 21, 2024 16:44

Make clippy happy

7560574

Merge branch 'master' into fix_dap_logging_message

33fc676

noppej enabled auto-merge May 21, 2024 21:12

noppej added this pull request to the merge queue May 21, 2024

Merged via the queue into master with commit df90aa8 May 21, 2024
19 checks passed

noppej deleted the fix_dap_logging_message branch May 21, 2024 21:19

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

DAP logging: Allow sending `tracing` data to DAP client Debug Console #2457

DAP logging: Allow sending `tracing` data to DAP client Debug Console #2457

noppej commented May 10, 2024 •

edited

bugadani commented May 10, 2024 •

edited

noppej commented May 10, 2024 •

edited

noppej commented May 10, 2024

bugadani commented May 10, 2024

noppej commented May 10, 2024

bugadani commented May 10, 2024

noppej commented May 20, 2024 •

edited

bugadani May 21, 2024

noppej May 21, 2024

bugadani May 21, 2024

bugadani May 21, 2024

noppej May 21, 2024

bugadani May 21, 2024

bugadani May 21, 2024

noppej May 21, 2024

bugadani May 21, 2024

noppej May 21, 2024

bugadani May 21, 2024

noppej May 21, 2024

bugadani left a comment

noppej commented May 21, 2024

bugadani May 21, 2024

noppej commented May 21, 2024

DAP logging: Allow sending tracing data to DAP client Debug Console #2457

DAP logging: Allow sending tracing data to DAP client Debug Console #2457

Conversation

noppej commented May 10, 2024 • edited

bugadani commented May 10, 2024 • edited

noppej commented May 10, 2024 • edited

noppej commented May 10, 2024

bugadani commented May 10, 2024

noppej commented May 10, 2024

bugadani commented May 10, 2024

noppej commented May 20, 2024 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bugadani left a comment

Choose a reason for hiding this comment

noppej commented May 21, 2024

Choose a reason for hiding this comment

noppej commented May 21, 2024

DAP logging: Allow sending `tracing` data to DAP client Debug Console #2457

DAP logging: Allow sending `tracing` data to DAP client Debug Console #2457

noppej commented May 10, 2024 •

edited

bugadani commented May 10, 2024 •

edited

noppej commented May 10, 2024 •

edited

noppej commented May 20, 2024 •

edited