Changing from 4.2.2 -> 4.3.0M4: Rules engine not yet started

chincheta0815 · November 15, 2024, 9:16am

Hej there,

for some reason (e.g. the matter addon) I change my version from 4.2.2 to 4.3.0.

I made a backup of my configuration of OH 4.2.2 and restored it into OH 4.3.0M4.
(Probably that was stupid?)

Anyways, after starting OH 4.3.0M4 the “Rules engine is not yet started”. NO UI-made rules is fired at all. The log shows, that the triggeres are received from e.g. a Hue System.
But: The trigger does not start the rule and the rule engine says it’s not started yet.

Before, with 4.2.2 all rules already worked as expected.

Did I do something wrong with my “brute force” update or is there something else in the deep that I have to think of???

hmerk · November 15, 2024, 9:28am

Please post your startup log (text, no screenshot), otherwise it is hard to help.

chincheta0815 · November 15, 2024, 9:40am

Okay. Just to make sure: You need the openhab.log file, right? Any specific log levels for some entities?

hmerk · November 15, 2024, 9:41am

Correct. At first, no specific log levels needed.

chincheta0815 · November 15, 2024, 9:43am

2024-11-15 10:38:56.102 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 4.2.2 (Milestone Build)
2024-11-15 10:38:57.721 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
2024-11-15 10:38:57.744 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '<topSecret>'.
2024-11-15 10:38:57.749 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'de_DE'.
2024-11-15 10:39:23.980 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2024-11-15 10:39:59.090 [WARN ] [tv.internal.handler.SamsungTvHandler] - 192.168.47.214: Art Mode MAY NOT BE SUPPORTED on Frame TV's after 2021 model year
2024-11-15 10:39:59.243 [WARN ] [ty.util.ssl.SslContextFactory.config] - Trusting all certificates configured for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.250 [WARN ] [ty.util.ssl.SslContextFactory.config] - No Client EndPointIdentificationAlgorithm configured for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.261 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.267 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.272 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.279 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.283 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_DHE_RSA_WITH_AES_256_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.286 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_DHE_DSS_WITH_AES_256_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.294 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_DHE_RSA_WITH_AES_128_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.296 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_DHE_DSS_WITH_AES_128_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.304 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_RSA_WITH_AES_256_GCM_SHA384 enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.314 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_RSA_WITH_AES_128_GCM_SHA256 enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.333 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_RSA_WITH_AES_256_CBC_SHA256 enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.335 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_RSA_WITH_AES_128_CBC_SHA256 enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.339 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_RSA_WITH_AES_256_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.342 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_RSA_WITH_AES_256_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.345 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_RSA_WITH_AES_128_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.347 [WARN ] [ty.util.ssl.SslContextFactory.config] - Weak cipher suite TLS_RSA_WITH_AES_128_CBC_SHA enabled for Client@74cdaab1[provider=null,keyStore=null,trustStore=null]
2024-11-15 10:39:59.440 [INFO ] [ternal.service.SmartThingsApiService] - 192.168.47.214: SSE Creating Smartthings Subscription
2024-11-15 10:40:00.310 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:device:001788fffe2d3081:35269ef3-0c87-4c10-8a91-acad951ac54e' to inbox.
2024-11-15 10:40:00.363 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:device:001788fffe2d3081:451c50da-8a38-4352-bd7c-36ee49b396d0' to inbox.
2024-11-15 10:40:00.421 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:device:001788fffe2d3081:5e47fc26-9308-4c70-8f13-f5694a1a72b2' to inbox.
2024-11-15 10:40:00.463 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:device:001788fffe2d3081:65248445-fd84-40c9-af52-b50b930065f8' to inbox.
2024-11-15 10:40:00.536 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:device:001788fffe2d3081:725623ab-310b-4665-be50-cb21f05ca8d8' to inbox.
2024-11-15 10:40:00.606 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:device:001788fffe2d3081:72d478d8-6933-4507-8faf-0f05bfb53d4f' to inbox.
2024-11-15 10:40:00.683 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:device:001788fffe2d3081:88d649ad-ec2e-4738-b0cb-daea913b42b7' to inbox.
2024-11-15 10:40:00.737 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:device:001788fffe2d3081:bfdbf521-5b81-450c-95d2-39366b4a2d0f' to inbox.
2024-11-15 10:40:00.798 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:device:001788fffe2d3081:c4c5affa-cd00-4a10-9cd0-44399a38f9eb' to inbox.
2024-11-15 10:40:00.881 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:device:001788fffe2d3081:ef297154-4715-4c6a-95f4-4a486fda201e' to inbox.
2024-11-15 10:40:00.939 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:device:001788fffe2d3081:f649d214-f81b-4d8f-a465-ad0a28b46c1c' to inbox.
2024-11-15 10:40:01.192 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:room:001788fffe2d3081:1aa90107-299f-4e92-8171-9a8b2a6ec882' to inbox.
2024-11-15 10:40:01.236 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:room:001788fffe2d3081:1c9ef6ed-950f-485d-99c5-bfd79947d06c' to inbox.
2024-11-15 10:40:01.279 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:room:001788fffe2d3081:3f77e5f9-40e1-4d9e-b6d5-4011c02c8a98' to inbox.
2024-11-15 10:40:01.305 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:room:001788fffe2d3081:5a9ed93a-7a8a-41d7-a3b7-887a517ba251' to inbox.
2024-11-15 10:40:01.341 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:room:001788fffe2d3081:e2731251-68f7-4106-a21b-4da55b1b1f99' to inbox.
2024-11-15 10:40:01.386 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:room:001788fffe2d3081:e968de3c-15e3-442a-9c15-06a6ae6405a0' to inbox.
2024-11-15 10:40:01.529 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'hue:zone:001788fffe2d3081:fb287411-c024-46d8-aacc-527048ed7bb3' to inbox.
2024-11-15 10:40:01.679 [INFO ] [ungtv.internal.protocol.WebSocketArt] - 192.168.47.214: Art Mode has been renabled on Frame TV's >= 2022
2024-11-15 10:40:18.116 [INFO ] [.matter.internal.bridge.MatterBridge] - No devices found to register with bridge, not starting bridge

