Adding diagnostics instrumentation around CosmosDB failures and process termination. (#341)

peterfelts · saixiaohui · commit b3de8ff5ce67 · 2019-03-29T15:41:22.000-07:00
diff --git a/Services.Test/Storage/CosmosDbSql/EngineTest.cs b/Services.Test/Storage/CosmosDbSql/EngineTest.cs
@@ -26,6 +26,7 @@ public class EngineTest
 
         private readonly Mock<IFactory> factory;
         private readonly Mock<ILogger> logger;
+        private readonly Mock<IDiagnosticsLogger> mockDiagnosticsLogger;
         private readonly Mock<IInstance> instance;
         private readonly Mock<ISDKWrapper> cosmosDbSql;
         private readonly Mock<IDocumentClient> cosmosDbSqlClient;
@@ -39,6 +40,7 @@ public EngineTest()
         {
             this.factory = new Mock<IFactory>();
             this.logger = new Mock<ILogger>();
+            this.mockDiagnosticsLogger = new Mock<IDiagnosticsLogger>();
             this.instance = new Mock<IInstance>();
 
             this.storageConfig = new Config { CosmosDbSqlDatabase = "db", CosmosDbSqlCollection = "coll" };
@@ -49,7 +51,7 @@ public EngineTest()
             this.cosmosDbSqlClient = new Mock<IDocumentClient>();
             this.cosmosDbSql.Setup(x => x.GetClientAsync(this.storageConfig)).ReturnsAsync(this.cosmosDbSqlClient.Object);
 
-            this.target = new Engine(this.factory.Object, this.logger.Object, this.instance.Object);
+            this.target = new Engine(this.factory.Object, this.logger.Object, this.mockDiagnosticsLogger.Object, this.instance.Object);
 
             this.target.Init(this.storageConfig);
             this.instance.Invocations.Clear();
@@ -59,7 +61,7 @@ public EngineTest()
         public void ItCanBeInitializedOnlyOnce()
         {
             // Act
-            var engine = new Engine(this.factory.Object, this.logger.Object, this.instance.Object);
+            var engine = new Engine(this.factory.Object, this.logger.Object, this.mockDiagnosticsLogger.Object, this.instance.Object);
             engine.Init(this.storageConfig);
 
             // Assert
diff --git a/Services.Test/Storage/EnginesTest.cs b/Services.Test/Storage/EnginesTest.cs
@@ -28,8 +28,9 @@ public EnginesTest()
             // implement the same interface and don't have a parameterless ctor
             this.instance = new Mock<IInstance>();
             var logger = new Mock<ILogger>();
+            var mockDiagnosticsLogger = new Mock<IDiagnosticsLogger>();
             this.factory.Setup(x => x.Resolve<CosmosDbSqlEngine>())
-                .Returns(new CosmosDbSqlEngine(this.factory.Object, logger.Object, this.instance.Object));
+                .Returns(new CosmosDbSqlEngine(this.factory.Object, logger.Object, mockDiagnosticsLogger.Object, this.instance.Object));
             this.factory.Setup(x => x.Resolve<TableStorageEngine>())
                 .Returns(new TableStorageEngine(this.factory.Object, logger.Object, this.instance.Object));
         }
diff --git a/Services/Storage/CosmosDbSql/Engine.cs b/Services/Storage/CosmosDbSql/Engine.cs
@@ -2,7 +2,6 @@
 
 using System;
 using System.Collections.Generic;
-using System.Linq;
 using System.Net;
 using System.Threading.Tasks;
 using Microsoft.Azure.Documents;
@@ -19,6 +18,7 @@ public class Engine : IEngine, IDisposable
         private readonly ILogger log;
         private readonly IInstance instance;
         private readonly IFactory factory;
+        private readonly IDiagnosticsLogger diagnosticsLogger;
 
         private Config storageConfig;
 
@@ -34,10 +34,12 @@ public class Engine : IEngine, IDisposable
         public Engine(
             IFactory factory,
             ILogger logger,
+            IDiagnosticsLogger diagnosticsLogger,
             IInstance instance)
         {
             this.log = logger;
             this.instance = instance;
+            this.diagnosticsLogger = diagnosticsLogger;
             this.factory = factory;
 
             this.disposedValue = false;
@@ -118,7 +120,11 @@ public async Task<IEnumerable<IDataRecord>> GetAllAsync()
             }
             catch (Exception e)
             {
-                this.log.Error("Unexpected error while reading from Cosmos DB SQL", () => new { this.storageName, e });
+                const string MSG = "Unexpected error while reading from Cosmos DB SQL";
+                var errorData = new { this.storageName, e };
+
+                this.log.Error(MSG, () => errorData);
+                this.diagnosticsLogger.LogServiceError(MSG, errorData);
                 throw new ExternalDependencyException(e);
             }
         }
@@ -146,8 +152,11 @@ public async Task<IDataRecord> CreateAsync(IDataRecord input)
             }
             catch (Exception e)
             {
-                this.log.Error("Unexpected error while writing to Cosmos DB SQL",
-                    () => new { this.storageName, Id = input.GetId(), e });
+                const string MSG = "Unexpected error while writing to Cosmos DB SQL";
+                var errorData = new { this.storageName, Id = input.GetId(), e };
+
+                this.log.Error(MSG, () => errorData);
+                this.diagnosticsLogger.LogServiceError(MSG, errorData);
                 throw new ExternalDependencyException(e);
             }
         }
