New plug-in (re-written from scratch) for OpenSprinkler, supporting zones, programs and more!

Set DebugMode parameter to 1 and post some logs.

Did that I still get the same “unable to send command” but clicking on Logs in the device it says “no logs found”

OK making some progress now. Still getting “no logs found” but I changed the default website in OSPi from port 808 to port 80 and reloaded LUUP and now I am no longer getting “unable to send command to the controller” And I am getting all of the Zones showing up in Devices as dimmable switches but they are showing up under “No Room” even though the OpenSprinkler device is showing up under Garage (the room I defined it in) I can go into a Zone and assign it to a room.
I do have 1 zone on the sprinkler that is not connected to a sprinkler valve and it is showing up as a device even though I disabled that zone in Open Sprinkler. I can move the slider back and forth on a zone in the Vera interface and it does not seem to turn on or off the sprinker

Logs are exposed in a different way => http://wiki.micasaverde.com/index.php/Logs

Port 80 is the default, or you can specify it with the IP in the format IP:port

Devices not are placed in any rooms; this is a known bug. I will probably fix it later.

Zones are offered as dimmers, so you can set how may minutes you want to run them. Disabled zones are not communicated via the API, so you have to hide the device manually. Get the device ID of the zone, then run this code

luup.attr_set("invisible", "1", id)

Logs are definitely helpful to understand why it’s not switching zone on/off.

Unfortunately the VeraPlus is 70 miles away and I don’t have the root password off the bottom of it with me. If there’s any tricks to getting the log printed out by doing an luup.call_action() in the run window I can do that but otherwise root access will have to wait until I’m out at the house next.

Also, you need to update the readme on github with

As device type, please insert
urn:schemas-upnp-org:device:BinaryLight:1

and as device_json
D_BinaryLight1.json

and it might be helpful to add that you can reload luup with the command

luup.call_action(“urn:micasaverde-com:serviceId:HomeAutomationGateway1”, “Reload”, {}, 0)

in the luup test window since the Vera does not provide a button to do it.

Device type is not mandatory. Luup reload con be called with luup.reload(). I will update the doc accordingly.

Here’s the logs I obtained them with the command:

http://172.16.100.135/cgi-bin/cmh/log.sh?Device=LuaUPnP

in a web browser from a machine that was on the same subnet at the site. Device 41 is one of the sprinkler zones. I first tried flipping the switch and then I tried moving the dimmer slider

