zwave stops broadcasting commands

[petrklus]

State right after OH restart, log when flipping a switch (and the light goes on and off):

12:48:48.930 DEBUG o.o.i.r.i.r.ItemResource[:196]- Received HTTP POST request at 'items/ZWave_Light_IND_Kitchen' with value 'ON'.
12:48:48.933 DEBUG o.o.b.z.i.p.c.ZWaveBinarySwitchCommandClass[:135]- Creating new message for application command SWITCH_BINARY_SET for node 2
12:48:48.934 DEBUG o.o.b.z.i.protocol.ZWaveNode[:551]- NODE 2: Encapsulating message, instance / endpoint 1
12:48:48.935 DEBUG o.o.b.z.i.p.c.ZWaveMultiInstanceCommandClass[:499]- NODE 2: Creating new message for application command MULTI_CHANNEL_ENCAP endpoint 1
12:48:48.935 DEBUG o.o.b.z.i.p.ZWaveController[:598]- Callback ID = 21
12:48:48.936 DEBUG o.o.b.z.i.p.ZWaveController[:361]- Enqueueing message. Queue length = 1
12:48:48.936 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:771]- Took message from queue for sending. Queue length = 0
12:48:48.938 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:800]- Sending Message = 01 0E 00 13 02 07 60 0D 01 01 25 01 FF 25 15 61 
12:48:48.944 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:971]- Receive Message = 01 04 01 13 01 E8 
12:48:48.945 DEBUG o.o.b.z.i.p.ZWaveController[:150]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
12:48:48.972 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:971]- Receive Message = 01 05 00 13 15 00 FC 
12:48:48.973 DEBUG o.o.b.z.i.p.ZWaveController[:150]- Message: class = SendData (0x13), type = Request (0x00), payload = 15 00 
12:48:48.975 DEBUG o.o.b.z.i.p.ZWaveController[:376]- Notifying event listeners
12:48:48.975 DEBUG o.o.b.z.i.ZWaveActiveBinding[:286]- ZwaveIncomingEvent
12:48:48.976 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:846]- Response processed after 38ms/216ms.
12:48:49.729 DEBUG o.o.i.r.i.r.ItemResource[:196]- Received HTTP POST request at 'items/ZWave_Light_IND_Kitchen' with value 'OFF'.
12:48:49.732 DEBUG o.o.b.z.i.p.c.ZWaveBinarySwitchCommandClass[:135]- Creating new message for application command SWITCH_BINARY_SET for node 2
12:48:49.733 DEBUG o.o.b.z.i.protocol.ZWaveNode[:551]- NODE 2: Encapsulating message, instance / endpoint 1
12:48:49.733 DEBUG o.o.b.z.i.p.c.ZWaveMultiInstanceCommandClass[:499]- NODE 2: Creating new message for application command MULTI_CHANNEL_ENCAP endpoint 1
12:48:49.733 DEBUG o.o.b.z.i.p.ZWaveController[:598]- Callback ID = 22
12:48:49.734 DEBUG o.o.b.z.i.p.ZWaveController[:361]- Enqueueing message. Queue length = 1
12:48:49.734 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:771]- Took message from queue for sending. Queue length = 0
12:48:49.735 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:800]- Sending Message = 01 0E 00 13 02 07 60 0D 01 01 25 01 00 25 16 9D 
12:48:49.741 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:971]- Receive Message = 01 04 01 13 01 E8 
12:48:49.742 DEBUG o.o.b.z.i.p.ZWaveController[:150]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
12:48:49.754 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:971]- Receive Message = 01 05 00 13 16 00 FF 
12:48:49.755 DEBUG o.o.b.z.i.p.ZWaveController[:150]- Message: class = SendData (0x13), type = Request (0x00), payload = 16 00 
12:48:49.756 DEBUG o.o.b.z.i.p.ZWaveController[:376]- Notifying event listeners
12:48:49.757 DEBUG o.o.b.z.i.ZWaveActiveBinding[:286]- ZwaveIncomingEvent
12:48:49.757 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:846]- Response processed after 21ms/216ms.

However, later it stops working (same command issued, however, no corresponding zwave binding activity):