@@ -182,8 +191,11 @@ public async Task<IDataRecord> UpsertAsync(IDataRecord input, string eTag)
             }
             catch (Exception e)
             {
-                this.log.Error("Unexpected error while writing to Cosmos DB SQL",
-                    () => new { this.storageName, Id = input.GetId(), eTag, e });
+                const string MSG = "Unexpected error while writing to Cosmos DB SQL";
+                var errorData = new { this.storageName, Id = input.GetId(), eTag, e };
+
+                this.log.Error(MSG, () => errorData);
+                this.diagnosticsLogger.LogServiceError(MSG, errorData);
                 throw new ExternalDependencyException(e);
             }
         }
@@ -207,8 +219,11 @@ public async Task DeleteAsync(string id)
             }
             catch (Exception e)
             {
-                this.log.Error("Unexpected error while writing to Cosmos DB SQL",
-                    () => new { this.storageName, id, e });
+                const string MSG = "Unexpected error while writing to Cosmos DB SQL";
+                var errorData = new { this.storageName, id, e };
+
+                this.log.Error(MSG, () => errorData);
+                this.diagnosticsLogger.LogServiceError(MSG, errorData);
                 throw new ExternalDependencyException(e);
             }
         }
@@ -274,8 +289,11 @@ public async Task<bool> TryToLockAsync(
             }
             catch (Exception e)
             {
-                this.log.Error("Unexpected error while writing to Cosmos DB SQL",
-                    () => new { this.storageName, id, ownerId, ownerType, lockDurationSecs = durationSeconds, e });
+                const string MSG = "Unexpected error while writing to Cosmos DB SQL";
+                var errorData = new { this.storageName, id, ownerId, ownerType, lockDurationSecs = durationSeconds, e };
+
+                this.log.Error(MSG, () => errorData);
+                this.diagnosticsLogger.LogServiceError(MSG, errorData);
             }
 
             return false;
@@ -321,8 +339,11 @@ public async Task<bool> TryToUnlockAsync(string id, string ownerId, string owner
             }
             catch (Exception e)
             {
-                this.log.Error("Unexpected error while writing to Cosmos DB SQL",
-                    () => new { this.storageName, id, ownerId, ownerType, e });
+                const string MSG = "Unexpected error while writing to Cosmos DB SQL";
+                var errorData = new { this.storageName, id, ownerId, ownerType, e };
+
+                this.log.Error(MSG, () => errorData);
+                this.diagnosticsLogger.LogServiceError(MSG, errorData);
             }
 
             return false;
