Consolidate Logging

src/GeoCop.Api/Authorization/GeocopUserHandler.cs

@@ -8,14 +8,17 @@ namespace GeoCop.Api.Authorization;
 public class GeocopUserHandler : AuthorizationHandler<GeocopUserRequirement>
 {
     private readonly Context dbContext;
+    private readonly Logger<GeocopUserHandler> logger;
 
     /// <summary>
     /// Initializes a new instance of the <see cref="GeocopUserHandler"/> class.
     /// </summary>
     /// <param name="dbContext">The database context.</param>
-    public GeocopUserHandler(Context dbContext)
+    /// <param name="logger">The logger used for authorization related logging.</param>
+    public GeocopUserHandler(Logger<GeocopUserHandler> logger, Context dbContext)
     {
         this.dbContext = dbContext;
+        this.logger = logger;
     }
 
     /// <inheritdoc/>
@@ -29,12 +32,17 @@ protected override async Task HandleRequirementAsync(AuthorizationHandlerContext
         var dbUser = await dbContext.GetUserByPrincipalAsync(context.User);
         if (dbUser == null)
         {
+            logger.LogWarning("There was a logging attempt for user with id <{UserId}> without corresponding user in database.",
+                context.User.Claims.FirstOrDefault(claim => claim.Type == "oid")?.Value.ReplaceLineEndings(string.Empty));
             return;
         }
 
-        if (!requirement.RequireAdmin || dbUser.IsAdmin)
+        if (requirement.RequireAdmin && !dbUser.IsAdmin)
         {
-            context.Succeed(requirement);
+            logger.LogWarning("User with id <{UserId}> did not fulfill admin requirement.", dbUser.AuthIdentifier);
+            return;
         }
+
+        context.Succeed(requirement);
     }
 }

src/GeoCop.Api/Controllers/DeliveryController.cs

@@ -47,18 +47,18 @@ public DeliveryController(ILogger<DeliveryController> logger, Context context, I
     [SwaggerResponse(StatusCodes.Status500InternalServerError, "The server encountered an unexpected condition that prevented it from fulfilling the request.", typeof(ProblemDetails), new[] { "application/json" })]
     public async Task<IActionResult> Create(DeliveryRequest declaration)
     {
-        logger.LogTrace("Declaration for job <{JobId}> requested.", declaration.JobId);
+        logger.LogInformation("Declaration for job with id <{JobId}> requested.", declaration.JobId);
 
         var jobStatus = validatorService.GetJobStatus(declaration.JobId);
         if (jobStatus == default)
         {
-            logger.LogTrace("No job information available for job id <{JobId}>.", declaration.JobId);
-            return NotFound($"No job information available for job id <{declaration.JobId}>");
+            logger.LogTrace("No job information available for job with id <{JobId}>.", declaration.JobId);
+            return NotFound($"No job information available for job with id <{declaration.JobId}>");
         }
         else if (jobStatus.Status != Status.Completed)
         {
-            logger.LogTrace("Job <{JobId}> is not completed.", declaration.JobId);
-            return BadRequest($"Job <{declaration.JobId}> is not completed.");
+            logger.LogTrace("Job with id <{JobId}> is not completed.", declaration.JobId);
+            return BadRequest($"Job with id <{declaration.JobId}> is not completed.");
         }
 
         var user = await context.GetUserByPrincipalAsync(User);
@@ -72,7 +72,7 @@ public async Task<IActionResult> Create(DeliveryRequest declaration)
 
         if (mandate is null || !mandate.Organisations.SelectMany(u => u.Users).Any(u => u.Id == user.Id))
         {
-            logger.LogTrace("User <{AuthIdentifier}> is not authorized to create a delivery for mandate <{MandateId}>.", user.AuthIdentifier, declaration.DeliveryMandateId);
+            logger.LogTrace("User <{AuthIdentifier}> is not authorized to create a delivery for mandate with id <{MandateId}>.", user.AuthIdentifier, declaration.DeliveryMandateId);
             return NotFound($"Mandate with id <{declaration.DeliveryMandateId}> not found or user is not authorized.");
         }
 
@@ -84,8 +84,8 @@ public async Task<IActionResult> Create(DeliveryRequest declaration)
 
         if (declaration.PrecursorDeliveryId.HasValue && precursorDelivery is null)
         {
-            logger.LogTrace("Precursor delivery with Id <{DeliveryId}> was not found or user <{AuthIdentifier}> is not authorized.", declaration.PrecursorDeliveryId.Value, user.AuthIdentifier);
-            return NotFound($"Precursor delivery with Id {declaration.PrecursorDeliveryId} not found or user is not authorized.");
+            logger.LogTrace("Precursor delivery with id <{DeliveryId}> was not found or user <{AuthIdentifier}> is not authorized.", declaration.PrecursorDeliveryId.Value, user.AuthIdentifier);
+            return NotFound($"Precursor delivery with id {declaration.PrecursorDeliveryId} not found or user is not authorized.");
         }
 
         var delivery = new Delivery
@@ -105,8 +105,8 @@ public async Task<IActionResult> Create(DeliveryRequest declaration)
         }
         catch (Exception e)
         {
-            logger.LogError(e, "Error while persisting assets for job <{JobId}>.", declaration.JobId);
-            return Problem($"Error while persisting assets for job <{declaration.JobId}>.");
+            logger.LogError(e, "Error while persisting assets for job whith id <{JobId}>.", declaration.JobId);
+            return Problem($"Error while persisting assets for job whith id <{declaration.JobId}>.");
         }
 
         var entityEntry = context.Deliveries.Add(delivery);
@@ -120,6 +120,7 @@ public async Task<IActionResult> Create(DeliveryRequest declaration)
             string.Format(CultureInfo.InvariantCulture, "/api/v1/delivery/{0}", entityEntry.Entity.Id),
             UriKind.Relative);
 
