Hi Hari,
I have got an timed event that is supposed to turn of the outside lights in the garten at 00:00. For some reason that seems sometimes to go crasy and send more than 340000 off commands.
The red light of the zwave sender was still blinking like hell this morning.
36 12/09/09 23:59:17.814 We have been idle for 30 seconds, polling device states <0xb78fcb90>
40 12/09/09 23:59:17.914 Sending job 0x9e53250 (cb 17) - 0x1 0x9 0x0 0x13 0xff 0x2 0x20 0x2 0x5 0x11 0x2e
(ESC[31;1m###### ###.ESC[0m) <0xb78fcb90>
41 12/09/09 23:59:17.918 0x1 0x4 0x1 0x13 0x1 0xe8 (ESC[33;1m######ESC[0m) <0xb78fcb90>
36 12/09/09 23:59:17.918 ZW_SEND delivered to Z-Wave stack <0xb78fcb90>
41 12/09/09 23:59:17.939 0x1 0x5 0x0 0x13 0x11 0x0 0xf8 (ESC[33;1m#######ESC[0m) <0xb78fcb90>
36 12/09/09 23:59:17.939 ZW_SEND Response with callback 17 received <0xb78fcb90>
36 12/09/09 23:59:17.939 ZW_SEND was successful, removing job <0xb78fcb90>
41 12/09/09 23:59:18.024 0x1 0x9 0x0 0x4 0x0 0x3 0x3 0x20 0x3 0xff 0x2e (ESC[33;1m####### ##.ESC[0m) <0xb78fcb90>
36 12/09/09 23:59:18.024 FUNC_ID_APPLICATION_COMMAND_HANDLER: <0xb78fcb90>
36 12/09/09 23:59:18.024 COMMAND_CLASS_BASIC - <0xb78fcb90>
36 12/09/09 23:59:18.025 Got basic report from node 3, value: 255 <0xb78fcb90>
40 12/09/09 23:59:18.122 Sending job 0x9e53470 (cb 18) - 0x1 0x9 0x0 0x13 0xff 0x2 0x31 0x4 0x5 0x12 0x3a (ESC[31;1m######1###:ESC[0m) <0xb78fcb90>
41 12/09/09 23:59:18.125 0x1 0x4 0x1 0x13 0x1 0xe8 (ESC[33;1m######ESC[0m) <0xb78fcb90>
36 12/09/09 23:59:18.125 ZW_SEND delivered to Z-Wave stack <0xb78fcb90>
41 12/09/09 23:59:18.147 0x1 0x5 0x0 0x13 0x12 0x0 0xfb (ESC[33;1m#######ESC[0m) <0xb78fcb90>
36 12/09/09 23:59:18.147 ZW_SEND Response with callback 18 received <0xb78fcb90>
36 12/09/09 23:59:18.147 ZW_SEND was successful, removing job <0xb78fcb90>
41 12/09/09 23:59:18.241 0x1 0x9 0x0 0x4 0x0 0x4 0x3 0x20 0x3 0x0 0xd6 (ESC[33;1m####### ###ESC[0m) <0xb78fcb90>
36 12/09/09 23:59:18.241 FUNC_ID_APPLICATION_COMMAND_HANDLER: <0xb78fcb90>
36 12/09/09 23:59:18.241 COMMAND_CLASS_BASIC - <0xb78fcb90>
36 12/09/09 23:59:18.241 Got basic report from node 4, value: 0 <0xb78fcb90>
36 12/09/09 23:59:48.338 We have been idle for 30 seconds, polling device states <0xb78fcb90>
40 12/09/09 23:59:48.438 Sending job 0x9e53690 (cb 19) - 0x1 0x9 0x0 0x13 0xff 0x2 0x20 0x2 0x5 0x13 0x2c (ESC[31;1m###### ###,ESC[0m) <0xb78fcb90>
41 12/09/09 23:59:48.442 0x1 0x4 0x1 0x13 0x1 0xe8 (ESC[33;1m######ESC[0m) <0xb78fcb90>
36 12/09/09 23:59:48.442 ZW_SEND delivered to Z-Wave stack <0xb78fcb90>
41 12/09/09 23:59:48.463 0x1 0x5 0x0 0x13 0x13 0x0 0xfa (ESC[33;1m#######ESC[0m) <0xb78fcb90>
36 12/09/09 23:59:48.464 ZW_SEND Response with callback 19 received <0xb78fcb90>
36 12/09/09 23:59:48.464 ZW_SEND was successful, removing job <0xb78fcb90>
40 12/09/09 23:59:48.562 Sending job 0x9e538b0 (cb 20) - 0x1 0x9 0x0 0x13 0xff 0x2 0x31 0x4 0x5 0x14 0x3c (ESC[31;1m######1###<ESC[0m) <0xb78fcb90>
41 12/09/09 23:59:48.566 0x1 0x4 0x1 0x13 0x1 0xe8 (ESC[33;1m######ESC[0m) <0xb78fcb90>
36 12/09/09 23:59:48.566 ZW_SEND delivered to Z-Wave stack <0xb78fcb90>
41 12/09/09 23:59:48.587 0x1 0x5 0x0 0x13 0x14 0x0 0xfd (ESC[33;1m#######ESC[0m) <0xb78fcb90>
36 12/09/09 23:59:48.587 ZW_SEND Response with callback 20 received <0xb78fcb90>
36 12/09/09 23:59:48.587 ZW_SEND was successful, removing job <0xb78fcb90>
36 12/10/09 0:00:09.264 Received command for child <0xb68fab90>
36 12/10/09 0:00:09.264 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.274 Received command for child <0xb68fab90>
36 12/10/09 0:00:09.274 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.276 Received command for child <0xb68fab90>
36 12/10/09 0:00:09.276 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.279 Received command for child <0xb68fab90>
36 12/10/09 0:00:09.279 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.282 Received command for child <0xb68fab90>
36 12/10/09 0:00:09.282 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.285 Received command for child <0xb68fab90>
36 12/10/09 0:00:09.285 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.286 Received command for child <0xb68fab90>
36 12/10/09 0:00:09.286 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.288 Received command for child <0xb68fab90>
36 12/10/09 0:00:09.288 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.290 Received command for child <0xb68fab90>
36 12/10/09 0:00:09.290 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.291 Received command for child <0xb68fab90>
....
#grep "OFF RECEIVED FOR CHILD 4" 33_ZWave.log |wc -l
341181
Here the beginning and the end of the same grep :
36 12/09/09 22:57:32.505 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/09/09 22:57:55.018 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.264 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.274 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:00:09.276 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
<SNIP>
36 12/10/09 0:05:16.119 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:05:16.120 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 0:05:16.121 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 8:42:07.392 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
36 12/10/09 9:00:02.284 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
Viking
Hi Viking,
this is not z-wave related. As you can see here we are receiving all those commands from the DCE stack:
36 12/10/09 0:00:09.264 Received command for child <0xb68fab90>
36 12/10/09 0:00:09.264 OFF RECEIVED FOR CHILD 4 <0xb68fab90>
I'd guess that the event plugin goes crazy..
br Hari
Hi Hari,
OK, so what can I do to debug this ?
Viking
BTW. happend again tonight. This time 319048 times.
It has probably already killed two of my ACT zwave devices :( So I would really like to get it fixed.
That first ACT died and I thought it was because it got to hot. I then replaced it and shortly after it also died. I then got into looking throgh the log and found the above problem.
Viking
Hi,
maybe it has something to do with the time 00:00 - I changed it now to 23:30 - lets se what happens.
Another Times Event at 09:00 has no problems.
Viking
After changing the time for the event to 23:30 there has been no problems....
I wil test setting it back to 00:00 later.
Can anyone try to test this on their core ?
Viking
Timed event between 00:00 and 00:59 cause this and one gets out of this crazy loop by reloading the router.
Tried to see the relevant timed event source code but can't spot the error source.