Zwave control command (turn ON / OFF) delay issue after discovery scan

I met a zwave device delay issue for control command
like turn ON/OFF if I do it immediately after zwave binding scan ->
inbox approve.Here is my operation flow.
1 I already zwave controller which I can see in Habmin.
2 in Habmin, click zwave binding on the top.
3 in Habmin, click to open inbox and add z-wave Node 16: DSC06 Smart Energy Switch.
4 wait until thing status of “z-wave Node 16: DSC06 Smart Energy Switch” change to green and with a tick on the left.

If I immediately send change to sitemap page, and slide the slider of this zwave device. I have a delay issue.

Here is my log

I saw some 2 errors in the log which is

2016-12-13 12:49:56.778 [ERROR] [WaveController$ZWaveSendThread:1211 ] - NODE 16: Timeout while sending message. Requeueing - 1 attempts left!
2016-12-13 12:49:56.779 [ERROR] [b.z.i.p.s.SendDataMessageClass:162 ] - NODE 16: Got an error while sending data. Resending message.

And also MISMATCH message.

2016-12-13 12:49:56.819 [DEBUG]
[.z.i.p.s.ZWaveCommandProcessor:110 ] - Checking transaction complete:
class=SendData, callback id=114, expected=ApplicationCommandHandler,
cancelled=false MISMATCH

So one thing is certain, the delay is on
the zwave binding as we can see clearly by the log timestamp, it cost
within 1s for the received HTTP POST to reach zwave binding by OH2 event
bus.I wonder whether any expert can provide some advice for this issue.
Like
1 Whether it is possible to fix,
2 which zwave binding version I should upgrade to
3 Some configuration I should look into

Thank you very much.

I’ve not yet looked at the log, but there’s a LOT happening when you include a device into the network, and it’s not at all surprising that there are delays when you try and send a command as there will be a lot of messages to send. 1 second seems quite good - probably better than I would expect if the device isn’t initialised.

1 second seems quite good - probably better than I would expect if the device isn’t initialised.

Not really.
1 From OH2 receiving HTTP POST request to the command reaching zwave binding is within 1 second.
2 But those 2 Errors cost 5 seconds.
3 I do NOT send command until zwave device thing icon in Habmin change to
green and with a tick on the left. So at that time the zwave device thing status should be ONLINE already.

You can easily verify my first 2 points by the log.
Thank you.

Hi Chris,

Today, I have done some test for the zwave POST control command delay issue I have experienced previously. I still can replicate the delay.

**Here is my steps and some configuration. **
1 I disable simple mode.
2 create item an link to zwave switch device channel.
**Above 2 steps only are only done once. Below steps are duplicate for testing. **
1 in Habmin, delete zwave switch device.
2 in Habmin, scan zwave binding.
3 in Habmin, approve zwave switch device.
4 Then I slide widget to send POST control command.

strong text

I get response >2s a couple of times. In specific, they are 2.5s, 3s, 3.5s, 3.5s(2), 3.5s(3), 4s, 4s(2), 4s(3), 4.5s.

In comparison to console log with and without delay, you will notice that in log with delay, we have

2016-12-21 12:21:54.816 [ERROR] [WaveController$ZWaveSendThread:1211 ] - NODE 16: Timeout while sending message. Requeueing - 0 attempts left!
2016-12-21 12:21:54.816 [ERROR] [b.z.i.p.s.SendDataMessageClass:162 ] - NODE 16: Got an error while sending data. Resending message.

which does NOT exist in log without delay.

Reference Log:
1 log without delay


2 log with delay








I would say
1 this delay issue is Not hard to replicate immediately after the discovery.
2 it is from zwave binding instead of OH2 / UI.
Do you agree with me about that?

My another question is, given this delay issue exsit, is the user supposed to accept this delay(2s to 5s)? Or we can expect this delay issue will be solved and the delay will be less than 2 seconds.

Thank you very much. Please let me know if I can do something to help.

If it is “immediately after discovery” as you say, then I would ignore it - the system will be slow at this time as there is a LOT of traffic and you should not be using the system when you are commissioning devices.

