Refactor trace messages

Build/MQTTnet.nuspec

@@ -2,7 +2,7 @@
 <package >
   <metadata>
     <id>MQTTnet</id>
-    <version>2.5.1.1</version>
+    <version>2.5.2</version>
     <authors>Christian Kratky</authors>
     <owners>Christian Kratky</owners>
     <licenseUrl>https://github.com/chkr1011/MQTTnet/blob/master/LICENSE</licenseUrl>
@@ -10,13 +10,7 @@
     <iconUrl>https://raw.githubusercontent.com/chkr1011/MQTTnet/master/Images/Logo_128x128.png</iconUrl>
     <requireLicenseAcceptance>false</requireLicenseAcceptance>
     <description>MQTTnet is a high performance .NET library for MQTT based communication. It provides a MQTT client and a MQTT server (broker).</description>
-    <releaseNotes>* [Core] Fixed library reference issues for .NET 4.6 and netstandard 2.0 (Thanks to @JanEggers).
+    <releaseNotes>* [Core] Refactored trace messages.
-* [Core] Several COM exceptions are now wrapped properly resulting in less warnings in the trace.
-* [Core] Removed application message payload from trace to reduce trace size and increase performance.
-* [Client] Fixed WebSocket sub protocol negotiation for ASP.NET Core 2 servers (Thanks to @JanEggers).
-* [Client] Fixed broken connection after 30 seconds then using WebSocket protocol (Thanks to @ChristianRiedl).
-* [Server] Client connections are now closed when the server is stopped (Thanks to @zhudanfei).
-* [Server] Published messages from the server are now retained (if set) (Thanks to @ChristianRiedl). BREAKING CHANGE!
     </releaseNotes>
     <copyright>Copyright Christian Kratky 2016-2017</copyright>
     <tags>MQTT Message Queue Telemetry Transport MQTTClient MQTTServer Server MQTTBroker Broker NETStandard IoT InternetOfThings Messaging Hardware Arduino Sensor Actuator M2M ESP Smart Home Cities Automation Xamarin</tags> 

Build/build.ps1

@@ -1,4 +1,4 @@
-param([string]$version)
+param([string]$assemblyVersion, [string]$nugetVersion)
 
 if ([string]::IsNullOrEmpty($version)) {$version = "0.0.1"}
 
