diff --git a/api/src/org/labkey/api/assay/transform/DataTransformService.java b/api/src/org/labkey/api/assay/transform/DataTransformService.java index 70d6886b2bb..4e421e95efc 100644 --- a/api/src/org/labkey/api/assay/transform/DataTransformService.java +++ b/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 paramMap = new HashMap<>(); diff --git a/api/src/org/labkey/api/reports/ExternalScriptEngine.java b/api/src/org/labkey/api/reports/ExternalScriptEngine.java index 64a79d1a439..851dbb50b76 100644 --- a/api/src/org/labkey/api/reports/ExternalScriptEngine.java +++ b/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 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); } diff --git a/api/src/org/labkey/api/reports/ScriptInvocationLog.java b/api/src/org/labkey/api/reports/ScriptInvocationLog.java new file mode 100644 index 00000000000..b83683c37ef --- /dev/null +++ b/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 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 time(String engine, @Nullable String label, ScriptBody 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); + } +} diff --git a/api/src/org/labkey/api/reports/report/ExternalScriptEngineReport.java b/api/src/org/labkey/api/reports/report/ExternalScriptEngineReport.java index 1cab97ee43a..a394302d5a0 100644 --- a/api/src/org/labkey/api/reports/report/ExternalScriptEngineReport.java +++ b/api/src/org/labkey/api/reports/report/ExternalScriptEngineReport.java @@ -344,6 +344,10 @@ protected Object runScript(ScriptEngine engine, ViewContext context, List