08 05/20/20 7:16:14.050 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x7403b520>
08 05/20/20 7:16:14.051 JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x7403b520>
08 05/20/20 7:16:14.051 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x7403b520>
08 05/20/20 7:16:14.051 JobHandler_LuaUPnP::HandleActionRequest argument rand=0.7534559642162413 <0x7403b520>
02 05/20/20 7:16:14.051 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7403b520>
02 05/20/20 7:16:14.052 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:SwitchPower1/SetTarget failed with -911/Device not ready <0x7403b520>
08 05/20/20 7:16:16.692 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x7303b520>
08 05/20/20 7:16:16.692 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7303b520>
08 05/20/20 7:16:16.693 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x7303b520>
08 05/20/20 7:16:16.693 JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x7303b520>
08 05/20/20 7:16:16.693 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x7303b520>
08 05/20/20 7:16:16.693 JobHandler_LuaUPnP::HandleActionRequest argument rand=0.7534559642162413 <0x7303b520>
02 05/20/20 7:16:16.694 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7303b520>
02 05/20/20 7:16:16.694 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:SwitchPower1/SetTarget failed with -911/Device not ready <0x7303b520>
08 05/20/20 7:16:19.198 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x7403b520>
08 05/20/20 7:16:19.198 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7403b520>
08 05/20/20 7:16:19.198 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x7403b520>
08 05/20/20 7:16:19.199 JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x7403b520>
08 05/20/20 7:16:19.199 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x7403b520>
08 05/20/20 7:16:19.199 JobHandler_LuaUPnP::HandleActionRequest argument rand=0.7534559642162413 <0x7403b520>
02 05/20/20 7:16:19.199 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7403b520>
02 05/20/20 7:16:19.199 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:SwitchPower1/SetTarget failed with -911/Device not ready <0x7403b520>
08 05/20/20 7:16:21.657 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x7403b520>
08 05/20/20 7:16:21.658 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7403b520>
08 05/20/20 7:16:21.658 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x7403b520>
08 05/20/20 7:16:21.658 JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x7403b520>
08 05/20/20 7:16:21.658 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x7403b520>
08 05/20/20 7:16:21.659 JobHandler_LuaUPnP::HandleActionRequest argument rand=0.7534559642162413 <0x7403b520>
02 05/20/20 7:16:21.659 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7403b520>
02 05/20/20 7:16:21.659 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:SwitchPower1/SetTarget failed with -911/Device not ready <0x7403b520>
08 05/20/20 7:16:24.062 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x7303b520>
08 05/20/20 7:16:24.062 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7303b520>
08 05/20/20 7:16:24.062 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x7303b520>
08 05/20/20 7:16:24.063 JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x7303b520>
08 05/20/20 7:16:24.063 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=1 <0x7303b520>
08 05/20/20 7:16:24.063 JobHandler_LuaUPnP::HandleActionRequest argument rand=0.7534559642162413 <0x7303b520>
02 05/20/20 7:16:24.063 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7303b520>
02 05/20/20 7:16:24.063 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:SwitchPower1/SetTarget failed with -911/Device not ready <0x7303b520>
06 05/20/20 7:16:30.616 Device_Variable::m_szValue_set device: 28 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 62.94 now: 62.94 #hooks: 0 upnp: 0 skip: 0 v:0x10d33d0/NONE duplicate:1 <0x75a7c520>
06 05/20/20 7:16:30.616 Device_Variable::m_szValue_set device: 29 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 62.94 now: 62.94 #hooks: 0 upnp: 0 skip: 0 v:0x10d33d0/NONE duplicate:1 <0x75a7c520>
06 05/20/20 7:16:37.210 Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSensor1 variable: CurrentTemperature was: 64.00 now: 64.00 #hooks: 0 upnp: 0 skip: 0 v:0x10d33d0/NONE duplicate:1 <0x7667c520>
06 05/20/20 7:16:43.581 Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:HVAC_FanOperatingMode1 variable: Mode was: Auto now: Auto #hooks: 0 upnp: 0 skip: 0 v:0x10cba90/NONE duplicate:1 <0x7667c520>
06 05/20/20 7:16:45.701 Device_Variable::m_szValue_set device: 5 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 <0x7667c520>
06 05/20/20 7:16:45.702 Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSetpoint1_Heat variable: CurrentSetpoint was: 55.00 now: 55.00 #hooks: 0 upnp: 0 skip: 0 v:0x10e7208/NONE duplicate:1 <0x7667c520>
06 05/20/20 7:16:45.702 Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSetpoint1 variable: CurrentSetpoint was: 55.00 now: 55.00 #hooks: 0 upnp: 0 skip: 0 v:0x10e2f90/NONE duplicate:1 <0x7667c520>
06 05/20/20 7:16:45.702 Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSetpoint1 variable: AllSetpoints was: 55.00,70.00,62.50 now: 55.000000,70.000000,62.500000 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7667c520>
06 05/20/20 7:16:45.703 Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSetpoint1 variable: AllSetpoints was: 55.000000,70.000000,62.500000 now: 55.00,70.00,62.50 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7667c520>
06 05/20/20 7:16:47.825 Device_Variable::m_szValue_set device: 5 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 <0x7667c520>
06 05/20/20 7:16:47.826 Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSetpoint1_Cool variable: CurrentSetpoint was: 70.00 now: 70.00 #hooks: 0 upnp: 0 skip: 0 v:0x10e7c30/NONE duplicate:1 <0x7667c520>
06 05/20/20 7:16:47.826 Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSetpoint1 variable: AllSetpoints was: 55.00,70.00,62.50 now: 55.000000,70.000000,62.500000 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7667c520>
06 05/20/20 7:16:47.827 Device_Variable::m_szValue_set device: 5 service: urn:upnp-org:serviceId:TemperatureSetpoint1 variable: AllSetpoints was: 55.000000,70.000000,62.500000 now: 55.00,70.00,62.50 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7667c520>
04 05/20/20 7:16:47.828 <0x7667c520>
02 05/20/20 7:16:47.828 Device_Basic::AddPoll 5 poll list full, deleting old one <0x7667c520>
06 05/20/20 7:16:47.829 Device_Variable::m_szValue_set device: 5 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 <0x7667c520>
06 05/20/20 7:16:47.829 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastPollSuccess was: 1589984117 now: 1589984207 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7667c520>
06 05/20/20 7:16:47.829 Device_Variable::m_szValue_set device: 5 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: ConsecutivePollFails was: 0 now: 0 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x7667c520>
06 05/20/20 7:16:50.088 Device_Variable::m_szValue_set device: 28 service: urn:micasaverde-com:serviceId:ZigbeeDevice1 variable: VoltageLevel was: 30 now: 30 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x75a7c520>
06 05/20/20 7:16:50.088 Device_Variable::m_szValue_set device: 28 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryLevel was: 100 now: 100 #hooks: 0 upnp: 0 skip: 0 v:0x10bfef8/NONE duplicate:1 <0x75a7c520>
06 05/20/20 7:16:50.088 Device_Variable::m_szValue_set device: 28 service: urn:micasaverde-com:serviceId:HaDevice1 variable: BatteryDate was: 1589984134 now: 1589984210 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x75a7c520>
01 05/20/20 7:16:53.118 FileUtils::ReadURL 28/resp:0 user: pass: size 1 https://plugin1.mios.com/sync_plugins2.php?PK_AccessPoint=50020223&HW_Key=V989PZxhwKXOAVEberds66ZbQZ0nFTJs&Plugins=6196,8840,8942,7246,9231, response: <0x7687c520>
01 05/20/20 7:16:53.124 RAServerSync::SyncPlugins failed to sync https://plugin1.mios.com/sync_plugins2.php?PK_AccessPoint=50020223&HW_Key=V989PZxhwKXOAVEberds66ZbQZ0nFTJs&Plugins=6196,8840,8942,7246,9231, <0x7687c520>
02 05/20/20 7:16:53.125 UserData::AlarmCallback ALARM_RESYNC_DEVICES <0x7687c520>
02 05/20/20 7:16:53.777 RAServerSync::SyncDevice alt 0 response 200 url https://vera-us-oem-device12.mios.com/device/device/device/50020223/localdevices with 11257 bytes <0x7687c520>
06 05/20/20 7:16:53.853 Device_Variable::m_szValue_set device: 30 service: urn:upnp-micasaverde-com:serviceId:Weather1 variable: CurrentDewPoint was: 48.5 now: 48.7 #hooks: 0 upnp: 0 skip: 0 v:0x1185c88/NONE duplicate:0 <0x7527c520>
06 05/20/20 7:16:53.854 Device_Variable::m_szValue_set device: 30 service: urn:upnp-micasaverde-com:serviceId:Weather1 variable: LastUpdate was: 1589982413 now: 1589984213 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7527c520>
06 05/20/20 7:16:53.854 Device_Variable::m_szValue_set device: 30 service: urn:upnp-micasaverde-com:serviceId:Weather1 variable: CurrentWindSpeed was: 8.4 now: 8.5 #hooks: 0 upnp: 0 skip: 0 v:0x11672c0/NONE duplicate:0 <0x7527c520>
06 05/20/20 7:16:53.855 Device_Variable::m_szValue_set device: 30 service: urn:upnp-micasaverde-com:serviceId:Weather1 variable: CurrentOzone was: 358.2 now: 357.5 #hooks: 0 upnp: 0 skip: 0 v:0x1185820/NONE duplicate:0 <0x7527c520>
06 05/20/20 7:16:53.855 Device_Variable::m_szValue_set device: 30 service: urn:upnp-micasaverde-com:serviceId:Weather1 variable: CurrentCloudCover was: 89 now: 91 #hooks: 0 upnp: 0 skip: 0 v:0x1185c50/NONE duplicate:0 <0x7527c520>
06 05/20/20 7:16:53.856 Device_Variable::m_szValue_set device: 30 service: urn:upnp-micasaverde-com:serviceId:Weather1 variable: CurrentWindGust was: 11.8 now: 11.5 #hooks: 0 upnp: 0 skip: 0 v:0x1167858/NONE duplicate:0 <0x7527c520>
06 05/20/20 7:16:53.856 Device_Variable::m_szValue_set device: 30 service: urn:upnp-micasaverde-com:serviceId:Weather1 variable: CurrentWindBearing was: 274 now: 275 #hooks: 0 upnp: 0 skip: 0 v:0x1167200/NONE duplicate:0 <0x7527c520>
06 05/20/20 7:16:53.857 Device_Variable::m_szValue_set device: 30 service: urn:upnp-micasaverde-com:serviceId:Weather1 variable: CurrentTemperature was: 52.6 now: 52.8 #hooks: 0 upnp: 0 skip: 0 v:0x1185b20/NONE duplicate:0 <0x7527c520>
06 05/20/20 7:16:53.858 Device_Variable::m_szValue_set device: 30 service: urn:upnp-micasaverde-com:serviceId:Weather1 variable: CurrentApparentTemperature was: 52.6 now: 52.8 #hooks: 0 upnp: 0 skip: 0 v:0x1186570/NONE duplicate:0 <0x7527c520>
08 05/20/20 7:17:00.129 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7403b520>
08 05/20/20 7:17:00.130 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7403b520>
08 05/20/20 7:17:00.130 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7403b520>
08 05/20/20 7:17:00.130 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7403b520>
08 05/20/20 7:17:00.130 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7403b520>
02 05/20/20 7:17:00.130 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7403b520>
02 05/20/20 7:17:00.131 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7403b520>
08 05/20/20 7:17:01.050 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7403b520>
08 05/20/20 7:17:01.051 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7403b520>
08 05/20/20 7:17:01.051 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7403b520>
08 05/20/20 7:17:01.051 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7403b520>
08 05/20/20 7:17:01.051 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7403b520>
02 05/20/20 7:17:01.052 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7403b520>
02 05/20/20 7:17:01.052 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7403b520>
08 05/20/20 7:17:01.446 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:01.447 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7303b520>
08 05/20/20 7:17:01.447 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7303b520>
08 05/20/20 7:17:01.447 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:01.447 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7303b520>
02 05/20/20 7:17:01.447 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7303b520>
02 05/20/20 7:17:01.448 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7303b520>
08 05/20/20 7:17:02.377 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:02.377 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7303b520>
08 05/20/20 7:17:02.378 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7303b520>
08 05/20/20 7:17:02.378 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:02.378 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7303b520>
02 05/20/20 7:17:02.378 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7303b520>
02 05/20/20 7:17:02.378 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7303b520>
08 05/20/20 7:17:03.560 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:03.561 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7303b520>
08 05/20/20 7:17:03.561 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7303b520>
08 05/20/20 7:17:03.561 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:03.561 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7303b520>
02 05/20/20 7:17:03.562 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7303b520>
02 05/20/20 7:17:03.562 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7303b520>
08 05/20/20 7:17:03.960 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7403b520>
08 05/20/20 7:17:03.961 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7403b520>
08 05/20/20 7:17:03.961 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7403b520>
08 05/20/20 7:17:03.961 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7403b520>
08 05/20/20 7:17:03.962 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7403b520>
02 05/20/20 7:17:03.962 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7403b520>
02 05/20/20 7:17:03.962 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7403b520>
08 05/20/20 7:17:04.729 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7403b520>
08 05/20/20 7:17:04.729 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7403b520>
08 05/20/20 7:17:04.729 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7403b520>
08 05/20/20 7:17:04.729 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7403b520>
08 05/20/20 7:17:04.730 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7403b520>
02 05/20/20 7:17:04.730 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7403b520>
02 05/20/20 7:17:04.730 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7403b520>
08 05/20/20 7:17:06.060 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7403b520>
08 05/20/20 7:17:06.060 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7403b520>
08 05/20/20 7:17:06.060 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7403b520>
08 05/20/20 7:17:06.060 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7403b520>
08 05/20/20 7:17:06.061 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7403b520>
02 05/20/20 7:17:06.061 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7403b520>
02 05/20/20 7:17:06.061 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7403b520>
08 05/20/20 7:17:06.457 JobHandler_LuaUPnP::HandleActionRequest device: 43 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:06.457 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=43 <0x7303b520>
08 05/20/20 7:17:06.457 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7303b520>
08 05/20/20 7:17:06.458 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:06.458 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=0 <0x7303b520>
02 05/20/20 7:17:06.458 Device_LuaUPnP::HandleActionRequest 43 not ready 0x109faa0 <0x7303b520>
02 05/20/20 7:17:06.458 JobHandler_LuaUPnP::RunAction device 43 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7303b520>
08 05/20/20 7:17:06.551 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:06.551 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7303b520>
08 05/20/20 7:17:06.551 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7303b520>
08 05/20/20 7:17:06.551 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:06.552 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7303b520>
02 05/20/20 7:17:06.552 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7303b520>
02 05/20/20 7:17:06.552 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7303b520>
08 05/20/20 7:17:07.079 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:07.079 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7303b520>
08 05/20/20 7:17:07.080 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7303b520>
08 05/20/20 7:17:07.080 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:07.080 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7303b520>
02 05/20/20 7:17:07.080 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7303b520>
02 05/20/20 7:17:07.081 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7303b520>
04 05/20/20 7:17:07.586 <0x7667c520>
02 05/20/20 7:17:07.586 Device_Basic::AddPoll 9 poll list full, deleting old one <0x7667c520>
06 05/20/20 7:17:07.587 Device_Variable::m_szValue_set device: 9 service: urn:micasaverde-com:serviceId:HaDevice1 variable: PollRatings was: 4.90 now: 5.00 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7667c520>
06 05/20/20 7:17:07.588 Device_Variable::m_szValue_set device: 9 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastPollSuccess was: 1589984137 now: 1589984227 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x7667c520>
06 05/20/20 7:17:07.588 Device_Variable::m_szValue_set device: 9 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: ConsecutivePollFails was: 0 now: 0 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x7667c520>
08 05/20/20 7:17:08.565 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:08.565 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7303b520>
08 05/20/20 7:17:08.565 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7303b520>
08 05/20/20 7:17:08.565 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:08.566 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7303b520>
02 05/20/20 7:17:08.566 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7303b520>
02 05/20/20 7:17:08.566 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7303b520>
08 05/20/20 7:17:08.969 JobHandler_LuaUPnP::HandleActionRequest device: 41 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:08.969 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=41 <0x7303b520>
08 05/20/20 7:17:08.969 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:Dimming1 <0x7303b520>
08 05/20/20 7:17:08.969 JobHandler_LuaUPnP::HandleActionRequest argument action=SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:08.970 JobHandler_LuaUPnP::HandleActionRequest argument newLoadlevelTarget=47 <0x7303b520>
02 05/20/20 7:17:08.970 Device_LuaUPnP::HandleActionRequest 41 not ready 0x109faa0 <0x7303b520>
02 05/20/20 7:17:08.970 JobHandler_LuaUPnP::RunAction device 41 action urn:upnp-org:serviceId:Dimming1/SetLoadLevelTarget failed with -911/Device not ready <0x7303b520>
08 05/20/20 7:17:09.064 JobHandler_LuaUPnP::HandleActionRequest device: 43 service: urn:upnp-org:serviceId:Dimming1 action: SetLoadLevelTarget <0x7303b520>
08 05/20/20 7:17:09.065 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=43

