Split debug logging into debug and trace log levels.

lateralusX · lateralusX · commit ff7d474f034c · 2021-04-15T20:31:17.000+02:00
diff --git a/src/Microsoft.Diagnostics.NETCore.Client/DiagnosticsServerRouter/DiagnosticsServerRouterFactory.cs b/src/Microsoft.Diagnostics.NETCore.Client/DiagnosticsServerRouter/DiagnosticsServerRouterFactory.cs
@@ -177,7 +177,6 @@ protected async Task<Stream> AcceptTcpStreamAsync(CancellationToken token)
                 if (connectTimeoutTokenSource.IsCancellationRequested)
                 {
                     Logger.LogDebug("No tcp stream connected before timeout.");
-
                     throw new BackendStreamTimeoutException(TcpServerTimeoutMs);
                 }
 
@@ -476,7 +475,6 @@ protected async Task<Stream> AcceptIpcStreamAsync(CancellationToken token)
                 if (connectTimeoutTokenSource.IsCancellationRequested)
                 {
                     Logger.LogDebug("No ipc stream connected, timing out.");
-
                     throw new TimeoutException();
                 }
 
@@ -641,11 +639,10 @@ protected async Task<Stream> ConnectIpcStreamAsync(CancellationToken token)
                         if (connectTimeoutTokenSource.IsCancellationRequested)
                         {
                             Logger.LogDebug("No ipc stream connected, timing out.");
-
                             throw new TimeoutException();
                         }
 
-                        Logger.LogDebug($"Failed connecting {_ipcClientPath}, wait {IpcClientRetryTimeoutMs} ms before retrying.");
+                        Logger.LogTrace($"Failed connecting {_ipcClientPath}, wait {IpcClientRetryTimeoutMs} ms before retrying.");
 
                         // If we get an error (without hitting timeout above), most likely due to unavailable listener.
                         // Delay execution to prevent to rapid retry attempts.
@@ -785,8 +782,8 @@ public void Dispose()
 
                 Interlocked.Decrement(ref s_routerInstanceCount);
 
-                _logger.LogDebug($"Diposed stats: Backend->Frontend {_backendToFrontendByteTransfer} bytes, Frontend->Backend {_frontendToBackendByteTransfer} bytes.");
-                _logger.LogDebug($"Active instances: {s_routerInstanceCount}");
+                _logger.LogTrace($"Diposed stats: Backend->Frontend {_backendToFrontendByteTransfer} bytes, Frontend->Backend {_frontendToBackendByteTransfer} bytes.");
+                _logger.LogTrace($"Active instances: {s_routerInstanceCount}");
             }
         }
 
@@ -797,35 +794,35 @@ async Task BackendReadFrontendWrite(CancellationToken token)
                 byte[] buffer = new byte[1024];
                 while (!token.IsCancellationRequested)
                 {
-                    _logger.LogDebug("Start reading bytes from backend.");
+                    _logger.LogTrace("Start reading bytes from backend.");
 
                     int bytesRead = await _backendStream.ReadAsync(buffer, 0, buffer.Length, token).ConfigureAwait(false);
 
-                    _logger.LogDebug($"Read {bytesRead} bytes from backend.");
+                    _logger.LogTrace($"Read {bytesRead} bytes from backend.");
 
                     // Check for end of stream indicating that remote end hung-up.
                     if (bytesRead == 0)
                     {
-                        _logger.LogDebug("Backend hung up.");
+                        _logger.LogTrace("Backend hung up.");
                         break;
                     }
 
                     _backendToFrontendByteTransfer += (ulong)bytesRead;
 
-                    _logger.LogDebug($"Start writing {bytesRead} bytes to frontend.");
+                    _logger.LogTrace($"Start writing {bytesRead} bytes to frontend.");
 
                     await _frontendStream.WriteAsync(buffer, 0, bytesRead, token).ConfigureAwait(false);
                     await _frontendStream.FlushAsync().ConfigureAwait(false);
 
-                    _logger.LogDebug($"Wrote {bytesRead} bytes to frontend.");
+                    _logger.LogTrace($"Wrote {bytesRead} bytes to frontend.");
                 }
             }
             catch (Exception)
             {
                 // Completing task will trigger dispose of instance and cleanup.
                 // Faliure mainly consists of closed/disposed streams and cancelation requests.
                 // Just make sure task gets complete, nothing more needs to be in response to these exceptions.
-                _logger.LogDebug("Failed stream operation. Completing task.");
+                _logger.LogTrace("Failed stream operation. Completing task.");
             }
 
             RouterTaskCompleted?.TrySetResult(true);
