zwave initialisation updates

[Chris Jackson]

I've created a PR for the zwave initialisation updates. This is still a long way off being merged, but I wanted to make it visible so people can comment on it since it's a big change to the binding. Basically, this should hopefully improve the performance of the initialisation, and also make it easier to enhance later. Previously, the initialisation code was scattered throughout the command classes, making it difficult to maintain, test, and modify. This has all been brought into a single class. Other changes have been made to improve performance, such as delaying battery node initialisation until mains nodes have completed (since they can't be initialised until they wakeup anyway!).

It's still work in progress, and there will be further changes, but review and comments appreciated. https://github.com/openhab/openhab/pull/1678. I'll probably give it a week or so of testing before I make a release version available - just to try and weed out the major problems (although it seems to be working nicely at the moment!)

Below is the overview of the initialisation process... I still have some features to add...

Cheers

Chris

Node initialisation is handled solely within the NodeStageAdvancer. It is not
based on time - it waits for the transactions to complete. Time cannot be
used reliably since with larger networks, it may take a long time for the
initialisation. This is especially true if there are battery nodes since the
PING phase, used to detect if a node is active, will time-out for battery
devices. A timeout takes 5 seconds, and if there are retries active, this may
be extended to 15 seconds. For a network with 8 battery nodes, this could
mean a delay of 2 minutes!

We use the 'listening' flag to prioritise the initialisation of nodes. Rather
than kicking off all nodes at the same time and have battery nodes timing out
and delaying the initialisation of mains nodes, we try and initialise nodes
that are listening first. This is checked after the protocol information
is received, and non-listening nodes are held at a WAIT state until the
transmit queue drops below 2 frames when they are allowed to proceed to PING.

The NodeStageAdvancer registers an event listener during the initialisation
of a node. This allows it to be notified when each transaction is complete,
and we can process this accordingly. The event listener is removed when we
stop initialising to reduce processor loading.

Command classes are responsible for building lists of messages needed to
initialise themselves. The command class also needs to keep track of
responses so it knows if initialisation of this stage is complete. Other than
that, the command class does not have any input into the initialisation
phase, and the sequencing of events - this is all handled here in the node
advancer class.

For each stage, the advancer builds a list of all messages that need to be
sent to the node. Since the initialisation phase is an intense period, with a
lot of messages on the network, we try and ensure that only 1 packet is
outstanding to any node at once to avoid filling up the main transmit queue
which could impact on the performance of other nodes.

Each time we receive an ACK for a message, the node advancer gets called, and
we see if this is an ACK for a message that's part of the initialisation. If
it is, the message gets removed from the list.

Each time we receive a command message, the node advancer gets called. This
is called after the command class has been updated, so at this stage we know
if the stage can be completed.

Two checks are performed to allow a node stage to advance. Firstly, we make
sure we've sent all the messages required for this phase. Sending the
messages however doesn't guarantee that we get a response, so we then run
through the stage again to make sure that the command class really is
initialised. If the second run queues no messages, then we can reliably
assume this stage is completed. If we've missed anything, then we continue
until there are no messages to send.

[Phil]

Awesome! Thanks!
I hope to test it soon (as soon my new equipment arrives)

-phil

[dan cunningham]

That's great Chris , I'll give a go tonight.

Sent from my iPad

On Nov 16, 2014, at 1:05 PM, Chris Jackson <ch...@cd-jackson.com> wrote:

I've created a PR for the zwave initialisation updates. This is still a long way off being merged, but I wanted to make it visible so people can comment on it since it's a big change to the binding. Basically, this should hopefully improve the performance of the initialisation, and also make it easier to enhance later. Previously, the initialisation code was scattered throughout the command classes, making it difficult to maintain, test, and modify. This has all been brought into a single class. Other changes have been made to improve performance, such as delaying battery node initialisation until mains nodes have completed (since they can't be initialised until they wakeup anyway!).

It's still work in progress, and there will be further changes, but review and comments appreciated. https://github.com/openhab/openhab/pull/1678. I'll probably give it a week or so of testing before I make a release version available - just to try and weed out the major problems (although it seems to be working nicely at the moment!)

Below is the overview of the initialisation process... I still have some features to add...

Cheers

Chris

Node initialisation is handled solely within the NodeStageAdvancer. It is not
based on time - it waits for the transactions to complete. Time cannot be

used since with larger networks, it may take a long time for the

--
You received this message because you are subscribed to the Google Groups "openhab" group.
To unsubscribe from this group and stop receiving emails from it, send an email to openhab+u...@googlegroups.com.
To post to this group, send email to ope...@googlegroups.com.
Visit this group at http://groups.google.com/group/openhab.
For more options, visit https://groups.google.com/d/optout.

[Chris Jackson]

I've now generated a binary and loaded it to the HABmin site (https://github.com/cdjackson/HABmin/blob/master/addons/org.openhab.binding.zwave-1.6.0-SNAPSHOT.jar) .

I am finding that this is initialising much better than the old system - my battery devices initialise quickly (after they wake up of course) and powered devices are definitely quicker... It also seems a lot more reliable.

One area that does need to be looked at is making sure that all classes/items are initialising fully. I found yesterday that I'd missed some endpoint initialisation, and I've also added some code to reduce the number of command classes that are requested for multi-instance initialisation (eg removing classes that I think can never be multi-instance classes, like wakeup, association, configuration and no-op). The initialisation phase is 'busy' so removing unnecessary messages from the mix all helps to reduce network congestion, and improve speed and reliability...

I still have some changes to make, but if anyone is game, I'd welcome feedback from a few people to see firstly if it works :) but then to make sure it's ok with different devices and different item configurations (different endpoints etc).

Cheers

Chris

[Ben Jones]

Good timing - just doing a few tweaks which will involve restarting my server. Don't do that very often these days! So will use this new version of the binding and see how it fares. Stand by...

BTW - should I delete my /etc/zwave folder and let it reinitialise everything from scratch? Or safe to copy my /etc/zwave/1.6 config files to /etc/zwave?

[Chris Jackson]

Hey Ben,
I think the binding will not use the files anyway as there’s some more info stored, but to be safe, it’s possibly best to delete them (or not copy them from the 1.6 folder down into the zwave folder).

Good luck :) - let me know how it goes… Hopefully it won’t make you restart more often :)

Cheers
Chris

[Ryan Press]

Thanks Chris!

I just gave this a go and now my CT30 thermostat comes up right away,
whereas before it was hit or miss.

I did need to add my id 0x0158 and type 0x1E10 to the products.xml
under CT30. If you want me to do a separate feature request for this
let me know.

Thanks,
Ryan

[Ben Jones]

I have been following your threads but I can't quite recall exactly what I need to do with respect to end points. Must all item bindings now have an endpoint specified? 

E.g. for a simple flood sensor I currently have;

Number         Sensor_FloodBattery              "Flood Sensor [%.0f %%]"                   <battery>        (SensorBattery100)   { zwave="17:command=BATTERY" }

Does this need to change?

[Chris Jackson]

I think this will be ok (battery I think should be at the root anyway - i.e. no endpoint). Some sensors may change, and I think my Fibaro relay switches had to change - especially if you’re not using an endpoint (i.e. letting it default to 1) then you’ll probably need to add it.

I think if you’ve got an endpoint of 2 or higher, then it is ok - it’s just the 1s that could change.

[Chris Jackson]

> I just gave this a go and now my CT30 thermostat comes up right away,
> whereas before it was hit or miss.

:)

Phew - that’s great - thanks.

> I did need to add my id 0x0158 and type 0x1E10 to the products.xml
> under CT30. If you want me to do a separate feature request for this
> let me know.

I’ll add it - thanks.

[Ben Jones]

I am seeing a load of;

No command class found for item = Door_BackDoor, command class name = sensor_binary, using 0 refresh interval.

My item binding is;

Contact         Door_BackDoor                 "Back Door [%s]"                     <frontdoor>      (DoorsExternal)           { zwave="29:1:command=SENSOR_BINARY,respond_to_basic=TRUE" }

Is this a case of having to remove the end point?

[Ben Jones]

Minor bug noticed in debug log for multilevel sensor report...

2014-11-24 09:20:24.707 DEBUG o.o.b.z.i.p.c.ZWaveMultiLevelSensorCommandClass[:153]- NODE %d: Sensor Value = (10)

[Ben Jones]

All seems to be ok now - although my controller is marked as DEAD and won't recover. Everything is working ok (i.e. the controller is sending/receiving messages) but each time I restart it comes up dead. It even completes a HEAL ok.

Log attached...

[Gert Konemann]

I have the same problem as Ben. And after some time it gets worse. Node 2 and 3 (GreenWave NP210 powerbars) are declared dead too. As i trust the zwave binding to control my central heating, I went back to the previous version of the binding. Here is my console log.

Gert Könemann