@@ -8,17 +8,16 @@ $path = &$vswhere -latest -products * -requires Microsoft.Component.MSBuild -pro
 if ($path) {
     $msbuild = join-path $path 'MSBuild\15.0\Bin\MSBuild.exe'
 
-    &$msbuild ..\Frameworks\MQTTnet.Netstandard\MQTTnet.Netstandard.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="net452" /p:FileVersion=$version /p:AssemblyVersion=$version /verbosity:m
+    &$msbuild ..\Frameworks\MQTTnet.Netstandard\MQTTnet.Netstandard.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="net452" /p:FileVersion=$assemblyVersion /p:AssemblyVersion=$assemblyVersion /verbosity:m
-    &$msbuild ..\Frameworks\MQTTnet.Netstandard\MQTTnet.Netstandard.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="net461" /p:FileVersion=$version /p:AssemblyVersion=$version /verbosity:m
+    &$msbuild ..\Frameworks\MQTTnet.Netstandard\MQTTnet.Netstandard.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="net461" /p:FileVersion=$assemblyVersion /p:AssemblyVersion=$assemblyVersion /verbosity:m
-    &$msbuild ..\Frameworks\MQTTnet.Netstandard\MQTTnet.Netstandard.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="netstandard1.3" /p:FileVersion=$version /p:AssemblyVersion=$version /verbosity:m
+    &$msbuild ..\Frameworks\MQTTnet.Netstandard\MQTTnet.Netstandard.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="netstandard1.3" /p:FileVersion=$assemblyVersion /p:AssemblyVersion=$assemblyVersion /verbosity:m
-    &$msbuild ..\Frameworks\MQTTnet.Netstandard\MQTTnet.Netstandard.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="netstandard2.0" /p:FileVersion=$version /p:AssemblyVersion=$version /verbosity:m
+    &$msbuild ..\Frameworks\MQTTnet.Netstandard\MQTTnet.Netstandard.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="netstandard2.0" /p:FileVersion=$assemblyVersion /p:AssemblyVersion=$assemblyVersion /verbosity:m
-    &$msbuild ..\Frameworks\MQTTnet.Netstandard\MQTTnet.Netstandard.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="uap10.0" /p:FileVersion=$version /p:AssemblyVersion=$version /verbosity:m
+    &$msbuild ..\Frameworks\MQTTnet.Netstandard\MQTTnet.Netstandard.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="uap10.0" /p:FileVersion=$assemblyVersion /p:AssemblyVersion=$assemblyVersion /verbosity:m
     
-	&$msbuild ..\Frameworks\MQTTnet.AspNetCore\MQTTnet.AspNetCore.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="netstandard2.0" /p:FileVersion=$version /p:AssemblyVersion=$version /verbosity:m
+	&$msbuild ..\Frameworks\MQTTnet.AspNetCore\MQTTnet.AspNetCore.csproj /t:Build /p:Configuration="Release" /p:TargetFramework="netstandard2.0" /p:FileVersion=$assemblyVersion /p:AssemblyVersion=$assemblyVersion /verbosity:m
 
     Remove-Item .\NuGet -Force -Recurse
     New-Item -ItemType Directory -Force -Path .\NuGet
-    .\NuGet.exe pack MQTTnet.nuspec -Verbosity detailed -Symbols -OutputDir "NuGet" -Version $version
+    .\NuGet.exe pack MQTTnet.nuspec -Verbosity detailed -Symbols -OutputDir "NuGet" -Version $nugetVersion
-    .\NuGet.exe pack MQTTnet.AspNetCore.nuspec -Verbosity detailed -Symbols -OutputDir "NuGet" -Version $version
+    .\NuGet.exe pack MQTTnet.AspNetCore.nuspec -Verbosity detailed -Symbols -OutputDir "NuGet" -Version $nugetVersion
-}
+}
-

Frameworks/MQTTnet.AspnetCore/MQTTnet.AspnetCore.csproj

@@ -2,6 +2,8 @@
 
   <PropertyGroup>
     <TargetFramework>netstandard2.0</TargetFramework>
+    <AssemblyVersion>2.5.2.0</AssemblyVersion>
+    <FileVersion>2.5.2.0</FileVersion>
   </PropertyGroup>
 
   <ItemGroup>

Frameworks/MQTTnet.NetStandard/MQTTnet.Netstandard.csproj

@@ -4,8 +4,8 @@
     <TargetFrameworks>netstandard1.3;netstandard2.0;net452;net461;uap10.0</TargetFrameworks>
     <AssemblyName>MQTTnet</AssemblyName>
     <RootNamespace>MQTTnet</RootNamespace>
-    <AssemblyVersion>2.5.0.0</AssemblyVersion>
+    <AssemblyVersion>2.5.2.0</AssemblyVersion>
-    <FileVersion>2.5.0.0</FileVersion>
+    <FileVersion>2.5.2.0</FileVersion>
     <Version>0.0.0.0</Version>
     <Company />
     <Product />

MQTTnet.Core/Adapter/MqttChannelCommunicationAdapter.cs

@@ -32,11 +32,15 @@ namespace MQTTnet.Core.Adapter
 
         public async Task ConnectAsync(TimeSpan timeout)
         {
+            _logger.LogInformation("Connecting [Timeout={0}]", timeout);
+
             await ExecuteAndWrapExceptionAsync(() => _channel.ConnectAsync().TimeoutAfter(timeout));
         }
 
         public async Task DisconnectAsync(TimeSpan timeout)
         {
+            _logger.LogInformation("Disconnecting [Timeout={0}]", timeout);
+
             await ExecuteAndWrapExceptionAsync(() => _channel.DisconnectAsync().TimeoutAfter(timeout));
         }
 

MQTTnet.Core/MQTTnet.Core.csproj

@@ -17,8 +17,8 @@
     <PackageIconUrl></PackageIconUrl>
     <RepositoryUrl></RepositoryUrl>
     <PackageTags></PackageTags>
