OH4.3.0-SNAPSHOT Blockly log not working (debug and trace)

Setup, Configuration and Use Scripts & Rules
, ,
1

Hi All

I am running the following SNAPSHOT version:

openHAB 4.3.0 Build #4197

While trying to debug a Blockly Rule with logging statements I discovered that logging does not seem to be working for debug and trace levels.

I am using a rule as follows (very simple):

image

Which produces:

console.debug('****************************************Test Log Debug has run');

This produces no output at all (I have set the loglevel as follows:

log:set DEBUG org.openhab.automation.script.ui.Log_Debug

If I use the same command for info, error and warn I can see the output, so only seems to be an issue with debug and trace.

I can work around with the lower levels - was jsut surpised to see these not working as all my rules with loggin have them set to debug

Thanks
Mark

2

Are you certain the logger name is correct? The “Log_Debug” part doesn’t look right but I don’t do much Blockly to know off the top of my head. But I would just set something higher in the hierarchy to DEBUG level, such as org.openhab.automation.script. That will apply to everything at that level and below.

3

Thanks Rich - Yes, I am pretty configent that it is correct. Using:

log:set WARN org.openhab.automation.script.ui.SunSynk_Date_Time_Change

and
image

console.warn('****************************************Test Log Debug has run');

Produces:

17:27:09.790 [WARN ] [org.openhab.automation.script        ] - ****************************************Test Log Debug has run

However

log:set DEBUG org.openhab.automation.script.ui.SunSynk_Date_Time_Change

With:
image

console.debug('****************************************Test Log Debug has run');

Produces nothing in the logs.

17:29:51.884 [INFO ] [openhab.event.RuleUpdatedEvent       ] - Rule 'Log_Debug' has been updated.
17:29:53.027 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_UPS_LastUpdate' changed from 2024-07-26T17:29:51.000+0200 to 2024-07-26T17:29:53.000+0200
17:29:53.027 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_UPS_Voltage' changed from 233.9 V to 233.7 V
17:29:53.027 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_Watt' changed from 41.16 W to 60.87 W
17:29:53.028 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_LastUpdate' changed from 2024-07-26T17:29:51.000+0200 to 2024-07-26T17:29:53.000+0200
17:29:53.028 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_Voltage' changed from 233.9 V to 233.7 V
17:29:53.187 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Shelly_UNI_Garage_Voltage' changed from 13.79 V to 13.86 V
17:29:53.833 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_Watt' changed from 60.87 W to 66.07 W
17:29:53.834 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_ReactiveWatt' changed from 0 W to 511.57 W
17:29:53.834 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_PowerFactor' changed from 0.07 to 0.13
17:29:53.870 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'openHABServer_CPULoad' changed from 19.3 % to 15 %
17:29:54.044 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_UPS_LastUpdate' changed from 2024-07-26T17:29:53.000+0200 to 2024-07-26T17:29:54.000+0200
17:29:54.045 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_LastUpdate' changed from 2024-07-26T17:29:53.000+0200 to 2024-07-26T17:29:54.000+0200
17:29:55.879 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'openHABServer_MemoryUsed' changed from 86.8 to 86.9
17:29:55.881 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'openHABServer_CPULoad' changed from 15 % to 14 %
17:29:55.894 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ParadoxpanelEVO192_Date' changed from 2024-07-26T18:26:17.000+0200 to 2024-07-26T18:26:22.000+0200
17:29:55.894 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ParadoxpanelEVO192_Voltage' changed from 16.96470588235294 V to 16.742352941176474 V
17:29:56.013 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_UPS_LastUpdate' changed from 2024-07-26T17:29:54.000+0200 to 2024-07-26T17:29:56.000+0200
17:29:56.014 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_UPS_Voltage' changed from 233.7 V to 233.5 V
17:29:56.014 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_Watt' changed from 66.07 W to 55.96 W
17:29:56.014 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_LastUpdate' changed from 2024-07-26T17:29:54.000+0200 to 2024-07-26T17:29:56.000+0200
17:29:56.015 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_Voltage' changed from 233.7 V to 233.5 V
17:29:56.248 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Shelly_UNI_Garage_Voltage' changed from 13.86 V to 13.79 V
17:29:56.859 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_UPS_Voltage' changed from 233.5 V to 233.6 V
17:29:56.859 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_Watt' changed from 55.96 W to 61.1 W
17:29:56.860 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_ReactiveWatt' changed from 511.57 W to 532 W
17:29:56.860 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_Voltage' changed from 233.5 V to 233.6 V
17:29:56.860 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_PowerFactor' changed from 0.13 to 0.11
17:29:57.888 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'openHABServer_MemoryUsed' changed from 86.9 to 86.8
17:29:57.890 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'openHABServer_CPULoad' changed from 14 % to 13.3 %
17:29:59.308 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Shelly_UNI_Garage_Voltage' changed from 13.79 V to 13.83 V
17:29:59.882 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_UPS_Voltage' changed from 233.6 V to 233.9 V
17:29:59.882 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_UPS_LastUpdate' changed from 2024-07-26T17:29:56.000+0200 to 2024-07-26T17:29:59.000+0200
17:29:59.883 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_Watt' changed from 61.1 W to 67.6 W
17:29:59.883 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_ReactiveWatt' changed from 532 W to 502.1 W
17:29:59.883 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_Voltage' changed from 233.6 V to 233.9 V
17:29:59.883 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_PowerFactor' changed from 0.11 to 0.13
17:29:59.884 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ShellyEM_MAINS_LastUpdate' changed from 2024-07-26T17:29:56.000+0200 to 2024-07-26T17:29:59.000+0200
17:29:59.899 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'openHABServer_CPULoad' changed from 13.3 % to 13.4 %

And the same with trace

However your suggestion of:

log:set DEBUG org.openhab.automation.script

Does work?

17:37:22.768 [DEBUG] [org.openhab.automation.script        ] - ****************************************Test Log Debug has run

But the following does not:

log:set DEBUG org.openhab.automation.script.ui
4

That test doesn’t really tell you anything because the default log level is INFO meaning all INFO, WARN, and ERROR level logs will be shown. If you log out at the INFO level and it doesn’t show up then that would show that you’ve set the log level correctly.

But notice this part: [org.openhab.automation.script ] of the log statement. That’s the logger name. You need to set org.openhab.automation.script to DEBUG. Anything after that doesn’t do anything meaning the “ui.SunSynk_Date_Time_Change” part is causing the log setting to do nothing.

Of course it wouldn’t. The default level is INFO which doesn’t show DEBUG anyway.

TRACE is the lowest level of logging. If you don’t set the level to TRACE you won’t see any TRACE level logs.

The levels work like this:

  • TRACE: shows all logging regardless of the level
  • DEBUG: shows all logging except for TRACE
  • INFO: the default, shows all logging except for DEBUG and TRACE
  • WARN: only shows WARN and ERROR level logs
  • ERROR: only shows ERROR level logs
5

Thanks Rich. Sorry to admit that I have been caught by this before, but as usual you have pointed me in the right direction.

It seems that the logging has changed between

openHAB 4.2.0.M2

Milestone Build

and

openHAB 4.3.0

Build #4197

With OH 4.2.0.M2 the logging for a rule looks like:

19:54:35.512 [DEBUG] [.openhab.automation.script.ui.ZZ_Test] - *** Test Log has Run ***

so the command:

log:set DEBUG org.openhab.automation.script.ui.ZZ_Test

works and shows the correct DEBUG logging for the specified rule.

and with OH 4.3.0.SNAPSHOT:

20:00:24.040 [INFO ] [org.openhab.automation.script        ] - ****************************************Test Log Debug has run

So the .ui.<SCRIPT NAME> is no longer shown/logged.

I guess this explains why the syntax that worked in 4.2.0.M2 no longer works in 4.3.0.SNAPSHOT.

Is this a bug? Or an intentional change?

Thanks
Mark

6

I’m not aware of any changes to logger names so can’t say if there was a change that as deliberate or not. I’m not sure where the logger name is controlled. I always set my own logger name in rules.

I do know that “org.openhab.automation.script” used to be the default a long time ago before I started using my own logger names. Maybe they went back to that?

I’m not sure where to file the issue, assuming there is an issue here. Maybe openhab-js. If not there I imagine it would be openhab-core.

1 Like
7

I have opened an issue at OH 4.3.0-SNAPHOST logger name changed. No longer able to set logger level per rule · Issue #366 · openhab/openhab-js · GitHub