Support semantic logging (#1648)

- For EventSource and legacy logger refactor logging to support the built in LogValueFormatter, which provides the format strings suitable for `string.Format`.
- **Breaking change**: For `TraceEvent` this is a breaking change, because there is no implementation yet to support to provide the reformatted format string. With this implementation if a logging framework is used which supports the semantic logging, there is no issue. With frameworks which do not understand semantic logging strings(e.g. log4net) it is a breaking change, string.format will throw exceptions --> move to ILogger hook using `SetLogger`. 
- **Warning**: When Microsoft.Extensions.Logger based loggers are used, format strings must follow this convention:
i) All variable entries must follow order and count up, e.g. "{0} -- {1}" etc., no mix of "{2}--{0}"
ii) in the same way the args must follow this strict ordering. 
- Format strings will be changed by future PR to include the semantic values.

Libraries/Opc.Ua.Client/Session.cs

@@ -1212,7 +1212,7 @@ public void Reconnect(ITransportWaitingConnection connection)
 
                 if (!result.AsyncWaitHandle.WaitOne(5000))
                 {
-                    Utils.LogWarning("WARNING: ACTIVATE SESSION timed out. {1}/{0}", OutstandingRequestCount, GoodPublishRequestCount);
+                    Utils.LogWarning("WARNING: ACTIVATE SESSION timed out. {0}/{1}", GoodPublishRequestCount, OutstandingRequestCount);
                 }
 
                 EndActivateSession(
@@ -3841,7 +3841,7 @@ private void OnKeepAlive(object state)
             }
             catch (Exception e)
             {
-                Utils.LogError("Could not send keep alive request: {1} {0}", e.Message, e.GetType().FullName);
+                Utils.LogError("Could not send keep alive request: {0} {1}", e.GetType().FullName, e.Message);
             }
         }
 
@@ -3960,11 +3960,11 @@ protected virtual bool OnKeepAliveError(ServiceResult result)
             }
 
             Utils.LogInfo(
-                "KEEP ALIVE LATE: {0}s, EndpointUrl={1}, RequestCount={3}/{2}",
+                "KEEP ALIVE LATE: {0}s, EndpointUrl={1}, RequestCount={2}/{3}",
                 ((double)delta) / TimeSpan.TicksPerSecond,
                 this.Endpoint.EndpointUrl,
-                this.OutstandingRequestCount,
-                this.GoodPublishRequestCount);
+                this.GoodPublishRequestCount,
+                this.OutstandingRequestCount);
 
             KeepAliveEventHandler callback = null;
 
@@ -4151,7 +4151,7 @@ private void OnPublishComplete(IAsyncResult result)
                 }
                 else
                 {
-                    Utils.LogError("Publish #{0}, Reconnecting={2}, Error: {1}", requestHeader.RequestHandle, e.Message, m_reconnecting);
+                    Utils.LogError("Publish #{0}, Reconnecting={1}, Error: {2}", requestHeader.RequestHandle, m_reconnecting, e.Message);
                 }
 
                 moreNotifications = false;

Libraries/Opc.Ua.Gds.Server.Common/ApplicationsNodeManager.cs

@@ -571,7 +571,7 @@ out nextRecordId
                 }
                 catch
                 {
-                    Utils.Trace(Utils.TraceMasks.Error, "Failed to revoke: {0}", certType.Value);
+                    Utils.LogError("Failed to revoke: {0}", certType.Value);
                 }
             }
 

Libraries/Opc.Ua.Server/Server/OpcUaServerEventSource.cs

@@ -194,7 +194,8 @@ public void DequeueValue(Variant wrappedValue, StatusCode statusCode)
                 }
                 else if (Logger.IsEnabled(LogLevel.Trace))
                 {
-                    LogTrace("DEQUEUE VALUE: Value={0} CODE={1}<{1:X8}> OVERFLOW={2}", wrappedValue, statusCode.Code, statusCode.Overflow);
+                    LogTrace("DEQUEUE VALUE: Value={0} CODE={1}<{2:X8}> OVERFLOW={3}",
+                        wrappedValue, statusCode.Code, statusCode.Code, statusCode.Overflow);
                 }
             }
         }
@@ -213,8 +214,8 @@ public void QueueValue(uint id, Variant wrappedValue, StatusCode statusCode)
                 }
                 else if (Logger.IsEnabled(LogLevel.Trace))
                 {
-                    LogTrace(TraceMasks.OperationDetail, "QUEUE VALUE[{0}]: Value={1} CODE={2}<{2:X8}> OVERFLOW={3}",
-                        id, wrappedValue, statusCode.Code, statusCode.Overflow);
+                    LogTrace(TraceMasks.OperationDetail, "QUEUE VALUE[{0}]: Value={1} CODE={2}<{3:X8}> OVERFLOW={4}",
+                        id, wrappedValue, statusCode.Code, statusCode.Code, statusCode.Overflow);
                 }
             }
         }

