Use Docker Timestamp When Log Timestamp is not Available in JSON log. (…

…#5173)

Derived from #4981

Context:
It generates the attached file, if a module does not use the prescribed logging format (which most module do not), the timestamp is 0. This makes the logs not very useful. The timestamp irrespective of logging format is actually available from Docker log API.

Solution: 
This PR issues `timestamps` from edgeAgent via mgmt.sock to prepending the returning log with timestamp.  edgeAgent then parse the timestamp & return the value in json format to portal.

Note: 
This feature requires #5172

builds/checkin/dotnet.yaml

@@ -46,7 +46,12 @@ jobs:
         displayName: Test
         inputs:
           filePath: scripts/linux/runTests.sh
-          arguments: '"--filter Category=Unit"'
+          arguments: '"--filter Category=Unit&Category!=GetLogsTests"'
+      - task: Bash@3
+        displayName: Run GetLogsTests Tests
+        inputs:
+          filePath: scripts/linux/runTests.sh
+          arguments: '"--filter Category=GetLogsTests"'
       - task: PublishTestResults@2
         displayName: Publish Test Results
         inputs:
@@ -73,7 +78,12 @@ jobs:
         displayName: Test
         inputs:
           filePath: scripts/windows/test/Test-Branch.ps1
-          arguments: -Filter Category=Unit
+          arguments: -Filter:"Category=Unit&Category!=GetLogsTests"
+      - task: PowerShell@2
+        displayName: Run GetLogsTests Tests
+        inputs:
+          filePath: scripts/windows/test/Test-Branch.ps1
+          arguments: -Filter:"Category=GetLogsTests"
       - task: PublishTestResults@2
         displayName: Publish Test Results
         inputs:
@@ -103,7 +113,19 @@ jobs:
           testSelector: testAssemblies
           testAssemblyVer2: |
             target\*Test.dll
-          testFiltercriteria: Category=Unit
+          testFiltercriteria: Category=Unit&Category!=GetLogsTests
+          runInParallel: true
+          runTestsInIsolation: true
+          codeCoverageEnabled: true
+          runSettingsFile: CodeCoverage.runsettings
+          publishRunAttachments: true
+      - task: VSTest@2
+        displayName: Run GetLogsTests unit tests with code coverage
+        inputs:
+          testSelector: testAssemblies
+          testAssemblyVer2: |
+            target\*Test.dll
+          testFiltercriteria: Category=GetLogsTests
           runInParallel: true
           runTestsInIsolation: true
           codeCoverageEnabled: true

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/IRuntimeInfoProvider.cs

@@ -16,7 +16,7 @@ public interface IRuntimeInfoProvider
     {
         Task<IEnumerable<ModuleRuntimeInfo>> GetModules(CancellationToken cancellationToken);
 
-        Task<Stream> GetModuleLogs(string module, bool follow, Option<int> tail, Option<string> since, Option<string> until, CancellationToken cancellationToken);
+        Task<Stream> GetModuleLogs(string module, bool follow, Option<int> tail, Option<string> since, Option<string> until, Option<bool> includeTimestamp, CancellationToken cancellationToken);
 
         Task<SystemInfo> GetSystemInfo(CancellationToken cancellationToken);
     }

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/logs/ILogMessageParser.cs

@@ -3,6 +3,7 @@ namespace Microsoft.Azure.Devices.Edge.Agent.Core.Logs
 {
     extern alias akka;
     using akka::Akka.IO;
+    using Microsoft.Azure.Devices.Edge.Util;
 
     public interface ILogMessageParser
     {

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/logs/LogMessageParser.cs

@@ -29,7 +29,7 @@ namespace Microsoft.Azure.Devices.Edge.Agent.Core.Logs
     public class LogMessageParser : ILogMessageParser
     {
         const int DefaultLogLevel = 6;
-        const string LogRegexPattern = @"^(<(?<logLevel>\d)>)?\s*((?<timestamp>\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}.\d{3}\s[+-]\d{2}:\d{2})\s)?\s*(?<logtext>.*)";
+        const string LogRegexPattern = @"^((?<dockerTimestamp>\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{9}Z))?\s*(<(?<logLevel>\d)>)?\s*((?<timestamp>\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}.\d{3}\s[+-]\d{2}:\d{2})\s)?\s*(?<logtext>.*)";
 
         readonly string iotHubName;
         readonly string deviceId;
@@ -48,6 +48,7 @@ internal static ModuleLogMessageData GetLogMessage(ByteString arg, string iotHub
             string stream = GetStream(arg[0]);
             ByteString payload = arg.Slice(8);
             string payloadString = payload.ToString(Encoding.UTF8);
+
             (int logLevel, Option<DateTime> timeStamp, string logText) = ParseLogText(payloadString);
             var moduleLogMessage = new ModuleLogMessageData(iotHubName, deviceId, moduleId, stream, logLevel, timeStamp, logText, arg, payloadString);
             return moduleLogMessage;
@@ -58,14 +59,24 @@ internal static ModuleLogMessageData GetLogMessage(ByteString arg, string iotHub
         internal static (int logLevel, Option<DateTime> timeStamp, string text) ParseLogText(string value)
         {
             var regex = new Regex(LogRegexPattern);
+
             var match = regex.Match(value);
             int logLevel = DefaultLogLevel;
             string text = value;
             Option<DateTime> timeStamp = Option.None<DateTime>();
             if (match.Success)
             {
+                var dtsg = match.Groups["dockerTimestamp"];
+                if (dtsg?.Length > 0)
+                {
+                    if (DateTime.TryParse(dtsg.Value, out DateTime dt))
+                    {
+                        timeStamp = Option.Some(dt);
+                    }
+                }
+
                 var tsg = match.Groups["timestamp"];
-                if (tsg?.Length > 0)
+                if (tsg?.Length > 0 && !timeStamp.HasValue)
                 {
                     if (DateTime.TryParse(tsg.Value, out DateTime dt))
                     {

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/logs/LogsProvider.cs

@@ -26,7 +26,12 @@ public async Task<byte[]> GetLogs(string id, ModuleLogOptions logOptions, Cancel
         {
             Preconditions.CheckNotNull(logOptions, nameof(logOptions));
 
-            Stream logsStream = await this.runtimeInfoProvider.GetModuleLogs(id, false, logOptions.Filter.Tail, logOptions.Filter.Since, logOptions.Filter.Until, cancellationToken);
+            if (logOptions.ContentType == LogsContentType.Json)
+            {
+                logOptions.Filter.IncludeTimestamp = Option.Some(true);
+            }
+
+            Stream logsStream = await this.runtimeInfoProvider.GetModuleLogs(id, false, logOptions.Filter.Tail, logOptions.Filter.Since, logOptions.Filter.Until, logOptions.Filter.IncludeTimestamp, cancellationToken);
             Events.ReceivedStream(id);
 
             byte[] logBytes = await this.GetProcessedLogs(id, logsStream, logOptions);
@@ -60,7 +65,7 @@ internal async Task GetLogsStreamInternal(string id, ModuleLogOptions logOptions
             Preconditions.CheckNotNull(logOptions, nameof(logOptions));
             Preconditions.CheckNotNull(callback, nameof(callback));
 
-            Stream logsStream = await this.runtimeInfoProvider.GetModuleLogs(id, logOptions.Follow, logOptions.Filter.Tail, logOptions.Filter.Since, logOptions.Filter.Until, cancellationToken);
+            Stream logsStream = await this.runtimeInfoProvider.GetModuleLogs(id, logOptions.Follow, logOptions.Filter.Tail, logOptions.Filter.Since, logOptions.Filter.Until, logOptions.Filter.IncludeTimestamp, cancellationToken);
             Events.ReceivedStream(id);
 
             await this.logsProcessor.ProcessLogsStream(id, logsStream, logOptions, callback);

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Core/logs/ModuleLogFilter.cs

@@ -10,21 +10,22 @@ namespace Microsoft.Azure.Devices.Edge.Agent.Core.Logs
 
     public class ModuleLogFilter : IEquatable<ModuleLogFilter>
     {
-        public static ModuleLogFilter Empty = new ModuleLogFilter(Option.None<int>(), Option.None<string>(), Option.None<string>(), Option.None<int>(), Option.None<string>());
+        public static ModuleLogFilter Empty = new ModuleLogFilter(Option.None<int>(), Option.None<string>(), Option.None<string>(), Option.None<int>(), Option.None<bool>(), Option.None<string>());
 
-        public ModuleLogFilter(Option<int> tail, Option<string> since, Option<string> until, Option<int> logLevel, Option<string> regex)
+        public ModuleLogFilter(Option<int> tail, Option<string> since, Option<string> until, Option<int> logLevel, Option<bool> includeTimestamp, Option<string> regex)
         {
             this.Tail = tail;
             this.Since = since;
             this.Until = until;
             this.LogLevel = logLevel;
             this.RegexString = regex;
+            this.IncludeTimestamp = includeTimestamp;
             this.Regex = regex.Map(r => new Regex(r));
         }
 
         [JsonConstructor]
-        ModuleLogFilter(int? tail, string since, string until, int? loglevel, string regex)
-            : this(Option.Maybe(tail), Option.Maybe(since), Option.Maybe(until), Option.Maybe(loglevel), Option.Maybe(regex))
+        ModuleLogFilter(int? tail, string since, string until, int? loglevel, bool? includeTimestamp, string regex)
+            : this(Option.Maybe(tail), Option.Maybe(since), Option.Maybe(until), Option.Maybe(loglevel), Option.Maybe(includeTimestamp), Option.Maybe(regex))
         {
         }
 
@@ -44,6 +45,9 @@ public ModuleLogFilter(Option<int> tail, Option<string> since, Option<string> un
         [JsonConverter(typeof(OptionConverter<int>), true)]
         public Option<int> LogLevel { get; }
 
+        [JsonIgnore]
+        public Option<bool> IncludeTimestamp { get; set; }
+
         [JsonIgnore]
         public Option<Regex> Regex { get; }
 
@@ -59,6 +63,7 @@ public bool Equals(ModuleLogFilter other)
                this.Tail.Equals(other.Tail) &&
                this.Since.Equals(other.Since) &&
                this.LogLevel.Equals(other.LogLevel) &&
+               this.IncludeTimestamp.Equals(other.IncludeTimestamp) &&
                this.RegexString.Equals(other.RegexString);
 
         public override int GetHashCode()
@@ -67,6 +72,7 @@ public override int GetHashCode()
             hashCode = hashCode * -1521134295 + EqualityComparer<Option<int>>.Default.GetHashCode(this.Tail);
             hashCode = hashCode * -1521134295 + EqualityComparer<Option<string>>.Default.GetHashCode(this.Since);
             hashCode = hashCode * -1521134295 + EqualityComparer<Option<int>>.Default.GetHashCode(this.LogLevel);
+            hashCode = hashCode * -1521134295 + EqualityComparer<Option<bool>>.Default.GetHashCode(this.IncludeTimestamp);
             hashCode = hashCode * -1521134295 + EqualityComparer<Option<string>>.Default.GetHashCode(this.RegexString);
             return hashCode;
         }

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Docker/RuntimeInfoProvider.cs

@@ -79,7 +79,7 @@ public async Task<IEnumerable<ModuleRuntimeInfo>> GetModules(CancellationToken c
             return modules;
         }
 
-        public Task<Stream> GetModuleLogs(string module, bool follow, Option<int> tail, Option<string> since, Option<string> until, CancellationToken cancellationToken)
+        public Task<Stream> GetModuleLogs(string module, bool follow, Option<int> tail, Option<string> since, Option<string> until, Option<bool> includeTimestamp, CancellationToken cancellationToken)
         {
             var containerLogsParameters = new ContainerLogsParameters
             {
@@ -89,6 +89,7 @@ public Task<Stream> GetModuleLogs(string module, bool follow, Option<int> tail,
             };
             tail.ForEach(t => containerLogsParameters.Tail = t.ToString());
             since.ForEach(t => containerLogsParameters.Since = t.ToString());
+            includeTimestamp.ForEach(t => containerLogsParameters.Timestamps = t);
 
             return this.client.Containers.GetContainerLogsAsync(module, containerLogsParameters, cancellationToken);
         }

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/IModuleManager.cs

@@ -34,7 +34,7 @@ public interface IModuleManager
 
         Task PrepareUpdateAsync(ModuleSpec moduleSpec);
 
-        Task<Stream> GetModuleLogs(string name, bool follow, Option<int> tail, Option<string> since, Option<string> until, CancellationToken cancellationToken);
+        Task<Stream> GetModuleLogs(string name, bool follow, Option<int> tail, Option<string> since, Option<string> until, Option<bool> includeTimestamp, CancellationToken cancellationToken);
 
         Task<Stream> GetSupportBundle(Option<string> since, Option<string> until, Option<string> iothubHostname, Option<bool> edgeRuntimeOnly, CancellationToken token);
     }

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/ModuleManagementHttpClient.cs

@@ -57,8 +57,8 @@ public ModuleManagementHttpClient(Uri managementUri, string serverSupportedApiVe
 
         public Task ReprovisionDeviceAsync() => this.inner.ReprovisionDeviceAsync();
 
-        public Task<Stream> GetModuleLogs(string name, bool follow, Option<int> tail, Option<string> since, Option<string> until, CancellationToken cancellationToken) =>
-            this.inner.GetModuleLogs(name, follow, tail, since, until, cancellationToken);
+        public Task<Stream> GetModuleLogs(string name, bool follow, Option<int> tail, Option<string> since, Option<string> until, Option<bool> includeTimestamp, CancellationToken cancellationToken) =>
+            this.inner.GetModuleLogs(name, follow, tail, since, until, includeTimestamp, cancellationToken);
 
         public Task<Stream> GetSupportBundle(Option<string> since, Option<string> until, Option<string> iothubHostname, Option<bool> edgeRuntimeOnly, CancellationToken token) =>
             this.inner.GetSupportBundle(since, until, iothubHostname, edgeRuntimeOnly, token);

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/RuntimeInfoProvider.cs

@@ -20,8 +20,8 @@ public RuntimeInfoProvider(IModuleManager moduleManager)
         public Task<IEnumerable<ModuleRuntimeInfo>> GetModules(CancellationToken token) =>
             this.moduleManager.GetModules<T>(token);
 
-        public Task<Stream> GetModuleLogs(string module, bool follow, Option<int> tail, Option<string> since, Option<string> until, CancellationToken cancellationToken) =>
-             this.moduleManager.GetModuleLogs(module, follow, tail, since, until, cancellationToken);
+        public Task<Stream> GetModuleLogs(string module, bool follow, Option<int> tail, Option<string> since, Option<string> until, Option<bool> includeTimestamp, CancellationToken cancellationToken) =>
+             this.moduleManager.GetModuleLogs(module, follow, tail, since, until, includeTimestamp, cancellationToken);
 
         public Task<SystemInfo> GetSystemInfo(CancellationToken token) => this.moduleManager.GetSystemInfoAsync(token);
 

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Edgelet/versioning/ModuleManagementHttpClientVersioned.cs

@@ -25,6 +25,7 @@ abstract class ModuleManagementHttpClientVersioned
         const string LogsUrlTailParameter = "tail";
         const string LogsUrlSinceParameter = "since";
         const string LogsUrlUntilParameter = "until";
+        const string LogsIncludeTimestampParameter = "timestamps";
 
         static readonly TimeSpan DefaultOperationTimeout = TimeSpan.FromMinutes(5);
 
@@ -84,7 +85,7 @@ abstract class ModuleManagementHttpClientVersioned
 
         public abstract Task<Stream> GetSupportBundle(Option<string> since, Option<string> until, Option<string> iothubHostname, Option<bool> edgeRuntimeOnly, CancellationToken token);
 
-        public virtual async Task<Stream> GetModuleLogs(string module, bool follow, Option<int> tail, Option<string> since, Option<string> until, CancellationToken cancellationToken)
+        public virtual async Task<Stream> GetModuleLogs(string module, bool follow, Option<int> tail, Option<string> since, Option<string> until, Option<bool> includeTimestamp, CancellationToken cancellationToken)
         {
             using (HttpClient httpClient = HttpClientHelper.GetHttpClient(this.ManagementUri))
             {
@@ -93,13 +94,15 @@ public virtual async Task<Stream> GetModuleLogs(string module, bool follow, Opti
                 logsUrl.AppendFormat(CultureInfo.InvariantCulture, LogsUrlTemplate, baseUrl, module, this.Version.Name, follow.ToString().ToLowerInvariant());
                 since.ForEach(s => logsUrl.AppendFormat($"&{LogsUrlSinceParameter}={Uri.EscapeUriString(s)}"));
                 until.ForEach(u => logsUrl.AppendFormat($"&{LogsUrlUntilParameter}={Uri.EscapeUriString(u)}"));
+                includeTimestamp.ForEach(b => logsUrl.AppendFormat($"&{LogsIncludeTimestampParameter}={b.ToString().ToLower()}"));
 
                 if (!(tail.HasValue && since.HasValue && until.HasValue))
                 {
                     tail.ForEach(t => logsUrl.AppendFormat($"&{LogsUrlTailParameter}={t}"));
                 }
 
                 var logsUri = new Uri(logsUrl.ToString());
+
                 var httpRequest = new HttpRequestMessage(HttpMethod.Get, logsUri);
                 Stream stream = await this.Execute(
                     async () =>
@@ -108,6 +111,7 @@ public virtual async Task<Stream> GetModuleLogs(string module, bool follow, Opti
                         return await httpResponseMessage.Content.ReadAsStreamAsync();
                     },
                     $"Get logs for {module}");
+
                 return stream;
             }
         }

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.IoTHub/blob/AzureBlobRequestsUploader.cs

@@ -49,6 +49,7 @@ public async Task UploadLogs(string uri, string id, byte[] payload, LogsContentE
                 string blobName = this.GetBlobName(id, GetLogsExtension(logsContentEncoding, logsContentType));
                 var container = new CloudBlobContainer(containerUri);
                 Events.Uploading(blobName, container.Name);
+
                 await ExecuteWithRetry(
                     () =>
                     {

edge-agent/src/Microsoft.Azure.Devices.Edge.Agent.Kubernetes/KubernetesRuntimeInfoProvider.cs

@@ -76,7 +76,7 @@ public async Task<IEnumerable<ModuleRuntimeInfo>> GetModules(CancellationToken c
             return await Task.FromResult(moduleRuntimeInfoList);
         }
 
-        public Task<Stream> GetModuleLogs(string module, bool follow, Option<int> tail, Option<string> since, Option<string> until, CancellationToken cancellationToken)
+        public Task<Stream> GetModuleLogs(string module, bool follow, Option<int> tail, Option<string> since, Option<string> until, Option<bool> includeTimestamp, CancellationToken cancellationToken)
         {
             return Task.FromResult(Stream.Null);
         }