Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Remove the IsDebugEnabled check from audit expiration #2775

Merged
merged 2 commits into from Feb 1, 2022
Merged

Remove the IsDebugEnabled check from audit expiration #2775

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
f22035e
Disable IsDebugEnabled check
WilliamBZA Jan 31, 2022
62ff0e5
Change to interpolation
WilliamBZA Feb 1, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
1 change: 0 additions & 1 deletion src/ServiceControl.Audit/Auditing/BodyStorage/BodyStorageFeature.cs
View file
Open in desktop
@@ -1,6 +1,5 @@
namespace ServiceControl.Audit.Auditing.BodyStorage
{
using System;
danielmarbach marked this conversation as resolved.
Show resolved Hide resolved
using System.Collections.Generic;
using System.Text;
using System.Threading.Tasks;
Expand Down
1 change: 0 additions & 1 deletion src/ServiceControl.Audit/Infrastructure/RavenDB/EmbeddedRavenDbHostedService.cs
View file
Open in desktop
Expand Up @@ -57,6 +57,5 @@ public Task StopAsync(CancellationToken cancellationToken)
}

static readonly ILog Logger = LogManager.GetLogger(typeof(EmbeddedRavenDbHostedService));

danielmarbach marked this conversation as resolved.
Show resolved Hide resolved
}
}
30 changes: 6 additions & 24 deletions src/ServiceControl.Audit/Infrastructure/RavenDB/Expiration/AuditMessageCleaner.cs
View file
Open in desktop
Expand Up @@ -86,27 +86,18 @@ public static void Clean(int deletionBatchSize, DocumentDatabase database, DateT

var deletedAuditDocuments = Chunker.ExecuteInChunks(items.Count, (itemsForBatch, db, s, e) =>
{
if (logger.IsDebugEnabled)
{
logger.Debug($"Batching deletion of {s}-{e} audit documents.");
}
logger.Debug($"Batching deletion of {s}-{e} audit documents.");

var results = db.Batch(itemsForBatch.GetRange(s, e - s + 1), CancellationToken.None);
if (logger.IsDebugEnabled)
{
logger.Debug($"Batching deletion of {s}-{e} audit documents completed.");
}
logger.Debug($"Batching deletion of {s}-{e} audit documents completed.");

return results.Count(x => x.Deleted == true);
}, items, database, cancellationToken);

var deletedAttachments = Chunker.ExecuteInChunks(attachments.Count, (att, db, s, e) =>
{
var deleted = 0;
if (logger.IsDebugEnabled)
{
logger.Debug($"Batching deletion of {s}-{e} attachment audit documents.");
}
logger.Debug($"Batching deletion of {s}-{e} attachment audit documents.");

db.TransactionalStorage.Batch(accessor =>
{
Expand All @@ -119,27 +110,18 @@ public static void Clean(int deletionBatchSize, DocumentDatabase database, DateT
deleted++;
}
});
if (logger.IsDebugEnabled)
{
logger.Debug($"Batching deletion of {s}-{e} attachment audit documents completed.");
}
logger.Debug($"Batching deletion of {s}-{e} attachment audit documents completed.");

return deleted;
}, attachments, database, cancellationToken);

if (deletedAttachments + deletedAuditDocuments == 0)
{
if (logger.IsDebugEnabled)
{
logger.Debug("No expired audit documents found");
}
logger.Debug("No expired audit documents found");
}
else
{
if (logger.IsDebugEnabled)
{
logger.Debug($"Deleted {deletedAuditDocuments} expired audit documents and {deletedAttachments} message body attachments. Batch execution took {stopwatch.ElapsedMilliseconds} ms");
}
logger.Debug($"Deleted {deletedAuditDocuments} expired audit documents and {deletedAttachments} message body attachments. Batch execution took {stopwatch.ElapsedMilliseconds} ms");
}
}

