Automated tests for script execution logging

src/org/labkey/test/tests/DataReportsTest.java

@@ -26,15 +26,18 @@
 import org.labkey.test.SortDirection;
 import org.labkey.test.TestProperties;
 import org.labkey.test.TestTimeoutException;
+import org.labkey.test.WebDriverWrapper;
 import org.labkey.test.categories.Daily;
 import org.labkey.test.categories.Reports;
 import org.labkey.test.pages.reports.ScriptReportPage;
 import org.labkey.test.util.ApiPermissionsHelper;
 import org.labkey.test.util.DataRegionTable;
 import org.labkey.test.util.Ext4Helper;
+import org.labkey.test.util.Log4jUtils;
 import org.labkey.test.util.LogMethod;
 import org.labkey.test.util.PermissionsHelper;
 import org.labkey.test.util.RReportHelper;
+import org.labkey.test.util.ScriptInvocationLogHelper;
 import org.openqa.selenium.WebElement;
 
 import java.io.File;
@@ -533,6 +536,19 @@ public void testRReportShowSource()
         goToProjectHome();
     }
 
+    @Test
+    public void testScriptInvocationLogging() throws Exception
+    {
+        final String reportName = "Invocation logging report";
+        final String sentinel = "invocation logging sentinel";
+
+        Log4jUtils.resetLogMark();
+        String output = _rReportHelper.createAndRunRReport(reportName, "print('" + sentinel + "')", false);
+        assertTrue("R report didn't execute. Console output was:\n" + output, output.contains(sentinel));
+
+        ScriptInvocationLogHelper.assertScriptLogged((WebDriverWrapper) this, "done", "report id=", reportName);
+    }
+
     /**create an R report from the dataset page
      *
      * @param name name of script

src/org/labkey/test/tests/assay/AssayTransformWarningTest.java

@@ -24,15 +24,18 @@
 import org.labkey.test.Locators;
 import org.labkey.test.TestFileUtils;
 import org.labkey.test.TestTimeoutException;
+import org.labkey.test.WebDriverWrapper;
 import org.labkey.test.categories.Assays;
 import org.labkey.test.categories.Daily;
 import org.labkey.test.components.assay.AssayConstants;
 import org.labkey.test.pages.ReactAssayDesignerPage;
 import org.labkey.test.pages.files.WebDavPage;
 import org.labkey.test.params.FieldDefinition;
 import org.labkey.test.util.DataRegionTable;
+import org.labkey.test.util.Log4jUtils;
 import org.labkey.test.util.QCAssayScriptHelper;
 import org.labkey.test.util.RReportHelper;
+import org.labkey.test.util.ScriptInvocationLogHelper;
 
 import java.io.File;
 import java.util.Arrays;
@@ -190,6 +193,33 @@ public void testRTransformWarning()
         assertTextPresent("RWarned");
     }
 
+    @Test
+    public void testRTransformInvocationLogging() throws Exception
+    {
+        String assayName = "transformInvocationLoggingR";
+        String importData = "ParticipantId\nRLogged";
+        String runName = "R transform logging run";
+
+        // copy the script to a distinct name to avoid upload collisions with the other test methods
+        File loggingRScript = TestFileUtils.writeTempFile("transformLogging.R", TestFileUtils.getFileContents(R_TRANSFORM_SCRIPT));
+
+        _assayHelper.createAssayDesign("General", assayName)
+                .addTransformScript(loggingRScript, true)
+                .clickFinish();
+
+        clickAndWait(Locator.linkWithText(assayName));
+        clickButton("Import Data");
+        clickButton("Next");
+        setFormElement(ASSAY_NAME_FIELD_LOCATOR, runName);
+        setFormElement(AssayConstants.TEXT_AREA_DATA_COLLECTOR_LOCATOR, importData);
+
+        Log4jUtils.resetLogMark();
+        clickButton("Save and Finish");
+        assertElementPresent(Locators.labkeyError.containing("Inline warning from R transform."));
+
+        ScriptInvocationLogHelper.assertScriptLogged((WebDriverWrapper) this, "done", "transform protocol=", "operation=INSERT", assayName);
+    }
+
     @Test
     public void testRTransformUpdateWarning() throws Exception
     {
@@ -223,13 +253,16 @@ public void testRTransformUpdateWarning() throws Exception
         // edit the result, expect warning
         clickAndWait(Locator.linkWithText(runName));
         DataRegionTable table = new DataRegionTable("Data", this);
+        Log4jUtils.resetLogMark();
         table.clickEditRow(0)
                 .setField("comment", "commented")
                 .submit();
 
         // note: we currently do not support warnings on update; Issue 52299 tracks this
         // for now, expect warning-generating script events to show up as errors
         assertTextPresent("An error occurred when running the script 'transformWarnUpdate.R', exit code: 1.");
+
+        ScriptInvocationLogHelper.assertScriptLogged((WebDriverWrapper) this, "failed", "transform protocol=", updateWarnRScript.getName());
     }
 
     @Test

src/org/labkey/test/util/Log4jUtils.java

@@ -104,4 +104,13 @@ public static void showLogSinceMark(WebDriverWrapper driver) throws IOException
     {
         driver.beginAt(WebTestHelper.buildURL("admin", "showPrimaryLogSinceMark"));
     }
+
+    /** The primary log since the last {@link #resetLogMark()}, for tests that assert on what the server logged. */
+    @LogMethod(quiet = true)
+    public static String getLogSinceMark(WebDriverWrapper driver) throws IOException
+    {
+        SimpleHttpRequest request = new SimpleHttpRequest(WebTestHelper.buildURL("admin", "showPrimaryLogSinceMark"));
+        request.copySession(driver.getDriver());
+        return request.getResponse().getResponseBody();
+    }
 }

