From 1d036d1f3d2e59dd45c76c810c39a9c475c75acf Mon Sep 17 00:00:00 2001 From: Luis Cantero Date: Tue, 30 Jul 2024 23:02:58 +0200 Subject: [PATCH] Use code gen logging (#380) * Move calc to helper * Improve logs * Update version * Improve status codes * Cosmetic * Debug level * Disable publish metrics during high load * Remove test --- src/Helpers/MetricsHelper.cs | 27 +++- src/PlcServer.cs | 233 +++++++++++++++-------------------- tests/MetricsTests.cs | 11 +- version.json | 2 +- 4 files changed, 126 insertions(+), 147 deletions(-) diff --git a/src/Helpers/MetricsHelper.cs b/src/Helpers/MetricsHelper.cs index e4fc6297..83941e5c 100644 --- a/src/Helpers/MetricsHelper.cs +++ b/src/Helpers/MetricsHelper.cs @@ -1,5 +1,7 @@ namespace OpcPlc; +using Microsoft.Extensions.Logging; +using Opc.Ua; using System; using System.Collections.Generic; using System.Diagnostics.Metrics; @@ -151,18 +153,37 @@ public static void AddMonitoredItemCount(int delta = 1) /// /// Add a published count. /// - public static void AddPublishedCount(string sessionId, string subscriptionId, int dataPoints, int events) + public static void AddPublishedCount(string sessionId, string subscriptionId, NotificationMessage notificationMessage, ILogger logger) { if (!IsEnabled) { return; } - if (dataPoints > 0) + int events = 0; + int dataChanges = 0; + int diagnostics = 0; + notificationMessage.NotificationData.ForEach(x => { + if (x.Body is DataChangeNotification changeNotification) + { + dataChanges += changeNotification.MonitoredItems.Count; + diagnostics += changeNotification.DiagnosticInfos.Count; + } + else if (x.Body is EventNotificationList eventNotification) + { + events += eventNotification.Events.Count; + } + else + { + logger.LogDebug("Unknown notification type: {NotificationType}", x.Body.GetType().Name); + } + }); + + if (dataChanges > 0) { var dataPointsDimensions = MergeWithBaseDimensions( new KeyValuePair("type", "data_point")); - _publishedCountWithType.Add(dataPoints, dataPointsDimensions); + _publishedCountWithType.Add(dataChanges, dataPointsDimensions); } if (events > 0) diff --git a/src/PlcServer.cs b/src/PlcServer.cs index 83c6e7f3..330b9853 100644 --- a/src/PlcServer.cs +++ b/src/PlcServer.cs @@ -21,7 +21,9 @@ namespace OpcPlc; using System.Threading; public partial class PlcServer : StandardServer -{ +{ + private const uint PlcShutdownWaitSeconds = 10; + public PlcNodeManager PlcNodeManager { get; set; } public AlarmConditionServerNodeManager AlarmNodeManager { get; set; } @@ -37,7 +39,9 @@ public partial class PlcServer : StandardServer public readonly TimeService TimeService; private readonly ImmutableList _pluginNodes; private readonly ILogger _logger; - private readonly Timer _periodicLoggingTimer; + private readonly Timer _periodicLoggingTimer; + + private bool _disablePublishMetrics; public PlcServer(OpcPlcConfiguration config, PlcSimulation plcSimulation, TimeService timeService, ImmutableList pluginNodes, ILogger logger) { @@ -55,21 +59,20 @@ public PlcServer(OpcPlcConfiguration config, PlcSimulation plcSimulation, TimeSe ThreadPool.GetAvailableThreads(out int availWorkerThreads, out int availCompletionPortThreads); - _logger.LogInformation( - "\n\t# Open sessions: {Sessions}\n" + - "\t# Open subscriptions: {Subscriptions}\n" + - "\t# Monitored items: {MonitoredItems:N0}\n" + - "\t# Working set: {WorkingSet:N0} MB\n" + - "\t# Available worker threads: {AvailWorkerThreads:N0}\n" + - "\t# Available completion port threads: {AvailCompletionPortThreads:N0}\n" + - "\t# Thread count: {ThreadCount:N0}", - ServerInternal.SessionManager.GetSessions().Count, - ServerInternal.SubscriptionManager.GetSubscriptions().Count, - ServerInternal.SubscriptionManager.GetSubscriptions().Sum(s => s.MonitoredItemCount), - curProc.WorkingSet64 / 1024 / 1024, - availWorkerThreads, - availCompletionPortThreads, + int sessionCount = ServerInternal.SessionManager.GetSessions().Count; + IList subscriptions = ServerInternal.SubscriptionManager.GetSubscriptions(); + int monitoredItemsCount = subscriptions.Sum(s => s.MonitoredItemCount); + + LogPeriodicInfo( + sessionCount, + subscriptions.Count, + monitoredItemsCount, + curProc.WorkingSet64 / 1024 / 1024, + availWorkerThreads, + availCompletionPortThreads, curProc.Threads.Count); + + _disablePublishMetrics = sessionCount > 40 || monitoredItemsCount > 500; } catch { @@ -107,14 +110,15 @@ public override ResponseHeader CreateSession( MetricsHelper.AddSessionCount(sessionId.ToString()); - _logger.LogDebug("{function} completed successfully with sessionId: {sessionId}", nameof(CreateSession), sessionId); + LogSuccessWithSessionId(nameof(CreateSession), sessionId); return responseHeader; } catch (Exception ex) { - MetricsHelper.RecordTotalErrors(nameof(CreateSession)); - _logger.LogError(ex, "Error creating session"); + MetricsHelper.RecordTotalErrors(nameof(CreateSession)); + + LogError(nameof(CreateSession), ex); throw; } } @@ -140,10 +144,9 @@ public override ResponseHeader CreateSubscription( MetricsHelper.AddSubscriptionCount(context.SessionId.ToString(), subscriptionId.ToString()); - _logger.LogDebug( - "{function} completed successfully with sessionId: {sessionId} and subscriptionId: {subscriptionId}", - nameof(CreateSubscription), - context.SessionId, + LogSuccessWithSessionIdAndSubscriptionId( + nameof(CreateSubscription), + context.SessionId, subscriptionId); return responseHeader; @@ -151,7 +154,8 @@ public override ResponseHeader CreateSubscription( catch (Exception ex) { MetricsHelper.RecordTotalErrors(nameof(CreateSubscription)); - _logger.LogError(ex, "Error creating subscription"); + + LogError(nameof(CreateSubscription), ex); throw; } } @@ -175,7 +179,7 @@ public override ResponseHeader CreateMonitoredItems( MetricsHelper.AddMonitoredItemCount(itemsToCreate.Count); - _logger.LogDebug("{function} completed successfully with sessionId: {sessionId}, subscriptionId: {subscriptionId} and count: {count}", + LogSuccessWithSessionIdAndSubscriptionIdAndCount( nameof(CreateMonitoredItems), context.SessionId, subscriptionId, @@ -183,44 +187,11 @@ public override ResponseHeader CreateMonitoredItems( return responseHeader; } - catch (ServiceResultException ex) when (ex.StatusCode == StatusCodes.BadNoSubscription) - { - MetricsHelper.RecordTotalErrors(nameof(CreateMonitoredItems)); - - _logger.LogDebug( - ex, - "Failed creating monitored items: {StatusCode}", - StatusCodes.BadNoSubscription.ToString()); - - return new ResponseHeader { ServiceResult = StatusCodes.BadNoSubscription }; - } - catch (ServiceResultException ex) when (ex.StatusCode == StatusCodes.BadSessionIdInvalid) - { - MetricsHelper.RecordTotalErrors(nameof(CreateMonitoredItems)); - - _logger.LogDebug( - ex, - "Failed creating monitored items: {StatusCode}", - StatusCodes.BadSessionIdInvalid.ToString()); - - return new ResponseHeader { ServiceResult = StatusCodes.BadSessionIdInvalid }; - } - catch (ServiceResultException ex) when (ex.StatusCode == StatusCodes.BadSecureChannelIdInvalid) - { - MetricsHelper.RecordTotalErrors(nameof(CreateMonitoredItems)); - - _logger.LogDebug( - ex, - "Failed creating monitored items: {StatusCode}", - StatusCodes.BadSecureChannelIdInvalid.ToString()); - - return new ResponseHeader { ServiceResult = StatusCodes.BadSecureChannelIdInvalid }; - } catch (Exception ex) { MetricsHelper.RecordTotalErrors(nameof(CreateMonitoredItems)); - _logger.LogError(ex, "Error creating monitored items"); + LogError(nameof(CreateSubscription), ex); throw; } } @@ -248,28 +219,12 @@ public override ResponseHeader Publish( var responseHeader = base.Publish(requestHeader, subscriptionAcknowledgements, out subscriptionId, out availableSequenceNumbers, out moreNotifications, out notificationMessage, out results, out diagnosticInfos); - int events = 0; - int dataChanges = 0; - int diagnostics = 0; - notificationMessage.NotificationData.ForEach(x => { - if (x.Body is DataChangeNotification changeNotification) - { - dataChanges += changeNotification.MonitoredItems.Count; - diagnostics += changeNotification.DiagnosticInfos.Count; - } - else if (x.Body is EventNotificationList eventNotification) - { - events += eventNotification.Events.Count; - } - else - { - _logger.LogDebug("Unknown notification type: {notificationType}", x.Body.GetType().Name); - } - }); - - MetricsHelper.AddPublishedCount(context.SessionId.ToString(), subscriptionId.ToString(), dataChanges, events); + if (!_disablePublishMetrics) + { + MetricsHelper.AddPublishedCount(context.SessionId.ToString(), subscriptionId.ToString(), notificationMessage, _logger); + } - _logger.LogDebug("{function} successfully with session: {sessionId} and subscriptionId: {subscriptionId}", + LogSuccessWithSessionIdAndSubscriptionId( nameof(Publish), context.SessionId, subscriptionId); @@ -280,10 +235,10 @@ public override ResponseHeader Publish( { MetricsHelper.RecordTotalErrors(nameof(Publish)); - _logger.LogDebug( - ex, - "Failed to publish: {StatusCode}", - StatusCodes.BadNoSubscription.ToString()); + LogErrorWithStatusCode( + nameof(Publish), + nameof(StatusCodes.BadNoSubscription), + ex); return new ResponseHeader { ServiceResult = StatusCodes.BadNoSubscription }; } @@ -291,10 +246,10 @@ public override ResponseHeader Publish( { MetricsHelper.RecordTotalErrors(nameof(Publish)); - _logger.LogDebug( - ex, - "Failed to publish: {StatusCode}", - StatusCodes.BadSessionIdInvalid.ToString()); + LogErrorWithStatusCode( + nameof(Publish), + nameof(StatusCodes.BadSessionIdInvalid), + ex); return new ResponseHeader { ServiceResult = StatusCodes.BadSessionIdInvalid }; } @@ -302,10 +257,10 @@ public override ResponseHeader Publish( { MetricsHelper.RecordTotalErrors(nameof(Publish)); - _logger.LogDebug( - ex, - "Failed to publish: {StatusCode}", - StatusCodes.BadSecureChannelIdInvalid.ToString()); + LogErrorWithStatusCode( + nameof(Publish), + nameof(StatusCodes.BadSecureChannelIdInvalid), + ex); return new ResponseHeader { ServiceResult = StatusCodes.BadSecureChannelIdInvalid }; } @@ -313,7 +268,7 @@ public override ResponseHeader Publish( { MetricsHelper.RecordTotalErrors(nameof(Publish)); - _logger.LogError(ex, "Error publishing"); + LogError(nameof(Publish), ex); throw; } } @@ -333,48 +288,15 @@ public override ResponseHeader Read( { var responseHeader = base.Read(requestHeader, maxAge, timestampsToReturn, nodesToRead, out results, out diagnosticInfos); - _logger.LogDebug("{function} completed successfully", nameof(Read)); + LogSuccess(nameof(Read)); return responseHeader; } - catch (ServiceResultException ex) when (ex.StatusCode == StatusCodes.BadNoSubscription) - { - MetricsHelper.RecordTotalErrors(nameof(Read)); - - _logger.LogDebug( - ex, - "Failed to read: {StatusCode}", - StatusCodes.BadNoSubscription.ToString()); - - return new ResponseHeader { ServiceResult = StatusCodes.BadNoSubscription }; - } - catch (ServiceResultException ex) when (ex.StatusCode == StatusCodes.BadSessionIdInvalid) - { - MetricsHelper.RecordTotalErrors(nameof(Read)); - - _logger.LogDebug( - ex, - "Failed to read: {StatusCode}", - StatusCodes.BadSessionIdInvalid.ToString()); - - return new ResponseHeader { ServiceResult = StatusCodes.BadSessionIdInvalid }; - } - catch (ServiceResultException ex) when (ex.StatusCode == StatusCodes.BadSecureChannelIdInvalid) - { - MetricsHelper.RecordTotalErrors(nameof(Read)); - - _logger.LogDebug( - ex, - "Failed to read: {StatusCode}", - StatusCodes.BadSecureChannelIdInvalid.ToString()); - - return new ResponseHeader { ServiceResult = StatusCodes.BadSecureChannelIdInvalid }; - } catch (Exception ex) { MetricsHelper.RecordTotalErrors(nameof(Read)); - _logger.LogError(ex, "Error reading"); + LogError(nameof(Read), ex); throw; } } @@ -385,14 +307,15 @@ public override ResponseHeader Write(RequestHeader requestHeader, WriteValueColl { var responseHeader = base.Write(requestHeader, nodesToWrite, out results, out diagnosticInfos); - _logger.LogDebug("{function} completed successfully", nameof(Write)); + LogSuccess(nameof(Write)); return responseHeader; } catch (Exception ex) { MetricsHelper.RecordTotalErrors(nameof(Write)); - _logger.LogError(ex, "Error writing"); + + LogError(nameof(Write), ex); throw; } } @@ -459,13 +382,13 @@ protected override MasterNodeManager CreateMasterNodeManager(IServerInternal ser if (string.IsNullOrWhiteSpace(scriptFileName)) { string errorMessage = "The script file for deterministic testing is not set (deterministicalarms)"; - _logger.LogError(errorMessage); + LogErrorMessage(errorMessage); throw new Exception(errorMessage); } if (!File.Exists(scriptFileName)) { string errorMessage = $"The script file ({scriptFileName}) for deterministic testing does not exist"; - _logger.LogError(errorMessage); + LogErrorMessage(errorMessage); throw new Exception(errorMessage); } @@ -603,5 +526,49 @@ protected override void OnServerStopping() base.OnServerStopping(); } - private const uint PlcShutdownWaitSeconds = 10; + [LoggerMessage( + Level = LogLevel.Information, + Message = "\n\t# Open sessions: {Sessions}\n" + + "\t# Open subscriptions: {Subscriptions}\n" + + "\t# Monitored items: {MonitoredItems:N0}\n" + + "\t# Working set: {WorkingSet:N0} MB\n" + + "\t# Available worker threads: {AvailWorkerThreads:N0}\n" + + "\t# Available completion port threads: {AvailCompletionPortThreads:N0}\n" + + "\t# Thread count: {ThreadCount:N0}")] + partial void LogPeriodicInfo(int sessions, int subscriptions, int monitoredItems, long workingSet, int availWorkerThreads, int availCompletionPortThreads, int threadCount); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "{Function} completed successfully")] + partial void LogSuccess(string function); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "{Function} completed successfully with sessionId: {SessionId}")] + partial void LogSuccessWithSessionId(string function, NodeId sessionId); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "{Function} completed successfully with sessionId: {SessionId} and subscriptionId: {SubscriptionId}")] + partial void LogSuccessWithSessionIdAndSubscriptionId(string function, NodeId sessionId, uint subscriptionId); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "{Function} completed successfully with sessionId: {SessionId}, subscriptionId: {SubscriptionId} and count: {Count}")] + partial void LogSuccessWithSessionIdAndSubscriptionIdAndCount(string function, NodeId sessionId, uint subscriptionId, int count); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "{Function} error")] + partial void LogError(string function, Exception exception); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "{Function} error: {StatusCode}")] + partial void LogErrorWithStatusCode(string function, string statusCode, Exception exception); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "{message}")] + partial void LogErrorMessage(string message); } diff --git a/tests/MetricsTests.cs b/tests/MetricsTests.cs index 26b6df1e..6f715e03 100644 --- a/tests/MetricsTests.cs +++ b/tests/MetricsTests.cs @@ -2,6 +2,7 @@ namespace OpcPlc.Tests; using FluentAssertions; using NUnit.Framework; +using Opc.Ua; using System; using System.Collections.Generic; using System.Diagnostics.Metrics; @@ -79,16 +80,6 @@ public void TestAddMonitoredItemCount() counter.Should().Be(1); } - [Test] - public void TestAddPublishedCount() - { - var sessionId = Guid.NewGuid().ToString(); - var subscriptionId = Guid.NewGuid().ToString(); - MetricsHelper.AddPublishedCount(sessionId, subscriptionId, 1, 0); - _metrics.TryGetValue("opc_plc_published_count_with_type", out var counter).Should().BeTrue(); - counter.Should().Be(1); - } - [Test] public void TestRecordTotalErrors() { diff --git a/version.json b/version.json index 6977793d..1f1a5bbc 100644 --- a/version.json +++ b/version.json @@ -1,6 +1,6 @@ { "$schema": "https://raw.githubusercontent.com/AArnott/Nerdbank.GitVersioning/master/src/NerdBank.GitVersioning/version.schema.json", - "version": "2.12.20", + "version": "2.12.21", "versionHeightOffset": -1, "publicReleaseRefSpec": [ "^refs/heads/main$",