Logging in Belgrade ProductCatalog demo

Added logging in Belgrade ProductCatalog using Serilog library.

samples/demos/BelgradeProductCatalogDemo/Controllers/ProductController.cs

@@ -1,5 +1,6 @@
 using Belgrade.SqlClient;
 using Microsoft.AspNetCore.Mvc;
+using Microsoft.Extensions.Logging;
 using System;
 using System.Data.SqlClient;
 using System.IO;
@@ -17,17 +18,25 @@ namespace ProductCatalog.Controllers
         ICommand sqlCmd = null;
         private readonly string EMPTY_PRODUCTS_ARRAY = "{\"data\":[]}";
         private readonly byte[] EMPTY_PRODUCTS_ARRAY_GZIPPED = new byte[] {0x1F,0x8B,0x08,0x00,0x00,0x00,0x00,0x00,0x04,0x00,0xAB,0x66,0x50,0x62,0x48,0x61,0x48,0x64,0x28,0x01,0x62,0x25,0x06,0x2B,0x86,0x68,0x86,0x58,0x86,0x5A,0x06,0x00,0xB3,0x4C,0x62,0xB2,0x16,0x00,0x00,0x00};
+        private readonly ILogger logger;
 
-        public ProductController(IQueryPipe sqlQueryService, ICommand sqlCommandService)
+        public ProductController(IQueryPipe sqlQueryService, ICommand sqlCommandService, ILogger<ProductController> logger)
         {
             this.sqlQuery = sqlQueryService;
             this.sqlCmd = sqlCommandService;
+            this.logger = logger;
         }
 
         // GET api/Product
         public async Task Get()
         {
-            await sqlQuery.Stream(@"
+            await sqlQuery
+                .OnError(
+                    ex => { logger.LogError("Error while trying to get products: {Error}\n{StackTrace}", ex.Message, ex.StackTrace);
+                        this.Response.StatusCode = 500;
+                        throw ex;
+                })
+                .Stream(@"
             select  ProductID, Name, Color, Price, Quantity,
                     JSON_VALUE(Data, '$.MadeIn') as MadeIn, JSON_QUERY(Tags) as Tags
             from Product
@@ -116,7 +125,14 @@ FOR JSON PATH, WITHOUT_ARRAY_WRAPPER");
             var cmd = new SqlCommand("EXEC RestoreProduct @productid, @date");
             cmd.Parameters.AddWithValue("@productid", ProductId);
             cmd.Parameters.AddWithValue("@date", DateModified);
-            this.sqlCmd.ExecuteNonQuery(cmd);
+            this.sqlCmd
+                .OnError(
+                    ex => {
+                        logger.LogError("Error while trying to restore product with id {ProductID} from time {DateModified}.\n{Error}\n{StackTrace}", ProductId, DateModified, ex.Message, ex.StackTrace);
+                        this.Response.StatusCode = 500;
+                        throw ex;
+                    })
+                .ExecuteNonQuery(cmd);
         }
     }
 }

samples/demos/BelgradeProductCatalogDemo/Startup.cs

@@ -1,5 +1,4 @@
-using Belgrade.SqlClient;
-using Belgrade.SqlClient.SqlDb;
+using Belgrade.SqlClient.SqlDb;
 using Belgrade.SqlClient.SqlDb.Rls;
 using Microsoft.AspNetCore.Builder;
 using Microsoft.AspNetCore.Hosting;
@@ -7,6 +6,10 @@ using Microsoft.AspNetCore.Http;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Logging;
+using Serilog;
+#if NET46 
+using Serilog.Sinks.MSSqlServer;
+#endif
 using System;
 using System.Data.SqlClient;
 using System.Linq;
@@ -23,6 +26,24 @@ namespace ProductCatalog
                 .AddJsonFile($"appsettings.{env.EnvironmentName}.json", optional: true)
                 .AddEnvironmentVariables();
             Configuration = builder.Build();
+#if NETCOREAPP1_0
+            Log.Logger = new LoggerConfiguration()
+                .WriteTo.RollingFile(new Serilog.Formatting.Json.JsonFormatter(), System.IO.Path.Combine(env.ContentRootPath, "log-{Date}.ndjson"))
+                .CreateLogger();
+#endif
+#if NET46
+            var columnOptions = new ColumnOptions();
+            // Don't include the Properties XML column.
+            columnOptions.Store.Remove(StandardColumn.Properties);
+            columnOptions.Store.Remove(StandardColumn.MessageTemplate);
+            columnOptions.Store.Remove(StandardColumn.Exception);
+            // Do include the log event data as JSON.
+            columnOptions.Store.Add(StandardColumn.LogEvent);
+
+            Log.Logger = new LoggerConfiguration()
+                .WriteTo.MSSqlServer(Configuration["ConnectionStrings:BelgradeDemo"], "dbo.Logs", columnOptions: columnOptions)
+                .CreateLogger();
+#endif
         }
 
         public IConfigurationRoot Configuration { get; }