Op zondag 23 november 2014 21:53:32 UTC+1 schreef Ben Jones:

[dan cunningham]

Giving it a go now.

On Sun, Nov 23, 2014 at 11:18 AM, Chris Jackson <ch...@cd-jackson.com> wrote:

--

[Ben Jones]

Did some digging around Chris. The problem is in ZWaveNodeStageAdvancer.advanceNodeStage() when you detect the controller node during the PING stage, and terminate initialisation by setting the node stage to DONE.

After the end of the switch statement sendMessage() is called which returns false, since there is nothing in the queue. Therefore the node stage is advanced, and it moves into INIT (which is directly after DONE in the enumeration)). INIT isn't handled by the advancer so it assumes there is a problem and marks the node as DEAD.

So I guess there needs to be some check for a DONE node before you do the advancing? Think it should be a pretty simple fix and as I mentioned, everything is running fine aside from this state indicator.

Great work as usual!

[Chris Jackson]

Hi Ben,

Thanks - sorry for the slow response - the root hard disk on my server decided to throw a wobbly last night and it took me a while to work out and get email back up...

I'll take a look at this tonight if I can (am travelling to Germany though :( ).

Cheers

Chris

[Chris Jackson]

Hi Gert,

Unfortunately the log isn't very useful as it's only logging warnings. Are you able to produce one with debug enabled? Also, can you tell me what the devices are?

Once the devices are initialised, the binding should work the same as the old one, so it shouldn't get worse, but a debug log would be really useful.

Cheers

Chris

[Herbert Altmann]

Hello,

first of all many thanks to Chris for this Binding.

I have issues with the latest version of the bindig. I used a long time a version from August and had only the issue, that sometimes (e.g. once a week) there was an exception which causes to stop OH. So i decided to go with a version from this weekend, but with this i have the problem, that my battery devices (6 fibaro smoke sensors, 1 vision siren and 1 vision smoke soensor) are initialized very slowly, something never. So i happy to see that the initialisation is new, and i tried this, but now are the battery devices and some of my wall plugs not initilized. The wall plugs are not in the Database because i dont find them in the pebble db. I have debug logging activated, what of the log should i attach? And is it possible to only log some intresting nodes?

Update: Forgot to write: The wall plugs are these: http://www.taphome.eu/en/easyplug-details.html and i have datapoints which show the date and time, when the battery device send last message (lastupdate) and these datapoints are correctly updated but in habmin i dont see the descriptions of the devices and they are grey.

Nodes 3,5,6,7 are the wall plugs

Nodes 2,8,9,10,18,20 are fibaro smoke sensors

Node 11 is a vision smoke sonsor

Herbert

Hope you understand my english ;)

[Chris Jackson]

Hi Herbert,

Yes, please provide the log and I'll take a look. It's not possible to only log some nodes, but I can easily filter. If you don't want to post the log to the group, you can email it to me at chris -at- cd-jackson.com.

I'll be working strange (and long) hours this week so I'm not sure exactly when I'll look at it, but I'll try and do so in the next day or three.

Cheers

Chris

[Herbert Altmann]

Hi Chris,

here is the log. I have filtered it. So when you need more, i can send i have also a debog.log of the binding from the weekend.

Thanks in advice,

Herbert

[Herbert Altmann]

Hi,

here you can compare the created XML from August and from now.

Herbert

Am Montag, 24. November 2014 10:13:06 UTC+1 schrieb Herbert Altmann:

Hi Chris,

here is the log. I have filtered it. So when you need more, i can send i have also a debog.log of the binding from the weekend.

Thanks in advice,

Herbert

Am Montag, 24. November 2014 09:31:14 UTC+1 schrieb Chris Jackson:

[Ben Jones]

Chris - I have just made a quick change to try and resolve this controller initialisation bug - I have created a pull request against your zwave-initialisation branch if you want to have a look - feel free to make any changes or ignore if I am wrong! But I am running that code on my server now and everything is looking pretty good - the controller is no longer DEAD so now just waiting for my battery sensors to wakeup a few times and complete etc.

If any one is interested in this patched version ping me on here and I will post it.

[Chris Jackson]

Thanks Ben,

I’ll take a look now and see if I can compile up a new version before I hit the hay.

Cheers

Chris

On 24 Nov 2014, at 20:28, Ben Jones <ben.j...@gmail.com> wrote:

Chris - I have just made a quick change to try and resolve this controller initialisation bug - I have created a pull request against your zwave-initialisation branch if you want to have a look - feel free to make any changes or ignore if I am wrong! But I am running that code on my server now and everything is looking pretty good - the controller is no longer DEAD so now just waiting for my battery sensors to wakeup a few times and complete etc.

If any one is interested in this patched version ping me on here and I will post it.

[Chris Jackson]

I’ve updated the JAR on the HABmin repo - thanks for the update Ben.

Cheers
Chris

[Chris Jackson]

Hi Herbert,
Looking at these XML files, they both have dates from before the new version. Maybe it’s worth deleting the XML files to ensure they are refreshed.

I don’t see anything obviously wrong with your battery nodes, but they don’t seem to respond to messages when they wake up - I’m not sure why. I will try and take a better look at this tomorrow to see if I can understand it better.

Cheers
Chris

[Ben Jones]

I was seeing this yesterday as well (before my patch). And my patch shouldn't have changed anything so I am sure it will still be an issue.

My battery nodes are only configured to wake up every 6 hours so I have to wait a while but I will keep an eye out.

Attached are my logs from startup yesterday till when I restarted this morning. 

[Chris Jackson]

Thanks Ben,

I’m finding my battery nodes come up straight away (i.e. when they first wake up, they run right through initialisation first time). I’ll take a look at your log tomorrow as well…

Cheers

Chris

--
You received this message because you are subscribed to the Google Groups "openhab" group.
To unsubscribe from this group and stop receiving emails from it, send an email to openhab+u...@googlegroups.com.
To post to this group, send email to ope...@googlegroups.com.
Visit this group at http://groups.google.com/group/openhab.
For more options, visit https://groups.google.com/d/optout.

<zwave.zip>

[Ben Jones]

So far this morning (grepping 'BATTERY' on my debug log);

2014-11-25 10:19:30.846 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:457]- NODE 21: Node advancer: DYNAMIC_VALUES - checking BATTERY
2014-11-25 10:19:30.846 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:460]- NODE 21: Node advancer: DYNAMIC_VALUES - found    BATTERY
2014-11-25 10:19:30.846 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:464]- NODE 21: Found 0 instances of BATTERY
2014-11-25 10:20:16.228 DEBUG o.o.b.z.i.c.ZWaveBatteryConverter[:60]- Generating poll message for BATTERY for node 21 endpoint 0
2014-11-25 10:20:16.229 DEBUG o.o.b.z.i.p.c.ZWaveBatteryCommandClass[:106]- Node 21: Creating new message for application command BATTERY_GET
2014-11-25 11:03:13.145 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:457]- NODE 33: Node advancer: DYNAMIC_VALUES - checking BATTERY
2014-11-25 11:03:13.145 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:460]- NODE 33: Node advancer: DYNAMIC_VALUES - found    BATTERY
2014-11-25 11:03:13.145 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:464]- NODE 33: Found 0 instances of BATTERY
2014-11-25 11:03:16.269 DEBUG o.o.b.z.i.c.ZWaveBatteryConverter[:60]- Generating poll message for BATTERY for node 33 endpoint 0
2014-11-25 11:03:16.270 DEBUG o.o.b.z.i.p.c.ZWaveBatteryCommandClass[:106]- Node 33: Creating new message for application command BATTERY_GET
2014-11-25 11:20:16.285 DEBUG o.o.b.z.i.c.ZWaveBatteryConverter[:60]- Generating poll message for BATTERY for node 21 endpoint 0
2014-11-25 11:20:16.285 DEBUG o.o.b.z.i.p.c.ZWaveBatteryCommandClass[:106]- Node 21: Creating new message for application command BATTERY_GET
2014-11-25 11:56:19.430 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:457]- NODE 20: Node advancer: DYNAMIC_VALUES - checking BATTERY
2014-11-25 11:56:19.430 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:460]- NODE 20: Node advancer: DYNAMIC_VALUES - found    BATTERY
2014-11-25 11:56:19.430 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:464]- NODE 20: Found 0 instances of BATTERY
2014-11-25 11:57:16.318 DEBUG o.o.b.z.i.c.ZWaveBatteryConverter[:60]- Generating poll message for BATTERY for node 20 endpoint 0
2014-11-25 11:57:16.318 DEBUG o.o.b.z.i.p.c.ZWaveBatteryCommandClass[:106]- Node 20: Creating new message for application command BATTERY_GET
2014-11-25 12:03:16.324 DEBUG o.o.b.z.i.c.ZWaveBatteryConverter[:60]- Generating poll message for BATTERY for node 33 endpoint 0
2014-11-25 12:03:16.324 DEBUG o.o.b.z.i.p.c.ZWaveBatteryCommandClass[:106]- Node 33: Creating new message for application command BATTERY_GET
2014-11-25 12:20:16.338 DEBUG o.o.b.z.i.c.ZWaveBatteryConverter[:60]- Generating poll message for BATTERY for node 21 endpoint 0
2014-11-25 12:20:16.338 DEBUG o.o.b.z.i.p.c.ZWaveBatteryCommandClass[:106]- Node 21: Creating new message for application command BATTERY_GET
2014-11-25 12:41:32.798 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:457]- NODE 31: Node advancer: DYNAMIC_VALUES - checking BATTERY
2014-11-25 12:41:32.798 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:460]- NODE 31: Node advancer: DYNAMIC_VALUES - found    BATTERY
2014-11-25 12:41:32.799 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:464]- NODE 31: Found 0 instances of BATTERY
2014-11-25 12:42:16.356 DEBUG o.o.b.z.i.c.ZWaveBatteryConverter[:60]- Generating poll message for BATTERY for node 31 endpoint 0
2014-11-25 12:42:16.356 DEBUG o.o.b.z.i.p.c.ZWaveBatteryCommandClass[:106]- Node 31: Creating new message for application command BATTERY_GET
2014-11-25 12:57:16.368 DEBUG o.o.b.z.i.c.ZWaveBatteryConverter[:60]- Generating poll message for BATTERY for node 20 endpoint 0
2014-11-25 12:57:16.368 DEBUG o.o.b.z.i.p.c.ZWaveBatteryCommandClass[:106]- Node 20: Creating new message for application command BATTERY_GET

