[PM-26401] Add logging logic (#6523)

src/Api/AdminConsole/Controllers/EventsController.cs

@@ -3,6 +3,7 @@
 
 using Bit.Api.Models.Response;
 using Bit.Api.Utilities;
+using Bit.Api.Utilities.DiagnosticTools;
 using Bit.Core.AdminConsole.Repositories;
 using Bit.Core.Context;
 using Bit.Core.Enums;
@@ -31,10 +32,11 @@ public class EventsController : Controller
     private readonly ISecretRepository _secretRepository;
     private readonly IProjectRepository _projectRepository;
     private readonly IServiceAccountRepository _serviceAccountRepository;
+    private readonly ILogger<EventsController> _logger;
+    private readonly IFeatureService _featureService;
 
 
-    public EventsController(
+    public EventsController(IUserService userService,
-        IUserService userService,
         ICipherRepository cipherRepository,
         IOrganizationUserRepository organizationUserRepository,
         IProviderUserRepository providerUserRepository,
@@ -42,7 +44,9 @@ public class EventsController : Controller
         ICurrentContext currentContext,
         ISecretRepository secretRepository,
         IProjectRepository projectRepository,
-        IServiceAccountRepository serviceAccountRepository)
+        IServiceAccountRepository serviceAccountRepository,
+        ILogger<EventsController> logger,
+        IFeatureService featureService)
     {
         _userService = userService;
         _cipherRepository = cipherRepository;
@@ -53,6 +57,8 @@ public class EventsController : Controller
         _secretRepository = secretRepository;
         _projectRepository = projectRepository;
         _serviceAccountRepository = serviceAccountRepository;
+        _logger = logger;
+        _featureService = featureService;
     }
 
     [HttpGet("")]
@@ -114,6 +120,9 @@ public class EventsController : Controller
         var result = await _eventRepository.GetManyByOrganizationAsync(orgId, dateRange.Item1, dateRange.Item2,
             new PageOptions { ContinuationToken = continuationToken });
         var responses = result.Data.Select(e => new EventResponseModel(e));
+
+        _logger.LogAggregateData(_featureService, orgId, responses, continuationToken, start, end);
+
         return new ListResponseModel<EventResponseModel>(responses, result.ContinuationToken);
     }
 

src/Api/AdminConsole/Public/Controllers/EventsController.cs

@@ -4,9 +4,11 @@
 using System.Net;
 using Bit.Api.Models.Public.Request;
 using Bit.Api.Models.Public.Response;
+using Bit.Api.Utilities.DiagnosticTools;
 using Bit.Core.Context;
 using Bit.Core.Models.Data;
 using Bit.Core.Repositories;
+using Bit.Core.Services;
 using Bit.Core.Vault.Repositories;
 using Microsoft.AspNetCore.Authorization;
 using Microsoft.AspNetCore.Mvc;
@@ -20,15 +22,21 @@ public class EventsController : Controller
     private readonly IEventRepository _eventRepository;
     private readonly ICipherRepository _cipherRepository;
     private readonly ICurrentContext _currentContext;
+    private readonly ILogger<EventsController> _logger;
+    private readonly IFeatureService _featureService;
 
     public EventsController(
         IEventRepository eventRepository,
         ICipherRepository cipherRepository,
-        ICurrentContext currentContext)
+        ICurrentContext currentContext,
+        ILogger<EventsController> logger,
+        IFeatureService featureService)
     {
         _eventRepository = eventRepository;
         _cipherRepository = cipherRepository;
         _currentContext = currentContext;
+        _logger = logger;
+        _featureService = featureService;
     }
 
     /// <summary>
@@ -69,6 +77,8 @@ public class EventsController : Controller
 
         var eventResponses = result.Data.Select(e => new EventResponseModel(e));
         var response = new PagedListResponseModel<EventResponseModel>(eventResponses, result.ContinuationToken);
+
+        _logger.LogAggregateData(_featureService, _currentContext.OrganizationId!.Value, response, request);
         return new JsonResult(response);
     }
 }

src/Api/Utilities/DiagnosticTools/EventDiagnosticLogger.cs

