Feature/logging (#696)

* Added additional logging when acquire a distributed lock * Removed unused variable * Removed server name from startup
didx-xyz · Apr 9, 2024 · 5a2db09 · 5a2db09
1 parent 28d7051
commit 5a2db09
Show file tree

Hide file tree

Showing 10 changed files with 76 additions and 37 deletions.
diff --git a/src/api/src/application/Yoma.Core.Api/Controllers/KeycloakController.cs b/src/api/src/application/Yoma.Core.Api/Controllers/KeycloakController.cs
@@ -224,7 +224,7 @@ private async Task UpdateUserProfile(WebhookRequestEventType type, KeycloakWebho
 
           //updated here after email verification a login event is raised
           userRequest.EmailConfirmed = kcUser.EmailVerified;
-          userRequest.DateLastLogin = DateTime.Now;
+          userRequest.DateLastLogin = DateTimeOffset.UtcNow;
 
           try
           {

diff --git a/src/api/src/domain/Yoma.Core.Domain/Entity/Services/OrganizationBackgroundService.cs b/src/api/src/domain/Yoma.Core.Domain/Entity/Services/OrganizationBackgroundService.cs
@@ -63,20 +63,23 @@ public OrganizationBackgroundService(ILogger<OrganizationBackgroundService> logg
     public async Task ProcessDeclination()
     {
       const string lockIdentifier = "organization_process_declination";
-      var dateTimeNow = DateTime.Now;
+      var dateTimeNow = DateTimeOffset.UtcNow;
       var executeUntil = dateTimeNow.AddHours(_scheduleJobOptions.DefaultScheduleMaxIntervalInHours);
       var lockDuration = executeUntil - dateTimeNow + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
+
           _logger.LogInformation("Processing organization declination");
 
           var statusDeclinationIds = Statuses_Declination.Select(o => _organizationStatusService.GetByName(o.ToString()).Id).ToList();
           var statusDeclinedId = _organizationStatusService.GetByName(OrganizationStatus.Declined.ToString()).Id;
 
-          while (executeUntil > DateTime.Now)
+          while (executeUntil > DateTimeOffset.UtcNow)
           {
             var items = _organizationRepository.Query(true).Where(o => statusDeclinationIds.Contains(o.StatusId) &&
              o.DateModified <= DateTimeOffset.UtcNow.AddDays(-_scheduleJobOptions.OrganizationDeclinationIntervalInDays))
@@ -129,7 +132,7 @@ public async Task ProcessDeclination()
               }
             }
 
-            if (executeUntil <= DateTime.Now) break;
+            if (executeUntil <= DateTimeOffset.UtcNow) break;
           }
         }
 
@@ -148,20 +151,23 @@ public async Task ProcessDeclination()
     public async Task ProcessDeletion()
     {
       const string lockIdentifier = "organization_process_deletion";
-      var dateTimeNow = DateTime.Now;
+      var dateTimeNow = DateTimeOffset.UtcNow;
       var executeUntil = dateTimeNow.AddHours(_scheduleJobOptions.DefaultScheduleMaxIntervalInHours);
       var lockDuration = executeUntil - dateTimeNow + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
+
           _logger.LogInformation("Processing organization deletion");
 
           var statusDeletionIds = Statuses_Deletion.Select(o => _organizationStatusService.GetByName(o.ToString()).Id).ToList();
           var statusDeletedId = _organizationStatusService.GetByName(OrganizationStatus.Deleted.ToString()).Id;
 
-          while (executeUntil > DateTime.Now)
+          while (executeUntil > DateTimeOffset.UtcNow)
           {
             var items = _organizationRepository.Query().Where(o => statusDeletionIds.Contains(o.StatusId) &&
                 o.DateModified <= DateTimeOffset.UtcNow.AddDays(-_scheduleJobOptions.OrganizationDeletionIntervalInDays))
@@ -179,7 +185,7 @@ public async Task ProcessDeletion()
 
             await _organizationRepository.Update(items);
 
-            if (executeUntil <= DateTime.Now) break;
+            if (executeUntil <= DateTimeOffset.UtcNow) break;
           }
 
           _logger.LogInformation("Processed organization deletion");
@@ -198,13 +204,15 @@ public async Task ProcessDeletion()
     public async Task SeedLogoAndDocuments()
     {
       const string lockIdentifier = "organization_seed_logos_and_documents";
-      var dateTimeNow = DateTime.Now;
       var lockDuration = TimeSpan.FromHours(_scheduleJobOptions.DefaultScheduleMaxIntervalInHours) + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
+
           if (!_appSettings.TestDataSeedingEnvironmentsAsEnum.HasFlag(_environmentProvider.Environment))
           {
             _logger.LogInformation("Organization logo and document seeding skipped for environment '{environment}'", _environmentProvider.Environment);

diff --git a/src/api/src/domain/Yoma.Core.Domain/Entity/Services/UserBackgroundService.cs b/src/api/src/domain/Yoma.Core.Domain/Entity/Services/UserBackgroundService.cs
@@ -43,13 +43,15 @@ public UserBackgroundService(ILogger<UserBackgroundService> logger,
     public async Task SeedPhotos()
     {
       const string lockIdentifier = "user_seed_photos";
-      var dateTimeNow = DateTime.Now;
       var lockDuration = TimeSpan.FromHours(_scheduleJobOptions.DefaultScheduleMaxIntervalInHours) + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
+
           if (!_appSettings.TestDataSeedingEnvironmentsAsEnum.HasFlag(_environmentProvider.Environment))
           {
             _logger.LogInformation("User image seeding seeding skipped for environment '{environment}'", _environmentProvider.Environment);

diff --git a/src/api/src/domain/Yoma.Core.Domain/Lookups/Services/SkillService.cs b/src/api/src/domain/Yoma.Core.Domain/Lookups/Services/SkillService.cs
@@ -106,13 +106,15 @@ public SkillSearchResults Search(SkillSearchFilter filter)
     public async Task SeedSkills(bool onStartupInitialSeeding)
     {
       const string lockIdentifier = "skill_seed";
-      var dateTimeNow = DateTime.Now;
       var lockDuration = TimeSpan.FromHours(_scheduleJobOptions.DefaultScheduleMaxIntervalInHours) + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
+
           try
           {
             if (onStartupInitialSeeding && _skillRepository.Query().Any())

diff --git a/src/api/src/domain/Yoma.Core.Domain/MyOpportunity/Services/MyOpportunityBackgroundService.cs b/src/api/src/domain/Yoma.Core.Domain/MyOpportunity/Services/MyOpportunityBackgroundService.cs
@@ -69,20 +69,23 @@ public MyOpportunityBackgroundService(ILogger<MyOpportunityBackgroundService> lo
     public async Task ProcessVerificationRejection()
     {
       const string lockIdentifier = "myopportunity_process_verification_rejection";
-      var dateTimeNow = DateTime.Now;
+      var dateTimeNow = DateTimeOffset.UtcNow;
       var executeUntil = dateTimeNow.AddHours(_scheduleJobOptions.DefaultScheduleMaxIntervalInHours);
       var lockDuration = executeUntil - dateTimeNow + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
+
           _logger.LogInformation("Processing 'my' opportunity verification rejection");
 
           var statusRejectedId = _myOpportunityVerificationStatusService.GetByName(VerificationStatus.Rejected.ToString()).Id;
           var statusRejectableIds = Statuses_Rejectable.Select(o => _myOpportunityVerificationStatusService.GetByName(o.ToString()).Id).ToList();
 
-          while (executeUntil > DateTime.Now)
+          while (executeUntil > DateTimeOffset.UtcNow)
           {
             var items = _myOpportunityRepository.Query().Where(o => o.VerificationStatusId.HasValue && statusRejectableIds.Contains(o.VerificationStatusId.Value) &&
               o.DateModified <= DateTimeOffset.UtcNow.AddDays(-_scheduleJobOptions.MyOpportunityRejectionIntervalInDays))
@@ -140,7 +143,7 @@ public async Task ProcessVerificationRejection()
               }
             }
 
-            if (executeUntil <= DateTime.Now) break;
+            if (executeUntil <= DateTimeOffset.UtcNow) break;
           }
 
           _logger.LogInformation("Processed 'my' opportunity verification rejection");
@@ -159,13 +162,15 @@ public async Task ProcessVerificationRejection()
     public async Task SeedPendingVerifications()
     {
       const string lockIdentifier = "myopportunity_seed_pending_verifications]";
-      var dateTimeNow = DateTime.Now;
       var lockDuration = TimeSpan.FromHours(_scheduleJobOptions.DefaultScheduleMaxIntervalInHours) + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
+
           if (!_appSettings.TestDataSeedingEnvironmentsAsEnum.HasFlag(_environmentProvider.Environment))
           {
             _logger.LogInformation("Pending verification seeding skipped for environment '{environment}'", _environmentProvider.Environment);

diff --git a/src/api/src/domain/Yoma.Core.Domain/Opportunity/Services/OpportunityBackgroundService.cs b/src/api/src/domain/Yoma.Core.Domain/Opportunity/Services/OpportunityBackgroundService.cs
@@ -54,20 +54,23 @@ public OpportunityBackgroundService(ILogger<OpportunityBackgroundService> logger
     public async Task ProcessExpiration()
     {
       const string lockIdentifier = "opporrtunity_process_expiration";
-      var dateTimeNow = DateTime.Now;
+      var dateTimeNow = DateTimeOffset.UtcNow;
       var executeUntil = dateTimeNow.AddHours(_scheduleJobOptions.DefaultScheduleMaxIntervalInHours);
       var lockDuration = executeUntil - dateTimeNow + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
+
           _logger.LogInformation("Processing opportunity expiration");
 
           var statusExpiredId = _opportunityStatusService.GetByName(Status.Expired.ToString()).Id;
           var statusExpirableIds = Statuses_Expirable.Select(o => _opportunityStatusService.GetByName(o.ToString()).Id).ToList();
 
-          while (executeUntil > DateTime.Now)
+          while (executeUntil > DateTimeOffset.UtcNow)
           {
             var items = _opportunityRepository.Query().Where(o => statusExpirableIds.Contains(o.StatusId) &&
                 o.DateEnd.HasValue && o.DateEnd.Value <= DateTimeOffset.UtcNow).OrderBy(o => o.DateEnd).Take(_scheduleJobOptions.OpportunityExpirationBatchSize).ToList();
@@ -86,7 +89,7 @@ public async Task ProcessExpiration()
 
             await SendEmail(items, EmailType.Opportunity_Expiration_Expired);
 
-            if (executeUntil <= DateTime.Now) break;
+            if (executeUntil <= DateTimeOffset.UtcNow) break;
           }
 
           _logger.LogInformation("Processed opportunity expiration");
@@ -105,13 +108,14 @@ public async Task ProcessExpiration()
     public async Task ProcessExpirationNotifications()
     {
       const string lockIdentifier = "opporrtunity_process_expiration_notifications";
-      var dateTimeNow = DateTime.Now;
       var lockDuration = TimeSpan.FromHours(_scheduleJobOptions.DefaultScheduleMaxIntervalInHours) + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
 
           _logger.LogInformation("Processing opportunity expiration notifications");
 
@@ -142,20 +146,23 @@ public async Task ProcessExpirationNotifications()
     public async Task ProcessDeletion()
     {
       const string lockIdentifier = "opporrtunity_process_deletion";
-      var dateTimeNow = DateTime.Now;
+      var dateTimeNow = DateTimeOffset.UtcNow;
       var executeUntil = dateTimeNow.AddHours(_scheduleJobOptions.DefaultScheduleMaxIntervalInHours);
       var lockDuration = executeUntil - dateTimeNow + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
+
           _logger.LogInformation("Processing opportunity deletion");
 
           var statusDeletionIds = Statuses_Deletion.Select(o => _opportunityStatusService.GetByName(o.ToString()).Id).ToList();
           var statusDeletedId = _opportunityStatusService.GetByName(Status.Deleted.ToString()).Id;
 
-          while (executeUntil > DateTime.Now)
+          while (executeUntil > DateTimeOffset.UtcNow)
           {
             {
               var items = _opportunityRepository.Query().Where(o => statusDeletionIds.Contains(o.StatusId) &&
@@ -174,7 +181,7 @@ public async Task ProcessDeletion()
 
               await _opportunityRepository.Update(items);
 
-              if (executeUntil <= DateTime.Now) break;
+              if (executeUntil <= DateTimeOffset.UtcNow) break;
             }
           }
 

diff --git a/src/api/src/domain/Yoma.Core.Domain/Opportunity/Services/OpportunityInfoService.cs b/src/api/src/domain/Yoma.Core.Domain/Opportunity/Services/OpportunityInfoService.cs
@@ -139,7 +139,7 @@ public OpportunitySearchResultsInfo Search(OpportunitySearchFilter filter)
         cw.WriteRecords(result.Items);
       }
 
-      var fileName = $"Transactions_{DateTime.Now:yyyy-dd-M--HH-mm-ss}.csv";
+      var fileName = $"Transactions_{DateTimeOffset.UtcNow:yyyy-dd-M--HH-mm-ss}.csv";
       return (fileName, stream.ToArray());
     }
     #endregion

diff --git a/src/api/src/domain/Yoma.Core.Domain/Reward/Services/RewardBackgroundService.cs b/src/api/src/domain/Yoma.Core.Domain/Reward/Services/RewardBackgroundService.cs
@@ -54,18 +54,21 @@ public RewardBackgroundService(ILogger<SSIBackgroundService> logger,
     public async Task ProcessWalletCreation()
     {
       const string lockIdentifier = "reward_process_wallet_creation";
-      var dateTimeNow = DateTime.Now;
+      var dateTimeNow = DateTimeOffset.UtcNow;
       var executeUntil = dateTimeNow.AddHours(_scheduleJobOptions.RewardWalletCreationScheduleMaxIntervalInHours);
       var lockDuration = executeUntil - dateTimeNow + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
+
           _logger.LogInformation("Processing Reward wallet creation");
 
           var itemIdsToSkip = new List<Guid>();
-          while (executeUntil > DateTime.Now)
+          while (executeUntil > DateTimeOffset.UtcNow)
           {
             var items = _walletService.ListPendingCreationSchedule(_scheduleJobOptions.RewardWalletCreationScheduleBatchSize, itemIdsToSkip);
             if (items.Count == 0) break;
@@ -103,7 +106,7 @@ await _executionStrategyService.ExecuteInExecutionStrategyAsync(async () =>
                 itemIdsToSkip.Add(item.Id);
               }
 
-              if (executeUntil <= DateTime.Now) break;
+              if (executeUntil <= DateTimeOffset.UtcNow) break;
             }
           }
 
@@ -123,18 +126,21 @@ await _executionStrategyService.ExecuteInExecutionStrategyAsync(async () =>
     public async Task ProcessRewardTransactions()
     {
       const string lockIdentifier = "reward_process_transactions";
-      var dateTimeNow = DateTime.Now;
+      var dateTimeNow = DateTimeOffset.UtcNow;
       var executeUntil = dateTimeNow.AddHours(_scheduleJobOptions.RewardTransactionScheduleMaxIntervalInHours);
       var lockDuration = executeUntil - dateTimeNow + TimeSpan.FromMinutes(_scheduleJobOptions.DistributedLockDurationBufferInMinutes);
 
       try
       {
         using (JobStorage.Current.GetConnection().AcquireDistributedLock(lockIdentifier, lockDuration))
         {
+          _logger.LogInformation("Lock '{lockIdentifier}' acquired by {hostName} at {dateStamp}. Lock duration set to {lockDurationInMinutes} minutes",
+            lockIdentifier, Environment.MachineName, DateTimeOffset.UtcNow, lockDuration.TotalMinutes);
+
           _logger.LogInformation("Processing reward transactions");
 
           var itemIdsToSkip = new List<Guid>();
-          while (executeUntil > DateTime.Now)
+          while (executeUntil > DateTimeOffset.UtcNow)
           {
             var items = _rewardService.ListPendingTransactionSchedule(_scheduleJobOptions.RewardTransactionScheduleBatchSize, itemIdsToSkip);
             if (items.Count == 0) break;
@@ -206,7 +212,7 @@ public async Task ProcessRewardTransactions()
                 itemIdsToSkip.Add(item.Id);
               }
 
-              if (executeUntil <= DateTime.Now) break;
+              if (executeUntil <= DateTimeOffset.UtcNow) break;
             }
           }