We have moved at community.getvera.com

Author Topic: Waking up devices / Issue with thermostat setpoints  (Read 11997 times)

Offline ajlennon

  • Full Member
  • ***
  • Posts: 154
  • Karma: +0/-0
Waking up devices / Issue with thermostat setpoints
« on: November 11, 2011, 04:28:18 pm »
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
http://www.dynamicdevices.co.uk

Offline utz

  • Sr. Member
  • ****
  • Posts: 274
  • Karma: +0/-0
Re: Waking up devices / Issue with thermostat setpoints
« Reply #1 on: November 12, 2011, 10:29:06 am »
I have the problem too and have not found a solution yet (I have not looked into it in too much detail yet). 

Offline intveltr

  • Beta Testers
  • Hero Member
  • *****
  • Posts: 1741
  • Karma: +102/-5
Re: Waking up devices / Issue with thermostat setpoints
« Reply #2 on: November 12, 2011, 10:43:34 am »
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.
HomeWave is available in the App Store!  Turn your iPhone/iPad into an easy-to-use remote control for Vera.

Offline oTi@

  • Community Beta
  • Master Member
  • ******
  • Posts: 4041
  • Karma: +32/-6
  • UI what ?!
Re: Waking up devices / Issue with thermostat setpoints
« Reply #3 on: November 12, 2011, 11:17:56 am »
[...] 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).

Quote
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.
« Last Edit: November 13, 2011, 06:44:01 am by oTi@ »
Dezwaved at the moment...

Offline ajlennon

  • Full Member
  • ***
  • Posts: 154
  • Karma: +0/-0
Re: Waking up devices / Issue with thermostat setpoints
« Reply #4 on: November 12, 2011, 11:37:27 am »

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

Offline oTi@

  • Community Beta
  • Master Member
  • ******
  • Posts: 4041
  • Karma: +32/-6
  • UI what ?!
Re: Waking up devices / Issue with thermostat setpoints
« Reply #5 on: November 12, 2011, 11:46:52 am »
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.

Quote
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.

Quote
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 @intveltr's report I got the impression that is the case, but the GUI doesn't follow along.
Dezwaved at the moment...

Offline ajlennon

  • Full Member
  • ***
  • Posts: 154
  • Karma: +0/-0
Re: Waking up devices / Issue with thermostat setpoints
« Reply #6 on: November 13, 2011, 06:37:17 am »

"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?)

Offline oTi@

  • Community Beta
  • Master Member
  • ******
  • Posts: 4041
  • Karma: +32/-6
  • UI what ?!
Re: Waking up devices / Issue with thermostat setpoints
« Reply #7 on: November 13, 2011, 06:52:18 am »
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.)
Dezwaved at the moment...

Offline ajlennon

  • Full Member
  • ***
  • Posts: 154
  • Karma: +0/-0
Re: Waking up devices / Issue with thermostat setpoints
« Reply #8 on: November 13, 2011, 06:56:51 am »
"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

Offline oTi@

  • Community Beta
  • Master Member
  • ******
  • Posts: 4041
  • Karma: +32/-6
  • UI what ?!
Re: Waking up devices / Issue with thermostat setpoints
« Reply #9 on: November 13, 2011, 07:08:59 am »
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?
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?
« Last Edit: November 13, 2011, 07:11:23 am by oTi@ »
Dezwaved at the moment...

Offline ajlennon

  • Full Member
  • ***
  • Posts: 154
  • Karma: +0/-0
Re: Waking up devices / Issue with thermostat setpoints
« Reply #10 on: November 13, 2011, 07:12:00 am »

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

Offline oTi@

  • Community Beta
  • Master Member
  • ******
  • Posts: 4041
  • Karma: +32/-6
  • UI what ?!
