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..3a73c57e13d 100644 --- a/api/src/org/labkey/api/reports/ExternalScriptEngine.java +++ b/api/src/org/labkey/api/reports/ExternalScriptEngine.java @@ -80,11 +80,17 @@ 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^'^\\\"]+)"); private FileLike _workingDirectory; + /** Set when runProcess() kills the script, so the kill's exit code isn't logged as a second, separate failure. */ + private boolean _timedOut; + protected ExternalScriptEngineDefinition _def; protected Writer _originalWriter; @@ -110,7 +116,15 @@ 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() + _timedOut = false; + 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 +153,8 @@ protected Object eval(FileLike scriptFile, ScriptContext context) throws ScriptE int exitCode = runProcess(context, pb, output, timeout, TimeUnit.SECONDS); if (exitCode != 0) { + if (!_timedOut) + 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 +400,8 @@ protected int runProcess(ScriptContext context, LabKeyProcessBuilder pb, StringB String msg = "Process killed after exceeding timeout of " + timeout + " " + timeoutUnit.name().toLowerCase() + "\n"; output.append(msg); + _timedOut = true; + 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..77a0ac55b22 --- /dev/null +++ b/api/src/org/labkey/api/reports/ScriptInvocationLog.java @@ -0,0 +1,94 @@ +/* + * 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; +import java.util.regex.Pattern; + +/** + * 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. 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 static final Pattern LINE_BREAKS = Pattern.compile("[\\r\\n]+"); + + private ScriptInvocationLog() + { + } + + public interface ScriptBody + { + T run() throws ScriptException; + } + + /** + * The caller's INVOCATION_LABEL binding, or null if the caller didn't set one. Labels embed user-supplied report + * and assay design names, so line breaks are collapsed to keep one invocation on one line. + */ + @Nullable + public static String label(ScriptContext context) + { + Object label = context == null ? null : context.getAttribute(ExternalScriptEngine.INVOCATION_LABEL, ScriptContext.ENGINE_SCOPE); + return label == null ? null : LINE_BREAKS.matcher(String.valueOf(label)).replaceAll(" "); + } + + /** + * Start is DEBUG because it only matters for diagnosing a hang, where a start with no completion is the sole evidence. + * The failure line deliberately omits the exception message: for a non-zero exit that message carries the script's + * entire stdout/stderr, which can be huge and can echo the transform session's API key. + */ + public static T time(String engine, @Nullable String label, ScriptBody body) throws ScriptException + { + LOG.debug("script start engine={} label={}", engine, label); + long start = System.nanoTime(); + boolean completed = false; + try + { + T result = body.run(); + completed = true; + return result; + } + finally + { + // finally rather than catch so an Error still logs a duration, which a hang never does + long durationMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start); + if (completed) + LOG.info("script done engine={} label={} durationMs={}", engine, label, durationMs); + else + LOG.warn("script failed engine={} label={} durationMs={}", engine, label, durationMs); + } + } + + 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