Logging for script execution, including duration

api/src/org/labkey/api/assay/transform/DataTransformService.java

@@ -157,6 +157,11 @@ public TransformResult transformAndValidate(
 
                         bindings.put(ExternalScriptEngine.WORKING_DIRECTORY, scriptDir.toNioPathForWrite().toString());
                         bindings.put(ExternalScriptEngine.SCRIPT_PATH, scriptFile.toNioPathForRead().toFile().getAbsolutePath());
+                        bindings.put(ExternalScriptEngine.INVOCATION_LABEL, "transform protocol=" + context.getProtocol().getRowId()
+                                + " name='" + context.getProtocol().getName() + "'"
+                                + " operation=" + operation.name()
+                                + " script='" + scriptFile.getName() + "'"
+                                + " container=" + context.getContainer().getPath());
 
                         Map<String, String> paramMap = new HashMap<>();
 

api/src/org/labkey/api/reports/ExternalScriptEngine.java

@@ -80,6 +80,9 @@ public class ExternalScriptEngine extends AbstractScriptEngine implements LabKey
     /** Timeout in seconds. */
     public static final String TIMEOUT = "external.script.engine.timeout";
 
+    /** Caller-supplied identity for the invocation log; the engine knows the duration but not which report or assay design it ran for. */
+    public static final String INVOCATION_LABEL = "external.script.engine.invocationLabel";
+
     public static final String DEFAULT_WORKING_DIRECTORY = "ExternalScript";
     private static final Pattern scriptCmdPattern = Pattern.compile("'([^']+)'|\\\"([^\\\"]+)\\\"|(^[^\\s]+)|(\\s[^\\s^'^\\\"]+)");
 
@@ -110,7 +113,14 @@ public boolean isBinary(FileLike file)
     }
 
     @Override
