02	12/28/22 12:47:03.375	Finished rotate logs <0x77ccd320>
08	12/28/22 13:27:17.300	JobHandler_LuaUPnP::HandleActionRequest device: 0 service: urn:micasaverde-com:serviceId:HomeAutomationGateway1 action: RunLua <0x73e2d520>
08	12/28/22 13:27:17.301	JobHandler_LuaUPnP::HandleActionRequest argument id=lu_action <0x73e2d520>
08	12/28/22 13:27:17.301	JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:micasaverde-com:serviceId:HomeAutomationGateway1 <0x73e2d520>
08	12/28/22 13:27:17.301	JobHandler_LuaUPnP::HandleActionRequest argument action=RunLua <0x73e2d520>
08	12/28/22 13:27:17.301	JobHandler_LuaUPnP::HandleActionRequest argument Code=local resultCode, resultString, job, returnArguments = luup.call_action('urn:micasaverde-com:serviceId:ZWaveNetwork1','SendData',{Node='22', Data='0x91 4'}, 1)
luup.log("resultCode: "..resultCode)
luup.log("resultString: "..resultString)
luup.log("job: "..(job or 'nil'))
for i,v in ipairs(returnArguments) do
 luup.log("i,v: "..i..", "..v)
end

 <0x73e2d520>