There can be delays during initialisation of the binding due to a lot of traffic on the network, but in general, everything happens “instantly” here (ie the delay is tens of milliseconds.

I’m afraid I don’t have time to look at this at the moment - as above, if it’s a commissioning issue, then you should expect things to be slow - I would say it is normal.

Hi chris,

I am afraid I am confusing here by “immediately after discovery”.

By “after discovery”, I mean, after “zwave binding scan” (1 click here in Habmin) and “zwave switch device” approve (1 click here in Habmin), in addtion, I also wait until the zwave device thing(zwave node16 in below snapshot) in Habmin turn green.

Then I switch to sitemap page to slide the widget to send out ON/OFF command to zwave device.


And also as I port this zwave device discovey process to habdroid, on habdroid side, after binding scan and zwave device approve steps, I even use /rest/things to get zwave device status, wait until I saw status as ONLINE. This moment is when I refer as “after discovery”.

Then I switch to sitemap page to slide the widget to send out ON/OFF command to zwave device.


I understand there would be some busy traffic during device discovery and initialization, but “after discovery” really means after this discovery stage as above.
1 I hope I clarify the meaning of “after discovery”.

2
And my another question is,
Say during device commission, zwave device is busy.
Is there simple any way to know when the zwave device is ready to accept ON/OFF command ?
Like but maybe NOT correct, by REST /rest/things, zwave device thing has a field called “status” which can be “ONLINE”.

Thank you very much for attention.

At this point, there is still a lot of traffic - the device has not completed initialisation at this point. It’s ONLINE, yes, but it’s not necessarily finished initialisation.

We always try and accept and ON/OFF, and even if you have a 1 or 2 second delay, the system still works. The system will queue commands - commands like ON/OFF are give quite a high priority so they should be quite quick - assuming devices are responding quickly.

I’m not sure I fully understand what you mean, but as I said above, just because a device is ONLINE doesn’t mean it’s not initialising in some way, or its not doing a heal, or a poll or something else. We prioritise commands that get send so that commands that set the state of a device have the highest priority, but if there is other traffic happening, like neighbour updates, heal etc, then there can be some delay.

In your logs above, I see a lot of timeouts - you should look at why these are happening - if it’s only ever a single command/request to a certain device, and every other message to the device works fine, then you should identify these commands so we can investigate. If it is more random, then it’s probable that the network is not meshed well and the links between nodes is not strong.

I hope this helps your understanding.

Hi chris,
Thank you for your response.

Thank you for stating that thing status as ONLINE is NOT the right indicator for initialisation completion.
Can we get to know when the initialization is completed by REST /rest/thing/ query? If not, do you have some plan for that in the future?
Say, if the field status is NOT the right data I should see for that, is there some data field in some REST API I should look at?
Actually this is the same question as my second question in previous post.

1 Not only 1 or 2 seconds, if you see my 8 logs for delay issue, the delay is between 2 to 5 seconds.
2 And by the log, we can see that these 2 to 5 seconds are in the zwave binding instead of OH2.

Thank you for sharing your understanding.
But actually my environment is quite simple,
only 1 Aeon Labs Z-stick Series 2 sticker pluggged in USB port, and 1 Aeon Labs Appliance Switch (110 VOLT).
And the moment and testing scenario is,
1 click zwave binding scan
2 click approve of discovered zwave Appliance Switch
3 See status as ONLINE by /rest/things REST query
4 slide widget to send out ON/OFF command to zwave Appliance Switch.
(1 time ON, 1 time OFF).
Up to here, This is all what I do.
So it does NOT seem there’s some other network traffic, at least I do NOT trigger them by command.
5 Then I may saw 2 to 5 seconds costing in zwave binding by Eclipse log.Please see below.

5 Then I may saw 2 to 5 seconds costing in zwave binding by Eclipse log.
And actually as you already notice the [ERROR] timeout in log is right after something like,
[DEBUG] [.b.z.handler.ZWaveThingHandler:769 ] - NODE 16: Command received zwave:device:1579c2c54b2:node16:switch_binary --> OFF
and right before something like
NODE 16: Response processed after 19ms/588ms
I would say the ON / OFF command is the command that trigger the problem.

I am willing willing to do more for this. But I am not quite sure which information I should focus at the log. I may need some guidance from you as I really NOT familiar this zwave protocol details.
For example,
1 should I capture all the “NODE 16: Command received” closely before [Error]Node16:Timeout while sending message. to you? As that will show which command are before the 2 to 5 seconds delay.
2 If so, how long before [Error]Node16:Timeout while sending message. I should capture?

Thank you very much for response.

As I said above, you have a lot of timeouts in your logs - the timeouts take 5 seconds so this is the cause of your problem and you need to understand why the device is not responding to the requests.

It should be very easy to see if you put it into the log viewer on my website. From here it should be easy to see what message is timing out, and if there is any consistency/repeatability in these timeouts.

Hi chris,
Thank you for your response.

I do upload below 2 logs to log viewer as you suggested,
zwave_habmin
zwave_habmin2

1 It seems to me that firstly there is a transaction complete MISMATCH.
Log:
2016-12-21 11:43:58.840 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:110 ] - Checking transaction complete: class=SendData, callback id=165, expected=ApplicationCommandHandler, cancelled=false MISMATCH