Re: Waking up devices / Issue with thermostat setpoints
« Reply #11 on: November 13, 2011, 07:24:26 am »
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 Poll now? (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
« Last Edit: November 13, 2011, 07:34:38 am by oTi@ »
Dezwaved at the moment...

Offline ajlennon

  • Full Member
  • ***
  • Posts: 154
  • Karma: +0/-0
Re: Waking up devices / Issue with thermostat setpoints
« Reply #12 on: November 13, 2011, 07:40:22 am »
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

Code: [Select]
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: SetCurrentSetpoint <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: SetpointTarget was: 28 now: 22 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x50008>
02 11/13/11 12:12:34.503 ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x50008>
02 11/13/11 12:12:34.506 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:12:34.507 ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
06 11/13/11 12:12:34.661 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure 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: LastError 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 ZWJob_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 0 <0x803>
02 11/13/11 12:12:34.668 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:12:34.669 ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
02 11/13/11 12:12:34.861 ZWJob_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 1 <0x803>
02 11/13/11 12:12:34.866 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:12:34.866 ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
02 11/13/11 12:12:35.051 ZWJob_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 2 <0x803>
02 11/13/11 12:12:35.056 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:12:35.056 ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
02 11/13/11 12:12:35.201 ZWJob_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 3 <0x803>
02 11/13/11 12:12:35.206 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:12:35.206 ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
02 11/13/11 12:12:35.391 ZWJob_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 4 <0x803>
02 11/13/11 12:12:35.396 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:12:35.396 ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
02 11/13/11 12:12:35.581 ZWJob_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 5 <0x803>
01 11/13/11 12:12:35.584 ZWJob_SendData::JobFailed job#563 :Heat SP 22 node 4 (0x7957a8) N:4 P:70 S:5 Priority 70 <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 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:12:54.183 ZW_Send_Data node 2 NO ROUTE (nil) <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 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:14:24.343 ZW_Send_Data node 2 NO ROUTE (nil) <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: LastWakeup was: 1321186271 now: 1321186527 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x803>
02 11/13/11 12:15:27.455 ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x803>
02 11/13/11 12:15:27.456 ZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil) <0x803>
02 11/13/11 12:15:27.458 ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x803>
02 11/13/11 12:15:27.472 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:15:27.473 ZW_Send_Data node 4 NO ROUTE (nil) <0xc04>
06 11/13/11 12:15:27.611 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommFailure 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: LastError 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 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:15:27.622 ZW_Send_Data node 4 NO ROUTE (nil) <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 ZWaveNode::HandlePollUpdate_Basic_Set node 4 device 5 unhandled <0x803>
02 11/13/11 12:15:54.016 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:15:54.173 ZW_Send_Data node 2 NO ROUTE (nil) <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: CurrentTemperature was: 22 now: 23 #hooks: 0 upnp: 0 v:0x79ea48/NONE duplicate:0 <0x803>
02 11/13/11 12:17:24.015 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:17:24.223 ZW_Send_Data node 2 NO ROUTE (nil) <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 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:18:54.183 ZW_Send_Data node 2 NO ROUTE (nil) <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: LastWakeup was: 1321186527 now: 1321186783 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x803>
02 11/13/11 12:19:43.493 ZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil) <0x803>
02 11/13/11 12:19:43.495 ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x803>
02 11/13/11 12:19:43.508 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:19:43.509 ZW_Send_Data node 4 NO ROUTE (nil) <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: LogIpRequest <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 LOG_CHECK_MEMORY_LEAK pMem start 0x7ff000 now 0x80f000 last 0x808000 leaked 65536 <0x803>
02 11/13/11 12:20:24.014 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:20:24.183 ZW_Send_Data node 2 NO ROUTE (nil) <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: LogIpRequest <0x51c0e>
02 11/13/11 12:21:54.015 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:21:54.154 ZW_Send_Data node 2 NO ROUTE (nil) <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 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:23:24.183 ZW_Send_Data node 2 NO ROUTE (nil) <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: LastWakeup was: 1321186783 now: 1321187039 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x803>
02 11/13/11 12:23:59.453 ZWaveNode::Wakeup did a poll for 4 256 seconds existing (nil) heal (nil) <0x803>
02 11/13/11 12:23:59.455 ZWJob_SendData  UPDATE MANUAL ROUTE 4=(nil) <0x803>
02 11/13/11 12:23:59.468 UPDATE MANUAL ROUTE2 4=(nil) <0xc04>
02 11/13/11 12:23:59.469 ZW_Send_Data node 4 NO ROUTE (nil) <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: LogIpRequest <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 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:24:54.183 ZW_Send_Data node 2 NO ROUTE (nil) <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 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:26:26.380 ZWaveSerial::GetFrame 0x7f3ff7d8 timed out now 0 m_listGetFramePending 0 <0xc04>
02 11/13/11 12:26:26.381 ZWaveJobHandler::SendDataAbort got m_iFrameID 0 <0xc04>
01 11/13/11 12:26:26.382 ZWJob_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 0 <0xc04>
02 11/13/11 12:26:26.383 ZWJob_PollNode::PollFailed job job#577 :pollnode #2 (0x7d1520) N:2 P:100 S:1 node 2 battery 0 <0xc04>
06 11/13/11 12:26:26.383 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: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 JobHandler::PurgeCompletedJobs purge job#577 :pollnode #2 (0x7d1520) N:2 P:100 S:2 pollnode #2 2 cmds status 2 <0xc04>
02 11/13/11 12:27:54.015 ZW_Send_Data node 2 NO ROUTE (nil) <0xc04>
02 11/13/11 12:27:54.183 ZW_Send_Data node 2 NO ROUTE (nil) <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...
« Last Edit: November 13, 2011, 07:45:09 am by oTi@ »