@@ -838,35 +835,35 @@ async Task FrontendReadBackendWrite(CancellationToken token)
                 byte[] buffer = new byte[1024];
                 while (!token.IsCancellationRequested)
                 {
-                    _logger.LogDebug("Start reading bytes from frotend.");
+                    _logger.LogTrace("Start reading bytes from frotend.");
 
                     int bytesRead = await _frontendStream.ReadAsync(buffer, 0, buffer.Length, token).ConfigureAwait(false);
 
-                    _logger.LogDebug($"Read {bytesRead} bytes from frontend.");
+                    _logger.LogTrace($"Read {bytesRead} bytes from frontend.");
 
                     // Check for end of stream indicating that remote end hung-up.
                     if (bytesRead == 0)
                     {
-                        _logger.LogDebug("Frontend hung up.");
+                        _logger.LogTrace("Frontend hung up.");
                         break;
                     }
 
                     _frontendToBackendByteTransfer += (ulong)bytesRead;
 
-                    _logger.LogDebug($"Start writing {bytesRead} bytes to backend.");
+                    _logger.LogTrace($"Start writing {bytesRead} bytes to backend.");
 
                     await _backendStream.WriteAsync(buffer, 0, bytesRead, token).ConfigureAwait(false);
                     await _backendStream.FlushAsync().ConfigureAwait(false);
 
-                    _logger.LogDebug($"Wrote {bytesRead} bytes to backend.");
+                    _logger.LogTrace($"Wrote {bytesRead} bytes to backend.");
                 }
             }
             catch (Exception)
             {
                 // Completing task will trigger dispose of instance and cleanup.
                 // Faliure mainly consists of closed/disposed streams and cancelation requests.
                 // Just make sure task gets complete, nothing more needs to be in response to these exceptions.
-                _logger.LogDebug("Failed stream operation. Completing task.");
+                _logger.LogTrace("Failed stream operation. Completing task.");
             }
 
             RouterTaskCompleted?.TrySetResult(true);
diff --git a/src/Tools/dotnet-dsrouter/DiagnosticsServerRouterCommands.cs b/src/Tools/dotnet-dsrouter/DiagnosticsServerRouterCommands.cs
@@ -47,18 +47,24 @@ public DiagnosticsServerRouterCommands()
         {
         }
 