src/org/labkey/test/util/ScriptInvocationLogHelper.java

@@ -0,0 +1,62 @@
+/*
+ * Copyright (c) 2026 LabKey Corporation
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.labkey.test.util;
+
+import org.labkey.test.WebDriverWrapper;
+
+import java.io.IOException;
+import java.util.Arrays;
+import java.util.regex.Matcher;
+import java.util.regex.Pattern;
+
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertTrue;
+import static org.junit.Assert.fail;
+
+/**
+ * Assertions against the org.labkey.api.reports.ScriptInvocationLog category, which records duration and a
+ * caller-supplied label for every external script the server runs.
+ */
+public abstract class ScriptInvocationLogHelper
+{
+    private static final Pattern SCRIPT_COMPLETION = Pattern.compile(
+            "script (?<outcome>done|failed) engine=\\S+ label=(?<label>.*?) durationMs=(?<durationMs>\\d+)(?<trailing>.*)");
+
+    /**
+     * Assert that a script logged the given outcome since the last {@link Log4jUtils#resetLogMark()} with a label
+     * containing every fragment.
+     */
+    public static void assertScriptLogged(WebDriverWrapper test, String outcome, String... labelFragments) throws IOException
+    {
+        String log = Log4jUtils.getLogSinceMark(test);
+        Matcher matcher = SCRIPT_COMPLETION.matcher(log);
+
+        while (matcher.find())
+        {
+            String label = matcher.group("label");
+            if (outcome.equals(matcher.group("outcome")) && Arrays.stream(labelFragments).allMatch(label::contains))
+            {
+                long durationMs = Long.parseLong(matcher.group("durationMs"));
+                assertTrue("Logged durationMs doesn't look like an elapsed time: " + durationMs,
+                        durationMs < 1_000_000L && durationMs > 0);
+                assertEquals("'script " + outcome + "' line should end at the duration", "", matcher.group("trailing").trim());
+                return;
+            }
+        }
+
+        fail("No 'script " + outcome + "' line with a label containing " + Arrays.toString(labelFragments) + ". Log since mark:\n" + log);
+    }
+}