+        logger.LogInformation("Declaration for job whith id <{JobId}> created.", declaration.JobId);
         return Created(location, resultDelivery);
     }
 
@@ -138,6 +139,10 @@ public async Task<IActionResult> Get([FromQuery] int? mandateId = null)
         if (user == null)
             return Unauthorized();
 
+        logger.LogInformation("User <{UserId}> accessed list of deliveries filtered by mandateId <{MandateId}>",
+            user.AuthIdentifier,
+            mandateId?.ToString(CultureInfo.InvariantCulture).ReplaceLineEndings(string.Empty));
+
         var userMandatesIds = context.DeliveryMandates
             .Where(m => user.IsAdmin || m.Organisations.SelectMany(o => o.Users).Any(u => u.Id == user.Id))
             .Select(m => m.Id)
@@ -169,12 +174,13 @@ public async Task<IActionResult> Get([FromQuery] int? mandateId = null)
     [SwaggerResponse(StatusCodes.Status500InternalServerError, "The server encountered an unexpected condition that prevented it from fulfilling the request.", typeof(ProblemDetails), new[] { "application/json" })]
     public IActionResult Delete([FromRoute] int deliveryId)
     {
+        logger.LogInformation("Deleting of delivery with id <{DeliveryId}> started.", deliveryId);
         try
         {
             var delivery = context.Deliveries.Include(d => d.Assets).FirstOrDefault(d => d.Id == deliveryId);
             if (delivery == default)
             {
-                logger.LogTrace($"No delivery with id <{deliveryId}> found.");
+                logger.LogTrace("No delivery with id <{DeliveryId}> found.", deliveryId);
                 return NotFound($"No delivery with id <{deliveryId}> found.");
             }
 
@@ -184,13 +190,13 @@ public IActionResult Delete([FromRoute] int deliveryId)
 
             context.SaveChanges();
 
+            logger.LogInformation("Deleting of delivery with id <{DeliveryId}> successful.", deliveryId);
             return Ok();
         }
         catch (Exception e)
         {
-            var message = $"Error while deleting delivery <{deliveryId}>.";
-            logger.LogError(e, message);
-            return Problem(message);
+            logger.LogError(e, "Error while deleting delivery with id <{DeliveryId}>.", deliveryId);
+            return Problem($"Error while deleting delivery with id <{deliveryId}>.");
         }
     }
 
