Waking up devices / Issue with thermostat setpoints

No there’s only one from later on in the morning after I initiated it to try to fix the problem -

11-11-15 10:51:36 report for HealNetwork.  Successful: Y Updated net: N  mr_only:0 Job ID: job#64 :heal network (0x785a98) P:71 S:5



=======NEIGHBOR NODE UPDATES=======
Node 2 Device 3 Combi Boiler neighbor nodes updated 0 times (incomplete 5 in a row 0), woke up 0 times configured: NO
Node 4 Device 5 _Thermostat neighbor nodes updated 0 times (incomplete 1 in a row 0), woke up 1 times configured: NO


=======STRESS TEST RESULT=======
Node 2 Device 3 Combi Boiler
  Test: NOP Sent 2 test frames and 0 succeeded (0%) with average of 0.000000 seconds and maximum of 0.000000 seconds
  Test: Basic_Get Sent 2 test frames and 0 succeeded (0%) with average of 0.000000 seconds and maximum of 0.000000 seconds
  Test: Get Node Info  Sent 2 test frames and 0 succeeded (0%) with average of 0.000000 seconds and maximum of 0.000000 seconds
  --HEALTH SCORE: 0--


=======NEIGHBOR NODE RESULT=======
Node 2 Device 3 Combi Boiler took 0.64126000 seconds to report neighbors: 
Node 4 Device 5 _Thermostat took 0.36870000 seconds to report neighbors: 

Inversely:


=======EDGE NODE PROFILE=======



=======DETAILED LOG=======
--Stage #1 started: 11-11-15 10:51:36 completed: 11-11-15 10:51:36 successful: N
---11-11-15 10:47:06 Job unknown
--Stage #2 started: 11-11-15 10:47:06 completed: 11-11-15 10:51:36 successful: Y
---11-11-15 10:47:06 Pass 0/5 Updating neighbors for node 2
---11-11-15 10:47:13 Job job#65 :heal_neighbor_node 2 (0x7ea5c8) P:70 S:4 was Successful
---11-11-15 10:47:13 Pass 0/5 Updating neighbors for node 4
---11-11-15 10:47:14 Job job#66 :heal_neighbor_node 4 (0x79e218) P:70 S:4 was Successful
---11-11-15 10:47:14 Pass 1/5 Updating neighbors for node 2
---11-11-15 10:47:21 Job job#67 :heal_neighbor_node 2 (0x784680) P:70 S:4 was Successful
---11-11-15 10:47:21 Pass 2/5 Updating neighbors for node 2
---11-11-15 10:47:29 Job job#68 :heal_neighbor_node 2 (0x769fc8) P:70 S:4 was Successful
---11-11-15 10:47:29 Pass 3/5 Updating neighbors for node 2
---11-11-15 10:47:37 Job job#69 :heal_neighbor_node 2 (0x7b9f38) P:70 S:4 was Successful
---11-11-15 10:47:37 Pass 4/5 Updating neighbors for node 2
---11-11-15 10:47:45 Job job#70 :heal_neighbor_node 2 (0x8273c0) P:70 S:4 was Successful
---11-11-15 10:47:45 Neighbor Update Done
--Stage #3 started: 11-11-15 10:47:45 completed: 11-11-15 10:51:36 successful: Y
---11-11-15 10:47:45 Routing update node 2
---11-11-15 10:47:45 Job job#71 :heal_routing_node 2 (0x7a9528) P:70 S:4 was Successful
---11-11-15 10:47:45 Routing update node 4
---11-11-15 10:47:45 Job job#72 :heal_routing_node 4 (0x828890) P:70 S:4 was Successful
---11-11-15 10:47:45 Routing update done
--Stage #4 started: 11-11-15 10:51:36 completed: 11-11-15 10:51:36 successful: Y
---11-11-15 10:47:46 Calculate Routes Done
--Stage #5 started: 11-11-15 10:47:46 completed: 11-11-15 10:51:36 successful: Y
---11-11-15 10:47:46 Configure node 2
---11-11-15 10:47:56 Job job#73 :conf_jh#2 (0x828bc0) P:70 S:3 was Aborted: Unable to get any information on node
---11-11-15 10:47:56 Configure node 4
---11-11-15 10:48:07 Job job#75 :conf_jh#4 (0x826680) P:70 S:3 was Aborted: Unable to get any information on node
---11-11-15 10:48:07 Configure Done
--Stage #6 started: 11-11-15 10:50:19 completed: 11-11-15 10:51:36 successful: Y
---11-11-15 10:50:19 Node 4 woke up
---11-11-15 10:50:19 Pass 5/5 Updating neighbors for node 4
---11-11-15 10:51:07 Battery devices awoke
--Stage #7 started: 11-11-15 10:51:07 completed: 11-11-15 10:51:36 successful: Y
---11-11-15 10:51:11 Node Details heal 2
---11-11-15 10:51:25 Node Details heal 2
---11-11-15 10:51:36 Stress test Done

That said I have rebooted the box a couple of times since then. I don’t know if that would delete them?

Very very strange. The errors from the boiler actuator were related to it not being configured (although it was fine yesterday).

After I ran the heal I was still getting those errors so I caused the UI to “configure node now” which it did.

After that it was fine! Can’t understand why it thought it was no longer configured…