So the battery nodes are initialising ok, just remains to be seen if they respond to those battery requests when they wake up next time...

[Chris Jackson]

This is actually something I’m seeing here - the battery nodes (apparently) complete initialisation ok, but I’m still not seeing the battery level displayed.  I noticed this yesterday, but forgot to follow it up.

Off to bed though, so it’ll be one to look at tomorrow.

Cheers

Chris

[Ben Jones]

Chris, all my battery nodes have reported a battery state message in the last couple of hours so everything is looking pretty good at this stage.

[Chris Jackson]

Ok - cool. So everything is looking good for you then?

I'll check what's happening on my system when I get back to the hotel tonight...

Cheers

Chris

[Ben Jones]

Seems to be yes - haven't noticed any issues at all and all nodes are initialised and happily reporting events etc.

Looks like your changes are a winner! A bit like the ABs...

[Chris Jackson]

Looks like your changes are a winner! A bit like the ABs...

:)

Well, at least one of the above was always going to be the case (although I was a little worried during the England game!).

I tried for tickets to the world cup next year - nada :(

Chris 

[dan cunningham]

First off thanks for the tireless work Chris, really awesome. I just installed the latest jar ( with Ben's changes), startup is quick which is good, it finds all my nodes, identifies them and gets all the way to dynamic values where its failing for all 28 of my nodes, none of them are battery powered.  Whats interesting is that from the logs it sees that a node supports "SWITCH_MULTILEVEL" but then reports there are no instances and moves on.  It's morning here, I probably won't get a chance to go through the code until tonight when I get back home.  

2014-11-25 07:12:51.493 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:164]- NODE 15: Node advancer - checking initialisation queue.

2014-11-25 07:12:51.494 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:169]- NODE 15: Node advancer - message removed from queue. Queue size now 0.

2014-11-25 07:12:51.494 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:229]- NODE 15: Node advancer - NEIGHBORS: queue length(0), free to send(true)

2014-11-25 07:12:51.494 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:256]- NODE 15: Node advancer: loop - NEIGHBORS: stageAdvanced(false)

2014-11-25 07:12:51.494 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:544]- NODE 15: Node advancer - advancing to SESSION.

2014-11-25 07:12:51.495 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:256]- NODE 15: Node advancer: loop - SESSION: stageAdvanced(true)

2014-11-25 07:12:51.495 ERROR o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:529]- NODE 15: Node advancer: Unknown node state SESSION encountered.

2014-11-25 07:12:51.495 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:544]- NODE 15: Node advancer - advancing to DYNAMIC_VALUES.

2014-11-25 07:12:51.496 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:256]- NODE 15: Node advancer: loop - DYNAMIC_VALUES: stageAdvanced(true)

2014-11-25 07:12:51.496 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:457]- NODE 15: Node advancer: DYNAMIC_VALUES - checking ASSOCIATION

2014-11-25 07:12:51.496 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:460]- NODE 15: Node advancer: DYNAMIC_VALUES - found    ASSOCIATION

2014-11-25 07:12:51.496 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:464]- NODE 15: Found 0 instances of ASSOCIATION

2014-11-25 07:12:51.497 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:457]- NODE 15: Node advancer: DYNAMIC_VALUES - checking SCENE_ACTIVATION

2014-11-25 07:12:51.497 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:457]- NODE 15: Node advancer: DYNAMIC_VALUES - checking BASIC

2014-11-25 07:12:51.497 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:457]- NODE 15: Node advancer: DYNAMIC_VALUES - checking MANUFACTURER_SPECIFIC

2014-11-25 07:12:51.497 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:457]- NODE 15: Node advancer: DYNAMIC_VALUES - checking SWITCH_MULTILEVEL

2014-11-25 07:12:51.498 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:460]- NODE 15: Node advancer: DYNAMIC_VALUES - found    SWITCH_MULTILEVEL

2014-11-25 07:12:51.498 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:464]- NODE 15: Found 0 instances of SWITCH_MULTILEVEL

2014-11-25 07:12:51.498 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:457]- NODE 15: Node advancer: DYNAMIC_VALUES - checking VERSION

2014-11-25 07:12:51.498 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:457]- NODE 15: Node advancer: DYNAMIC_VALUES - checking NO_OPERATION

2014-11-25 07:12:51.499 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:492]- NODE 15: Node advancer: DYNAMIC_VALUES - queued 0 frames

2014-11-25 07:12:51.499 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:544]- NODE 15: Node advancer - advancing to CONFIG.

2014-11-25 07:12:51.499 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:256]- NODE 15: Node advancer: loop - CONFIG: stageAdvanced(true)

2014-11-25 07:12:51.500 ERROR o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:529]- NODE 15: Node advancer: Unknown node state CONFIG encountered.

2014-11-25 07:12:51.500 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:544]- NODE 15: Node advancer - advancing to DONE.

2014-11-25 07:12:51.500 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:256]- NODE 15: Node advancer: loop - DONE: stageAdvanced(true)

2014-11-25 07:12:51.501 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:507]- NODE 15: Node advancer: Initialisation complete!

On Tue, Nov 25, 2014 at 2:41 AM, Chris Jackson <ch...@cd-jackson.com> wrote:

Looks like your changes are a winner! A bit like the ABs...

:)

Well, at least one of the above was always going to be the case (although I was a little worried during the England game!).

I tried for tickets to the world cup next yead - nada :(

Chris 

[Chris Jackson]

Thanks Dan,
Sounds like it’s getting there - I think there might be a few issues to iron out yet, but I’m confident that this will ultimately improve the binding initialisation…

I suspect that this may be the same issue as the battery ’non initialisation'. In theory, the battery level should be read during the dynamic value stage, so I think there’s something up there… I’ve also just noticed that my log file from last night is REALLY big - I’m in Germany at the mo, so it’s taking a ‘few minutes’ to download! :(

I’ll probably go and grab some dinner and take a look a little later.

Cheers
Chris

[Chris Jackson]

Hi Dan,
Do you know if these devices support multiple instances, and if so, what version of the multi_endpoint class?

Chris

[Ben Jones]

Hey Chris,

See the attached log, in particular node 26. It is a Fibaro Dimmer module and has never been a problem before, but for some reason it is failing during the heal process and is being reported as red in HABMin. I have just done a manual HEAL and it gets most of the way through before throwing a few errors. It is then reported as DONE in the heal status in HABMin (see screenshot). 

But the node is still red. Can't quite work out what the problem is, and the node seems to be working fine.

Let me know if you find anything.

Cheers,

Ben

[dan cunningham]

They do not, nearly all of them are the leviton dimmer or switch
models and are a single endpoint

Sent from my mobile.

[Chris Jackson]

Hmmm - ok, that’s probably the problem then :)

I set the number of instances to 0, to show that the class isn’t initialised - it then gets set to 1 (or more) when the initialisation is done, but there’s nothing to set it to 1 if the multi_instance class isn’t supported… I’ll add something to try and work around this, but you’ll need to test as it’s not something I’ve come across (knowingly anyway!).

[dan cunningham]

Sounds great , thanks!

Sent from my mobile.

[Ben Jones]

Hey Chris, I just had a bit of a dig around my logs and noticed the following;