Libraries/Opc.Ua.Server/Subscription/Subscription.cs

@@ -860,10 +860,9 @@ public NotificationMessage PublishTimeout()
             {
 
                 Utils.LogWarning(
-                    "WARNING: QUEUE OVERFLOW. Dropping {2} Messages. Increase MaxMessageQueueSize. SubId={0}, MaxMessageQueueSize={1}",
-                    m_id,
-                    m_maxMessageCount,
-                    overflowCount);
+                    "WARNING: QUEUE OVERFLOW. Dropping {0} Messages. Increase MaxMessageQueueSize. SubId={1}, MaxMessageQueueSize={2}",
+                    overflowCount, m_id, m_maxMessageCount
+                    );
 
                 messages.RemoveRange(0, overflowCount);
 

Stack/Opc.Ua.Core/Security/Certificates/DirectoryCertificateStore.cs

@@ -381,7 +381,7 @@ public X509Certificate2 LoadPrivateKey(string thumbprint, string subjectName, st
                 }
                 catch (Exception e)
                 {
-                    Utils.LogError(e, "Could not load private key for certificate " + subjectName);
+                    Utils.LogError(e, "Could not load private key for certificate [{0}]", subjectName);
                 }
             }
 

Stack/Opc.Ua.Core/Stack/Tcp/TcpServerChannel.cs

@@ -625,7 +625,7 @@ private bool ProcessOpenSecureChannelRequest(uint messageType, ArraySegment<byte
                             request);
 
                         Utils.LogInfo(
-                            "{0} ReconnectToExistingChannel Socket={0:X8}, ChannelId={1}, TokenId={2}",
+                            "{0} ReconnectToExistingChannel Socket={1:X8}, ChannelId={2}, TokenId={3}",
                             ChannelName,
                             (Socket != null) ? Socket.Handle : 0,
                             (CurrentToken != null) ? CurrentToken.ChannelId : 0,
@@ -896,7 +896,7 @@ private bool ProcessRequestMessage(uint messageType, ArraySegment<byte> messageC
                 // check for an abort.
                 if (TcpMessageType.IsAbort(messageType))
                 {
-                    Utils.LogWarning(TraceMasks.ServiceDetail, "ChannelId {0}: ProcessRequestMessage RequestId {0} was aborted.", requestId);
+                    Utils.LogWarning(TraceMasks.ServiceDetail, "ChannelId {0}: ProcessRequestMessage RequestId {1} was aborted.", ChannelId, requestId);
                     chunksToProcess = GetSavedChunks(requestId, messageBody);
                     return true;
                 }

Stack/Opc.Ua.Core/Stack/Tcp/TcpTransportListener.cs

@@ -321,7 +321,7 @@ public void Start()
                         m_listeningSocket.Dispose();
                         m_listeningSocket = null;
                     }
-                    Utils.LogWarning("failed to create IPv4 listening socket: " + ex.Message);
+                    Utils.LogWarning("Failed to create IPv4 listening socket: {0}", ex.Message);
                 }
 
                 if (ipAddress == IPAddress.Any)
@@ -349,7 +349,7 @@ public void Start()
                             m_listeningSocketIPv6.Dispose();
                             m_listeningSocketIPv6 = null;
                         }
-                        Utils.LogWarning("failed to create IPv6 listening socket: " + ex.Message);
+                        Utils.LogWarning("Failed to create IPv6 listening socket: {0}", ex.Message);
                     }
                 }
                 if (m_listeningSocketIPv6 == null && m_listeningSocket == null)

Stack/Opc.Ua.Core/Stack/Tcp/UaSCBinaryChannel.cs

@@ -242,7 +242,8 @@ protected bool VerifySequenceNumber(uint sequenceNumber, string context)
                 }
             }
 
-            Utils.LogError("ChannelId {1}: {0} - Duplicate sequence number: {2} <= {3}", context, ChannelId, sequenceNumber, m_remoteSequenceNumber);
+            Utils.LogError("ChannelId {0}: {1} - Duplicate sequence number: {2} <= {3}",
+                ChannelId, context, sequenceNumber, m_remoteSequenceNumber);
             return false;
         }
 

Stack/Opc.Ua.Core/Stack/Tcp/UaSCBinaryClientChannel.cs