Offline ajlennon

  • Full Member
  • ***
  • Posts: 154
  • Karma: +0/-0
Re: Waking up devices / Issue with thermostat setpoints
« Reply #13 on: November 13, 2011, 07:41:50 am »
...

Still at 29 locally...

Code: [Select]
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.
« Last Edit: November 13, 2011, 07:46:51 am by oTi@ »

Offline ajlennon

  • Full Member
  • ***
  • Posts: 154
  • Karma: +0/-0
Re: Waking up devices / Issue with thermostat setpoints
« Reply #14 on: November 13, 2011, 07:52:31 am »
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: [Select]
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   <Job ID="0" Name="init" Device="1" Created="11-11-13 12:42:26" Started="11-11-13 12:42:26" Completed="11-11-13 12:42:31" Duration="4.438797000" Runtime="4.431230000" Status="Successful" LastNote=""/> <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   <Job ID="1" Name="getnodes" Device="" Created="11-11-13 12:42:31" Started="11-11-13 12:42:31" Completed="11-11-13 12:42:31" Duration="0.212695000" Runtime="0.167008000" Status="Successful" LastNote=""/> <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   <Job ID="2" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:42:46" Started="11-11-13 12:42:46" Completed="11-11-13 12:42:46" Duration="0.390921000" Runtime="0.388785000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <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   <Job ID="3" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:44:16" Started="11-11-13 12:44:16" Completed="11-11-13 12:44:16" Duration="0.331084000" Runtime="0.329345000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <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   <Job ID="4" Name="Wakeup done 4" Device="5" Created="11-11-13 12:45:19" Started="11-11-13 12:45:19" Completed="11-11-13 12:45:19" Duration="0.137271000" Runtime="0.126147000" Status="Successful" LastNote="Transmit was ok" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/> <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   <Job ID="5" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:45:46" Started="11-11-13 12:45:46" Completed="11-11-13 12:45:46" Duration="0.461014000" Runtime="0.457381000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <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   <Job ID="6" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:47:16" Started="11-11-13 12:47:16" Completed="11-11-13 12:47:16" Duration="0.331161000" Runtime="0.328301000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <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   <Job ID="7" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:48:46" Started="11-11-13 12:48:46" Completed="11-11-13 12:48:46" Duration="0.381254000" Runtime="0.377535000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <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   <Job ID="8" Name="Wakeup done 4" Device="5" Created="11-11-13 12:49:35" Started="11-11-13 12:49:35" Completed="11-11-13 12:49:35" Duration="0.138281000" Runtime="0.124657000" Status="Successful" LastNote="Transmit was ok" Node="4" NodeType="ZWaveThermostat" NodeDescription="_Thermostat"/> <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   <Job ID="9" Name="pollnode #2 2 cmds" Device="3" Created="11-11-13 12:50:16" Started="11-11-13 12:50:16" Completed="11-11-13 12:50:16" Duration="0.501066000" Runtime="0.499414000" Status="Successful" LastNote="" Node="2" NodeType="ZWaveThermostat" NodeDescription="Combi Boiler"/> <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