OH2 Z-Wave refactoring and testing... and SECURITY

chris · July 15, 2018, 6:17pm

I missed changing a break to a continue… It’s updated if you want to give it another go…

chris · July 15, 2018, 6:19pm

I’m not holding my breath just yet . This version isn’t a lot different to the one I sent you a few days back.

Still - let’s see …

5iver · July 15, 2018, 6:35pm

It seems a lot faster to stabilize after a restart. I haven’t done any scientific comparison, but load on the server seems reduced too, and clears up in 5-10 minutes. I’m up to 3 dead nodes (battery)… different device type than before. After the last update, the minimote is still reporting `Command class COMMAND_CLASS_SCENE_ACTIVATION not found, event though…

2018-07-15 14:26:33.996 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Initialising Thing Node...
2018-07-15 14:26:33.996 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Initialising cmd channel zwave:device:07cb40a2:node212:scene_number for DecimalType
2018-07-15 14:26:33.996 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Initialising state channel zwave:device:07cb40a2:node212:scene_number for DecimalType
2018-07-15 14:26:33.996 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Initialising state channel zwave:device:07cb40a2:node212:scene_number for DecimalType

It’s odd that ths device would be polled at all, since it would never respond…

2018-07-15 14:26:56.676 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Polling...
2018-07-15 14:26:56.676 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Polling zwave:device:07cb40a2:node212:scene_number
2018-07-15 14:26:56.676 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 212: Polling skipped for zwave:device:07cb40a2:node212:scene_number on COMMAND_CLASS_BASIC

mhilbush · July 15, 2018, 6:36pm

That seems to have done the trick! Thanks!!!

mhilbush · July 15, 2018, 6:37pm

Try the latest version.

5iver · July 15, 2018, 6:38pm

I think that’s what I’m on… 2.4.0.201807151606

chris · July 15, 2018, 6:50pm

You’re 2 versions behind!

5iver · July 15, 2018, 6:54pm

Shoot… I used an old screen. I’m actually on 2.4.0.201807151916.

But now I see a 2.4.0.201807151930… I need a rule for this!

sihui · July 15, 2018, 7:02pm

Seems Chris is winning the championship today for fastest binding updates

mhilbush · July 15, 2018, 7:08pm

I’m on 2.4.0.201807151916 – Oh dear, now I’m behind!

5iver · July 15, 2018, 7:10pm

I just deleted all my minimotes and the XMLs are still there. Looks like this isn’t working.

But your minimotes are working… hmmm. I’ll try restarting OH.

mhilbush · July 15, 2018, 7:15pm

That’s correct. There’s still an issue that the XML file is not deleted when the Thing is deleted.

BTW, @chris, I was looking at this ESH API, which I don’t recall ever seeing. It’s supposed to be called by the framework when the Thing is removed (i.e. deleted).

mhilbush · July 15, 2018, 7:17pm

Wanting to start from a completely clean slate with my MMs, I excluded them, did a factory reset, and then included.

chris · July 15, 2018, 7:30pm

There were no changes relating to this in the 1930 version - I just updated an XML for another issue…

vossivossi · July 15, 2018, 7:35pm

Unfortunately the binding has stability issues, it just stopps working with a Java exception and after that there are no more updates to OH and no more XML-initialization is done. I already noticed that with the version 20180708 from last week (from time to time the Jave exception occured).
Here is the Debug log (exception at 20:32:48.691)

2018-07-15 20:32:23.688 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 01 55 86 00 00 00 00 00 00 00 00 00 00 49 
2018-07-15 20:32:23.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 98<>30 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 55 86 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:23.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 55 86 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:24.421 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 B1 06 31 05 04 22 00 85 D7 
2018-07-15 20:32:24.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 28<>100 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 85 
2018-07-15 20:32:24.425 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 85 
2018-07-15 20:32:24.775 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 B0 06 31 05 04 22 00 F0 A3 
2018-07-15 20:32:24.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 29<>99 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=176, callback=0, payload=00 B0 06 31 05 04 22 00 F0 
2018-07-15 20:32:24.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=176, callback=0, payload=00 B0 06 31 05 04 22 00 F0 
2018-07-15 20:32:25.354 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:32:25.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 99<>29 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:25.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:25.793 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 9A 0E 60 0D 01 01 32 02 21 44 00 00 01 16 00 00 54 
2018-07-15 20:32:25.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 30<>98 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=154, callback=0, payload=00 9A 0E 60 0D 01 01 32 02 21 44 00 00 01 16 00 00 
2018-07-15 20:32:25.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=154, callback=0, payload=00 9A 0E 60 0D 01 01 32 02 21 44 00 00 01 16 00 00 
2018-07-15 20:32:25.979 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 2F 0A 32 02 21 34 00 00 00 79 00 00 92 
2018-07-15 20:32:25.980 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 100<>28 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=47, callback=0, payload=00 2F 0A 32 02 21 34 00 00 00 79 00 00 
2018-07-15 20:32:25.980 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=47, callback=0, payload=00 2F 0A 32 02 21 34 00 00 00 79 00 00 
2018-07-15 20:32:26.457 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 37 06 43 03 01 22 00 B9 1C 
2018-07-15 20:32:26.458 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 101<>27 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=55, callback=0, payload=00 37 06 43 03 01 22 00 B9 
2018-07-15 20:32:26.458 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=55, callback=0, payload=00 37 06 43 03 01 22 00 B9 
2018-07-15 20:32:26.688 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 00 30 95 00 00 00 00 00 00 00 00 00 00 3E 
2018-07-15 20:32:26.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 102<>26 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 30 95 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:26.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 30 95 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:27.428 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 B1 06 31 05 04 22 00 FE AC 
2018-07-15 20:32:27.432 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 31<>97 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 FE 
2018-07-15 20:32:27.432 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 FE 
2018-07-15 20:32:27.688 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 00 1A BE 00 00 00 00 00 00 00 00 00 00 3F 
2018-07-15 20:32:27.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 103<>25 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 1A BE 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:27.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 1A BE 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:27.809 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 22 0E 60 0D 01 01 32 02 21 34 00 00 00 00 00 00 8B 
2018-07-15 20:32:27.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 104<>24 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=34, callback=0, payload=00 22 0E 60 0D 01 01 32 02 21 34 00 00 00 00 00 00 
2018-07-15 20:32:27.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=34, callback=0, payload=00 22 0E 60 0D 01 01 32 02 21 34 00 00 00 00 00 00 
2018-07-15 20:32:27.914 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:32:27.915 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 105<>23 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:27.916 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:28.816 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 09 0A 56 01 31 05 01 22 00 CC DD 5E E7 
2018-07-15 20:32:28.819 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 5<>123 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=9, callback=0, payload=00 09 0A 56 01 31 05 01 22 00 CC DD 5E 
2018-07-15 20:32:28.819 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=9, callback=0, payload=00 09 0A 56 01 31 05 01 22 00 CC DD 5E 
2018-07-15 20:32:29.451 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 32 03 20 03 FF 1F 
2018-07-15 20:32:29.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 106<>22 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=50, callback=0, payload=00 32 03 20 03 FF 
2018-07-15 20:32:29.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=50, callback=0, payload=00 32 03 20 03 FF 
2018-07-15 20:32:30.473 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:32:30.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 107<>21 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:30.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:30.689 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 01 7A E6 00 00 00 00 00 00 00 00 00 00 06 
2018-07-15 20:32:30.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 108<>20 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 7A E6 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:30.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 7A E6 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:31.688 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 01 D3 6C 00 00 00 00 00 00 00 00 00 00 25 
2018-07-15 20:32:31.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 109<>19 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 D3 6C 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:31.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 D3 6C 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:33.032 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:32:33.034 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 110<>18 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:33.034 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:33.689 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 01 3F A2 00 00 00 00 00 00 00 00 00 00 07 
2018-07-15 20:32:33.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 111<>17 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 3F A2 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:33.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 3F A2 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:35.596 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:32:35.598 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 112<>16 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:35.598 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:35.695 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 01 9F F9 00 00 00 00 00 00 00 00 00 00 FC 
2018-07-15 20:32:35.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 113<>15 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 9F F9 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:35.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 9F F9 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:38.153 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:32:38.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 114<>14 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:38.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:38.714 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 2E 0E 60 0D 02 00 32 02 21 34 00 00 00 00 00 00 85 
2018-07-15 20:32:38.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 115<>13 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=46, callback=0, payload=00 2E 0E 60 0D 02 00 32 02 21 34 00 00 00 00 00 00 
2018-07-15 20:32:38.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=46, callback=0, payload=00 2E 0E 60 0D 02 00 32 02 21 34 00 00 00 00 00 00 
2018-07-15 20:32:39.688 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 00 6F 20 00 00 00 00 00 00 00 00 00 00 D4 
2018-07-15 20:32:39.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 116<>12 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 6F 20 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:39.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 6F 20 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:40.688 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 00 1E 95 00 00 00 00 00 00 00 00 00 00 10 
2018-07-15 20:32:40.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 117<>11 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 1E 95 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:40.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 1E 95 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:40.735 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:32:40.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 118<>10 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:40.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:40.811 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:32:40.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 119<>9 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:40.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:41.424 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 B1 06 31 05 04 22 00 67 35 
2018-07-15 20:32:41.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 32<>96 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 67 
2018-07-15 20:32:41.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 67 
2018-07-15 20:32:42.835 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 AB 12 32 02 21 74 00 00 02 86 00 00 00 00 00 00 00 00 00 00 BB 
2018-07-15 20:32:42.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 33<>95 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=171, callback=0, payload=00 AB 12 32 02 21 74 00 00 02 86 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:42.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=171, callback=0, payload=00 AB 12 32 02 21 74 00 00 02 86 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:43.273 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:32:43.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 120<>8 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:43.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:43.420 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 B1 06 31 05 04 22 00 D0 82 
2018-07-15 20:32:43.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 34<>94 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 D0 
2018-07-15 20:32:43.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 D0 
2018-07-15 20:32:43.688 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 00 37 FF 00 00 00 00 00 00 00 00 00 00 53 
2018-07-15 20:32:43.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 121<>7 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 37 FF 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:43.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 00 37 FF 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:43.837 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 AB 12 32 02 21 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3F 
2018-07-15 20:32:43.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 35<>93 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=171, callback=0, payload=00 AB 12 32 02 21 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:43.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=171, callback=0, payload=00 AB 12 32 02 21 74 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:44.688 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 02 35 26 00 00 00 00 00 00 00 00 00 00 8A 
2018-07-15 20:32:44.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 122<>6 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 02 35 26 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:44.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 02 35 26 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:45.420 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 B1 06 31 05 04 22 00 5E 0C 
2018-07-15 20:32:45.426 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 36<>92 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 5E 
2018-07-15 20:32:45.426 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 5E 
2018-07-15 20:32:45.688 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 01 2B 4A 00 00 00 00 00 00 00 00 00 00 FB 
2018-07-15 20:32:45.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 123<>5 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 2B 4A 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:45.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 2B 4A 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:45.834 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:32:45.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 124<>4 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:45.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:46.687 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 01 97 1C 00 00 00 00 00 00 00 00 00 00 11 
2018-07-15 20:32:46.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 125<>3 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 97 1C 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:46.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 97 1C 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:47.421 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 B1 06 31 05 04 22 00 EE BC 
2018-07-15 20:32:47.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 37<>91 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 EE 
2018-07-15 20:32:47.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 EE 
2018-07-15 20:32:47.688 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 01 41 55 00 00 00 00 00 00 00 00 00 00 8E 
2018-07-15 20:32:47.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 126<>2 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 41 55 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:47.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 41 55 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:48.424 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 B1 06 31 05 04 22 00 C5 97 
2018-07-15 20:32:48.426 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-15 20:32:48.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 127<>1 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:48.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-15 20:32:48.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 38<>90 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 C5 
2018-07-15 20:32:48.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=177, callback=0, payload=00 B1 06 31 05 04 22 00 C5 
2018-07-15 20:32:48.688 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 04 00 0F 12 32 02 21 74 00 01 83 63 00 00 00 00 00 00 00 00 00 00 7A 
2018-07-15 20:32:48.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 128<>0 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 83 63 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:48.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 12 32 02 21 74 00 01 83 63 00 00 00 00 00 00 00 00 00 00 
2018-07-15 20:32:48.691 [ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread. 
java.lang.IllegalStateException: Queue full
	at java.util.AbstractQueue.add(Unknown Source) [?:?]
	at java.util.concurrent.ArrayBlockingQueue.add(Unknown Source) [?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:394) [259:org.openhab.binding.zwave:2.4.0.201807151916]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1053) [259:org.openhab.binding.zwave:2.4.0.201807151916]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:634) [259:org.openhab.binding.zwave:2.4.0.201807151916]
	at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:319) [259:org.openhab.binding.zwave:2.4.0.201807151916]
2018-07-15 20:32:48.691 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive
2018-07-15 20:32:50.847 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 69: Polling...
2018-07-15 20:32:50.847 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 69: Polling deferred until initialisation complete
2018-07-15 20:32:57.533 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 53 0E 32 02 21 64 00 01 19 8C 00 78 00 01 19 8C BF 
2018-07-15 20:32:57.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 39<>89 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=83, callback=0, payload=00 53 0E 32 02 21 64 00 01 19 8C 00 78 00 01 19 8C 
2018-07-15 20:32:57.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=83, callback=0, payload=00 53 0E 32 02 21 64 00 01 19 8C 00 78 00 01 19 8C 
2018-07-15 20:32:59.736 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 54 0E 32 02 21 64 00 02 48 7A 00 78 00 02 48 7A B8 
2018-07-15 20:32:59.739 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 40<>88 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=84, callback=0, payload=00 54 0E 32 02 21 64 00 02 48 7A 00 78 00 02 48 7A 
2018-07-15 20:32:59.739 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=84, callback=0, payload=00 54 0E 32 02 21 64 00 02 48 7A 00 78 00 02 48 7A 
2018-07-15 20:33:06.649 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 3F 06 31 05 01 22 01 13 CB 
2018-07-15 20:33:06.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 41<>87 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 13 
2018-07-15 20:33:06.651 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 13 
2018-07-15 20:33:06.770 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 45 06 43 03 01 22 00 CD 1A

chris · July 15, 2018, 7:35pm

At the moment, it should only delete the XML when the device is excluded - is that what you’re doing and it’s not working?

The XMLs are part of the protocol layer. We could delete them when the thing is removed, but it feels a bit wrong to me.

chris · July 15, 2018, 7:38pm

This isn’t the root cause - something else must have happened somewhere earlier than this log as it’s not processing messages at all in this log.

vossivossi · July 15, 2018, 7:45pm

I just checked the timestamps in the persistence DB now and you are right, the last updates happened at 20:31:18 (1:30 minutes before the exception).
However this only happened with the 20180708 experimental version before (before that the different Z-Wave bindings never stopped working in operation). I switched back to the “normal” DEV version 20180703 5 days ago and since then the error did not show up again (while the 20180708 stopped after 10-30 hours every time).
Now I changed 2 hours ago to the very fresh dev version and the error is in it also.
What else could I check to narrow down the root cause?

chris · July 15, 2018, 7:50pm

Check the debug logs to see what was received at the time it stopped working. It should be easy to see the change in logging as there is nothing being processed.

mhilbush · July 15, 2018, 7:53pm

Ah, ok. I thought the XML would be removed when the node was excluded or when the thing was deleted.