Expand Down
4 changes: 2 additions & 2 deletions src/ServiceControl.Audit/Infrastructure/RavenDB/Expiration/ExpiredDocumentsCleaner.cs
View file
Open in desktop
Expand Up @@ -3,8 +3,8 @@
using System.Globalization;
using System.Threading;
using System.Threading.Tasks;
using NServiceBus.Logging;
using Raven.Abstractions;
using Raven.Abstractions.Logging;
using Raven.Database;
using ServiceControl.SagaAudit;
using Settings;
Expand All @@ -15,7 +15,7 @@ public static Task<TimerJobExecutionResult> RunCleanup(int deletionBatchSize, Do
{
var threshold = SystemTime.UtcNow.Add(-settings.AuditRetentionPeriod);

logger.Debug("Trying to find expired ProcessedMessage, SagaHistory and KnownEndpoint documents to delete (with threshold {0})", threshold.ToString(Default.DateTimeFormatsToWrite, CultureInfo.InvariantCulture));
logger.Debug($"Trying to find expired ProcessedMessage, SagaHistory and KnownEndpoint documents to delete (with threshold {threshold.ToString(Default.DateTimeFormatsToWrite, CultureInfo.InvariantCulture)})");
AuditMessageCleaner.Clean(deletionBatchSize, database, threshold, cancellationToken);
KnownEndpointsCleaner.Clean(deletionBatchSize, database, threshold, cancellationToken);
SagaHistoryCleaner.Clean(deletionBatchSize, database, threshold, cancellationToken);
Expand Down
10 changes: 5 additions & 5 deletions src/ServiceControl.Audit/Infrastructure/RavenDB/Expiration/ExpiredDocumentsCleanerBundle.cs
View file
Open in desktop
Expand Up @@ -3,7 +3,7 @@
using System;
using System.ComponentModel.Composition;
using System.Threading.Tasks;
using Raven.Abstractions.Logging;
using NServiceBus.Logging;
using Raven.Database;
using Raven.Database.Plugins;

Expand Down Expand Up @@ -50,12 +50,12 @@ public void Execute(DocumentDatabase database)
var due = TimeSpan.FromSeconds(deleteFrequencyInSeconds);
var deletionBatchSize = RavenBootstrapper.Settings.ExpirationProcessBatchSize;

logger.Info("Running deletion of expired documents every {0} seconds", deleteFrequencyInSeconds);
logger.Info("Deletion batch size set to {0}", deletionBatchSize);
logger.Info("Retention period for audits and saga history is {0}", RavenBootstrapper.Settings.AuditRetentionPeriod);
logger.Info($"Running deletion of expired documents every {deleteFrequencyInSeconds} seconds");
logger.Info($"Deletion batch size set to {deletionBatchSize}");
logger.Info($"Retention period for audits and saga history is {RavenBootstrapper.Settings.AuditRetentionPeriod}");

timer = new AsyncTimer(
token => ExpiredDocumentsCleaner.RunCleanup(deletionBatchSize, database, RavenBootstrapper.Settings, token), due, due, e => { logger.ErrorException("Error when trying to find expired documents", e); });
token => ExpiredDocumentsCleaner.RunCleanup(deletionBatchSize, database, RavenBootstrapper.Settings, token), due, due, e => { logger.Error("Error when trying to find expired documents", e); });
}

ILog logger = LogManager.GetLogger(typeof(ExpiredDocumentsCleanerBundle));
Expand Down
20 changes: 4 additions & 16 deletions src/ServiceControl.Audit/Infrastructure/RavenDB/Expiration/KnownEndpointsCleaner.cs
View file
Open in desktop
Expand Up @@ -77,34 +77,22 @@ public static void Clean(int deletionBatchSize, DocumentDatabase database, DateT

var deleteKnownEndpointDocuments = Chunker.ExecuteInChunks(items.Count, (itemsForBatch, db, s, e) =>
{
if (logger.IsDebugEnabled)
{
logger.Debug($"Batching deletion of {s}-{e} known endpoint documents.");
}
logger.Debug($"Batching deletion of {s}-{e} known endpoint documents.");

var results = db.Batch(itemsForBatch.GetRange(s, e - s + 1), CancellationToken.None);
if (logger.IsDebugEnabled)
{
logger.Debug($"Batching deletion of {s}-{e} known endpoint documents completed.");
}
logger.Debug($"Batching deletion of {s}-{e} known endpoint documents completed.");

return results.Count(x => x.Deleted == true);
}, items, database, cancellationToken);


if (deleteKnownEndpointDocuments == 0)
{
if (logger.IsDebugEnabled)
{
logger.Debug("No expired known endpoints documents found");
}
logger.Debug("No expired known endpoints documents found");
}
else
{
if (logger.IsDebugEnabled)
{
logger.Debug($"Deleted {deleteKnownEndpointDocuments} expired known endpoint documents. Batch execution took {stopwatch.ElapsedMilliseconds} ms");
}
logger.Debug($"Deleted {deleteKnownEndpointDocuments} expired known endpoint documents. Batch execution took {stopwatch.ElapsedMilliseconds} ms");
}
}

