// Copyright Keysight Technologies 2012-2019 // This Source Code Form is subject to the terms of the Mozilla Public // License, v. 2.0. If a copy of the MPL was not distributed with this // file, you can obtain one at http://mozilla.org/MPL/2.0/. using System; using System.Diagnostics; using System.Reflection; using System.IO; using OpenTap.Diagnostic; using System.Collections.Generic; using System.Collections.ObjectModel; using System.Linq; using System.Text; namespace OpenTap { /// /// Identifies the type of event that is logged. /// public enum LogEventType { /// /// Recoverable error. /// Error = 10, /// /// Noncritical problem. /// Warning = 20, /// /// Informational message. /// Information = 30, /// /// Debugging trace. /// Debug = 40 } /// /// Encapsulates the features of the OpenTAP logging infrastructure. /// public class TraceSource { internal ILog log; /// The object that owns this trace source. internal object Owner; internal TraceSource(ILog logSource) { log = logSource; } LogContext.LogInjector redirectedLog => Log.RedirectedLog; /// /// Blocks until all messages posted up to this point have reached all TraceListeners. /// public void Flush() { Log.Flush(); } /// /// Register a single event. /// public void TraceEvent(LogEventType te, int id, string message) { if (message == null) throw new ArgumentNullException(nameof(message)); if(redirectedLog != null) redirectedLog.LogEvent(log.Source, (int)te, message); else log.LogEvent((int)te, message); } /// Register a single event with formatting and duration. public void TraceEvent(long durationNs, LogEventType te, int id, string message, params object[] args) { if(redirectedLog != null) redirectedLog.LogEvent(log.Source, (int)te, durationNs, message, args); else log.LogEvent((int)te, durationNs, message, args); } /// Register a single event without formatting and duration. public void TraceEvent(long durationNs, LogEventType te, int id, string message) { // this overload is important since otherwise the logging system will use // the overload with [args] even though there are none. And that can give // problems if the message itself contains formatting demarcations e.g '{0}' if (redirectedLog != null) redirectedLog.LogEvent(log.Source, (int)te, durationNs, message); else log.LogEvent((int)te, durationNs, message); } /// /// Register a single event with formatting /// public void TraceEvent(LogEventType te, int id, string message, params object[] args) { if (message == null) throw new ArgumentNullException(nameof(message)); if (args == null) throw new ArgumentNullException(nameof(args)); if(redirectedLog != null) redirectedLog.LogEvent(log.Source, (int)te, message, args); else log.LogEvent((int)te, message, args); } } /// /// Base class for various listeners. /// public class TraceListener : ILogListener { void ILogListener.EventsLogged(IEnumerable events) { TraceEvents(events); } /// /// Receives all log messages. The virtual method simply calls directly. /// public virtual void TraceEvents(IEnumerable events) { foreach (var evt in events) TraceEvent(evt.Source, (LogEventType)evt.EventType, 0, evt.Message); } /// /// Empty TraceEvent method. /// public virtual void TraceEvent(string source, LogEventType eventType, int id, string format) { } /// /// Empty TraceEvent method. /// public virtual void TraceEvent(string source, LogEventType eventType, int id, string format, params object[] args) { TraceEvent(source, eventType, id, string.Format(format, args)); } /// /// Virtual method to match System.Diagnostics.TraceListener. Might be removed. /// public virtual void Write(string str) { } /// /// Virtual method to match System.Diagnostics.TraceListener. Might be removed. /// public virtual void WriteLine(string str) { } /// /// Waits until all sent log messages have been processed by this and all other TraceListeners. /// public virtual void Flush() { Log.Flush(); } } /// /// Simple TraceListener which outputs data to a TextWriter. /// class TextWriterTraceListener : TraceListener, IDisposable { private TextWriter writer; readonly object lockObject = new object(); /// /// The writer that is used as the output. /// public TextWriter Writer { get => writer; set { if (writer != value) { lock(lockObject) writer = value; } } } /// /// Creates a new TextWriterTraceListener writing to the given filename. /// public TextWriterTraceListener(string filename) : this(new FileStream(filename, FileMode.Append)) { } /// /// Creates a new TextWriterTraceListener writing to the given stream. /// public TextWriterTraceListener(Stream stream) { Writer = new StreamWriter(stream); } /// /// Writes a string to the current Writer. /// public override void Write(string message) { lock(lockObject) Writer.Write(message); } /// /// Writes a string including a newline to the current Writer. /// public override void WriteLine(string message) { lock(lockObject) Writer.WriteLine(message); } /// /// Flushes the log system and the current Writer. /// public override void Flush() { base.Flush(); lock(lockObject) writer.Flush(); } /// /// Frees up the writer. /// public void Dispose() { lock(lockObject) { if (writer != null) { writer.Close(); writer = null; } } } } /// /// This class extends System.Diagnostics.Log to provide shorthand methods /// for logging/tracing messages at different levels. /// public static class Log { static readonly LogContext rootLogContext = (LogContext)LogFactory.CreateContext(); internal static ILogTimestampProvider Timestamper { get => rootLogContext.Timestamper; set => rootLogContext.Timestamper = value; } static readonly SessionLocal logField = new SessionLocal(null); static readonly SessionLocal sessionLogContext = new SessionLocal(rootLogContext); internal static void WithNewContext() { var ctx = new LogContext(); logField.Value = new LogContext.LogInjector(ctx); sessionLogContext.Value = ctx; } internal static LogContext.LogInjector RedirectedLog => logField.Value; /// The current log context. public static ILogContext Context => sessionLogContext.Value; /// Makes a TraceListener start receiving log messages. /// The TraceListener to add. public static void AddListener(ILogListener listener) { if (listener == null) throw new ArgumentNullException(nameof(listener)); var ctx = Context; ctx.Flush(); ctx.AttachListener(listener); } /// Stops a specified TraceListener from receiving log messages. /// The TraceListener to remove. public static void RemoveListener(ILogListener listener) { if (listener == null) throw new ArgumentNullException(nameof(listener)); var ctx = Context; listener.Flush(); ctx.DetachListener(listener); listener.Flush(); } /// /// Gets all added TraceListeners. /// /// A readonly collection of TraceListeners. public static ReadOnlyCollection GetListeners() { return sessionLogContext.Value?.GetListeners(); } /// Creates a new log source. /// The name of the Log. /// The created Log. public static TraceSource CreateSource(string name) { return new TraceSource(rootLogContext.CreateLog(name)); } // ConditionalWeakTable keys does not count as a reference and are automatically removed on GC. This way we avoid leak. CWT's are thread safe. static readonly System.Runtime.CompilerServices.ConditionalWeakTable ownedTraceSources = new System.Runtime.CompilerServices.ConditionalWeakTable(); static readonly object addlock = new object(); /// Creates a new owned log source. Note that any given object can only have one owned TraceSource. /// The name of the Log. /// The object owning the log. This is used to enable OpenTAP to emit log messages on behalf of the owner object. /// The created Log. public static TraceSource CreateSource(string name, object owner) { if (owner == null) throw new ArgumentNullException(nameof(owner)); var source = CreateSource(name); source.Owner = owner; lock (addlock) { ownedTraceSources.Remove(owner); ownedTraceSources.Add(owner, source); // in this version of .NET there is no Update method... } return source; } /// Gets the source of a specified owner. /// /// returns the TraceSource or null if the owner owns no source. public static TraceSource GetOwnedSource(object owner) { if (owner == null) throw new ArgumentNullException(nameof(owner)); lock (addlock) { ownedTraceSources.TryGetValue(owner, out TraceSource source); return source; } } /// /// Removes a previously Created Log from the list of sources. /// /// public static void RemoveSource(TraceSource source) { if (source == null) throw new ArgumentNullException(nameof(source)); rootLogContext.RemoveLog(source.log); } static Log() { // This improves performance by disabling a critical region that the .NET framework // would otherwise put around writing to _all_ listeners. With UseGlobalLock set to // false instead, a critical region will only be put around each listener individually // and only if they have IsThreadSafe=false. UseGlobalLock=false is also required to // prevent a deadlock when using the Log Breaking feature in the GUI. Trace.UseGlobalLock = false; rootLogContext.Async = true; rootLogContext.MessageBufferSize = 8 * 1024 * 1024; } // Performance: Reuse the string build each time to avoid generating GC pressure. [ThreadStatic] static StringBuilder sb; /// /// like traceEvent except it uses a stopwatch 'timer' to write formatted time after the message [{1:0}ms]. /// Usually used to signal in the log how long an operation took. /// /// /// /// /// /// static void traceEvent(this TraceSource trace, TimeSpan elapsed, LogEventType eventType, string message, params object[] args) { if (message == null) throw new ArgumentNullException(nameof(message)); var timespan = ShortTimeSpan.FromSeconds(elapsed.TotalSeconds); if (sb == null) sb = StringBuilderCache.GetStringBuilder(); sb.Clear(); if (args.Length == 0) { sb.Append(message); } else { sb.AppendFormat(message, args); } sb.Append(" ["); timespan.ToString(sb); sb.Append("]"); // * 1_000_000 steals about 20 bits of precision // so ticks can be about 2^43 before overflowing (signed int) // long durationNs = elapsed.Ticks * NanoSecondsPerTick; trace.TraceEvent(durationNs, eventType, 0, sb.ToString()); } // this should always be exactly 100. const long NanoSecondsPerTick = 1_000_000_000 / TimeSpan.TicksPerSecond; /// /// Write a message to the log with a given trace level. /// /// /// /// /// static void traceEvent(this TraceSource trace, LogEventType eventType, string message, params object[] args) { if (message == null) throw new ArgumentNullException(nameof(message)); if (args.Length == 0) { trace.TraceEvent(eventType, 0, message); } else { trace.TraceEvent(eventType, 0, message, args); } } static void exceptionEvent(this TraceSource trace, Exception exception, LogEventType eventType) { if (exception == null) throw new ArgumentNullException(nameof(exception)); WriteException(trace, exception, eventType); } /// /// Trace a message at level "Information" (). /// /// this(extension method). /// Message to write. public static void TraceInformation(this TraceSource trace, string message) { Info(trace, message); } /// /// Trace a message at level "Debug" (). /// /// this(extension method). /// Message to write. /// parameters (see ). public static void Debug(this TraceSource trace, string message, params object[] args) { traceEvent(trace, LogEventType.Debug, message, args); } /// /// Writes a message with the time measured by timer appended in the format [xx.x (m/u/n)s]. /// if timer is a TimerToken it will be disposed. /// Information level log message. /// /// /// /// /// public static void Info(this TraceSource trace, Stopwatch timer, string message, params object[] args) { if (timer == null) throw new ArgumentNullException("timer"); traceEvent(trace, timer.Elapsed, LogEventType.Information, message, args); } /// /// Writes a message with the time measured by timer appended in the format [xx.x (m/u/n)s]. /// if timer is a TimerToken it will be disposed. /// Debug level end message. /// /// /// /// /// public static void Debug(this TraceSource trace, Stopwatch timer, string message, params object[] args) { if (timer == null) throw new ArgumentNullException("timer"); traceEvent(trace, timer.Elapsed, LogEventType.Debug, message, args); } /// /// Writes a message with the time measured by timer appended in the format [xx.x (m/u/n)s]. /// if timer is a TimerToken it will be disposed. /// Warning level end message. /// /// /// /// /// public static void Warning(this TraceSource trace, Stopwatch timer, string message, params object[] args) { if (timer == null) throw new ArgumentNullException("timer"); traceEvent(trace, timer.Elapsed, LogEventType.Warning, message, args); } /// /// Writes a message with the time measured by timer appended in the format [xx.x (m/u/n)s]. /// if timer is a TimerToken it will be disposed. /// Error level end message. /// /// /// /// /// public static void Error(this TraceSource trace, Stopwatch timer, string message, params object[] args) { if (timer == null) throw new ArgumentNullException("timer"); traceEvent(trace, timer.Elapsed, LogEventType.Error, message, args); } /// /// Writes a message with the time appended in the format [xx.x (m/u/n)s]. /// if timer is a TimerToken it will be disposed. /// Information level log message. /// /// /// /// /// public static void Info(this TraceSource trace, TimeSpan elapsed, string message, params object[] args) { traceEvent(trace, elapsed, LogEventType.Information, message, args); } /// /// Writes a message with the time appended in the format [xx.x (m/u/n)s]. /// if timer is a TimerToken it will be disposed. /// Debug level end message. /// /// /// /// /// public static void Debug(this TraceSource trace, TimeSpan elapsed, string message, params object[] args) { traceEvent(trace, elapsed, LogEventType.Debug, message, args); } /// /// Writes a message with the time appended in the format [xx.x (m/u/n)s]. /// if timer is a TimerToken it will be disposed. /// Warning level end message. /// /// /// /// /// public static void Warning(this TraceSource trace, TimeSpan elapsed, string message, params object[] args) { traceEvent(trace, elapsed, LogEventType.Warning, message, args); } /// /// Writes a message with the time appended in the format [xx.x (m/u/n)s]. /// if timer is a TimerToken it will be disposed. /// Error level end message. /// /// /// /// /// public static void Error(this TraceSource trace, TimeSpan elapsed, string message, params object[] args) { traceEvent(trace, elapsed, LogEventType.Error, message, args); } /// /// Trace a message at level "Information" (). /// /// this(extension method). /// Message to write. /// parameters (see ). public static void Info(this TraceSource trace, string message, params object[] args) { traceEvent(trace, LogEventType.Information, message, args); } /// /// Trace a message at level "Warning" (). /// /// this(extension method). /// Message to write. /// parameters (see ). public static void Warning(this TraceSource trace, string message, params object[] args) { traceEvent(trace, LogEventType.Warning, message, args); } /// /// Trace a message at level "Error" (). /// /// this(extension method). /// Message to write. /// parameters (see ). public static void Error(this TraceSource trace, string message, params object[] args) { traceEvent(trace, LogEventType.Error, message, args); } /// /// Write exception details (including stack trace) to the trace at level "Debug" (). /// /// this(extension method). /// Inputs error exception. public static void Debug(this TraceSource trace, Exception exception) { exceptionEvent(trace, exception, LogEventType.Debug); } /// /// Write exception details (including stack trace) to the trace at level "Error" (). /// /// this(extension method). /// Inputs error exception. public static void Error(this TraceSource trace, Exception exception) { exceptionEvent(trace, exception, LogEventType.Error); } const int callerStackTraceLimit = 4; static void WriteStackTrace(TraceSource trace, StackTrace stack, LogEventType level) { var frames = stack.GetFrames() ?? Array.Empty(); var lines = frames .Skip(3) // Skip the frames from the logging itself. .Where(line => line.HasMethod()); // only take those with the method available. int lineCount = lines.Count(); lines = lines.Take(callerStackTraceLimit); // Just show the top of the call stack. foreach (StackFrame line in lines) { var fixedLine = $"at {line.GetMethod()}"; if (line.HasSource()) { fixedLine += $" in {line.GetFileName()}:line {line.GetFileLineNumber()}"; } trace.TraceEvent(level, 2, " " + fixedLine, false); } if (lineCount > callerStackTraceLimit) { trace.TraceEvent(level, 2, " ..."); } } static void WriteException(TraceSource trace, Exception exception, LogEventType level, bool appendStack = true, bool isInner = false) { var exceptionName = exception.GetType().Name; try { var exceptionMessage = exception.Message .Replace("{", "{{") .Replace("}", "}}"); if (isInner) trace.TraceEvent(level, 2, " Inner " + exceptionName + ": " + exceptionMessage, false); else trace.TraceEvent(level, 2, exceptionName + ": " + exceptionMessage); if (exception.StackTrace != null) { string[] lines = exception.StackTrace.Split(new char[] {'\n'}); foreach (string line in lines) { var fixedLine = line.Replace("{", "{{").Replace("}", "}}").Trim(); trace.TraceEvent(LogEventType.Debug, 2, " " + fixedLine, false); } } if (exception is ReflectionTypeLoadException) { ReflectionTypeLoadException reflectionTypeLoadException = (ReflectionTypeLoadException) exception; foreach (Exception ex in reflectionTypeLoadException.LoaderExceptions) { WriteException(trace, ex, level, false); } } else if (exception is AggregateException ag) { foreach (var inner in ag.InnerExceptions) { WriteException(trace, inner, level, false, true); } } else if (exception.InnerException is Exception inner) { WriteException(trace, inner, level, false, true); } } catch (Exception) { trace.TraceEvent(level, 2, "Error caught while logging an exception."); } if (appendStack) { try { var stackTrace = new StackTrace(true); trace.TraceEvent(level, 2, "Exception caught at:"); WriteStackTrace(trace, stackTrace, level); } catch { trace.TraceEvent(level, 2, "Error retrieving current stacktrace."); } } } /// /// Flushes all waiting log trace events. /// public static void Flush() { rootLogContext.Flush(); } /// /// Puts the current log context into synchronous mode. /// All TraceSources will now wait for their trace events to be handled by all TraceListeners before returning. /// public static void StartSync() { Flush(); rootLogContext.Async = false; } /// /// Ends synchronous mode. Must be called after . /// public static void StopSync() { rootLogContext.Async = true; Flush(); } } /// /// Extension methods for Exception. /// static class ExceptionExtensions { /// /// Finds the message of the inner most exception for this exception. If no inner exceptions are set, the message of this exception is returned. /// COMExceptions are ignored as their message is not very useful. /// public static string GetInnerMostExceptionMessage(this Exception ex) { if (ex is AggregateException ag) { if(ag.InnerExceptions.Count == 1) return ag.InnerExceptions[0].GetInnerMostExceptionMessage(); return ag.Message; } if (ex is System.Runtime.InteropServices.COMException) return ex.Message; return ex.InnerException?.GetInnerMostExceptionMessage() ?? ex.Message; } public static void Rethrow(this Exception ex) { System.Runtime.ExceptionServices.ExceptionDispatchInfo.Capture(ex).Throw(); } public static void RethrowInner(this Exception ex) { if(ex is AggregateException a && a.InnerExceptions.Count > 1) ex.Rethrow(); else (ex.InnerException ?? ex).Rethrow(); } } static class StringBuilderCache { [ThreadStatic] static StringBuilder sb; public static StringBuilder GetStringBuilder() { var sb2 = sb ??= new StringBuilder(); sb2.Clear(); return sb2; } } }