Zwave - timed event sends 341000 OFF commands in 5 seconds ...

[Viking]

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.

Code: [Select]

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 :

Code: [Select]

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

[hari]

Hi Viking,

this is not z-wave related. As you can see here we are receiving all those commands from the DCE stack:

Code: [Select]

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

[Viking]

Hi Hari,

OK, so what can I do to debug this ?

Viking

[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

[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

[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

[Kooma]

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.