-    public Object eval(String script, ScriptContext context) throws ScriptException
+    public final Object eval(String script, ScriptContext context) throws ScriptException
+    {
+        // final so every engine in this hierarchy is timed from one place; subclasses override evalScript()
+        return ScriptInvocationLog.time(getClass().getSimpleName(), ScriptInvocationLog.label(context),
+                () -> evalScript(script, context));
+    }
+
+    protected Object evalScript(String script, ScriptContext context) throws ScriptException
     {
         List<String> extensions = getFactory().getExtensions();
 
@@ -139,6 +149,7 @@ protected Object eval(FileLike scriptFile, ScriptContext context) throws ScriptE
             int exitCode = runProcess(context, pb, output, timeout, TimeUnit.SECONDS);
             if (exitCode != 0)
             {
+                ScriptInvocationLog.nonZeroExit(getClass().getSimpleName(), ScriptInvocationLog.label(context), exitCode);
                 throw new ScriptException("An error occurred when running the script '" + scriptFile.getName() + "', exit code: " + exitCode + ".\n" + output);
             }
             else
@@ -384,6 +395,7 @@ protected int runProcess(ScriptContext context, LabKeyProcessBuilder pb, StringB
 
                         String msg = "Process killed after exceeding timeout of " + timeout + " " + timeoutUnit.name().toLowerCase() + "\n";
                         output.append(msg);
+                        ScriptInvocationLog.timedOut(getClass().getSimpleName(), ScriptInvocationLog.label(context), timeout, timeoutUnit);
                         if (writer != null)
                             writer.write(msg);
                     }

api/src/org/labkey/api/reports/ScriptInvocationLog.java

@@ -0,0 +1,83 @@
+/*
+ * 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.api.reports;
+
+import org.apache.logging.log4j.Logger;
+import org.jetbrains.annotations.Nullable;
+import org.labkey.api.util.logging.LogHelper;
+
+import javax.script.ScriptContext;
+import javax.script.ScriptException;
+import java.util.concurrent.TimeUnit;
+
+/**
+ * Start/completion/duration logging for external script invocations. Separate class so it gets its own logger
+ * category, enabling timing without the engines' unrelated debug output, and so the non-ExternalScriptEngine
+ * paths can share it. Messages are key=value to keep log analysis parser-free.
+ */
+public final class ScriptInvocationLog
+{
+    private static final Logger LOG = LogHelper.getLogger(ScriptInvocationLog.class, "R and Python script invocation start, completion, and duration");
+
+    private ScriptInvocationLog()
+    {
+    }
+
+    public interface ScriptBody<T>
+    {
+        T run() throws ScriptException;
+    }
+
+    /**
+     * The caller's INVOCATION_LABEL binding, or null if the caller didn't set one.
+     */
+    @Nullable
+    public static String label(ScriptContext context)
+    {
+        Object label = context == null ? null : context.getAttribute(ExternalScriptEngine.INVOCATION_LABEL, ScriptContext.ENGINE_SCOPE);
+        return label == null ? null : String.valueOf(label);
+    }
+
+    /**
+     * Start is DEBUG because it only matters for diagnosing a hang, where a start with no completion is the sole evidence.
+     */
+    public static <T> T time(String engine, @Nullable String label, ScriptBody<T> body) throws ScriptException
+    {
+        LOG.debug("script start engine={} label={}", engine, label);
+        long start = System.currentTimeMillis();
+        try
+        {
+            T result = body.run();
+            LOG.info("script done engine={} label={} durationMs={}", engine, label, start);
+            return result;
+        }
+        catch (ScriptException | RuntimeException e)
+        {
+            LOG.warn("script failed engine={} label={} durationMs={} error={}", engine, label, start, e.getMessage());
+            throw e;
+        }
+    }
+
+    public static void timedOut(String engine, @Nullable String label, long timeout, TimeUnit unit)
+    {
+        LOG.warn("script timeout engine={} label={} timeout={} unit={}", engine, label, timeout, unit.name().toLowerCase());
+    }
+
+    public static void nonZeroExit(String engine, @Nullable String label, int exitCode)
+    {
+        LOG.warn("script exit engine={} label={} exitCode={}", engine, label, exitCode);
+    }
+}

api/src/org/labkey/api/reports/report/ExternalScriptEngineReport.java

@@ -344,6 +344,10 @@ protected Object runScript(ScriptEngine engine, ViewContext context, List<ParamR
         {
             Bindings bindings = engine.getBindings(ScriptContext.ENGINE_SCOPE);
             bindings.put(ExternalScriptEngine.WORKING_DIRECTORY, getReportDirFileLike(context.getContainer().getId()).toNioPathForWrite().toString());
+            bindings.put(ExternalScriptEngine.INVOCATION_LABEL, "report id=" + getDescriptor().getReportId()
+                    + " type=" + getType()
+                    + " name='" + getDescriptor().getReportName() + "'"
+                    + " container=" + context.getContainer().getPath());
 
             Map<String, String> paramMap = new HashMap<>();
             DataTransformService.get().addStandardParameters(null, context.getContainer(), null, session.getApiKey(), paramMap);

api/src/org/labkey/api/reports/report/r/RScriptEngine.java

@@ -87,7 +87,7 @@ protected FileLike prepareScriptFile(String script, ScriptContext context, List<
     }
 
     @Override
-    public Object eval(String script, ScriptContext context) throws ScriptException
+    protected Object evalScript(String script, ScriptContext context) throws ScriptException
     {
         List<String> extensions = getFactory().getExtensions();
 

api/src/org/labkey/api/reports/report/r/RserveScriptEngine.java

@@ -290,7 +290,7 @@ protected void copyWorkingDirectoryFromRemote(RConnection rconn) throws IOExcept
 
 
     @Override
-    public Object eval(String script, ScriptContext context) throws ScriptException
+    protected Object evalScript(String script, ScriptContext context) throws ScriptException
     {
         List<String> extensions = getFactory().getExtensions();
         RConnection rconn = null;

pipeline/src/org/labkey/pipeline/api/ScriptTaskImpl.java

@@ -170,6 +170,9 @@ else if (factory._scriptPath != null)
                 bindings.put(ExternalScriptEngine.SCRIPT_PATH, scriptFile.toNioPathForRead().toFile().toString());
 
             bindings.put(ExternalScriptEngine.WORKING_DIRECTORY, _wd.getDir().toNioPathForRead().toString());
+            bindings.put(ExternalScriptEngine.INVOCATION_LABEL, "pipeline task=" + _factory.getId()
+                    + " job=" + getJob().getJobGUID()
+                    + " container=" + container.getPath());
 
             // Thread the timeout option through to the external script engine
             if (_factory.getTimeout() != null && _factory.getTimeout() > 0)