@@ -397,8 +418,11 @@ private async Task SetupStorageAsync()
             }
             catch (Exception e)
             {
-                this.log.Error("Unexpected error while reading from Cosmos DB SQL",
-                    () => new { this.storageName, id, e });
+                const string MSG = "Unexpected error while reading from Cosmos DB SQL";
+                var errorData = new { this.storageName, id, e};
+
+                this.log.Error(MSG, () => errorData);
+                this.diagnosticsLogger.LogServiceError(MSG, errorData);
                 throw new ExternalDependencyException(e);
             }
         }
@@ -436,7 +460,11 @@ private async Task TryToDeleteExpiredRecord(string id)
             catch (Exception e)
             {
                 // Log and do not throw, we're just trying to delete and will retry automatically later
-                this.log.Warn("Unexpected error while writing to Cosmos DB SQL", () => new { this.storageName, id, e });
+                const string MSG = "Unexpected error while writing to Cosmos DB SQL";
+                var errorData = new { this.storageName, id, e };
+
+                this.log.Error(MSG, () => errorData);
+                this.diagnosticsLogger.LogServiceError(MSG, errorData);
             }
         }
     }
diff --git a/WebService/Startup.cs b/WebService/Startup.cs
@@ -10,6 +10,7 @@
 using Microsoft.AspNetCore.Hosting;
 using Microsoft.Azure.IoTSolutions.DeviceSimulation.PartitioningAgent;
 using Microsoft.Azure.IoTSolutions.DeviceSimulation.Services;
+using Microsoft.Azure.IoTSolutions.DeviceSimulation.Services.Diagnostics;
 using Microsoft.Azure.IoTSolutions.DeviceSimulation.SimulationAgent;
 using Microsoft.Azure.IoTSolutions.DeviceSimulation.WebService.Auth;
 using Microsoft.Azure.IoTSolutions.DeviceSimulation.WebService.Runtime;