[tt]41 11/14/11 14:02:20.311 0x1 0x10 0x0 0x19 0x4[sup]1[/sup] 0x5 0x43[sup]2[/sup] 0x1 0x1 0x1 0x1a[sup]3[/sup] 0x5 0x0 0x0 0x0 0x0 0x3 0xa9 (######C###########) <0xc04>

41 11/14/11 14:02:20.492 0x1 0x10 0x0 0x19 0x4 0x5 0x43 0x1 0x1 0x1 0x1a 0x25 0x0 0x0 0x0 0x0 0x4 0x8e (######C####%######) <0xc04>

41 11/14/11 14:02:20.709 0x1 0x10 0x0 0x19 0x4 0x5 0x43 0x1 0x1 0x1 0x1a 0x25 0x0 0x0 0x0 0x0 0x5 0x8f (######C####%######) <0xc04>

02 11/14/11 14:02:20.971 ZWJob_SendData::ReceivedFrame job job#3 :Heat SP 26 node 4 (0x81fcd8) N:4 P:70 S:5 to node 4 command 67/1 failed m_cTxStatus 1 retries 2 <0x803>[/tt]

From what I can tell from the logs Vera sent a command of class 0x43[sup]2[/sup] with the new setpoint of 26(0x1a)[sup]3[/sup] to node 4[sup]1[/sup]. It sent the message once (311), then retried twice (at 492 and 709) and eventually it concluded that the new setpoint wasn’t set (971). I don’t know why this happened (maybe it didn’t receive what it expected from the thermostat?), but it seems that this is the reason why Vera is not updating the setpoint variable. I will try to find more about this.

@mcvflorin,

I think that’s the sequence for when the t-stat is still sleeping. A little later (14:04:16.837) the command does seem to go through when the t-stat is awake and the comm failure is cleared, and I believe the OP was seeing ‘transmit ok’ and a changed setpoint on the t-stat itself.

Thanks Florin / oti@

Florin,

I think it as oti@ suggests. It does retry a few times then fail as the thermostat is asleep. Then it waits and retries as below -

02      11/15/11 18:05:36.724   ZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil) <0x803>
02      11/15/11 18:05:36.726   ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x803>
02      11/15/11 18:05:36.743   UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02      11/15/11 18:05:36.744   ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
41      11/15/11 18:05:36.746   ZWaveSerial::Send XXXX  node 4 using route 0.32.80.58 autoroute: 1 direct: 0 <0xc04>
41      11/15/11 18:05:36.747   0x1 0x10 0x0 0x19 0x4 0x5 0x43 0x1 0x1 0x1 0x16 0x5 0x0 0x0 0x0 0x0 0x14 0xb2 (######C###########) <0xc04>
42      11/15/11 18:05:36.791   0x6 0x1 0x4 0x1 0x19 0x1 0xe2 (#######) <0x1406>
42      11/15/11 18:05:36.791   got expected ACK <0x1406>
41      11/15/11 18:05:36.792   ACK: 0x6 (#) <0x1406>
42      11/15/11 18:05:36.841   0x1 0x5 0x0 0x19 0x14 0x0 0xf7 (#######) <0x1406>
41      11/15/11 18:05:36.841   ACK: 0x6 (#) <0x1406>
06      11/15/11 18:05:36.851   Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 1 now: 0 #hooks: 0 upnp: 0 v:0x828b38/NONE duplicate:0 <0x803>
06      11/15/11 18:05:36.852   Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastError was: Node 4 failed now: Node 4 failed #hooks: 0 upnp: 0 v:0x8289a8/NONE duplicate:1 <0x803>
04      11/15/11 18:05:36.855   <Job ID="11" Name="send failed node 4" Device="5" Created="11-11-15 18:05:36" Started="11-11-15 18:05:36" Completed="11-11-15 18:05:36" Duration="0.131155000" Runtime="0.112545000" Status="Successful" LastNote="Transmit was ok" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/> <0x803>
02      11/15/11 18:05:36.861   UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02      11/15/11 18:05:36.862   ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>

Going back to your earlier comment

Vera tells the thermostat to change its setpoint, and doesn’t update its internal setpoint variable until it gets confirmation from the thermostat that the setpoint successfully changed. Maybe the thermostat isn’t replying back its status?

We’re seeing the success ACK come back I think, and Vera is updating its status to “Successful” so shouldn’t it also be updating its internal setpoint at this time?

Cheers,

Alex/

For now, I’m using a crappy workaround to get the GUI to update correctly. It requires LUA code but I am using that anyway. I have a virtual thermostat that holds the default day temperature; so that I can easily change the default temperature by changing the virtual device rather than going through scenes to change hardcoded values. When I return home or in the morning when the timer fires, this scene copies the temperature set in the virtual thermostat to the actual device. There are two commands, one to send the new temp setpoint to the thermostat, and the other to set the local setpoint (which is what Vera displays).

local DEVICE_HUISKAMER = 91
local DEFAULT_HUISKAMER = 95

local t_huis = luup.variable_get("urn:upnp-org:serviceId:TemperatureSetpoint1_Heat", "CurrentSetpoint", DEFAULT_HUISKAMER)
luup.variable_set("urn:upnp-org:serviceId:TemperatureSetpoint1_Heat", "CurrentSetpoint", t_huis, DEVICE_HUISKAMER)
luup.call_action ("urn:upnp-org:serviceId:TemperatureSetpoint1_Heat", "SetCurrentSetpoint", {NewCurrentSetpoint = t_huis}, DEVICE_HUISKAMER)

I am stuck at that point now too. Where is the code that processes the ACK so we could maybe fix this? Any idea?

Where is the code that processes the ACK so we could maybe fix this?

In [tt]LuaUPnP[/tt]?

Can you be a bit more precise? I am not familiar with the internal structure of vera. I know about files you need for a plugin and generally there would be an implementation file I_xxx. I am just not sure where this would be for the Thermostat device. Any pointer where to start looking (directory, filename, …)

Thanks,

Utz

@utz The issue with much of this appears to be that it’s handled in the closed source portion of Vera (LuaUPnP is closed I believe), for example Z-Wave Rx packet handling and I presume ACKs