Expand Down
20 changes: 4 additions & 16 deletions src/ServiceControl.SagaAudit/SagaHistoryCleaner.cs
View file
Open in desktop
Expand Up @@ -77,33 +77,21 @@ public static void Clean(int deletionBatchSize, DocumentDatabase database, DateT

var deletionCount = Chunker.ExecuteInChunks(items.Count, (itemsForBatch, db, s, e) =>
{
if (logger.IsDebugEnabled)
{
logger.Debug($"Batching deletion of {s}-{e} saga history documents.");
}
logger.Debug($"Batching deletion of {s}-{e} saga history documents.");
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is a more general comment for all changes in this PR, where we still use interpolation. For consistency, would it make sense to also use the format-based overloads, like you did in some other changes in this PR?

Copy link
Member Author

@WilliamBZA WilliamBZA Feb 1, 2022 •
edited

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've actually gone the other way and have gone for interpolation rather than using the format overloads. My reasons:

  • It's easier to read what the value is when compared to looking at the index number and comparing to the args array
  • If we support structured logging in the future, we may be able to pull more meaning from the logs.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not an expert on this. If I read this right, we would have to use the template-based approach outlined in
https://docs.microsoft.com/en-us/aspnet/core/fundamentals/logging/?view=aspnetcore-6.0#log-message-template
docs.microsoft.comdocs.microsoft.com

Which means "not using interpolation".


var results = db.Batch(itemsForBatch.GetRange(s, e - s + 1), CancellationToken.None);
if (logger.IsDebugEnabled)
{
logger.Debug($"Batching deletion of {s}-{e} saga history documents completed.");
}
logger.Debug($"Batching deletion of {s}-{e} saga history documents completed.");

return results.Count(x => x.Deleted == true);
}, items, database, cancellationToken);

if (deletionCount == 0)
{
if (logger.IsDebugEnabled)
{
logger.Debug("No expired saga history documents found");
}
logger.Debug("No expired saga history documents found");
}
else
{
if (logger.IsDebugEnabled)
{
logger.Debug($"Deleted {deletionCount} expired saga history documents. Batch execution took {stopwatch.ElapsedMilliseconds} ms");
}
logger.Debug($"Deleted {deletionCount} expired saga history documents. Batch execution took {stopwatch.ElapsedMilliseconds} ms");
}
}