@@ -34,26 +55,19 @@ namespace ProductCatalog
             string ConnString = Configuration["ConnectionStrings:BelgradeDemo"];
             
             // Adding data access services/components.
-            services.AddTransient<IQueryPipe>(
-                sp =>
-                {
-                    return new QueryPipeSessionContextAdapter(
-                        new QueryPipe(new SqlConnection(ConnString)),
-                        "CompanyID",
-                        () => GetCompanyIdFromSession(sp));
-                });
+            services.AddTransient(
+                sp => new QueryPipe(new SqlConnection(ConnString))
+                            .AddRls("CompanyID",() => GetCompanyIdFromSession(sp))
+                );
 
-            services.AddTransient<ICommand>(
-                sp =>
-                {
-                    return new CommandSessionContextAdapter(
-                        new Command(new SqlConnection(ConnString)),
-                        "CompanyID",
-                        () => GetCompanyIdFromSession(sp));
-                });
+            services.AddTransient(
+                sp => new Command(new SqlConnection(ConnString))
+                            .AddRls("CompanyID", () => GetCompanyIdFromSession(sp))
+                );
 
             // Add framework services.
             services.AddSingleton<IHttpContextAccessor, HttpContextAccessor>();
+            services.AddLogging();
             services.AddSession();
             services.AddMvc();
         }
@@ -63,6 +77,7 @@ namespace ProductCatalog
         {
             loggerFactory.AddConsole(Configuration.GetSection("Logging"));
             loggerFactory.AddDebug();
+            loggerFactory.AddSerilog();
 
             app.UseSession();
             app.UseMvc();

samples/demos/BelgradeProductCatalogDemo/project.json

@@ -1,6 +1,6 @@
 {
   "dependencies": {
-    "Belgrade.Sql.Client": "0.6.0",
+    "Belgrade.Sql.Client": "0.6.2",
     "Microsoft.AspNetCore.Mvc": "1.0.0",
     "Microsoft.AspNetCore.Server.IISIntegration": "1.0.0",
     "Microsoft.AspNetCore.Server.Kestrel": "1.0.0",
@@ -12,6 +12,10 @@
     "Microsoft.Extensions.Logging": "1.0.0",
     "Microsoft.Extensions.Logging.Console": "1.0.0",
     "Microsoft.Extensions.Logging.Debug": "1.0.0",
+    "Serilog": "2.3.0",
+    "Serilog.Extensions.Logging": "1.3.1",
+    "Serilog.Sinks.PeriodicBatching": "2.1.0",
+    "Serilog.Sinks.RollingFile": "3.3.0",
     "System.Data.SqlClient": "4.1.0"
   },
 
@@ -33,6 +37,7 @@
     },
     "net46": {
       "dependencies": {
+        "Serilog.Sinks.MSSqlServer": "4.2.0"
       }
     }
   },

samples/demos/BelgradeProductCatalogDemo/sql-scripts/1 setup.sql

@@ -112,3 +112,14 @@ AS BEGIN
 
 END
 GO
+
+CREATE TABLE Logs (
+   Id int IDENTITY PRIMARY KEY,
+   Message nvarchar(max) NULL,
+   MessageTemplate nvarchar(max) NULL,
+   Level nvarchar(128) NULL,
+   TimeStamp datetimeoffset(7) NOT NULL,
+   Exception nvarchar(max) NULL,
+   Properties xml NULL,
+   LogEvent nvarchar(max) NULL
+);

samples/demos/BelgradeProductCatalogDemo/sql-scripts/A4 structured log analysis.sql

@@ -0,0 +1,7 @@
+SELECT
+		JSON_VALUE(LogEvent, '$.Properties.RequestPath') as Url,
+		AVG( CAST(JSON_VALUE(LogEvent, '$.Properties.ElapsedMilliseconds') as float) ) as milliseconds
+FROM Logs
+WHERE JSON_VALUE(LogEvent, '$.Properties.RequestPath') IS NOT NULL
+AND Timestamp BETWEEN '2017-01-09' AND '2017-01-10'
+GROUP BY JSON_VALUE(LogEvent, '$.Properties.RequestPath')