13:15:30.486 DEBUG o.o.i.r.i.r.ItemResource[:196]- Received HTTP POST request at 'items/ZWave_Light_IND_Hallway' with value 'ON'.
13:15:31.958 DEBUG o.o.i.r.i.r.ItemResource[:196]- Received HTTP POST request at 'items/ZWave_Light_IND_Hallway' with value 'OFF'.

What is going on? Why does the binding not create and enqueue the new commands?

The PING goes through just fine:

13:15:35.103 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:277]- NODE 2: Sending periodic PING.
13:15:35.103 DEBUG o.o.b.z.i.p.c.ZWaveNoOperationCommandClass[:75]- NODE 2: Creating new message for application command No Operation
13:15:35.104 DEBUG o.o.b.z.i.p.ZWaveController[:598]- Callback ID = 44
13:15:35.104 DEBUG o.o.b.z.i.p.ZWaveController[:361]- Enqueueing message. Queue length = 1
13:15:35.104 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:771]- Took message from queue for sending. Queue length = 0
13:15:35.105 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:800]- Sending Message = 01 08 00 13 02 01 00 25 2C EE 
13:15:35.110 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:971]- Receive Message = 01 04 01 13 01 E8 
13:15:35.111 DEBUG o.o.b.z.i.p.ZWaveController[:150]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
13:15:35.122 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:971]- Receive Message = 01 05 00 13 2C 00 C5 
13:15:35.123 DEBUG o.o.b.z.i.p.ZWaveController[:150]- Message: class = SendData (0x13), type = Request (0x00), payload = 2C 00 
13:15:35.124 DEBUG o.o.b.z.i.p.ZWaveController[:376]- Notifying event listeners
13:15:35.124 DEBUG o.o.b.z.i.ZWaveActiveBinding[:286]- ZwaveIncomingEvent
13:15:35.124 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:846]- Response processed after 19ms/216ms.

Why is the ping still working but normal commands are not sent out?

[petrklus]

And I've seen in the logs a message from the packets being received when the light switches were flipped too..

On Mon, May 5, 2014 at 5:42 PM, Petr Klus petr@klus.co.uk wrote:

If I have, it needs to be the default setting :). Yes, Europe - Spain to be specific (bought from zwave.es).

On Mon, May 5, 2014 at 5:11 PM, Chris Jackson notifications@github.comwrote:

On 5 May 2014, at 16:07, petrklus notifications@github.com wrote:

Ok, sounds interesting when I get more zwave devices, that I will link them together internally. Also, how come that my light switches on OH user interface got updated even without the association groups?

Maybe you have polling enabled? Or some switches will send a message even without associations - these mostly seem to be used in the USA from what I’ve seen (I’m guessing you’re in Europe somewhere?).

— Reply to this email directly or view it on GitHubhttps://github.com/openhab/openhab/issues/1044#issuecomment-42198071 .

[petrklus]

Hi, small update - after a few days, the switch is still yellow.. is it going to stay this way?

[cdjackson]

Hmmm - I must say its not immediately obvious why this is still yellow. I assume you’ve refreshed the interface recently - just in case it’s just not updated?

Looking at the code, and the dates in your screen dump, I don’t think it should be yellow, but maybe there’s something wrong with my logic. I’ll take a look when I get a chance (I’m away from home at the moment).

Cheers Chris

[petrklus]

Could it be because the 3am daily heal fails? And yes, I've re-freshed...

On Thu, May 8, 2014 at 5:23 PM, Chris Jackson notifications@github.comwrote:

Hmmm - I must say its not immediately obvious why this is still yellow. I assume you’ve refreshed the interface recently - just in case it’s just not updated?

Looking at the code, and the dates in your screen dump, I don’t think it should be yellow, but maybe there’s something wrong with my logic. I’ll take a look when I get a chance (I’m away from home at the moment).

Cheers Chris

— Reply to this email directly or view it on GitHubhttps://github.com/openhab/openhab/issues/1044#issuecomment-42563413 .

[cdjackson]

No - I don’t think so.