Expand Down
8 changes: 4 additions & 4 deletions src/ServiceControl/Infrastructure/RavenDB/Expiration/ExpiredDocumentsCleaner.cs
View file
Open in desktop
Expand Up @@ -4,8 +4,8 @@
using System.Threading;
using System.Threading.Tasks;
using BackgroundTasks;
using NServiceBus.Logging;
using Raven.Abstractions;
using Raven.Abstractions.Logging;
danielmarbach marked this conversation as resolved.
Show resolved Hide resolved
using Raven.Database;
using SagaAudit;
using ServiceBus.Management.Infrastructure.Settings;
Expand All @@ -16,19 +16,19 @@ public static Task<TimerJobExecutionResult> RunCleanup(int deletionBatchSize, Do
{
var threshold = SystemTime.UtcNow.Add(-settings.ErrorRetentionPeriod);

logger.Debug("Trying to find expired FailedMessage documents to delete (with threshold {0})", threshold.ToString(Default.DateTimeFormatsToWrite, CultureInfo.InvariantCulture));
logger.Debug($"Trying to find expired FailedMessage documents to delete (with threshold {threshold.ToString(Default.DateTimeFormatsToWrite, CultureInfo.InvariantCulture)})");
ErrorMessageCleaner.Clean(deletionBatchSize, database, threshold, cancellationToken);

threshold = SystemTime.UtcNow.Add(-settings.EventsRetentionPeriod);

logger.Debug("Trying to find expired EventLogItem documents to delete (with threshold {0})", threshold.ToString(Default.DateTimeFormatsToWrite, CultureInfo.InvariantCulture));
logger.Debug($"Trying to find expired EventLogItem documents to delete (with threshold {threshold.ToString(Default.DateTimeFormatsToWrite, CultureInfo.InvariantCulture)})");
EventLogItemsCleaner.Clean(deletionBatchSize, database, threshold, cancellationToken);

if (settings.AuditRetentionPeriod.HasValue)
{
threshold = SystemTime.UtcNow.Add(-settings.AuditRetentionPeriod.Value);

logger.Debug("Trying to find expired ProcessedMessage and SagaHistory documents to delete (with threshold {0})", threshold.ToString(Default.DateTimeFormatsToWrite, CultureInfo.InvariantCulture));
logger.Debug($"Trying to find expired ProcessedMessage and SagaHistory documents to delete (with threshold {threshold.ToString(Default.DateTimeFormatsToWrite, CultureInfo.InvariantCulture)})");
AuditMessageCleaner.Clean(deletionBatchSize, database, threshold, cancellationToken);
SagaHistoryCleaner.Clean(deletionBatchSize, database, threshold, cancellationToken);
}
Expand Down
12 changes: 6 additions & 6 deletions src/ServiceControl/Infrastructure/RavenDB/Expiration/ExpiredDocumentsCleanerBundle.cs
View file
Open in desktop
Expand Up @@ -4,7 +4,7 @@
using System.ComponentModel.Composition;
using System.Threading.Tasks;
using BackgroundTasks;
using Raven.Abstractions.Logging;
using NServiceBus.Logging;
using Raven.Database;
using Raven.Database.Plugins;

Expand Down Expand Up @@ -51,19 +51,19 @@ public void Execute(DocumentDatabase database)
var due = TimeSpan.FromSeconds(deleteFrequencyInSeconds);
var deletionBatchSize = RavenBootstrapper.Settings.ExpirationProcessBatchSize;

logger.Info("Running deletion of expired documents every {0} seconds", deleteFrequencyInSeconds);
logger.Info("Deletion batch size set to {0}", deletionBatchSize);
logger.Info("Retention period for errors is {0}", RavenBootstrapper.Settings.ErrorRetentionPeriod);
logger.Info($"Running deletion of expired documents every {deleteFrequencyInSeconds} seconds");
logger.Info($"Deletion batch size set to {deletionBatchSize}");
logger.Info($"Retention period for errors is {RavenBootstrapper.Settings.ErrorRetentionPeriod}");

var auditRetention = RavenBootstrapper.Settings.AuditRetentionPeriod;

if (auditRetention.HasValue)
{
logger.Info("Retention period for audits and saga history is {0}", RavenBootstrapper.Settings.AuditRetentionPeriod);
logger.InfoFormat("Retention period for audits and saga history is {0}", RavenBootstrapper.Settings.AuditRetentionPeriod);
}

timer = new TimerJob(
token => ExpiredDocumentsCleaner.RunCleanup(deletionBatchSize, database, RavenBootstrapper.Settings, token), due, due, e => { logger.ErrorException("Error when trying to find expired documents", e); });
token => ExpiredDocumentsCleaner.RunCleanup(deletionBatchSize, database, RavenBootstrapper.Settings, token), due, due, e => { logger.Error("Error when trying to find expired documents", e); });
}

ILog logger = LogManager.GetLogger(typeof(ExpiredDocumentsCleanerBundle));
Expand Down