Make use of logging source generators except for temporary logs

tinglesoftware · Sep 21, 2023 · fc71a45 · fc71a45
1 parent 63c690a
commit fc71a45
Show file tree

Hide file tree

Showing 10 changed files with 176 additions and 51 deletions.
diff --git a/server/Tingle.Dependabot/Consumers/ProcessSynchronizationConsumer.cs b/server/Tingle.Dependabot/Consumers/ProcessSynchronizationConsumer.cs
@@ -29,7 +29,7 @@ public async Task ConsumeAsync(EventContext<ProcessSynchronization> context, Can
         var project = await dbContext.Projects.SingleOrDefaultAsync(r => r.Id == projectId, cancellationToken);
         if (project is null)
         {
-            logger.LogWarning("Skipping trigger for update because project '{Project}' does not exist.", projectId);
+            logger.SkippingSyncProjectNotFound(projectId);
             return;
         }
 
@@ -40,7 +40,7 @@ public async Task ConsumeAsync(EventContext<ProcessSynchronization> context, Can
             var repository = await dbContext.Repositories.SingleOrDefaultAsync(r => r.ProjectId == project.Id && r.Id == repositoryId, cancellationToken);
             if (repository is null)
             {
-                logger.LogWarning("Skipping synchronization because repository '{Repository}' does not exist.", repositoryId);
+                logger.SkippingSyncRepositoryNotFound(repositoryId);
                 return;
             }
 

diff --git a/server/Tingle.Dependabot/Consumers/TriggerUpdateJobsEventConsumer.cs b/server/Tingle.Dependabot/Consumers/TriggerUpdateJobsEventConsumer.cs
@@ -29,7 +29,7 @@ public async Task ConsumeAsync(EventContext<TriggerUpdateJobsEvent> context, Can
         var project = await dbContext.Projects.SingleOrDefaultAsync(r => r.Id == projectId, cancellationToken);
         if (project is null)
         {
-            logger.LogWarning("Skipping trigger for update because project '{Project}' does not exist.", projectId);
+            logger.SkippingTriggerProjectNotFound(projectId);
             return;
         }
 
@@ -38,7 +38,7 @@ public async Task ConsumeAsync(EventContext<TriggerUpdateJobsEvent> context, Can
         var repository = await dbContext.Repositories.SingleOrDefaultAsync(r => r.Id == repositoryId, cancellationToken);
         if (repository is null)
         {
-            logger.LogWarning("Skipping trigger for update because repository '{Repository}' does not exist.", repositoryId);
+            logger.SkippingTriggerRepositoryNotFound(repositoryId: repositoryId, projectId: project.Id);
             return;
         }
 
@@ -50,7 +50,7 @@ public async Task ConsumeAsync(EventContext<TriggerUpdateJobsEvent> context, Can
             var update = repository.Updates.ElementAtOrDefault(repositoryUpdateId.Value);
             if (update is null)
             {
-                logger.LogWarning("Skipping trigger for update because repository update '{RepositoryUpdateId}' does not exist.", repositoryUpdateId);
+                logger.SkippingTriggerRepositoryUpdateNotFound(repositoryId: repositoryId, repositoryUpdateId.Value, projectId: project.Id);
                 return;
             }
             updates = new[] { update, };
@@ -70,10 +70,10 @@ public async Task ConsumeAsync(EventContext<TriggerUpdateJobsEvent> context, Can
             var job = await dbContext.UpdateJobs.SingleOrDefaultAsync(j => j.PackageEcosystem == ecosystem && j.Directory == update.Directory && j.EventBusId == eventBusId, cancellationToken);
             if (job is not null)
             {
-                logger.LogWarning("A job for update '{RepositoryId}({UpdateId})' requested by event '{EventBusId}' already exists. Skipping it ...",
-                                  repository.Id,
-                                  repository.Updates.IndexOf(update),
-                                  eventBusId);
+                logger.SkippingTriggerJobAlreadyExists(repositoryId: repository.Id,
+                                                       repositoryUpdateId: repository.Updates.IndexOf(update),
+                                                       projectId: project.Id,
+                                                       eventBusId: eventBusId);
             }
             else
             {

diff --git a/server/Tingle.Dependabot/Consumers/UpdateJobEventsConsumer.cs b/server/Tingle.Dependabot/Consumers/UpdateJobEventsConsumer.cs
@@ -1,4 +1,5 @@
 using Microsoft.EntityFrameworkCore;
+using Microsoft.Extensions.Logging;
 using Tingle.Dependabot.Events;
 using Tingle.Dependabot.Models;
 using Tingle.Dependabot.Models.Management;
@@ -29,28 +30,28 @@ public async Task ConsumeAsync(EventContext<UpdateJobCheckStateEvent> context, C
         var job = await dbContext.UpdateJobs.SingleOrDefaultAsync(j => j.Id == jobId, cancellationToken);
         if (job is null)
         {
-            logger.LogWarning("Cannot update state for job '{UpdateJobId}' as it does not exist.", jobId);
+            logger.UpdateJobCannotUpdateStateNotFound(jobId);
             return;
         }
 
         // skip jobs in a terminal state (useful when reprocessed events)
         if (job.Status is UpdateJobStatus.Succeeded or UpdateJobStatus.Failed)
         {
-            logger.LogWarning("Cannot update state for job '{UpdateJobId}' as it is already in a terminal state.", jobId);
+            logger.UpdateJobCannotUpdateStateTerminalState(job.Id);
             return;
         }
 
         // get the state from the runner
         var state = await updateRunner.GetStateAsync(job, cancellationToken);
         if (state is null)
         {
-            logger.LogInformation("The runner did not provide a state for job '{UpdateJobId}'.", jobId);
+            logger.UpdateJobRunnerNoState(job.Id);
 
             // delete the job if we have been waiting for over 180 minutes and still do not have state
             var diff = DateTimeOffset.UtcNow - job.Created;
             if (diff > TimeSpan.FromMinutes(180))
             {
-                logger.LogWarning("Deleting job '{UpdateJobId}' as it has been pending for more than 90 minutes.", jobId);
+                logger.UpdateJobPendingTooLong(job.Id);
 
                 // delete the run
                 await updateRunner.DeleteAsync(job, cancellationToken);
@@ -108,14 +109,14 @@ public async Task ConsumeAsync(EventContext<UpdateJobCollectLogsEvent> context,
         var job = await dbContext.UpdateJobs.SingleOrDefaultAsync(j => j.Id == jobId, cancellationToken);
         if (job is null)
         {
-            logger.LogWarning("Cannot collect logs for job '{UpdateJobId}' as it does not exist.", jobId);
+            logger.UpdateJobCannotCollectLogsNotFound(jobId);
             return;
         }
 
         // ensure the job succeeded or failed
         if (job.Status is not UpdateJobStatus.Succeeded and not UpdateJobStatus.Failed)
         {
-            logger.LogWarning("Cannot collect logs for job '{UpdateJobId}' with status '{UpdateJobStatus}'.", job.Id, job.Status);
+            logger.UpdateJobCannotCollectLogsInvalidStatus(job.Id, job.Status);
             return;
         }
 

diff --git a/server/Tingle.Dependabot/Controllers/WebhooksController.cs b/server/Tingle.Dependabot/Controllers/WebhooksController.cs
@@ -29,10 +29,7 @@ public WebhooksController(MainDbContext dbContext, IEventPublisher publisher, IL
     public async Task<IActionResult> PostAsync([FromBody] AzureDevOpsEvent model)
     {
         var type = model.EventType;
-        logger.LogDebug("Received {EventType} notification {NotificationId} on subscription {SubscriptionId}",
-                        type,
-                        model.NotificationId,
-                        model.SubscriptionId);
+        logger.WebhooksReceivedEvent(type, model.NotificationId, model.SubscriptionId);
 
         if (type is AzureDevOpsEventType.GitPush)
         {
@@ -69,20 +66,14 @@ public async Task<IActionResult> PostAsync([FromBody] AzureDevOpsEvent model)
 
             if (type is AzureDevOpsEventType.GitPullRequestUpdated)
             {
-                logger.LogInformation("PR {PullRequestId} in {RepositoryUrl} status updated to {PullRequestStatus}",
-                                      prId,
-                                      adoRepository.RemoteUrl,
-                                      status);
+                logger.WebhooksPullRequestStatusUpdated(prId, adoRepository.RemoteUrl, status);
 
                 // TODO: handle the logic for merge conflicts here using events
 
             }
             else if (type is AzureDevOpsEventType.GitPullRequestMerged)
             {
-                logger.LogInformation("Merge status {MergeStatus} for PR {PullRequestId} in {RepositoryUrl}",
-                                      resource.MergeStatus,
-                                      prId,
-                                      adoRepository.RemoteUrl);
+                logger.WebhooksPullRequestMergedStatusUpdated(prId, adoRepository.RemoteUrl, resource.MergeStatus);
 
                 // TODO: handle the logic for updating other PRs to find merge conflicts (restart merge or attempt merge)
 
@@ -106,17 +97,14 @@ public async Task<IActionResult> PostAsync([FromBody] AzureDevOpsEvent model)
             var content = comment.Content?.Trim();
             if (content is not null && content.StartsWith("@dependabot"))
             {
-                logger.LogInformation("PR {PullRequestId} in {RepositoryUrl} was commented on: {Content}",
-                                      prId,
-                                      adoRepository.RemoteUrl,
-                                      content);
+                logger.WebhooksPullRequestCommentedOn(prId, adoRepository.RemoteUrl, content);
 
                 // TODO: handle the logic for comments here using events
             }
         }
         else
         {
-            logger.LogWarning("'{EventType}' events are not supported!", type);
+            logger.WebhooksReceivedEventUnsupported(type);
         }
 
         return Ok();

diff --git a/server/Tingle.Dependabot/Extensions/ILoggerExtensions.cs b/server/Tingle.Dependabot/Extensions/ILoggerExtensions.cs
@@ -0,0 +1,136 @@
+using Tingle.Dependabot.Models.Azure;
+using Tingle.Dependabot.Models.Management;
+
+namespace Microsoft.Extensions.Logging;
+
+internal static partial class ILoggerExtensions
+{
+    //[LoggerMessage(100, LogLevel.Warning, "Retrying periodic task execution {CurrentTry} of {MaxRetries}")]
+    //public static partial void RetryingExecutionOfPeriodicTask(this ILogger logger, Exception exception, int currentTry, int maxRetries);
+
+    #region Webhooks (2xx)
+
+    [LoggerMessage(200, LogLevel.Debug, "Received {EventType} notification {NotificationId} on subscription {SubscriptionId}")]
+    public static partial void WebhooksReceivedEvent(this ILogger logger, AzureDevOpsEventType? eventType, int notificationId, string? subscriptionId);
+
+    [LoggerMessage(201, LogLevel.Information, "PR {PullRequestId} in {RepositoryUrl} status updated to {PullRequestStatus}")]
+    public static partial void WebhooksPullRequestStatusUpdated(this ILogger logger, int pullRequestId, string? repositoryUrl, string? pullRequestStatus);
+
+    [LoggerMessage(202, LogLevel.Information, "PR {PullRequestId} in {RepositoryUrl} merge status changed to {MergeStatus}")]
+    public static partial void WebhooksPullRequestMergedStatusUpdated(this ILogger logger, int pullRequestId, string? repositoryUrl, string? mergeStatus);
+
+    [LoggerMessage(203, LogLevel.Information, "PR {PullRequestId} in {RepositoryUrl} was commented on: {CommentContent}")]
+    public static partial void WebhooksPullRequestCommentedOn(this ILogger logger, int pullRequestId, string? repositoryUrl, string? commentContent);
+
+    [LoggerMessage(204, LogLevel.Warning, "'{EventType}' events are not supported!")]
+    public static partial void WebhooksReceivedEventUnsupported(this ILogger logger, AzureDevOpsEventType? eventType);
+
+    #endregion
+
+    #region Synchronizer (3xx)
+
+    [LoggerMessage(300, LogLevel.Information, "Skipping synchronization for {ProjectId} since it last happened recently at {Synchronized}.")]
+    public static partial void SkippingSyncProjectTooSoon(this ILogger logger, string? projectId, DateTimeOffset? synchronized);
+
+    [LoggerMessage(301, LogLevel.Warning, "Skipping sync for update because project '{ProjectId}' does not exist.")]
+    public static partial void SkippingSyncProjectNotFound(this ILogger logger, string? projectId);
+
+    [LoggerMessage(302, LogLevel.Warning, "Skipping synchronization because repository '{RepositoryId}' does not exist.")]
+    public static partial void SkippingSyncRepositoryNotFound(this ILogger logger, string? repositoryId);
+
+    [LoggerMessage(303, LogLevel.Debug, "Skipping sync for {RepositoryName} in {ProjectId} because it is disabled or is a fork")]
+    public static partial void SkippingSyncRepositoryDisabledOrFork(this ILogger logger, string repositoryName, string? projectId);
+
+    [LoggerMessage(304, LogLevel.Debug, "Listing repositories in {ProjectId} ...")]
+    public static partial void SyncListingRepositories(this ILogger logger, string? projectId);
+
+    [LoggerMessage(305, LogLevel.Debug, "Found {RepositoriesCount} repositories in {ProjectId}")]
+    public static partial void SyncListingRepositories(this ILogger logger, int repositoriesCount, string? projectId);
+
+    [LoggerMessage(306, LogLevel.Information, "Deleted {RepositoriesCount} repositories that are no longer present in {ProjectId}.")]
+    public static partial void SyncDeletedRepositories(this ILogger logger, int repositoriesCount, string? projectId);
+
+    [LoggerMessage(307, LogLevel.Information, "Deleting '{RepositorySlug}' in {ProjectId} as it no longer has a configuration file.")]
+    public static partial void SyncDeletingRepository(this ILogger logger, string? repositorySlug, string? projectId);
+
+    [LoggerMessage(308, LogLevel.Information, "Configuration file for '{RepositorySlug}' in {ProjectId} is new or has been updated.")]
+    public static partial void SyncConfigFileChanged(this ILogger logger, string? repositorySlug, string? projectId);
+
+    [LoggerMessage(309, LogLevel.Warning, "Skipping '{RepositorySlug}' in {ProjectId}. The YAML file is invalid.")]
+    public static partial void SyncConfigFileInvalidStructure(this ILogger logger, Exception exception, string? repositorySlug, string? projectId);
+
+    [LoggerMessage(310, LogLevel.Warning, "Skipping '{RepositorySlug}' in {ProjectId}. The parsed configuration is invalid.")]
+    public static partial void SyncConfigFileInvalidData(this ILogger logger, Exception exception, string? repositorySlug, string? projectId);
+
+    #endregion
+
+    #region Scheduler (4xx)
+
+    [LoggerMessage(400, LogLevel.Debug, "Creating/Updating schedules for repository '{RepositoryId}' in project '{ProjectId}'")]
+    public static partial void SchedulesUpdating(this ILogger logger, string? repositoryId, string? projectId);
+
+    [LoggerMessage(401, LogLevel.Error, "Timer call back does not have correct argument. Exepected '{ExpectedType}' but got '{ActualType}'")]
+    public static partial void SchedulesTimerInvalidCallbackArgument(this ILogger logger, string? expectedType, string? actualType);
+
+    [LoggerMessage(402, LogLevel.Warning, "Schedule was missed for {RepositoryId}({UpdateId}) in project '{ProjectId}'. Triggering now ...")]
+    public static partial void ScheduleTriggerMissed(this ILogger logger, string? repositoryId, int updateId, string? projectId);
+
+    #endregion
+
+    #region Runner (5xx)
+
+    [LoggerMessage(500, LogLevel.Information, "Written job definition file for {UpdateJobId} at {JobDefinitionPath}")]
+    public static partial void WrittenJobDefinitionFile(this ILogger logger, string? updateJobId, string? jobDefinitionPath);
+
+    [LoggerMessage(501, LogLevel.Information, "Created ContainerApp Job for {UpdateJobId}")]
+    public static partial void CreatedContainerAppJob(this ILogger logger, string? updateJobId);
+
+    [LoggerMessage(502, LogLevel.Information, "Started ContainerApp Job for {UpdateJobId}")]
+    public static partial void StartedContainerAppJob(this ILogger logger, string? updateJobId);
+
+    #endregion
+
+    #region Update Jobs (6xx)
+
+    [LoggerMessage(600, LogLevel.Warning, "Cannot update state for job '{UpdateJobId}' as it does not exist.")]
+    public static partial void UpdateJobCannotUpdateStateNotFound(this ILogger logger, string? updateJobId);
+
+    [LoggerMessage(601, LogLevel.Warning, "Cannot update state for job '{UpdateJobId}' as it is already in a terminal state.")]
+    public static partial void UpdateJobCannotUpdateStateTerminalState(this ILogger logger, string? updateJobId);
+
+    [LoggerMessage(602, LogLevel.Information, "The runner did not provide a state for job '{UpdateJobId}'.")]
+    public static partial void UpdateJobRunnerNoState(this ILogger logger, string? updateJobId);
+
+    [LoggerMessage(603, LogLevel.Warning, "Deleting job '{UpdateJobId}' as it has been pending for more than 90 minutes.")]
+    public static partial void UpdateJobPendingTooLong(this ILogger logger, string? updateJobId);
+
+    [LoggerMessage(604, LogLevel.Warning, "Cannot collect logs for job '{UpdateJobId}' as it does not exist.")]
+    public static partial void UpdateJobCannotCollectLogsNotFound(this ILogger logger, string? updateJobId);
+
+    [LoggerMessage(605, LogLevel.Warning, "Cannot collect logs for job '{UpdateJobId}' with status '{UpdateJobStatus}'.")]
+    public static partial void UpdateJobCannotCollectLogsInvalidStatus(this ILogger logger, string? updateJobId, UpdateJobStatus updateJobStatus);
+
+    [LoggerMessage(606, LogLevel.Information, "Found {UpdateJobsCount} jobs that are still pending for more than 10 min. Requesting manual resolution ...")]
+    public static partial void UpdateJobRequestingManualResolution(this ILogger logger, int updateJobsCount);
+
+    [LoggerMessage(607, LogLevel.Information, "Removed {UpdateJobsCount} jobs that older than {Cutoff}")]
+    public static partial void UpdateJobRemovedOldJobs(this ILogger logger, int updateJobsCount, DateTimeOffset cutoff);
+
+    #endregion
+
+    #region Update Jobs (7xx)
+
+    [LoggerMessage(700, LogLevel.Warning, "Skipping trigger for update because project '{ProjectId}' does not exist.")]
+    public static partial void SkippingTriggerProjectNotFound(this ILogger logger, string projectId);
+
+    [LoggerMessage(701, LogLevel.Warning, "Skipping trigger for update because repository '{RepositoryId}' in project '{ProjectId}' does not exist.")]
+    public static partial void SkippingTriggerRepositoryNotFound(this ILogger logger, string repositoryId, string? projectId);
+
+    [LoggerMessage(702, LogLevel.Warning, "Skipping trigger for update because repository update '{RepositoryId}({RepositoryUpdateId})' in project '{ProjectId}' does not exist.")]
+    public static partial void SkippingTriggerRepositoryUpdateNotFound(this ILogger logger, string repositoryId, int repositoryUpdateId, string? projectId);
+
+    [LoggerMessage(703, LogLevel.Warning, "A job for update '{RepositoryId}({RepositoryUpdateId})' in project '{ProjectId}' requested by event '{EventBusId}' already exists. Skipping it ...")]
+    public static partial void SkippingTriggerJobAlreadyExists(this ILogger logger, string? repositoryId, int repositoryUpdateId, string? projectId, string? eventBusId);
+
+    #endregion
+}
diff --git a/server/Tingle.Dependabot/PeriodicTasks/MissedTriggerCheckerTask.cs b/server/Tingle.Dependabot/PeriodicTasks/MissedTriggerCheckerTask.cs
@@ -63,7 +63,7 @@ internal virtual async Task CheckAsync(DateTimeOffset referencePoint, Cancellati
                     // if we missed an execution, trigger one
                     if (missed)
                     {
-                        logger.LogWarning("Schedule was missed for {RepositoryId}({UpdateId}). Triggering now", repository.Id, repository.Updates.IndexOf(update));
+                        logger.ScheduleTriggerMissed(repositoryId: repository.Id, updateId: repository.Updates.IndexOf(update), projectId: project.Id);
 
                         // publish event for the job to be run
                         var evt = new TriggerUpdateJobsEvent

diff --git a/server/Tingle.Dependabot/PeriodicTasks/UpdateJobsCleanerTask.cs b/server/Tingle.Dependabot/PeriodicTasks/UpdateJobsCleanerTask.cs
@@ -39,7 +39,7 @@ orderby j.Created ascending
 
         if (jobs.Count > 0)
         {
-            logger.LogInformation("Found {Count} jobs that are still pending for more than 10 min. Requesting manual resolution ...", jobs.Count);
+            logger.UpdateJobRequestingManualResolution(jobs.Count);
 
             var events = jobs.Select(j => new UpdateJobCheckStateEvent { JobId = j.Id, }).ToList();
             await publisher.PublishAsync<UpdateJobCheckStateEvent>(events, cancellationToken: cancellationToken);
@@ -55,7 +55,7 @@ orderby j.Created ascending
         {
             dbContext.UpdateJobs.RemoveRange(jobs);
             await dbContext.SaveChangesAsync(cancellationToken);
-            logger.LogInformation("Removed {Count} jobs that older than {Cutoff}", jobs.Count, cutoff);
+            logger.UpdateJobRemovedOldJobs(jobs.Count, cutoff);
         }
     }
 }