@@ -206,12 +212,13 @@ public IActionResult Delete([FromRoute] int deliveryId)
     [SwaggerResponse(StatusCodes.Status500InternalServerError, "The server encountered an unexpected condition that prevented it from fulfilling the request.", typeof(ProblemDetails), new[] { "application/json" })]
     public async Task<IActionResult> DownloadAsync([FromRoute] int assetId)
     {
+        logger.LogInformation("Downloading asset with id <{AssetId}> started.", assetId);
         try
         {
             var asset = context.Assets.Include(a => a.Delivery).FirstOrDefault(a => a.Id == assetId && !a.Deleted);
             if (asset == default)
             {
-                logger.LogTrace($"No delivery with id <{assetId}> found.");
+                logger.LogTrace("No delivery with id <{AssetId}> found.", assetId);
                 return NotFound($"No delivery with id <{assetId}> found.");
             }
 
@@ -220,9 +227,8 @@ public async Task<IActionResult> DownloadAsync([FromRoute] int assetId)
         }
         catch (Exception e)
         {
-            var message = $"Error while deleting delivery <{assetId}>.";
-            logger.LogError(e, message);
-            return Problem(message);
+            logger.LogError(e, "Error while accessing delivery asset with id <{AssetId}>.", assetId);
+            return Problem($"Error while accessing delivery asset with id <{assetId}>.");
         }
     }
 }

src/GeoCop.Api/Controllers/MandateController.cs

@@ -44,6 +44,8 @@
         [FromQuery, SwaggerParameter("Filter mandates matching validation job file extension.")]
         string jobId = "")
     {
+        logger.LogInformation("Getting mandates for job with id <{JobId}>.", jobId.ReplaceLineEndings(string.Empty));
+
         var user = await context.GetUserByPrincipalAsync(User);
         if (user == null)
             return Unauthorized();
@@ -55,14 +57,20 @@
         {
             var job = validationService.GetJob(guid);
             if (job is null)
+            {
+                logger.LogTrace("Validation job with id <{JobId}> was not found.", guid.ToString());
                 return Ok(Array.Empty<DeliveryMandate>());
+            }
 
+            logger.LogTrace("Filtering mandates for job with id <{JobId}>", guid.ToString());
             var extension = Path.GetExtension(job.OriginalFileName);
             mandates = mandates
                 .Where(m => m.FileTypes.Contains(".*") || m.FileTypes.Contains(extension));
         }
 
         var result = await mandates.ToListAsync();
+
+        logger.LogInformation("Getting mandates with for job with id <{JobId}> resulted in <{MatchingMandatesCount}> matching mandates.", guid.ToString(), result.Count);
         return Ok(mandates);
     }
 }

src/GeoCop.Api/Controllers/UserController.cs

@@ -14,16 +14,19 @@ namespace GeoCop.Api.Controllers;
 [Route("api/v{version:apiVersion}/[controller]")]
 public class UserController : ControllerBase
 {
+    private readonly ILogger<UserController> logger;
     private readonly Context context;
     private readonly BrowserAuthOptions authOptions;
 
     /// <summary>
     /// Initializes a new instance of the <see cref="UserController"/> class.
     /// </summary>
+    /// <param name="logger">The logger for the instance.</param>
     /// <param name="context">The database context.</param>
     /// <param name="authOptions">The browser auth options.</param>
-    public UserController(Context context, IOptions<BrowserAuthOptions> authOptions)
+    public UserController(ILogger<UserController> logger, Context context, IOptions<BrowserAuthOptions> authOptions)
     {
+        this.logger = logger;
         this.context = context;
         this.authOptions = authOptions.Value;
     }
@@ -36,7 +39,17 @@ public UserController(Context context, IOptions<BrowserAuthOptions> authOptions)
     [Authorize(Policy = GeocopPolicies.User)]
     public async Task<User?> GetAsync()
     {
-        return await context.GetUserByPrincipalAsync(User);
+        var user = await context.GetUserByPrincipalAsync(User);
+        if (user == null)
+        {
+            logger.LogWarning("Getting user information attempted without registered user with name <{UserName}>", User.Identity?.Name);
+        }
+        else
+        {
+            logger.LogTrace("User <{AuthIdenifier}> getting account information.", user.AuthIdentifier);
+        }
+
+        return user;
     }
 
     /// <summary>
@@ -47,6 +60,7 @@ public UserController(Context context, IOptions<BrowserAuthOptions> authOptions)
     [AllowAnonymous]
     public BrowserAuthOptions GetAuthOptions()
     {
+        logger.LogInformation("Getting auth options.");
         return authOptions;
     }
 }