The code is below - it only uses the last dead time (which was 3 days ago) and the retry count (which is 20, and 20 * 100 / 2200 is < 5). So, both of these checks (I believe) should be ok I think.

                Date lastDead = node.getDeadTime();
                Long timeSinceLastDead = Long.MAX_VALUE;
                if(lastDead != null) {
                    timeSinceLastDead = lastDead.getTime() - System.currentTimeMillis();
                }
                if(node.getDeadCount() > 0 && timeSinceLastDead < 86400000)
                    record.state = OpenHABConfigurationRecord.STATE.WARNING;
                else if(node.getSendCount() > 0 && (node.getRetryCount() * 100 / node.getSendCount()) > 5)
                    record.state = OpenHABConfigurationRecord.STATE.WARNING;
                else
                    record.state = OpenHABConfigurationRecord.STATE.OK;
                break;

[petrklus]

Shouldn't it be:

timeSinceLastDead = System.currentTimeMillis() - lastDead.getTime();

instead of

timeSinceLastDead = lastDead.getTime() - System.currentTimeMillis();

[petrklus]

Because the statement is always negative, as the System.currentTimeMillis() is always larger than any dead time. Therefore, it is always smaller than 86400000 and thus if there is any dead time recorded, it always resolves to WARNING.

On Thu, May 8, 2014 at 6:27 PM, Petr Klus petr@klus.co.uk wrote:

Shouldn't it be:

timeSinceLastDead = System.currentTimeMillis() - lastDead.getTime();

instead of

timeSinceLastDead = lastDead.getTime() - System.currentTimeMillis();

On Thu, May 8, 2014 at 5:34 PM, Chris Jackson notifications@github.comwrote:

No - I don’t think so.

The code is below - it only uses the last dead time (which was 3 days ago) and the retry count (which is 20, and 20 * 100 / 2200 is < 5). So, both of these checks (I believe) should be ok I think.

Date lastDead = node.getDeadTime(); Long timeSinceLastDead = Long.MAX_VALUE; if(lastDead != null) { timeSinceLastDead = lastDead.getTime() - System.currentTimeMillis(); } if(node.getDeadCount() > 0 && timeSinceLastDead < 86400000) record.state = OpenHABConfigurationRecord.STATE.WARNING; else if(node.getSendCount() > 0 && (node.getRetryCount() * 100 / node.getSendCount()) > 5) record.state = OpenHABConfigurationRecord.STATE.WARNING; else record.state = OpenHABConfigurationRecord.STATE.OK; break;

— Reply to this email directly or view it on GitHubhttps://github.com/openhab/openhab/issues/1044#issuecomment-42564945 .

[cdjackson]

Hmmm - yes, that looks better! I’m from New Zealand - I was thinking upside down :)

I’ll change this when I get a chance - either tonight when I get back from dinner (depending on how many German beers I drink) or tomorrow when I get home).

Cheers Chris

[petrklus]

I cannot count how many times things like this caught me out so I am always on a lookout.

Cool, let me know when I can get the latest binding.. no rush I think as this one is really just a matter of cosmetics.

By the way - will be extending my zwave network soon, going for switches/dimmers + some contacts, my idea is to go with Fibaro mainly, any other brands you think work best? What do you use in your setup?

Not sure that after-beer code changes are the best idea :beers: :smile:

[cdjackson]

I use mostly Fibaro devices - I think they make some nice innovative stuff and it generally seems to work pretty well. I’ve got a few other bits and pieces, but all my light switches are now Fibaro, along with door sensors, and their new little motion sensor seems to be pretty cool (I’ve only just started playing with it, but it seems really nice, and it’s pretty small compared to other devices out there).

Chris

[teichsta]

guys, could you advice me how to proceed with this issue? Any PR to refer to?

[cdjackson]

1058 and #1075 cover this I think. @petrklus - any comment?

[petrklus]

@cdjackson I have to rely on you for the PR ids but in terms of functionality, it is all working with code I snatched from your repository.

I still occasionally get DEAD nodes, meaning that the node colour turns to yellow from time to time, however, no functionality is affected that I can tell - it still sends/receives all commands without any trouble

[petrklus]

@cdjackson what about the configurable parameter of packet timeout? I think that 5s seems a bit long...

[cdjackson]

It is configurable, but I've not told people how to set it because there's some more investigation required to make sure there's no nasty side effects. However, that's another 'issue' - this one wasn't about making the timeout configurable, so I think that this can be closed.

[teichsta]

1058 and #1075 cover this I think. @petrklus - any comment?

since both PRs are merged i'll close this for now. Please feel free to reopen in case. Best, Thomas E.-E.