@@ -158,6 +159,8 @@ private void StopAgents()
 
         private Task MonitorThreadsAsync(IApplicationLifetime appLifetime)
         {
+            const string MSG = "Part of the service is not running";
+
             return Task.Run(() =>
                 {
                     while (!this.appStopToken.IsCancellationRequested)
@@ -173,12 +176,18 @@ private Task MonitorThreadsAsync(IApplicationLifetime appLifetime)
                             || this.partitioningAgentTask.Status == TaskStatus.RanToCompletion)
                         {
                             var log = this.ApplicationContainer.Resolve<ILogger>();
-                            log.Error("Part of the service is not running",
-                                () => new
-                                {
-                                    SimulationAgent = this.simulationAgentTask.Status.ToString(),
-                                    PartitioningAgent = this.partitioningAgentTask.Status.ToString()
-                                });
+                            var diagnosticsLogger = this.ApplicationContainer.Resolve<IDiagnosticsLogger>();
+
+                            var errorData = new
+                            {
+                                SimulationAgent = this.simulationAgentTask.Status.ToString(),
+                                PartitioningAgent = this.partitioningAgentTask.Status.ToString()
+                            };
+
+                            log.Error(MSG, () => errorData);
+
+                            // Send diagnostics information
+                            diagnosticsLogger.LogServiceError(MSG, errorData);
 
                             // Allow few seconds to flush logs
                             Thread.Sleep(5000);

Original file line number	Diff line number	Diff line change
`@@ -2,7 +2,6 @@`
`2`	`2`
`3`	`3`	`using System;`
`4`	`4`	`using System.Collections.Generic;`
`5`		`-using System.Linq;`
`6`	`5`	`using System.Net;`
`7`	`6`	`using System.Threading.Tasks;`
`8`	`7`	`using Microsoft.Azure.Documents;`
`@@ -19,6 +18,7 @@ public class Engine : IEngine, IDisposable`
`19`	`18`	`private readonly ILogger log;`
`20`	`19`	`private readonly IInstance instance;`
`21`	`20`	`private readonly IFactory factory;`
	`21`	`+ private readonly IDiagnosticsLogger diagnosticsLogger;`
`22`	`22`
`23`	`23`	`private Config storageConfig;`
`24`	`24`
`@@ -34,10 +34,12 @@ public class Engine : IEngine, IDisposable`
`34`	`34`	`public Engine(`
`35`	`35`	`IFactory factory,`
`36`	`36`	`ILogger logger,`
	`37`	`+ IDiagnosticsLogger diagnosticsLogger,`
`37`	`38`	`IInstance instance)`
`38`	`39`	`{`
`39`	`40`	`this.log = logger;`
`40`	`41`	`this.instance = instance;`
	`42`	`+ this.diagnosticsLogger = diagnosticsLogger;`
`41`	`43`	`this.factory = factory;`
`42`	`44`
`43`	`45`	`this.disposedValue = false;`
`@@ -118,7 +120,11 @@ public async Task<IEnumerable<IDataRecord>> GetAllAsync()`
`118`	`120`	`}`
`119`	`121`	`catch (Exception e)`
`120`	`122`	`{`
`121`		`- this.log.Error("Unexpected error while reading from Cosmos DB SQL", () => new { this.storageName, e });`
	`123`	`+ const string MSG = "Unexpected error while reading from Cosmos DB SQL";`
	`124`	`+ var errorData = new { this.storageName, e };`
	`125`	`+`
	`126`	`+ this.log.Error(MSG, () => errorData);`
	`127`	`+ this.diagnosticsLogger.LogServiceError(MSG, errorData);`
`122`	`128`	`throw new ExternalDependencyException(e);`
`123`	`129`	`}`
`124`	`130`	`}`
`@@ -146,8 +152,11 @@ public async Task<IDataRecord> CreateAsync(IDataRecord input)`
`146`	`152`	`}`
`147`	`153`	`catch (Exception e)`
`148`	`154`	`{`
`149`		`- this.log.Error("Unexpected error while writing to Cosmos DB SQL",`
`150`		`- () => new { this.storageName, Id = input.GetId(), e });`
	`155`	`+ const string MSG = "Unexpected error while writing to Cosmos DB SQL";`
	`156`	`+ var errorData = new { this.storageName, Id = input.GetId(), e };`
	`157`	`+`
	`158`	`+ this.log.Error(MSG, () => errorData);`
	`159`	`+ this.diagnosticsLogger.LogServiceError(MSG, errorData);`
`151`	`160`	`throw new ExternalDependencyException(e);`
`152`	`161`	`}`
`153`	`162`	`}`
`@@ -182,8 +191,11 @@ public async Task<IDataRecord> UpsertAsync(IDataRecord input, string eTag)`
`182`	`191`	`}`
`183`	`192`	`catch (Exception e)`
`184`	`193`	`{`
`185`		`- this.log.Error("Unexpected error while writing to Cosmos DB SQL",`
`186`		`- () => new { this.storageName, Id = input.GetId(), eTag, e });`
	`194`	`+ const string MSG = "Unexpected error while writing to Cosmos DB SQL";`
	`195`	`+ var errorData = new { this.storageName, Id = input.GetId(), eTag, e };`
	`196`	`+`
	`197`	`+ this.log.Error(MSG, () => errorData);`
	`198`	`+ this.diagnosticsLogger.LogServiceError(MSG, errorData);`
`187`	`199`	`throw new ExternalDependencyException(e);`
`188`	`200`	`}`
`189`	`201`	`}`
`@@ -207,8 +219,11 @@ public async Task DeleteAsync(string id)`
`207`	`219`	`}`
`208`	`220`	`catch (Exception e)`
`209`	`221`	`{`
`210`		`- this.log.Error("Unexpected error while writing to Cosmos DB SQL",`
`211`		`- () => new { this.storageName, id, e });`
	`222`	`+ const string MSG = "Unexpected error while writing to Cosmos DB SQL";`
	`223`	`+ var errorData = new { this.storageName, id, e };`
	`224`	`+`
	`225`	`+ this.log.Error(MSG, () => errorData);`
	`226`	`+ this.diagnosticsLogger.LogServiceError(MSG, errorData);`
`212`	`227`	`throw new ExternalDependencyException(e);`
`213`	`228`	`}`
`214`	`229`	`}`
`@@ -274,8 +289,11 @@ public async Task<bool> TryToLockAsync(`
`274`	`289`	`}`
`275`	`290`	`catch (Exception e)`
`276`	`291`	`{`
`277`		`- this.log.Error("Unexpected error while writing to Cosmos DB SQL",`
`278`		`- () => new { this.storageName, id, ownerId, ownerType, lockDurationSecs = durationSeconds, e });`
	`292`	`+ const string MSG = "Unexpected error while writing to Cosmos DB SQL";`
	`293`	`+ var errorData = new { this.storageName, id, ownerId, ownerType, lockDurationSecs = durationSeconds, e };`
	`294`	`+`
	`295`	`+ this.log.Error(MSG, () => errorData);`
	`296`	`+ this.diagnosticsLogger.LogServiceError(MSG, errorData);`
`279`	`297`	`}`
`280`	`298`
`281`	`299`	`return false;`
`@@ -321,8 +339,11 @@ public async Task<bool> TryToUnlockAsync(string id, string ownerId, string owner`
`321`	`339`	`}`
`322`	`340`	`catch (Exception e)`
`323`	`341`	`{`
`324`		`- this.log.Error("Unexpected error while writing to Cosmos DB SQL",`
`325`		`- () => new { this.storageName, id, ownerId, ownerType, e });`
	`342`	`+ const string MSG = "Unexpected error while writing to Cosmos DB SQL";`
	`343`	`+ var errorData = new { this.storageName, id, ownerId, ownerType, e };`
	`344`	`+`
	`345`	`+ this.log.Error(MSG, () => errorData);`
	`346`	`+ this.diagnosticsLogger.LogServiceError(MSG, errorData);`
`326`	`347`	`}`
`327`	`348`
`328`	`349`	`return false;`
`@@ -397,8 +418,11 @@ private async Task SetupStorageAsync()`
`397`	`418`	`}`
`398`	`419`	`catch (Exception e)`
`399`	`420`	`{`
`400`		`- this.log.Error("Unexpected error while reading from Cosmos DB SQL",`
`401`		`- () => new { this.storageName, id, e });`
	`421`	`+ const string MSG = "Unexpected error while reading from Cosmos DB SQL";`
	`422`	`+ var errorData = new { this.storageName, id, e};`
	`423`	`+`
	`424`	`+ this.log.Error(MSG, () => errorData);`
	`425`	`+ this.diagnosticsLogger.LogServiceError(MSG, errorData);`
`402`	`426`	`throw new ExternalDependencyException(e);`
`403`	`427`	`}`
`404`	`428`	`}`
`@@ -436,7 +460,11 @@ private async Task TryToDeleteExpiredRecord(string id)`
`436`	`460`	`catch (Exception e)`
`437`	`461`	`{`
`438`	`462`	`// Log and do not throw, we're just trying to delete and will retry automatically later`
`439`		`- this.log.Warn("Unexpected error while writing to Cosmos DB SQL", () => new { this.storageName, id, e });`
	`463`	`+ const string MSG = "Unexpected error while writing to Cosmos DB SQL";`
	`464`	`+ var errorData = new { this.storageName, id, e };`
	`465`	`+`
	`466`	`+ this.log.Error(MSG, () => errorData);`
	`467`	`+ this.diagnosticsLogger.LogServiceError(MSG, errorData);`
`440`	`468`	`}`
`441`	`469`	`}`
`442`	`470`	`}`