@@ -0,0 +1,87 @@
+using Bit.Api.Models.Public.Request;
+using Bit.Api.Models.Public.Response;
+using Bit.Core;
+using Bit.Core.Services;
+
+namespace Bit.Api.Utilities.DiagnosticTools;
+
+public static class EventDiagnosticLogger
+{
+    public static void LogAggregateData(
+        this ILogger logger,
+        IFeatureService featureService,
+        Guid organizationId,
+        PagedListResponseModel<EventResponseModel> data, EventFilterRequestModel request)
+    {
+        try
+        {
+            if (!featureService.IsEnabled(FeatureFlagKeys.EventDiagnosticLogging))
+            {
+                return;
+            }
+
+            var orderedRecords = data.Data.OrderBy(e => e.Date).ToList();
+            var recordCount = orderedRecords.Count;
+            var newestRecordDate = orderedRecords.LastOrDefault()?.Date.ToString("o");
+            var oldestRecordDate = orderedRecords.FirstOrDefault()?.Date.ToString("o"); ;
+            var hasMore = !string.IsNullOrEmpty(data.ContinuationToken);
+
+            logger.LogInformation(
+                "Events query for Organization:{OrgId}. Event count:{Count} newest record:{newestRecord}  oldest record:{oldestRecord} HasMore:{HasMore} " +
+                "Request Filters Start:{QueryStart} End:{QueryEnd} ActingUserId:{ActingUserId} ItemId:{ItemId},",
+                organizationId,
+                recordCount,
+                newestRecordDate,
+                oldestRecordDate,
+                hasMore,
+                request.Start?.ToString("o"),
+                request.End?.ToString("o"),
+                request.ActingUserId,
+                request.ItemId);
+        }
+        catch (Exception exception)
+        {
+            logger.LogWarning(exception, "Unexpected exception from EventDiagnosticLogger.LogAggregateData");
+        }
+    }
+
+    public static void LogAggregateData(
+        this ILogger logger,
+        IFeatureService featureService,
+        Guid organizationId,
+        IEnumerable<Bit.Api.Models.Response.EventResponseModel> data,
+        string? continuationToken,
+        DateTime? queryStart = null,
+        DateTime? queryEnd = null)
+    {
+
+        try
+        {
+            if (!featureService.IsEnabled(FeatureFlagKeys.EventDiagnosticLogging))
+            {
+                return;
+            }
+
+            var orderedRecords = data.OrderBy(e => e.Date).ToList();
+            var recordCount = orderedRecords.Count;
+            var newestRecordDate = orderedRecords.LastOrDefault()?.Date.ToString("o");
+            var oldestRecordDate = orderedRecords.FirstOrDefault()?.Date.ToString("o"); ;
+            var hasMore = !string.IsNullOrEmpty(continuationToken);
+
+            logger.LogInformation(
+                "Events query for Organization:{OrgId}. Event count:{Count} newest record:{newestRecord}  oldest record:{oldestRecord} HasMore:{HasMore} " +
+                "Request Filters Start:{QueryStart} End:{QueryEnd}",
+                organizationId,
+                recordCount,
+                newestRecordDate,
+                oldestRecordDate,
+                hasMore,
+                queryStart?.ToString("o"),
+                queryEnd?.ToString("o"));
+        }
+        catch (Exception exception)
+        {
+            logger.LogWarning(exception, "Unexpected exception from EventDiagnosticLogger.LogAggregateData");
+        }
+    }
+}

src/Core/Constants.cs

@@ -252,6 +252,7 @@ public static class FeatureFlagKeys
     /* DIRT Team */
     public const string PM22887_RiskInsightsActivityTab = "pm-22887-risk-insights-activity-tab";
     public const string EventManagementForDataDogAndCrowdStrike = "event-management-for-datadog-and-crowdstrike";
