Fix hgweb race condition in GetLastCommitTime (#1026)

* Fix hgweb race condition in GetLastCommitTime

If a project has just been created and then a zip file uploaded to
populate it with initial data, as happens often in integration tests,
then hgweb could return 404 for /hg/projectCode/log because its internal
list of repos was recently refreshed (by another test) and the refresh
interval hasn't been reached yet. One way to avoid this is to use the
command runner to get the last commit date, since the hg command line
doesn't use the refreshinterval setting from hgweb.

* Move all date-parsing code into ConvertHgDate

Also expand the range of unit tests to include all kinds of invalid
values, making sure ConvertHgDate returns null for all invalid data.

* Upload k8s logs as artifacts on test failure

---------

Co-authored-by: Kevin Hahn <kevin_hahn@sil.org>

.github/workflows/develop-api.yaml

@@ -52,7 +52,7 @@ jobs:
       deploy-domain: lexbox.dev.languagetechnology.org
 
   integration-test-gha:
-    name: Self hosted integration tests
+    name: GHA integration tests
     needs: [build-api, set-version]
     uses: ./.github/workflows/integration-test-gha.yaml
     with:

.github/workflows/integration-test-gha.yaml

@@ -1,4 +1,4 @@
-name: Self contained integration tests
+name: GHA integration tests
 on:
   workflow_dispatch:
     inputs:
@@ -39,6 +39,25 @@ jobs:
         uses: mikefarah/yq@0b34c9a00de1c575a34eea05af1d956a525c4fc1 # v4.34.2
         with:
           cmd: yq eval -i '(.images.[] | select(.name == "ghcr.io/sillsdev/lexbox-api").newTag) = "${{ inputs.lexbox-api-tag }}"' "./deployment/gha/kustomization.yaml"
+      # It's also possible that hgweb and/or ui image may have changed; if so, pull them and update kustomization.yaml for them as well
+      - name: Pull hgweb if updated
+        id: hgweb_image
+        continue-on-error: true
+        run: docker pull ghcr.io/sillsdev/lexbox-hgweb:${{ inputs.lexbox-api-tag }}
+      - name: Update image hgweb version
+        if: ${{ steps.hgweb_image.outcome == 'success' }}
+        uses: mikefarah/yq@0b34c9a00de1c575a34eea05af1d956a525c4fc1 # v4.34.2
+        with:
+          cmd: yq eval -i '(.images.[] | select(.name == "ghcr.io/sillsdev/lexbox-hgweb").newTag) = "${{ inputs.lexbox-api-tag }}"' "./deployment/gha/kustomization.yaml"
+      - name: Pull ui if updated
+        id: ui_image
+        continue-on-error: true
+        run: docker pull ghcr.io/sillsdev/lexbox-ui:${{ inputs.lexbox-api-tag }}
+      - name: Update image ui version
+        if: ${{ steps.ui_image.outcome == 'success' }}
+        uses: mikefarah/yq@0b34c9a00de1c575a34eea05af1d956a525c4fc1 # v4.34.2
+        with:
+          cmd: yq eval -i '(.images.[] | select(.name == "ghcr.io/sillsdev/lexbox-ui").newTag) = "${{ inputs.lexbox-api-tag }}"' "./deployment/gha/kustomization.yaml"
       - name: deploy
         run: |
           kubectl create namespace languagedepot
@@ -47,14 +66,6 @@ jobs:
           kubectl apply -k ./deployment/gha
           kubectl wait --for=condition=Ready --timeout=120s pod -l 'app.kubernetes.io/component=controller' -n languagedepot
           kubectl wait --for=condition=Ready --timeout=120s pod -l 'app in (lexbox, ui, hg, db)' -n languagedepot
-      - name: status
-        if: failure()
-        run: |
-          kubectl describe pods -l 'app in (lexbox, ui, hg, db)' -n languagedepot
-          echo "========== LOGS =========="
-          kubectl logs -l 'app in (lexbox, ui, hg, db)' -n languagedepot --prefix --all-containers --tail=50
-          echo "========== INGRESS =========="
-          kubectl logs -l 'app.kubernetes.io/name=ingress-nginx' -n languagedepot --prefix --all-containers --tail=50
       - name: forward ingress
         run: kubectl port-forward service/ingress-nginx-controller 6579:80 -n languagedepot &
       - name: verify ingress
@@ -69,4 +80,19 @@ jobs:
           TEST_PROJECT_CODE: 'sena-3'
           TEST_DEFAULT_PASSWORD: 'pass'
         run: dotnet test LexBoxOnly.slnf --logger GitHubActions --filter "Category=Integration|Category=FlakyIntegration" --blame-hang-timeout 40m
+      - name: status
+        if: failure()
+        run: |
+          mkdir -p k8s-logs
+          for app in lexbox ui hg db; do
+            kubectl describe pods -l "app=${app}" -n languagedepot > k8s-logs/describe-${app}.txt
+            kubectl logs -l "app=${app}" -n languagedepot --prefix --all-containers --tail=-1 > k8s-logs/logs-${app}.txt
+          done
+          kubectl logs -l 'app.kubernetes.io/name=ingress-nginx' -n languagedepot --prefix --all-containers --tail=-1 > k8s-logs/logs-ingress.txt
+      - name: upload status
+        if: failure()
+        uses: actions/upload-artifact@v4
+        with:
+          name: k8s-logs
+          path: k8s-logs/*.txt
 

backend/LexBoxApi/Services/HgService.cs

@@ -280,17 +280,8 @@ public bool RepoIsLocked(ProjectCode projectCode)
 
     public async Task<DateTimeOffset?> GetLastCommitTimeFromHg(ProjectCode projectCode)
     {
-        var json = await GetCommit(projectCode, "tip");
-        //format is this: [1678687688, offset] offset is
-        var dateArray = json?["entries"]?[0]?["date"].Deserialize<decimal[]>();
-        if (dateArray is null || dateArray.Length != 2 || dateArray[0] <= 0)
-            return null;
-        //offsets are weird. The format we get the offset in is opposite of how we typically represent offsets, eg normally the US has negative
-        //offsets because it's behind UTC. But in other cases the US has positive offsets because time needs to be added to reach UTC.
-        //the offset we get here is the latter but dotnet expects the former so we need to invert it.
-        var offset = (double)dateArray[1] * -1;
-        var date = DateTimeOffset.FromUnixTimeSeconds((long)dateArray[0]).ToOffset(TimeSpan.FromSeconds(offset));
-        return date.ToUniversalTime();
+        var dateStr = await GetTipDate(projectCode);
+        return ConvertHgDate(dateStr);
     }
 
     private async Task<JsonObject?> GetCommit(ProjectCode projectCode, string rev)
@@ -339,6 +330,29 @@ public Task<HttpContent> InvalidateDirCache(ProjectCode code, CancellationToken
         return result;
     }
 
+    public static DateTimeOffset? ConvertHgDate(string? dateStr)
+    {
+        // Format is "1472445535 -25200", two ints separated by a single space.
+        // "0 0" is returned for empty repos (no commits), but we prefer to represent that as null
+        if (dateStr == "0 0") return null;
+        var dateArray = dateStr?.Split();
+        if (dateArray is null || dateArray.Length != 2) return null;
+        // Parse to 64-bit ints so we don't have a year 2038 problem
+        if (!long.TryParse(dateArray[0], out var timestamp)) return null;
+        if (!long.TryParse(dateArray[1], out var offset)) return null;
+        //hg offsets are weird. The format we get the offset in is opposite of how we typically represent offsets, eg normally the US has negative
+        //offsets because it's behind UTC. But in other cases the US has positive offsets because time needs to be added to reach UTC.
+        //the offset we get here is the latter but dotnet expects the former so we need to invert it.
+        var date = DateTimeOffset.FromUnixTimeSeconds(timestamp).ToOffset(TimeSpan.FromSeconds(offset * -1));
+        return date.ToUniversalTime();
+    }
+
+    public async Task<string> GetTipDate(ProjectCode code, CancellationToken token = default)
+    {
+        var content = await ExecuteHgCommandServerCommand(code, "tipdate", token);
+        return await content.ReadAsStringAsync();
+    }
+
     public async Task<string> GetTipHash(ProjectCode code, CancellationToken token = default)
     {
         var content = await ExecuteHgCommandServerCommand(code, "tip", token);

backend/Testing/LexCore/Services/HgServiceTests.cs

@@ -62,6 +62,29 @@ public void DetermineProjectPrefixWorks(HgType type, string expectedUrl)
         HgService.DetermineProjectUrlPrefix(type, _hgConfig).ShouldBe(expectedUrl);
     }
 
+    [Theory]
+    // Valid values
+    [InlineData("1630088815 0", "2021-08-27T18:26:55+0000")]
+    [InlineData("1472445535 -25200", "2016-08-29T11:38:55+0700")]
+    [InlineData("1472028930 14400", "2016-08-24T04:55:30-0400")]
+    // hg returns "0 0" for a repo with no commits, which we want to represent as null
+    [InlineData("0 0", null)]
+    // Invalid values should also return null
+    [InlineData("", null)]
+    [InlineData(null, null)]
+    [InlineData("1722581047", null)]
+    [InlineData("1722581047 0 3", null)]
+    [InlineData("1722581047 xyz", null)]
+    [InlineData("xyz", null)]
+    [InlineData("xyz 0", null)]
+    [InlineData("xyz 7200", null)]
+    public void HgDatesConvertedAccurately(string? input, string? expectedStr)
+    {
+        DateTimeOffset? expected = expectedStr == null ? null : DateTimeOffset.Parse(expectedStr);
+        var actual = HgService.ConvertHgDate(input);
+        actual.ShouldBe(expected);
+    }
+
     [Theory]
     [InlineData(".hg/important-file.bin")]
     [InlineData("unzip-test/.hg/important-file.bin")]

hgweb/command-runner.sh

@@ -1,7 +1,7 @@
 #!/bin/bash
 
 # Define the list of allowed commands
-allowed_commands=("verify" "tip" "wesaylexentrycount" "lexentrycount" "flexprojectid" "flexwritingsystems" "recover" "healthz" "invalidatedircache")
+allowed_commands=("verify" "tip" "tipdate" "wesaylexentrycount" "lexentrycount" "flexprojectid" "flexwritingsystems" "recover" "healthz" "invalidatedircache")
 
 # Get the project code and command name from the URL
 IFS='/' read -ra PATH_SEGMENTS <<< "$PATH_INFO"
@@ -78,6 +78,10 @@ case $command_name in
         chg tip --template '{node}'
         ;;
 
+    tipdate)
+        chg tip --template '{date|hgdate}'
+        ;;
+
     verify)
         # Env var PYTHONUNBUFFERED required for commands like verify and recover, so that output can stream back to the project page
         export PYTHONUNBUFFERED=1