Community.VisualStudio.Toolkit icon indicating copy to clipboard operation
Community.VisualStudio.Toolkit copied to clipboard

Logging Best Practices

Open niemyjski opened this issue 3 years ago • 5 comments

Is there documentation someplace that says the best way to do logging in Visual Studio?

Currently we are using this library to create an VS Output window pane and then calling Write (non async). We have a singleton logging service that uses this output window pane to log messages out to. The problem that we are seeing is tons of dead locks around this writing call due to:

  • We have wpf sync handlers calling this method which then does an async joinable task in the background..
  • We are kicking off new background threads / tasks for expensive work that logs which then joins via joinable task.
  • We don't know the calling context but more than likely background calls to do logging.

niemyjski avatar May 20 '22 14:05 niemyjski

We use SeriLog which gives us the flexibility of logging to a file, debugview. And logging to a VS Output window is done through a single object of the OutputWindowPane class in this toolkit using the WriteLineAsync method that switches to the main thread.

RobertvanderHulst avatar May 20 '22 14:05 RobertvanderHulst

We can't really take on any third-party dependencies for logging at this point unless critically necessary. Would you mind sharing your sink in the meantime?

niemyjski avatar May 23 '22 12:05 niemyjski

After some digging between what used to be happening and is that this library exposes the sync OutputWindowPane.WriteLine into the behind-the-scenes async call via ThreadHelper.JoinableTaskFactory.Run. This may be causing the deadlocks while it tries to swtich to the ui thread (Still tracking this one down)? However, in my previous implementation using VsXtra, it was calling into IVsOutputWindowPane.OutputStringThreadSafe which doesn't have these issues. I Get that I could call into this still via the Pane property but doesn't seem recommended way. It does solve all the dead lock issues.

It would be nice if one could write to the pane in sync or async fashion and then logs are periodically flushed out.

@madskristensen do you have any advice for best practices here? I have a ton of custom Logging Abstraction that I can't change out without massive amount of work and breaking api compat of a project that started ~20 years ago with massive amount of sdk consumers. It all just calls _pane.WriteLine(output); (in sync void methods).

niemyjski avatar May 24 '22 11:05 niemyjski

Looking at what others were doing I also came across this: https://github.com/madskristensen/VsixLogger/blob/master/src/Logger.cs#L43-L59 which is what we were doing.

niemyjski avatar May 24 '22 11:05 niemyjski

I'm not aware of any library that can handle buffering/flushing to the output window. It would be a good thing to have I assume, but I haven't heard of anyone having issues with this before.

madskristensen avatar May 24 '22 18:05 madskristensen