-    <FileVersion>2.5.0.0</FileVersion>
+    <FileVersion>2.5.2.0</FileVersion>
-    <AssemblyVersion>2.5.0.0</AssemblyVersion>
+    <AssemblyVersion>2.5.2.0</AssemblyVersion>
     <PackageLicenseUrl></PackageLicenseUrl>
   </PropertyGroup>
 

MQTTnet.Core/Packets/MqttConnAckPacket.cs

@@ -10,7 +10,7 @@ namespace MQTTnet.Core.Packets
 
         public override string ToString()
         {
-            return nameof(MqttConnAckPacket) + ": [ConnectReturnCode=" + ConnectReturnCode + "] [IsSessionPresent=" + IsSessionPresent + "]";
+            return "ConnAck: [ConnectReturnCode=" + ConnectReturnCode + "] [IsSessionPresent=" + IsSessionPresent + "]";
         }
     }
 }

MQTTnet.Core/Packets/MqttConnectPacket.cs

@@ -20,7 +20,7 @@ namespace MQTTnet.Core.Packets
 
         public override string ToString()
         {
-            return nameof(MqttConnectPacket) + ": [ClientId=" + ClientId + "] [Username=" + Username + "] [Password=" + Password + "] [KeepAlivePeriod=" + KeepAlivePeriod + "] [CleanSession=" + CleanSession + "]";
+            return "Connect: [ClientId=" + ClientId + "] [Username=" + Username + "] [Password=" + Password + "] [KeepAlivePeriod=" + KeepAlivePeriod + "] [CleanSession=" + CleanSession + "]";
         }
     }
 }

MQTTnet.Core/Packets/MqttDisconnectPacket.cs

@@ -2,5 +2,9 @@
 {
     public sealed class MqttDisconnectPacket : MqttBasePacket
     {
+        public override string ToString()
+        {
+            return "Disconnect";
+        }
     }
 }

MQTTnet.Core/Packets/MqttPingReqPacket.cs

@@ -4,7 +4,7 @@
     {
         public override string ToString()
         {
-            return nameof(MqttPingReqPacket);
+            return "PingReq";
         }
     }
 }

MQTTnet.Core/Packets/MqttPingRespPacket.cs

@@ -4,7 +4,7 @@
     {
         public override string ToString()
         {
-            return nameof(MqttPingRespPacket);
+            return "PingResp";
         }
     }
 }

MQTTnet.Core/Packets/MqttPubAckPacket.cs

@@ -2,5 +2,9 @@
 {
     public sealed class MqttPubAckPacket : MqttBasePublishPacket
     {
+        public override string ToString()
+        {
+            return "PubAck";
+        }
     }
 }

MQTTnet.Core/Packets/MqttPubCompPacket.cs

@@ -2,5 +2,9 @@
 {
     public sealed class MqttPubCompPacket : MqttBasePublishPacket
     {
+        public override string ToString()
+        {
+            return "PubComp";
+        }
     }
 }

MQTTnet.Core/Packets/MqttPubRecPacket.cs

@@ -2,5 +2,9 @@
 {
     public sealed class MqttPubRecPacket : MqttBasePublishPacket
     {
+        public override string ToString()
+        {
+            return "PubRec";
+        }
     }
 }

MQTTnet.Core/Packets/MqttPubRelPacket.cs

@@ -2,5 +2,9 @@
 {
     public sealed class MqttPubRelPacket : MqttBasePublishPacket
     {
+        public override string ToString()
+        {
+            return "PubRel";
+        }
     }
 }

MQTTnet.Core/Packets/MqttPublishPacket.cs