At 2am every morning the ZWave binding schedules a heal. This places a series of requests on the wake up queue of each of my battery nodes. Because these nodes only process the heal messages when they wake up and usually only get enough time to process one or two, the wakeup queue stays pretty full all day (especially for me with my 6 hour wakeup interval). 

When the binding then periodically sends the BATTERY_GET requests, these also get queued, but I am guessing get placed at the end of the queue, or at least after the HEAL requests. This means that even though my nodes are waking up every 6 hours they only finally get to the BATTERY_GET messages very late in the day after all the HEAL requests have been processed.

Obviously your new code has changed the way the wakeup queue is handled but I am wondering if the daily HEAL should be scheduled for battery nodes at all? But I guess you have to do it, otherwise those nodes will never get 'fixed up' when things are moved around. What will happen if the previous days HEAL requests haven't finished being processed before 2am the following day? Perhaps you can look in the wake up queue and skip the HEAL if the previous one hasn't finished?

That leaves the BATTERY_GET requests - can you give priorities to message types? If you made the HEAL requests the lowest priority then any BATTERY_GET requests and/or CONFIG_GET/SET requests would be processed first during the wakeup interval and the HEAL requests would only be processed last.

I think this explains why you weren't seeing battery updates, and why I have only seen one or two in the last 48 hours.

Cheers,

Ben

[Chris Jackson]

Hi Ben,
The new initialisation code shouldn’t have changed the way the heal works, or the way the wakeup queue is managed, so I would have expected this to have been the same as it’s been for quite a while…

The heal code shouldn't generate messages for the battery nodes at 2am. The way it’s meant to work is that battery nodes get healed (or queued for healing) at 2am, but no frames should be queued. It uses the ‘listening’ flag for this (i.e. if a node isn’t permanently listening, then it shouldn’t be ‘actively’ healed). As I said though, the battery nodes are still healed (or we try to anyway!), but this is triggered on a wakeup - the network monitor heal code has an event handler that waits for a node to wake, and then tries to progress the heal by sending the next frame. Maybe it’s this that’s happening, and you’re getting frames queued due to this, and not actually at the 2am point? If things aren’t working as expected, then maybe what you’re seeing is the backlog starting at the next wakeup after the first 2am after you start the binding (if you follow that?).

I still think battery nodes should be healed. The heal process is mostly about making sure that return routes are set if the network changes. Battery nodes (I think!) still need this information so that they know the route from themselves to (say) a node to which they are associated. Currently, this is only done in the heal process.

If you have a log (or part of) I’d be interested to take a look.

I’m also considering making the main tx queue prioritised. So, we can then set things like polls to a low priority, commands to a high priority, and everything else in the middle. One other ‘really high priority’ is the wakeup queue. The problem with the wakeup queue at the moment is that messages get queued in the nodes wakeup queue, and when the node wakes we offload these messages into the main tx queue. The problem here is that if there are a couple of other messages queued in the main tx queue (e.g. polls) then these messages for the battery node go on the end of the tx queue - I think they really need to bump the queue as the device is only going to be awake for a few seconds! Anyway, that is something I want to think about after the initialisation updates. I don’t think the queueing is a difficult change, but I want to stabilise the current changes first :)

Cheers
Chris

[Chris Jackson]

I’ve just put a new binding version on the HABmin site. This does the endpoint initialisation if the multi_instance class isn’t supported. Ben - I think this might also explain why the battery nodes weren’t updated during the initialisation. I looked back through my logs and found the same “0 instances” message Dan found, for the battery class, so the battery level wasn’t requested during initialisation (this check isn’t applicable after initialisation).

Chris

[Ben Jones]

What you have explained makes sense and agrees with what I was seeing. I obviously don't quite understand the code as well as you (I don't think anyone does!) so it was all just speculation! I only noticed these lack of battery reports as I have some 'activity items' which get updated when a sensor sends a battery report. If there is no activity for more than 6 hours the UI shows a different colour and I very rarely used to see this happen. 

I am more than confident however that you have it all in hand!

One thing I noticed tonight is that my 2x1.5kW relays are not being updated in openHAB when the switches are manually flicked. I had a look in the logs and saw this for one of them (the first event is me switching the light via openHAB, the second is when switching manually);

2014-11-26 22:14:00.440 DEBUG o.o.b.z.i.p.SerialMessage[:108]- NODE 7: Creating empty message of class = SendData (0x13), type = Request (0x00)

2014-11-26 22:14:00.441 DEBUG o.o.b.z.i.protocol.ZWaveNode[:567]- NODE 7: Encapsulating message, instance / endpoint 1

2014-11-26 22:14:00.441 DEBUG o.o.b.z.i.p.c.ZWaveMultiInstanceCommandClass[:510]- NODE 7: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1

2014-11-26 22:14:00.441 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1102]- NODE 7: Sending REQUEST Message = 01 0E 00 13 07 07 60 0D 01 01 25 01 00 25 74 FA

2014-11-26 22:14:00.442 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1117]- NODE 7: Wait for response

2014-11-26 22:14:00.461 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:69]- NODE 7: SendData Request. CallBack ID = 116, Status = Transmission complete and ACK received(0)

2014-11-26 22:14:20.131 DEBUG o.o.b.z.i.p.s.ApplicationCommandMessageClass[:37]- NODE 7: Application Command Request (Stage: DONE)

2014-11-26 22:14:20.131 DEBUG o.o.b.z.i.p.s.ApplicationCommandMessageClass[:56]- NODE 7: Incoming command class SWITCH_BINARY (0x25)

2014-11-26 22:14:20.132 DEBUG o.o.b.z.i.ZWaveActiveBinding[:421]- NODE 7: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 255

Looks like the endpoint is wrong which is why it is not being updated in openHAB. Any ideas if your other fix is related?

[Ben Jones]

It is only endpoint 1 that fails to update, endpoint 2 is ok;

Here is another node; with me manually switching both switches in turn (a few secs apart);

2014-11-26 22:22:25.313 DEBUG o.o.b.z.i.p.s.ApplicationCommandMessageClass[:37]- NODE 11: Application Command Request (Stage: DONE)

2014-11-26 22:22:25.313 DEBUG o.o.b.z.i.p.s.ApplicationCommandMessageClass[:56]- NODE 11: Incoming command class MULTI_INSTANCE (0x60)

2014-11-26 22:22:25.313 DEBUG o.o.b.z.i.p.c.ZWaveMultiInstanceCommandClass[:137]- NODE 11: Received Multi-instance/Multi-channel Request

2014-11-26 22:22:25.313 DEBUG o.o.b.z.i.p.c.ZWaveMultiInstanceCommandClass[:402]- NODE 11: Requested Command Class = SWITCH_BINARY (0x25)

2014-11-26 22:22:25.313 DEBUG o.o.b.z.i.p.c.ZWaveMultiInstanceCommandClass[:422]- NODE 11: Endpoint = 2, calling handleApplicationCommandRequest.

2014-11-26 22:22:25.313 DEBUG o.o.b.z.i.ZWaveActiveBinding[:421]- NODE 11: Got a value event from Z-Wave network, endpoint = 2, command class = SWITCH_BINARY, value = 255

2014-11-26 22:22:28.511 DEBUG o.o.b.z.i.p.s.ApplicationCommandMessageClass[:37]- NODE 11: Application Command Request (Stage: DONE)

2014-11-26 22:22:28.511 DEBUG o.o.b.z.i.p.s.ApplicationCommandMessageClass[:56]- NODE 11: Incoming command class SWITCH_BINARY (0x25)

2014-11-26 22:22:28.512 DEBUG o.o.b.z.i.ZWaveActiveBinding[:421]- NODE 11: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 0

The first event (relay 2) comes thru as a multi-instance command and gets mapped to the correct endpoint. But the second event (relay 1) doesn't for some reason?

[Chris Jackson]

Hi Ben,

What are your binding strings for this? I suspect that this is a consequence of the endpoint change that was made for 1.6 - if endpoint 1 doesn’t have an endpoint specified (which would have worked with the old binding, but won’t now) then you need to add it -:

Switch Hall_FrontLights "Front Hall Lights" <light> { zwave="9:1" }