+    public const string EventDiagnosticLogging = "pm-27666-siem-event-log-debugging";
 
     public static List<string> GetAllKeys()
     {

test/Api.Test/Utilities/DiagnosticTools/EventDiagnosticLoggerTests.cs

@@ -0,0 +1,221 @@
+using Bit.Api.Models.Public.Request;
+using Bit.Api.Models.Public.Response;
+using Bit.Api.Utilities.DiagnosticTools;
+using Bit.Core;
+using Bit.Core.Models.Data;
+using Bit.Core.Services;
+using Bit.Test.Common.AutoFixture.Attributes;
+using Microsoft.Extensions.Logging;
+using NSubstitute;
+using Xunit;
+
+namespace Bit.Api.Test.Utilities.DiagnosticTools;
+
+public class EventDiagnosticLoggerTests
+{
+    [Theory, BitAutoData]
+    public void LogAggregateData_WithPublicResponse_FeatureFlagEnabled_LogsInformation(
+        Guid organizationId)
+    {
+        // Arrange
+        var logger = Substitute.For<ILogger>();
+        var featureService = Substitute.For<IFeatureService>();
+        featureService.IsEnabled(FeatureFlagKeys.EventDiagnosticLogging).Returns(true);
+
+        var request = new EventFilterRequestModel()
+        {
+            Start = DateTime.UtcNow.AddMinutes(-3),
+            End = DateTime.UtcNow,
+            ActingUserId = Guid.NewGuid(),
+            ItemId = Guid.NewGuid(),
+        };
+
+        var newestEvent = Substitute.For<IEvent>();
+        newestEvent.Date.Returns(DateTime.UtcNow);
+        var middleEvent = Substitute.For<IEvent>();
+        middleEvent.Date.Returns(DateTime.UtcNow.AddDays(-1));
+        var oldestEvent = Substitute.For<IEvent>();
+        oldestEvent.Date.Returns(DateTime.UtcNow.AddDays(-3));
+
+        var eventResponses = new List<EventResponseModel>
+        {
+            new (newestEvent),
+            new (middleEvent),
+            new (oldestEvent)
+        };
+        var response = new PagedListResponseModel<EventResponseModel>(eventResponses, "continuation-token");
+
+        // Act
+        logger.LogAggregateData(featureService, organizationId, response, request);
+
+        // Assert
+        logger.Received(1).Log(
+            LogLevel.Information,
+            Arg.Any<EventId>(),
+            Arg.Is<object>(o =>
+                o.ToString().Contains(organizationId.ToString()) &&
+                o.ToString().Contains($"Event count:{eventResponses.Count}") &&
+                o.ToString().Contains($"newest record:{newestEvent.Date:O}") &&
+                o.ToString().Contains($"oldest record:{oldestEvent.Date:O}") &&
+                o.ToString().Contains("HasMore:True") &&
+                o.ToString().Contains($"Start:{request.Start:o}") &&
+                o.ToString().Contains($"End:{request.End:o}") &&
+                o.ToString().Contains($"ActingUserId:{request.ActingUserId}") &&
+                o.ToString().Contains($"ItemId:{request.ItemId}"))
+            ,
+            null,
+            Arg.Any<Func<object, Exception, string>>());
+    }
+
+    [Theory, BitAutoData]
+    public void LogAggregateData_WithPublicResponse_FeatureFlagDisabled_DoesNotLog(
+        Guid organizationId,
+        EventFilterRequestModel request)
+    {
+        // Arrange
+        var logger = Substitute.For<ILogger>();
+        var featureService = Substitute.For<IFeatureService>();
+        featureService.IsEnabled(FeatureFlagKeys.EventDiagnosticLogging).Returns(false);
+
+        PagedListResponseModel<EventResponseModel> dummy = null;
+
+        // Act
+        logger.LogAggregateData(featureService, organizationId, dummy, request);
+
+        // Assert
+        logger.DidNotReceive().Log(
+            LogLevel.Information,
+            Arg.Any<EventId>(),
+            Arg.Any<object>(),
+            Arg.Any<Exception>(),
+            Arg.Any<Func<object, Exception, string>>());
+    }
+
+    [Theory, BitAutoData]
+    public void LogAggregateData_WithPublicResponse_EmptyData_LogsZeroCount(
+        Guid organizationId)
+    {
+        // Arrange
+        var logger = Substitute.For<ILogger>();
+        var featureService = Substitute.For<IFeatureService>();
+        featureService.IsEnabled(FeatureFlagKeys.EventDiagnosticLogging).Returns(true);
+
+        var request = new EventFilterRequestModel()
+        {
+            Start = null,
+            End = null,
+            ActingUserId = null,
+            ItemId = null,
+            ContinuationToken = null,
+        };
+        var response = new PagedListResponseModel<EventResponseModel>(new List<EventResponseModel>(), null);
+
+        // Act
+        logger.LogAggregateData(featureService, organizationId, response, request);
+
+        // Assert
+        logger.Received(1).Log(
+            LogLevel.Information,
+            Arg.Any<EventId>(),
+            Arg.Is<object>(o =>
+                o.ToString().Contains(organizationId.ToString()) &&
+                o.ToString().Contains("Event count:0") &&
+                o.ToString().Contains("HasMore:False")),
+            null,
+            Arg.Any<Func<object, Exception, string>>());
+    }
+
+    [Theory, BitAutoData]
+    public void LogAggregateData_WithInternalResponse_FeatureFlagDisabled_DoesNotLog(Guid organizationId)
+    {
+        // Arrange
+        var logger = Substitute.For<ILogger>();
+        var featureService = Substitute.For<IFeatureService>();
+        featureService.IsEnabled(FeatureFlagKeys.EventDiagnosticLogging).Returns(false);
+
+
+        // Act
+        logger.LogAggregateData(featureService, organizationId, null, null, null, null);
+
+        // Assert
+        logger.DidNotReceive().Log(
+            LogLevel.Information,
+            Arg.Any<EventId>(),
+            Arg.Any<object>(),
+            Arg.Any<Exception>(),
+            Arg.Any<Func<object, Exception, string>>());
+    }
+
+    [Theory, BitAutoData]
+    public void LogAggregateData_WithInternalResponse_EmptyData_LogsZeroCount(
+        Guid organizationId)
+    {
+        // Arrange
+        var logger = Substitute.For<ILogger>();
+        var featureService = Substitute.For<IFeatureService>();
+        featureService.IsEnabled(FeatureFlagKeys.EventDiagnosticLogging).Returns(true);
+
+        Bit.Api.Models.Response.EventResponseModel[] emptyEvents = [];
+
+        // Act
+        logger.LogAggregateData(featureService, organizationId, emptyEvents, null, null, null);
+
+        // Assert
+        logger.Received(1).Log(
+            LogLevel.Information,
+            Arg.Any<EventId>(),
+            Arg.Is<object>(o =>
+                o.ToString().Contains(organizationId.ToString()) &&
+                o.ToString().Contains("Event count:0") &&
+                o.ToString().Contains("HasMore:False")),
+            null,
+            Arg.Any<Func<object, Exception, string>>());
+    }
+
+    [Theory, BitAutoData]
+    public void LogAggregateData_WithInternalResponse_FeatureFlagEnabled_LogsInformation(
+        Guid organizationId)
+    {
+        // Arrange
+        var logger = Substitute.For<ILogger>();
+        var featureService = Substitute.For<IFeatureService>();
+        featureService.IsEnabled(FeatureFlagKeys.EventDiagnosticLogging).Returns(true);
+
+        var newestEvent = Substitute.For<IEvent>();
+        newestEvent.Date.Returns(DateTime.UtcNow);
+        var middleEvent = Substitute.For<IEvent>();
+        middleEvent.Date.Returns(DateTime.UtcNow.AddDays(-1));
+        var oldestEvent = Substitute.For<IEvent>();
+        oldestEvent.Date.Returns(DateTime.UtcNow.AddDays(-2));
+
+        var events = new List<Bit.Api.Models.Response.EventResponseModel>
+        {
+            new (newestEvent),
+            new (middleEvent),
+            new (oldestEvent)
+        };
+
+        var queryStart = DateTime.UtcNow.AddMinutes(-3);
+        var queryEnd = DateTime.UtcNow;
+        const string continuationToken = "continuation-token";
+
+        // Act
+        logger.LogAggregateData(featureService, organizationId, events, continuationToken, queryStart, queryEnd);
+
+        // Assert
+        logger.Received(1).Log(
+            LogLevel.Information,
+            Arg.Any<EventId>(),
+            Arg.Is<object>(o =>
+                o.ToString().Contains(organizationId.ToString()) &&
+                o.ToString().Contains($"Event count:{events.Count}") &&
+                o.ToString().Contains($"newest record:{newestEvent.Date:O}") &&
+                o.ToString().Contains($"oldest record:{oldestEvent.Date:O}") &&
+                o.ToString().Contains("HasMore:True") &&
+                o.ToString().Contains($"Start:{queryStart:o}") &&
+                o.ToString().Contains($"End:{queryEnd:o}"))
+            ,
+            null,
+            Arg.Any<Func<object, Exception, string>>());
+    }
+}