@@ -16,9 +16,8 @@ namespace MQTTnet.Core.Packets
 
         public override string ToString()
         {
-            return nameof(MqttPublishPacket) +
+            return "Publish: [Topic=" + Topic + "]" +
-                ": [Topic=" + Topic + "]" +
+                " [Payload.Length=" + Payload?.Length + "]" +
-                " [PayloadLength=" + Payload?.Length + "]" +
                 " [QoSLevel=" + QualityOfServiceLevel + "]" +
                 " [Dup=" + Dup + "]" +
                 " [Retain=" + Retain + "]" +

MQTTnet.Core/Packets/MqttSubAckPacket.cs

@@ -13,7 +13,7 @@ namespace MQTTnet.Core.Packets
         public override string ToString()
         {
             var subscribeReturnCodesText = string.Join(",", SubscribeReturnCodes.Select(f => f.ToString()));
-            return nameof(MqttSubAckPacket) + ": [PacketIdentifier=" + PacketIdentifier + "] [SubscribeReturnCodes=" + subscribeReturnCodesText + "]";
+            return "SubAck: [PacketIdentifier=" + PacketIdentifier + "] [SubscribeReturnCodes=" + subscribeReturnCodesText + "]";
         }
     }
 }

MQTTnet.Core/Packets/MqttSubscribePacket.cs

@@ -12,7 +12,7 @@ namespace MQTTnet.Core.Packets
         public override string ToString()
         {
             var topicFiltersText = string.Join(",", TopicFilters.Select(f => f.Topic + "@" + f.QualityOfServiceLevel));
-            return nameof(MqttSubscribePacket) + ": [PacketIdentifier=" + PacketIdentifier + "] [TopicFilters=" + topicFiltersText + "]";
+            return "Subscribe: [PacketIdentifier=" + PacketIdentifier + "] [TopicFilters=" + topicFiltersText + "]";
         }
     }
 }

MQTTnet.Core/Packets/MqttUnsubAckPacket.cs

@@ -3,5 +3,10 @@
     public sealed class MqttUnsubAckPacket : MqttBasePacket, IMqttPacketWithIdentifier
     {
         public ushort PacketIdentifier { get; set; }
+
+        public override string ToString()
+        {
+            return "UnsubAck: [PacketIdentifier=" + PacketIdentifier + "]";
+        }
     }
 }

MQTTnet.Core/Packets/MqttUnsubscribe.cs

@@ -7,5 +7,11 @@ namespace MQTTnet.Core.Packets
         public ushort PacketIdentifier { get; set; }
 
         public IList<string> TopicFilters { get; set; } = new List<string>();
+
+        public override string ToString()
+        {
+            var topicFiltersText = string.Join(",", TopicFilters);
+            return "Subscribe: [PacketIdentifier=" + PacketIdentifier + "] [TopicFilters=" + topicFiltersText + "]";
+        }
     }
 }

MQTTnet.Core/Server/MqttClientRetainedMessagesManager.cs

@@ -57,42 +57,7 @@ namespace MQTTnet.Core.Server
             await _gate.WaitAsync().ConfigureAwait(false);
             try
             {
-                var saveIsRequired = false;
+                await HandleMessageInternalAsync(clientId, applicationMessage);
-
-                if (applicationMessage.Payload?.Any() == false)
-                {
-                    saveIsRequired = _retainedMessages.Remove(applicationMessage.Topic);
-                    _logger.LogInformation("Client '{0}' cleared retained message for topic '{1}'.", clientId, applicationMessage.Topic);
-                }
-                else
-                {
-                    if (!_retainedMessages.ContainsKey(applicationMessage.Topic))
-                    {
-                        _retainedMessages[applicationMessage.Topic] = applicationMessage;
-                        saveIsRequired = true;
-                    }
-                    else
-                    {
-                        var existingMessage = _retainedMessages[applicationMessage.Topic];
-                        if (existingMessage.QualityOfServiceLevel != applicationMessage.QualityOfServiceLevel || !existingMessage.Payload.SequenceEqual(applicationMessage.Payload ?? new byte[0]))
-                        {
-                            _retainedMessages[applicationMessage.Topic] = applicationMessage;
-                            saveIsRequired = true;
-                        }
-                    }
-                    
-                    _logger.LogInformation("Client '{0}' set retained message for topic '{1}'.", clientId, applicationMessage.Topic);
-                }
-
-                if (!saveIsRequired)
-                {
-                    _logger.LogTrace("Skipped saving retained messages because no changes were detected.");
-                }
-
-                if (saveIsRequired && _options.Storage != null)
-                {
-                    await _options.Storage.SaveRetainedMessagesAsync(_retainedMessages.Values.ToList());
-                }
             }
             catch (Exception exception)
             {
@@ -137,5 +102,45 @@ namespace MQTTnet.Core.Server
 
             return retainedMessages;
         }
