Waking up devices / Issue with thermostat setpoints

[ajlennon]

Hi,

Could somebody help me with an answer to a newbie question? I’ve got a battery powered
Horstmann thermostat which I have kind of working thanks to the help of the people here, and
I’m trying to understand the Z-Wave paradigm.

Being a battery powered device the thermostat is going to try to be in a powered down state
as much of the time as possible, keeping the radio off and so on and so forth. There seems to
be an ongoing discussion about “waking up” Z-Wave devices and I’m wondering if it is possible
to wake up a Z-Wave device remotely or not?

At present when I try to set a setpoint via the Vera UI it immediately tries to instruct the
thermostat and fails, I believe as the thermostat is sleeping, and then whichever Vera subsystem
it is sensibly attempts to wait until the device wakes up.

So Q. could Vera do anything at this point to force the device to wake up?

And then the other major issue is that the setpoint never actually seems to be set into the
thermostat. Can anybody comment on any code I could look at here to determine what is
going wrong?

Thanks,

Alex Lennon
Dynamic Devices Ltd

Home - Dynamic Devices Ltd

[utz]

I have the problem too and have not found a solution yet (I have not looked into it in too much detail yet).

[intveltr]

From messing around with the Horstmann thermostat, I found that setting its wakeup interval to the lowest value (256 seconds; setting it lower has no effect) will have it wake up often enough to get the setpoint value from Vera. Vera will report failure when it first try to send the value, but when the thermostat wakes up a few minutes later, Vera will retransmit.

Not sure what it does to the battery life, and I am not sure what the longest possible wakeup interval is that will still work reliably.

[sparkejj]

@ajlennon

[…] wondering if it is possible to wake up a Z-Wave device remotely or not?

The way I understand it: in general yes, but it depends on the type of device. A lot of battery operated devices are asleep most of the time, so they cannot be talked to. They would only wake up if they need to autonomously report something (through an alarm, a report, an association, a scene, etc.). They may also support the specific wake-up feature, where the controller (i.e. Vera) can configure a wake-up interval, so the device will periodically wake up, inform the controller of that fact, so the controller gets a chance to do something (i.e. configure, request etc.) at that time. Without (further) communication from the controller, the device goes back to sleep until the next wake-up period.

Then there are devices that are battery operated, but you want to be able to talk to at any time, such as a door lock. For those devices there is the beaming feature, which allows the device to listen frequently and save battery power. These are the (battery-operated) devices that can be ‘woken up’ (i.e. they are not really sleeping).

So Q. could Vera do anything at this point to force the device to wake up?

I don't have this device, but from the manual it seems to rely on the wake-up feature only, i.e. it will wake up every so often (configurable by Vera) and give Vera a chance to do things.

[ajlennon]

Thanks for the comments everybody. I have a little more information to add from my testing…

When I heat up the thermostat it seems to report temperature changes immediately (which is nice).

So I think that this 256s interval is the “must wake up even if there’s nothing to transmit”.

I still have the problem that entering a heating setpoint in Vera 2 doesn’t seem to work.

It fails to transmit, then seems to wait until the device wakes and and seems to think it’s transmitted but the value doesn’t change to the value I expect.

I think perhaps I need to understand more about the Vera 2 Z-Wave logging to see where the problem is here. I would really like to be able to set the setpoint from the Vera 2

[sparkejj]

@ajlennon

When I heat up the thermostat it seems to report temperature changes immediately (which is nice).

Makes sense. It’s initiated by the t-stat.

So I _think_ that this 256s interval is the "must wake up even if there's nothing to transmit".

Right. The wake-up interval. To allow comms initiated by the controller.

It fails to transmit, then seems to wait until the device wakes and and seems to think it's transmitted but the value doesn't change to the value I expect.

