How to troubleshoot a schedule not running

bbollard · December 24, 2012, 5:14pm

Hi folks,
I have a scene that is attached to a schedule that is supposed to run at 6:15 AM each weekday. The last time the schedule was run was on 21-December 0615AM and today, 24-December (Merry Christmas!) the schedule was not run at 0615 event though today is a Monday.

I am running beta firmware 1.5.459 (Aeon 4-in-1 support, still not working) and am wondering how one would go about troubleshooting this.

I’ve attached two snips out of UI5 to show how I configured the schedule and the indication that it did run on the 21st (but not today).

Thank you!

beachboync · January 21, 2013, 9:36pm

I also have a schedule that intermittently doesn’t run. Fails about once in a couple of weeks. The status of the device (GE outdoor switch, but not outdoors) shows correctly al the time, it just isn’t doing what it should - I.e. tun off at 2PM. No error indication, and network health and visibility seems fine.

How to troubleshoot?

Thanks, Bob (beachboync)

RichardTSchaefer · January 22, 2013, 12:19pm

You need to look at the log file at the time it was supposed to fire and see what was happening.

beachboync · January 23, 2013, 7:57pm

Hi Richard. My logfile seems to fill up quickly and I don’t see far enough back to tell. Obviously if I was there just when the problem occurred it would be OK, but what happens is that I only notice later that it had failed.

Am I doing the logfile thing correctly? I go to http:///cgi-bin/cmh/log.sh?Device=LuaUPnP and then hit Ctrl-A to select all and past into Notepad.

Thanks, Bob (beachboync)

RichardTSchaefer · January 24, 2013, 12:09am

If you are linux savy … you can edit the file on vera:
/etc/cmh/cmh.conf

Some settings:
ImmediatelyFlushLog=1
NumberOfCopies= 10
ArchiveLogsOnServer=0

Then you can find your log files in:
/tmp/log/cmh

beachboync · February 1, 2013, 7:22pm

I finally caught the problem happening. The device is 8, and the scene is Pond Off. Here is the log:

08 02/01/13 14:00:00.105 Scene::RunScene running 7 Pond Off <0x2ba27680>
08 02/01/13 14:00:00.106 JobHandler_LuaUPnP::HandleActionRequest device: 8 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2ba27680>
08 02/01/13 14:00:00.106 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=0 <0x2ba27680>
06 02/01/13 14:00:00.106 Device_Variable::m_szValue_set device: 8 service: urn:upnp-org:serviceId:SwitchPower1 variable: Target was: 1 now: 0 #hooks: 0 upnp: 0 v:0x8c4570/NONE duplicate:0 <0x2ba27680>
02 02/01/13 14:00:00.107 ZWJob_SendData UPDATE MANUAL ROUTE 5=0x8b855f <0x2ba27680>
02 02/01/13 14:00:00.120 UPDATE MANUAL ROUTE2 5=0x8b855f <0x2be27680>
02 02/01/13 14:00:00.121 ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
08 02/01/13 14:00:00.122 JobHandler_LuaUPnP::AlarmCallback Ran scene:7 Pond Off / timer:Pond Off next at 1359831600 now 1359745200 <0x2ba27680>
02 02/01/13 14:00:00.210 UPDATE MANUAL ROUTE2 5=0x8b855f <0x2be27680>
02 02/01/13 14:00:00.210 ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
06 02/01/13 14:00:00.318 Device_Variable::m_szValue_set device: 8 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 1 now: 0 #hooks: 3 upnp: 0 v:0x8c49d8/NONE duplicate:0 <0x2ba27680>
04 02/01/13 14:00:00.320 <0x2ba27680>
02 02/01/13 14:00:27.102 ZW_Send_Data node 8 USING ROUTE 255.0.0.0 <0x2be27680>
04 02/01/13 14:00:27.250 <0x2ba27680>
02 02/01/13 14:00:57.102 ZW_Send_Data node 9 USING ROUTE 255.88.147.133 <0x2be27680>
04 02/01/13 14:00:57.239 <0x2ba27680>
02 02/01/13 14:01:27.102 ZW_Send_Data node 2 USING ROUTE 255.105.99.101 <0x2be27680>
04 02/01/13 14:01:27.239 <0x2ba27680>
02 02/01/13 14:01:57.102 ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
06 02/01/13 14:01:57.248 Device_Variable::m_szValue_set device: 8 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 3 upnp: 0 v:0x8c49d8/NONE duplicate:0 <0x2ba27680>
04 02/01/13 14:01:57.250 <0x2ba27680>
02 02/01/13 14:02:27.102 ZW_Send_Data node 6 USING ROUTE 9.0.0.0 <0x2be27680>
04 02/01/13 14:02:27.229 <0x2ba27680>
02 02/01/13 14:02:57.102 ZW_Send_Data node 7 USING ROUTE 255.45.111.114 <0x2be27680>
04 02/01/13 14:02:57.229 <0x2ba27680>
02 02/01/13 14:03:27.103 ZW_Send_Data node 8 USING ROUTE 255.0.0.0 <0x2be27680>
04 02/01/13 14:03:27.249 <0x2ba27680>
02 02/01/13 14:03:57.102 ZW_Send_Data node 9 USING ROUTE 255.88.147.133 <0x2be27680>