28	12/28/22 13:27:17.301	JobHandler_LuaUPnP::HandleActionRequest testing Bluetooth urn:micasaverde-com:serviceId:HomeAutomationGateway1, urn:micasaverde-com:serviceId:BluetoothNetwork1, (nil) <0x73e2d520>
08	12/28/22 13:27:17.302	JobHandler_LuaUPnP::HandleActionRequest device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 action: SendData <0x73e2d520>
08	12/28/22 13:27:17.303	JobHandler_LuaUPnP::HandleActionRequest argument Node=22 <0x73e2d520>
08	12/28/22 13:27:17.303	JobHandler_LuaUPnP::HandleActionRequest argument Data=0x91 4 <0x73e2d520>
24	12/28/22 13:27:17.303	sbrk ZWaveJobHandler::sbrkaddjob pMem 0x14a7000/21655552 diff: 10350592 quit 0 <0x73e2d520>
50	12/28/22 13:27:17.305	luup_log:0: resultCode: 0 <0x73e2d520>
50	12/28/22 13:27:17.305	luup_log:0: resultString:  <0x73e2d520>
50	12/28/22 13:27:17.305	luup_log:0: job: 4 <0x73e2d520>
24	12/28/22 13:27:17.305	ZWJob_SendData::Run job job#4 :childcmd node 22 dev:1691 (0xcb7be8) N:22 P:35 S:1 Id: 4 to node 22 command 0x91/0x4 callback 19 m_iFrameID 73 method 2 options 0x5 retries 0 of 5 <0x7626e520>
24	12/28/22 13:27:17.316	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0x12df0b8 <0x7626e520>
41	12/28/22 13:27:17.316	ZWaveSerial::Send XXXX  node 22 using route 0.101.32.50 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:27:17.326	ZWaveSerial::Send m_iFrameID 73 type 0x0 command 0x13 sent ok waiting for 2 ulTime 56325 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:27:17.336	got expected ACK <0x75e6e520>
24	12/28/22 13:27:17.337	ZWaveSerial::Send woke up: ulTime 56325 ulTime_end 56336 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:27:17.337	ZWaveSerial::Send m_iFrameID 73 type 0x0 command 0x13 sent ok waiting for 2 ulTime 56325 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:27:17.337	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 74 gwf_sd <0x75e6e520>
24	12/28/22 13:27:17.362	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 74 gwf_sd <0x75e6e520>
24	12/28/22 13:27:17.362	ZWaveSerial::ReceivedFrame m_iFrameID 74 gwf_sd is a response frame for m_iFrameID 73 sd_rjob#4 :childcmd node 22 dev:1691 (0xcb7be8) N:22 P:35 S:1 Id: 4 we're waiting got ack 1 expected response 2 <0x75e6e520>
24	12/28/22 13:27:17.362	ZWaveSerial::Send woke up: ulTime 56325 ulTime_end 56362 TimeToWaitInMs 20000 m_pres 0x118c238 m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:27:17.362	ZWaveSerial::Send m_iFrameID 73 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:27:17.363	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0x12df0b8 now (nil) <0x7626e520>
24	12/28/22 13:27:17.363	ZWJob_SendData::Run done: job job#4 :childcmd node 22 dev:1691 (0xcb7be8) N:22 P:35 S:7 Id: 4 took 59 ms m_enumSendMethod 2 to node 22 command 0x91/0x4 callback 19 m_iFrameID 73 total 0.59228000 sec type 2 <0x7626e520>
24	12/28/22 13:27:17.393	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 75 gwf_sd <0x75e6e520>
24	12/28/22 13:27:17.410	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 75 gwf_sd <0x75e6e520>
24	12/28/22 13:27:17.410	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:13/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x13 m_iFrameID 75 gwf_sd <0x75e6e520>
24	12/28/22 13:27:17.410	ZWaveJobHandler::DoReceivedFrame m_iFrameID 75 gwf_sd node 0 command 0x13 data  <0x7686e520>
24	12/28/22 13:27:17.411	ZWaveJobHandler::DoReceivedFrame m_iFrameID 75 passing to job#4 :childcmd node 22 dev:1691 (0xcb7be8) N:22 P:35 S:5 Id: 4 auto del: 1 <0x7686e520>
24	12/28/22 13:27:17.411	ZWaveNode::m_bLastContactFailed_set device 1691 = 0, force 0, m_bNotListening 0 zw poll7 <0x7686e520>
24	12/28/22 13:27:17.411	ZWJob_SendData::ReceivedFrame ok job job#4 :childcmd node 22 dev:1691 (0xcb7be8) N:22 P:35 S:5 Id: 4 to node 22 command 145/4 ok first try resend: 0 waiting 0/0 got 0 <0x7686e520>
24	12/28/22 13:27:17.411	ZWaveNode::m_bLastContactFailed_set device 1691 = 0, force 0, m_bNotListening 0 zw poll8 <0x7686e520>
04	12/28/22 13:27:17.412	<Job ID="4" Name="childcmd node 22" Device="1691" Created="2022-12-28 13:27:17" Started="2022-12-28 13:27:17" Completed="2022-12-28 13:27:17" Duration="0.108400000" Runtime="0.107810000" Status="Successful" LastNote="SUCCESS! Transmit was OK" Node="22" NodeType="ZWaveThermostat" NodeDescription="Honeywell Thermostat"/> <0x7686e520>
06	12/28/22 13:27:20.053	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 0B 96 07 00 7A 2D 01 49  now: 0A 52 0D 0C D8 03 00 BC 29 01 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:20.054	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252031 now: 1672252040 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:20.060	Device_Variable::m_szValue_set device: 2346 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252005 now: 1672252040 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:20.061	Device_Variable::m_szValue_set device: 2347 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252005 now: 1672252040 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:21.128	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 0C D8 03 00 BC 29 01 79  now: 0A 52 0D 0D 1C 02 00 A1 2E 01 59  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:21.129	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252040 now: 1672252041 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:21.135	Device_Variable::m_szValue_set device: 2348 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252006 now: 1672252041 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:21.136	Device_Variable::m_szValue_set device: 2349 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252006 now: 1672252041 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:24.532	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 0D 1C 02 00 A1 2E 01 59  now: 0A 52 09 0E A1 08 00 DC 0C 02 39  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:24.533	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252041 now: 1672252044 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:24.542	Device_Variable::m_szValue_set device: 2672 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 71.8 now: 71.6 #hooks: 1 upnp: 0 skip: 0 v:0xd6d338/NONE duplicate:0 <0x73b1d520>
50	12/28/22 13:27:24.542	luup_log:1471: RFXtrx: logVariableChange- device: 2672 new value: 71.6 <0x73b1d520>
06	12/28/22 13:27:24.564	Device_Variable::m_szValue_set device: 2672 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672251965 now: 1672252044 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:24.585	Device_Variable::m_szValue_set device: 1580 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 03 96 07 00 7A 2D 01 69  now: 0A 52 09 04 A1 08 00 DC 0C 02 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:27:24.586	Device_Variable::m_szValue_set device: 1580 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252031 now: 1672252044 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:27:25.863	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 0E A1 08 00 DC 0C 02 39  now: 0A 52 0D 0F 3B 01 00 A9 30 01 69  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:25.864	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252044 now: 1672252045 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:25.869	Device_Variable::m_szValue_set device: 2334 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252010 now: 1672252045 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:25.870	Device_Variable::m_szValue_set device: 2335 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252010 now: 1672252045 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:27.102	Device_Variable::m_szValue_set device: 1523 service: urn:micasaverde-com:serviceId:HaDevice1 variable: WakeupRatings was: 5.00 now: 5.00 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x7686e520>
24	12/28/22 13:27:27.103	ZWaveJobHandler::UpdateDeviceTimes <0x7686e520>
06	12/28/22 13:27:28.310	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 0F 3B 01 00 A9 30 01 69  now: 0A 52 0D 10 98 01 00 CF 23 02 69  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:28.311	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252045 now: 1672252048 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:28.316	Device_Variable::m_szValue_set device: 2332 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252013 now: 1672252048 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:28.317	Device_Variable::m_szValue_set device: 2333 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252013 now: 1672252048 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:29.860	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 10 98 01 00 CF 23 02 69  now: 0A 52 0E 11 EA 01 80 F7 35 01 50  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:29.861	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252048 now: 1672252049 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:37.195	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0E 11 EA 01 80 F7 35 01 50  now: 0A 52 09 12 B5 03 80 D4 0D 02 59  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:37.196	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252049 now: 1672252057 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:37.225	Device_Variable::m_szValue_set device: 2338 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: -6.7 now: -6.2 #hooks: 0 upnp: 0 skip: 0 v:0xd6d338/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:37.226	Device_Variable::m_szValue_set device: 2338 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: MaxMinTemps was: 3.6,-3.5,-3.6,-10.3,-2.7,-11,2.1,-2.6,3.6,-7.1,-7.2,-11.2,-0.4,-10.1,3.4,-0.2,3.6,-8.9,-4.4,-11.2,1.4,-4.2,3.7,-5.4,-5.4,-10.7,-6.7,-11,1.8,-9.8,-3.6,-11,1.8,-3.5,3.6,-6,-6.2,-10.8,-1.1,-10.8,3,-0.8,3.7,-8.7,-5.8,-11,1,-5.6 now: 3.6,-3.5,-3.6,-10.3,-2.7,-11,2.1,-2.6,3.6,-7.1,-7.2,-11.2,-0.4,-10.1,3.4,-0.2,3.6,-8.9,-4.4,-11.2,1.4,-4.2,3.7,-5.4,-5.4,-10.7,-6.2,-11,1.8,-9.8,-3.6,-11,1.8,-3.5,3.6,-6,-6.2,-10.8,-1.1,-10.8,3,-0.8,3.7,-8.7,-5.8,-11,1,-5.6 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:37.227	Device_Variable::m_szValue_set device: 2338 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672251939 now: 1672252057 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:37.256	Device_Variable::m_szValue_set device: 1580 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 04 A1 08 00 DC 0C 02 79  now: 0A 52 09 05 B5 03 80 D4 0D 02 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:27:37.257	Device_Variable::m_szValue_set device: 1580 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252044 now: 1672252057 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:27:42.335	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 12 B5 03 80 D4 0D 02 59  now: 0A 52 0D 13 2F 01 00 5C 3E 01 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:42.336	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252057 now: 1672252062 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:42.352	Device_Variable::m_szValue_set device: 1546 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252027 now: 1672252062 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:42.353	Device_Variable::m_szValue_set device: 1547 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252027 now: 1672252062 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
24	12/28/22 13:27:43.100	ZWaveJobHandler::ServicePollLoop not polling 2 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:27:43.101	ZWaveJobHandler::ServicePollLoop not polling 4 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:27:43.101	ZWaveJobHandler::ServicePollLoop not polling 5 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:27:43.101	ZWaveJobHandler::ServicePollLoop not polling 6 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:27:43.101	ZWaveJobHandler::ServicePollLoop not polling 7 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:27:43.102	ZWaveJobHandler::ServicePollLoop not polling 8 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:27:43.102	ZWaveJobHandler::ServicePollLoop not polling 9 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:27:43.102	ZWaveJobHandler::ServicePollLoop not polling 10 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:27:43.102	ZWaveJobHandler::ServicePollLoop not polling node 12 m_tLastPolled_get 60 PollTime 60 <0x7686e520>
24	12/28/22 13:27:43.102	ZWaveJobHandler::ServicePollLoop not polling 14 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:27:43.103	ZWaveJobHandler::ServicePollLoop not polling node 16 m_tLastPolled_get 30 PollTime 60 <0x7686e520>
24	12/28/22 13:27:43.103	ZWaveJobHandler::ServicePollLoop not polling 20 bypass 0 freq 10800 listen 1 <0x7686e520>
24	12/28/22 13:27:43.103	ZWaveJobHandler::ServicePollLoop not polling 24 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:27:43.103	ZWaveJobHandler::ServicePollLoop not polling 31 bypass 0 freq 0 listen 1 <0x7686e520>
24	12/28/22 13:27:43.103	ZWaveJobHandler::ServicePollLoop polling node 22 <0x7686e520>
24	12/28/22 13:27:43.104	sbrk ZWaveJobHandler::sbrkaddjob pMem 0x14a7000/21655552 diff: 10350592 quit 0 <0x7686e520>
24	12/28/22 13:27:43.104	ZWJob_PollNode::ReadyToRun job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 priority 100 can cancel <0x7626e520>
24	12/28/22 13:27:43.105	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 <0x11fc660> m_eJobStatus Running after 0.1288000 seconds <0x7626e520>
24	12/28/22 13:27:43.105	ZWJob_PollNode::Run job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 size cmds 0 <0x7626e520>
24	12/28/22 13:27:43.106	ZWaveNode::AddPollingCommand node 22 device 1692 added  <0x7626e520>
24	12/28/22 13:27:43.107	ZWaveNode::AddPollingCommand node 22 device 1691 added 22/1691=0x31,22/1691=0x31,22/1691=0x40,22/1691=0x42,22/1691=0x44,22/1691=0x43,22/1691=0x43,22/1691=0x80, <0x7626e520>
24	12/28/22 13:27:43.107	ZWJob_PollNode::Run Polling job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 device 1691 with command class 0x31 command 0x4 <0x7626e520>
24	12/28/22 13:27:43.107	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:7 Id: 5 <0x11fc660> m_eJobStatus PendingData after 0.3444000 seconds <0x7626e520>
24	12/28/22 13:27:43.107	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0x12e7228 <0x7626e520>
41	12/28/22 13:27:43.107	ZWaveSerial::Send XXXX  node 22 using route 0.32.83.58 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:27:43.122	ZWaveSerial::Send m_iFrameID 76 type 0x0 command 0x13 sent ok waiting for 3 ulTime 82121 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:27:43.132	got expected ACK <0x75e6e520>
24	12/28/22 13:27:43.133	ZWaveSerial::Send woke up: ulTime 82121 ulTime_end 82132 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:27:43.133	ZWaveSerial::Send m_iFrameID 76 type 0x0 command 0x13 sent ok waiting for 3 ulTime 82121 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:27:43.133	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 77 gwf_sd <0x75e6e520>
24	12/28/22 13:27:43.158	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 77 gwf_sd <0x75e6e520>
24	12/28/22 13:27:43.158	ZWaveSerial::ReceivedFrame m_iFrameID 77 gwf_sd is a response frame for m_iFrameID 76 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:43.180	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 78 gwf_sd <0x75e6e520>
24	12/28/22 13:27:43.198	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 78 gwf_sd <0x75e6e520>
24	12/28/22 13:27:43.198	ZWaveSerial::ReceivedFrame m_iFrameID 78 gwf_sd is a request frame for m_iFrameID 76 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:43.198	ZWaveSerial::Send woke up: ulTime 82121 ulTime_end 82198 TimeToWaitInMs 20000 m_pres 0xcf4a18 m_preq 0xcf4a68 status 1 <0x7626e520>
24	12/28/22 13:27:43.198	ZWaveSerial::Send m_iFrameID 76 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:27:43.199	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0x12e7228 now (nil) <0x7626e520>
24	12/28/22 13:27:43.199	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 <0x11fc660> m_eJobStatus Waiting after 0.95304000 seconds <0x7626e520>
24	12/28/22 13:27:43.229	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 79 gwf_ach <0x75e6e520>
24	12/28/22 13:27:43.246	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 79 gwf_ach <0x75e6e520>
24	12/28/22 13:27:43.246	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 79 gwf_ach <0x75e6e520>
24	12/28/22 13:27:43.246	ZWaveJobHandler::DoReceivedFrame m_iFrameID 79 gwf_ach node 22 command 0x4 data  <0x7686e520>
24	12/28/22 13:27:43.247	ZWaveJobHandler::DoReceivedFrame m_iFrameID 79 passing to job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 auto del: 1 <0x7686e520>
24	12/28/22 13:27:43.247	ZWaveNode::HandlePollUpdate node 22 device 1691 class 0x31 command 0x5 m_iFrameID 79/19252032 data 0x1 0x22 0x0 0xc8 (#"##) <0x7686e520>
06	12/28/22 13:27:43.247	Device_Variable::m_szValue_set device: 1691 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 68.00 now: 68.00 #hooks: 0 upnp: 0 skip: 0 v:0xd6d338/NONE duplicate:1 <0x7686e520>
24	12/28/22 13:27:43.248	ZWaveNode::HandlePollUpdate_SensorMultiLevel_MeterReport 0x31 node 22 device 1691 child 22/1691 cat 17 embed: 1 type 1 rate type 0 is 68.000000 was 0.000000 prec 1 sca 0 size 2 delta -1 previous -1.000000 len 4 <0x7686e520>
24	12/28/22 13:27:43.248	ZWJob_PollNode::ReceivedFrame -end- job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 got after 0 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 22 status 0 iOK 0 iBadTx 0 iNoReply 0 data 0x1 0x22 0x0 0xc8 (#"##) <0x7686e520>
24	12/28/22 13:27:43.248	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 <0x11fc660> m_eJobStatus Queued after 0.144700000 seconds <0x7686e520>
24	12/28/22 13:27:45.249	ZWJob_PollNode::ReadyToRun job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 priority 100 can cancel <0x7626e520>
24	12/28/22 13:27:45.250	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 <0x11fc660> m_eJobStatus Running after 2.145894000 seconds <0x7626e520>
24	12/28/22 13:27:45.250	ZWJob_PollNode::Run job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 size cmds 8 <0x7626e520>
24	12/28/22 13:27:45.251	ZWJob_PollNode::Run Polling job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 device 1691 with command class 0x31 command 0x4 <0x7626e520>
24	12/28/22 13:27:45.251	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:7 Id: 5 <0x11fc660> m_eJobStatus PendingData after 2.147230000 seconds <0x7626e520>
24	12/28/22 13:27:45.251	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0x12e7228 <0x7626e520>
41	12/28/22 13:27:45.251	ZWaveSerial::Send XXXX  node 22 using route 0.32.83.58 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:27:45.262	ZWaveSerial::Send m_iFrameID 80 type 0x0 command 0x13 sent ok waiting for 3 ulTime 84261 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:27:45.272	got expected ACK <0x75e6e520>
24	12/28/22 13:27:45.273	ZWaveSerial::Send woke up: ulTime 84261 ulTime_end 84272 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:27:45.273	ZWaveSerial::Send m_iFrameID 80 type 0x0 command 0x13 sent ok waiting for 3 ulTime 84261 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:27:45.273	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 81 gwf_sd <0x75e6e520>
24	12/28/22 13:27:45.298	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 81 gwf_sd <0x75e6e520>
24	12/28/22 13:27:45.298	ZWaveSerial::ReceivedFrame m_iFrameID 81 gwf_sd is a response frame for m_iFrameID 80 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:45.319	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 82 gwf_sd <0x75e6e520>
24	12/28/22 13:27:45.334	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 82 gwf_sd <0x75e6e520>
24	12/28/22 13:27:45.334	ZWaveSerial::ReceivedFrame m_iFrameID 82 gwf_sd is a request frame for m_iFrameID 80 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:45.334	ZWaveSerial::Send woke up: ulTime 84261 ulTime_end 84334 TimeToWaitInMs 20000 m_pres 0x122bc70 m_preq 0xf2dba8 status 1 <0x7626e520>
24	12/28/22 13:27:45.334	ZWaveSerial::Send m_iFrameID 80 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:27:45.335	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0x12e7228 now (nil) <0x7626e520>
24	12/28/22 13:27:45.335	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 <0x11fc660> m_eJobStatus Waiting after 2.231269000 seconds <0x7626e520>
24	12/28/22 13:27:45.365	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 83 gwf_ach <0x75e6e520>
24	12/28/22 13:27:45.382	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 83 gwf_ach <0x75e6e520>
24	12/28/22 13:27:45.382	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 83 gwf_ach <0x75e6e520>
24	12/28/22 13:27:45.382	ZWaveJobHandler::DoReceivedFrame m_iFrameID 83 gwf_ach node 22 command 0x4 data  <0x7686e520>
24	12/28/22 13:27:45.383	ZWaveJobHandler::DoReceivedFrame m_iFrameID 83 passing to job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 auto del: 1 <0x7686e520>
24	12/28/22 13:27:45.383	ZWaveNode::HandlePollUpdate node 22 device 1691 class 0x31 command 0x5 m_iFrameID 83/16440264 data 0x5 0x22 0x1 0x9a (#"##) <0x7686e520>
06	12/28/22 13:27:45.383	Device_Variable::m_szValue_set device: 1692 service: urn:micasaverde-com:serviceId:HumiditySensor1 variable: CurrentLevel was: 41.0 now: 41.0 #hooks: 0 upnp: 0 skip: 0 v:0xd91c88/NONE duplicate:1 <0x7686e520>
24	12/28/22 13:27:45.384	ZWaveNode::HandlePollUpdate_SensorMultiLevel_MeterReport 0x31 node 22 device 1691 child 22/1692 cat 16 embed: 1 type 5 rate type 0 is 41.000000 was 41.000000 prec 1 sca 0 size 2 delta -1 previous -1.000000 len 4 <0x7686e520>
24	12/28/22 13:27:45.384	ZWJob_PollNode::ReceivedFrame -end- job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 got after 0 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 22 status 0 iOK 0 iBadTx 0 iNoReply 0 data 0x5 0x22 0x1 0x9a (#"##) <0x7686e520>
24	12/28/22 13:27:45.385	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 <0x11fc660> m_eJobStatus Queued after 2.281021000 seconds <0x7686e520>
24	12/28/22 13:27:47.385	ZWJob_PollNode::ReadyToRun job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 priority 100 can cancel <0x7626e520>
24	12/28/22 13:27:47.386	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 <0x11fc660> m_eJobStatus Running after 4.282369000 seconds <0x7626e520>
24	12/28/22 13:27:47.386	ZWJob_PollNode::Run job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 size cmds 8 <0x7626e520>
24	12/28/22 13:27:47.387	ZWJob_PollNode::Run Polling job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 device 1691 with command class 0x40 command 0x2 <0x7626e520>
24	12/28/22 13:27:47.387	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:7 Id: 5 <0x11fc660> m_eJobStatus PendingData after 4.283255000 seconds <0x7626e520>
24	12/28/22 13:27:47.387	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0x122bc70 <0x7626e520>
41	12/28/22 13:27:47.387	ZWaveSerial::Send XXXX  node 22 using route 0.98.56.32 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:27:47.398	ZWaveSerial::Send m_iFrameID 84 type 0x0 command 0x13 sent ok waiting for 3 ulTime 86397 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:27:47.408	got expected ACK <0x75e6e520>
24	12/28/22 13:27:47.409	ZWaveSerial::Send woke up: ulTime 86397 ulTime_end 86408 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:27:47.409	ZWaveSerial::Send m_iFrameID 84 type 0x0 command 0x13 sent ok waiting for 3 ulTime 86397 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:27:47.409	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 85 gwf_sd <0x75e6e520>
24	12/28/22 13:27:47.434	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 85 gwf_sd <0x75e6e520>
24	12/28/22 13:27:47.434	ZWaveSerial::ReceivedFrame m_iFrameID 85 gwf_sd is a response frame for m_iFrameID 84 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:47.454	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 86 gwf_sd <0x75e6e520>
24	12/28/22 13:27:47.470	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 86 gwf_sd <0x75e6e520>
24	12/28/22 13:27:47.470	ZWaveSerial::ReceivedFrame m_iFrameID 86 gwf_sd is a request frame for m_iFrameID 84 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:47.470	ZWaveSerial::Send woke up: ulTime 86397 ulTime_end 86470 TimeToWaitInMs 20000 m_pres 0x122bea0 m_preq 0xf2dba8 status 1 <0x7626e520>
24	12/28/22 13:27:47.470	ZWaveSerial::Send m_iFrameID 84 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:27:47.471	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0x122bc70 now (nil) <0x7626e520>
24	12/28/22 13:27:47.471	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 <0x11fc660> m_eJobStatus Waiting after 4.367238000 seconds <0x7626e520>
24	12/28/22 13:27:47.490	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 87 gwf_ach <0x75e6e520>
24	12/28/22 13:27:47.506	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 87 gwf_ach <0x75e6e520>
24	12/28/22 13:27:47.506	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 87 gwf_ach <0x75e6e520>
24	12/28/22 13:27:47.506	ZWaveJobHandler::DoReceivedFrame m_iFrameID 87 gwf_ach node 22 command 0x4 data  <0x7686e520>
24	12/28/22 13:27:47.507	ZWaveJobHandler::DoReceivedFrame m_iFrameID 87 passing to job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 auto del: 1 <0x7686e520>
24	12/28/22 13:27:47.507	ZWaveNode::HandlePollUpdate node 22 device 1691 class 0x40 command 0x3 m_iFrameID 87/17311584 data 0x1 (#) <0x7686e520>
24	12/28/22 13:27:47.508	ZWaveNode::HandlePollUpdate_ThermostatModeReport node 22 device 1691 mode is HeatOn was HeatOn <0x7686e520>
24	12/28/22 13:27:47.508	ZWJob_PollNode::ReceivedFrame -end- job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 got after 0 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 22 status 0 iOK 0 iBadTx 0 iNoReply 0 data 0x1 (#) <0x7686e520>
24	12/28/22 13:27:47.508	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 <0x11fc660> m_eJobStatus Queued after 4.404845000 seconds <0x7686e520>
06	12/28/22 13:27:49.504	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 13 2F 01 00 5C 3E 01 79  now: 0A 52 09 14 5D 0C 01 03 0A 02 39  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:49.505	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252062 now: 1672252069 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
24	12/28/22 13:27:49.510	ZWJob_PollNode::ReadyToRun job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 priority 100 can cancel <0x7626e520>
24	12/28/22 13:27:49.510	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 <0x11fc660> m_eJobStatus Running after 6.406726000 seconds <0x7626e520>
24	12/28/22 13:27:49.511	ZWJob_PollNode::Run job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 size cmds 8 <0x7626e520>
24	12/28/22 13:27:49.511	ZWJob_PollNode::Run Polling job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 device 1691 with command class 0x42 command 0x2 <0x7626e520>
24	12/28/22 13:27:49.512	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:7 Id: 5 <0x11fc660> m_eJobStatus PendingData after 6.407950000 seconds <0x7626e520>
24	12/28/22 13:27:49.512	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0xf2dba8 <0x7626e520>
41	12/28/22 13:27:49.512	ZWaveSerial::Send XXXX  node 22 using route 0.102.32.48 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:27:49.522	ZWaveSerial::Send m_iFrameID 88 type 0x0 command 0x13 sent ok waiting for 3 ulTime 88521 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:27:49.532	got expected ACK <0x75e6e520>
24	12/28/22 13:27:49.533	ZWaveSerial::Send woke up: ulTime 88521 ulTime_end 88532 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:27:49.533	ZWaveSerial::Send m_iFrameID 88 type 0x0 command 0x13 sent ok waiting for 3 ulTime 88521 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
06	12/28/22 13:27:49.533	Device_Variable::m_szValue_set device: 2670 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252008 now: 1672252069 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
24	12/28/22 13:27:49.533	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 89 gwf_sd <0x75e6e520>
24	12/28/22 13:27:49.550	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 89 gwf_sd <0x75e6e520>
24	12/28/22 13:27:49.550	ZWaveSerial::ReceivedFrame m_iFrameID 89 gwf_sd is a response frame for m_iFrameID 88 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
06	12/28/22 13:27:49.557	Device_Variable::m_szValue_set device: 1580 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 05 B5 03 80 D4 0D 02 79  now: 0A 52 09 06 5D 0C 01 03 0A 02 69  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:27:49.558	Device_Variable::m_szValue_set device: 1580 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252057 now: 1672252069 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
24	12/28/22 13:27:49.571	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 90 gwf_sd <0x75e6e520>
24	12/28/22 13:27:49.586	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 90 gwf_sd <0x75e6e520>
24	12/28/22 13:27:49.586	ZWaveSerial::ReceivedFrame m_iFrameID 90 gwf_sd is a request frame for m_iFrameID 88 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:49.587	ZWaveSerial::Send woke up: ulTime 88521 ulTime_end 88586 TimeToWaitInMs 20000 m_pres 0x110cc20 m_preq 0x12b4b40 status 1 <0x7626e520>
24	12/28/22 13:27:49.587	ZWaveSerial::Send m_iFrameID 88 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:27:49.587	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0xf2dba8 now (nil) <0x7626e520>
24	12/28/22 13:27:49.588	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 <0x11fc660> m_eJobStatus Waiting after 6.483890000 seconds <0x7626e520>
24	12/28/22 13:27:49.617	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 91 gwf_ach <0x75e6e520>
24	12/28/22 13:27:49.634	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 91 gwf_ach <0x75e6e520>
24	12/28/22 13:27:49.634	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 91 gwf_ach <0x75e6e520>
24	12/28/22 13:27:49.634	ZWaveJobHandler::DoReceivedFrame m_iFrameID 91 gwf_ach node 22 command 0x4 data  <0x7686e520>
24	12/28/22 13:27:49.635	ZWaveJobHandler::DoReceivedFrame m_iFrameID 91 passing to job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 auto del: 1 <0x7686e520>
24	12/28/22 13:27:49.635	ZWaveNode::HandlePollUpdate node 22 device 1691 class 0x42 command 0x3 m_iFrameID 91/13344792 data 0x1 (#) <0x7686e520>
24	12/28/22 13:27:49.635	ZWaveThermostat::HandlePollUpdate_ThermostatStateReport node 22 device 1691 state is Heating was Heating <0x7686e520>
24	12/28/22 13:27:49.635	ZWJob_PollNode::ReceivedFrame -end- job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 got after 0 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 22 status 0 iOK 0 iBadTx 0 iNoReply 0 data 0x1 (#) <0x7686e520>
24	12/28/22 13:27:49.636	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 <0x11fc660> m_eJobStatus Queued after 6.532062000 seconds <0x7686e520>
24	12/28/22 13:27:51.636	ZWJob_PollNode::ReadyToRun job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 priority 100 can cancel <0x7626e520>
24	12/28/22 13:27:51.637	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 <0x11fc660> m_eJobStatus Running after 8.533234000 seconds <0x7626e520>
24	12/28/22 13:27:51.637	ZWJob_PollNode::Run job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 size cmds 8 <0x7626e520>
24	12/28/22 13:27:51.637	ZWJob_PollNode::Run Polling job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 device 1691 with command class 0x44 command 0x2 <0x7626e520>
24	12/28/22 13:27:51.638	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:7 Id: 5 <0x11fc660> m_eJobStatus PendingData after 8.534086000 seconds <0x7626e520>
24	12/28/22 13:27:51.638	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0x110cc20 <0x7626e520>
41	12/28/22 13:27:51.638	ZWaveSerial::Send XXXX  node 22 using route 0.32.49.52 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:27:51.646	ZWaveSerial::Send m_iFrameID 92 type 0x0 command 0x13 sent ok waiting for 3 ulTime 90645 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:27:51.657	got expected ACK <0x75e6e520>
24	12/28/22 13:27:51.657	ZWaveSerial::Send woke up: ulTime 90645 ulTime_end 90657 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:27:51.657	ZWaveSerial::Send m_iFrameID 92 type 0x0 command 0x13 sent ok waiting for 3 ulTime 90645 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:27:51.657	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 93 gwf_sd <0x75e6e520>
24	12/28/22 13:27:51.682	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 93 gwf_sd <0x75e6e520>
24	12/28/22 13:27:51.682	ZWaveSerial::ReceivedFrame m_iFrameID 93 gwf_sd is a response frame for m_iFrameID 92 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:51.705	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 94 gwf_sd <0x75e6e520>
24	12/28/22 13:27:51.722	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 94 gwf_sd <0x75e6e520>
24	12/28/22 13:27:51.722	ZWaveSerial::ReceivedFrame m_iFrameID 94 gwf_sd is a request frame for m_iFrameID 92 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:51.722	ZWaveSerial::Send woke up: ulTime 90645 ulTime_end 90722 TimeToWaitInMs 20000 m_pres 0xf2dba8 m_preq 0xc9a3f0 status 1 <0x7626e520>
24	12/28/22 13:27:51.722	ZWaveSerial::Send m_iFrameID 92 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:27:51.723	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0x110cc20 now (nil) <0x7626e520>
24	12/28/22 13:27:51.723	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 <0x11fc660> m_eJobStatus Waiting after 8.619305000 seconds <0x7626e520>
24	12/28/22 13:27:51.753	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 95 gwf_ach <0x75e6e520>
24	12/28/22 13:27:51.770	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 95 gwf_ach <0x75e6e520>
24	12/28/22 13:27:51.770	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 95 gwf_ach <0x75e6e520>
24	12/28/22 13:27:51.770	ZWaveJobHandler::DoReceivedFrame m_iFrameID 95 gwf_ach node 22 command 0x4 data  <0x7686e520>
24	12/28/22 13:27:51.771	ZWaveJobHandler::DoReceivedFrame m_iFrameID 95 passing to job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 auto del: 1 <0x7686e520>
24	12/28/22 13:27:51.771	ZWaveNode::HandlePollUpdate node 22 device 1691 class 0x44 command 0x3 m_iFrameID 95/18647216 data 0x0 (#) <0x7686e520>
06	12/28/22 13:27:51.771	Device_Variable::m_szValue_set device: 1691 service: urn:upnp-org:serviceId:HVAC_FanOperatingMode1 variable: Mode was: Auto now: Auto #hooks: 0 upnp: 0 skip: 0 v:0xd9d010/NONE duplicate:1 <0x7686e520>
24	12/28/22 13:27:51.771	ZWaveThermostat::HandlePollUpdate_ThermostatFanReport node 22 device 1691 mode 0 <0x7686e520>
24	12/28/22 13:27:51.772	ZWJob_PollNode::ReceivedFrame -end- job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 got after 0 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 22 status 0 iOK 0 iBadTx 0 iNoReply 0 data 0x0 (#) <0x7686e520>
24	12/28/22 13:27:51.772	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 <0x11fc660> m_eJobStatus Queued after 8.668278000 seconds <0x7686e520>
24	12/28/22 13:27:53.773	ZWJob_PollNode::ReadyToRun job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 priority 100 can cancel <0x7626e520>
24	12/28/22 13:27:53.773	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 <0x11fc660> m_eJobStatus Running after 10.669478000 seconds <0x7626e520>
24	12/28/22 13:27:53.773	ZWJob_PollNode::Run job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 size cmds 8 <0x7626e520>
24	12/28/22 13:27:53.774	ZWJob_PollNode::Run Polling job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 device 1691 with command class 0x43 command 0x2 <0x7626e520>
24	12/28/22 13:27:53.774	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:7 Id: 5 <0x11fc660> m_eJobStatus PendingData after 10.670590000 seconds <0x7626e520>
24	12/28/22 13:27:53.774	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0x12b4c88 <0x7626e520>
41	12/28/22 13:27:53.775	ZWaveSerial::Send XXXX  node 22 using route 0.32.83.58 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:27:53.786	ZWaveSerial::Send m_iFrameID 96 type 0x0 command 0x13 sent ok waiting for 3 ulTime 92785 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:27:53.796	got expected ACK <0x75e6e520>
24	12/28/22 13:27:53.796	ZWaveSerial::Send woke up: ulTime 92785 ulTime_end 92796 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:27:53.797	ZWaveSerial::Send m_iFrameID 96 type 0x0 command 0x13 sent ok waiting for 3 ulTime 92785 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:27:53.796	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 97 gwf_sd <0x75e6e520>
24	12/28/22 13:27:53.822	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 97 gwf_sd <0x75e6e520>
24	12/28/22 13:27:53.822	ZWaveSerial::ReceivedFrame m_iFrameID 97 gwf_sd is a response frame for m_iFrameID 96 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:53.845	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 98 gwf_sd <0x75e6e520>
24	12/28/22 13:27:53.862	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 98 gwf_sd <0x75e6e520>
24	12/28/22 13:27:53.862	ZWaveSerial::ReceivedFrame m_iFrameID 98 gwf_sd is a request frame for m_iFrameID 96 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:53.862	ZWaveSerial::Send woke up: ulTime 92785 ulTime_end 92862 TimeToWaitInMs 20000 m_pres 0x110cc20 m_preq 0xf2dba8 status 1 <0x7626e520>
24	12/28/22 13:27:53.862	ZWaveSerial::Send m_iFrameID 96 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:27:53.863	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0x12b4c88 now (nil) <0x7626e520>
24	12/28/22 13:27:53.863	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 <0x11fc660> m_eJobStatus Waiting after 10.759333000 seconds <0x7626e520>
24	12/28/22 13:27:53.893	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 99 gwf_ach <0x75e6e520>
24	12/28/22 13:27:53.910	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 99 gwf_ach <0x75e6e520>
24	12/28/22 13:27:53.910	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 99 gwf_ach <0x75e6e520>
24	12/28/22 13:27:53.910	ZWaveJobHandler::DoReceivedFrame m_iFrameID 99 gwf_ach node 22 command 0x4 data  <0x7686e520>
24	12/28/22 13:27:53.911	ZWaveJobHandler::DoReceivedFrame m_iFrameID 99 passing to job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 auto del: 1 <0x7686e520>
24	12/28/22 13:27:53.911	ZWaveNode::HandlePollUpdate node 22 device 1691 class 0x43 command 0x3 m_iFrameID 99/18649856 data 0x1 0x2a 0x2 0xa8 (#*##) <0x7686e520>
06	12/28/22 13:27:53.911	Device_Variable::m_szValue_set device: 1691 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: TemperatureScale was: 1,1,2 now: 1,1,2 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:27:53.912	Device_Variable::m_szValue_set device: 1691 service: urn:upnp-org:serviceId:TemperatureSetpoint1_Heat variable: CurrentSetpoint was: 68.00 now: 68.00 #hooks: 0 upnp: 0 skip: 0 v:0xd9b5b8/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:27:53.912	Device_Variable::m_szValue_set device: 1691 service: urn:upnp-org:serviceId:TemperatureSetpoint1 variable: CurrentSetpoint was: 68.00 now: 68.00 #hooks: 0 upnp: 0 skip: 0 v:0xd9ab90/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:27:53.912	Device_Variable::m_szValue_set device: 1691 service: urn:upnp-org:serviceId:TemperatureSetpoint1 variable: AllSetpoints was: 68.00,78.00,73.00 now: 68.000000,78.000000,73.000000 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7686e520>
06	12/28/22 13:27:53.913	Device_Variable::m_szValue_set device: 1691 service: urn:upnp-org:serviceId:TemperatureSetpoint1 variable: AllSetpoints was: 68.000000,78.000000,73.000000 now: 68.00,78.00,73.00 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7686e520>
24	12/28/22 13:27:53.934	ZWaveThermostat::HandlePollUpdate_ThermostatSetpointReport heating node 22 device 1691 type 1 temp 68.000000 ambient 0.000000 <0x7686e520>
24	12/28/22 13:27:53.935	ZWJob_PollNode::ReceivedFrame -end- job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 got after 0 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 22 status 0 iOK 0 iBadTx 0 iNoReply 0 data 0x1 0x2a 0x2 0xa8 (#*##) <0x7686e520>
24	12/28/22 13:27:53.935	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 <0x11fc660> m_eJobStatus Queued after 10.831786000 seconds <0x7686e520>
06	12/28/22 13:27:55.055	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 14 5D 0C 01 03 0A 02 39  now: 0A 52 0D 15 D8 03 00 BC 29 01 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:55.055	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252069 now: 1672252075 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:55.062	Device_Variable::m_szValue_set device: 2346 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252040 now: 1672252075 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:55.063	Device_Variable::m_szValue_set device: 2347 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252040 now: 1672252075 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
24	12/28/22 13:27:55.936	ZWJob_PollNode::ReadyToRun job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 priority 100 can cancel <0x7626e520>
24	12/28/22 13:27:55.937	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 <0x11fc660> m_eJobStatus Running after 12.832964000 seconds <0x7626e520>
24	12/28/22 13:27:55.937	ZWJob_PollNode::Run job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 size cmds 8 <0x7626e520>
24	12/28/22 13:27:55.937	ZWJob_PollNode::Run Polling job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:1 Id: 5 node 22 device 1691 with command class 0x43 command 0x2 <0x7626e520>
24	12/28/22 13:27:55.937	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:7 Id: 5 <0x11fc660> m_eJobStatus PendingData after 12.833752000 seconds <0x7626e520>
24	12/28/22 13:27:55.938	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0x110cc20 <0x7626e520>
41	12/28/22 13:27:55.938	ZWaveSerial::Send XXXX  node 22 using route 0.32.49.52 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:27:55.946	ZWaveSerial::Send m_iFrameID 100 type 0x0 command 0x13 sent ok waiting for 3 ulTime 94945 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:27:55.956	got expected ACK <0x75e6e520>
24	12/28/22 13:27:55.957	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 101 gwf_sd <0x75e6e520>
24	12/28/22 13:27:55.957	ZWaveSerial::Send woke up: ulTime 94945 ulTime_end 94956 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:27:55.968	ZWaveSerial::Send m_iFrameID 100 type 0x0 command 0x13 sent ok waiting for 3 ulTime 94945 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:27:55.974	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 101 gwf_sd <0x75e6e520>
24	12/28/22 13:27:55.974	ZWaveSerial::ReceivedFrame m_iFrameID 101 gwf_sd is a response frame for m_iFrameID 100 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:55.994	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 102 gwf_sd <0x75e6e520>
24	12/28/22 13:27:56.010	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 102 gwf_sd <0x75e6e520>
24	12/28/22 13:27:56.010	ZWaveSerial::ReceivedFrame m_iFrameID 102 gwf_sd is a request frame for m_iFrameID 100 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:27:56.011	ZWaveSerial::Send woke up: ulTime 94945 ulTime_end 95010 TimeToWaitInMs 20000 m_pres 0xc8e600 m_preq 0xc596b8 status 1 <0x7626e520>
24	12/28/22 13:27:56.011	ZWaveSerial::Send m_iFrameID 100 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:27:56.011	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0x110cc20 now (nil) <0x7626e520>
24	12/28/22 13:27:56.011	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 <0x11fc660> m_eJobStatus Waiting after 12.907835000 seconds <0x7626e520>
24	12/28/22 13:27:56.041	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 103 gwf_ach <0x75e6e520>
24	12/28/22 13:27:56.058	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 103 gwf_ach <0x75e6e520>
24	12/28/22 13:27:56.058	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 103 gwf_ach <0x75e6e520>
24	12/28/22 13:27:56.058	ZWaveJobHandler::DoReceivedFrame m_iFrameID 103 gwf_ach node 22 command 0x4 data  <0x7686e520>
24	12/28/22 13:27:56.059	ZWaveJobHandler::DoReceivedFrame m_iFrameID 103 passing to job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 auto del: 1 <0x7686e520>
24	12/28/22 13:27:56.059	ZWaveNode::HandlePollUpdate node 22 device 1691 class 0x43 command 0x3 m_iFrameID 103/19569768 data 0x2 0x2a 0x3 0xc (#*##) <0x7686e520>
06	12/28/22 13:27:56.059	Device_Variable::m_szValue_set device: 1691 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: TemperatureScale was: 1,1,2 now: 1,1,2 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:27:56.059	Device_Variable::m_szValue_set device: 1691 service: urn:upnp-org:serviceId:TemperatureSetpoint1_Cool variable: CurrentSetpoint was: 78.00 now: 78.00 #hooks: 0 upnp: 0 skip: 0 v:0xd9c8c8/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:27:56.060	Device_Variable::m_szValue_set device: 1691 service: urn:upnp-org:serviceId:TemperatureSetpoint1 variable: AllSetpoints was: 68.00,78.00,73.00 now: 68.000000,78.000000,73.000000 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7686e520>
06	12/28/22 13:27:56.060	Device_Variable::m_szValue_set device: 1691 service: urn:upnp-org:serviceId:TemperatureSetpoint1 variable: AllSetpoints was: 68.000000,78.000000,73.000000 now: 68.00,78.00,73.00 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7686e520>
24	12/28/22 13:27:56.061	ZWaveThermostat::HandlePollUpdate_ThermostatSetpointReport cooling node 22 device 1691 type 2 temp 78.000000 ambient 0.000000 <0x7686e520>
24	12/28/22 13:27:56.061	ZWJob_PollNode::ReceivedFrame -end- job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:5 Id: 5 got after 1 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 22 status 0 iOK 0 iBadTx 0 iNoReply 0 data 0x2 0x2a 0x3 0xc (#*##) <0x7686e520>
24	12/28/22 13:27:56.061	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 <0x11fc660> m_eJobStatus Queued after 12.957783000 seconds <0x7686e520>
06	12/28/22 13:27:56.129	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 15 D8 03 00 BC 29 01 79  now: 0A 52 0D 16 1C 02 00 A1 2E 01 59  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:56.130	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252075 now: 1672252076 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:56.137	Device_Variable::m_szValue_set device: 2348 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252041 now: 1672252076 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:27:56.138	Device_Variable::m_szValue_set device: 2349 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252041 now: 1672252076 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
08	12/28/22 13:27:57.748	JobHandler_LuaUPnP::HandleActionRequest device: 0 service: urn:micasaverde-com:serviceId:HomeAutomationGateway1 action: RunLua <0x73e2d520>
08	12/28/22 13:27:57.749	JobHandler_LuaUPnP::HandleActionRequest argument id=lu_action <0x73e2d520>
08	12/28/22 13:27:57.749	JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:micasaverde-com:serviceId:HomeAutomationGateway1 <0x73e2d520>
08	12/28/22 13:27:57.749	JobHandler_LuaUPnP::HandleActionRequest argument action=RunLua <0x73e2d520>
08	12/28/22 13:27:57.749	JobHandler_LuaUPnP::HandleActionRequest argument Code=local resultCode, resultString, job, returnArguments = luup.call_action('urn:micasaverde-com:serviceId:ZWaveNetwork1','SendData',{Node='22', Data='0x31 4'}, 1)
luup.log("resultCode: "..resultCode)
luup.log("resultString: "..resultString)
luup.log("job: "..(job or 'nil'))
for i,v in ipairs(returnArguments) do
 luup.log("i,v: "..i..", "..v)
end

 <0x73e2d520>
28	12/28/22 13:27:57.749	JobHandler_LuaUPnP::HandleActionRequest testing Bluetooth urn:micasaverde-com:serviceId:HomeAutomationGateway1, urn:micasaverde-com:serviceId:BluetoothNetwork1, (nil) <0x73e2d520>
08	12/28/22 13:27:57.750	JobHandler_LuaUPnP::HandleActionRequest device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 action: SendData <0x73e2d520>
08	12/28/22 13:27:57.750	JobHandler_LuaUPnP::HandleActionRequest argument Node=22 <0x73e2d520>
08	12/28/22 13:27:57.751	JobHandler_LuaUPnP::HandleActionRequest argument Data=0x31 4 <0x73e2d520>
24	12/28/22 13:27:57.751	sbrk ZWaveJobHandler::sbrkaddjob pMem 0x14a7000/21655552 diff: 10350592 quit 0 <0x73e2d520>
24	12/28/22 13:27:57.751	ZWaveJobHandler::AddJob abort poll job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 for job#6 :childcmd node 22 dev:1691 (0xc5a6b8) N:22 P:35 S:0 Id: 6 <0x73e2d520>
24	12/28/22 13:27:57.752	ZWaveJobHandler::AlarmCallback abort poll job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5(1) 100 <0x7686e520>
50	12/28/22 13:27:57.753	luup_log:0: resultCode: 0 <0x73e2d520>
50	12/28/22 13:27:57.753	luup_log:0: resultString:  <0x73e2d520>
50	12/28/22 13:27:57.753	luup_log:0: job: 6 <0x73e2d520>
24	12/28/22 13:27:57.762	ZWJob_PollNode::Abort job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 clearing m_pZWJob_PollNode m_pZW_Send_Data 0x110cc20 m_bWaitingForApplicationCommandHandler 0 <0x7686e520>
24	12/28/22 13:27:57.763	ZWJob_PollNode::Abort job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:0 Id: 5 doesn't need to be aborted waiting 0 <0x7686e520>
24	12/28/22 13:27:57.763	ZWJob_PollNode::m_eJobStatus job job#5 :pollnode #22 dev:1691 (0x11fc660) N:22 P:100 S:3 Id: 5 <0x11fc660> m_eJobStatus Aborted after 14.659533000 seconds <0x7686e520>
04	12/28/22 13:27:57.764	<Job ID="5" Name="pollnode #22 8 cmds" Device="1691" Created="2022-12-28 13:27:43" Started="2022-12-28 13:27:43" Completed="2022-12-28 13:27:57" Duration="14.659533000" Runtime="14.658595000" Status="Aborted" LastNote="" Node="22" NodeType="ZWaveThermostat" NodeDescription="Honeywell Thermostat"/> <0x7686e520>
24	12/28/22 13:27:57.765	ZWJob_SendData::Run job job#6 :childcmd node 22 dev:1691 (0xc5a6b8) N:22 P:35 S:1 Id: 6 to node 22 command 0x31/0x4 callback 19 m_iFrameID 104 method 2 options 0x5 retries 0 of 5 <0x7626e520>
24	12/28/22 13:27:57.765	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0xcf8158 <0x7626e520>
41	12/28/22 13:27:57.765	ZWaveSerial::Send XXXX  node 22 using route 0.51.53.32 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:27:57.774	ZWaveSerial::Send m_iFrameID 104 type 0x0 command 0x13 sent ok waiting for 2 ulTime 96773 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:27:57.794	got expected ACK <0x75e6e520>
24	12/28/22 13:27:57.795	ZWaveSerial::Send woke up: ulTime 96773 ulTime_end 96794 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:27:57.795	ZWaveSerial::Send m_iFrameID 104 type 0x0 command 0x13 sent ok waiting for 2 ulTime 96773 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:27:57.795	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 105 gwf_sd <0x75e6e520>
24	12/28/22 13:27:57.822	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 105 gwf_sd <0x75e6e520>
24	12/28/22 13:27:57.822	ZWaveSerial::ReceivedFrame m_iFrameID 105 gwf_sd is a response frame for m_iFrameID 104 sd_rjob#6 :childcmd node 22 dev:1691 (0xc5a6b8) N:22 P:35 S:1 Id: 6 we're waiting got ack 1 expected response 2 <0x75e6e520>
24	12/28/22 13:27:57.822	ZWaveSerial::Send woke up: ulTime 96773 ulTime_end 96822 TimeToWaitInMs 20000 m_pres 0xc5aab8 m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:27:57.822	ZWaveSerial::Send m_iFrameID 104 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:27:57.823	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0xcf8158 now (nil) <0x7626e520>
24	12/28/22 13:27:57.823	ZWJob_SendData::Run done: job job#6 :childcmd node 22 dev:1691 (0xc5a6b8) N:22 P:35 S:7 Id: 6 took 59 ms m_enumSendMethod 2 to node 22 command 0x31/0x4 callback 19 m_iFrameID 104 total 0.58927000 sec type 2 <0x7626e520>
24	12/28/22 13:27:57.853	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 106 gwf_sd <0x75e6e520>
24	12/28/22 13:27:57.870	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 106 gwf_sd <0x75e6e520>
24	12/28/22 13:27:57.870	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:13/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x13 m_iFrameID 106 gwf_sd <0x75e6e520>
24	12/28/22 13:27:57.870	ZWaveJobHandler::DoReceivedFrame m_iFrameID 106 gwf_sd node 0 command 0x13 data  <0x7686e520>
24	12/28/22 13:27:57.871	ZWaveJobHandler::DoReceivedFrame m_iFrameID 106 passing to job#6 :childcmd node 22 dev:1691 (0xc5a6b8) N:22 P:35 S:5 Id: 6 auto del: 1 <0x7686e520>
24	12/28/22 13:27:57.871	ZWaveNode::m_bLastContactFailed_set device 1691 = 0, force 0, m_bNotListening 0 zw poll7 <0x7686e520>
24	12/28/22 13:27:57.871	ZWJob_SendData::ReceivedFrame ok job job#6 :childcmd node 22 dev:1691 (0xc5a6b8) N:22 P:35 S:5 Id: 6 to node 22 command 49/4 ok first try resend: 0 waiting 0/0 got 0 <0x7686e520>
24	12/28/22 13:27:57.871	ZWaveNode::m_bLastContactFailed_set device 1691 = 0, force 0, m_bNotListening 0 zw poll8 <0x7686e520>
04	12/28/22 13:27:57.872	<Job ID="6" Name="childcmd node 22" Device="1691" Created="2022-12-28 13:27:57" Started="2022-12-28 13:27:57" Completed="2022-12-28 13:27:57" Duration="0.120859000" Runtime="0.107604000" Status="Successful" LastNote="SUCCESS! Transmit was OK" Node="22" NodeType="ZWaveThermostat" NodeDescription="Honeywell Thermostat"/> <0x7686e520>
24	12/28/22 13:27:57.901	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 107 gwf_ach <0x75e6e520>
24	12/28/22 13:27:57.918	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 107 gwf_ach <0x75e6e520>
24	12/28/22 13:27:57.918	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 107 gwf_ach <0x75e6e520>
24	12/28/22 13:27:57.918	ZWaveJobHandler::DoReceivedFrame m_iFrameID 107 gwf_ach node 22 command 0x4 data  <0x7686e520>
24	12/28/22 13:27:57.919	ZWaveNode::HandlePollUpdate node 22 device 1691 class 0x31 command 0x5 m_iFrameID 107/16829920 data 0x1 0x2a 0x2 0xa8 (#*##) <0x7686e520>
06	12/28/22 13:27:57.919	Device_Variable::m_szValue_set device: 1691 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 68.00 now: 68.00 #hooks: 0 upnp: 0 skip: 0 v:0xd6d338/NONE duplicate:1 <0x7686e520>
24	12/28/22 13:27:57.919	ZWaveNode::HandlePollUpdate_SensorMultiLevel_MeterReport 0x31 node 22 device 1691 child 22/1691 cat 17 embed: 1 type 1 rate type 0 is 68.000000 was 0.000000 prec 1 sca 1 size 2 delta -1 previous -1.000000 len 4 <0x7686e520>
24	12/28/22 13:27:57.920	ZWaveJobHandler::DoReceivedFrame m_iFrameID 107 done 1 <0x7686e520>
06	12/28/22 13:28:00.864	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 16 1C 02 00 A1 2E 01 59  now: 0A 52 0D 17 3B 01 00 A9 30 01 69  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:00.865	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252076 now: 1672252080 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:00.870	Device_Variable::m_szValue_set device: 2334 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252045 now: 1672252080 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:00.871	Device_Variable::m_szValue_set device: 2335 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252045 now: 1672252080 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
02	12/28/22 13:28:01.100	UserData::AlarmCallback ALARM_RESYNC_DEVICES <0x76a6e520>
02	12/28/22 13:28:02.985	RAServerSync::SyncDevice alt 0 response 200 url https://vera-us-oem-device12.mios.com/device/device/device/50004845/localdevices with 36648 bytes <0x76a6e520>
06	12/28/22 13:28:03.311	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 17 3B 01 00 A9 30 01 69  now: 0A 52 0D 18 98 01 00 CF 23 02 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:03.312	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252080 now: 1672252083 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:03.317	Device_Variable::m_szValue_set device: 2332 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommStrength was: 6 now: 7 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:03.317	Device_Variable::m_szValue_set device: 2332 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252048 now: 1672252083 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:03.318	Device_Variable::m_szValue_set device: 2333 service: urn:micasaverde-com:serviceId:HaDevice1 variable: CommStrength was: 6 now: 7 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:03.319	Device_Variable::m_szValue_set device: 2333 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252048 now: 1672252083 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:04.860	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 18 98 01 00 CF 23 02 79  now: 0A 52 0E 19 EA 01 80 F7 35 01 50  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:04.861	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252083 now: 1672252084 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:06.372	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0E 19 EA 01 80 F7 35 01 50  now: 0A 52 0E 1A F9 01 00 57 1F 02 49  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:06.373	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252084 now: 1672252086 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:06.378	Device_Variable::m_szValue_set device: 2330 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252025 now: 1672252086 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:06.383	Device_Variable::m_szValue_set device: 2331 service: urn:micasaverde-com:serviceId:HumiditySensor1 variable: CurrentLevel was: 30 now: 31 #hooks: 0 upnp: 0 skip: 0 v:0xd91c88/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:06.383	Device_Variable::m_szValue_set device: 2331 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252025 now: 1672252086 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
24	12/28/22 13:28:13.100	ZWaveJobHandler::ServicePollLoop not polling 2 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:13.101	ZWaveJobHandler::ServicePollLoop not polling 4 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:13.101	ZWaveJobHandler::ServicePollLoop not polling 5 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:13.101	ZWaveJobHandler::ServicePollLoop not polling 6 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:13.101	ZWaveJobHandler::ServicePollLoop not polling 7 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:13.102	ZWaveJobHandler::ServicePollLoop not polling 8 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:13.102	ZWaveJobHandler::ServicePollLoop not polling 9 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:13.102	ZWaveJobHandler::ServicePollLoop not polling 10 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:13.102	ZWaveJobHandler::ServicePollLoop not polling 14 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:13.103	ZWaveJobHandler::ServicePollLoop not polling 20 bypass 0 freq 10800 listen 1 <0x7686e520>
24	12/28/22 13:28:13.103	ZWaveJobHandler::ServicePollLoop not polling 24 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:13.103	ZWaveJobHandler::ServicePollLoop not polling 31 bypass 0 freq 0 listen 1 <0x7686e520>
24	12/28/22 13:28:13.103	ZWaveJobHandler::ServicePollLoop polling node 23 <0x7686e520>
24	12/28/22 13:28:13.104	sbrk ZWaveJobHandler::sbrkaddjob pMem 0x152e000/22208512 diff: 10903552 quit 0 <0x7686e520>
24	12/28/22 13:28:13.104	ZWJob_PollNode::ReadyToRun job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:0 Id: 7 priority 100 can cancel <0x7626e520>
24	12/28/22 13:28:13.104	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:1 Id: 7 <0x1157890> m_eJobStatus Running after 0.1125000 seconds <0x7626e520>
24	12/28/22 13:28:13.105	ZWJob_PollNode::Run job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:1 Id: 7 node 23 size cmds 0 <0x7626e520>
24	12/28/22 13:28:13.105	ZWaveNode::AddPollingCommand node 23 device 2112 added 23/2112=0x25,23/2112=0x32,23/2112=0x32, <0x7626e520>
24	12/28/22 13:28:13.106	ZWJob_PollNode::Run Polling job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:1 Id: 7 node 23 device 2112 with command class 0x25 command 0x2 <0x7626e520>
24	12/28/22 13:28:13.106	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:7 Id: 7 <0x1157890> m_eJobStatus PendingData after 0.2559000 seconds <0x7626e520>
24	12/28/22 13:28:13.106	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0x11ed2e0 <0x7626e520>
41	12/28/22 13:28:13.106	ZWaveSerial::Send XXXX  node 23 using route 0.58.50.49 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:28:13.118	ZWaveSerial::Send m_iFrameID 108 type 0x0 command 0x13 sent ok waiting for 3 ulTime 112117 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:28:13.138	got expected ACK <0x75e6e520>
24	12/28/22 13:28:13.139	ZWaveSerial::Send woke up: ulTime 112117 ulTime_end 112138 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:28:13.139	ZWaveSerial::Send m_iFrameID 108 type 0x0 command 0x13 sent ok waiting for 3 ulTime 112117 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:28:13.139	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 109 gwf_sd <0x75e6e520>
24	12/28/22 13:28:13.166	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 109 gwf_sd <0x75e6e520>
24	12/28/22 13:28:13.166	ZWaveSerial::ReceivedFrame m_iFrameID 109 gwf_sd is a response frame for m_iFrameID 108 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:28:13.186	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 110 gwf_sd <0x75e6e520>
24	12/28/22 13:28:13.202	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 110 gwf_sd <0x75e6e520>
24	12/28/22 13:28:13.202	ZWaveSerial::ReceivedFrame m_iFrameID 110 gwf_sd is a request frame for m_iFrameID 108 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:28:13.203	ZWaveSerial::Send woke up: ulTime 112117 ulTime_end 112202 TimeToWaitInMs 20000 m_pres 0x11ed360 m_preq 0x11ed3b0 status 1 <0x7626e520>
24	12/28/22 13:28:13.203	ZWaveSerial::Send m_iFrameID 108 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:28:13.203	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0x11ed2e0 now (nil) <0x7626e520>
24	12/28/22 13:28:13.203	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:5 Id: 7 <0x1157890> m_eJobStatus Waiting after 0.100069000 seconds <0x7626e520>
24	12/28/22 13:28:13.256	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 111 gwf_ach <0x75e6e520>
24	12/28/22 13:28:13.274	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 111 gwf_ach <0x75e6e520>
24	12/28/22 13:28:13.274	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 111 gwf_ach <0x75e6e520>
24	12/28/22 13:28:13.274	ZWaveJobHandler::DoReceivedFrame m_iFrameID 111 gwf_ach node 23 command 0x4 data  <0x7686e520>
24	12/28/22 13:28:13.275	ZWaveJobHandler::DoReceivedFrame m_iFrameID 111 passing to job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:5 Id: 7 auto del: 1 <0x7686e520>
24	12/28/22 13:28:13.275	ZWaveNode::HandlePollUpdate node 23 device 2112 class 0x25 command 0x3 m_iFrameID 111/17899064 data 0xff (#) <0x7686e520>
24	12/28/22 13:28:13.275	ZWaveNode::HandlePollUpdate_Basic_Report node 23 device 2112 now is 255 was 1/-99999 <0x7686e520>
24	12/28/22 13:28:13.275	ZWJob_PollNode::ReceivedFrame -end- job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:5 Id: 7 got after 0 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 23 status 0 iOK 0 iBadTx 0 iNoReply 0 data 0xff (#) <0x7686e520>
24	12/28/22 13:28:13.276	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:0 Id: 7 <0x1157890> m_eJobStatus Queued after 0.172301000 seconds <0x7686e520>
24	12/28/22 13:28:15.276	ZWJob_PollNode::ReadyToRun job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:0 Id: 7 priority 100 can cancel <0x7626e520>
24	12/28/22 13:28:15.277	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:1 Id: 7 <0x1157890> m_eJobStatus Running after 2.173438000 seconds <0x7626e520>
24	12/28/22 13:28:15.277	ZWJob_PollNode::Run job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:1 Id: 7 node 23 size cmds 3 <0x7626e520>
24	12/28/22 13:28:15.277	ZWJob_PollNode::Run Polling job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:1 Id: 7 node 23 device 2112 with command class 0x32 command 0x1 <0x7626e520>
24	12/28/22 13:28:15.278	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:7 Id: 7 <0x1157890> m_eJobStatus PendingData after 2.174324000 seconds <0x7626e520>
24	12/28/22 13:28:15.278	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0x11ed238 <0x7626e520>
41	12/28/22 13:28:15.278	ZWaveSerial::Send XXXX  node 23 using route 0.32.83.58 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:28:15.290	ZWaveSerial::Send m_iFrameID 112 type 0x0 command 0x13 sent ok waiting for 3 ulTime 114289 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:28:15.310	got expected ACK <0x75e6e520>
24	12/28/22 13:28:15.311	ZWaveSerial::Send woke up: ulTime 114289 ulTime_end 114310 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:28:15.311	ZWaveSerial::Send m_iFrameID 112 type 0x0 command 0x13 sent ok waiting for 3 ulTime 114289 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:28:15.311	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 113 gwf_sd <0x75e6e520>
24	12/28/22 13:28:15.338	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 113 gwf_sd <0x75e6e520>
24	12/28/22 13:28:15.338	ZWaveSerial::ReceivedFrame m_iFrameID 113 gwf_sd is a response frame for m_iFrameID 112 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:28:15.359	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 114 gwf_sd <0x75e6e520>
24	12/28/22 13:28:15.374	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 114 gwf_sd <0x75e6e520>
24	12/28/22 13:28:15.374	ZWaveSerial::ReceivedFrame m_iFrameID 114 gwf_sd is a request frame for m_iFrameID 112 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:28:15.374	ZWaveSerial::Send woke up: ulTime 114289 ulTime_end 114374 TimeToWaitInMs 20000 m_pres 0x11ed2e0 m_preq 0x11ed460 status 1 <0x7626e520>
24	12/28/22 13:28:15.374	ZWaveSerial::Send m_iFrameID 112 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:28:15.375	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0x11ed238 now (nil) <0x7626e520>
24	12/28/22 13:28:15.375	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:5 Id: 7 <0x1157890> m_eJobStatus Waiting after 2.271617000 seconds <0x7626e520>
24	12/28/22 13:28:15.431	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 115 gwf_ach <0x75e6e520>
24	12/28/22 13:28:15.446	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 115 gwf_ach <0x75e6e520>
24	12/28/22 13:28:15.446	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 115 gwf_ach <0x75e6e520>
24	12/28/22 13:28:15.446	ZWaveJobHandler::DoReceivedFrame m_iFrameID 115 gwf_ach node 23 command 0x4 data  <0x7686e520>
24	12/28/22 13:28:15.447	ZWaveJobHandler::DoReceivedFrame m_iFrameID 115 passing to job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:5 Id: 7 auto del: 1 <0x7686e520>
24	12/28/22 13:28:15.447	ZWaveNode::HandlePollUpdate node 23 device 2112 class 0x32 command 0x2 m_iFrameID 115/19650824 data 0x21 0x44 0x0 0x0 0x0 0x0 0x0 0xd9 0x0 0x0 0x0 0x0 (!D##########) <0x7686e520>
06	12/28/22 13:28:15.447	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWH was: 0.0000 now: 0.0000 #hooks: 0 upnp: 0 skip: 0 v:0xd2be50/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:28:15.448	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWHReading was: 1672251879 now: 1672252095 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7686e520>
24	12/28/22 13:28:15.448	ZWaveNode::HandlePollUpdate_SensorMultiLevel_MeterReport 0x32 node 23 device 2112 child 0/0 cat 0 embed: 0 type 1 rate type 1 is 0.000000 was 0.000000 prec 2 sca 0 size 4 delta 0 previous -1.000000 len 12 <0x7686e520>
24	12/28/22 13:28:15.449	ZWJob_PollNode::ReceivedFrame -end- job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:5 Id: 7 got after 0 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 23 status 0 iOK 0 iBadTx 0 iNoReply 0 data 0x21 0x44 0x0 0x0 0x0 0x0 0x0 0xd9 0x0 0x0 0x0 0x0 (!D##########) <0x7686e520>
24	12/28/22 13:28:15.449	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:0 Id: 7 <0x1157890> m_eJobStatus Queued after 2.346079000 seconds <0x7686e520>
06	12/28/22 13:28:17.337	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0E 1A F9 01 00 57 1F 02 49  now: 0A 52 0D 1B 2F 01 00 5D 3D 01 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:17.338	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252086 now: 1672252097 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:17.344	Device_Variable::m_szValue_set device: 1546 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 48.6 now: 48.7 #hooks: 0 upnp: 0 skip: 0 v:0xd6d338/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:17.344	Device_Variable::m_szValue_set device: 1546 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: MaxTemp24hr was: 48.6 now: 48.7 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:17.346	Device_Variable::m_szValue_set device: 1546 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: MaxMinTemps was: 35.1,34,34,33.1,33.1,32.2,32.2,31.3,31.5,30.7,30.7,30.4,30.4,29.8,29.8,29.7,31.1,29.7,34,31.1,37,34,42.1,37.2,46.4,42.1,48.6,46.4,45.1,43.9,45.3,44.4,44.6,44.1,44.1,42.8,42.8,41.7,41.7,40.5,40.5,39.2,39.2,37.6,37.6,36.3,36.3,34.9 now: 35.1,34,34,33.1,33.1,32.2,32.2,31.3,31.5,30.7,30.7,30.4,30.4,29.8,29.8,29.7,31.1,29.7,34,31.1,37,34,42.1,37.2,46.4,42.1,48.7,46.4,45.1,43.9,45.3,44.4,44.6,44.1,44.1,42.8,42.8,41.7,41.7,40.5,40.5,39.2,39.2,37.6,37.6,36.3,36.3,34.9 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:17.347	Device_Variable::m_szValue_set device: 1546 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252062 now: 1672252097 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:17.347	Device_Variable::m_szValue_set device: 1547 service: urn:micasaverde-com:serviceId:HumiditySensor1 variable: CurrentLevel was: 62 now: 61 #hooks: 0 upnp: 0 skip: 0 v:0xd91c88/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:17.348	Device_Variable::m_szValue_set device: 1547 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252062 now: 1672252097 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
24	12/28/22 13:28:17.451	ZWJob_PollNode::ReadyToRun job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:0 Id: 7 priority 100 can cancel <0x7626e520>
24	12/28/22 13:28:17.451	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:1 Id: 7 <0x1157890> m_eJobStatus Running after 4.348124000 seconds <0x7626e520>
24	12/28/22 13:28:17.452	ZWJob_PollNode::Run job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:1 Id: 7 node 23 size cmds 3 <0x7626e520>
24	12/28/22 13:28:17.452	ZWJob_PollNode::Run Polling job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:1 Id: 7 node 23 device 2112 with command class 0x32 command 0x1 <0x7626e520>
24	12/28/22 13:28:17.452	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:7 Id: 7 <0x1157890> m_eJobStatus PendingData after 4.348887000 seconds <0x7626e520>
24	12/28/22 13:28:17.452	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0x11ed2e0 <0x7626e520>
41	12/28/22 13:28:17.453	ZWaveSerial::Send XXXX  node 23 using route 0.32.83.58 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:28:17.462	ZWaveSerial::Send m_iFrameID 116 type 0x0 command 0x13 sent ok waiting for 3 ulTime 116461 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:28:17.482	got expected ACK <0x75e6e520>
24	12/28/22 13:28:17.483	ZWaveSerial::Send woke up: ulTime 116461 ulTime_end 116482 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:28:17.483	ZWaveSerial::Send m_iFrameID 116 type 0x0 command 0x13 sent ok waiting for 3 ulTime 116461 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:28:17.483	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 117 gwf_sd <0x75e6e520>
24	12/28/22 13:28:17.510	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 117 gwf_sd <0x75e6e520>
24	12/28/22 13:28:17.510	ZWaveSerial::ReceivedFrame m_iFrameID 117 gwf_sd is a response frame for m_iFrameID 116 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:28:17.541	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 118 gwf_sd <0x75e6e520>
24	12/28/22 13:28:17.558	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 118 gwf_sd <0x75e6e520>
24	12/28/22 13:28:17.558	ZWaveSerial::ReceivedFrame m_iFrameID 118 gwf_sd is a request frame for m_iFrameID 116 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:28:17.558	ZWaveSerial::Send woke up: ulTime 116461 ulTime_end 116558 TimeToWaitInMs 20000 m_pres 0x11ed238 m_preq 0x1333700 status 1 <0x7626e520>
24	12/28/22 13:28:17.558	ZWaveSerial::Send m_iFrameID 116 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:28:17.559	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0x11ed2e0 now (nil) <0x7626e520>
24	12/28/22 13:28:17.559	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:5 Id: 7 <0x1157890> m_eJobStatus Waiting after 4.456111000 seconds <0x7626e520>
24	12/28/22 13:28:17.591	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 119 gwf_ach <0x75e6e520>
24	12/28/22 13:28:17.606	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 119 gwf_ach <0x75e6e520>
24	12/28/22 13:28:17.606	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 119 gwf_ach <0x75e6e520>
24	12/28/22 13:28:17.606	ZWaveJobHandler::DoReceivedFrame m_iFrameID 119 gwf_ach node 23 command 0x4 data  <0x7686e520>
24	12/28/22 13:28:17.607	ZWaveJobHandler::DoReceivedFrame m_iFrameID 119 passing to job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:5 Id: 7 auto del: 1 <0x7686e520>
24	12/28/22 13:28:17.607	ZWaveNode::HandlePollUpdate node 23 device 2112 class 0x32 command 0x2 m_iFrameID 119/18348560 data 0x21 0x54 0x0 0x0 0x0 0x0 0x0 0xd9 0x0 0x0 0x0 0x0 (!T##########) <0x7686e520>
06	12/28/22 13:28:17.607	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Watts was: 0.00 now: 0.00 #hooks: 0 upnp: 0 skip: 0 v:0xd22620/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:28:17.607	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: ActualUsage was: 1 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xd16338/NONE duplicate:1 <0x7686e520>
24	12/28/22 13:28:17.608	ZWaveNode::HandlePollUpdate_SensorMultiLevel_MeterReport 0x32 node 23 device 2112 child 0/0 cat 0 embed: 0 type 1 rate type 1 is 0.000000 was 0.000000 prec 2 sca 2 size 4 delta 0 previous -1.000000 len 12 <0x7686e520>
24	12/28/22 13:28:17.608	ZWJob_PollNode::ReceivedFrame -end- job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:5 Id: 7 got after 0 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 23 status 0 iOK 0 iBadTx 0 iNoReply 0 data 0x21 0x54 0x0 0x0 0x0 0x0 0x0 0xd9 0x0 0x0 0x0 0x0 (!T##########) <0x7686e520>
24	12/28/22 13:28:17.608	ZWJob_PollNode::ReceivedFrame poll_ok job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:5 Id: 7 node 23 <0x7686e520>
24	12/28/22 13:28:17.609	ZWJob_PollNode::m_eJobStatus job job#7 :pollnode #23 dev:2112 (0x1157890) N:23 P:100 S:4 Id: 7 <0x1157890> m_eJobStatus Successful after 4.505375000 seconds <0x7686e520>
04	12/28/22 13:28:17.609	<Job ID="7" Name="pollnode #23 3 cmds" Device="2112" Created="2022-12-28 13:28:13" Started="2022-12-28 13:28:13" Completed="2022-12-28 13:28:17" Duration="4.505375000" Runtime="4.504583000" Status="Successful" LastNote="" Node="23" NodeType="ZWaveNonDimmableLight" NodeDescription="Dome Module"/> <0x7686e520>
02	12/28/22 13:28:17.609	Device_Basic::AddPoll 2112 poll list full, deleting old one <0x7686e520>
06	12/28/22 13:28:17.611	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:HaDevice1 variable: PollRatings was: 5.00 now: 5.00 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:28:17.611	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastPollSuccess was: 1672251881 now: 1672252097 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7686e520>
24	12/28/22 13:28:17.611	ZWaveNode::m_bLastContactFailed_set device 2112 = 0, force 0, m_bNotListening 0 zw poll3 <0x7686e520>
06	12/28/22 13:28:17.611	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: ConsecutivePollFails was: 0 now: 0 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:28:24.712	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 1B 2F 01 00 5D 3D 01 79  now: 0A 52 09 1C 96 07 00 7A 2D 01 49  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:24.713	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252097 now: 1672252104 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:24.732	Device_Variable::m_szValue_set device: 2468 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252031 now: 1672252104 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:24.733	Device_Variable::m_szValue_set device: 2469 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252031 now: 1672252104 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:24.752	Device_Variable::m_szValue_set device: 1580 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 06 5D 0C 01 03 0A 02 69  now: 0A 52 09 07 96 07 00 7A 2D 01 69  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:28:24.752	Device_Variable::m_szValue_set device: 1580 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252069 now: 1672252104 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:28:30.055	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 1C 96 07 00 7A 2D 01 49  now: 0A 52 0D 1D D8 03 00 BC 29 01 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:30.056	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252104 now: 1672252110 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:30.083	Device_Variable::m_szValue_set device: 2346 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252075 now: 1672252110 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:30.084	Device_Variable::m_szValue_set device: 2347 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252075 now: 1672252110 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:31.131	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 1D D8 03 00 BC 29 01 79  now: 0A 52 0D 1E 1C 02 00 A1 2E 01 59  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:31.131	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252110 now: 1672252111 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:31.138	Device_Variable::m_szValue_set device: 2348 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252076 now: 1672252111 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:31.139	Device_Variable::m_szValue_set device: 2349 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252076 now: 1672252111 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:36.364	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 1E 1C 02 00 A1 2E 01 59  now: 0A 52 0D 1F 3B 01 00 A9 30 01 69  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:36.365	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252111 now: 1672252116 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:36.381	Device_Variable::m_szValue_set device: 2334 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252080 now: 1672252116 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:36.382	Device_Variable::m_szValue_set device: 2335 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252080 now: 1672252116 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:37.367	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 1F 3B 01 00 A9 30 01 69  now: 0A 52 0E 20 F9 01 00 57 1E 02 49  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:37.368	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252116 now: 1672252117 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:37.373	Device_Variable::m_szValue_set device: 2330 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252086 now: 1672252117 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:37.378	Device_Variable::m_szValue_set device: 2331 service: urn:micasaverde-com:serviceId:HumiditySensor1 variable: CurrentLevel was: 31 now: 30 #hooks: 0 upnp: 0 skip: 0 v:0xd91c88/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:37.379	Device_Variable::m_szValue_set device: 2331 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252086 now: 1672252117 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:38.312	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0E 20 F9 01 00 57 1E 02 49  now: 0A 52 0D 21 98 01 00 CF 23 02 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:38.313	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252117 now: 1672252118 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:38.318	Device_Variable::m_szValue_set device: 2332 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252083 now: 1672252118 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:38.319	Device_Variable::m_szValue_set device: 2333 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252083 now: 1672252118 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:39.726	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 21 98 01 00 CF 23 02 79  now: 0A 52 0E 22 EA 01 80 F7 35 01 50  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:39.727	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252118 now: 1672252119 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
24	12/28/22 13:28:43.100	ZWaveJobHandler::ServicePollLoop not polling 2 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:43.101	ZWaveJobHandler::ServicePollLoop not polling 4 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:43.101	ZWaveJobHandler::ServicePollLoop not polling 5 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:43.101	ZWaveJobHandler::ServicePollLoop not polling 6 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:43.101	ZWaveJobHandler::ServicePollLoop not polling 7 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:43.102	ZWaveJobHandler::ServicePollLoop not polling 8 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:43.102	ZWaveJobHandler::ServicePollLoop not polling 9 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:43.102	ZWaveJobHandler::ServicePollLoop not polling 10 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:43.102	ZWaveJobHandler::ServicePollLoop not polling 14 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:43.103	ZWaveJobHandler::ServicePollLoop not polling 20 bypass 0 freq 10800 listen 1 <0x7686e520>
24	12/28/22 13:28:43.103	ZWaveJobHandler::ServicePollLoop not polling 24 bypass 0 freq 0 listen 0 <0x7686e520>
24	12/28/22 13:28:43.103	ZWaveJobHandler::ServicePollLoop not polling 31 bypass 0 freq 0 listen 1 <0x7686e520>
24	12/28/22 13:28:43.104	ZWaveJobHandler::ServicePollLoop polling node 27 <0x7686e520>
24	12/28/22 13:28:43.104	sbrk ZWaveJobHandler::sbrkaddjob pMem 0x152e000/22208512 diff: 10903552 quit 0 <0x7686e520>
24	12/28/22 13:28:43.105	ZWJob_PollNode::ReadyToRun job#8 :pollnode #27 dev:2124 (0x1332a90) N:27 P:100 S:0 Id: 8 priority 100 can cancel <0x7626e520>
24	12/28/22 13:28:43.105	ZWJob_PollNode::m_eJobStatus job job#8 :pollnode #27 dev:2124 (0x1332a90) N:27 P:100 S:1 Id: 8 <0x1332a90> m_eJobStatus Running after 0.1202000 seconds <0x7626e520>
24	12/28/22 13:28:43.105	ZWJob_PollNode::Run job#8 :pollnode #27 dev:2124 (0x1332a90) N:27 P:100 S:1 Id: 8 node 27 size cmds 0 <0x7626e520>
24	12/28/22 13:28:43.106	ZWaveNode::AddPollingCommand node 27 device 2124 added 27/2124=0x25, <0x7626e520>
24	12/28/22 13:28:43.106	ZWJob_PollNode::Run Polling job#8 :pollnode #27 dev:2124 (0x1332a90) N:27 P:100 S:1 Id: 8 node 27 device 2124 with command class 0x25 command 0x2 <0x7626e520>
24	12/28/22 13:28:43.107	ZWJob_PollNode::m_eJobStatus job job#8 :pollnode #27 dev:2124 (0x1332a90) N:27 P:100 S:7 Id: 8 <0x1332a90> m_eJobStatus PendingData after 0.2649000 seconds <0x7626e520>
24	12/28/22 13:28:43.107	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p (nil) now 0x1332c20 <0x7626e520>
41	12/28/22 13:28:43.107	ZWaveSerial::Send XXXX  node 27 using route 0.32.83.58 autoroute: 1 direct: 0 <0x7626e520>
24	12/28/22 13:28:43.118	ZWaveSerial::Send m_iFrameID 120 type 0x0 command 0x13 sent ok waiting for 3 ulTime 142117 timeout 2:2000 bWaitingForAck 1 abort 0 <0x7626e520>
42	12/28/22 13:28:43.128	got expected ACK <0x75e6e520>
24	12/28/22 13:28:43.129	ZWaveSerial::Send woke up: ulTime 142117 ulTime_end 142128 TimeToWaitInMs 2000 m_pres (nil) m_preq (nil) status 1 <0x7626e520>
24	12/28/22 13:28:43.129	ZWaveSerial::Send m_iFrameID 120 type 0x0 command 0x13 sent ok waiting for 3 ulTime 142117 timeout 20:20000 bWaitingForAck 0 abort 0 <0x7626e520>
24	12/28/22 13:28:43.129	ZWaveSerial::ReceiveData got frame type 0x1 command id 0x13 m_iFrameID 121 gwf_sd <0x75e6e520>
24	12/28/22 13:28:43.154	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 121 gwf_sd <0x75e6e520>
24	12/28/22 13:28:43.154	ZWaveSerial::ReceivedFrame m_iFrameID 121 gwf_sd is a response frame for m_iFrameID 120 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:28:43.174	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x13 m_iFrameID 122 gwf_sd <0x75e6e520>
24	12/28/22 13:28:43.190	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 122 gwf_sd <0x75e6e520>
24	12/28/22 13:28:43.190	ZWaveSerial::ReceivedFrame m_iFrameID 122 gwf_sd is a request frame for m_iFrameID 120 pd_r we're waiting got ack 1 expected response 3 <0x75e6e520>
24	12/28/22 13:28:43.190	ZWaveSerial::Send woke up: ulTime 142117 ulTime_end 142190 TimeToWaitInMs 20000 m_pres 0x1153910 m_preq 0x1153960 status 1 <0x7626e520>
24	12/28/22 13:28:43.190	ZWaveSerial::Send m_iFrameID 120 type 0x0 command 0x13 ok got response m_iSendsWithoutReceive 0 <0x7626e520>
24	12/28/22 13:28:43.191	ZWaveSerial::m_pZWaveFrame_Sending_set this 0x1086db8 m_p 0x1332c20 now (nil) <0x7626e520>
24	12/28/22 13:28:43.191	ZWJob_PollNode::m_eJobStatus job job#8 :pollnode #27 dev:2124 (0x1332a90) N:27 P:100 S:5 Id: 8 <0x1332a90> m_eJobStatus Waiting after 0.86931000 seconds <0x7626e520>
24	12/28/22 13:28:43.210	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 123 gwf_ach <0x75e6e520>
24	12/28/22 13:28:43.226	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 123 gwf_ach <0x75e6e520>
24	12/28/22 13:28:43.226	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 123 gwf_ach <0x75e6e520>
24	12/28/22 13:28:43.226	ZWaveJobHandler::DoReceivedFrame m_iFrameID 123 gwf_ach node 27 command 0x4 data  <0x7686e520>
24	12/28/22 13:28:43.227	ZWaveJobHandler::DoReceivedFrame m_iFrameID 123 passing to job#8 :pollnode #27 dev:2124 (0x1332a90) N:27 P:100 S:5 Id: 8 auto del: 1 <0x7686e520>
24	12/28/22 13:28:43.227	ZWaveNode::HandlePollUpdate node 27 device 2124 class 0x25 command 0x3 m_iFrameID 123/16677968 data 0x0 (#) <0x7686e520>
24	12/28/22 13:28:43.227	ZWaveNode::HandlePollUpdate_Basic_Report node 27 device 2124 now is 0 was 0/-99999 <0x7686e520>
24	12/28/22 13:28:43.228	ZWJob_PollNode::ReceivedFrame -end- job job#8 :pollnode #27 dev:2124 (0x1332a90) N:27 P:100 S:5 Id: 8 got after 0 seconds FUNC_ID_APPLICATION_COMMAND_HANDLER node info for 27 status 0 iOK 0 iBadTx 0 iNoReply 0 data 0x0 (#) <0x7686e520>
24	12/28/22 13:28:43.228	ZWJob_PollNode::ReceivedFrame poll_ok job job#8 :pollnode #27 dev:2124 (0x1332a90) N:27 P:100 S:5 Id: 8 node 27 <0x7686e520>
24	12/28/22 13:28:43.228	ZWJob_PollNode::m_eJobStatus job job#8 :pollnode #27 dev:2124 (0x1332a90) N:27 P:100 S:4 Id: 8 <0x1332a90> m_eJobStatus Successful after 0.124470000 seconds <0x7686e520>
04	12/28/22 13:28:43.229	<Job ID="8" Name="pollnode #27 1 cmds" Device="2124" Created="2022-12-28 13:28:43" Started="2022-12-28 13:28:43" Completed="2022-12-28 13:28:43" Duration="0.124470000" Runtime="0.123610000" Status="Successful" LastNote="" Node="27" NodeType="ZWaveNonDimmableLight" NodeDescription="Backup Power"/> <0x7686e520>
02	12/28/22 13:28:43.229	Device_Basic::AddPoll 2124 poll list full, deleting old one <0x7686e520>
06	12/28/22 13:28:43.230	Device_Variable::m_szValue_set device: 2124 service: urn:micasaverde-com:serviceId:HaDevice1 variable: PollRatings was: 5.00 now: 5.00 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:28:43.231	Device_Variable::m_szValue_set device: 2124 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastPollSuccess was: 1672251907 now: 1672252123 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7686e520>
24	12/28/22 13:28:43.231	ZWaveNode::m_bLastContactFailed_set device 2124 = 0, force 0, m_bNotListening 0 zw poll3 <0x7686e520>
06	12/28/22 13:28:43.231	Device_Variable::m_szValue_set device: 2124 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: ConsecutivePollFails was: 0 now: 0 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:28:43.594	Device_Variable::m_szValue_set device: 1580 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 07 96 07 00 7A 2D 01 69  now: 0A 52 09 08 A1 08 00 DC 0C 02 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:28:43.595	Device_Variable::m_szValue_set device: 1580 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252104 now: 1672252123 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:28:49.882	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0E 22 EA 01 80 F7 35 01 50  now: 0A 52 09 23 BC 02 80 B1 23 02 59  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:49.883	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252119 now: 1672252129 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:49.909	Device_Variable::m_szValue_set device: 2352 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252015 now: 1672252129 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:49.935	Device_Variable::m_szValue_set device: 1580 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 08 A1 08 00 DC 0C 02 79  now: 0A 52 09 09 BC 02 80 B1 23 02 69  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:28:49.936	Device_Variable::m_szValue_set device: 1580 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252123 now: 1672252129 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:28:50.505	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 23 BC 02 80 B1 23 02 59  now: 0A 52 09 24 5D 0C 01 03 0A 02 39  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:50.505	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252129 now: 1672252130 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:50.513	Device_Variable::m_szValue_set device: 2670 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252069 now: 1672252130 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:50.568	Device_Variable::m_szValue_set device: 1580 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 09 BC 02 80 B1 23 02 69  now: 0A 52 09 0A 5D 0C 01 03 0A 02 69  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:28:50.569	Device_Variable::m_szValue_set device: 1580 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252129 now: 1672252130 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73815520>
06	12/28/22 13:28:52.471	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 09 24 5D 0C 01 03 0A 02 39  now: 0A 52 0D 25 2F 01 00 5D 3D 01 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:52.471	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252130 now: 1672252132 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:52.476	Device_Variable::m_szValue_set device: 1546 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252097 now: 1672252132 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:28:52.477	Device_Variable::m_szValue_set device: 1547 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252097 now: 1672252132 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
24	12/28/22 13:28:53.916	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 124 gwf_ach <0x75e6e520>
24	12/28/22 13:28:53.934	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 124 gwf_ach <0x75e6e520>
24	12/28/22 13:28:53.934	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 124 gwf_ach <0x75e6e520>
24	12/28/22 13:28:53.934	ZWaveJobHandler::DoReceivedFrame m_iFrameID 124 gwf_ach node 23 command 0x4 data  <0x7686e520>
24	12/28/22 13:28:53.935	ZWaveNode::HandlePollUpdate node 23 device 2112 class 0x32 command 0x2 m_iFrameID 124/18920280 data 0x21 0x44 0x0 0x0 0x0 0x0 0x0 0x28 0x0 0x0 0x0 0x0 (!D#####(####) <0x7686e520>
06	12/28/22 13:28:53.935	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWH was: 0.0000 now: 0.0000 #hooks: 0 upnp: 0 skip: 0 v:0xd2be50/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:28:53.935	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: KWHReading was: 1672252095 now: 1672252133 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7686e520>
24	12/28/22 13:28:53.936	ZWaveNode::HandlePollUpdate_SensorMultiLevel_MeterReport 0x32 node 23 device 2112 child 0/0 cat 0 embed: 0 type 1 rate type 1 is 0.000000 was 0.000000 prec 2 sca 0 size 4 delta 0 previous -1.000000 len 12 <0x7686e520>
24	12/28/22 13:28:53.936	ZWaveJobHandler::DoReceivedFrame m_iFrameID 124 done 1 <0x7686e520>
24	12/28/22 13:28:54.928	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 125 gwf_ach <0x75e6e520>
24	12/28/22 13:28:54.946	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 125 gwf_ach <0x75e6e520>
24	12/28/22 13:28:54.947	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 125 gwf_ach <0x75e6e520>
24	12/28/22 13:28:54.947	ZWaveJobHandler::DoReceivedFrame m_iFrameID 125 gwf_ach node 23 command 0x4 data  <0x7686e520>
24	12/28/22 13:28:54.948	ZWaveNode::HandlePollUpdate node 23 device 2112 class 0x32 command 0x2 m_iFrameID 125/17213288 data 0x21 0x54 0x0 0x0 0x0 0x0 0x0 0x28 0x0 0x0 0x0 0x0 (!T#####(####) <0x7686e520>
06	12/28/22 13:28:54.948	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Watts was: 0.00 now: 0.00 #hooks: 0 upnp: 0 skip: 0 v:0xd22620/NONE duplicate:1 <0x7686e520>
06	12/28/22 13:28:54.948	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: ActualUsage was: 1 now: 1 #hooks: 0 upnp: 0 skip: 0 v:0xd16338/NONE duplicate:1 <0x7686e520>
24	12/28/22 13:28:54.949	ZWaveNode::HandlePollUpdate_SensorMultiLevel_MeterReport 0x32 node 23 device 2112 child 0/0 cat 0 embed: 0 type 1 rate type 1 is 0.000000 was 0.000000 prec 2 sca 2 size 4 delta 0 previous -1.000000 len 12 <0x7686e520>
24	12/28/22 13:28:54.949	ZWaveJobHandler::DoReceivedFrame m_iFrameID 125 done 1 <0x7686e520>
24	12/28/22 13:28:55.902	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 126 gwf_ach <0x75e6e520>
24	12/28/22 13:28:55.918	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 126 gwf_ach <0x75e6e520>
24	12/28/22 13:28:55.918	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 126 gwf_ach <0x75e6e520>
24	12/28/22 13:28:55.918	ZWaveJobHandler::DoReceivedFrame m_iFrameID 126 gwf_ach node 23 command 0x4 data  <0x7686e520>
24	12/28/22 13:28:55.919	ZWaveNode::HandlePollUpdate node 23 device 2112 class 0x32 command 0x2 m_iFrameID 126/11883112 data 0xa1 0x42 0x2f 0x9 0x0 0x28 0x2f 0xc (#B/##(/#) <0x7686e520>
06	12/28/22 13:28:55.919	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Volts was: 120.45 now: 120.41 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7686e520>
24	12/28/22 13:28:55.919	ZWaveNode::HandlePollUpdate_SensorMultiLevel_MeterReport 0x32 node 23 device 2112 child 0/0 cat 0 embed: 0 type 1 rate type 1 is 120.410000 was 0.000000 prec 2 sca 4 size 2 delta 12044 previous -1.000000 len 8 <0x7686e520>
24	12/28/22 13:28:55.920	ZWaveJobHandler::DoReceivedFrame m_iFrameID 126 done 1 <0x7686e520>
24	12/28/22 13:28:56.904	ZWaveSerial::ReceiveData got frame type 0x0 command id 0x4 m_iFrameID 127 gwf_ach <0x75e6e520>
24	12/28/22 13:28:56.922	ZWaveSerial::ReceivedFrame holding the srm mutex for m_iFrameID 127 gwf_ach <0x75e6e520>
24	12/28/22 13:28:56.922	ZWaveSerial::ReceivedFrame receive data not waiting for frame: (nil)/null expect -1 act 0 good 0 type 0 cmd:4/0 gd: 1 m_pRes (nil) m_pReq (nil) resp REQUEST pzw->m_c 0x4 m_iFrameID 127 gwf_ach <0x75e6e520>
24	12/28/22 13:28:56.922	ZWaveJobHandler::DoReceivedFrame m_iFrameID 127 gwf_ach node 23 command 0x4 data  <0x7686e520>
24	12/28/22 13:28:56.923	ZWaveNode::HandlePollUpdate node 23 device 2112 class 0x32 command 0x2 m_iFrameID 127/13157984 data 0xa1 0x4a 0x0 0x0 0x0 0x28 0x0 0x0 (#J###(##) <0x7686e520>
06	12/28/22 13:28:56.923	Device_Variable::m_szValue_set device: 2112 service: urn:micasaverde-com:serviceId:EnergyMetering1 variable: Amps was: 0.00 now: 0.00 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x7686e520>
24	12/28/22 13:28:56.923	ZWaveNode::HandlePollUpdate_SensorMultiLevel_MeterReport 0x32 node 23 device 2112 child 0/0 cat 0 embed: 0 type 1 rate type 1 is 0.000000 was 0.000000 prec 2 sca 5 size 2 delta 0 previous -1.000000 len 8 <0x7686e520>
24	12/28/22 13:28:56.923	ZWaveJobHandler::DoReceivedFrame m_iFrameID 127 done 1 <0x7686e520>
06	12/28/22 13:29:05.058	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 25 2F 01 00 5D 3D 01 79  now: 0A 52 0D 26 D8 03 00 BD 29 01 79  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:05.059	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252132 now: 1672252145 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:05.086	Device_Variable::m_szValue_set device: 2346 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 65.8 now: 66 #hooks: 0 upnp: 0 skip: 0 v:0xd6d338/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:05.087	Device_Variable::m_szValue_set device: 2346 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252110 now: 1672252145 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:05.088	Device_Variable::m_szValue_set device: 2347 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252110 now: 1672252145 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:06.131	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 26 D8 03 00 BD 29 01 79  now: 0A 52 0D 27 1C 02 00 A1 2E 01 59  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:06.132	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252145 now: 1672252146 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:06.139	Device_Variable::m_szValue_set device: 2348 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252111 now: 1672252146 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:06.140	Device_Variable::m_szValue_set device: 2349 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252111 now: 1672252146 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:08.009	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 0A 52 0D 27 1C 02 00 A1 2E 01 59  now: 05 03 04 28 02 00  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:08.010	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252146 now: 1672252148 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
02	12/28/22 13:29:08.010	luup_log:1471: RFXtrx: warning: No decode method for message: 05 03 04 28 02 00  <0x73b1d520>
06	12/28/22 13:29:08.376	Device_Variable::m_szValue_set device: 1471 service: urn:rfxcom-com:serviceId:rfxtrx1 variable: LastReceivedMsg was: 05 03 04 28 02 00  now: 0A 52 0E 29 F9 01 00 57 1D 02 49  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:08.377	Device_Variable::m_szValue_set device: 1471 service: upnp-rfxcom-com:serviceId:rfxtrx1 variable: VeraTime was: 1672252148 now: 1672252148 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x73b1d520>
06	12/28/22 13:29:08.389	Device_Variable::m_szValue_set device: 2330 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1672252117 now: 1672252148 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:08.403	Device_Variable::m_szValue_set device: 2331 service: urn:micasaverde-com:serviceId:HumiditySensor1 variable: CurrentLevel was: 30 now: 29 #hooks: 0 upnp: 0 skip: 0 v:0xd91c88/NONE duplicate:0 <0x73b1d520>
06	12/28/22 13:29:08.404	Device_Variable::m_szValue_set device: 2331 service: urn:micasaverde-com:serviceId:HumiditySensor1 variable: MinHum24hr was: 30 now: 29 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0