From 290835c3a30237971a5f5af5ad0e9a207a2b1b46 Mon Sep 17 00:00:00 2001
From: Jay Malhotra <5047192+SapiensAnatis@users.noreply.github.com>
Date: Thu, 31 Oct 2024 22:35:29 +0000
Subject: [PATCH] Add debug logging to fort error cases (#1138)

Investigating as part of #436.

Adds some debug logging to indicate the state of the fort at the time
these exceptions get thrown.
---
 .../Features/Fort/FortServiceTest.cs          |  7 ++++
 .../DragaliaAPI/Features/Fort/FortService.cs  | 42 ++++++++++++++++---
 2 files changed, 44 insertions(+), 5 deletions(-)

diff --git a/DragaliaAPI/DragaliaAPI.Test/Features/Fort/FortServiceTest.cs b/DragaliaAPI/DragaliaAPI.Test/Features/Fort/FortServiceTest.cs
index 9a28f52fa..2d8868eea 100644
--- a/DragaliaAPI/DragaliaAPI.Test/Features/Fort/FortServiceTest.cs
+++ b/DragaliaAPI/DragaliaAPI.Test/Features/Fort/FortServiceTest.cs
@@ -15,6 +15,7 @@
 using Microsoft.Extensions.Options;
 using Microsoft.Extensions.Time.Testing;
 using MockQueryable;
+using NSubstitute;
 using Range = Moq.Range;
 
 namespace DragaliaAPI.Test.Features.Fort;
@@ -428,6 +429,9 @@ public async Task BuildStart_InsufficientCarpenters_Throws()
             .Setup(x => x.GetFortDetail())
             .ReturnsAsync(new DbFortDetail() { ViewerId = 1, CarpenterNum = 1 });
         mockFortRepository.Setup(x => x.GetActiveCarpenters()).ReturnsAsync(1);
+        mockFortRepository
+            .Setup(x => x.Builds)
+            .Returns(Array.Empty<DbFortBuild>().AsQueryable().BuildMock());
 
         await fortService
             .Invoking(x => x.BuildStart(FortPlants.BlueFlowers, 2, 3))
@@ -506,6 +510,9 @@ public async Task LevelupStart_InsufficientCarpenters_Throws()
             .ReturnsAsync(new DbFortDetail() { ViewerId = 1, CarpenterNum = 1 });
         mockFortRepository.Setup(x => x.GetActiveCarpenters()).ReturnsAsync(1);
         mockFortRepository.Setup(x => x.GetBuilding(1)).ReturnsAsync(build);
+        mockFortRepository
+            .Setup(x => x.Builds)
+            .Returns(Array.Empty<DbFortBuild>().AsQueryable().BuildMock());
 
         await fortService
             .Invoking(x => x.LevelupStart(1))
diff --git a/DragaliaAPI/DragaliaAPI/Features/Fort/FortService.cs b/DragaliaAPI/DragaliaAPI/Features/Fort/FortService.cs
index c1c7c8044..fcc7a2fec 100644
--- a/DragaliaAPI/DragaliaAPI/Features/Fort/FortService.cs
+++ b/DragaliaAPI/DragaliaAPI/Features/Fort/FortService.cs
@@ -351,11 +351,24 @@ public async Task EndLevelup(long buildId)
 
         DbFortBuild build = await fortRepository.GetBuilding(buildId);
 
-        if (
-            build.BuildStatus is not FortBuildStatus.LevelUp
-            || dateTimeProvider.GetUtcNow() < build.BuildEndDate
-        )
+        DateTimeOffset time = dateTimeProvider.GetUtcNow();
+
+        if (build.BuildStatus is not FortBuildStatus.LevelUp || time < build.BuildEndDate)
+        {
+            logger.LogDebug(
+                "Building {@Build} has not finished levelling up. Current time: {Time}",
+                new
+                {
+                    build.BuildId,
+                    build.PlantId,
+                    build.Level,
+                    build.BuildStartDate,
+                    build.BuildEndDate,
+                },
+                time
+            );
             throw new InvalidOperationException($"This building has not completed levelling up.");
+        }
 
         await FinishUpgrade(build, true);
     }
@@ -503,9 +516,28 @@ private async Task Upgrade(FortPlantDetail plantDetail)
         // Check Carpenter available
         if (fortDetail.WorkingCarpenterNum >= fortDetail.CarpenterNum)
         {
+            var builds = await fortRepository
+                .Builds.Where(x => x.BuildEndDate != DateTimeOffset.UnixEpoch)
+                .Select(x => new
+                {
+                    x.BuildId,
+                    x.PlantId,
+                    x.Level,
+                    x.BuildStartDate,
+                    x.BuildEndDate,
+                })
+                .ToListAsync();
+
+            logger.LogDebug(
+                "Failed to perform upgrade {@PlantDetail} - carpenters busy",
+                plantDetail
+            );
+            logger.LogDebug("FortDetail: {@FortDetail}", fortDetail);
+            logger.LogDebug("Currently in progress builds: {@Builds}", builds);
+
             throw new DragaliaException(
                 ResultCode.FortBuildCarpenterBusy,
-                $"All carpenters are currently busy"
+                "All carpenters are currently busy"
             );
         }