@@ -240,7 +240,7 @@ public void Close(int timeout)
 
                         default:
                         {
-                            Utils.LogWarning(e, "ChannelId {0}: Could not gracefully close the channel. Reason={0}", ChannelId, e.Result.StatusCode);
+                            Utils.LogWarning(e, "ChannelId {0}: Could not gracefully close the channel. Reason={1}", ChannelId, e.Result.StatusCode);
                             break;
                         }
                     }
@@ -849,7 +849,7 @@ private void OnScheduledHandshake(object state)
 
                     if (Socket != null)
                     {
-                        Utils.LogInfo("ChannelId {0}: CLIENTCHANNEL SOCKET CLOSED: {0:X8}", ChannelId, Socket.Handle);
+                        Utils.LogInfo("ChannelId {0}: CLIENTCHANNEL SOCKET CLOSED: {1:X8}", ChannelId, Socket.Handle);
                         Socket.Close();
                         Socket = null;
                     }

Stack/Opc.Ua.Core/Stack/Types/ContentFilter.Evaluate.cs

@@ -1555,7 +1555,7 @@ private static object Cast(object source, BuiltInType sourceType, BuiltInType ta
             }
             catch (Exception e)
             {
-                Utils.LogError(e, "Error converting a {1} (Value={0}) to {2}.", source, sourceType, targetType);
+                Utils.LogError(e, "Error converting a {0} (Value={1}) to {2}.", sourceType, source, targetType);
             }
 
             // conversion not supported.

Stack/Opc.Ua.Core/Types/BuiltIn/NodeId.cs