Switch Outside_FrontLights "Outside Lights" <light> { zwave="9:2” }

If you just specify { zwave=“9” } then it will not be sent as a multi_endpoint message.

Chris

Chris

[Ben Jones]

Nope - all my dual relay nodes have endpoints specified;

Switch    Light_KitchenBench      "Bench"             <light>      (LightsKitchen)   { zwave="11:1" }

Switch    Light_KitchenIsland     "Island"            <light>      (LightsKitchen)   { zwave="11:2" }

The only things without explicit end points are my dimmers and Fibaro door/window sensors, my AeonLabs MultiSensor and my Fibaro Motion sensor.

Odd.

[Chris Jackson]

Hmmm - ok, you could try removing he endpoint number for the 11:1 string (i.e. just use 11). I’ll need to take a look at this when I get home as I have these switches myself… Unfortunately I’m stuck in Munich for work and won’t be home until Sunday night…

Chris

[Ben Jones]

I might just wait - I try and avoid restarting openHAB too often - can take a while to get everything back up! I will try and have a look around the code today and see if I can spot anything wrong. This definitely used to work fine so I presume it is something to do with the command class initialisation stuff. Although I did start from scratch w.r.t. my config files whereas previously they were just being reloaded so perhaps something changed previously that was being masked by the fact my config files were correctly initialising the nodes ok.

BTW - my battery reports seem to have come right after a few days. I am now seeing a report for each node every 6 hours which is great. It must have been still inside the startup routine before, so the battery reports were not being handled properly. 

[Chris Jackson]

I've just uploaded a new version. This adds the following main changes -:

• improves the handling of the application update message. If this message got lost, then initialisation is heading for failure. Since the binding is mainly looking at the sent message, if a response is somehow out of order, then it was possible to effectively bypass this phase, resulting in a bad initialisation
  
• fixes a bug with the handling of the node stage. This didn't seem to cause any problems if things went ok, but if a node went dead during the initialisation phase, then bad things happened!
• fixes the handling of endpoint initialisation with certain devices

Chris

[Ben Jones]

Thanks Chris - will give this a go in the next couple of days. Bit busy today with a half day of work and then a wedding in the arvo.

[Herbert Altmann]

Hello Chris,

you are the best. With the newest Binding, erverything seems fine. All of my Battery devices are working properly. I only have to softreset my Vision Stick, with pulling it from the PC because the softreset would lock it. After that and deleting all my XML, all nodes are complete after each wakeup.

But one question, is it possible to integrate my wall switches to the db? And is there any solution to find out, which configuration parameters they have? Because they are not in the pepper db!

Herbert

[Chris Jackson]

Hi Herbert,
That’s great news - thanks for the feedback.

I do apologise about the devices - I think we discussed it recently, but I now can’t find the email (I get a lot of requests for database additions and it can get confusing). Can you point me to the information and I’ll try and add it in the coming days.
Regarding finding out what configuration is supported, I’m afraid I can’t help. If the manufacturer won’t provide the information, and you can’t find it elsewhere on the web, then I don’t know how we can find out. It can’t be easily reverse engineered. I would hope that the manufacturer would provide this though - otherwise their device is not useful if they don’t say how to configure it...

Cheers
Chris

[mst...@gmail.com]

Hi Chris,

also from my side a big thank you for all your hard work. I just started to use
OpenHab recently and I have a some battery powered and also some main powered zwave devices.
I am now using yesterday's version from your habmin site and I have to say all is working perfectly.

Yesterday I received an Aeon labs Sirene, which is not yet in the database however. This device is giving some trouble but I don't think the binding is the problem here....

Again, thank you very much!

Regards,
Matt

[Chris Jackson]

Thanks for the feedback Matt.

> Yesterday I received an Aeon labs Sirene, which is not yet in the database however. This device is giving some trouble but I don't think the binding is the problem here....

I’ve just created an entry for this. I’ll try and create a new version for HABmin tonight or tomorrow…

Chris

[mst...@gmail.com]

Wow Chris, that would be awesome.

Thanks!

Cheers,
Matt

[Herbert Altmann]

Hi Chris,

here is a Link to the Wallplugs: http://www.taphome.eu/en/easyplug-details.html

I send an email to the manufacturer asking if they publish the configuration parameters. I hope they do it. But meanwhile i attached you the XML from one of this devices, so you can put the Information in the DB. My problem at the moment is, that i cannot configure a Name for this devices over Habmin, i think this is because they are not in the db.

Herbert

[Chris Jackson]

Thanks - I'll add this to the database when I get off work. If you can get manufacturer information then I'll update it...

Cheers

Chris

[gilles.l...@gmail.com]

Hi Chris,

I think it's not an "urgence" but since your initialisation modification on the binding, my zwave network works badly and the serialisation isn't done.

As I watch my debug log I see that is my vera ( used as secondary controller ) which is the origin of my zwave problem.

Here is an extract:

2014-11-29 10:33:26.387 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:696]- NODE 1: Node advancer - ENDPOINTS: Transaction complete (SendData:Request) success(true)
2014-11-29 10:33:26.388 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:164]- NODE 1: Node advancer - checking initialisation queue.
2014-11-29 10:33:26.388 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:169]- NODE 1: Node advancer - message removed from queue. Queue size now 0.
2014-11-29 10:33:26.389 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:229]- NODE 1: Node advancer - ENDPOINTS: queue length(0), free to send(true)
2014-11-29 10:33:26.389 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:256]- NODE 1: Node advancer: loop - ENDPOINTS: stageAdvanced(false)
2014-11-29 10:33:26.389 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:409]- NODE 1: Node advancer: ENDPOINTS - MultiInstance is supported
2014-11-29 10:33:26.390 DEBUG o.o.b.z.i.p.c.ZWaveMultiInstanceCommandClass[:538]- NODE 1: Initialising endpoints - version 2
2014-11-29 10:33:26.390 DEBUG o.o.b.z.i.p.c.ZWaveMultiInstanceCommandClass[:478]- NODE 1: Creating new message for command MULTI_CHANNEL_ENDPOINT_GET
2014-11-29 10:33:26.391 DEBUG o.o.b.z.i.p.SerialMessage[:108]- NODE 1: Creating empty message of class = SendData (0x13), type = Request (0x00)
2014-11-29 10:33:26.392 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:411]- NODE 1: Node advancer: ENDPOINTS - queued 1 frames
2014-11-29 10:33:26.392 DEBUG o.o.b.z.i.p.ZWaveController[:841]- Callback ID = 168
2014-11-29 10:33:26.393 DEBUG o.o.b.z.i.p.ZWaveController[:468]- Enqueueing message. Queue length = 23
2014-11-29 10:33:26.393 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:202]- NODE 1: Node advancer - queued packet. Queue length is 1
2014-11-29 10:33:26.394 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1159]- Response processed after 77ms/4997ms.
2014-11-29 10:33:26.395 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1067]- Took message from queue for sending. Queue length = 22
2014-11-29 10:33:26.396 DEBUG o.o.b.z.i.p.SerialMessage[:226]- Assembled message buffer = 01 09 00 13 01 02 60 07 25 A8 0C
2014-11-29 10:33:26.397 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1102]- NODE 1: Sending REQUEST Message = 01 09 00 13 01 02 60 07 25 A8 0C
2014-11-29 10:33:26.406 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:1276]- Receive Message = 01 04 01 13 01 E8
2014-11-29 10:33:26.409 DEBUG o.o.b.z.i.p.ZWaveController[:165]- Message: class = SendData (0x13), type = Response (0x01), payload = 01
2014-11-29 10:33:26.410 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:35]- Sent Data successfully placed on stack.
2014-11-29 10:33:26.423 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:1276]- Receive Message = 01 05 00 13 A8 00 41
2014-11-29 10:33:26.424 DEBUG o.o.b.z.i.p.ZWaveController[:165]- Message: class = SendData (0x13), type = Request (0x00), payload = A8 00
2014-11-29 10:33:26.425 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:69]- NODE 1: SendData Request. CallBack ID = 168, Status = Transmission complete and ACK received(0)
2014-11-29 10:33:26.425 DEBUG o.o.b.z.i.p.s.ZWaveCommandProcessor[:55]- Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=fals
e
2014-11-29 10:33:26.480 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:1276]- Receive Message = 01 18 00 04 00 3E 12 60 0D 02 00 32 02 21 74 00 04 8D 46 00 00 85
AC 7D E5 BB
2014-11-29 10:33:26.484 DEBUG o.o.b.z.i.p.ZWaveController[:165]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 3E 12 60 0D 02 00 32 02 21 74 00 04 8D 46 00 00 85 AC 7D E5
2014-11-29 10:33:26.485 DEBUG o.o.b.z.i.p.s.ApplicationCommandMessageClass[:37]- NODE 62: Application Command Request (Stage: PING)
2014-11-29 10:33:26.486 DEBUG o.o.b.z.i.p.s.ApplicationCommandMessageClass[:56]- NODE 62: Incoming command class MULTI_INSTANCE (0x60)
2014-11-29 10:33:26.487 DEBUG o.o.b.z.i.p.c.ZWaveMultiInstanceCommandClass[:138]- NODE 62: Received Multi-instance/Multi-channel Request
2014-11-29 10:33:26.487 DEBUG o.o.b.z.i.p.c.ZWaveMultiInstanceCommandClass[:406]- NODE 62: Requested Command Class = METER (0x32)
2014-11-29 10:33:26.488 ERROR o.o.b.z.i.p.c.ZWaveMultiInstanceCommandClass[:410]- NODE 62: Endpoint 2 not found. Cannot set command classes.
2014-11-29 10:33:26.489 DEBUG o.o.b.z.i.p.s.ZWaveCommandProcessor[:55]- Checking transaction complete: class=ApplicationCommandHandler, expected=ApplicationCommandHandler, cancelled=false
2014-11-29 10:33:26.490 DEBUG o.o.b.z.i.p.s.ZWaveCommandProcessor[:58]-          transaction complete!

