Difference in openhab.log OH2 <-> OH3, Thing statusInfo not logged in OH3 openhab.log

Hi,

here my problem:

  • same Chromecast Audio Group created as Thing in OH2 and OH3 (autodiscovery in OH3 finds the audio group with the same identifier as in OH2)
  • simple jython rule that prints log message when the state of the Thing changes
  • Rule writes log message in obenhab.log in OH2 but not in OH3

I have no explanation for this. How can I achieve these log messages in openhab.log in OH3 as well?

Details:

OH2 jython rule:

from core.rules import rule
from core.triggers import when
from core.log import logging, LOG_PREFIX
from org.eclipse.smarthome.core.thing import ThingUID

LOG = logging.getLogger("{}.{}".format(LOG_PREFIX, rules_filename))

@rule("ChromecastAudioGroupEG1 Thing changed Status")
@when("Thing chromecast:audiogroup:d2746188-7fd8-463b-b0db-fe980cdc9918 changed")
def ChromecastAudioGroupEG1_Thing_changed_Status(event):
	LOG.info("ChromecastAudioGroupEG1 Thing - changed Status, now {}".format(event.statusInfo.status))

OH2 openhab.log:

...
2021-02-19 17:10:37.093 [INFO ] [jsr223.jython.util.py  ] - ChromecastAudioGroupEG1 Thing - changed Status, now OFFLINE
2021-02-19 17:10:42.375 [INFO ] [jsr223.jython.util.py  ] - ChromecastAudioGroupEG1 Thing - changed Status, now ONLINE
2021-02-19 17:10:47.445 [INFO ] [jsr223.jython.util.py  ] - ChromecastAudioGroupEG1 Thing - changed Status, now OFFLINE
2021-02-19 17:10:52.516 [INFO ] [jsr223.jython.util.py  ] - ChromecastAudioGroupEG1 Thing - changed Status, now ONLINE
2021-02-19 17:10:57.582 [INFO ] [jsr223.jython.util.py  ] - ChromecastAudioGroupEG1 Thing - changed Status, now OFFLINE
2021-02-19 17:11:02.667 [INFO ] [jsr223.jython.util.py  ] - ChromecastAudioGroupEG1 Thing - changed Status, now ONLINE
2021-02-19 17:11:07.829 [INFO ] [jsr223.jython.util.py  ] - ChromecastAudioGroupEG1 Thing - changed Status, now OFFLINE
...

OH2 event.log:

...
2021-02-19 17:10:39.758 [smarthome.event.ThingStatusInfoChangedEvent       ] - 'chromecast:audiogroup:d2746188-7fd8-463b-b0db-fe980cdc9918' changed from OFFLINE to ONLINE
...

OH3 jython rule:

from core.rules import rule
from core.triggers import when
from core.log import logging, LOG_PREFIX
from org.openhab.core.thing import ThingUID

LOG = logging.getLogger("{}.{}".format(LOG_PREFIX, rules_filename))

@rule("ChromecastAudioGroupEG1 Thing changed Status")
@when("Thing chromecast:audiogroup:d2746188-7fd8-463b-b0db-fe980cdc9918 changed")
def ChromecastAudioGroupEG1_Thing_changed_Status(event):
	LOG.info("ChromecastAudioGroupEG1 Thing - changed Status {}".format(event.statusInfo.status))

OH3 openhab.log:

--> nothing about Chromecast Thing!!!!!!

OH3 event.log:

...
2021-02-19 17:10:39.018 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'chromecast:audiogroup:d2746188-7fd8-463b-b0db-fe980cdc9918' changed from OFFLINE (COMMUNICATION_ERROR): Verbindungsaufbau abgelehnt (Connection refused) to ONLINE
...

Default logging level is WARN in OH3 for jython.
Either use log.warn in rule or set the default logging level to INFO.

Thanks for the hint, you were right, I overlooked that …
Nevertheless, there is an inexplicable behavior for me even after changing the log level:

OH3 event.log:

2021-02-23 17:10:43.900 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'chromecast:audiogroup:d2746188-7fd8-463b-b0db-fe980cdc9918' changed from ONLINE to OFFLINE
2021-02-23 17:10:43.903 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'chromecast:audiogroup:d2746188-7fd8-463b-b0db-fe980cdc9918' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): Interrupted while waiting for response
2021-02-23 17:10:53.898 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'chromecast:audiogroup:d2746188-7fd8-463b-b0db-fe980cdc9918' changed from OFFLINE (COMMUNICATION_ERROR): Interrupted while waiting for response to OFFLINE (COMMUNICATION_ERROR): Verbindungsaufbau abgelehnt (Connection refused)

Why is there a message in event.log (OH3) and why is the rule not triggering (so there is no message in openhab.log either)?

In OH2 there was a corresponding message in the event.log and the rule was triggered, then the corresponding message also appears in openhab.log.

OH3 obenhab.log:

--> nothing about Chromecast Thing!!!!!!

OH3 and OH2 jython Rule:

@rule("ChromecastAudioGroupEG1 Thing changed Status")
@when("Thing chromecast:audiogroup:d2746188-7fd8-463b-b0db-fe980cdc9918 changed")
def ChromecastAudioGroupEG1_Thing_changed_Status(event):
	thing_status = things.get(ThingUID('chromecast:audiogroup:d2746188-7fd8-463b-b0db-fe980cdc9918')).status
	LOG.info("ChromecastAudioGroupEG1 Thing - changed Status {}".format(thing_status))

OH2 obenhab.log:

...
2021-02-23 17:10:43.896 [INFO ] [jsr223.jython.util.py       ] - ChromecastAudioGroupEG1 Thing - changed Status, now OFFLINE
2021-02-23 17:10:49.232 [INFO ] [jsr223.jython.util.py       ] - ChromecastAudioGroupEG1 Thing - changed Status, now OFFLINE
....

OH2 event.log:

...
2021-02-23 17:10:43.894 [smarthome.event.ThingStatusInfoChangedEvent       ] - 'chromecast:audiogroup:d2746188-7fd8-463b-b0db-fe980cdc9918' changed from ONLINE to OFFLINE
2021-02-23 17:10:43.895 [smarthome.event.ThingStatusInfoChangedEvent       ] - 'chromecast:audiogroup:d2746188-7fd8-463b-b0db-fe980cdc9918' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): Interrupted while waiting for response
...

There are obviously differences here!?

... OH 3.0.1

openhab> log:list
Logger                                             │ Level
───────────────────────────────────────────────────┼──────
ROOT                                               │ WARN
javax.jmdns                                        │ ERROR
javax.mail                                         │ ERROR
jsr223                                             │ INFO
openhab.event                                      │ INFO
openhab.event.AddonEvent                           │ ERROR
openhab.event.InboxUpdatedEvent                    │ ERROR
openhab.event.ItemAddedEvent                       │ ERROR
openhab.event.ItemChannelLinkAddedEvent            │ ERROR
openhab.event.ItemChannelLinkRemovedEvent          │ ERROR
openhab.event.ItemRemovedEvent                     │ ERROR
openhab.event.ItemStateEvent                       │ ERROR
openhab.event.RuleAddedEvent                       │ ERROR
openhab.event.RuleRemovedEvent                     │ ERROR
openhab.event.RuleStatusInfoEvent                  │ ERROR
openhab.event.StartlevelEvent                      │ ERROR
openhab.event.ThingAddedEvent                      │ ERROR
openhab.event.ThingRemovedEvent                    │ ERROR
openhab.event.ThingStatusInfoEvent                 │ ERROR
openhab.event.ThingUpdatedEvent                    │ ERROR
org.apache.cxf.jaxrs.sse.SseEventSinkImpl          │ ERROR
org.apache.karaf.jaas.modules.audit                │ INFO
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR
org.apache.karaf.shell.ssh.SshUtils                │ ERROR
org.apache.karaf.shell.support                     │ OFF
org.apache.sshd                                    │ WARN
org.eclipse.lsp4j                                  │ OFF
org.jupnp                                          │ ERROR
org.openhab                                        │ INFO
org.openhab.core.automation                        │ INFO
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime                  │ OFF
su.litvak.chromecast.api.v2.Channel                │ ERROR
openhab>

But …you’re showing us, it’s right there in your OH2 events.log

I have adjusted my post, it was a bit unclear …

you have to use log.warn in the rule

LOG.warn("ChromecastAudi....