2 Then the ON/OFF command will have a timeout [ERROR] which may cost 2 to 5 seconds delay.
Log:
2016-12-21 11:44:03.822 [ERROR] [WaveController$ZWaveSendThread:1211 ] - NODE 16: Timeout while sending message. Requeueing - 1 attempts left!
2016-12-21 11:44:03.822 [ERROR] [b.z.i.p.s.SendDataMessageClass:162 ] - NODE 16: Got an error while sending data. Resending message.

1 Do you mean that the timeout is caused by slave device(NOT zwave controller) NOT responding?
2 Should I research on zwave slave device slide?

1 To understand why the device is not responding, which further steps do you think I should do?
2 Should I more look into zwave bindinding log?
3 Or I should simply test by another zwave device?

Thank you for your attention.

This is normal - it’s not an error message. It means that a frame was received outside of the transaction - it’s 100% normal and very common.[quote=“laohixdxm2016, post:10, topic:18176”]
2 Then the ON/OFF command will have a timeout [ERROR] which may cost 2 to 5 seconds delay.Log:
[/quote]

A timeout is exactly 5 seconds.

Yes - almost certainly.

Yes - the log files will tell you what happens - there’s little else really to go on.

If I look at the log you linked above -:

Here it is clear what is happening. The binding is requesting METER data and the device is not responding to this request. Probably the device simply doesn’t support this. You can clearly see the 5 second timeout. You can also see the SET command to turn the light ON and this responds within 17ms - the same as the other requests.

Thank you for your explanation. Now I fully understand it and totally agree with you.

As we see, the delay reason is that, device is NOT responding the request.
1 My thinking is whether we can disable Meter Get sending out from zwave
sticker (zwave controller) in some say, for example, by setting some
configuration parameters?
If so, I hope to give a try to disable Meter Get to see whether the delay issue is still there which should NOT be by the log we have.

1 Do you agree that my thinking on this issue is right direction to go?
2 In addition, would you please give some idea / suggestion for this zwave sticker Meter GET disable / configuration parameters settings issue if possible?

Thank you very much.

Hi Chris,

I have a quick question for this METER GET command.

As we see, binding sending out METER GET command.
1 Am I correct to say METER is detected in zwave device before METER GET sending?
2 I mean, assume binding can NOT detect METER in zwave device, then it will NOT send METER GET command. Am I correct to say that?

Thank you.

Correct - the binding only sends commands to command classes it detects. If it doesn’t find the METER class, then it won’t try and send a command to the METER class.

1 Like

Thank you for your quick response.

So to disable METER GET, we may need to disable METER command class to on zwave device side.
Do you agree with me about that?

Thank you.

No - there’s a command/option we can set in the database (NOGET) that prevents the GET command for any command class. This should be used to prevent the METER_GET.

Hi Chris,

Thank you for pointing that out.

However, I have a stupid question.
1 Where can I configure command/option in zwave database?
I can NOT find entry in Habmin to configure command/option in zwave database.
Also, it does NOT look like I can do this by some REST API.

2 I have been to here,
http://www.cd-jackson.com/index.php/zwave/zwave-device-database
but have NO idea whether I should do something on this website.

Would you please provide some further advice which direction I should go if possible? Thank you.

The change needs to be made in the www.cd-jackson.com website. If you remind me what the device is I can easily make the change.

Hi Chris,

The controller is AEON LAB z-stick S2 and the device is AEON LAB appliance switch (110 volt).

1 How can we make the change in the website?
I can NOT find the entry.
Would you please post the link where we can do the zwave database configuration change if there is one?

2 But even we made the change on the website, how can be database change applied to my OH2 environment?
Should I rebuild zwave binding from source code or simply copy a data file which can exported from website to make that happen?

Thank you very much.

It’#s the link above (http://www.cd-jackson.com/index.php/zwave/zwave-device-database) but you need to register - have a read of the instructions.

The database is included in the binding, so you update to the latest binding.