+
+        private async Task HandleMessageInternalAsync(string clientId, MqttApplicationMessage applicationMessage)
+        {
+            var saveIsRequired = false;
+
+            if (applicationMessage.Payload?.Any() == false)
+            {
+                saveIsRequired = _retainedMessages.Remove(applicationMessage.Topic);
+                _logger.LogInformation("Client '{0}' cleared retained message for topic '{1}'.", clientId, applicationMessage.Topic);
+            }
+            else
+            {
+                if (!_retainedMessages.ContainsKey(applicationMessage.Topic))
+                {
+                    _retainedMessages[applicationMessage.Topic] = applicationMessage;
+                    saveIsRequired = true;
+                }
+                else
+                {
+                    var existingMessage = _retainedMessages[applicationMessage.Topic];
+                    if (existingMessage.QualityOfServiceLevel != applicationMessage.QualityOfServiceLevel || !existingMessage.Payload.SequenceEqual(applicationMessage.Payload ?? new byte[0]))
+                    {
+                        _retainedMessages[applicationMessage.Topic] = applicationMessage;
+                        saveIsRequired = true;
+                    }
+                }
+
+                _logger.LogInformation("Client '{0}' set retained message for topic '{1}'.", clientId, applicationMessage.Topic);
+            }
+
+            if (!saveIsRequired)
+            {
+                _logger.LogTrace("Skipped saving retained messages because no changes were detected.");
+            }
+
+            if (saveIsRequired && _options.Storage != null)
+            {
+                await _options.Storage.SaveRetainedMessagesAsync(_retainedMessages.Values.ToList());
+            }
+        }
     }
 }

Tests/MQTTnet.TestApp.UniversalWindows/MainPage.xaml.cs

@@ -1,4 +1,5 @@
 using System;
+using System.Collections.Concurrent;
 using System.Text;
 using System.Threading.Tasks;
 using Windows.Security.Cryptography.Certificates;
@@ -18,6 +19,8 @@ namespace MQTTnet.TestApp.UniversalWindows
 {
     public sealed partial class MainPage
     {
+        private readonly ConcurrentQueue<MqttNetTraceMessage> _traceMessages = new ConcurrentQueue<MqttNetTraceMessage>();
+
         private IMqttClient _mqttClient;
         private IMqttServer _mqttServer;
 
@@ -30,15 +33,32 @@ namespace MQTTnet.TestApp.UniversalWindows
 
         private async void OnTraceMessagePublished(object sender, MqttNetTraceMessagePublishedEventArgs e)
         {
-            var text = $"[{e.TraceMessage.Timestamp:yyyy-MM-dd HH:mm:ss.fff}] [{e.TraceMessage.Level}] [{e.TraceMessage.Source}] [{e.TraceMessage.ThreadId}] [{e.TraceMessage.Message}]{Environment.NewLine}";
+            _traceMessages.Enqueue(e.TraceMessage);
-            if (e.TraceMessage.Exception != null)
+            while (_traceMessages.Count > 100)
             {
-                text += $"{e.TraceMessage.Exception}{Environment.NewLine}";
+                _traceMessages.TryDequeue(out _);
             }
-            
+
+            var logText = new StringBuilder();
+            foreach (var traceMessage in _traceMessages)
+            {
+                logText.AppendFormat(
+                    "[{0:yyyy-MM-dd HH:mm:ss.fff}] [{1}] [{2}] [{3}] [{4}]{5}", traceMessage.Timestamp,
+                    traceMessage.Level,
+                    traceMessage.Source,
+                    traceMessage.ThreadId,
+                    traceMessage.Message,
+                    Environment.NewLine);
+
+                if (traceMessage.Exception != null)
+                {
+                    logText.AppendLine(traceMessage.Exception.ToString());
+                }
+            }
+
             await Trace.Dispatcher.RunAsync(CoreDispatcherPriority.Low, () =>
             {
-                Trace.Text += text;
+                Trace.Text = logText.ToString();
             });
         }