[SOLVED] Voice command sometimes is the previous command

monojetski · February 4, 2018, 6:03am

I notice sometimes I get the previous voice command written to the log… Looks to be either my fault or openhab internals.

Previous command is “1”, current command is “hello cats”.
You can see in the logs the command that was passed in was “hello cats”

2018-02-04 15:55:45.743 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@742cb8de[c=0,q=1,[0]=Content@6011a452{HeapByteBufferR@33ca5514[p=272,l=282,c=8192,r=10]={POST /rest/items/...khttp/3.6.0\r\n\r\n<<<hello cats>>>Range: bytes=0-\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}},s=STREAM] addContent Content@6011a452{HeapByteBufferR@33ca5514[p=272,l=282,c=8192,r=10]={POST /rest/items/...khttp/3.6.0\r\n\r\n<<<hello cats>>>Range: bytes=0-\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}

But what was logged is 1.

2018-02-04 15:55:46.161 [INFO ] [pse.smarthome.model.script.Voice.Rec] - VoiceCommand received 1

Test Code

rule "Voice control"
when
	Item VoiceCommand received command
then
	var String command = VoiceCommand.state.toString.toLowerCase
	logInfo("Voice.Rec","VoiceCommand received "+command)
	say(command)
    logInfo("TTS_1", command)
end

LOGS

2018-02-04 15:55:45.740 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@4f99d2ad[c=0,q=1,[0]=EOF,s=STREAM] addContent EOF
2018-02-04 15:55:45.743 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@742cb8de[c=0,q=1,[0]=Content@6011a452{HeapByteBufferR@33ca5514[p=272,l=282,c=8192,r=10]={POST /rest/items/...khttp/3.6.0\r\n\r\n<<<hello cats>>>Range: bytes=0-\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}},s=STREAM] addContent Content@6011a452{HeapByteBufferR@33ca5514[p=272,l=282,c=8192,r=10]={POST /rest/items/...khttp/3.6.0\r\n\r\n<<<hello cats>>>Range: bytes=0-\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}
2018-02-04 15:55:45.768 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Temperature' for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:45.838 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@742cb8de[c=0,q=2,[0]=Content@6011a452{HeapByteBufferR@33ca5514[p=272,l=282,c=8192,r=10]={POST /rest/items/...khttp/3.6.0\r\n\r\n<<<hello cats>>>Range: bytes=0-\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}},s=STREAM] addContent EOF
2018-02-04 15:55:45.865 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Temperature' for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:45.925 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@742cb8de[c=10,q=2,[0]=Content@6011a452{HeapByteBufferR@33ca5514[p=282,l=282,c=8192,r=0]={POST /rest/items/...0\r\n\r\nhello cats<<<>>>Range: bytes=0-\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}},s=STREAM] read 10 from Content@6011a452{HeapByteBufferR@33ca5514[p=282,l=282,c=8192,r=0]={POST /rest/items/...0\r\n\r\nhello cats<<<>>>Range: bytes=0-\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}
2018-02-04 15:55:45.953 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.026 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@742cb8de[c=10,q=1,[0]=EOF,s=STREAM] consumed Content@6011a452{HeapByteBufferR@33ca5514[p=282,l=282,c=8192,r=0]={POST /rest/items/...0\r\n\r\nhello cats<<<>>>Range: bytes=0-\r\n...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}}
2018-02-04 15:55:46.051 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.103 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@742cb8de[c=10,q=0,[0]=null,s=STREAM] consumed EOF
2018-02-04 15:55:46.128 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Luminance' for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.161 [INFO ] [pse.smarthome.model.script.Voice.Rec] - VoiceCommand received 1
2018-02-04 15:55:46.180 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Luminance' for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.226 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.265 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.282 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Battery' for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.300 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Battery' for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.318 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.335 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.352 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Motion' for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.369 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Motion' for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.387 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.404 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.421 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Status' for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.438 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item 'Status' for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.456 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.462 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@3134c347[c=0,q=1,[0]=EOF,s=STREAM] addContent EOF
2018-02-04 15:55:46.473 [ERROR] [ui.internal.items.ItemUIRegistryImpl] - Cannot retrieve item for widget org.eclipse.smarthome.model.sitemap.Group
2018-02-04 15:55:46.555 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@4f99d2ad[c=0,q=1,[0]=EOF,s=STREAM] addContent EOF
2018-02-04 15:55:46.592 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@64d58ced[c=0,q=1,[0]=EOF,s=STREAM] addContent EOF
2018-02-04 15:55:46.594 [DEBUG] [org.eclipse.jetty.server.HttpInput  ] - HttpInputOverHTTP@6b84f398[c=0,q=1,[0]=EOF,s=STREAM] addContent EOF
2018-02-04 15:55:47.260 [INFO ] [eclipse.smarthome.model.script.TTS_1] - 1

Anyone know what I might be doing wrong? or is this a bug. I think it happens more often when I say the commands straight after each other.

hr3 · February 4, 2018, 7:24am

Please post the events.log or log viewer.

monojetski · February 4, 2018, 10:34am

events.log around that time

2018-02-04 15:55:27.053 [ome.event.ItemCommandEvent] - Item 'VoiceCommand' received command 1
2018-02-04 15:55:27.095 [vent.ItemStateChangedEvent] - VoiceCommand changed from hey to 1
2018-02-04 15:55:29.658 [vent.ItemStateChangedEvent] - TiinaPhone_Time changed from 14.0 to 83.0
2018-02-04 15:55:32.619 [vent.ItemStateChangedEvent] - RafRedmiPhone_Time changed from 11.0 to 99.0
2018-02-04 15:55:46.158 [ome.event.ItemCommandEvent] - Item 'VoiceCommand' received command hello cats
2018-02-04 15:55:46.205 [vent.ItemStateChangedEvent] - VoiceCommand changed from 1 to hello cats
2018-02-04 15:56:29.869 [vent.ItemStateChangedEvent] - TiinaPhone_Time changed from 83.0 to 92.0
2018-02-04 15:56:37.682 [vent.ItemStateChangedEvent] - RafRedmiPhone_Time changed from 99.0 to 56.0
2018-02-04 15:57:30.071 [vent.ItemStateChangedEvent] - TiinaPhone_Time changed from 92.0 to 85.0
2018-02-04 15:57:42.885 [vent.ItemStateChangedEvent] - RafRedmiPhone_Time changed from 56.0 to 142.0
2018-02-04 15:58:30.214 [vent.ItemStateChangedEvent] - TiinaPhone_Time changed from 85.0 to 13.0
2018-02-04 15:58:47.999 [vent.ItemStateChangedEvent] - RafRedmiPhone_Time changed from 142.0 to 158.0
2018-02-04 15:59:30.560 [vent.ItemStateChangedEvent] - TiinaPhone_Time changed from 13.0 to 145.0

hr3 · February 4, 2018, 10:49am

I think, the rule was called 2 times. This is the first call. The instruction

var String command = VoiceCommand.state.toString.toLowerCase

was before the second change. Maybe your system is slow, because the errors.

monojetski · February 4, 2018, 10:55am

Testing again I think it has something to do with the way “received command” vs “received update” works

rule "Voice control"
when
	Item VoiceCommand received command

rule "Voice control"
when
	Item VoiceCommand received update

received update works as expected.

this issue gave me the hint: https://github.com/openhab/openhab-core/issues/126

rlkoshak · February 5, 2018, 7:35pm

When triggering a Rule on received command use receivedCommand instead of MyItem.state to get at the command that triggered the state. The Rule will trigger before the Item registry is updated so the MyItem is not always guaranteed to reflect the state of the command.

Pedro_Fonseca · January 5, 2020, 10:24am

This is the solution. Thanks for that.