DebugMode is set to 1? Can you please post a screenshot of the mater device Params? (under Advanced, then Params in device’s details). Thanks.


Device seems to be configured ok, but logs are not showing. I need verbose logs in order to help you, I’m sorry.

How do I get it to create verbose logs?
Can I just mod the XML file to turn on verbose debugging and upload it
if a verbose log is produced where is it saved in the filesystem?
I’ll be at the house this weekend and can deal with this.
Also I could port-forward the open sprinkler pi to a public IP and lock it down so you could access it if you want to see if the responses from the pi differ than from the regular open sprinkler.

Verbose logging is enabled if you set DebugMode to 1. Look under Variables on the master device. No need to reset anything. Also, do you install the store version, or the GitHub one? Because the GitHub one is more fresh.

I don’t need access to the PI, just PM me the output of ja?pw=a6d82bced638de3def1e9bbb4983225c
If you changed the password from the default, you have to specify it under your configuration and in the call I posted above.

DebugMode was indeed set to 1 as per your earlier instructions. Where in the Vera is the verbose log saved?

I am using the GitHub one as I stated.

I have not changed the password on the Pi from the default

" just PM me the output of ja?pw=a6d82bced638de3def1e9bbb4983225c"

That I completely do not understand. I do not have telnet or ssh setup on the pi I would have to run any command on the pi by logging in at the console. Is this a pi console command? Is it a luup command?