You can see that at 14.00.00.105 it does start the scene, and at 14.00.00.106 and 14.00.00.318 it does turn the device off. But at 14.01.57.247 it turns the device back on again. Why?

I see that those 3 entries are not the same. Both seem to be SetDevice, SwitchPower1 but in one case it shows Target and the others Status. Are the Status entries reading the device status and why was the second one “was 0 now 1”?

The scene is a simple turn the pond off at 2 PM.

Thanks, Bob (beachboync)

RichardTSchaefer · February 1, 2013, 9:51pm

Do you have a schedule in your scene (#7) that sends commands 1 minute later ?
Goto the advanced tab for the scene … this will show a summary of everything.

beachboync · February 1, 2013, 11:01pm

Thanks Richard.

I did put a second schedule in place for the same scene (before the instance above) for 10 minutes later. I only put this in because it was failing originally. I can remove this if needed.

Advanced tab has a single entry that says “Pond SetTarget newTargetValue 0” which sounds correct - the action of the scene is to set the target value to 0 (off) - right?

There is only one other scene that changes the Pond. The pond is on a separate schedule from all other devices and has only two scenes - Pond On and Pond Off. The Advanced tab for Pond On of course sets the value to 1. Pond On occurs at 10 AM.

Thanks, Bob

beachboync · February 1, 2013, 11:10pm

I am learning every day!

I see now that I was not interpreting the log entry correctly. The …106 log entry shows trying to set the value Target from 1 to 0. I am not sure what the variable Target does for this device.

The next two log entries at …318 is setting the variable Status from1 to 0 and then …1.57.248 are setting the value Status from 0 to 1.

So I think I first need to know what the variable Target does and what the variable Status does. Does Target set the value to be taken, and then Status changes after the actual event occurs?

Thanks, Bob

RichardTSchaefer · February 1, 2013, 11:21pm

Target is command to the binary switch Z-Wave device to set a state.
Status is the returned status (for devices that report status) …
For those that do not, I believe the Z-Wave driver just assumes the command worked and changes the status … which will be updated later when the device is polled.

beachboync · February 2, 2013, 12:29am

Great!

So now I need to find out if that switch returns status. But looking at the log it would seem so. But then why would the status go to 0 and then back to 1 a second later?

But the problem seems to point to some kind of network problem. That device is in fact the furthest away from the Vera. I need to look at routes, etc.

Thanks, Bob

RichardTSchaefer · February 2, 2013, 12:51am

Does the attached light actually flickr ?

brientim · February 2, 2013, 2:03am

Two things that may assist:
Review the details contained in the Dashboard > Overview. It will contain both trigger and upcoming schedules.
I have added two example for scene data recorded in the log because the log files you displayed appear incomplete to establish if the scene was completed successfully. You see in the examples, once the scene is committed it will generate a job and you are looking for the a line like this as “04 02/02/13 12:30:23.655 <Job ID=“XX”…” to indicate the end of the relevant entries. The complete scene records: “Transmit was ok” etc, whereby, if it fails you will receive a message similiar to - “command 32/1 failed m_cTxStatus 1 retries”. When it does fail to reach a device, it will try an alternative route and even update the routing table. But, this does not appear to be the case as per your log entries.

What I would do is:
Delete the current scene and recreate a new scene and see if the same behaviour is encountered.

To review scene data use one of the options below:
Option 1
http://Vera_IP:3480/data_request?id=scene&action=list&scene=Scene_Number
This will display the details for the scene requested.

Option 2
http://Vera_IP:3480/data_request?id=user_data&output_format=xml or
http://Vera_IP/port_3480/data_request?id=user_data&output_format=xml
Search for "action device=“8” to see what is recorded in any scene for that device… or in you case, you can also search for Scene 7

Example 1 - Completed scene

08	02/02/13 12:25:29.415	JobHandler_LuaUPnP::HandleActionRequest argument SceneNum=58 <0x32cea680>
08	02/02/13 12:25:29.415	Scene::RunScene running 58 !!Test1 Off <0x32cea680>
08	02/02/13 12:25:29.416	JobHandler_LuaUPnP::HandleActionRequest device: 333 service: urn:upnp-org:serviceId:SwitchPower1 action: e[36;1mSetTargete[0m <0x32cea680>
08	02/02/13 12:25:29.416	JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=0 <0x32cea680>
06	02/02/13 12:25:29.416	Device_Variable::m_szValue_set device: 333 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mTargete[0m was: 1 now: 0 #hooks: 0 upnp: 0 v:0xc65a28/NONE duplicate:0 <0x32cea680>
02	02/02/13 12:25:29.418	e[33;1mZWJob_SendData  UPDATE MANUAL ROUTE 30=0x19d3178e[0m <0x32cea680>
02	02/02/13 12:25:29.420	e[33;1mUPDATE MANUAL ROUTE2 30=0x19d3178e[0m <0x2bc5f680>
02	02/02/13 12:25:29.420	e[33;1mZW_Send_Data node 30 USING ROUTE 13.0.0.0e[0m <0x2bc5f680>
02	02/02/13 12:25:29.516	e[33;1mUPDATE MANUAL ROUTE2 30=0x19d3178e[0m <0x2bc5f680>
02	02/02/13 12:25:29.516	e[33;1mZW_Send_Data node 30 USING ROUTE 13.0.0.0e[0m <0x2bc5f680>
06	02/02/13 12:25:29.713	Device_Variable::m_szValue_set device: 333 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mStatuse[0m was: 1 now: 0 #hooks: 3 upnp: 0 v:0xc6acd8/NONE duplicate:0 <0x2b85f680>
04	02/02/13 12:25:29.716	<Job ID="19" Name="OFF node 30" Device="333" Created="2013-02-02 12:25:29" Started="2013-02-02 12:25:29" Completed="2013-02-02 12:25:29" Duration="0.297727000" Runtime="0.296621000" Status="Successful" LastNote="Transmit was ok" Node="30" NodeType="ZWaveNonDimmableLight" NodeDescription="Test1"/> <0x2b85f680>

Example 2 - Failed scene

08	02/02/13 12:29:39.560	Scene::RunScene running 58 !!Test1 Off <0x32cea680>
08	02/02/13 12:29:39.560	JobHandler_LuaUPnP::HandleActionRequest device: 333 service: urn:upnp-org:serviceId:SwitchPower1 action: e[36;1mSetTargete[0m <0x32cea680>
08	02/02/13 12:29:39.561	JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=0 <0x32cea680>
06	02/02/13 12:29:39.561	Device_Variable::m_szValue_set device: 333 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mTargete[0m was: 1 now: 0 #hooks: 0 upnp: 0 v:0xc65a28/NONE duplicate:0 <0x32cea680>
02	02/02/13 12:29:39.562	e[33;1mZWJob_SendData  UPDATE MANUAL ROUTE 30=0x19d3178e[0m <0x32cea680>
02	02/02/13 12:29:39.577	e[33;1mUPDATE MANUAL ROUTE2 30=0x19d3178e[0m <0x2bc5f680>
02	02/02/13 12:29:39.577	e[33;1mZW_Send_Data node 30 USING ROUTE 13.0.0.0e[0m <0x2bc5f680>
02	02/02/13 12:29:39.686	e[33;1mUPDATE MANUAL ROUTE2 30=0x19d3178e[0m <0x2bc5f680>
02	02/02/13 12:29:39.686	e[33;1mZW_Send_Data node 30 USING ROUTE 13.0.0.0e[0m <0x2bc5f680>
06	02/02/13 12:29:39.824	Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mLastErrore[0m was: Poll failed now: Node 30 failed #hooks: 0 upnp: 0 v:0xf9c4a0/NONE duplicate:0 <0x2b85f680>
01	02/02/13 12:29:39.825	e[31;1mZWaveNode::CurrentRouteFailed node 30 device 333 position 13 route 13.0.0.0 hop -1 (from 1)e[0m <0x2b85f680>
06	02/02/13 12:29:39.825	Device_Variable::m_szValue_set device: 333 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: e[35;1mAutoRoutee[0m was: 0-5x,17-14x,13-15,12-15 now: 0-5x,17-14x,13-15x,12-15 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b85f680>
06	02/02/13 12:29:39.826	Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mLastRouteFailuree[0m was: 1359768499 now: 1359768579 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b85f680>
02	02/02/13 12:29:39.827	e[33;1mCurrentRouteFailed XXX1 (null)e[0m <0x2b85f680>
02	02/02/13 12:29:39.827	e[33;1mCurrentRouteFailed XXX3 0-5x,17-14x,13-15x,12-15e[0m <0x2b85f680>
02	02/02/13 12:29:39.827	e[33;1mCurrentRouteFailed XXX4e[0m <0x2b85f680>
02	02/02/13 12:29:39.827	e[33;1mUpdateManualRoute XXX1 node 30 route 0-5x,17-14x,13-15x,12-15e[0m <0x2b85f680>
02	02/02/13 12:29:39.828	e[33;1mUpdateManualRoute XXX2 12.0.0.0 from 0-5x,17-14x,13-15x,12-15e[0m <0x2b85f680>
02	02/02/13 12:29:39.828	e[33;1mXXXX CurrentRouteFailed node 30 m_cRoutePosition 20 route 12.0.0.0e[0m <0x2b85f680>
02	02/02/13 12:29:39.828	e[33;1mZWJob_SendData::ReceivedFrame job job#32 :OFF node 30 dev:333 (0x1695390) N:30 P:35 S:5 to node 30 command 32/1 failed m_cTxStatus 1 retries 0e[0m <0x2b85f680>
02	02/02/13 12:29:39.831	e[33;1mUPDATE MANUAL ROUTE2 30=0x19d3178e[0m <0x2bc5f680>
02	02/02/13 12:29:39.831	e[33;1mZW_Send_Data node 30 USING ROUTE 12.0.0.0e[0m <0x2bc5f680>
01	02/02/13 12:29:40.043	e[31;1mZWaveNode::CurrentRouteFailed node 30 device 333 position 20 route 12.0.0.0 hop 1 (from 6)e[0m <0x2b85f680>
06	02/02/13 12:29:40.044	Device_Variable::m_szValue_set device: 333 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: e[35;1mAutoRoutee[0m was: 0-5x,17-14x,13-15x,12-15 now: 0-5x,17-14x,13-15x,12-15x #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b85f680>
06	02/02/13 12:29:40.045	Device_Variable::m_szValue_set device: 1 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: e[35;1mLastRouteFailuree[0m was: 1359768579 now: 1359768580 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b85f680>
02	02/02/13 12:29:40.045	e[33;1mCurrentRouteFailed XXX1 (null)e[0m <0x2b85f680>
02	02/02/13 12:29:40.046	e[33;1mCurrentRouteFailed XXX3 0-5x,17-14x,13-15x,12-15xe[0m <0x2b85f680>
02	02/02/13 12:29:40.046	e[33;1mCurrentRouteFailed XXX4e[0m <0x2b85f680>
02	02/02/13 12:29:40.046	e[33;1mUpdateManualRoute XXX1 node 30 route 0-5x,17-14x,13-15x,12-15xe[0m <0x2b85f680>
06	02/02/13 12:29:40.046	Device_Variable::m_szValue_set device: 333 service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: e[35;1mAllRoutesFailede[0m was: 0 now: 1 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2b85f680>
02	02/02/13 12:29:40.047	e[33;1mXXXX CurrentRouteFailed node 30 m_cRoutePosition 0 route 0.0.0.0e[0m <0x2b85f680>
02	02/02/13 12:29:40.047	e[33;1mZWJob_SendData::ReceivedFrame job job#32 :OFF node 30 dev:333 (0x1695390) N:30 P:70 S:5 to node 30 command 32/1 failed m_cTxStatus 6 retries 1e[0m <0x2b85f680>
02	02/02/13 12:29:40.050	e[33;1mUPDATE MANUAL ROUTE2 30=(nil)e[0m <0x2bc5f680>
02	02/02/13 12:29:40.051	e[33;1mZW_Send_Data node 30 NO ROUTE (nil)e[0m <0x2bc5f680>
02	02/02/13 12:29:51.923	e[33;1mZWJob_SendData::ReceivedFrame job job#32 :OFF node 30 dev:333 (0x1695390) N:30 P:70 S:5 to node 30 command 32/1 failed m_cTxStatus 1 retries 2e[0m <0x2b85f680>

beachboync · February 2, 2013, 2:34am

HI Brientem - nice to “meet” you and thanks for coming into this discussion. I appreciate the help from all and I am really learning a lot of new stuff.

My apologies on the log file. For some reason, I didn’t get it all in - a copy/paste error. Here is the fullest log I have, and it goes to about ten minutes after the initial Pond Off and shows another Pond Off starting. This is because, as I said above, I put in a second schedule for this event 10 minutes later since the first one didn’t seem to be taking all the time.

BTW, don’t forget that the problem is intermittent - usually it works. It took me a few days to wait for a fail and be there in time to get the log.

08	02/01/13 14:00:00.105	Scene::RunScene running 7 Pond Off <0x2ba27680>
08	02/01/13 14:00:00.106	JobHandler_LuaUPnP::HandleActionRequest device: 8 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2ba27680>
08	02/01/13 14:00:00.106	JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=0 <0x2ba27680>
06	02/01/13 14:00:00.106	Device_Variable::m_szValue_set device: 8 service: urn:upnp-org:serviceId:SwitchPower1 variable: Target was: 1 now: 0 #hooks: 0 upnp: 0 v:0x8c4570/NONE duplicate:0 <0x2ba27680>
02	02/01/13 14:00:00.107	ZWJob_SendData  UPDATE MANUAL ROUTE 5=0x8b855f <0x2ba27680>
02	02/01/13 14:00:00.120	UPDATE MANUAL ROUTE2 5=0x8b855f <0x2be27680>
02	02/01/13 14:00:00.121	ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
08	02/01/13 14:00:00.122	JobHandler_LuaUPnP::AlarmCallback Ran scene:7 Pond Off / timer:Pond Off next at 1359831600 now 1359745200 <0x2ba27680>
02	02/01/13 14:00:00.210	UPDATE MANUAL ROUTE2 5=0x8b855f <0x2be27680>
02	02/01/13 14:00:00.210	ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
06	02/01/13 14:00:00.318	Device_Variable::m_szValue_set device: 8 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 1 now: 0 #hooks: 3 upnp: 0 v:0x8c49d8/NONE duplicate:0 <0x2ba27680>
04	02/01/13 14:00:00.320	 <0x2ba27680>
02	02/01/13 14:00:27.102	ZW_Send_Data node 8 USING ROUTE 255.0.0.0 <0x2be27680>
04	02/01/13 14:00:27.250	 <0x2ba27680>
02	02/01/13 14:00:57.102	ZW_Send_Data node 9 USING ROUTE 255.88.147.133 <0x2be27680>
04	02/01/13 14:00:57.239	 <0x2ba27680>
02	02/01/13 14:01:27.102	ZW_Send_Data node 2 USING ROUTE 255.105.99.101 <0x2be27680>
04	02/01/13 14:01:27.239	 <0x2ba27680>
02	02/01/13 14:01:57.102	ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
06	02/01/13 14:01:57.248	Device_Variable::m_szValue_set device: 8 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 1 #hooks: 3 upnp: 0 v:0x8c49d8/NONE duplicate:0 <0x2ba27680>
04	02/01/13 14:01:57.250	 <0x2ba27680>
02	02/01/13 14:02:27.102	ZW_Send_Data node 6 USING ROUTE 9.0.0.0 <0x2be27680>
04	02/01/13 14:02:27.229	 <0x2ba27680>
02	02/01/13 14:02:57.102	ZW_Send_Data node 7 USING ROUTE 255.45.111.114 <0x2be27680>
04	02/01/13 14:02:57.229	 <0x2ba27680>
02	02/01/13 14:03:27.103	ZW_Send_Data node 8 USING ROUTE 255.0.0.0 <0x2be27680>
04	02/01/13 14:03:27.249	 <0x2ba27680>
02	02/01/13 14:03:57.102	ZW_Send_Data node 9 USING ROUTE 255.88.147.133 <0x2be27680>
04	02/01/13 14:03:57.249	 <0x2ba27680>
02	02/01/13 14:04:27.102	ZW_Send_Data node 2 USING ROUTE 255.105.99.101 <0x2be27680>
04	02/01/13 14:04:27.239	 <0x2ba27680>
02	02/01/13 14:04:57.103	ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
04	02/01/13 14:04:57.239	 <0x2ba27680>
02	02/01/13 14:05:05.373	luvd_get_info mg conn can't read /etc/cmh-ludl//toolbox.js or /etc/cmh-lu//toolbox.js from filename /toolbox.js pPtrFile (null) <0x2d427680>
02	02/01/13 14:05:27.102	ZW_Send_Data node 6 USING ROUTE 9.0.0.0 <0x2be27680>
04	02/01/13 14:05:27.229	 <0x2ba27680>
02	02/01/13 14:05:57.102	ZW_Send_Data node 7 USING ROUTE 255.45.111.114 <0x2be27680>
04	02/01/13 14:05:57.249	 <0x2ba27680>
02	02/01/13 14:06:27.102	ZW_Send_Data node 8 USING ROUTE 255.0.0.0 <0x2be27680>
04	02/01/13 14:06:27.269	 <0x2ba27680>
02	02/01/13 14:06:57.102	ZW_Send_Data node 9 USING ROUTE 255.88.147.133 <0x2be27680>
04	02/01/13 14:06:57.249	 <0x2ba27680>
02	02/01/13 14:07:27.102	ZW_Send_Data node 2 USING ROUTE 255.105.99.101 <0x2be27680>
04	02/01/13 14:07:27.239	 <0x2ba27680>
02	02/01/13 14:07:57.103	ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
04	02/01/13 14:07:57.249	 <0x2ba27680>
02	02/01/13 14:08:27.102	ZW_Send_Data node 6 USING ROUTE 9.0.0.0 <0x2be27680>
04	02/01/13 14:08:27.229	 <0x2ba27680>
08	02/01/13 14:08:55.075	JobHandler_LuaUPnP::HandleActionRequest device: 8 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2cc27680>
08	02/01/13 14:08:55.075	JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=8 <0x2cc27680>
08	02/01/13 14:08:55.076	JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x2cc27680>
08	02/01/13 14:08:55.076	JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x2cc27680>
08	02/01/13 14:08:55.076	JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=0 <0x2cc27680>
08	02/01/13 14:08:55.076	JobHandler_LuaUPnP::HandleActionRequest argument rand=0.9035133523114257 <0x2cc27680>
06	02/01/13 14:08:55.077	Device_Variable::m_szValue_set device: 8 service: urn:upnp-org:serviceId:SwitchPower1 variable: Target was: 0 now: 0 #hooks: 0 upnp: 0 v:0x8c4570/NONE duplicate:1 <0x2cc27680>
02	02/01/13 14:08:55.078	ZWJob_SendData  UPDATE MANUAL ROUTE 5=0x8b855f <0x2cc27680>
02	02/01/13 14:08:55.079	UPDATE MANUAL ROUTE2 5=0x8b855f <0x2be27680>
02	02/01/13 14:08:55.079	ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
02	02/01/13 14:08:55.170	UPDATE MANUAL ROUTE2 5=0x8b855f <0x2be27680>
02	02/01/13 14:08:55.170	ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
06	02/01/13 14:08:55.278	Device_Variable::m_szValue_set device: 8 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 1 now: 0 #hooks: 3 upnp: 0 v:0x8c49d8/NONE duplicate:0 <0x2ba27680>
04	02/01/13 14:08:55.280	 <0x2ba27680>
02	02/01/13 14:09:07.102	ZW_Send_Data node 7 USING ROUTE 255.45.111.114 <0x2be27680>
04	02/01/13 14:09:07.229	 <0x2ba27680>
02	02/01/13 14:09:37.102	ZW_Send_Data node 8 USING ROUTE 255.0.0.0 <0x2be27680>
04	02/01/13 14:09:37.229	 <0x2ba27680>
08	02/01/13 14:10:00.100	Scene::RunScene running 7 Pond Off <0x2ba27680>
08	02/01/13 14:10:00.101	JobHandler_LuaUPnP::HandleActionRequest device: 8 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x2ba27680>
08	02/01/13 14:10:00.101	JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=0 <0x2ba27680>
06	02/01/13 14:10:00.101	Device_Variable::m_szValue_set device: 8 service: urn:upnp-org:serviceId:SwitchPower1 variable: Target was: 0 now: 0 #hooks: 0 upnp: 0 v:0x8c4570/NONE duplicate:1 <0x2ba27680>
02	02/01/13 14:10:00.102	ZWJob_SendData  UPDATE MANUAL ROUTE 5=0x8b855f <0x2ba27680>
08	02/01/13 14:10:00.103	JobHandler_LuaUPnP::AlarmCallback Ran scene:7 Pond Off / timer:Second Off next at 1359832200 now 1359745800 <0x2ba27680>
02	02/01/13 14:10:00.105	UPDATE MANUAL ROUTE2 5=0x8b855f <0x2be27680>
02	02/01/13 14:10:00.105	ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
02	02/01/13 14:10:00.200	UPDATE MANUAL ROUTE2 5=0x8b855f <0x2be27680>
02	02/01/13 14:10:00.200	ZW_Send_Data node 5 USING ROUTE 255.0.0.0 <0x2be27680>
06	02/01/13 14:10:00.308	Device_Variable::m_szValue_set device: 8 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 0 now: 0 #hooks: 3 upnp: 0 v:0x8c49d8/NONE duplicate:1 <0x2ba27680>

I don’t see the Job ID= anywhere in that. But I did see this, which looks interesting and does imply that the job ended, perhaps. Not sure what an alarm callback is.

08 02/01/13 14:00:00.122 JobHandler_LuaUPnP::AlarmCallback Ran scene:7 Pond Off / timer:Pond Off next at 1359831600 now 1359745200 <0x2ba27680>

I will follow up on your other info.

Thanks, Bob

brientim · February 2, 2013, 3:17am

Hello Bob,

Nice to “meet” you too. Everyday is a school day and we are always learning! Well, I try to anyway.

How I would manage this is clear my log, so you only have a short amount of data to scroll through. Easiest way is to open it up and then delete the data (you may wish to save a copy first if you so desire), then save. I would then execute the scene manually and then grab the detail in the log immediately after this was completed. Also, if you run this info into your browser (change to suit) and post response as a reply, it may assist in reviewing if there is anything in the scene which needs looking at.

http://Vera_IP:3480/data_request?id=scene&action=list&scene=Scene_Number
e.g http://192.168.1.100:3480/data_request?id=scene&action=list&scene=7

Have look at Managed delays within your scene. If you have a look at the entries below, the first one has a one second delay and execute on a schedule and looks very similar to yours. The second code is the scene data as suggested above and note the ““delay”: 1”. This is also displayed in the Advanced tab of the scene.

08	02/02/13 14:09:00.101	Scene::RunScene running 58 !!Test1 Off <0x2b45b680>
08	02/02/13 14:09:00.102	JobHandler_LuaUPnP::HandleActionRequest device: 333 service: urn:upnp-org:serviceId:SwitchPower1 action: e[36;1mSetTargete[0m <0x2b45b680>
08	02/02/13 14:09:00.102	JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=0 <0x2b45b680>
06	02/02/13 14:09:00.102	Device_Variable::m_szValue_set device: 333 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mTargete[0m was: 0 now: 0 #hooks: 0 upnp: 0 v:0xf5a788/NONE duplicate:1 <0x2b45b680>
02	02/02/13 14:09:00.105	e[33;1mZWJob_SendData  UPDATE MANUAL ROUTE 30=(nil)e[0m <0x2b45b680>
02	02/02/13 14:09:00.107	e[33;1mUPDATE MANUAL ROUTE2 30=(nil)e[0m <0x2b85b680>
02	02/02/13 14:09:00.107	e[33;1mZW_Send_Data node 30 NO ROUTE (nil)e[0m <0x2b85b680>
08	02/02/13 14:09:00.114	JobHandler_LuaUPnP::AlarmCallback Ran scene:58 !!Test1 Off / timer:New schedule next at 1359774540 now 1359774540 <0x2b45b680>
02	02/02/13 14:09:00.216	e[33;1mUPDATE MANUAL ROUTE2 30=(nil)e[0m <0x2b85b680>
02	02/02/13 14:09:00.216	e[33;1mZW_Send_Data node 30 NO ROUTE (nil)e[0m <0x2b85b680>
06	02/02/13 14:09:00.323	Device_Variable::m_szValue_set device: 333 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mStatuse[0m was: 0 now: 0 #hooks: 4 upnp: 0 v:0xf5abf0/NONE duplicate:1 <0x2b45b680>
04	02/02/13 14:09:00.325	<Job ID="4" Name="OFF node 30" Device="333" Created="2013-02-02 14:09:00" Started="2013-02-02 14:09:00" Completed="2013-02-02 14:09:00" Duration="0.219868000" Runtime="0.218736000" Status="Successful" LastNote="Transmit was ok" Node="30" NodeType="ZWaveNonDimmableLight" NodeDescription="Test1"/> <0x2b45b680>
08	02/02/13 14:09:01.100	JobHandler_LuaUPnP::HandleActionRequest device: 333 service: urn:upnp-org:serviceId:SwitchPower1 action: e[36;1mSetTargete[0m <0x2b45b680>
08	02/02/13 14:09:01.101	JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x2b45b680>
06	02/02/13 14:09:01.101	Device_Variable::m_szValue_set device: 333 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mTargete[0m was: 0 now: 1 #hooks: 0 upnp: 0 v:0xf5a788/NONE duplicate:0 <0x2b45b680>
02	02/02/13 14:09:01.102	e[33;1mZWJob_SendData  UPDATE MANUAL ROUTE 30=(nil)e[0m <0x2b45b680>
02	02/02/13 14:09:01.105	e[33;1mUPDATE MANUAL ROUTE2 30=(nil)e[0m <0x2b85b680>
02	02/02/13 14:09:01.106	e[33;1mZW_Send_Data node 30 NO ROUTE (nil)e[0m <0x2b85b680>
02	02/02/13 14:09:01.216	e[33;1mUPDATE MANUAL ROUTE2 30=(nil)e[0m <0x2b85b680>
02	02/02/13 14:09:01.216	e[33;1mZW_Send_Data node 30 NO ROUTE (nil)e[0m <0x2b85b680>
06	02/02/13 14:09:01.323	Device_Variable::m_szValue_set device: 333 service: urn:upnp-org:serviceId:SwitchPower1 variable: e[35;1mStatuse[0m was: 0 now: 1 #hooks: 4 upnp: 0 v:0xf5abf0/NONE duplicate:0 <0x2b45b680>
04	02/02/13 14:09:01.326	<Job ID="5" Name="ON node 30" Device="333" Created="2013-02-02 14:09:01" Started="2013-02-02 14:09:01" Completed="2013-02-02 14:09:01" Duration="0.222923000" Runtime="0.221086000" Status="Successful" LastNote="Transmit was ok" Node="30" NodeType="ZWaveNonDimmableLight" NodeDescription="Test1"/> <0x2b45b680>

{ "name": "!!Test1 Off", "groups": [ { "delay": 0, "actions": [ { "device": "333", "service": "urn:upnp-org:serviceId:SwitchPower1", "action": "SetTarget", "arguments": [ { "name": "newTargetValue", "value": "0" } ] } ] }, { "delay": 1, "actions": [ { "device": "333", "service": "urn:upnp-org:serviceId:SwitchPower1", "action": "SetTarget", "arguments": [ { "name": "newTargetValue", "value": "1" } ] } ] } ], "id": 58, "onDashboard": 0, "timers": [ { "id": 1, "name": "New schedule", "type": "4", "enabled": 1, "abstime": "2013-2-2 14:9:0", "last_run": 1359774540, "next_run": 1359774540 } ], "Timestamp": 1359774490, "room": 0 }

brientim · February 2, 2013, 3:39am

Forgot to answer the second part of your post:

I don't see the Job ID= anywhere in that. But I did see this, which looks interesting and does imply that the job ended, perhaps. Not sure what an alarm callback is.
08 02/01/13 14:00:00.122 JobHandler_LuaUPnP::AlarmCallback Ran scene:7 Pond Off / timer:Pond Off next at 1359831600 now 1359745200 <0x2ba27680>

The “AlarmCallback” is setting the last time the schedule event was executed and the next time it should be executed. This is the basis for the details contained in the Dashboard > Overview for both trigger and upcoming schedules…

beachboync · February 2, 2013, 3:15pm

Great into Brientim, thank you. This morning I am working on my other problem (the phantom scene) but will get back to this one ASAP.

beachboync · February 3, 2013, 8:00pm

Today it ran fine. Well, back burner for a while.

Bob

brientim · February 3, 2013, 10:48pm

Bob,

Hopefully it stay that way - working and running on schedule!