Asking me: I do not see anything suspicious…

hmerk · November 15, 2024, 9:58am

Is this all ???

chincheta0815 · November 15, 2024, 10:09am

That is all until it it up…

Unfortunately, yes.
That’s why I was confused: Something does not work, but there is no line telling me in the first place.

I did once a

log:set TRACE org.openhab.core.automation.internal
log:set TRACE org.openhab.core.automation.internal.module.handler

then I got the message the the Rules engine is note yet started (and a lot more info).

The I made openhab more silent again with

log:set INFO org.openhab.core.automation.internal
log:set INFO org.openhab.core.automation.internal.module.handler

Do you need a more talkative log?

AndrewFG · November 15, 2024, 10:16am

I would suggest to disable the matter bridge thing and try another restart. (Then if that still fails then disable the hue bridge thing… etc.)

chincheta0815 · November 15, 2024, 10:37am

I did remove the Matter addon and other bindings.
Now I have just bindings that were there last time it worked with 4.2.2
For the HueBinding: That is actually one trigger I need… And the trigger is registered but it does not start the rule…

AndrewFG · November 15, 2024, 10:49am

The last entry in your log is about the matter bridge, and there are no entries after that, so I would suspect that that last entry was related to the rules engine not loading.

chincheta0815 · November 15, 2024, 10:50am

From the logs with

log:set TRACE org.openhab.core.automation.internal
log:set TRACE org.openhab.core.automation.internal.module.handler

I get:

11:46:08.484 [TRACE] [le.handler.ChannelEventTriggerHandler] - ->FILTER: 1000:null
11:46:08.488 [TRACE] [le.handler.ChannelEventTriggerHandler] - Received Event: Source: null Topic: openhab/channels/hue:device:001788fffe2d3081:42fc921e-e4f7-4517-89c1-882e5cab98be:button-last-event/triggered Type: ChannelTriggeredEvent  Payload: {"event":"1000","channel":"hue:device:001788fffe2d3081:42fc921e-e4f7-4517-89c1-882e5cab98be:button-last-event"}
11:46:08.493 [DEBUG] [re.automation.internal.RuleEngineImpl] - Rule engine not yet started - not executing rule '4b3d448e69',
11:46:08.493 [DEBUG] [re.automation.internal.RuleEngineImpl] - The trigger '1' of rule '4b3d448e69' is triggered.
11:46:09.491 [TRACE] [le.handler.ChannelEventTriggerHandler] - ->FILTER: 1002:null
11:46:09.497 [TRACE] [le.handler.ChannelEventTriggerHandler] - Received Event: Source: null Topic: openhab/channels/hue:device:001788fffe2d3081:42fc921e-e4f7-4517-89c1-882e5cab98be:button-last-event/triggered Type: ChannelTriggeredEvent  Payload: {"event":"1002","channel":"hue:device:001788fffe2d3081:42fc921e-e4f7-4517-89c1-882e5cab98be:button-last-event"}
11:46:09.505 [DEBUG] [re.automation.internal.RuleEngineImpl] - The trigger '1' of rule '4b3d448e69' is triggered.
11:46:09.507 [DEBUG] [re.automation.internal.RuleEngineImpl] - Rule engine not yet started - not executing rule '4b3d448e69',
11:46:10.497 [TRACE] [le.handler.ChannelEventTriggerHandler] - ->FILTER: 1000:null
11:46:10.502 [TRACE] [le.handler.ChannelEventTriggerHandler] - ->FILTER: 1002:null
11:46:10.502 [TRACE] [le.handler.ChannelEventTriggerHandler] - Received Event: Source: null Topic: openhab/channels/hue:device:001788fffe2d3081:42fc921e-e4f7-4517-89c1-882e5cab98be:button-last-event/triggered Type: ChannelTriggeredEvent  Payload: {"event":"1000","channel":"hue:device:001788fffe2d3081:42fc921e-e4f7-4517-89c1-882e5cab98be:button-last-event"}
11:46:10.509 [DEBUG] [re.automation.internal.RuleEngineImpl] - The trigger '1' of rule '4b3d448e69' is triggered.
11:46:10.511 [DEBUG] [re.automation.internal.RuleEngineImpl] - Rule engine not yet started - not executing rule '4b3d448e69',
11:46:10.513 [TRACE] [le.handler.ChannelEventTriggerHandler] - Received Event: Source: null Topic: openhab/channels/hue:device:001788fffe2d3081:42fc921e-e4f7-4517-89c1-882e5cab98be:button-last-event/triggered Type: ChannelTriggeredEvent  Payload: {"event":"1002","channel":"hue:device:001788fffe2d3081:42fc921e-e4f7-4517-89c1-882e5cab98be:button-last-event"}
11:46:10.523 [DEBUG] [re.automation.internal.RuleEngineImpl] - The trigger '1' of rule '4b3d448e69' is triggered.
11:46:10.524 [DEBUG] [re.automation.internal.RuleEngineImpl] - Rule engine not yet started - not executing rule '4b3d448e69',

This seems to me, that the trigger is registered. OH even knows, which trigger it is, e.g. trigger ‘1’. That is all correct.

But the rule:

logInfo('TEST','TEST')

is not showning up.

chincheta0815 · November 15, 2024, 11:03am

Back on 4.2.2 it works!?
So is there a bug/change in the 4.3.0.M4 milestone or is ti simply a wrong update?

chincheta0815 · November 15, 2024, 1:27pm

I got it working again and also with 4.3.0.M4:
The solutiont was using the update script provide in the $OH_HOME/openhab/runtime/bin…

And now it runs smoothly…

Thanks a lot. Although you guy did not directly tell what to do your questions made me think in the correct direction.