-        public async Task<int> RunIpcClientTcpServerRouter(CancellationToken token, string ipcClient, string tcpServer, int runtimeTimeout, bool verbose)
+        public async Task<int> RunIpcClientTcpServerRouter(CancellationToken token, string ipcClient, string tcpServer, int runtimeTimeout, string verbose)
         {
             checkLoopbackOnly(tcpServer);
 
             using CancellationTokenSource cancelRouterTask = new CancellationTokenSource();
             using CancellationTokenSource linkedCancelToken = CancellationTokenSource.CreateLinkedTokenSource(token, cancelRouterTask.Token);
 
+            LogLevel logLevel = LogLevel.Information;
+            if (string.Compare(verbose, "debug", StringComparison.OrdinalIgnoreCase) == 0)
+                logLevel = LogLevel.Debug;
+            else if (string.Compare(verbose, "trace", StringComparison.OrdinalIgnoreCase) == 0)
+                logLevel = LogLevel.Trace;
+
             using var factory = new LoggerFactory();
-            factory.AddConsole(verbose ? LogLevel.Debug : LogLevel.Information, false);
+            factory.AddConsole(logLevel, false);
 
             Launcher.SuspendProcess = true;
-            Launcher.Verbose = verbose;
+            Launcher.Verbose = logLevel != LogLevel.Information;
             Launcher.CommandToken = token;
 
             var routerTask = DiagnosticsServerRouterRunner.runIpcClientTcpServerRouter(linkedCancelToken.Token, ipcClient, tcpServer, runtimeTimeout == Timeout.Infinite ? runtimeTimeout : runtimeTimeout * 1000, factory.CreateLogger("dotnet-dsrounter"), Launcher);
@@ -83,18 +89,24 @@ public async Task<int> RunIpcClientTcpServerRouter(CancellationToken token, stri
             return routerTask.Result;
         }
 
-        public async Task<int> RunIpcServerTcpServerRouter(CancellationToken token, string ipcServer, string tcpServer, int runtimeTimeout, bool verbose)
+        public async Task<int> RunIpcServerTcpServerRouter(CancellationToken token, string ipcServer, string tcpServer, int runtimeTimeout, string verbose)
         {
             checkLoopbackOnly(tcpServer);
 
             using CancellationTokenSource cancelRouterTask = new CancellationTokenSource();
             using CancellationTokenSource linkedCancelToken = CancellationTokenSource.CreateLinkedTokenSource(token, cancelRouterTask.Token);
 
+            LogLevel logLevel = LogLevel.Information;
+            if (string.Compare(verbose, "debug", StringComparison.OrdinalIgnoreCase) == 0)
+                logLevel = LogLevel.Debug;
+            else if (string.Compare(verbose, "trace", StringComparison.OrdinalIgnoreCase) == 0)
+                logLevel = LogLevel.Trace;
+
             using var factory = new LoggerFactory();
-            factory.AddConsole(verbose ? LogLevel.Debug : LogLevel.Information, false);
+            factory.AddConsole(logLevel, false);
 
             Launcher.SuspendProcess = true;
-            Launcher.Verbose = verbose;
+            Launcher.Verbose = logLevel != LogLevel.Information;
             Launcher.CommandToken = token;
 
             var routerTask = DiagnosticsServerRouterRunner.runIpcServerTcpServerRouter(linkedCancelToken.Token, ipcServer, tcpServer, runtimeTimeout == Timeout.Infinite ? runtimeTimeout : runtimeTimeout * 1000, factory.CreateLogger("dotnet-dsrounter"), Launcher);
diff --git a/src/Tools/dotnet-dsrouter/Program.cs b/src/Tools/dotnet-dsrouter/Program.cs
@@ -17,8 +17,8 @@ namespace Microsoft.Diagnostics.Tools.DiagnosticsServerRouter
 {
     internal class Program
     {
-        delegate Task<int> DiagnosticsServerIpcClientTcpServerRouterDelegate(CancellationToken ct, string ipcClient, string tcpServer, int runtimeTimeoutS, bool verbose);
-        delegate Task<int> DiagnosticsServerIpcServerTcpServerRouterDelegate(CancellationToken ct, string ipcServer, string tcpServer, int runtimeTimeoutS, bool verbose);
+        delegate Task<int> DiagnosticsServerIpcClientTcpServerRouterDelegate(CancellationToken ct, string ipcClient, string tcpServer, int runtimeTimeoutS, string verbose);
+        delegate Task<int> DiagnosticsServerIpcServerTcpServerRouterDelegate(CancellationToken ct, string ipcServer, string tcpServer, int runtimeTimeoutS, string verbose);
 
         private static Command IpcClientTcpServerRouterCommand() =>
             new Command(
@@ -89,9 +89,9 @@ private static Option RuntimeTimeoutOption() =>
         private static Option VerboseOption() =>
             new Option(
                 aliases: new[] { "--verbose", "-v" },
-                description:    "Enable verbose logging.")
+                description:    "Enable verbose logging (debug|trace)")
             {
-                Argument = new Argument<bool>(name: "verbose", getDefaultValue: () => false)
+                Argument = new Argument<string>(name: "verbose", getDefaultValue: () => "")
             };
 
         private static int Main(string[] args)

Original file line number	Diff line number	Diff line change
`@@ -177,7 +177,6 @@ protected async Task<Stream> AcceptTcpStreamAsync(CancellationToken token)`
`177`	`177`	`if (connectTimeoutTokenSource.IsCancellationRequested)`
`178`	`178`	`{`
`179`	`179`	`Logger.LogDebug("No tcp stream connected before timeout.");`
`180`		`-`
`181`	`180`	`throw new BackendStreamTimeoutException(TcpServerTimeoutMs);`
`182`	`181`	`}`
`183`	`182`
`@@ -476,7 +475,6 @@ protected async Task<Stream> AcceptIpcStreamAsync(CancellationToken token)`
`476`	`475`	`if (connectTimeoutTokenSource.IsCancellationRequested)`
`477`	`476`	`{`
`478`	`477`	`Logger.LogDebug("No ipc stream connected, timing out.");`
`479`		`-`
`480`	`478`	`throw new TimeoutException();`
`481`	`479`	`}`
`482`	`480`
`@@ -641,11 +639,10 @@ protected async Task<Stream> ConnectIpcStreamAsync(CancellationToken token)`
`641`	`639`	`if (connectTimeoutTokenSource.IsCancellationRequested)`
`642`	`640`	`{`
`643`	`641`	`Logger.LogDebug("No ipc stream connected, timing out.");`
`644`		`-`
`645`	`642`	`throw new TimeoutException();`
`646`	`643`	`}`
`647`	`644`
`648`		`- Logger.LogDebug($"Failed connecting {_ipcClientPath}, wait {IpcClientRetryTimeoutMs} ms before retrying.");`
	`645`	`+ Logger.LogTrace($"Failed connecting {_ipcClientPath}, wait {IpcClientRetryTimeoutMs} ms before retrying.");`
`649`	`646`
`650`	`647`	`// If we get an error (without hitting timeout above), most likely due to unavailable listener.`
`651`	`648`	`// Delay execution to prevent to rapid retry attempts.`
`@@ -785,8 +782,8 @@ public void Dispose()`
`785`	`782`
`786`	`783`	`Interlocked.Decrement(ref s_routerInstanceCount);`
`787`	`784`
`788`		`- _logger.LogDebug($"Diposed stats: Backend->Frontend {_backendToFrontendByteTransfer} bytes, Frontend->Backend {_frontendToBackendByteTransfer} bytes.");`
`789`		`- _logger.LogDebug($"Active instances: {s_routerInstanceCount}");`
	`785`	`+ _logger.LogTrace($"Diposed stats: Backend->Frontend {_backendToFrontendByteTransfer} bytes, Frontend->Backend {_frontendToBackendByteTransfer} bytes.");`
	`786`	`+ _logger.LogTrace($"Active instances: {s_routerInstanceCount}");`
`790`	`787`	`}`
`791`	`788`	`}`
`792`	`789`
`@@ -797,35 +794,35 @@ async Task BackendReadFrontendWrite(CancellationToken token)`
`797`	`794`	`byte[] buffer = new byte[1024];`
`798`	`795`	`while (!token.IsCancellationRequested)`
`799`	`796`	`{`
`800`		`- _logger.LogDebug("Start reading bytes from backend.");`
	`797`	`+ _logger.LogTrace("Start reading bytes from backend.");`
`801`	`798`
`802`	`799`	`int bytesRead = await _backendStream.ReadAsync(buffer, 0, buffer.Length, token).ConfigureAwait(false);`
`803`	`800`
`804`		`- _logger.LogDebug($"Read {bytesRead} bytes from backend.");`
	`801`	`+ _logger.LogTrace($"Read {bytesRead} bytes from backend.");`
`805`	`802`
`806`	`803`	`// Check for end of stream indicating that remote end hung-up.`
`807`	`804`	`if (bytesRead == 0)`
`808`	`805`	`{`
`809`		`- _logger.LogDebug("Backend hung up.");`
	`806`	`+ _logger.LogTrace("Backend hung up.");`
`810`	`807`	`break;`
`811`	`808`	`}`
`812`	`809`
`813`	`810`	`_backendToFrontendByteTransfer += (ulong)bytesRead;`
`814`	`811`
`815`		`- _logger.LogDebug($"Start writing {bytesRead} bytes to frontend.");`
	`812`	`+ _logger.LogTrace($"Start writing {bytesRead} bytes to frontend.");`
`816`	`813`
`817`	`814`	`await _frontendStream.WriteAsync(buffer, 0, bytesRead, token).ConfigureAwait(false);`
`818`	`815`	`await _frontendStream.FlushAsync().ConfigureAwait(false);`
`819`	`816`
`820`		`- _logger.LogDebug($"Wrote {bytesRead} bytes to frontend.");`
	`817`	`+ _logger.LogTrace($"Wrote {bytesRead} bytes to frontend.");`
`821`	`818`	`}`
`822`	`819`	`}`
`823`	`820`	`catch (Exception)`
`824`	`821`	`{`
`825`	`822`	`// Completing task will trigger dispose of instance and cleanup.`
`826`	`823`	`// Faliure mainly consists of closed/disposed streams and cancelation requests.`
`827`	`824`	`// Just make sure task gets complete, nothing more needs to be in response to these exceptions.`
`828`		`- _logger.LogDebug("Failed stream operation. Completing task.");`
	`825`	`+ _logger.LogTrace("Failed stream operation. Completing task.");`
`829`	`826`	`}`
`830`	`827`
`831`	`828`	`RouterTaskCompleted?.TrySetResult(true);`
`@@ -838,35 +835,35 @@ async Task FrontendReadBackendWrite(CancellationToken token)`
`838`	`835`	`byte[] buffer = new byte[1024];`
`839`	`836`	`while (!token.IsCancellationRequested)`
`840`	`837`	`{`
`841`		`- _logger.LogDebug("Start reading bytes from frotend.");`
	`838`	`+ _logger.LogTrace("Start reading bytes from frotend.");`
`842`	`839`
`843`	`840`	`int bytesRead = await _frontendStream.ReadAsync(buffer, 0, buffer.Length, token).ConfigureAwait(false);`
`844`	`841`
`845`		`- _logger.LogDebug($"Read {bytesRead} bytes from frontend.");`
	`842`	`+ _logger.LogTrace($"Read {bytesRead} bytes from frontend.");`
`846`	`843`
`847`	`844`	`// Check for end of stream indicating that remote end hung-up.`
`848`	`845`	`if (bytesRead == 0)`
`849`	`846`	`{`
`850`		`- _logger.LogDebug("Frontend hung up.");`
	`847`	`+ _logger.LogTrace("Frontend hung up.");`
`851`	`848`	`break;`
`852`	`849`	`}`
`853`	`850`
`854`	`851`	`_frontendToBackendByteTransfer += (ulong)bytesRead;`
`855`	`852`
`856`		`- _logger.LogDebug($"Start writing {bytesRead} bytes to backend.");`
	`853`	`+ _logger.LogTrace($"Start writing {bytesRead} bytes to backend.");`
`857`	`854`
`858`	`855`	`await _backendStream.WriteAsync(buffer, 0, bytesRead, token).ConfigureAwait(false);`
`859`	`856`	`await _backendStream.FlushAsync().ConfigureAwait(false);`
`860`	`857`
`861`		`- _logger.LogDebug($"Wrote {bytesRead} bytes to backend.");`
	`858`	`+ _logger.LogTrace($"Wrote {bytesRead} bytes to backend.");`
`862`	`859`	`}`
`863`	`860`	`}`
`864`	`861`	`catch (Exception)`
`865`	`862`	`{`
`866`	`863`	`// Completing task will trigger dispose of instance and cleanup.`
`867`	`864`	`// Faliure mainly consists of closed/disposed streams and cancelation requests.`
`868`	`865`	`// Just make sure task gets complete, nothing more needs to be in response to these exceptions.`
`869`		`- _logger.LogDebug("Failed stream operation. Completing task.");`
	`866`	`+ _logger.LogTrace("Failed stream operation. Completing task.");`
`870`	`867`	`}`
`871`	`868`
`872`	`869`	`RouterTaskCompleted?.TrySetResult(true);`