`console.log()` outputs 4 times instead of 1

ErikDB · March 3, 2026, 7:56am

I’m trying to run a “Script” (i.e. a Rule that’s found under “Scripts” in the “Settings” menu) from a “Rule”, but my first test case revealed something strange. (I had originally mentioned this problem here, but it’s actually a different problem than what that topic was about.)

In any case, something unexpected happened. This is the “Script” (as a first step, I’m running the “Script” from another “Script”, and plan to migrate to a “Rule” in a next step) I ran:

rules.runRule("tado-API-script")

This is the “script” (i.e. rule) with Script ID tado-API-script:

console.log("hallo");

This is the output:

19:58:58.317 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo
19:58:58.318 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo
19:58:58.319 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo
19:58:58.320 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo

Why does it run 4 times?

@JustinG suggested posting the “complete yaml config”, but I don’t know how to retrieve that from “Scripts”? There are no tabs in the “Script” window:

JustinG · March 3, 2026, 2:05pm

My apologies, I thought the first code was in a rule with triggers and wanted to see if there were any that might possibly get triggered 4 times in a row.

I just tested again and putting runRule in a script and calling another script does not result in 4 iterations. There must be something more specific going on in your case.

Have you changed any of the jsscripting add-on settings away from their defaults?

ErikDB · March 3, 2026, 2:28pm

Not that I’m aware of:

I now tried setting the log level to TRACE, but when trying to save, this is logged:

15:27:41.472 [ERROR] [.internal.JSONResponseExceptionMapper] - Unexpected exception occurred while processing REST request.
java.lang.RuntimeException: Unable to set level for logger
        at org.apache.karaf.log.core.internal.LogServiceLog4j2XmlImpl.setLevel(LogServiceLog4j2XmlImpl.java:139) ~[?:?]
        at org.apache.karaf.log.core.internal.LogServiceImpl.setLevel(LogServiceImpl.java:114) ~[?:?]
        at org.openhab.core.karaf.internal.LoggerResource.putLoggers(LoggerResource.java:106) ~[?:?]
        at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:580) ~[?:?]
        at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:179) ~[bundleFile:3.6.8]
        at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) ~[bundleFile:3.6.8]
        at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:201) ~[bundleFile:3.6.8]
        at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:104) ~[bundleFile:3.6.8]
        at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59) ~[bundleFile:3.6.8]
        at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96) ~[bundleFile:3.6.8]
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307) ~[bundleFile:3.6.8]
        at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) ~[bundleFile:3.6.8]
        at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:267) ~[bundleFile:3.6.8]
        at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) ~[bundleFile:3.6.8]
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) ~[bundleFile:3.6.8]
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) ~[bundleFile:3.6.8]
        at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:225) ~[bundleFile:3.6.8]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:304) ~[bundleFile:3.6.8]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPut(AbstractHTTPServlet.java:234) ~[bundleFile:3.6.8]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:520) ~[bundleFile:4.0.4]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:279) ~[bundleFile:3.6.8]
        at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedServlet.service(OsgiInitializedServlet.java:102) ~[bundleFile:?]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1656) ~[bundleFile:9.4.57.v20241219]
        at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:113) ~[bundleFile:?]
        at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doHandle(PaxWebServletHandler.java:334) ~[bundleFile:?]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[bundleFile:9.4.57.v20241219]
        at org.ops4j.pax.web.service.jetty.internal.PrioritizedHandlerCollection.handle(PrioritizedHandlerCollection.java:96) ~[bundleFile:?]
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:722) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[bundleFile:9.4.57.v20241219]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[bundleFile:9.4.57.v20241219]
        at java.lang.Thread.run(Thread.java:1583) [?:?]
Caused by: org.w3c.dom.DOMException: NOT_FOUND_ERR: An attempt is made to reference a node in a context where it does not exist.
        at com.sun.org.apache.xerces.internal.dom.ParentNode.internalInsertBefore(ParentNode.java:364) ~[?:?]
        at com.sun.org.apache.xerces.internal.dom.ParentNode.insertBefore(ParentNode.java:286) ~[?:?]
        at org.apache.karaf.log.core.internal.LogServiceLog4j2XmlImpl.insertIndented(LogServiceLog4j2XmlImpl.java:168) ~[?:?]
        at org.apache.karaf.log.core.internal.LogServiceLog4j2XmlImpl.setLevel(LogServiceLog4j2XmlImpl.java:121) ~[?:?]
        ... 59 more

… and the debug level is stil at INFO.

sihui · March 3, 2026, 2:39pm

I tried this on my installation (5.2.0.M1) and it is set correctly:

2026-03-03 15:36:42.955 [DEBUG] [enhab.automation.jsscripting.openhab-js.rules] - Extracted event payload [object Object]
2026-03-03 15:36:42.981 [DEBUG] [penhab.automation.jsscripting.openhab-js.time] - toZDT: Parsing string 00:00

There must be something odd going on with your logging settings …

Edit:

Did you change your log4j2.xml?

ErikDB · March 3, 2026, 2:44pm

Yes, I’ve added many custom Appenders and Loggers over the years. It looks like the “UI setting” expects to find a node somewhere, and I probably moved it or put something else in front or behind it?

sihui · March 3, 2026, 2:56pm

I would save your current log4j2.xml and download the original file from github to test.

rlkoshak · March 3, 2026, 3:04pm

While we are modifying logger settings, change the openhab.event.RuleStatusInfoEvent to INFO level, and you will see an entry in events.log when a rule starts running and when it stops running.

That can prove informative, in this case it tells us whether your manually run script is running four times, or whether it’s just the called script that is running four times.

ErikDB · March 3, 2026, 3:19pm

Apparently neither:

16:17:32.343 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - scratchpad updated: RUNNING
16:17:32.346 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - tado-API-script updated: RUNNING
16:17:32.347 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo
16:17:32.350 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo
16:17:32.352 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo
16:17:32.355 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo
16:17:32.358 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - tado-API-script updated: IDLE
16:17:32.361 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - scratchpad updated: IDLE

For full disclosure (although I can’t believe it makes a difference), this is tado-API-script:

/*
var pythoninvenv = '/var/lib/openhab/bin/python/tado-manual-control/venv/bin/python';
var pythonscript = '/var/lib/openhab/bin/python/tado-manual-control/tado-manual-control.py';

function callPython(command) {
  var pythonOutput = actions.Exec.executeCommandLine(time.Duration.ofSeconds(3), command);
  console.log("python output = "+pythonOutput);
}
*/
//callPython(command);
//console.log(command);
console.log("hallo");

If I just run tado-API-script, the output also comes four times:

16:20:10.682 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - tado-API-script updated: RUNNING
16:20:10.683 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo
16:20:10.685 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo
16:20:10.687 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo
16:20:10.688 [INFO ] [tion.jsscripting.rule.tado-API-script] - hallo
16:20:10.689 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - tado-API-script updated: IDLE

So the issue is not with calling tado-API-script, but with the actual rule itself…