Improved logging (#76)

* Skip detailed assembly tracing. * Simplified trace lines (time, appdomain, thread skipped).
SenseNet · Jan 5, 2024 · 66bfb56 · 66bfb56
1 parent d7c2788
commit 66bfb56
Show file tree

Hide file tree

Showing 4 changed files with 81 additions and 10 deletions.
diff --git a/src/SenseNet.Tools.Tests/SnTraceTestClass.cs b/src/SenseNet.Tools.Tests/SnTraceTestClass.cs
@@ -1,4 +1,5 @@
-using Microsoft.VisualStudio.TestTools.UnitTesting;
+#define SIMPLIFIED_TRACE_LINE
+using Microsoft.VisualStudio.TestTools.UnitTesting;
 using SenseNet.Diagnostics;
 using System;
 using System.Collections.Generic;
@@ -57,7 +58,11 @@ protected string GetMessageFromLine(string line)
 
             var fields = line.Split('\t');
 
+#if SIMPLIFIED_TRACE_LINE
+            return fields.Length < 7 ? null : string.Join("\t", fields, 6, fields.Length - 6);
+#else
             return fields.Length < 10 ? null : string.Join("\t", fields, 9, fields.Length - 9);
+#endif
         }
         protected string GetColumnFromLine(string line, Entry.Field col)
         {

diff --git a/src/SenseNet.Tools/Diagnostics/Analysis/Entry.cs b/src/SenseNet.Tools/Diagnostics/Analysis/Entry.cs
@@ -1,4 +1,6 @@
-using System;
+#define SIMPLIFIED_TRACE_LINE
+
+using System;
 using System.Collections.Generic;
 using System.Globalization;
 using System.Linq;
@@ -19,6 +21,25 @@ public class Entry
         /// <summary>
         /// Field index helper
         /// </summary>
+#if SIMPLIFIED_TRACE_LINE
+        public enum Field
+        {
+            /// <summary>Value = 0</summary>
+            LineId = 0,
+            /// <summary>Value = 1</summary>
+            Category,
+            /// <summary>Value = 2</summary>
+            ProgramFlowId,
+            /// <summary>Value = 3</summary>
+            OpId,
+            /// <summary>Value = 4</summary>
+            Status,
+            /// <summary>Value = 5</summary>
+            Duration,
+            /// <summary>Value = 6</summary>
+            Message
+        }
+#else
         public enum Field
         {
             /// <summary>Value = 0</summary>
@@ -42,6 +63,8 @@ public enum Field
             /// <summary>Value = 9</summary>
             Message
         }
+#endif
+
 
         /// <summary>
         /// True if this line is the first in the block that written to disk in one step.
@@ -105,8 +128,13 @@ public Entry(Entry sourceEntry)
         /// </summary>
         public static Entry Parse(string oneLine)
         {
+#if SIMPLIFIED_TRACE_LINE
+            // 0        1       2       3   4               5
+            // >11929	Index	Op:2743	End	00:00:00.000000	IAQ: A160064 EXECUTION.
+#else
             // 0        1                           2       3           4       5       6   7               8
             // >11929	2016-04-07 01:59:57.42589	Index	A:/LM..231	T:46	Op:2743	End	00:00:00.000000	IAQ: A160064 EXECUTION.
+#endif
 
             if (string.IsNullOrEmpty(oneLine))
                 return null;
@@ -117,6 +145,20 @@ public static Entry Parse(string oneLine)
             if (data.Length < (int)Field.Message)
                 return null;
 
+#if SIMPLIFIED_TRACE_LINE
+            return new Entry
+            {
+                Raw = oneLine,
+                BlockStart = ParseBlockStart(data[(int)Field.LineId]),
+                LineId = ParseLineId(data[(int)Field.LineId]),
+                Category = data[(int)Field.Category],
+                ProgramFlowId = ParseProgramFlow(data[(int)Field.ProgramFlowId]),
+                OpId = ParseOperationId(data[(int)Field.OpId]),
+                Status = data[(int)Field.Status],
+                Duration = ParseDuration(data[(int)Field.Duration]),
+                Message = string.Join("\t", data.Skip((int)Field.Message))
+            };
+#else
             return new Entry
             {
                 Raw = oneLine,
@@ -132,6 +174,7 @@ public static Entry Parse(string oneLine)
                 Duration = ParseDuration(data[(int)Field.Duration]),
                 Message = string.Join("\t", data.Skip((int)Field.Message))
             };
+#endif
         }
 
         private static bool ParseBlockStart(string src)

diff --git a/src/SenseNet.Tools/Diagnostics/SnTrace.cs b/src/SenseNet.Tools/Diagnostics/SnTrace.cs
@@ -1,4 +1,6 @@
-using System;
+#define SIMPLIFIED_TRACE_LINE
+
+using System;
 using System.Collections;
 using System.Collections.Generic;
 using System.Diagnostics;
@@ -428,16 +430,28 @@ private static string FinishOperation(Operation op)
             var lineCounter = Interlocked.Increment(ref _lineCounter);
             var programFlow = GetProgramFlowId();
 
+#if SIMPLIFIED_TRACE_LINE
+            var line = string.Format("{0}\t{1}\tPf:{2}\tOp:{3}\t{4}\t{5:hh\':\'mm\':\'ss\'.\'ffffff}\t{6}"
+                , lineCounter
+                , op.Category
+                , programFlow
+                , op.Id
+                , op.Successful ? "End" : "UNTERMINATED"
+                , DateTime.UtcNow - op.StartedAt
+                , op.Message);
+#else
             var line = string.Format("{0}\t{1:yyyy-MM-dd HH:mm:ss.fffff}\t{2}\tA:{3}\tT:{4}\tPf:{5}\tOp:{6}\t{7}\t{8:hh\':\'mm\':\'ss\'.\'ffffff}\t{9}"
                 , lineCounter
-                , DateTime.UtcNow, op.Category
+                , DateTime.UtcNow
+                , op.Category
                 , AppDomainName
                 , Thread.CurrentThread.ManagedThreadId
                 , programFlow
                 , op.Id
                 , op.Successful ? "End" : "UNTERMINATED"
                 , DateTime.UtcNow - op.StartedAt
                 , op.Message);
+#endif
 
             return line;
         }