As I say it's not an emergency but it could be usefull and revelant to understand for your binding.

Cheers,

Gilles.

[Chris Jackson]

Hi Gilles,

Are you using the latest version (ie from Thursday I think)?

Which node is the Vera - is that node 1? Can you supply a longer log and also the XML file for the Vera (from an older version if it's not saving now).

Thanks

Chris

[Herbert Altmann]

Hello Chris,

i research a little bit and found some devices which look very similar to my wall plug. Is it possible to integrate this configuration parameters to my plugs and i try if this okay?

Here you can find it: http://manuals.zwaveeurope.com/make.php?lang=en&type=&sku=ZME_064374

and in the pepper-db: http://www.pepper1.net/zwavedb/device/567

Thanks,

Herbert

[Chris Jackson]

Hi Herbert,
I’d be a little hesitant to add this into the database without being reasonably sure it’s the same. This device supports 2 association classes where yours only has 1 (from the XML file you sent, and this comes from what the device is reporting), so it’s at least not the same device with a different badge on the front.

i’d suggest seeing first how we get on with getting information from the manufacturer for configuration. I’ll make a file this afternoon with the basic stuff in it, so the device will show up in the database, and I’ll add the associations since I can confirm the number of groups at least. The only things then that it won’t support is configuration, but without the information from the manufacturer, or another such source, then we’re guessing, and it might mean we configure the device incorrectly (which might not be good).

Cheers
Chris

[gilles.l...@gmail.com]

Hi Chris,

Sorry for my late answer.

Yes the version is since 27/11. from your github.



I can confirm that if vera is present and I restart openhab, initialisation isn't possible and serialization too.

You can see that in the log. if you want more information, don't hésitate to ask me.

May I ask you other thing, My SSA3 seems to be dead with this bind version, to be sure could you (when it's possible) add SSA3 siren so I can see if it's the problem.

To be sure I will see with ozwcp.

Really thank you,

Cheers,

Gilles.

[Chris Jackson]

Hi Gilles,

Thanks.

Can you please send me the nodeId / type of your SSA3. I added the SSA1 a few weeks back - I wasn’t aware that it was different, so maybe I’ve got the type or id wrong.

Thanks

Chris

On 29 Nov 2014, at 13:30, gilles.l...@gmail.com wrote:

Hi Chris,

Sorry for my late answer.

I can confirm that if vera is present and I restart openhab, initialisation isn't possible and serialization too.

You can see that in the log. if you want more information, don't hésitate to ask me.

May I ask you other thing, My SSA3 seems to be dead with this bind version, to be sure could you (when it's possible) add SSA3 siren so I can see if it's the problem.

To be sure I will see with ozwcp.

Really thank you,

Cheers,

Gilles.

Le samedi 29 novembre 2014 11:12:59 UTC+1, Chris Jackson a écrit :

--
You received this message because you are subscribed to the Google Groups "openhab" group.
To unsubscribe from this group and stop receiving emails from it, send an email to openhab+u...@googlegroups.com.
To post to this group, send email to ope...@googlegroups.com.
Visit this group at http://groups.google.com/group/openhab.
For more options, visit https://groups.google.com/d/optout.

<zwave_with_vera.log>

[gilles.l...@gmail.com]

Chris,

Here is the manual of the SSA3 from Fortrezz.

It works like a dimmer but after initialisation is consider as dead node.

Hoho, I found this device as a dead node in neighbors but before it was not a problem.

The id is 205 and the type is 341. manufacturer id 84

Cheers,

Gilles.

No tracability from pepper1.net

Le samedi 29 novembre 2014 14:56:48 UTC+1, Chris Jackson a écrit :

Hi Gilles,

[Chris Jackson]

Thanks. For now I’ll assume it’s the same as the SSA1 and SSA2 as I can’t find any specific configuration information on the device. I’ll add it tonight.

Chris

--
You received this message because you are subscribed to the Google Groups "openhab" group.
To unsubscribe from this group and stop receiving emails from it, send an email to openhab+u...@googlegroups.com.
To post to this group, send email to ope...@googlegroups.com.
Visit this group at http://groups.google.com/group/openhab.
For more options, visit https://groups.google.com/d/optout.

<fortrezz_ssa-03_manual_us.pdf>

[gilles.l...@gmail.com]

Ok I could you give a feedback about that.

I erase all my xml node then restart openhab and my zwave network don't initialize totally.

In fact my HEM G1 got a problem with controller:

Here is an extract of the log:

2014-11-29 17:25:14.772 DEBUG o.o.b.z.i.p.ZWaveController[:483]- Notifying event listeners
2014-11-29 17:25:14.773 DEBUG o.o.b.z.i.ZWaveActiveBinding[:399]- ZwaveIncomingEvent
2014-11-29 17:25:14.774 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:696]- NODE 61: Node advancer - VERSION: Transaction complete (SendData:Request) success(true)
2014-11-29 17:25:14.774 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:164]- NODE 61: Node advancer - checking initialisation queue.
2014-11-29 17:25:14.775 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:169]- NODE 61: Node advancer - message removed from queue. Queue size now 0.
2014-11-29 17:25:14.775 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:229]- NODE 61: Node advancer - VERSION: queue length(0), free to send(true)
2014-11-29 17:25:14.776 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:256]- NODE 61: Node advancer: loop - VERSION: stageAdvanced(false)
2014-11-29 17:25:14.776 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:369]- NODE 61: Node advancer: VERSION - checking ASSOCIATION, version is 1
2014-11-29 17:25:14.777 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:369]- NODE 61: Node advancer: VERSION - checking METER, version is 2
2014-11-29 17:25:14.777 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:369]- NODE 61: Node advancer: VERSION - checking MANUFACTURER_SPECIFIC, version is 1
2014-11-29 17:25:14.778 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:369]- NODE 61: Node advancer: VERSION - checking SENSOR_MULTILEVEL, version is 2
2014-11-29 17:25:14.779 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:369]- NODE 61: Node advancer: VERSION - checking MULTI_INSTANCE, version is 2
2014-11-29 17:25:14.779 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:369]- NODE 61: Node advancer: VERSION - checking BATTERY, version is 1
2014-11-29 17:25:14.780 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:369]- NODE 61: Node advancer: VERSION - checking VERSION, version is 1
2014-11-29 17:25:14.780 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:369]- NODE 61: Node advancer: VERSION - checking BASIC, version is 1
2014-11-29 17:25:14.781 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:369]- NODE 61: Node advancer: VERSION - checking CONFIGURATION, version is 1
2014-11-29 17:25:14.781 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:369]- NODE 61: Node advancer: VERSION - checking SWITCH_MULTILEVEL, version is 0
2014-11-29 17:25:14.782 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:372]- NODE 61: Node advancer: VERSION - queued   SWITCH_MULTILEVEL
2014-11-29 17:25:14.782 DEBUG o.o.b.z.i.p.c.ZWaveVersionCommandClass[:163]- NODE 61: Creating new message for application command VERSION_COMMAND_CLASS_GET command class SWITCH_MULTILEVEL
2014-11-29 17:25:14.783 DEBUG o.o.b.z.i.p.SerialMessage[:108]- NODE 61: Creating empty message of class = SendData (0x13), type = Request (0x00)
2014-11-29 17:25:14.784 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:369]- NODE 61: Node advancer: VERSION - checking NO_OPERATION, version is 1
2014-11-29 17:25:14.784 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:381]- NODE 61: Node advancer: VERSION - queued 1 frames
2014-11-29 17:25:14.785 DEBUG o.o.b.z.i.p.ZWaveController[:841]- Callback ID = 157
2014-11-29 17:25:14.785 DEBUG o.o.b.z.i.p.ZWaveController[:468]- Enqueueing message. Queue length = 8
2014-11-29 17:25:14.786 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:202]- NODE 61: Node advancer - queued packet. Queue length is 1
2014-11-29 17:25:14.787 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1159]- Response processed after 20ms/4784ms.
2014-11-29 17:25:14.787 ERROR o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:1291]- Message cancelled by controller (CAN), resending
2014-11-29 17:25:14.787 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1067]- Took message from queue for sending. Queue length = 7
2014-11-29 17:25:14.788 DEBUG o.o.b.z.i.p.SerialMessage[:226]- Assembled message buffer = 01 0A 00 13 3D 03 86 13 26 25 9D D3
2014-11-29 17:25:14.789 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1102]- NODE 61: Sending REQUEST Message = 01 0A 00 13 3D 03 86 13 26 25 9D D3
2014-11-29 17:25:14.888 DEBUG o.o.b.z.i.p.ZWaveController[:468]- Enqueueing message. Queue length = 8
2014-11-29 17:25:14.888 ERROR o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:1291]- Message cancelled by controller (CAN), resending
2014-11-29 17:25:14.888 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1159]- Response processed after 99ms/4784ms.
2014-11-29 17:25:14.889 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1067]- Took message from queue for sending. Queue length = 7
2014-11-29 17:25:14.890 DEBUG o.o.b.z.i.p.SerialMessage[:226]- Assembled message buffer = 01 0A 00 13 3D 03 86 13 26 25 9D D3
2014-11-29 17:25:14.891 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1102]- NODE 61: Sending REQUEST Message = 01 0A 00 13 3D 03 86 13 26 25 9D D3
2014-11-29 17:25:14.989 DEBUG o.o.b.z.i.p.ZWaveController[:468]- Enqueueing message. Queue length = 8
2014-11-29 17:25:14.989 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1159]- Response processed after 98ms/4784ms.
2014-11-29 17:25:14.989 ERROR o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:1291]- Message cancelled by controller (CAN), resending

