[jsscripting] Improve logging on JS error (openhab#16445)

* [jsscripting] Improve script error logging * [jsscripting] Suppress some warnings * [jsscripting] Throw ISE instead of RE * [jsscripting] Minor null annotation improvements Include fileName or ruleUID or transformation UID in the logger name used by the logged error stack trace. Signed-off-by: Florian Hotze <[email protected]>
matchews · Feb 24, 2024 · df7a57a · df7a57a
1 parent c9f8324
commit df7a57a
Show file tree

Hide file tree

Showing 2 changed files with 44 additions and 12 deletions.
diff --git a/...src/main/java/org/openhab/automation/jsscripting/internal/DebuggingGraalScriptEngine.java b/...src/main/java/org/openhab/automation/jsscripting/internal/DebuggingGraalScriptEngine.java
@@ -15,6 +15,7 @@
 import javax.script.Invocable;
 import javax.script.ScriptEngine;
 
+import org.eclipse.jdt.annotation.Nullable;
 import org.graalvm.polyglot.PolyglotException;
 import org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable;
 import org.slf4j.Logger;
@@ -28,22 +29,52 @@
 class DebuggingGraalScriptEngine<T extends ScriptEngine & Invocable & AutoCloseable>
         extends InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable<T> {
 
-    private static final Logger STACK_LOGGER = LoggerFactory
-            .getLogger("org.openhab.automation.script.javascript.stack");
+    private static final String SCRIPT_TRANSFORMATION_ENGINE_IDENTIFIER = "openhab-transformation-script-";
+
+    private @Nullable Logger logger;
 
     public DebuggingGraalScriptEngine(T delegate) {
         super(delegate);
     }
 
     @Override
     public Exception afterThrowsInvocation(Exception e) {
+        if (logger == null) {
+            initializeLogger();
+        }
+
         Throwable cause = e.getCause();
         if (cause instanceof IllegalArgumentException) {
-            STACK_LOGGER.error("Failed to execute script:", e);
+            logger.error("Failed to execute script:", e);
         }
         if (cause instanceof PolyglotException) {
-            STACK_LOGGER.error("Failed to execute script:", cause);
+            logger.error("Failed to execute script:", cause);
         }
         return e;
     }
+
+    /**
+     * Initializes the logger.
+     * This cannot be done on script engine creation because the context variables are not yet initialized.
+     * Therefore, the logger needs to be initialized on the first use after script engine creation.
+     */
+    private void initializeLogger() {
+        Object fileName = delegate.getContext().getAttribute("javax.script.filename");
+        Object ruleUID = delegate.getContext().getAttribute("ruleUID");
+        Object ohEngineIdentifier = delegate.getContext().getAttribute("oh.engine-identifier");
+
+        String identifier = "stack";
+        if (fileName != null) {
+            identifier = fileName.toString().replaceAll("^.*[/\\\\]", "");
+        } else if (ruleUID != null) {
+            identifier = ruleUID.toString();
+        } else if (ohEngineIdentifier != null) {
+            if (ohEngineIdentifier.toString().startsWith(SCRIPT_TRANSFORMATION_ENGINE_IDENTIFIER)) {
+                identifier = ohEngineIdentifier.toString().replaceAll(SCRIPT_TRANSFORMATION_ENGINE_IDENTIFIER,
+                        "transformation.");
+            }
+        }
+
+        logger = LoggerFactory.getLogger("org.openhab.automation.script.javascript." + identifier);
+    }
 }
diff --git a/...src/main/java/org/openhab/automation/jsscripting/internal/OpenhabGraalJSScriptEngine.java b/...src/main/java/org/openhab/automation/jsscripting/internal/OpenhabGraalJSScriptEngine.java
@@ -72,24 +72,24 @@ public class OpenhabGraalJSScriptEngine
         extends InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable<GraalJSScriptEngine> {
 
     private static final Logger LOGGER = LoggerFactory.getLogger(OpenhabGraalJSScriptEngine.class);
-    private static Source GLOBAL_SOURCE;
+    private static final Source GLOBAL_SOURCE;
     static {
         try {
             GLOBAL_SOURCE = Source.newBuilder("js", getFileAsReader("node_modules/@jsscripting-globals.js"),
                     "@jsscripting-globals.js").cached(true).build();
         } catch (IOException e) {
-            throw new RuntimeException("Failed to load @jsscripting-globals.js", e);
+            throw new IllegalStateException("Failed to load @jsscripting-globals.js", e);
         }
     }
 
-    private static Source OPENHAB_JS_SOURCE;
+    private static final Source OPENHAB_JS_SOURCE;
     static {
         try {
             OPENHAB_JS_SOURCE = Source
                     .newBuilder("js", getFileAsReader("node_modules/@openhab-globals.js"), "@openhab-globals.js")
                     .cached(true).build();
         } catch (IOException e) {
-            throw new RuntimeException("Failed to load @openhab-globals.js", e);
+            throw new IllegalStateException("Failed to load @openhab-globals.js", e);
         }
     }
     private static final String OPENHAB_JS_INJECTION_CODE = "Object.assign(this, require('openhab'));";
@@ -134,7 +134,7 @@ public class OpenhabGraalJSScriptEngine
     private final JSRuntimeFeatures jsRuntimeFeatures;
 
     // these fields start as null because they are populated on first use
-    private String engineIdentifier;
+    private @Nullable String engineIdentifier;
     private @Nullable Consumer<String> scriptDependencyListener;
 
     private boolean initialized = false;
@@ -239,10 +239,11 @@ protected void beforeInvocation() {
         }
 
         // these are added post-construction, so we need to fetch them late
-        this.engineIdentifier = (String) ctx.getAttribute(CONTEXT_KEY_ENGINE_IDENTIFIER);
-        if (this.engineIdentifier == null) {
+        String localEngineIdentifier = (String) ctx.getAttribute(CONTEXT_KEY_ENGINE_IDENTIFIER);
+        if (localEngineIdentifier == null) {
             throw new IllegalStateException("Failed to retrieve engine identifier from engine bindings");
         }
+        engineIdentifier = localEngineIdentifier;
 
         ScriptExtensionAccessor scriptExtensionAccessor = (ScriptExtensionAccessor) ctx
                 .getAttribute(CONTEXT_KEY_EXTENSION_ACCESSOR);
@@ -262,7 +263,7 @@ protected void beforeInvocation() {
 
         // Wrap the "require" function to also allow loading modules from the ScriptExtensionModuleProvider
         Function<Function<Object[], Object>, Function<String, Object>> wrapRequireFn = originalRequireFn -> moduleName -> scriptExtensionModuleProvider
-                .locatorFor(delegate.getPolyglotContext(), engineIdentifier).locateModule(moduleName)
+                .locatorFor(delegate.getPolyglotContext(), localEngineIdentifier).locateModule(moduleName)
                 .map(m -> (Object) m).orElseGet(() -> originalRequireFn.apply(new Object[] { moduleName }));
         delegate.getBindings(ScriptContext.ENGINE_SCOPE).put(REQUIRE_WRAPPER_NAME, wrapRequireFn);
         delegate.put("require", wrapRequireFn.apply((Function<Object[], Object>) delegate.get("require")));