@@ -535,8 +535,8 @@ public static NodeId Create(object identifier, string namespaceUri, NamespaceTab
         /// 
         /// //now to compare the node to the guids
         /// Utils.LogInfo("\n\nComparing NodeId to String");
-        /// Utils.LogInfo("\tComparing {0} to {0} = [equals] {2}", id1, id1, node1.Equals(id1));
-        /// Utils.LogInfo("\tComparing {0} to {0} = [ ==   ] {2}", id1, id1, node1 == id1);
+        /// Utils.LogInfo("\tComparing {0} to {1} = [equals] {2}", id1, id1, node1.Equals(id1));
+        /// Utils.LogInfo("\tComparing {0} to {1} = [ ==   ] {2}", id1, id1, node1 == id1);
         /// Utils.LogInfo("\tComparing {0} to {1} = [equals] {2}", id1, id2, node1.Equals(id2));
         /// Utils.LogInfo("\tComparing {0} to {1} = [ ==   ] {2}", id1, id2, node1 == id2);
         /// 
@@ -551,8 +551,8 @@ public static NodeId Create(object identifier, string namespaceUri, NamespaceTab
         /// 
         /// 'now to compare the node to the guids
         /// Utils.LogInfo("Comparing NodeId to String");
-        /// Utils.LogInfo(String.Format("Comparing {0} to {0} = [equals] {2}", id1, id1, node1.Equals(id1)));
-        /// Utils.LogInfo(String.Format("Comparing {0} to {0} = [  =   ] {2}", id1, id1, node1 = id1));
+        /// Utils.LogInfo(String.Format("Comparing {0} to {1} = [equals] {2}", id1, id1, node1.Equals(id1)));
+        /// Utils.LogInfo(String.Format("Comparing {0} to {1} = [  =   ] {2}", id1, id1, node1 = id1));
         /// Utils.LogInfo(String.Format("Comparing {0} to {1} = [equals] {2}", id1, id2, node1.Equals(id2)));
         /// Utils.LogInfo(String.Format("Comparing {0} to {1} = [  =   ] {2}", id1, id2, node1 = id2));
         /// 

Stack/Opc.Ua.Core/Types/Utils/LoggerUtils.cs

@@ -241,7 +241,7 @@ public static void LogTrace(EventId eventId, Exception exception, string message
         {
             if (EventLog.IsEnabled())
             {
-                EventLog.LogLog(LogLevel.Trace, eventId, exception, message, args);
+                EventLog.Log(LogLevel.Trace, eventId, exception, message, args);
             }
             else if (Logger.IsEnabled(LogLevel.Trace))
             {
@@ -260,7 +260,7 @@ public static void LogTrace(EventId eventId, string message, params object[] arg
         {
             if (EventLog.IsEnabled())
             {
-                EventLog.LogLog(LogLevel.Trace, eventId, message, args);
+                EventLog.Log(LogLevel.Trace, eventId, message, args);
             }
             else if (Logger.IsEnabled(LogLevel.Trace))
             {
@@ -279,7 +279,7 @@ public static void LogTrace(Exception exception, string message, params object[]
         {
             if (EventLog.IsEnabled())
             {
-                EventLog.LogLog(LogLevel.Trace, 0, exception, message, args);
+                EventLog.Log(LogLevel.Trace, 0, exception, message, args);
             }
             else if (Logger.IsEnabled(LogLevel.Trace))
             {
@@ -297,7 +297,7 @@ public static void LogTrace(string message, params object[] args)
         {
             if (EventLog.IsEnabled())
             {
-                EventLog.LogLog(LogLevel.Trace, 0, message, args);
+                EventLog.Log(LogLevel.Trace, 0, message, args);
             }
             else if (Logger.IsEnabled(LogLevel.Trace))
             {
@@ -529,18 +529,23 @@ public static void Log(LogLevel logLevel, EventId eventId, string message, param
         {
             if (EventLog.IsEnabled())
             {
-                EventLog.LogLog(logLevel, eventId, message, args);
+                EventLog.Log(logLevel, eventId, null, message, args);
             }
-            else if (UseTraceEvent)
+            else if (Logger.IsEnabled(logLevel))
             {
-                if (Logger.IsEnabled(logLevel))
+                // note: to support semantic logging strings
+                if (UseTraceEvent && Tracing.IsEnabled())
                 {
                     // call the legacy logging handler (TraceEvent)
-                    Utils.Trace(null, GetTraceMask(eventId, logLevel), message, false, args);
+                    int traceMask = GetTraceMask(eventId, logLevel);
+                    Tracing.Instance.RaiseTraceEvent(new TraceEventArgs(traceMask, message, string.Empty, null, args));
+                    // done if mask not enabled, otherwise legacy write handler is
+                    // called via logger interface to handle semantic logging.
+                    if ((s_traceMasks & traceMask) == 0)
+                    {
+                        return;
+                    }
                 }
-            }
-            else
-            {
                 Logger.Log(logLevel, eventId, null, message, args);
             }
         }
@@ -557,7 +562,6 @@ public static void Log(LogLevel logLevel, Exception exception, string message, p
             Log(logLevel, 0, exception, message, args);
         }
 
-
         /// <summary>
         /// Formats and writes a log message at the specified log level.
         /// </summary>
@@ -570,18 +574,22 @@ public static void Log(LogLevel logLevel, EventId eventId, Exception exception,
         {
             if (EventLog.IsEnabled())
             {
-                EventLog.LogLog(logLevel, eventId, exception, message, args);
+                EventLog.Log(logLevel, eventId, exception, message, args);
             }
-            else if (UseTraceEvent)
+            else if (Logger.IsEnabled(logLevel))
             {
-                if (Logger.IsEnabled(logLevel))
+                if (UseTraceEvent && Tracing.IsEnabled())
                 {
                     // call the legacy logging handler (TraceEvent)
-                    Utils.Trace(exception, GetTraceMask(eventId, logLevel), message, false, args);
+                    int traceMask = GetTraceMask(eventId, logLevel);
+                    Tracing.Instance.RaiseTraceEvent(new TraceEventArgs(traceMask, message, string.Empty, exception, args));
+                    // done if mask not enabled, otherwise legacy write handler is
+                    // called via logger interface to handle semantic logging.
+                    if ((s_traceMasks & traceMask) == 0)
+                    {
+                        return;
+                    }
                 }
-            }
-            else
-            {
                 Logger.Log(logLevel, eventId, exception, message, args);
             }
         }
@@ -603,6 +611,10 @@ public static void Log(LogLevel logLevel, EventId eventId, Exception exception,
             string messageFormat,
             params object[] args)
         {
+            if (EventLog.IsEnabled())
+            {
+                return EventLog.BeginScope(messageFormat, args);
+            }
             return Logger.BeginScope(messageFormat, args);
         }
         #endregion
@@ -613,7 +625,7 @@ public static void Log(LogLevel logLevel, EventId eventId, Exception exception,
         /// </summary>
         /// <param name="eventId">The event id.</param>
         /// <param name="logLevel">The log level.</param>
-        private static int GetTraceMask(EventId eventId, LogLevel logLevel)
+        internal static int GetTraceMask(EventId eventId, LogLevel logLevel)
         {
             int mask = eventId.Id & TraceMasks.All;
             if (mask == 0)
@@ -625,10 +637,15 @@ private static int GetTraceMask(EventId eventId, LogLevel logLevel)
                     case LogLevel.Error:
                         mask = TraceMasks.Error;
                         break;
-                    default:
                     case LogLevel.Information:
                         mask = TraceMasks.Information;
                         break;
+#if DEBUG
+                    case LogLevel.Debug:
+#endif
+                    case LogLevel.Trace:
+                        mask = TraceMasks.Operation;
+                        break;
                 }
             }
             return mask;