Somehow in the recent weeks I’ve encountered a mysterious issue. Most all of my rules are configured using .rules files with exception of two that I have created directly within the web interface. I now have a ‘phantom’ ON command being sent to my kitchen lights around sunset that is not defined anywhere in any of the rules. Does anyone have any idea of a way I can try to track down the source of this call? I’ve attempted to delete the item in hopes that I could catch the error and have that give me some info but it didn’t give me any sort of rule name - just the unknown item error. I’m currently on openHAB 3.1.0.M2 running within docker though this began when I was on 3.1.0.M1.
If there is any sort of extra debugging to turn on that I could see the source of command I’d appreciate it.
That should enable the logging of Rule events in events.log. Then you can see which rule starts running immediately before the Item gets its command. That won’t necessarily prove that it’s that rule but it certainly is a place to look.
It’ll only log the rule ID though so there will still need to be some research. I think (and rossko57 can correct me) that the ID for rules in a .rules file follow <filename>_<#> format where <#> is a one up number with the first rule in the file being 1 and second one 2 and so on.
Presumably the Item is called by name in your rule? If so you should be able to search for it using grep. Navigate to your $OH_CONF/rules folder and run
grep MyItemName *.rules
Obviously replace MyItemName with the name of the troublesome Item.
Then run from $OH_USERDATA/jsondb
grep MyItemName automation_rules.json
If either returns a hit, open the file and search for MyItemName to find where it’s used.
If none of those find your Item then one of two things is happening:
The command is coming from somewhere else.
The Item is not referenced directly. Perhaps the Item name is constructed based on the name of some other Item (e.g. Associated Items Design Pattern).
If it’s 2 you might be able to figure it out by searching for parts of the Item name.
All - Don’t see anything out of usual in the event.log of the rules running around the time but here is a copy of the error when the item was removed. Anything useful here? I realized I haven’t cleared the cache folder if you think that would help? Though I have done an upgrade and the issue persisted - I think that clears the cache on its own right?
2021-03-23 19:29:58.429 [ERROR] [ypes.access.impl.AbstractClassMirror] - resource is empty: java:/Objects/org.openhab.core.model.script.actions.Semantics
java.lang.IllegalStateException: null
at org.eclipse.xtext.common.types.access.impl.AbstractClassMirror.getEObject(AbstractClassMirror.java:95) [bundleFile:?]
at org.eclipse.xtext.common.types.access.TypeResource.getEObject(TypeResource.java:95) [bundleFile:?]
at org.eclipse.emf.ecore.resource.impl.ResourceSetImpl.getEObject(ResourceSetImpl.java:223) [bundleFile:?]
at org.eclipse.xtext.common.types.access.impl.IndexedJvmTypeAccess.getIndexedJvmType(IndexedJvmTypeAccess.java:80) [bundleFile:?]
at org.eclipse.xtext.common.types.access.impl.IndexedJvmTypeAccess.getIndexedJvmType(IndexedJvmTypeAccess.java:70) [bundleFile:?]
at org.eclipse.xtext.common.types.access.reflect.ReflectionTypeProvider.findTypeByClass(ReflectionTypeProvider.java:146) [bundleFile:?]
at org.eclipse.xtext.common.types.access.reflect.ReflectionTypeProvider.findTypeByName(ReflectionTypeProvider.java:88) [bundleFile:?]
at org.eclipse.xtext.common.types.util.TypeReferences.findDeclaredType(TypeReferences.java:256) [bundleFile:?]
at org.eclipse.xtext.common.types.util.TypeReferences.findDeclaredType(TypeReferences.java:233) [bundleFile:?]
at org.eclipse.xtext.xbase.scoping.batch.ImplicitlyImportedFeatures.getTypes(ImplicitlyImportedFeatures.java:82) [bundleFile:?]
at org.eclipse.xtext.xbase.scoping.batch.ImplicitlyImportedFeatures.getExtensionClasses(ImplicitlyImportedFeatures.java:76) [bundleFile:?]
at org.eclipse.xtext.xbase.scoping.batch.XbaseBatchScopeProvider.newSession(XbaseBatchScopeProvider.java:121) [bundleFile:?]
at org.eclipse.xtext.xbase.typesystem.internal.DefaultReentrantTypeResolver.resolve(DefaultReentrantTypeResolver.java:164) [bundleFile:?]
at org.eclipse.xtext.xbase.typesystem.internal.DefaultReentrantTypeResolver.reentrantResolve(DefaultReentrantTypeResolver.java:140) [bundleFile:?]
at org.eclipse.xtext.xbase.typesystem.internal.CachingBatchTypeResolver$LazyResolvedTypes.resolveTypes(CachingBatchTypeResolver.java:81) [bundleFile:?]
at org.eclipse.xtext.xbase.typesystem.internal.CachingBatchTypeResolver$2.process(CachingBatchTypeResolver.java:58) [bundleFile:?]
at org.eclipse.xtext.xbase.typesystem.internal.CachingBatchTypeResolver$2.process(CachingBatchTypeResolver.java:54) [bundleFile:?]
at org.eclipse.xtext.util.concurrent.IUnitOfWork$Void.exec(IUnitOfWork.java:38) [bundleFile:?]
at org.eclipse.xtext.util.OnChangeEvictingCache.execWithoutCacheClear(OnChangeEvictingCache.java:135) [bundleFile:?]
at org.eclipse.xtext.xbase.typesystem.internal.CachingBatchTypeResolver.doResolveTypes(CachingBatchTypeResolver.java:54) [bundleFile:?]
at org.eclipse.xtext.xbase.typesystem.internal.AbstractBatchTypeResolver.resolveTypes(AbstractBatchTypeResolver.java:70) [bundleFile:?]
at org.eclipse.xtext.xbase.resource.BatchLinkingService.resolveBatched(BatchLinkingService.java:72) [bundleFile:?]
at org.eclipse.xtext.xbase.resource.BatchLinkableResource.resolveLazyCrossReferences(BatchLinkableResource.java:166) [bundleFile:?]
at org.eclipse.xtext.EcoreUtil2.resolveLazyCrossReferences(EcoreUtil2.java:505) [bundleFile:?]
at org.eclipse.xtext.build.IncrementalBuilder$InternalStatefulIncrementalBuilder.lambda$launch$2(IncrementalBuilder.java:266) [bundleFile:?]
at com.google.common.collect.Iterators$6.transform(Iterators.java:783) [bundleFile:?]
at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:47) [bundleFile:?]
at com.google.common.collect.FluentIterable.copyInto(FluentIterable.java:791) [bundleFile:?]
at org.eclipse.xtext.build.ClusteringStorageAwareResourceLoader.executeClustered(ClusteringStorageAwareResourceLoader.java:69) [bundleFile:?]
at org.eclipse.xtext.build.BuildContext.executeClustered(BuildContext.java:55) [bundleFile:?]
at org.eclipse.xtext.build.IncrementalBuilder$InternalStatefulIncrementalBuilder.launch(IncrementalBuilder.java:259) [bundleFile:?]
at org.eclipse.xtext.build.IncrementalBuilder.build(IncrementalBuilder.java:404) [bundleFile:?]
at org.eclipse.xtext.build.IncrementalBuilder.build(IncrementalBuilder.java:386) [bundleFile:?]
at org.eclipse.xtext.ide.server.ProjectManager.doBuild(ProjectManager.java:106) [bundleFile:?]
at org.eclipse.xtext.ide.server.ProjectManager.doInitialBuild(ProjectManager.java:97) [bundleFile:?]
at org.eclipse.xtext.ide.server.BuildManager.doInitialBuild(BuildManager.java:164) [bundleFile:?]
at org.eclipse.xtext.ide.server.WorkspaceManager.refreshWorkspaceConfig(WorkspaceManager.java:233) [bundleFile:?]
at org.eclipse.xtext.ide.server.WorkspaceManager.initialize(WorkspaceManager.java:170) [bundleFile:?]
at org.eclipse.xtext.ide.server.LanguageServerImpl.lambda$initialize$0(LanguageServerImpl.java:225) [bundleFile:?]
at org.eclipse.xtext.ide.server.concurrent.WriteRequest.run(WriteRequest.java:50) [bundleFile:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
Just wanted to follow up to see if there was anywhere else I could check - today at around 1900 I moved all .rules files out of the rules folder and still at 1950 I saw in the logs that the kitchen got an “ON” command. I don’t use any UI rules - I had a few that I played with but deleted them. Any suggestions? I presume that had something been in a timer that moving the file out of the folder would have removed it’s context right?
Is that with or without the Item removed? Please don’t be secretive here - I doubt it tells us anything at all but you describe seeing things in the logs that you don’t show us.
Ye-es, but that would not of itself blow up the timer code - it has to attempt to use the context.
A simple long-running timer with only code someItem.sendCommand(ON) will happily survive the deletion of its parent rule file and execute on time.
More likely, an orphaned timer will successfully do some stuff before it encounters some code it can’t manage - you would have a tell-tale error in your openhab.log at that time i.e. at a similar time to your unexpected command.
No timers survive a reboot, for elimination purposes.
Follow profiles allow state changes to umm spoof commands to channels directly. The effect of that is to produce a command to a real device or service - but I am sure this does not appear in the events.log at all. The resulting state change might. So long as you see unexpected commands in your events.log this can be ruled out.
Some bindings - example KNX, MQTT - can produce OH commands instead of the usual state updates,in response to incoming data. There’s no way to detect that as a source, apart from inspection of the binding configuration or possibly TRACE log of the binding. Note these incoming commands would have to be via a channel i.e. explicitly linked to an Item by configuring.
Of course anybody anywhere (but probably a UI) can attempt to send a command to any arbitrary Item via REST API. The give-away would be a HTTP-ish error logged when it tried to do that on a non-existent Item.
Hi Rossko - thanks for the response. Not trying to secretive at all - promise. My most recent testing was with the item still being valid. I already attempted a test in which I removed the item and pasted a copy of the resultant openhab.log error message. This doesn’t seem to provide any meaningful output in my eyes at least. I will attempt this evening to do a full restart of the system after removing the .rules files so I can fully resolve if this is coming from a rules file timer - I’m just very purplexed because no where do I send the ON command to this item nor do I do any sort of item lookup/ send command on this item. I do have some other groupings of items that I use the item lookup command for to find an item based on its name and send commands that way - but those item names are all markedly different / nothing is ‘not working’ that would account for the misfire. I’ll post an update after my next test.
Just wanted to post that I was able to track this down - after trying various scenarios
Removed all Rules files (confirmed not a rules file/timer)
Blocked all incoming network traffic (confirmed not rest interface)
I Finally tracked this down - turns out there was somehow an alexa routine created that was turning this light on at sunset - which makes sense as it was tracking the sunset time.
Thanks for all of the help looking at this - the extra logging you guys provided is certainly good to know!
