logging tweaks

Author: retailcoder

Rubberduck.CodeAnalysis/Inspections/Abstract/InspectionBase.cs

@@ -83,8 +83,14 @@ public IEnumerable<IInspectionResult> GetInspectionResults(CancellationToken tok
                 .Where(ir => !ir.IsIgnoringInspectionResult(finder))
                 .ToList();
             stopwatch.Stop();
-            Logger.Trace("Intercepted invocation of '{0}.{1}' returned {2} objects.", GetType().Name, nameof(DoGetInspectionResults), result.Count);
-            Logger.Trace("Intercepted invocation of '{0}.{1}' ran for {2}ms", GetType().Name, nameof(DoGetInspectionResults), stopwatch.ElapsedMilliseconds);
+            if (result.Count > 0)
+            {
+                Logger.Trace("'Returned {2} results, completed in {3}ms.", result.Count, stopwatch.ElapsedMilliseconds);
+            }
+            else
+            {
+                Logger.Trace("Completed in {2}ms", stopwatch.ElapsedMilliseconds);
+            }
             return result;
         }
 
@@ -103,8 +109,14 @@ public IEnumerable<IInspectionResult> GetInspectionResults(QualifiedModuleName m
                 .Where(ir => !ir.IsIgnoringInspectionResult(finder))
                 .ToList();
             stopwatch.Stop();
-            Logger.Trace("Intercepted invocation of '{0}.{1}' returned {2} objects.", GetType().Name, nameof(DoGetInspectionResults), result.Count);
-            Logger.Trace("Intercepted invocation of '{0}.{1}' ran for {2}ms", GetType().Name, nameof(DoGetInspectionResults), stopwatch.ElapsedMilliseconds);
+            if (result.Count > 0)
+            {
+                Logger.Trace("'Returned {2} results, completed in {3}ms.", result.Count, stopwatch.ElapsedMilliseconds);
+            }
+            else
+            {
+                Logger.Trace("Completed in {2}ms", stopwatch.ElapsedMilliseconds);
+            }
             return result;
         }
 

Rubberduck.Core/UI/Inspections/InspectionResultsViewModel.cs

@@ -506,7 +506,7 @@ private async Task RefreshInspections_Internal(CancellationToken token)
             }
 
             stopwatch.Stop();
-            Logger.Trace("Inspection results returned in {0}ms", stopwatch.ElapsedMilliseconds);
+            Logger.Trace("Returned {0} inspection results in {1}ms", results.Count, stopwatch.ElapsedMilliseconds);
 
             _uiDispatcher.Invoke(() =>
             {
@@ -533,7 +533,7 @@ private async Task RefreshInspections_Internal(CancellationToken token)
                 }
 
                 stopwatch.Stop();
-                Logger.Trace("Inspection results rendered in {0}ms", stopwatch.ElapsedMilliseconds);
+                Logger.Trace("Rendering completed in {0}ms", stopwatch.ElapsedMilliseconds);
             });
         }
 

Rubberduck.Parsing/VBA/ParseCoordinator.cs

@@ -463,18 +463,18 @@ private void ParseAll(object requestor)
                 Monitor.Enter(ParsingRunSyncObject, ref lockTaken);
 
                 watch = Stopwatch.StartNew();
-                Logger.Debug("Parsing run started. (thread {0}).", Thread.CurrentThread.ManagedThreadId);
+                Logger.Debug("Parsing run started on thread {0}.", Thread.CurrentThread.ManagedThreadId);
 
                 ParseAllInternal(requestor, token);
             }
             catch (OperationCanceledException)
             {
                 //This is the point to which the cancellation should break.
-                Logger.Debug("Parsing run got canceled. (thread {0}).", Thread.CurrentThread.ManagedThreadId);
+                Logger.Debug("Parsing run was cancelled on thread {0}.", Thread.CurrentThread.ManagedThreadId);
             }
             catch (Exception exception)
             {
-                Logger.Error(exception, "Unexpected exception thrown in parsing run. (thread {0}).", Thread.CurrentThread.ManagedThreadId);
+                Logger.Error(exception, "Unexpected exception thrown in parsing run on thread {0}.", Thread.CurrentThread.ManagedThreadId);
                 if (_parserStateManager.OverallParserState != ParserState.UnexpectedError)
                 {
                     _parserStateManager.SetStatusAndFireStateChanged(this, ParserState.UnexpectedError, token);
@@ -489,7 +489,7 @@ private void ParseAll(object requestor)
                     ParsingSuspendLock.ExitReadLock();
                 }
             }