Verbose Logs are inside Vera logs. All plugins are writing their logs here. To be sure it’s running OK, just do a luup.reload() and get the the logs from the SSH windows while you’re there.

ja is an HTTP endpoint for your opensprinkler. something like http://yourPIIP/ja?pw=a6d82bced638de3def1e9bbb4983225c

I just published a minor revision on github. This should prevent a restart loop in race conditions, experienced by some users.

I just published another version, to fix other things in the backlog (public holiday from Saturday to Tuesday here in Italy).

So, version 1.4:

  • definitely fixes all the reboots/reloads/strange behaviors
  • introduce the ability (on by default) for the children to follow its master room (via the standard ChildrenSameRoom attribute, set to 0 if you want to have children in other rooms)
  • better handle different responses

Overall, this version should improve your controller stability.
Please, let me know if you happen to test it. Thanks!

Hi I get the following no joy from /tmp/log/cmh/LuaUPnP.log after doing a luup.reload() with the new file:

50 06/03/20 21:34:54.329 luup_log:37: VeraOpenSprinkler Controller Plug-In starting… <0x76792520>
50 06/03/20 21:34:54.351 luup_log:37: VeraOpenSprinkler[1.4.1]: Plugin starting: “VeraOpenSprinkler” - “1.4.1” <0x76792520>
50 06/03/20 21:34:54.353 luup_log:37: VeraOpenSprinkler1.4.1: updateFromController started: true <0x76792520>
50 06/03/20 21:34:54.354 luup_log:37: VeraOpenSprinkler1.4.1: sendDeviceCommand(“ja”,nil,37) <0x76792520>
50 06/03/20 21:34:54.355 luup_log:37: VeraOpenSprinkler1.4.1: sendDeviceCommand - url: “http://172.16.100.107/ja?&pw=a6d82bced638de3def1e9bbb4983225c” <0x76792520>
50 06/03/20 21:34:54.396 luup_log:37: VeraOpenSprinkler1.4.1: HttpGet: “http://172.16.100.107/ja?&pw=a6d82bced638de3def1e9bbb4983225c” - 1 - “200” - "{"settings":{"devt":1591230894,"nbrd":1,"en":1,"sn1":0,"sn2":0,"rd":0,"rdst":0,"sunrise":310,"sunset":1217,"eip":788989956,"lwc":1591224050,"lswc":1591224050,"lupt":0,"lrbtc":5,"lrun":[2,99,300,1589968429],"loc":"42.36,-71.06","jsp":"https://ui.opensprinkler.com/js\“,\“wsp\”:\“weather.opensprinkler.com\”,\“wto\”:{\“key\”:\”\“},\“ifkey\”:\”\“,\“wtdata\”:{\“wp\”:\“Manual\”},\“wterr\”:0,\“sbits\”:[0,0],\“ps\”:[[0,0,0],[0,0,0],[0,0,0],[0,0,0],[0,0,0],[0,0,0],[0,0,0],[0,0,0]]},\“programs\”:{\“nprogs\”:0,\“nboards\”:1,\“mnp\”:40,\“mnst\”:4,\“pnsize\”:32,\“pd\”:[]},\“options\”:{\“fwv\”:219,\“tz\”:32,\“hp0\”:80,\“hp1\”:0,\“hwv\”:64,\“ext\”:0,\“sdt\”:0,\“mas\”:0,\“mton\”:0,\“mtof\”:0,\“wl\”:100,\“den\”:1,\“ipas\”:0,\“devid\”:0,\“uwt\”:0,\“ntp1\”:0,\“ntp2\”:0,\“ntp3\”:0,\“ntp4\”:0,\“lg\”:1,\“mas2\”:0,\“mton2\”:0,\“mtof2\”:0,\“fwm\”:3,\“fpr0\”:100,\“fpr1\”:0,\“re\”:0,\“sar\”:0,\“ife\”:0,\“sn1t\”:1,\“sn1o\”:0,\“sn1on\”:0,\“sn1of\”:0,\“wimod\”:169,\“reset\”:0,\“dexp\”:-1,\“mexp\”:24,\“hwt\”:255},\“status\”:{\“sn\”:[0,0,0,0,0,0,0,0],\“nstations\”:8}” <0x76792520>
50 06/03/20 21:34:54.404 luup_log:37: VeraOpenSprinkler1.4.1: Discovery in progress… <0x76792520>
50 06/03/20 21:34:54.405 luup_log:37: VeraOpenSprinkler1.4.1: ChildrenSameRoom: true, #2 <0x76792520>
50 06/03/20 21:34:54.405 luup_log:37: VeraOpenSprinkler1.4.1: Discovery 1/3 in progress… <0x76792520>
01 06/03/20 21:34:54.406 LuaInterface::CallFunction_Startup-1 device 37 function startupPlugin failed [string “module(“L_VeraOpenSprinkler1”, package.seea…”]:284: attempt to index local ‘jsonResponse’ (a nil value) <0x76792520>
01 06/03/20 21:34:54.406 LuImplementation::StartLua running startup code for 37 I_VeraOpenSprinkler1.xml failed <0x76792520>
03 06/03/20 21:34:54.407 JobHandler_LuaUPnP::m_bReloadCriticalOnly_set now 1 <0x76792520>
02 06/03/20 21:34:54.407 JobHandler_LuaUPnP::AutoInstallPlugins plugin 9092:(null) is blacklisted, skipping <0x76792520>
02 06/03/20 21:34:54.407 JobHandler_LuaUPnP::AutoInstallPlugins plugin 9284:(null) is blacklisted, skipping <0x76792520>
03 06/03/20 21:34:54.407 JobHandler_LuaUPnP::m_bReloadCriticalOnly_set now 0 <0x76792520>

Here is the output of http://172.16.100.107/ja?pw=a6d82bced638de3def1e9bbb4983225c

{“settings”:{“devt”:1591231256,“nbrd”:1,“en”:1,“sn1”:0,“sn2”:0,“rd”:0,“rdst”:0,“sunrise”:310,“sunset”:1217,“eip”:788989956,“lwc”:1591224050,“lswc”:1591224050,“lupt”:0,“lrbtc”:5,“lrun”:[2,99,300,1589968429],“loc”:“42.36,-71.06”,“jsp”:“https://ui.opensprinkler.com/js",“wsp”:“weather.opensprinkler.com”,“wto”:{“key”:“”},“ifkey”:“”,“wtdata”:{“wp”:“Manual”},“wterr”:0,“sbits”:[0,0],“ps”:[[0,0,0],[0,0,0],[0,0,0],[0,0,0],[0,0,0],[0,0,0],[0,0,0],[0,0,0]]},“programs”:{“nprogs”:0,“nboards”:1,“mnp”:40,“mnst”:4,“pnsize”:32,“pd”:[]},“options”:{“fwv”:219,“tz”:32,“hp0”:80,“hp1”:0,“hwv”:64,“ext”:0,“sdt”:0,“mas”:0,“mton”:0,“mtof”:0,“wl”:100,“den”:1,“ipas”:0,“devid”:0,“uwt”:0,“ntp1”:0,“ntp2”:0,“ntp3”:0,“ntp4”:0,“lg”:1,“mas2”:0,“mton2”:0,“mtof2”:0,“fwm”:3,“fpr0”:100,“fpr1”:0,“re”:0,“sar”:0,“ife”:0,“sn1t”:1,“sn1o”:0,“sn1on”:0,“sn1of”:0,“wimod”:169,“reset”:0,“dexp”:-1,“mexp”:24,“hwt”:255},“status”:{“sn”:[0,0,0,0,0,0,0,0],“nstations”:8},“stations”:{“masop”:[255],“masop2”:[0],“ignore_rain”:[0],“ignore_sn1”:[0],“ignore_sn2”:[0],“stn_dis”:[128],“stn_seq”:[255],“stn_spe”:[0],“snames”:[“NorthGardenSideLawn”,“NorthWestBackyard”,“SouthBackyard”,“SouthSideLawn”,“SouthGardenAndPorch”,“NorthEastBackyard”,“SouthBackyardHedge”,“S08”],"maxlen”:32}}

One thing I can say is this - at some point a version I was testing DID populate the sprinkler zones. (so I presume it made it though discovery) However I have attempted to revert all the way back to version 1.1.0 and I’m getting the same error

One other thing I can add - I finally just deleted all of the opensprinkler luup files and the device and and installed the version from the app store. This one gives the exact same error in the log - here it is:

50 06/04/20 1:25:09.524 luup_log:51: VeraOpenSprinkler Controller Plug-In starting… <0x77478520>
50 06/04/20 1:25:09.546 luup_log:51: VeraOpenSprinkler[1.3.1]: Plugin starting: “VeraOpenSprinkler” - “1.3.1” <0x77478520>
01 06/04/20 1:25:09.595 LuaInterface::CallFunction_Startup-1 device 51 function startupPlugin failed [string “module(“L_VeraOpenSprinkler1”, package.seea…”]:439: attempt to index local ‘jsonResponse’ (a nil value) <0x77478520>
01 06/04/20 1:25:09.595 LuImplementation::StartLua running startup code for 51 I_VeraOpenSprinkler1.xml failed <0x77478520>
03 06/04/20 1:25:09.596 JobHandler_LuaUPnP::m_bReloadCriticalOnly_set now 1 <0x77478520>

But one huge difference is that the appstore one is showing red error messages and the logs in the Vera interface. So that says: “username or password not set”

In reading up on dkjson the author says in it’s default config there’s no global variables - would possibly the problem be that the “local json = require(“dkjson”)” should be just a “json = require(“dkjson”)” In looking at the opensprinkler code and the bit of testing I’ve done so far the discovery function seems to have no call to populate the jsonResponse variable as that variable is empty (a null) when the discovery function runs. (thus the error that blows it up)

yep, that’s strange, I’m working on it. do not use previous versions, because they all had the same problem. jsonResponse is null because it’s not able to decode the json output.

I’ve now updated a new version (and opened a new post on OpenSprinkler’s forum, in order to understand why lua is getting a different response than the one you posted). If you have time, @TedM please try it, since I cannot repro on my system. At its best, it should not crash and report if anything is wrong/missing.

I uploaded version 142 to vera and restarted luup and this time there was no json error. I set the parent device to reconfigure and it created all of the zones as devices in the vera. I have not tried turning on and off the sprinklers though since we have people in the house this weekend and I don’t want to get anyone who is in the yard wet. I’ll experiment later tonight when they are inside.

One thing the log shows that is interesting is after the first reconfiguration OpenSprinkler issued the error:

Got a nil respose (I think you have a spelling error there :wink: ) from API or error: “unterminated object at line 1, column 1”

But then 10 seconds later it did the HttpGet again and this time there was no error - and the log showed that it created a device for Zone 1 right after that. I am wondering if maybe the http response is so large from OpenSprinkler Pi that parts of it are being lost somewhere??