src/GeoCop.Api/Controllers/ValidationController.cs

@@ -94,7 +94,12 @@
     [SuppressMessage("StyleCop.CSharp.DocumentationRules", "SA1629:DocumentationTextMustEndWithAPeriod", Justification = "Not applicable for code examples.")]
     public async Task<IActionResult> UploadAsync(ApiVersion version, IFormFile file)
     {
-        if (file == null) return Problem($"Form data <{nameof(file)}> cannot be empty.", statusCode: StatusCodes.Status400BadRequest);
+        logger.LogInformation("File upload started.");
+        if (file == null)
+        {
+            logger.LogTrace("Uploaded file was emtpy.");
+            return Problem($"Form data <{nameof(file)}> cannot be empty.", statusCode: StatusCodes.Status400BadRequest);
+        }
 
         var fileExtension = Path.GetExtension(file.FileName);
         if (!await validationService.IsFileExtensionSupportedAsync(fileExtension))
@@ -157,8 +162,10 @@
     [SwaggerResponse(StatusCodes.Status404NotFound, "The job or log file cannot be found.", typeof(ProblemDetails), new[] { "application/json" })]
     public IActionResult Download(Guid jobId, string file)
     {
-        logger.LogTrace("Download file <{File}> for job <{JobId}> requested.", file, jobId);
+        // Sanitize user provided file name.
+        file = Path.GetFileName(file.Trim().ReplaceLineEndings(string.Empty));
 
+        logger.LogInformation("Download file <{File}> for job <{JobId}> requested.", file.ReplaceLineEndings(string.Empty), jobId.ToString());
         fileProvider.Initialize(jobId);
 
         var validationJob = validationService.GetJob(jobId);

src/GeoCop.Api/appsettings.Development.json

@@ -6,7 +6,8 @@
   "Logging": {
     "LogLevel": {
       "Default": "Information",
-      "Microsoft.AspNetCore": "Warning"
+      "Microsoft.AspNetCore": "Warning",
+      "Microsoft.EntityFrameworkCore": "Information"
     }
   },
   "ReverseProxy": {

src/GeoCop.Api/appsettings.json

@@ -10,7 +10,8 @@
   "Logging": {
     "LogLevel": {
       "Default": "Information",
-      "Microsoft.AspNetCore": "Warning"
+      "Microsoft.AspNetCore": "Warning",
+      "Microsoft.EntityFrameworkCore": "Warning"
     }
   },
   "AllowedHosts": "*",

tests/GeoCop.Api.Test/Controllers/UserControllerTest.cs

@@ -1,7 +1,9 @@
-using GeoCop.Api.Contracts;
+using Castle.Core.Logging;
+using GeoCop.Api.Contracts;
 using GeoCop.Api.Models;
 using GeoCop.Api.Test;
 using Microsoft.AspNetCore.Http;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using Moq;
 using System.Security.Claims;
@@ -19,6 +21,7 @@ public class UserControllerTest
     [TestInitialize]
     public void Initialize()
     {
+        var loggerMock = new Mock<ILogger<UserController>>();
         context = AssemblyInitialize.DbFixture.GetTestContext();
         authOptionsMock = new Mock<IOptions<BrowserAuthOptions>>();
         browserAuthOptions = new BrowserAuthOptions
@@ -31,7 +34,7 @@ public void Initialize()
         };
         authOptionsMock.SetupGet(o => o.Value).Returns(browserAuthOptions);
 
-        userController = new UserController(context, authOptionsMock.Object);
+        userController = new UserController(loggerMock.Object, context, authOptionsMock.Object);
     }
 
     [TestCleanup]