search

openhab / openhab-core

Core framework of openHAB
https://www.openhab.org/
Eclipse Public License 2.0
929 stars 428 forks source link

[Automation] EventSubscriber is not registered on startup for rules created in Paper UI #636

Closed 5iver closed 5 years ago

5iver commented 5 years ago

I'm seeing this in a test environment running S1549 (and S1534), but there was also at least one report in the forum, but that was on OH 2.4.0. After an OH restart, Paper UI rules can be triggered, and the log says they execute, but their actions don't run.

2019-03-05 12:37:54.031 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-05 12:37:54.031 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - The rule '38e28c16-4594-418d-a5f5-2758d876b471' is executed.
2019-03-05 12:37:54.032 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent

By editing a rule and saving it, without making any changes, the rules will work again. I'm experiencing this every time I restart OH S1549, on a test machine with only one Item and no bindings. When the rules are saved, the EventSubscriber is registered, but this does not occur after an OH startup.

2019-03-07 07:04:37.875 [DEBUG] [org.openhab.core.automation] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=421, service.bundleid=199, service.scope=singleton, event.topics=smarthome/items/Virtual_Switch_1/*} - org.openhab.core.automation
5iver commented 5 years ago

I spent some time looking into this, and have some more details. When disabling a rule, it is added to automation_rules_disabled.json. When reenabling it, it is removed. I found that after disabling all rules and restarting OH, the entries remained in automation_rules_disabled.json and the rules were not disabled, and all rules worked properly! After that, disabling/enabling a rule dis not modify automation_rules_disabled.json.

This leads me to think that there is some issue in the serialization/deserialization of the JSON rule files. But since this behavior does not occur in earlier builds, it seems possibly related to the ESH reintegration or the changes made in order to use maven/bnd.

Here are some startup logs from when they worked...

2019-03-22 19:50:38.873 [DEBUG] [org.openhab.core.automation] - ServiceEvent REGISTERED - {org.openhab.core.automation.RuleManager, org.eclipse.smarthome.core.common.registry.RegistryChangeListener}={service.id=361, service.bundleid=209, service.scope=bundle, component.name=org.openhab.core.automation.internal.RuleEngineImpl, component.id=200} - org.openhab.core.automation
2019-03-22 19:50:38.882 [DEBUG] [org.eclipse.smarthome.core.common.registry.AbstractRegistry] - Provider "org.openhab.core.automation.internal.provider.file.ModuleTypeFileProviderWatcher" has been added.
2019-03-22 19:50:38.883 [DEBUG] [org.eclipse.smarthome.core.common.registry.AbstractRegistry] - Provider "org.openhab.core.automation.internal.module.provider.AnnotatedActionModuleTypeProvider" has been added.
2019-03-22 19:50:38.884 [DEBUG] [org.eclipse.smarthome.core.common.registry.AbstractRegistry] - Provider "org.openhab.core.automation.internal.provider.ModuleTypeResourceBundleProvider" has been added.
2019-03-22 19:50:38.909 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleAddedEvent
2019-03-22 19:50:38.910 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:38.910 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleAddedEvent
2019-03-22 19:50:38.911 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:38.911 [DEBUG] [org.eclipse.smarthome.core.common.registry.AbstractRegistry] - Provider "org.openhab.core.automation.ManagedRuleProvider" has been added.
2019-03-22 19:50:38.911 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleAddedEvent
2019-03-22 19:50:38.913 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:38.914 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - ModuleHandlerFactory added CoreModuleHandlerFactory
2019-03-22 19:50:38.915 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - ModuleHandlerFactory added TimerModuleHandlerFactory
2019-03-22 19:50:38.915 [DEBUG] [org.openhab.core.automation.internal.RuleEngineImpl] - ModuleHandlerFactory added AnnotatedActionModuleTypeProvider
2019-03-22 19:50:38.918 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:38.919 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:38.919 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:38.920 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:38.920 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:38.920 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:38.921 [DEBUG] [org.eclipse.smarthome.storage.json.internal.JsonStorage] - Opened Json storage file at '/run/media/scott/Data/openhab/openhab/userdata/jsondb/automation_rules_disabled.json'.
2019-03-22 19:50:38.922 [DEBUG] [org.openhab.core.automation] - ServiceEvent REGISTERED - {org.openhab.core.automation.RuleRegistry}={service.id=360, service.bundleid=209, service.scope=bundle, rule.reinitialization.delay=500, component.name=org.openhab.core.automation.internal.RuleRegistryImpl, component.id=202} - org.openhab.core.automation

2019-03-22 19:50:39.518 [DEBUG] [org.glassfish.jersey.server.ApplicationHandler] - Clearing Jersey HK2 caches. Service cache size: 24, reflection cache size: 295.
2019-03-22 19:50:39.543 [INFO ] [org.glassfish.jersey.server.ApplicationHandler] - Jersey application initialized.
Root Resource Classes:
  org.eclipse.smarthome.io.rest.voice.internal.VoiceResource
  org.openhab.core.automation.rest.internal.ModuleTypeResource
  org.openhab.core.automation.rest.internal.TemplateResource
  org.eclipse.smarthome.io.rest.core.internal.binding.BindingResource
  org.openhab.core.automation.rest.internal.RuleResource
  org.eclipse.smarthome.io.rest.core.internal.service.ConfigurableServiceResource
  org.eclipse.smarthome.io.rest.core.internal.thing.ThingTypeResource
  org.eclipse.smarthome.core.id.internal.UUIDResource
  org.eclipse.smarthome.io.rest.internal.resources.RootResource
  org.eclipse.smarthome.io.rest.core.internal.extensions.ExtensionResource
  org.eclipse.smarthome.io.rest.core.internal.profile.ProfileTypeResource
  org.eclipse.smarthome.io.rest.core.internal.discovery.DiscoveryResource
  org.eclipse.smarthome.io.rest.sitemap.internal.SitemapResource
  org.eclipse.smarthome.ui.icon.internal.IconSetResource
  org.eclipse.smarthome.io.rest.core.internal.thing.ThingResource
  org.eclipse.smarthome.io.rest.core.internal.persistence.PersistenceResource
  org.eclipse.smarthome.io.rest.core.internal.link.ItemChannelLinkResource
  org.eclipse.smarthome.io.rest.core.internal.config.ConfigDescriptionResource
  org.eclipse.smarthome.io.rest.core.internal.discovery.InboxResource
  org.eclipse.smarthome.io.rest.core.internal.item.ItemResource
  org.eclipse.smarthome.io.rest.sse.SseResource
  org.eclipse.smarthome.io.rest.core.internal.channel.ChannelTypeResource
Pre-match Filters:
   org.eclipse.smarthome.io.rest.internal.filter.ProxyFilter
Global Request Filters:
   org.eclipse.smarthome.io.rest.internal.filter.SatisfiableResourceFilter
Global Reader Interceptors:
   org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor
Global Writer Interceptors:
   org.glassfish.jersey.server.internal.MappableExceptionWrapperInterceptor
   org.glassfish.jersey.server.internal.JsonWithPaddingInterceptor
Message Body Readers:
   org.eclipse.smarthome.io.rest.core.internal.GsonProvider
   org.glassfish.jersey.message.internal.SourceProvider$SaxSourceReader
   org.glassfish.jersey.message.internal.RenderedImageProvider
   org.glassfish.jersey.message.internal.FormMultivaluedMapProvider
   org.glassfish.jersey.message.internal.BasicTypesMessageProvider
   org.glassfish.jersey.message.internal.ReaderProvider
   org.glassfish.jersey.message.internal.InputStreamProvider
   org.glassfish.jersey.message.internal.StringMessageProvider
   org.glassfish.jersey.message.internal.SourceProvider$StreamSourceReader
   org.glassfish.jersey.message.internal.SourceProvider$DomSourceReader
   org.glassfish.jersey.message.internal.FormProvider
   org.glassfish.jersey.message.internal.ByteArrayProvider
   org.glassfish.jersey.message.internal.DataSourceProvider
   org.glassfish.jersey.message.internal.FileProvider
Message Body Writers:
   org.eclipse.smarthome.io.rest.core.internal.GsonProvider
   org.glassfish.jersey.message.internal.SourceProvider$SourceWriter
   org.glassfish.jersey.message.internal.RenderedImageProvider
   org.glassfish.jersey.message.internal.FormMultivaluedMapProvider
   org.glassfish.jersey.message.internal.BasicTypesMessageProvider
   org.glassfish.jersey.message.internal.ReaderProvider
   org.glassfish.jersey.message.internal.InputStreamProvider
   org.glassfish.jersey.message.internal.StringMessageProvider
   org.glassfish.jersey.message.internal.FormProvider
   org.glassfish.jersey.server.ChunkedResponseWriter
   org.glassfish.jersey.message.internal.ByteArrayProvider
   org.glassfish.jersey.media.sse.OutboundEventWriter
   org.glassfish.jersey.message.internal.DataSourceProvider
   org.glassfish.jersey.message.internal.StreamingOutputProvider
   org.glassfish.jersey.message.internal.FileProvider

2019-03-22 19:50:39.661 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:39.661 [TRACE] [org.openhab.core.automation.module.script.internal.factory.ScriptModuleHandlerFactory] - create 1 -> script.ScriptAction
2019-03-22 19:50:39.664 [TRACE] [org.openhab.core.automation.internal.module.factory.CoreModuleHandlerFactory] - create 2 -> core.ItemStateUpdateTrigger : 7bbe975d-6c05-44d6-91e9-607890ec20eb
2019-03-22 19:50:39.667 [DEBUG] [org.openhab.core.automation] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=407, service.bundleid=209, service.scope=singleton, event.topics=smarthome/items/Virtual_Switch_1/*} - org.openhab.core.automation
2019-03-22 19:50:39.669 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:39.669 [TRACE] [org.openhab.core.automation.module.script.internal.factory.ScriptModuleHandlerFactory] - create 1 -> script.ScriptAction
2019-03-22 19:50:39.669 [TRACE] [org.openhab.core.automation.internal.module.factory.CoreModuleHandlerFactory] - create 2 -> core.ItemStateUpdateTrigger : e716f878-9639-418e-a593-e13dd9efebc1
2019-03-22 19:50:39.669 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:39.671 [DEBUG] [org.openhab.core.automation] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=408, service.bundleid=209, service.scope=singleton, event.topics=smarthome/items/Virtual_Switch_1/*} - org.openhab.core.automation
2019-03-22 19:50:39.672 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:39.672 [TRACE] [org.openhab.core.automation.module.script.internal.factory.ScriptModuleHandlerFactory] - create 2 -> script.ScriptAction
2019-03-22 19:50:39.672 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:39.672 [TRACE] [org.openhab.core.automation.internal.module.factory.CoreModuleHandlerFactory] - create 1 -> core.ItemStateUpdateTrigger : fe65a9b1-950e-4640-bc8c-5332307de545
2019-03-22 19:50:39.673 [DEBUG] [org.openhab.core.automation] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=409, service.bundleid=209, service.scope=singleton, event.topics=smarthome/items/Virtual_Switch_1/*} - org.openhab.core.automation
2019-03-22 19:50:39.674 [TRACE] [org.openhab.core.automation.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2019-03-22 19:50:41.403 [INFO ] [org.ops4j.pax.web.service.internal.HttpServiceFactoryImpl] - Binding bundle: [org.openhab.core.boot_2.5.0.201903160006 [139]] to http service
2019-03-22 19:50:41.405 [DEBUG] [org.ops4j.pax.web.service.internal.HttpServiceStarted] - Creating http service for: org.openhab.core.boot_2.5.0.201903160006 [139]
2019-03-22 19:50:41.406 [DEBUG] [org.ops4j.pax.web.service.internal.HttpServiceProxy] - HttpServiceProxy created for HttpService org.ops4j.pax.web.service.internal.HttpServiceStarted@7a0dab49 for bundle org.openhab.core.boot_2.5.0.201903160006 [139]
2019-03-22 19:50:41.406 [DEBUG] [org.ops4j.pax.web.service.internal.HttpServiceProxy] - Creating a default context
5iver commented 5 years ago

Another piece to the puzzle... you will see the same behavior after opening and saving a working rule. It gets unregistered but never reregistered.

5iver commented 5 years ago

Resolved by #776.