@@ -446,6 +460,19 @@ private static string SafeFormatString(string category, bool isError, Operation
         {
             var lineCounter = Interlocked.Increment(ref _lineCounter);
             var programFlow = GetProgramFlowId();
+#if SIMPLIFIED_TRACE_LINE
+            var line = op != null
+                ? string.Format("{0}\t{1}\tPf:{2}\tOp:{3}\tStart\t\t"
+                    , lineCounter
+                    , category
+                    , programFlow
+                    , op.Id)
+                : string.Format("{0}\t{1}\tPf:{2}\t\t{3}\t\t"
+                    , lineCounter
+                    , category
+                    , programFlow
+                    , isError ? "ERROR" : "");
+#else
             var line = op != null
                 ? string.Format("{0}\t{1:yyyy-MM-dd HH:mm:ss.fffff}\t{2}\tA:{3}\tT:{4}\tPf:{5}\tOp:{6}\tStart\t\t"
                     , lineCounter
@@ -463,6 +490,7 @@ private static string SafeFormatString(string category, bool isError, Operation
                     , Thread.CurrentThread.ManagedThreadId
                     , programFlow
                     , isError ? "ERROR" : "");
+#endif
 
             // smart formatting
             if (args != null)

diff --git a/src/SenseNet.Tools/Tools/TypeResolver.cs b/src/SenseNet.Tools/Tools/TypeResolver.cs
@@ -196,16 +196,11 @@ public static string[] LoadAssembliesFrom(string path)
                         var asmName = AssemblyName.GetAssemblyName(dllPath);
                         var asmFullName = asmName.FullName;
                         var asmNameName = asmName.Name;
-                        if (assemblies.TryGetValue(asmNameName, out var origAsm))
-                        {
-                            SnTrace.Repository.Write("ASM Skipped: {0}, {1}", asmFullName, origAsm.Location);
-                        }
-                        else
+                        if (!assemblies.TryGetValue(asmNameName, out var origAsm))
                         {
                             var loadedAsm = Assembly.LoadFrom(dllPath);
                             assemblies.Add(asmNameName, loadedAsm);
                             loaded.Add(Path.GetFileName(dllPath));
-                            SnTrace.Repository.Write("ASM Loaded: {0}, {1}", asmFullName, dllPath);
                         }
                     }
                     catch (BadImageFormatException e) //logged