-            if (watch != null) Logger.Info("Parsing run finished after {0}s. (thread {1}).", watch.Elapsed.TotalSeconds, Thread.CurrentThread.ManagedThreadId);
+            if (watch != null) Logger.Info("Parsing run on thread {0} completed in {1}ms.", Thread.CurrentThread.ManagedThreadId, watch.ElapsedMilliseconds);
         }
 
         protected void ParseAllInternal(object requestor, CancellationToken token)

Rubberduck.Parsing/VBA/ReferenceManagement/ReferenceResolveRunnerBase.cs

@@ -182,7 +182,7 @@ protected void ResolveReferences(DeclarationFinder finder, QualifiedModuleName m
         {
             token.ThrowIfCancellationRequested();
 
-            Logger.Debug("Resolving identifier references in '{0}'... (thread {1})", module.Name, Thread.CurrentThread.ManagedThreadId);
+            Logger.Debug("Thread {0} is resolving identifier references in component '{1}'.", Thread.CurrentThread.ManagedThreadId, module.Name);
 
             var resolver = new IdentifierReferenceResolver(module, finder);
             var listener = new IdentifierReferenceListener(resolver);
@@ -195,8 +195,7 @@ protected void ResolveReferences(DeclarationFinder finder, QualifiedModuleName m
                     var watch = Stopwatch.StartNew();
                     walker.Walk(listener, tree);
                     watch.Stop();
-                    Logger.Debug("Binding resolution done for component '{0}' in {1}ms (thread {2})", module.Name,
-                        watch.ElapsedMilliseconds, Thread.CurrentThread.ManagedThreadId);
+                    Logger.Debug("Thread {0} completed binding resolution for component '{1}' in {2}ms", Thread.CurrentThread.ManagedThreadId, module.Name, watch.ElapsedMilliseconds);
 
                     //Evaluation of the overall status has to be deferred to allow processing of undeclared variables before setting the ready state.
                     _parserStateManager.SetModuleState(module, ParserState.Ready, token, false);

Rubberduck.Parsing/VBA/RubberduckParserState.cs

@@ -342,7 +342,7 @@ private void OnStateChanged(object requestor, CancellationToken token, ParserSta
         {
             Interlocked.Increment(ref _stateChangedInvocations);
 
-            Logger.Info($"{nameof(RubberduckParserState)} ({_stateChangedInvocations}) is invoking {nameof(StateChanged)} ({Status})");
+            Logger.Info($"{nameof(RubberduckParserState)}.{nameof(StateChanged)} invocation {_stateChangedInvocations} sets status to '{Status}'.");
 
             var highPriorityHandler = StateChangedHighPriority;
             if (highPriorityHandler != null && !token.IsCancellationRequested)
@@ -423,7 +423,7 @@ public void SetModuleState(QualifiedModuleName module, ParserState state, Cancel
 
             _moduleStates.AddOrUpdate(module, new ModuleState(state), (c, e) => e.SetState(state));
             _moduleStates.AddOrUpdate(module, new ModuleState(parserError), (c, e) => e.SetModuleException(parserError));
-            Logger.Debug("Module '{0}' state is changing to '{1}' (thread {2})", module.ComponentName, state, Thread.CurrentThread.ManagedThreadId);
+            Logger.Debug("Thread {0} is changing state of module '{1}' to '{2}'.", Thread.CurrentThread.ManagedThreadId, module.ComponentName, state);
             OnModuleStateChanged(module, state, oldState, token);
             if (evaluateOverallState)
             {