The problem is that until node  61 is not ok, the rest of the network isn't ok.

Gilles.

[Chris Jackson]

Hi Gilles,
I’m not sure why the issue is occurring on node 61. The controller is cancelling the request - it may be a by product of something else such as the Vera initialisation problem. I don’t know if the vera was still trying to initialise during this time?

Anyway, I hope to have fixed the problem with initialising the Vera - it’s a problem that may occur on other devices as well, so it might help others…

I’ll upload a new version later this evening - it would be good to know if the Vera initialises…

Cheers
Chris

[dan cunningham]

Hey Chris, I just checked out your repo and did some testing, here's what I have so far.

The first time I ran it I saw similar issues to before where it was not finding any instances of my devices, looking through the logs I could see that it was trying to read the endpoints from the xml files and failing to do so was just skipping that step.  Blowing away my XML files fixed this, but is something to be aware of for others upgrading

Now I'm stuck in the Dynamic stage for the first node ( Honeywell thermostat) and can't get out of it.  It correctly identifies the dynamic command classes and builds up a message queue, after the queue goes back down to 0, it starts over again and continues forever.  Since this is the first node on my network, I have not been able to see if other nodes have the same issue or if its something with this device.  I'm attaching my log file.

Let me know how I can help, I'm going through the code now, it may take me a little bit to get back up to speed on all the initialization stuff. 

Thanks!

Chris

--
You received this message because you are subscribed to the Google Groups "openhab" group.

[Chris Jackson]

Thanks Dan,
I’ll take a look at the log tomorrow. I suspect that your first problem might not be an issue with new users since the XML file won’t have been saved in a ‘broken’ state. The problem is that you’re system ran the old (new) binding, so saved the number of instances as 0 so the only way to recover was to delete the files. I think with the fix, this isn’t an issue.

I’ll look at the issue with the stuck dynamic stage issue in the log tomorrow…

Cheers
Chris

[Chris Jackson]

Binding is updated on the HABman site to fix the issues Gilles found with the Vera where some unsupported classes are assumed by the binding… Also added a number of new devices into the database (these will also be added to the main repo in the next day or so).

Chris

[Kevin Gottsman]

Chris,

I wasn't sure what the "cabman site" was so I grabbed the latest
snapshot from here:

https://github.com/cdjackson/HABmin/tree/master/addons

For my zwave setup, OH 1.5.1 works ok (although I kill all the zwave
messages in the console). OH 1.6 and 1.7-SNAPSHOT have been showing
strange errors and not working as expected. I have attached a brief log
if this helps. I can run in debug mode if further detail is needed.

Device #2 - GE 45604
Device #3-5 - GE 12721





On 11/29/14 7:17 PM, Chris Jackson wrote:
> Binding is updated on the cabman site to fix the issues Gilles found with the Vera where some unsupported classes are assumed by the binding… Also added a number of new devices into the database (these will also be added to the main repo in the next day or so).
>
> Chris
>

[Chris Jackson]

I wasn't sure what the "cabman site" was 

It's what happens when you let an Apple Mac autocorrect your spelling when you type habmin! :)

Thanks for the log - I'll take a look through this when I get a chance (probably tomorrow as I'm travelling home after work today).

Cheers

Chris

 

[Chris Jackson]

Hi Kevin,

Are you able to provide the XML files for your switches - if possible, for the new "test" binding, and the "old" one? Also, can you provide the item definitions for them?

Don't worry about the "node advancer - unknown state" errors - this isn't an issue and I'll probably remove these as errors...

Thanks

Chris

[gilles.l...@gmail.com]

Hi Chris,

I try you new binding with vera and no more result. it's blocked because of vera NODE1 and if I switch off vera and restart the binding it's my HEM with node61 who loop. The consequence is that configuration can't be seen in habmin for many devices randomly.

I give you zwave log and node 61 for HEM. The vera node1.xml hasn't been created.

Cheers,

Gilles.

[Chris Jackson]

Hi Gilles,

I think this log is incorrect - the filename has todays date, but the log is from yesterday afternoon.....

Chris

[gilles.l...@gmail.com]

Rahhaa sorry.

Here is the good log.

Gilles.

[Kevin Gottsman]

Chris,

Here are the files you requested... I noticed this in the wiki today.
Perhaps this is the issue.


PLEASE NOTE THAT THE ENDPOINT NUMBERING CHANGED FOR 1.6 RELEASE.
Previously, the default value was 1, but this caused problems with
multi-instance devices. This meant that a binding string of zwave=18:1
and zwave=18 was the same - this is now NOT the case.



-- Kevin

> --
> You received this message because you are subscribed to the Google
> Groups "openhab" group.
> To unsubscribe from this group and stop receiving emails from it, send
> an email to openhab+u...@googlegroups.com

> <mailto:openhab+u...@googlegroups.com>.

> To post to this group, send email to ope...@googlegroups.com

> <mailto:ope...@googlegroups.com>.

[Chris Jackson]

Hi Gilles,
I was wondering if you could try a couple of things. I’d like to get a log with the following conditions -:
1) With Vera - the same as you already sent
2) With Vera, but with node 61 disabled (if that’s possible?)
3) Without Vera, but with node 61 enabled.

For the first one, I want to see if the same thing happens…

Thanks
Chris

[Gilles L]

Hi Chris,
I can do that with pleasure.
To be sure: Node disable is the device switch off or device commented in openhab item file.
As I have to do it physically for Vera, I could do that tomorrow in late afternoon.
Hope it's not a problem for you.

Cheers,
Gilles.

--
You received this message because you are subscribed to a topic in the Google Groups "openhab" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/openhab/3kIL8rhTG60/unsubscribe.
To unsubscribe from this group and all its topics, send an email to openhab+u...@googlegroups.com.

[Chris Jackson]

Hi Gilles,
“disabled” means turn off the device…

No problem at all - tomorrow is fine. I’ve just got home from a very long week working in Munich, so tomorrow (or the next day) is fine - thanks.

Cheers
Chris

[Chris Jackson]

Hi Kevin,
Yes - I’d try removing the endpoint from the item definitions and see if that helps. I think it will solve the problem as at least for the XML file I looked at the device didn’t support multi_instances so the endpoint definition shouldn’t be there.

Cheers
Chris

[Chris Jackson]

Hi Dan,
Help would be brilliant if you can :)

The issue is in the getDynamicValues method - this method should only generate a list of request frames if the class hasn’t been initialised, or if the ‘refresh’ parameter is true. I’ve not handled this correctly for the thermostat frames I think, but I can't test this. What I do know is that I used a variable 'dynamicComplete' (or similar) and I don't actually set this to true, so this is why the system loops at this point.

However, I also changed this to add a child class that allows us to set an initialised flag on a 'mode by mode' basis (or setpoint by setpoint). The problem is that the getDynamicValues actually only requests a single frame I think, but I think there can be more than 1 setpoint/mode etc. 

Are you able to take a look at these classes?  Let me know if that's ok, or if you want any more explanation.

Thanks

Chris

[dan cunningham]

Hey Chris no problem, I will take a look today.  I see where you are talking about,  getDynamicValues looks reasonable, it returns a collection of messages, one for each supported setpoint, those are then added to the node's outbound queue. I see a variable named "dynamicDone", but its currently not used anywhere.  I will add a bunch of logging and see what's going on.    One question, once the ZodeAdvancer adds these messages to its queue, how does it determine if a command class has been satisfied with it's outstanding requests? So if a command class processes everything it needs to, how does the ZodeAdvancer know to move on to the next stage?  I'm about to hop on a plane so I may go silent for a few hours. 