Does the setpoint change in the thermostat? From [url=http://forum.micasaverde.com/index.php/topic,4575.msg53530.html#msg53530]@intveltr's report[/url] I got the impression that is the case, but the GUI doesn't follow along.

[ajlennon]

“Right. The wake-up interval. To allow comms initiated by the controller.”

I can’t quite see how that could work. It’s the thermostat that is waking up. The only way the controller could then intiiate comms to the thermostat when it woke is if they both run extremely accurate and synchronised clocks. Is that the case or does the thermostat initiate comms. when it wakes up (which I would think more likely?)

[sparkejj]

@ajlennon

I can’t quite see how that could work.[…]

I think the way the wake-up stuff works is that the device wakes up, sends out a message saying it’s awake, so that a controller that is waiting to communicate with that device then gets a chance to do so.

(I meant to contrast the device has something to say to the controller with the controller has something to say to the device. The former is possible at any time; the latter is not, as the device is asleep and the controller will have to wait for it to wake up. So comms from the device can be instant, comms to the device only every wake-up interval.)

[ajlennon]

“Does the setpoint change in the thermostat? From @intveltr’s report I got the impression that is the case, but the GUI doesn’t follow along.”

I’ve now performed a little more testing…

(1) Thermostat SP set to 21, showing 21 in the UK, my Lua code retrieving a value of 21.

NB. The Lua code uses this line to get the SP value -

local lul_sph = luup.variable_get(“urn:upnp-org:serviceId:TemperatureSetpoint1_Heat”, “CurrentSetpoint”, 5)

(I’m still not entirely clear where this value is coming from. Presumably it is cached somewhere.)

(2) I use the UI to set the heating SP to 28

(3) The failure message comes up -

“Failed, waiting to retry when the node wakes up”

The thermostat still shows 21

(4) After a short while the error message disappears from the UI

(5) After a couple of minutes there is a message there has been a successful transmission

“Transmit was ok”

(I have the thermostat set to wake up at the circa 4 mins interval and it has presumably
signalled it has woken up and the pending setpoint update to it has occured)

(6) Now showing 28 on thermostat

(7) I have my Lua code set to run off a timer every 4 minutes. (A hack to work around not yet having the events I need to drive it)

In my Lua code I log the retrieved values for the SetPoint and the Current temperature. The SetPoint value being retrieved is
not correct -

50 11/13/11 11:44:13.011 luup_log:0: Heating SetPoint = 21 <0x803>
50 11/13/11 11:44:13.012 luup_log:0: Temperature = 21 <0x803>

50 11/13/11 11:48:13.012 luup_log:0: Heating SetPoint = 21 <0x803>
50 11/13/11 11:48:13.012 luup_log:0: Temperature = 21 <0x803>

(8) If I then change the setpoint directly on the thermostat from 28 to 27 the thermostat correctly updates Vera 2, the SP displays in the UI correcly and the Lua code has the right value

50 11/13/11 11:55:21.365 luup_log:0: Heating SetPoint = 27 <0x803>
50 11/13/11 11:55:21.366 luup_log:0: Temperature = 21 <0x803>

…

So this appears to be more than just a UI issue. It seems more like a cached local value that isn’t being correctly updated
when the pending write occurs after an initial write failure. That sound about right?

Cheers,

Alex

[sparkejj]

[quote=“ajlennon, post:9, topic:169546”]So this appears to be more than just a UI issue. It seems more like a cached local value that isn’t being correctly updated
when the pending write occurs after an initial write failure. That sound about right?[/quote]
Sounds like Vera ‘forgets’ to update the setpoint value internally (i.e. the local data associated with the device) once the message goes through when the device wakes up. Consequently, the GUI shows the incorrect value as well.

Does it fix itself after the next 256 seconds?

[ajlennon]

No I left it runnign for 3 or 4 cycles of the Lua script on the basis it might update, but it didn’t fix itself. Will leave it running here again to double check

[sparkejj]

@ajlennon

No I left it runnign for 3 or 4 cycles of the Lua script on the basis it might update, but it didn’t fix itself. Will leave it running here again to double check

I see. And within 256 seconds after an engine restart (i.e. hit the circular arrows, top right) or hitting [tt]Poll now[/tt]? (I’m just wondering if Vera ever retrieves the current setpoint from the t-stat).

I’d probably file a bug at this point: http://bugs.micasaverde.com

[ajlennon]

Here’s my log. There’s probably something in here if I could make sense of the Z-Wave commands.

I’ll try the engine restart next, then file. Thanks for the link

I changed the thermostat to a SP or 29 directly -

07	11/13/11 12:12:18.593	Event::Evaluate 1 Setpoint Hot Change scene Heating is true <0x803>
08	11/13/11 12:12:18.593	Scene::RunScene running 3 Heating <0x803>

My logging

50	11/13/11 12:12:18.595	luup_log:0: Heating SetPoint = 29 <0x803>
50	11/13/11 12:12:18.595	luup_log:0: Temperature = 22 <0x803>
50	11/13/11 12:12:18.596	luup_log:0: Heating already on <0x803>

Here's where I used the UI to change the SP to 22

08	11/13/11 12:12:34.481	JobHandler_LuaUPnP::HandleActionRequest device: 5 service: urn:upnp-org:serviceId:TemperatureSetpoint1_Heat action: e[36;1mSetCurrentSetpointe[0m <0x50008>
08	11/13/11 12:12:34.482	JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=5 <0x50008>
08	11/13/11 12:12:34.482	JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:TemperatureSetpoint1_Heat <0x50008>
08	11/13/11 12:12:34.483	JobHandler_LuaUPnP::HandleActionRequest argument action=SetCurrentSetpoint <0x50008>
08	11/13/11 12:12:34.483	JobHandler_LuaUPnP::HandleActionRequest argument NewCurrentSetpoint=22 <0x50008>
08	11/13/11 12:12:34.484	JobHandler_LuaUPnP::HandleActionRequest argument rand=0.5722252454170261 <0x50008>
06	11/13/11 12:12:34.485	Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSetpoint1_Heat variable: e[35;1mSetpointTargete[0m was: 28 now: 22 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x50008>
02	11/13/11 12:12:34.503	e[33;1mZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil)e[0m <0x50008>
02	11/13/11 12:12:34.506	e[33;1mUPDATE MANUAL ROUTE2 4=(nil)e[0m <0xc04>
02	11/13/11 12:12:34.507	e[33;1mZW_Send_Data node 4 NO ROUTE (nil)e[0m <0xc04>
06	11/13/11 12:12:34.661	Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mCommFailuree[0m was: 0 now: 1 #hooks: 0 upnp: 0 v:0x78ec00/NONE duplicate:0 <0x803>
06	11/13/11 12:12:34.662	Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mLastErrore[0m was: Poll failed now: Node 4 failed #hooks: 0 upnp: 0 v:0x7b4398/NONE duplicate:0 <0x803>
02	11/13/11 12:12:34.664	e[33;1mZWJob_SendData::ReceivedFrame job job#563 :Heat SP 22 node 4 (0x7957a8) N:4 P:35 S:5 to node 4 command 67/1 failed m_cTxStatus 1 retries 0e[0m <0x803>
02	11/13/11 12:12:34.668	e[33;1mUPDATE MANUAL ROUTE2 4=(nil)e[0m <0xc04>
02	11/13/11 12:12:34.669	e[33;1mZW_Send_Data node 4 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:12:34.861	e[33;1mZWJob_SendData::ReceivedFrame job job#563 :Heat SP 22 node 4 (0x7957a8) N:4 P:70 S:5 to node 4 command 67/1 failed m_cTxStatus 1 retries 1e[0m <0x803>
02	11/13/11 12:12:34.866	e[33;1mUPDATE MANUAL ROUTE2 4=(nil)e[0m <0xc04>
02	11/13/11 12:12:34.866	e[33;1mZW_Send_Data node 4 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:12:35.051	e[33;1mZWJob_SendData::ReceivedFrame job job#563 :Heat SP 22 node 4 (0x7957a8) N:4 P:70 S:5 to node 4 command 67/1 failed m_cTxStatus 1 retries 2e[0m <0x803>
02	11/13/11 12:12:35.056	e[33;1mUPDATE MANUAL ROUTE2 4=(nil)e[0m <0xc04>
02	11/13/11 12:12:35.056	e[33;1mZW_Send_Data node 4 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:12:35.201	e[33;1mZWJob_SendData::ReceivedFrame job job#563 :Heat SP 22 node 4 (0x7957a8) N:4 P:70 S:5 to node 4 command 67/1 failed m_cTxStatus 1 retries 3e[0m <0x803>
02	11/13/11 12:12:35.206	e[33;1mUPDATE MANUAL ROUTE2 4=(nil)e[0m <0xc04>
02	11/13/11 12:12:35.206	e[33;1mZW_Send_Data node 4 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:12:35.391	e[33;1mZWJob_SendData::ReceivedFrame job job#563 :Heat SP 22 node 4 (0x7957a8) N:4 P:70 S:5 to node 4 command 67/1 failed m_cTxStatus 1 retries 4e[0m <0x803>
02	11/13/11 12:12:35.396	e[33;1mUPDATE MANUAL ROUTE2 4=(nil)e[0m <0xc04>
02	11/13/11 12:12:35.396	e[33;1mZW_Send_Data node 4 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:12:35.581	e[33;1mZWJob_SendData::ReceivedFrame job job#563 :Heat SP 22 node 4 (0x7957a8) N:4 P:70 S:5 to node 4 command 67/1 failed m_cTxStatus 1 retries 5e[0m <0x803>
01	11/13/11 12:12:35.584	e[31;1mZWJob_SendData::JobFailed job#563 :Heat SP 22 node 4 (0x7957a8) N:4 P:70 S:5 Priority 70e[0m <0x803>

And around here we see the failure message I see on the UI 

04	11/13/11 12:12:35.586	<Job ID="563" Name="Heat SP 22 node 4" Device="5" Created="11-11-13 12:12:34" Started="11-11-13 12:12:34" Completed="11-11-13 12:12:35" Duration="1.82911000" Runtime="1.79883000" Status="Aborted" LastNote="Failed, waiting to retry when the node wakes up" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/> <0x803>
02	11/13/11 12:12:54.014	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:12:54.183	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:12:54.343	<Job ID="564" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:12:54" Started="11-11-13 12:12:54" Completed="11-11-13 12:12:54" Duration="0.331173000" Runtime="0.329297000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
02	11/13/11 12:14:24.017	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:14:24.343	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:14:24.493	<Job ID="565" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:14:24" Started="11-11-13 12:14:24" Completed="11-11-13 12:14:24" Duration="0.480970000" Runtime="0.477158000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
06	11/13/11 12:15:27.451	Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: e[35;1mLastWakeupe[0m was: 1321186271 now: 1321186527 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x803>
02	11/13/11 12:15:27.455	e[33;1mZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil)e[0m <0x803>
02	11/13/11 12:15:27.456	e[33;1mZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil)e[0m <0x803>
02	11/13/11 12:15:27.458	e[33;1mZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil)e[0m <0x803>
02	11/13/11 12:15:27.472	e[33;1mUPDATE MANUAL ROUTE2 4=(nil)e[0m <0xc04>
02	11/13/11 12:15:27.473	e[33;1mZW_Send_Data node 4 NO ROUTE (nil)e[0m <0xc04>
06	11/13/11 12:15:27.611	Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:HaDevice1 variable: e[35;1mCommFailuree[0m was: 1 now: 0 #hooks: 0 upnp: 0 v:0x78ec00/NONE duplicate:0 <0x803>
06	11/13/11 12:15:27.613	Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mLastErrore[0m was: Node 4 failed now: Node 4 failed #hooks: 0 upnp: 0 v:0x7b4398/NONE duplicate:1 <0x803>


04	11/13/11 12:15:27.616	<Job ID="566" Name="send failed node 4" Device="5" Created="11-11-13 12:15:27" Started="11-11-13 12:15:27" Completed="11-11-13 12:15:27" Duration="0.160004000" Runtime="0.143333000" Status="Successful" LastNote="Transmit was ok" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/> <0x803>
02	11/13/11 12:15:27.621	e[33;1mUPDATE MANUAL ROUTE2 4=(nil)e[0m <0xc04>
02	11/13/11 12:15:27.622	e[33;1mZW_Send_Data node 4 NO ROUTE (nil)e[0m <0xc04>

Waking up I guess...

04	11/13/11 12:15:27.714	<Job ID="567" Name="Wakeup done 4" Device="5" Created="11-11-13 12:15:27" Started="11-11-13 12:15:27" Completed="11-11-13 12:15:27" Duration="0.255501000" Runtime="0.94364000" Status="Successful" LastNote="Transmit was ok" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/> <0x803>
02	11/13/11 12:15:28.101	e[33;1mZWaveNode::HandlePollUpdate_Basic_Set node 4 device 5 unhandlede[0m <0x803>
02	11/13/11 12:15:54.016	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:15:54.173	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:15:54.324	<Job ID="568" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:15:54" Started="11-11-13 12:15:54" Completed="11-11-13 12:15:54" Duration="0.311358000" Runtime="0.307779000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
08	11/13/11 12:16:13.010	Scene::RunScene running 3 Heating <0x803>
50	11/13/11 12:16:13.012	luup_log:0: Heating SetPoint = 29 <0x803>
50	11/13/11 12:16:13.012	luup_log:0: Temperature = 22 <0x803>
50	11/13/11 12:16:13.013	luup_log:0: Heating already on <0x803>
08	11/13/11 12:16:13.014	JobHandler_LuaUPnP::AlarmCallback Ran timer: Four Minute next at 1321186813 now 1321186573 <0x803>
06	11/13/11 12:17:18.471	Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: e[35;1mCurrentTemperaturee[0m was: 22 now: 23 #hooks: 0 upnp: 0 v:0x79ea48/NONE duplicate:0 <0x803>
02	11/13/11 12:17:24.015	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:17:24.223	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:17:24.373	<Job ID="569" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:17:24" Started="11-11-13 12:17:24" Completed="11-11-13 12:17:24" Duration="0.361195000" Runtime="0.358304000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
02	11/13/11 12:18:54.017	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:18:54.183	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:18:54.333	<Job ID="570" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:18:54" Started="11-11-13 12:18:54" Completed="11-11-13 12:18:54" Duration="0.321229000" Runtime="0.316529000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
06	11/13/11 12:19:43.491	Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: e[35;1mLastWakeupe[0m was: 1321186527 now: 1321186783 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x803>
02	11/13/11 12:19:43.493	e[33;1mZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil)e[0m <0x803>
02	11/13/11 12:19:43.495	e[33;1mZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil)e[0m <0x803>
02	11/13/11 12:19:43.508	e[33;1mUPDATE MANUAL ROUTE2 4=(nil)e[0m <0xc04>
02	11/13/11 12:19:43.509	e[33;1mZW_Send_Data node 4 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:19:43.633	<Job ID="571" Name="Wakeup done 4" Device="5" Created="11-11-13 12:19:43" Started="11-11-13 12:19:43" Completed="11-11-13 12:19:43" Duration="0.137509000" Runtime="0.125227000" Status="Successful" LastNote="Transmit was ok" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/> <0x803>
08	11/13/11 12:19:53.072	JobHandler_LuaUPnP::HandleActionRequest device: 0 service: urn:micasaverde-com:serviceId:HomeAutomationGateway1 action: e[36;1mLogIpRequeste[0m <0x50008>
08	11/13/11 12:20:13.010	Scene::RunScene running 3 Heating <0x803>
50	11/13/11 12:20:13.011	luup_log:0: Heating SetPoint = 29 <0x803>
50	11/13/11 12:20:13.012	luup_log:0: Temperature = 23 <0x803>
50	11/13/11 12:20:13.013	luup_log:0: Heating already on <0x803>
08	11/13/11 12:20:13.014	JobHandler_LuaUPnP::AlarmCallback Ran timer: Four Minute next at 1321187053 now 1321186813 <0x803>

I don't like the look of this.. (!)

02	11/13/11 12:20:19.011	e[33;1mLOG_CHECK_MEMORY_LEAK pMem start 0x7ff000 now 0x80f000 last 0x808000 leaked 65536e[0m <0x803>
02	11/13/11 12:20:24.014	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:20:24.183	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:20:24.333	<Job ID="572" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:20:24" Started="11-11-13 12:20:24" Completed="11-11-13 12:20:24" Duration="0.321273000" Runtime="0.319391000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
08	11/13/11 12:21:49.304	JobHandler_LuaUPnP::HandleActionRequest device: 0 service: urn:micasaverde-com:serviceId:HomeAutomationGateway1 action: e[36;1mLogIpRequeste[0m <0x51c0e>
02	11/13/11 12:21:54.015	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:21:54.154	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:21:54.453	<Job ID="573" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:21:54" Started="11-11-13 12:21:54" Completed="11-11-13 12:21:54" Duration="0.441151000" Runtime="0.438413000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
02	11/13/11 12:23:24.016	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:23:24.183	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:23:24.333	<Job ID="574" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:23:24" Started="11-11-13 12:23:24" Completed="11-11-13 12:23:24" Duration="0.321028000" Runtime="0.317303000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
06	11/13/11 12:23:59.451	Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: e[35;1mLastWakeupe[0m was: 1321186783 now: 1321187039 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x803>
02	11/13/11 12:23:59.453	e[33;1mZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil)e[0m <0x803>
02	11/13/11 12:23:59.455	e[33;1mZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil)e[0m <0x803>
02	11/13/11 12:23:59.468	e[33;1mUPDATE MANUAL ROUTE2 4=(nil)e[0m <0xc04>
02	11/13/11 12:23:59.469	e[33;1mZW_Send_Data node 4 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:23:59.593	<Job ID="575" Name="Wakeup done 4" Device="5" Created="11-11-13 12:23:59" Started="11-11-13 12:23:59" Completed="11-11-13 12:23:59" Duration="0.137363000" Runtime="0.125011000" Status="Successful" LastNote="Transmit was ok" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/> <0x803>
08	11/13/11 12:24:13.010	Scene::RunScene running 3 Heating <0x803>

Still at 29 locally...

50	11/13/11 12:24:13.012	luup_log:0: Heating SetPoint = 29 <0x803>
50	11/13/11 12:24:13.012	luup_log:0: Temperature = 23 <0x803>
50	11/13/11 12:24:13.013	luup_log:0: Heating already on <0x803>
08	11/13/11 12:24:13.014	JobHandler_LuaUPnP::AlarmCallback Ran timer: Four Minute next at 1321187293 now 1321187053 <0x803>
08	11/13/11 12:24:14.234	JobHandler_LuaUPnP::HandleActionRequest device: 0 service: urn:micasaverde-com:serviceId:HomeAutomationGateway1 action: e[36;1mLogIpRequeste[0m <0x5240e>
08	11/13/11 12:24:14.235	JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:micasaverde-com:serviceId:HomeAutomationGateway1 <0x5240e>
08	11/13/11 12:24:14.235	JobHandler_LuaUPnP::HandleActionRequest argument action=LogIpRequest <0x5240e>
08	11/13/11 12:24:14.236	JobHandler_LuaUPnP::HandleActionRequest argument IpAddress=192.168.1.105 <0x5240e>
08	11/13/11 12:24:14.236	JobHandler_LuaUPnP::HandleActionRequest argument MacAddress=00:21:5d:db:b8:d0 <0x5240e>
02	11/13/11 12:24:54.014	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:24:54.183	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:24:54.333	<Job ID="576" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:24:54" Started="11-11-13 12:24:54" Completed="11-11-13 12:24:54" Duration="0.321092000" Runtime="0.319411000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
02	11/13/11 12:26:24.015	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:26:26.380	e[33;1mZWaveSerial::GetFrame 0x7f3ff7d8 timed out now 0 m_listGetFramePending 0e[0m <0xc04>
02	11/13/11 12:26:26.381	e[33;1mZWaveJobHandler::SendDataAbort got m_iFrameID 0e[0m <0xc04>
01	11/13/11 12:26:26.382	e[31;1mZWJob_PollNode::Run job job#577 :pollnode #2 (0x7d1520) N:2 P:100 S:1 ZW_Send_Data to node 2 failed 1 req 0x77cc60/1 abort m_iFrameID 0e[0m <0xc04>
02	11/13/11 12:26:26.383	e[33;1mZWJob_PollNode::PollFailed job job#577 :pollnode #2 (0x7d1520) N:2 P:100 S:1 node 2 battery 0e[0m <0xc04>
06	11/13/11 12:26:26.383	Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mLastErrore[0m was: Node 4 failed now: Poll failed #hooks: 0 upnp: 0 v:0x7b4398/NONE duplicate:0 <0xc04>
04	11/13/11 12:26:26.386	<Job ID="577" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:26:24" Started="11-11-13 12:26:24" Completed="11-11-13 12:26:26" Duration="2.373942000" Runtime="2.371272000" Status="Failed" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0xc04>
02	11/13/11 12:26:26.388	e[33;1mJobHandler::PurgeCompletedJobs purge job#577 :pollnode #2 (0x7d1520) N:2 P:100 S:2 pollnode #2 2 cmds status 2e[0m <0xc04>
02	11/13/11 12:27:54.015	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
02	11/13/11 12:27:54.183	e[33;1mZW_Send_Data node 2 NO ROUTE (nil)e[0m <0xc04>
04	11/13/11 12:27:54.333	<Job ID="578" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:27:54" Started="11-11-13 12:27:54" Completed="11-11-13 12:27:54" Duration="0.321149000" Runtime="0.318319000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
08	11/13/11 12:28:13.010	Scene::RunScene running 3 Heating <0x803>

continued...

[ajlennon]

…

Still at 29 locally…

50	11/13/11 12:28:13.012	luup_log:0: Heating SetPoint = 29 <0x803>
50      11/13/11 12:28:13.013   luup_log:0: Temperature = 23 <0x803>
50      11/13/11 12:28:13.014   luup_log:0: Heating already on <0x803>
08      11/13/11 12:28:13.014   JobHandler_LuaUPnP::AlarmCallback Ran timer: Four Minute next at 1321187533 now 1321187293 <0x803>
06      11/13/11 12:28:15.461   Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: LastWakeup was: 1321187039 now: 1321187295 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x803>
02      11/13/11 12:28:15.463   ZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil) <0x803>
02      11/13/11 12:28:15.464   ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x803>
02      11/13/11 12:28:15.479   UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02      11/13/11 12:28:15.479   ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
04      11/13/11 12:28:15.603   <Job ID="579" Name="Wakeup done 4" Device="5" Created="11-11-13 12:28:15" Started="11-11-13 12:28:15" Completed="11-11-13 12:28:15" Duration="0.138169000" Runtime="0.124724000" Status="Successful" LastNote="Transmit was ok" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/> <0x803>
06      11/13/11 12:28:30.501   Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 23 now: 23 #hooks: 0 upnp: 0 v:0x79ea48/NONE duplicate:1 <0x803>
06      11/13/11 12:28:30.551   Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 23 now: 23 #hooks: 0 upnp: 0 v:0x79ea48/NONE duplicate:1 <0x803>
02      11/13/11 12:29:04.014   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02      11/13/11 12:29:04.183   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
04      11/13/11 12:29:04.334   <Job ID="580" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:29:04" Started="11-11-13 12:29:04" Completed="11-11-13 12:29:04" Duration="0.321377000" Runtime="0.319684000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
02      11/13/11 12:30:00.010   Energy::SetNextEnergyLogAlarm <0x402>
02      11/13/11 12:30:00.011   Energy::SetNextEnergyLogAlarm 2011-11-13 12:30:00 <0x402>
02      11/13/11 12:30:00.012   Energy::LogEnergyUsageOnServer starting 0 <0x402>
02      11/13/11 12:30:34.015   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02      11/13/11 12:30:36.350   ZWaveSerial::GetFrame 0x7f3ff7d8 timed out now 0 m_listGetFramePending 0 <0xc04>
02      11/13/11 12:30:36.351   ZWaveJobHandler::SendDataAbort got m_iFrameID 0 <0xc04>
01      11/13/11 12:30:36.352   ZWJob_PollNode::Run job job#581 :pollnode #2 (0x773378) N:2 P:100 S:1 ZW_Send_Data to node 2 failed 1 req 0x7aa620/1 abort m_iFrameID 0 <0xc04>
02      11/13/11 12:30:36.353   ZWJob_PollNode::PollFailed job job#581 :pollnode #2 (0x773378) N:2 P:100 S:1 node 2 battery 0 <0xc04>
06      11/13/11 12:30:36.354   Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastError was: Poll failed now: Poll failed #hooks: 0 upnp: 0 v:0x7b4398/NONE duplicate:1 <0xc04>
04      11/13/11 12:30:36.356   <Job ID="581" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:30:34" Started="11-11-13 12:30:34" Completed="11-11-13 12:30:36" Duration="2.343930000" Runtime="2.341156000" Status="Failed" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0xc04>
02      11/13/11 12:30:36.357   JobHandler::PurgeCompletedJobs purge job#581 :pollnode #2 (0x773378) N:2 P:100 S:2 pollnode #2 2 cmds status 2 <0xc04>
02      11/13/11 12:32:04.016   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02      11/13/11 12:32:04.193   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
04      11/13/11 12:32:04.343   <Job ID="582" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:32:04" Started="11-11-13 12:32:04" Completed="11-11-13 12:32:04" Duration="0.331177000" Runtime="0.327628000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
08      11/13/11 12:32:13.010   Scene::RunScene running 3 Heating <0x803>

Still at 29 locally...

50      11/13/11 12:32:13.011   luup_log:0: Heating SetPoint = 29 <0x803>
50      11/13/11 12:32:13.012   luup_log:0: Temperature = 23 <0x803>
50      11/13/11 12:32:13.013   luup_log:0: Heating already on <0x803>
08      11/13/11 12:32:13.013   JobHandler_LuaUPnP::AlarmCallback Ran timer: Four Minute next at 1321187773 now 1321187533 <0x803>
06      11/13/11 12:32:31.501   Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: LastWakeup was: 1321187295 now: 1321187551 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x803>
02      11/13/11 12:32:31.503   ZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil) <0x803>
02      11/13/11 12:32:31.504   ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x803>
02      11/13/11 12:32:31.518   UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02      11/13/11 12:32:31.519   ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
04      11/13/11 12:32:31.623   <Job ID="583" Name="Wakeup done 4" Device="5" Created="11-11-13 12:32:31" Started="11-11-13 12:32:31" Completed="11-11-13 12:32:31" Duration="0.118462000" Runtime="0.105045000" Status="Successful" LastNote="Transmit was ok" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/> <0x803>
02      11/13/11 12:33:14.015   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02      11/13/11 12:33:14.233   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02      11/13/11 12:33:36.370   ZWaveSerial::GetFrame 0x7f3ff758 timed out now 0 m_listGetFramePending 0 <0xc04>
02      11/13/11 12:33:36.371   ZWaveJobHandler::SendDataAbort got m_iFrameID 0 <0xc04>
02      11/13/11 12:33:36.372   ZWJob_PollNode::ReturnMessageNotReceived -end- job job#584 :pollnode #2 (0x796350) N:2 P:100 S:5 node 2 didn't reply iOK 49 iBadTx 0 iNoReply 1 Abort returned m_iFrameID 0 <0xc04>
02      11/13/11 12:33:36.373   ZWJob_PollNode::PollFailed job job#584 :pollnode #2 (0x796350) N:2 P:100 S:5 node 2 battery 0 <0xc04>
06      11/13/11 12:33:36.374   Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastError was: Poll failed now: Poll failed #hooks: 0 upnp: 0 v:0x7b4398/NONE duplicate:1 <0xc04>
04      11/13/11 12:33:36.376   <Job ID="584" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:33:14" Started="11-11-13 12:33:14" Completed="11-11-13 12:33:36" Duration="22.363449000" Runtime="22.361179000" Status="Failed" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0xc04>
02      11/13/11 12:33:36.377   JobHandler::PurgeCompletedJobs purge job#584 :pollnode #2 (0x796350) N:2 P:100 S:2 pollnode #2 2 cmds status 2 <0xc04>
02      11/13/11 12:34:44.015   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02      11/13/11 12:34:44.193   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
04      11/13/11 12:34:44.423   <Job ID="585" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:34:44" Started="11-11-13 12:34:44" Completed="11-11-13 12:34:44" Duration="0.411191000" Runtime="0.408320000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
08      11/13/11 12:36:13.010   Scene::RunScene running 3 Heating <0x803>

Still at 29 locally...

50      11/13/11 12:36:13.012   luup_log:0: Heating SetPoint = 29 <0x803>
50      11/13/11 12:36:13.012   luup_log:0: Temperature = 23 <0x803>
50      11/13/11 12:36:13.013^[[A^[[5~

etc.etc.

[ajlennon]

No, the engine restart doesn’t fix it. Will file bug report now.

I’m happy to take a look at what the code is doing wrong - presumably not correctly updating a local variable after the pending write succeeds - if somebody points me to the right place to look…

[code]03 11/13/11 12:42:25.284 LuaUPNP: starting bLogUPnP 0 <0x400>
02 11/13/11 12:42:25.298 JobHandler_LuaUPnP::Run: pid 6189 didn’t exit <0x400>
09 11/13/11 12:42:25.418 UserData::ParseRooms 1 Back Room bSynced 1 <0x400>
09 11/13/11 12:42:25.419 UserData::ParseRooms 2 Kitchen bSynced 1 <0x400>
09 11/13/11 12:42:25.419 UserData::ParseRooms 3 Front Room bSynced 1 <0x400>
09 11/13/11 12:42:25.441 UserData::ParseRooms 4 Hall bSynced 1 <0x400>
03 11/13/11 12:42:25.449 UserData::LoadUserData BuildVersion: 1.1.1362 SvnVersion: 5226 Model: 2 SERCOMM NA401 flush: 0 changed: 0 resync: 9437 syncdevice:0 <0x400>
02 11/13/11 12:42:26.186 Device_Service::MatchupUpnpServices no upnp service for urn:micasaverde-com:serviceId:ZWaveDevice1 <0x400>
02 11/13/11 12:42:26.192 Device_Service::MatchupUpnpServices no upnp service for urn:micasaverde-com:serviceId:ZWaveDevice1 <0x400>
02 11/13/11 12:42:26.203 Device_Service::MatchupUpnpServices no upnp service for urn:micasaverde-com:serviceId:ZWaveDevice1 <0x400>
06 11/13/11 12:42:26.323 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastUpdate was: 1321149613 now: 1321188146 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x400>
06 11/13/11 12:42:26.325 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusID was: 2 now: 7 #hooks: 0 upnp: 0 v:0x7ab7d8/NONE duplicate:0 <0x400>
06 11/13/11 12:42:26.326 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusText was: Resetting ZWave Network now: Starting ZWave Network #hooks: 0 upnp: 0 v:0x7b4298/NONE duplicate:0 <0x400>
02 11/13/11 12:42:26.644 ZWaveJobHandler::Run connect to /dev/tts/1 -0 lock 1 <0xc04>
02 11/13/11 12:42:26.716 ZWaveJobHandler::Run connected to /dev/tts/1=1 i=0 <0xc04>
06 11/13/11 12:42:26.768 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusID was: 7 now: 7 #hooks: 0 upnp: 0 v:0x7ab7d8/NONE duplicate:1 <0xc04>
06 11/13/11 12:42:26.769 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusText was: Starting ZWave Network now: Starting ZWave Network #hooks: 0 upnp: 0 v:0x7b4298/NONE duplicate:1 <0xc04>
03 11/13/11 12:42:31.272 ZWJob_Initialize::JobDone version 3.20 type 1 role is 0 house id f937175b node id 1 suc 0 IsSecondary 0 bOnOtherNetwork 0 NodeIdServerPresent 0 IsRealPrimary 1 IsSuc 0 <0xc04>
06 11/13/11 12:42:31.279 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: VersionInfo was: 3.20 L:1 now: 3.20 L:1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0xc04>
06 11/13/11 12:42:31.280 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: HomeID was: House: f937175b Node 1 Suc 0 now: House: f937175b Node 1 Suc 0 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0xc04>
06 11/13/11 12:42:31.281 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: Role was: Master SIS:NO PRI:YES now: Master SIS:NO PRI:YES #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0xc04>
04 11/13/11 12:42:31.284 <0xc04>
02 11/13/11 12:42:31.351 ZWave::Start reset 0 inter 0 upgrade 0 use45:1 minor:20 model:2 port:/dev/tts/1 nodes:3 <0x400>
02 11/13/11 12:42:31.355 JobHandler_LuaUPnP::StartPlugins Energy STARTED <0x400>
02 11/13/11 12:42:31.532 XXXX setinitial UpdateManualRoute node 1 = (null) <0xc04>
02 11/13/11 12:42:31.532 XXXX UpdateManualRoute setinitial node 1 m_cRoutePosition 0 <0xc04>
02 11/13/11 12:42:31.534 ZWaveNode::UpdateCommandClasses node 1 empty – – <0xc04>
02 11/13/11 12:42:31.535 XXXX setinitial UpdateManualRoute node 2 = 0-5x <0xc04>
02 11/13/11 12:42:31.536 UpdateManualRoute XXX1 node 2 route 0-5x <0xc04>
02 11/13/11 12:42:31.537 XXXX UpdateManualRoute setinitial node 2 m_cRoutePosition 0 <0xc04>
06 11/13/11 12:42:31.539 Device_Variable::m_szValue_set device: 3 service: urn:micasaverde-com:serviceId:HaDevice1 variable: Configured was: 1 now: 1 #hooks: 0 upnp: 0 v:0x78d7a0/NONE duplicate:1 <0xc04>
06 11/13/11 12:42:31.540 Device_Variable::m_szValue_set device: 3 service: urn:micasaverde-com:serviceId:HaDevice1 variable: Configured was: 1 now: 1 #hooks: 0 upnp: 0 v:0x78d7a0/NONE duplicate:1 <0xc04>
02 11/13/11 12:42:31.541 XXXX setinitial UpdateManualRoute node 4 = (null) <0xc04>
02 11/13/11 12:42:31.542 XXXX UpdateManualRoute setinitial node 4 m_cRoutePosition 0 <0xc04>
06 11/13/11 12:42:31.544 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:HaDevice1 variable: Configured was: 1 now: 1 #hooks: 0 upnp: 0 v:0x78d7a0/NONE duplicate:1 <0xc04>
06 11/13/11 12:42:31.545 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:HaDevice1 variable: Configured was: 1 now: 1 #hooks: 0 upnp: 0 v:0x78d7a0/NONE duplicate:1 <0xc04>
09 11/13/11 12:42:31.547 ZWaveJobHandler::UpdateNodes dongle is node 1 device 2 iExtraNodesForTest 0 <0xc04>
06 11/13/11 12:42:31.547 Device_Variable::m_szValue_set device: 2 service: urn:micasaverde-com:serviceId:SceneController1 variable: Scenes was: now: #hooks: 0 upnp: 0 v:0x78f1a8/NONE duplicate:1 <0xc04>
09 11/13/11 12:42:31.549 ZWaveJobHandler::UpdateNodes node 2 Device_NumTemplate D_HVAC_ZoneThermostat1.xml type ZWaveThermostat Device_Num 3 Room 2 auto-conf -1 cap 0xd2 sec 0x9c res 0x0 bas 0x4 gen 0x8 spe 0x0 config 1 secure 0 Combi Boiler classes 25,40,72,86, mfr: Horstmann Controls Limited/ mfr: 0x59 prodtype: 0x3 prodid: 0x1 notlistening: 0 list:1 rout:1 beam:1 rtsl:1 sec:0 1k:0 250:0 <0xc04>
02 11/13/11 12:42:31.550 ZWaveJobHandler::UpdateNodes not configuring node 4 because it’s not listening <0xc04>
09 11/13/11 12:42:31.561 ZWaveJobHandler::UpdateNodes node 4 Device_NumTemplate D_HVAC_ZoneThermostat1.xml type ZWaveThermostat Device_Num 5 Room 1 auto-conf -1 cap 0x12 sec 0x96 res 0x0 bas 0x1 gen 0x8 spe 0x0 config 1 secure 0 _Thermostat classes 31,43,70,72,80,84,85,86, mfr: Horstmann Controls Limited/ mfr: 0x59 prodtype: 0x1 prodid: 0x3 notlistening: 1 list:0 rout:0 beam:1 rtsl:0 sec:0 1k:0 250:0 <0xc04>
06 11/13/11 12:42:31.562 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusID was: 7 now: 5 #hooks: 0 upnp: 0 v:0x7ab7d8/NONE duplicate:0 <0xc04>
06 11/13/11 12:42:31.563 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusText was: Starting ZWave Network now: Configuring ZWave devices #hooks: 0 upnp: 0 v:0x7b4298/NONE duplicate:0 <0xc04>
04 11/13/11 12:42:31.567 <0xc04>
02 11/13/11 12:42:31.573 JobHandler_LuaUPnP::StartUPnPServices starting with /etc/cmh-ludl/ / http://192.168.1.116:49451/luaupnp.xml <0x400>
09 11/13/11 12:42:31.703 JobHandler_LuaUPnP::Run device 3 Combi Boiler room 2 type urn:schemas-upnp-org:device:HVAC_ZoneThermostat:1 id 2 parent 1/0x756ed0 upnp: 0 <0x400>
09 11/13/11 12:42:31.704 JobHandler_LuaUPnP::Run device 2 _Scene Controller room 0 type urn:schemas-micasaverde-com:device:SceneController:1 id 1 parent 1/0x753c68 upnp: 0

<0x400>
09 11/13/11 12:42:31.705 JobHandler_LuaUPnP::Run device 5 _Thermostat room 1 type urn:schemas-upnp-org:device:HVAC_ZoneThermostat:1 id 4 parent 1/0x773628 upnp: 0 <0x400>
09 11/13/11 12:42:31.706 JobHandler_LuaUPnP::Run device 1 ZWave room 0 type urn:schemas-micasaverde-com:device:ZWaveNetwork:1 id parent 0/0x753518 upnp: 0 <0x400>
03 11/13/11 12:42:31.746 JobHandler_LuaUPnP::Run ready 4 devices installation 31706 missing version 1.1.1362 allow_evt: 1 allow_ud: 1 upnp 1 changed: 0 pMem 0x7ea000 start 7647232 diff: 651264 <0x400>
02 11/13/11 12:42:33.011 ZWaveJobHandler::SetDeviceStatus XXX2 0/0/0/0 <0x803>
06 11/13/11 12:42:34.014 Device_Variable::m_szValue_set device: 3 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: ManufacturerInfo was: 89,3,1 now: 89,3,1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x803>
06 11/13/11 12:42:34.016 Device_Variable::m_szValue_set device: 3 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: Capabilities was: 210,156,0,4,8,0,L,R,B,RS,|37,64,114,134, now: 210,156,0,4,8,0,L,R,B,RS,|37,64,114,134, #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x803>
06 11/13/11 12:42:34.017 Device_Variable::m_szValue_set device: 3 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: Neighbors was: 1, now: 1, #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x803>
06 11/13/11 12:42:34.018 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: ManufacturerInfo was: 89,1,3 now: 89,1,3 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x803>
06 11/13/11 12:42:34.018 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: Capabilities was: 18,150,0,1,8,0,B,|49,67,112,114,128,132:2,133,134, now: 18,150,0,1,8,0,B,|49,67,112,114,128,132:2,133,134, #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x803>
06 11/13/11 12:42:34.019 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusID was: 5 now: 1 #hooks: 0 upnp: 0 v:0x7ab7d8/NONE duplicate:0 <0x803>
06 11/13/11 12:42:34.020 Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: NetStatusText was: Configuring ZWave devices now: OK #hooks: 0 upnp: 0 v:0x7b4298/NONE duplicate:0 <0x803>
02 11/13/11 12:42:46.016 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:42:46.194 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
04 11/13/11 12:42:46.403 <0x803>
06 11/13/11 12:43:24.562 Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 23 now: 24 #hooks: 0 upnp: 0 v:0x79ea48/NONE duplicate:0 <0x803>
02 11/13/11 12:44:16.014 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:44:16.173 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
04 11/13/11 12:44:16.343 <0x803>
02 11/13/11 12:44:35.123 UPnPCallbackEventHandler 6 start PIDLOG2 11972 <0x2009>
02 11/13/11 12:44:39.123 UPnPCallbackEventHandler 6 start PIDLOG2 11973 <0x240a>
02 11/13/11 12:45:01.011 UPnPCallbackEventHandler 7 start PIDLOG2 11976 <0x300d>
06 11/13/11 12:45:19.471 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: LastWakeup was: 1321188063 now: 1321188319 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x803>
02 11/13/11 12:45:19.473

    ZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil) <0x803>

02 11/13/11 12:45:19.475 ZWJob_SendData UPDATE MANUAL ROUTE 4=(nil) <0x803>
02 11/13/11 12:45:19.488 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:45:19.488 ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
04 11/13/11 12:45:19.613 <0x803>
02 11/13/11 12:45:46.016 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:45:46.193 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
04 11/13/11 12:45:46.473 <0x803>
08 11/13/11 12:46:26.010 Scene::RunScene running 3 Heating <0x803>
50 11/13/11 12:46:26.013 luup_log:0: Heating SetPoint = 29 <0x803>
50 11/13/11 12:46:26.013 luup_log:0: Temperature = 24 <0x803>
50 11/13/11 12:46:26.014 luup_log:0: Heating already on <0x803>
08 11/13/11 12:46:26.015 JobHandler_LuaUPnP::AlarmCallback Ran timer: Four Minute next at 1321188626 now 1321188386 <0x803>
02 11/13/11 12:47:16.016 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:47:16.193 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
04 11/13/11 12:47:16.343 <0x803>
02 11/13/11 12:48:46.016 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:48:46.243 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
04 11/13/11 12:48:46.394 <0x803>
06 11/13/11 12:49:35.471 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: LastWakeup was: 1321188319 now: 1321188575 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x803>
02 11/13/11 12:49:35.473 ZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil) <0x803>
02 11/13/11 12:49:35.474 ZWJob_SendData UPDATE MANUAL ROUTE 4=(nil) <0x803>
02 11/13/11 12:49:35.489 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:49:35.490 ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
04 11/13/11 12:49:35.613 <0x803>
02 11/13/11 12:50:16.014 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:50:16.363 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
04 11/13/11 12:50:16.513 <0x803>
08 11/13/11 12:50:26.010 Scene::RunScene running 3 Heating <0x803>
50 11/13/11 12:50:26.011 luup_log:0: Heating SetPoint = 29 <0x803>
50 11/13/11 12:50:26.012 luup_log:0: Temperature = 24 <0x803>
50 11/13/11 12:50:26.013 luup_log:0: Heating already on <0x803
[/code]

[ajlennon]

The Mantis engine seems not to want to email me an account activation, so I guess I’ll have to wait…

[mcvflorin]

Hi ajlennon,

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? In your logs you don’t have Z-Wave log lines (lines starting with 41 and 42) to see the messages exchanged between Vera and the thermostat, which would help finding the cause.

[ajlennon]

Hi mcvflorin (Florin?),

41,42 - useful to know thanks. Here’s a new log of my attempt to change the SP from to 26. It updated in the thermostat but not the UI

Here’s where I attempt to change the SP in the UI -

       luup_log:6: dataMine: Watching: D[5] S[urn:upnp-org:serviceId:TemperatureSensor1] V[CurrentTemperature] <0x402>
06      11/14/11 14:02:07.225   Device_Variable::m_szValue_set device: 6 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelCnt was: 3 now: 3 #hooks: 0 upnp: 0 v:0x7b9fd8/NONE duplicate:1 <0x402>
06      11/14/11 14:02:07.226   Device_Variable::m_szValue_set device: 6 service: urn:cd-jackson-com:serviceId:DataMine1 variable: ChannelRec was: 3 now: 3 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x402>
02      11/14/11 14:02:20.015   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
41      11/14/11 14:02:20.017   ZWaveSerial::Send XXXX  node 2 using route 0.0.40.137 autoroute: 1 direct: 0 <0xc04>
41      11/14/11 14:02:20.018   0x1 0xd 0x0 0x19 0x2 0x2 0x25 0x2 0x5 0x0 0x0 0x0 0x0 0x1 0xc8 (#\r####%########) <0xc04>
42      11/14/11 14:02:20.041   0x6 0x1 0x4 0x1 0x19 0x1 0xe2 (#######) <0x1406>
42      11/14/11 14:02:20.041   got expected ACK <0x1406>
41      11/14/11 14:02:20.042   ACK: 0x6 (#) <0x1406>
42      11/14/11 14:02:20.090   0x1 0x5 0x0 0x19 0x1 0x0 0xe2 (#######) <0x1406>
41      11/14/11 14:02:20.091   ACK: 0x6 (#) <0x1406>
42      11/14/11 14:02:20.141   0x1 0x9 0x0 0x4 0x0 0x2 0x3 0x25 0x3 0x0 0xd5 (#######%###) <0x1406>
41      11/14/11 14:02:20.142   ACK: 0x6 (#) <0x1406>
02      11/14/11 14:02:20.154   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
41      11/14/11 14:02:20.155   ZWaveSerial::Send XXXX  node 2 using route 0.0.40.137 autoroute: 1 direct: 0 <0xc04>
41      11/14/11 14:02:20.156   0x1 0xd 0x0 0x19 0x2 0x2 0x40 0x2 0x5 0x0 0x0 0x0 0x0 0x2 0xae (#\r####@########) <0xc04>
08      11/14/11 14:02:20.168   JobHandler_LuaUPnP::HandleActionRequest device: 5 service: urn:upnp-org:serviceId:TemperatureSetpoint1_Heat action: SetCurrentSetpoint <0x4408>
08      11/14/11 14:02:20.169   JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=5 <0x4408>
08      11/14/11 14:02:20.170   JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:TemperatureSetpoint1_Heat <0x4408>
08      11/14/11 14:02:20.171   JobHandler_LuaUPnP::HandleActionRequest argument action=SetCurrentSetpoint <0x4408>
08      11/14/11 14:02:20.171   JobHandler_LuaUPnP::HandleActionRequest argument NewCurrentSetpoint=26 <0x4408>
08      11/14/11 14:02:20.172   JobHandler_LuaUPnP::HandleActionRequest argument rand=0.631132904025657 <0x4408>
06      11/14/11 14:02:20.173   Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSetpoint1_Heat variable: SetpointTarget was: 22 now: 26 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x4408>
42      11/14/11 14:02:20.191   0x6 0x1 0x4 0x1 0x19 0x1 0xe2 (#######) <0x1406>
42      11/14/11 14:02:20.191   got expected ACK <0x1406>
41      11/14/11 14:02:20.192   ACK: 0x6 (#) <0x1406>
02      11/14/11 14:02:20.195   ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x4408>
41      11/14/11 14:02:20.202   0x1 0x3 0x0 0x16 0xea (#####) <0xc04>
42      11/14/11 14:02:20.241   0x1 0x5 0x0 0x19 0x2 0x0 0xe1 0x18 (########) <0x1406>
41      11/14/11 14:02:20.241   ACK: 0x6 (#) <0x1406>
01      11/14/11 14:02:20.251   got CAN <0x1406>
01      11/14/11 14:02:20.252   ZWaveSerial::Send m_iFrameID 29 type 0x0 command 0x16 got repeat failure 24 iNumFailedResponse 1 time 22251 start time 22210 wait 2000 m_iSendsWithoutReceive 0 <0xc04>
01      11/14/11 14:02:20.252   ZWaveJobHandler::SendDataAbort failed <0xc04>
01      11/14/11 14:02:20.253   ZWJob_PollNode::Run job job#2 :pollnode #2 (0x798820) N:2 P:100 S:1 ZW_Send_Data to node 2 failed 4 req (nil)/-1 abort m_iFrameID 0 <0xc04>
02      11/14/11 14:02:20.254   ZWJob_PollNode::PollFailed job job#2 :pollnode #2 (0x798820) N:2 P:100 S:1 node 2 battery 0 <0xc04>
06      11/14/11 14:02:20.255   Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastError was: Node 4 failed now: Poll failed #hooks: 0 upnp: 0 v:0x7f5d08/NONE duplicate:0 <0xc04>
04      11/14/11 14:02:20.258   <Job ID="2" Name="pollnode #2 2 cmds" Device="3" Created="11-11-14 14:02:20" Started="11-11-14 14:02:20" Completed="11-11-14 14:02:20" Duration="0.245098000" Runtime="0.242949000" Status="Failed" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0xc04>
41      11/14/11 14:02:20.261   0x1 0x3 0x0 0x16 0xea (#####) <0x803>
42      11/14/11 14:02:20.291   0x1 0x9 0x0 0x4 0x0 0x2 0x3 0x40 0x3 0x0 0xb0 0x18 (#######@####) <0x1406>
41      11/14/11 14:02:20.292   ACK: 0x6 (#) <0x1406>
01      11/14/11 14:02:20.301   got CAN <0x1406>
01      11/14/11 14:02:20.302   ZWaveSerial::Send m_iFrameID 28 type 0x0 command 0x16 got repeat failure 24 iNumFailedResponse 1 time 22301 start time 22270 wait 2000 m_iSendsWithoutReceive 0 <0x803>
01      11/14/11 14:02:20.302   ZWJob_PollNode::Abort job job#2 :pollnode #2 (0x798820) N:2 P:100 S:2 to node 2 failed 2 <0x803>
02      11/14/11 14:02:20.304   JobHandler::PurgeCompletedJobs purge job#2 :pollnode #2 (0x798820) N:2 P:100 S:2 pollnode #2 2 cmds status 2 <0xc04>
02      11/14/11 14:02:20.307   UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02      11/14/11 14:02:20.308   ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
41      11/14/11 14:02:20.310   ZWaveSerial::Send XXXX  node 4 using route 0.101.32.35 autoroute: 1 direct: 0 <0xc04>
41      11/14/11 14:02:20.311   0x1 0x10 0x0 0x19 0x4 0x5 0x43 0x1 0x1 0x1 0x1a 0x5 0x0 0x0 0x0 0x0 0x3 0xa9 (######C###########) <0xc04>
42      11/14/11 14:02:20.341   0x6 0x1 0x4 0x1 0x19 0x1 0xe2 (#######) <0x1406>
42      11/14/11 14:02:20.341   got expected ACK <0x1406>
41      11/14/11 14:02:20.342   ACK: 0x6 (#) <0x1406>
42      11/14/11 14:02:20.471   0x1 0x5 0x0 0x19 0x3 0x6 0xe6 (#######) <0x1406>
41      11/14/11 14:02:20.471   ACK: 0x6 (#) <0x1406>
06      11/14/11 14:02:20.481   Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 0 now: 1 #hooks: 0 upnp: 0 v:0x79e478/NONE duplicate:0 <0x803>
06      11/14/11 14:02:20.483   Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastError was: Poll failed now: Node 4 failed #hooks: 0 upnp: 0 v:0x7f5d08/NONE duplicate:0 <0x803>
02      11/14/11 14:02:20.484   ZWJob_SendData::ReceivedFrame job job#3 :Heat SP 26 node 4 (0x81fcd8) N:4 P:35 S:5 to node 4 command 67/1 failed m_cTxStatus 6 retries 0 <0x803>
02      11/14/11 14:02:20.488   UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02      11/14/11 14:02:20.489   ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
41      11/14/11 14:02:20.491   ZWaveSerial::Send XXXX  node 4 using route 0.58.55.48 autoroute: 1 direct: 0 <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>
42      11/14/11 14:02:20.521   0x6 0x1 0x4 0x1 0x19 0x1 0xe2 (#######) <0x1406>
42      11/14/11 14:02:20.521   got expected ACK <0x1406>
41      11/14/11 14:02:20.522   ACK: 0x6 (#) <0x1406>
42      11/14/11 14:02:20.691   0x1 0x5 0x0 0x19 0x4 0x1 0xe6 (#######) <0x1406>
41      11/14/11 14:02:20.691   ACK: 0x6 (#) <0x1406>
02      11/14/11 14:02:20.701   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 1 <0x803>
02      11/14/11 14:02:20.705   UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02      11/14/11 14:02:20.706   ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
41      11/14/11 14:02:20.708   ZWaveSerial::Send XXXX  node 4 using route 0.58.55.48 autoroute: 1 direct: 0 <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>
42      11/14/11 14:02:20.740   0x6 0x1 0x4 0x1 0x19 0x1 0xe2 (#######) <0x1406>
42      11/14/11 14:02:20.741   got expected ACK <0x1406>
41      11/14/11 14:02:20.742   ACK: 0x6 (#) <0x1406>
42      11/14/11 14:02:20.961   0x1 0x5 0x0 0x19 0x5 0x1 0xe7 (#######) <0x1406>
41      11/14/11 14:02:20.961   ACK: 0x6 (#) <0x1406>
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>
02      11/14/11 14:02:20.975   UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02      11/14/11 14:02:20.976

And here’s where it actually changes when the thermostat wakes up

02      11/14/11 14:03:50.183   ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
41      11/14/11 14:03:50.184   ZWaveSerial::Send XXXX  node 2 using route 0.0.44.184 autoroute: 1 direct: 0 ... <0xc04>
41      11/14/11 14:03:50.186   0x1 0xd 0x0 0x19 0x2 0x2 0x40 0x2 0x5 0x0 0x0 0x0 0x0 0xa 0xa6 (#\r####@######\n#) <0xc04>
42      11/14/11 14:03:50.221   0x6 0x1 0x4 0x1 0x19 0x1 0xe2 (#######) <0x1406>
42      11/14/11 14:03:50.221   got expected ACK <0x1406>
41      11/14/11 14:03:50.222   ACK: 0x6 (#) <0x1406>
42      11/14/11 14:03:50.270   0x1 0x5 0x0 0x19 0xa 0x0 0xe9 (####\n##) <0x1406>
41      11/14/11 14:03:50.271   ACK: 0x6 (#) <0x1406>
42      11/14/11 14:03:50.321   0x1 0x9 0x0 0x4 0x0 0x2 0x3 0x40 0x3 0x0 0xb0 (#######@###) <0x1406>
41      11/14/11 14:03:50.321   ACK: 0x6 (#) <0x1406>
04      11/14/11 14:03:50.333   <Job ID="4" Name="pollnode #2 2 cmds" Device="3" Created="11-11-14 14:03:50" Started="11-11-14 14:03:50" Completed="11-11-14 14:03:50" Duration="0.321132000" Runtime="0.319539000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <0x803>
02      11/14/11 14:04:16.123   UPnPCallbackEventHandler 6 start PIDLOG2 20580 <0x2009>
42      11/14/11 14:04:16.801   0x1 0x8 0x0 0x4 0x0 0x4 0x2 0x84 0x7 0x76 (#########v) <0x1406>
41      11/14/11 14:04:16.802   ACK: 0x6 (#) <0x1406>
06      11/14/11 14:04:16.811   Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: LastWakeup was: 1321279200 now: 1321279456 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x803>
02      11/14/11 14:04:16.814   ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x803>
02      11/14/11 14:04:16.815   ZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil) <0x803>
02      11/14/11 14:04:16.816   ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x803>
02      11/14/11 14:04:16.834   UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02      11/14/11 14:04:16.835   ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
41      11/14/11 14:04:16.836   ZWaveSerial::Send XXXX  node 4 using route 0.0.49.52 autoroute: 1 direct: 0 <0xc04>
41      11/14/11 14:04:16.837   0x1 0x10 0x0 0x19 0x4 0x5 0x43 0x1 0x1 0x1 0x1a 0x5 0x0 0x0 0x0 0x0 0xb 0xa1 (######C###########) <0xc04>
42      11/14/11 14:04:16.851   0x6 0x1 0x4 0x1 0x19 0x1 0xe2 (#######) <0x1406>
42      11/14/11 14:04:16.851   got expected ACK <0x1406>
41      11/14/11 14:04:16.852   ACK: 0x6 (#) <0x1406>
42      11/14/11 14:04:16.911   0x1 0x5 0x0 0x19 0xb 0x0 0xe8 (#######) <0x1406>
41      11/14/11 14:04:16.911   ACK: 0x6 (#) <0x1406>
06      11/14/11 14:04:16.921   Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure was: 1 now: 0 #hooks: 0 upnp: 0 v:0x79e478/NONE duplicate:0 <0x803>
06      11/14/11 14:04:16.922   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:0x7f5d08/NONE duplicate:1 <0x803>
04      11/14/11 14:04:16.925   <Job ID="5" Name="send failed node 4" Device="5" Created="11-11-14 14:04:16" Started="11-11-14 14:04:16" Completed="11-11-14 14:04:16" Duration="0.110942000" Runtime="0.103293000" Status="Successful" LastNote="Transmit was ok" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/> <0x803>
02      11/14/11 14:04:16.929   UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02      11/14/11 14:04:16.931   ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
41      11/14/11 14:04:16.933   ZWaveSerial::Send XXXX  node 4 using route 0.0.88.14 autoroute: 1 direct: 0 <0xc04>
41      11/14/11 14:04:16.934   0x1 0xd 0x0 0x19 0x4 0x2 0x84 0x8 0x5 0x0 0x0 0x0 0x0 0xc 0x68 (#\r############h) <0xc04>
42      11/14/11 14:04:16.961   0x6 0x1 0x4 0x1 0x19 0x1 0xe2 (#######) <0x1406>
42      11/14/11 14:04:16.961   got expected ACK <0x1406>
41      11/14/11 14:04:16.962   ACK: 0x6 (#) <0x1406>
42      11/14/11 14:04:17.011   0x1 0x5 0x0 0x19 0xc 0x0 0xef (#######) <0x1406>
41      11/14/11 14:04:17.011   ACK: 0x6 (#) <0x1406>
04      11/14/11 14:04:17.024   <Job ID="6" Name="Wakeup done 4" Device="5" Created="11-11-14 14:04:16" Started="11-11-14 14:04:16" Completed="11-11-14 14:04:17" Duration="0.206535000" Runtime="0.94609000" Status="Successful" LastNote="Transmit was ok" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/>^[[5~

[ajlennon]

All of a sudden overnight Vera 2 is no longer communicating with either the boiler actuator or the thermostat (!)

I’m getting various messages from the UI in including “unable to communicate with node” and turn heating on or off

I’ve tried healing the network.

The logs seem to be saying something about the actuator not being configured!

02      11/15/11 11:03:13.011   UPnPCallbackEventHandler 7 start PIDLOG2 7265 <0x300d>
08      11/15/11 11:04:38.010   Scene::RunScene running 3 Heating <0x803>
50      11/15/11 11:04:38.012   luup_log:0: Heating SetPoint = 19 <0x803>
50      11/15/11 11:04:38.013   luup_log:0: Temperature = 19 <0x803>
50      11/15/11 11:04:38.013   luup_log:0: Heating already off <0x803>
08      11/15/11 11:04:38.014   JobHandler_LuaUPnP::AlarmCallback Ran timer: Four Minute next at 1321355318 now 1321355078 <0x803>
08      11/15/11 11:07:17.928   JobHandler_LuaUPnP::HandleActionRequest device: 3 service: urn:upnp-org:serviceId:HVAC_UserOperatingMode1 action: SetModeTarget <0x5408>
08      11/15/11 11:07:17.929   JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=3 <0x5408>
08      11/15/11 11:07:17.930   JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:HVAC_UserOperatingMode1 <0x5408>
08      11/15/11 11:07:17.931   JobHandler_LuaUPnP::HandleActionRequest argument action=SetModeTarget <0x5408>
08      11/15/11 11:07:17.931   JobHandler_LuaUPnP::HandleActionRequest argument NewModeTarget=HeatOn <0x5408>
08      11/15/11 11:07:17.932   JobHandler_LuaUPnP::HandleActionRequest argument rand=0.6412345498113862 <0x5408>
02      11/15/11 11:07:17.970   ZWaveThermostat::ReceivedMessage no COMMAND_CLASS_THERMOSTAT_MODE <0x5408>
02      11/15/11 11:07:17.971   ZWaveNode::ReceivedMessage serv urn:upnp-org:serviceId:HVAC_UserOperatingMode1 action SetModeTarget unhandled <0x5408>
02      11/15/11 11:07:17.971   JobHandler_LuaUPnP::RunAction device 3 action urn:upnp-org:serviceId:HVAC_UserOperatingMode1/SetModeTarget failed with -911/ERROR Thermostat is not configured <0x5408>
08      11/15/11 11:07:21.207   JobHandler_LuaUPnP::HandleActionRequest device: 3 service: urn:upnp-org:serviceId:HVAC_UserOperatingMode1 action: SetModeTarget <0x5408>
08      11/15/11 11:07:21.208   JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=3 <0x5408>
08      11/15/11 11:07:21.208   JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:HVAC_UserOperatingMode1 <0x5408>
08      11/15/11 11:07:21.209   JobHandler_LuaUPnP::HandleActionRequest argument action=SetModeTarget <0x5408>
08      11/15/11 11:07:21.209   JobHandler_LuaUPnP::HandleActionRequest argument NewModeTarget=HeatOn

I’m baffled as to what changed overnight. Any ideas?

[sparkejj]

@ajlennon

I’m baffled as to what changed overnight. Any ideas?

Is there a repair report for 2am this morning? ([tt]Z-Wave device[/tt] > [tt]Repair[/tt])