ERROR ssage.ApplicationCommandMessageClass in openhab.log

Setup, Configuration and Use Runtime
1

Newbie to OH, I keep getting these messages in my openhab.log:

2016-12-08 14:06:36.024 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising Thing Node…
2016-12-08 14:06:36.024 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node…
2016-12-08 14:06:36.025 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node…
2016-12-08 14:06:44.725 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 2 attempts left!
2016-12-08 14:07:09.244 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 70 06 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 70 06 (5)
2016-12-08 14:07:14.204 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 2 attempts left!
2016-12-08 14:07:38.786 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 70 06 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 70 06 (5)
2016-12-08 14:07:43.744 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Timeout while sending message. Requeueing - 1 attempts left!

Node 4 is a Zwave Everspring SP103 motion sensor, it appears to work OK in my rules though.

The ssage error keeps coming out periodically separate from the NODE 4 Timeout which only seems to appear on OH startup.

Is it anything to be concerned about ?

Thanks!

2

Seems to repeat every 30 minutes:

2016-12-12 01:29:44.134 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 (5)
2016-12-12 01:59:50.606 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 (5)
2016-12-12 02:29:27.941 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 (5)
2016-12-12 02:59:35.408 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 (5)
2016-12-12 03:29:41.692 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 (5)
2016-12-12 03:59:50.157 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 (5)
2016-12-12 04:29:32.317 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 (5)
2016-12-12 04:59:45.849 [ERROR] [ssage.ApplicationCommandMessageClass] - Error processing frame: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 >> Attempt to read message payload out of bounds: Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 04 02 30 03 (5)

3

Please provide a debug log around the time leading up to these messages and I’ll have a look.

4

Thanks, so I need to

http://docs.openhab.org/administration/logging.html

log:set DEBUG package.subpackage <- what package and subpackage ?

5

This is for zwave, so org.openhab.binding.zwave should be what you need…

6

Sorry I’m very new to OH.

I put this entry into openhab.cfg:-
log:set DEBUG org.openhab.binding.zwave

but do not see any additional output in openhab.log or events.log after restarting?

7

No, this has nothing to do with the openhab.cfg.

You have to enter this in the Karaf console. You posted the link for this yourself. Open a console (if you are using Linux on a Raspberry, most probably a SSH connection), log-in and then type in:

ssh openhab@localhost -p 8101

The password is habopen

For the first log-in, it could take quite a while or even time out. Then just try again.

When successfully done, you are in the Karaf console. There you have to enter:

log:set DEBUG org.openhab.binding.zwave

With the command ‘logout’ you are back on your regular console.

After that, you find all the zwave related log entries with DEBUG level in the openhab.log.

And because you already mentioned two times, that you are new to the whole OH-world, I would strongly suggest to study the documentation at docs.openhab.org.

After you figured out the zwave related problem, don’t forget to switch back to the normal log level:

log:set INFO org.openhab.binding.zwave

8

I will try the console then.

I did read the docs and it states:- “Note that the log levels set using the log:set commands are not persistent and will be lost upon restart. To configure those in a persistent way, the commands have to be added to the configuration file.”

hence my thought to use openhab.cfg.

Please tell me the name of the configuration file ? rg.ops4j.pax.logging.cfg ?

9

I’m using docker so

docker exec -it Openhab /openhab/runtime/bin/client

openhab> log:set DEBUG org.openhab.binding.zwave
openhab>

hopefully that will do it

10

Log file is here

https://drive.google.com/open?id=0B6cAC5bGur8ZcVBGN2Jkc3BCMVU

11

Hope the log proves useful

12

Sorry - I’ve been away for a few days. I’ll take a look tonight or tomorrow.

13

The problem is caused by the following -:

Pasted image1024×262 60.2 KB

The sensor is sending two responses - the first one has no data and is in violation of the protocol. The binding reacts with the error that you see in the log since the data is corrupt. The second response it sends is ok.

14

OK thanks.

Node 4 is an Everspring SP103 motion sensor, OH automatically detected and configured it.

So its not a configuration issue on my side, definitely some problem I should report to Everspring ?

15

Well, the only other thing I can think of that it could be is some sort of lost data in your computer sucn that it’s dropping a byte. I doubt it’s configuration anyway…

16

Appreciate your assistance, it doesn’t seem to be causing any operational issues and my sensor works fine in my rules so will just ignore this for the time being.

Regards.