--

You received this message because you are subscribed to the Google Groups "openhab" group.

To unsubscribe from this group and stop receiving emails from it, send an email to openhab+u...@googlegroups.com.
To post to this group, send email to ope...@googlegroups.com.

[Kevin Gottsman]

Fixed the problem right away. Its acting like normal now.

-- Kevin

[Chris Jackson]

Thanks Dan,

 

Hey Chris no problem, I will take a look today.  I see where you are talking about,  getDynamicValues looks reasonable, it returns a collection of messages, one for each supported setpoint, those are then added to the node's outbound queue. I see a variable named "dynamicDone", but its currently not used anywhere.  I will add a bunch of logging and see what's going on.  

I don't think "dynamicDone" is needed for these classes. I think that these classes can hold multiple values (eg multiple setpoints etc), so there's an array/list of setpoints (using setpoints as an example). For each setpoint, we need to remember if it's initialised - this is the purpose of the child class. The dynamicDone variable was probably a cut and paste from another class when I was going through and updating everything, but it needs to account for multiple responses....

 

One question, once the ZodeAdvancer adds these messages to its queue, how does it determine if a command class has been satisfied with it's outstanding requests? So if a command class processes everything it needs to, how does the ZodeAdvancer know to move on to the next stage?

The command class needs to hold enough information to know if it's been initialised fully. So, for 'simple' classes where we make a request and get a result, simply looking to see if we've received the response (eg for the battery class, if we've received the battery voltage, then we know it's initialised). For more complex classes, like the thermostat classes where there are multiple setpoints etc, and we're making multiple requests, we need to know if we've received all the requests. This is why I added the child class with the initialised member. The idea was to set all these to not initialised, then as all the responses come in, set each one to initialised.

So.... The answer to your question is that if the getDynamicValues doesn't return a list, then that class must be initialised. Within the node advancer, it holds a list of outstanding requests, and when there's no more requests in it's queue, it loops around the same stage one more time. If all our requests had received responses, then getDynamicValues will return null (or an empty list - I forget which) and we can then continue to the next stage.

I hope that all makes sense? If not, just holler.

Cheers

Chris

[Chris Jackson]

On Monday, 1 December 2014 14:54:39 UTC, Kevin Gottsman wrote:

Fixed the problem right away. Its acting like normal now.

Great - thanks for the feedback :)

Cheers

Chris 

[gilles.l...@gmail.com]

Hi Chris,

Do you need my log or it's no more necessary ?

I'm going to begin my tests if you want.

Cheers,

Gilles.

[Chris Jackson]

Hi  Gilles,

Yes - the log would be great - thanks… 

Cheers

Chris

--
You received this message because you are subscribed to the Google Groups "openhab" group.

To unsubscribe from this group and stop receiving emails from it, send an email to openhab+u...@googlegroups.com.
To post to this group, send email to ope...@googlegroups.com.

[dan cunningham]

Hey Chris I think i have the thermostat issues solved, I'll get a pull request to you later today.  There were actually a few issues, some small changes to the command classes, but also a bug in the Honeywell thermostat.  It reports that it supports 4 different setpoints, but will actually only ever respond to the 2 ( heating and cooling) that I have it setup to use.  I have a fix for this too that will be in the PR. 

I had gone back to the master version of the binding over the weekend and once again had to blow away the XML files to get multiple instances working,  just an FYI. 

Everything else looks great!

--

You received this message because you are subscribed to the Google Groups "openhab" group.

To unsubscribe from this group and stop receiving emails from it, send an email to openhab+u...@googlegroups.com.
To post to this group, send email to ope...@googlegroups.com.

[gilles.l...@gmail.com]

Ok,

First with vera on, nodes erased from /etc/zwave and node 61 on. Only node 71.xml was created. => zwave_with_vera_0112_with_node61.log

second without vera with node 61 => zwave_without_vera_0112_with_node61.log

third without vera without node 61 => zwave_without_vera_0112_without_node61.log

pfiuuu finished.



Cheers,

Gilles.

Le lundi 1 décembre 2014 20:09:25 UTC+1, Chris Jackson a écrit :

Hi  Gilles,

Yes - the log would be great - thanks… 

Cheers

Chris

On 1 Dec 2014, at 18:55, gilles.l...@gmail.com wrote:

Hi Chris,

Do you need my log or it's no more necessary ?

I'm going to begin my tests if you want.

Cheers,

Gilles.

Le lundi 1 décembre 2014 16:39:47 UTC+1, Chris Jackson a écrit :

On Monday, 1 December 2014 14:54:39 UTC, Kevin Gottsman wrote:

Fixed the problem right away. Its acting like normal now.

Great - thanks for the feedback :)

Cheers

Chris 

[Chris Jackson]

Great stuff - thanks Dan….

How did you work around the 2 of 4 setpoint reporting issue? Did you have to add a hack, or was there an elegant workaround?

Cheers
Chris

[dan cunningham]

Elegant.....no ;-)  I have a counter and a max number of tries.  if you request more then this max value during the dynamic phase it gives up and and and sets itself to initialized.  I have that at 5 right now which would seem to be safe. 

Cheers
Chris

[Chris Jackson]

I suspected :)

I have in mind to add things like this to the database - e.g. in this case, add something in the command class section to say it only supports set points 1 and 2 (or whatever). There are a few other hacks in the code where it looks at specific devices and changes the functionality and it would be nice to have a neater, more configurable/flexible solution….

One for later though :)

Cheers
Chris

[gilles.l...@gmail.com]

Don't know if this is about that you're speaking but the binding loop on a device node which isn't connecte for the moment. NODE 46

Notifying event listeners
2014-12-01 22:39:33.082 DEBUG o.o.b.z.i.ZWaveActiveBinding[:412]- ZwaveIncomingEvent
2014-12-01 22:39:33.082 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:696]- NODE 46: Node advancer - DETAILS: Transaction complete (RequestNodeInfo:Request) success(true)
2014-12-01 22:39:33.083 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:164]- NODE 46: Node advancer - checking initialisation queue.
2014-12-01 22:39:33.083 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:169]- NODE 46: Node advancer - message removed from queue. Queue size now 0.
2014-12-01 22:39:33.084 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:229]- NODE 46: Node advancer - DETAILS: queue length(0), free to send(true)
2014-12-01 22:39:33.084 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:256]- NODE 46: Node advancer: loop - DETAILS: stageAdvanced(false)
2014-12-01 22:39:33.085 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:338]- NODE 46: Node advancer: DETAILS - send RequestNodeInfo
2014-12-01 22:39:33.086 DEBUG o.o.b.z.i.p.SerialMessage[:108]- NODE 46: Creating empty message of class = RequestNodeInfo (0x60), type = Request (0x00)
2014-12-01 22:39:33.087 DEBUG o.o.b.z.i.p.ZWaveController[:472]- Enqueueing message. Queue length = 660
2014-12-01 22:39:33.087 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:202]- NODE 46: Node advancer - queued packet. Queue length is 1
2014-12-01 22:39:33.088 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1163]- Response processed after 4125ms/4985ms.
2014-12-01 22:39:33.089 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1071]- Took message from queue for sending. Queue length = 659
2014-12-01 22:39:33.090 DEBUG o.o.b.z.i.p.SerialMessage[:226]- Assembled message buffer = 01 04 00 60 2E B5
2014-12-01 22:39:33.090 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1106]- NODE 46: Sending REQUEST Message = 01 04 00 60 2E B5
2014-12-01 22:39:33.102 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:1297]- Receive Message = 01 04 01 60 01 9B
2014-12-01 22:39:33.104 DEBUG o.o.b.z.i.p.ZWaveController[:169]- Message: class = RequestNodeInfo (0x60), type = Response (0x01), payload = 01
2014-12-01 22:39:33.105 DEBUG o.o.b.z.i.p.s.RequestNodeInfoMessageClass[:38]- Request node info successfully placed on stack.

[Chris Jackson]

Thanks Gilles,
Can you post a bit more of the log - maybe another 10 or 20 lines before this line? Is this repeating continuously?

Cheers
Chris

[dan cunningham]

I thought about the database as well.  My guess is that this device would behave differently depending on how the user set it up (heating only, heating and cooling,  heat pump, etc..), there are 12 modes to be exact.  Maybe having a max retry at the device level would suffice?  In any case I just submitted a PR to your repo, the retry is at the setpoint type level, I think it should be fairly safe for the majority of cases. 

[Chris Jackson]

Thanks Dan,

I'll take a look at this tonight. So does your system now initialise correctly?

Cheers

Chris

[dan cunningham]

It does, for the first time everything gets initialized including the thermostats, all 28 nodes takes less then 30 seconds from start to finish.  I would say this is a huge improvement. Nice job!

Sent from my iPad