Delay on Zwave execution after command sent using MIOS Binding

ubergeek · October 19, 2015, 11:41pm

Not sure if this is a MIOS problem or just a Vera issue

Everything had been working fine and recently have noticed a significant delay in the zwave device turning on/off after command issued through openhab (10-20 seconds)

Noticed some strange behavior in the log as well, any ideas?

2015-10-19 19:34:44.628 [INFO ] [runtime.busevents ] - SwitchingPluginStatus received command OFF
2015-10-19 19:34:55.602 [INFO ] [runtime.busevents ] - PANEL_MESSAGE state updated to 500: A command has been received successfully.
2015-10-19 19:34:55.603 [INFO ] [runtime.busevents ] - PANEL_CONNECTION state updated to 1
2015-10-19 19:35:03.783 [INFO ] [runtime.busevents ] - SwitchingPluginStatus received command ON

Then a little bit later…(nothing happens in log)

2015-10-19 19:35:18.736 [INFO ] [runtime.busevents ] - SwitchingPluginDeviceStatus state updated to PENDING
2015-10-19 19:35:18.740 [INFO ] [runtime.busevents ] - SwitchingPluginTarget state updated to 0
2015-10-19 19:35:18.743 [INFO ] [runtime.busevents ] - SwitchingPluginId state updated to 3
2015-10-19 19:35:19.150 [INFO ] [runtime.busevents ] - SwitchingPluginDeviceStatus state updated to SUCCESS
2015-10-19 19:35:19.151 [INFO ] [runtime.busevents ] - SwitchingPluginStatus state updated to OFF
2015-10-19 19:35:19.152 [INFO ] [runtime.busevents ] - SwitchingPluginId state updated to 3
2015-10-19 19:35:48.701 [INFO ] [runtime.busevents ] - BedroomTstatLastPollSuccess state updated to 1445297748
2015-10-19 19:35:48.704 [INFO ] [runtime.busevents ] - BedroomTstatId state updated to 13
2015-10-19 19:35:50.873 [INFO ] [runtime.busevents ] - SwitchingPluginDeviceStatus state updated to NONE

Notice the commands on and off did not occur when I initially issued them, but instead executed all together in one second after a 10-20 second delay

guessed · October 26, 2015, 2:47am

That’s really odd. I fire up a thread to send the outbound Commands to the MiOS Devices, so that part of the delivery should be nearly instant.

Can you enable TRACE mode for the MiOS Binding in configurations/logback.xml, and provide the same trace?

It’ll be a configuration line like:

   <logger name="org.openhab.binding.mios" level="TRACE" />

You’ll want to limit the length of time you run in that mode, since it’ll generate a lot of output from the MiOS Binding.

If you have any Rules on this Item, then provide those also, but more importantly the Item definition itself for MiOS Device Id=3 (opehHAB Item SwitchingPluginStatus)

PS: sorry for the delay, I didn’t notice this post. If you use @guessed, or tag it with mios, then it’ll get my attn more directly.

ubergeek · October 26, 2015, 3:02am

Thanks for the reply mark…will make sure to tag you net time right away

heres the log after firing the off command

oops…sorry here’s the formatted log, again

2015-10-25 23:00:53.014 [INFO ] [runtime.busevents             ] - SwitchingPluginStatus received command OFF
2015-10-25 23:01:03.144 [DEBUG] [b.m.internal.MiosUnitConnector] - processResponse: success! loadTime=1445646973, dataVersion=646979400 devices(1) scenes(0) rooms(0) sections(0)
2015-10-25 23:01:03.146 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,device:3/PendingJobs"}, value=0
2015-10-25 23:01:03.147 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Using_2G"}, value=0
2015-10-25 23:01:03.147 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LoadTime"}, value=2015-10-23T20:36:13
2015-10-25 23:01:03.147 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/DataVersion"}, value=646979400
2015-10-25 23:01:03.147 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/UserData_DataVersion"}, value=646973056
2015-10-25 23:01:03.147 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/TimeStamp"}, value=2015-10-25T23:01:05
2015-10-25 23:01:03.147 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_on"}, value=0
2015-10-25 23:01:03.147 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_off"}, value=0
2015-10-25 23:01:03.147 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_locked"}, value=0
2015-10-25 23:01:03.148 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_unlocked"}, value=1
2015-10-25 23:01:03.148 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_tripped"}, value=0
2015-10-25 23:01:03.148 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_not_tripped"}, value=0
2015-10-25 23:01:03.148 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/failed_devices"}, value=0
2015-10-25 23:01:03.148 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/visible_devices"}, value=8
2015-10-25 23:01:03.148 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_active"}, value=0
2015-10-25 23:01:03.148 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_notactive"}, value=0
2015-10-25 23:01:03.148 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/ZWaveStatus"}, value=1
2015-10-25 23:01:03.148 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Mode"}, value=1
2015-10-25 23:01:03.148 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LocalTime"}, value=2015-10-25 23:01:05 N
2015-10-25 23:01:03.149 [DEBUG] [b.m.internal.MiosUnitConnector] - run: URI Built was 'http://192.168.20.35:3480/data_request?id=status2&LoadTime=1445646973&DataVersion=646979400&Timeout=40&MinimumDelay=0' loop '51099'
2015-10-25 23:01:03.189 [DEBUG] [b.m.internal.MiosUnitConnector] - processResponse: success! loadTime=1445646973, dataVersion=646979403 devices(1) scenes(0) rooms(0) sections(0)
2015-10-25 23:01:03.189 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,device:3/PendingJobs"}, value=0
2015-10-25 23:01:03.190 [TRACE] [.b.m.i.MiosBindingProviderImpl] - getItemNamesForProperty: MATCH property 'unit:savannah,device:3/status' against BindingConfig.toProperty 'unit:savannah,device:3/status'
2015-10-25 23:01:03.190 [TRACE] [b.m.i.config.MiosBindingConfig] - createState: Converted 'SUCCESS' to 'org.openhab.core.library.types.StringType', bound to 'class org.openhab.core.library.items.StringItem'
2015-10-25 23:01:03.190 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: transformation performed, from '4' to 'SUCCESS'
2015-10-25 23:01:03.190 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Incr) Updating 'SwitchingPluginDeviceStatus {mios="unit:savannah,device:3/status"}' to 'SUCCESS'
2015-10-25 23:01:03.190 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND {mios="unit:savannah,device:3/status"}, value=SUCCESS, bound 1 time(s)
2015-10-25 23:01:03.190 [TRACE] [.b.m.i.MiosBindingProviderImpl] - getItemNamesForProperty: MATCH property 'unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Status' against BindingConfig.toProperty 'unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Status'
2015-10-25 23:01:03.190 [TRACE] [.o.b.mios.internal.MiosBinding] - internalReceiveUpdate: itemName 'SwitchingPluginDeviceStatus', newState 'SUCCESS', class 'class org.openhab.core.library.types.StringType'
2015-10-25 23:01:03.192 [TRACE] [b.m.i.config.MiosBindingConfig] - createState: Converted 'OFF' to 'org.openhab.core.library.types.OnOffType', bound to 'class org.openhab.core.library.items.SwitchItem'
2015-10-25 23:01:03.197 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: transformation performed, from '0' to 'OFF'
2015-10-25 23:01:03.197 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Incr) Updating 'SwitchingPluginStatus {mios="unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Status"}' to 'OFF'
2015-10-25 23:01:03.197 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND {mios="unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Status"}, value=OFF, bound 1 time(s)
2015-10-25 23:01:03.198 [TRACE] [.b.m.i.MiosBindingProviderImpl] - getItemNamesForProperty: MATCH property 'unit:savannah,device:3/id' against BindingConfig.toProperty 'unit:savannah,device:3/id'
2015-10-25 23:01:03.198 [TRACE] [b.m.i.config.MiosBindingConfig] - createState: Converted '3' to 'org.openhab.core.library.types.DecimalType', bound to 'class org.openhab.core.library.items.NumberItem'
2015-10-25 23:01:03.198 [TRACE] [b.m.i.config.MiosBindingConfig] - transformIn: Converted value '3' from StringType to more scoped type 'class org.openhab.core.library.types.DecimalType'
2015-10-25 23:01:03.198 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: transformation performed, from '3' to '3'
2015-10-25 23:01:03.199 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Incr) Updating 'SwitchingPluginId {mios="unit:savannah,device:3/id"}' to '3'
2015-10-25 23:01:03.199 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND {mios="unit:savannah,device:3/id"}, value=3, bound 1 time(s)
2015-10-25 23:01:03.199 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Using_2G"}, value=0
2015-10-25 23:01:03.199 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LoadTime"}, value=2015-10-23T20:36:13
2015-10-25 23:01:03.199 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/DataVersion"}, value=646979403
2015-10-25 23:01:03.199 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/UserData_DataVersion"}, value=646973056
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/TimeStamp"}, value=2015-10-25T23:01:05
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_on"}, value=0
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_off"}, value=0
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_locked"}, value=0
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_unlocked"}, value=1
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_tripped"}, value=0
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_not_tripped"}, value=0
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/failed_devices"}, value=0
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/visible_devices"}, value=8
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_active"}, value=0
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_notactive"}, value=0
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/ZWaveStatus"}, value=1
2015-10-25 23:01:03.200 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Mode"}, value=1
2015-10-25 23:01:03.196 [INFO ] [runtime.busevents             ] - SwitchingPluginDeviceStatus state updated to SUCCESS
2015-10-25 23:01:03.202 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LocalTime"}, value=2015-10-25 23:01:05 N
2015-10-25 23:01:03.204 [TRACE] [.o.b.mios.internal.MiosBinding] - internalReceiveUpdate: itemName 'SwitchingPluginStatus', newState 'OFF', class 'class org.openhab.core.library.types.OnOffType'
2015-10-25 23:01:03.205 [INFO ] [runtime.busevents             ] - SwitchingPluginStatus state updated to OFF
2015-10-25 23:01:03.206 [TRACE] [.o.b.mios.internal.MiosBinding] - internalReceiveUpdate: itemName 'SwitchingPluginId', newState '3', class 'class org.openhab.core.library.types.DecimalType'
2015-10-25 23:01:03.206 [INFO ] [runtime.busevents             ] - SwitchingPluginId state updated to 3
2015-10-25 23:01:03.204 [DEBUG] [b.m.internal.MiosUnitConnector] - run: URI Built was 'http://192.168.20.35:3480/data_request?id=status2&LoadTime=1445646973&DataVersion=646979403&Timeout=40&MinimumDelay=0' loop '51100'
2015-10-25 23:01:08.498 [INFO ] [runtime.busevents             ] - PANEL_MESSAGE state updated to 500: A command has been received successfully.
2015-10-25 23:01:08.499 [INFO ] [runtime.busevents             ] - PANEL_CONNECTION state updated to 1

guessed · October 26, 2015, 3:19am

Do you mind editing the post above and putting the following around it:
```log
your log output here
```

The 3x back-quote chars will make the post a ton easier on the eyes (and I suspect we’ll have a few more iterations.

Anyhow, what version of the MiOS Binding are you using?

Also, I’m guessing you’re on UI7, since there’s a bunch of extra Attrs I’m not used to seeing at the system level… can you confirm?

ubergeek · October 26, 2015, 3:40am

Using mios binding 1.7.1 and yes UI7, haven’t restarted the vera yet to see if that fixes

guessed · October 26, 2015, 3:53am

That’s really odd. I can see the calls to get the Meta from Vera, but the outbound call indicating the Command, and that data being sent to Vera, is completely missing from the log snippet.

It’s the logs from callDevice & callMios that are completely missing from the openhab.log snippet:

github.com

openhab/openhab1-addons/blob/master/bundles/binding/org.openhab.binding.mios/src/main/java/org/openhab/binding/mios/internal/MiosUnitConnector.java

/**
 * Copyright (c) 2010-2016 by the respective copyright holders.
 *
 * All rights reserved. This program and the accompanying materials
 * are made available under the terms of the Eclipse Public License v1.0
 * which accompanies this distribution, and is available at
 * http://www.eclipse.org/legal/epl-v10.html
 */
package org.openhab.binding.mios.internal;

import java.io.IOException;
import java.io.UnsupportedEncodingException;
import java.net.URLEncoder;
import java.util.ArrayList;
import java.util.Calendar;
import java.util.HashMap;
import java.util.List;
import java.util.Locale;
import java.util.Map;
import java.util.Map.Entry;

This file has been truncated. show original

Looks like you’re using the hot-reload functionality of the logging sub-system. You may need to restart openHAB to get it to load correctly and get the required output.

PS: It’s 3x back-quote chars like - ` On a Mac, it’s typically the key in the upper Left (same key used for the tilde character ~)

ubergeek · October 26, 2015, 3:57am

thanks for the snippet tutorial, I’m learning…will restart and report back

2015-10-26 00:23:11.441 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalReceiveCommand: itemName 'SwitchingPluginStatus', command 'OFF'
2015-10-26 00:23:11.450 [TRACE] [.o.b.mios.internal.MiosBinding] - getMiosUnitName: start itemName 'SwitchingPluginStatus'
2015-10-26 00:23:11.460 [TRACE] [.o.b.mios.internal.MiosBinding] - getMiosConnector: start unitName 'savannah'
2015-10-26 00:23:11.463 [DEBUG] [b.m.internal.MiosUnitConnector] - callDevice: Need to remote-invoke Device 'unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Status' action 'OFF' and current state 'ON')
2015-10-26 00:23:11.464 [DEBUG] [b.m.internal.MiosUnitConnector] - callDevice: decoded as serviceName 'urn:upnp-org:serviceId:SwitchPower1' serviceAction 'SetTarget' serviceParam 'newTargetValue' serviceValue '0'
2015-10-26 00:23:11.483 [DEBUG] [b.m.internal.MiosUnitConnector] - callMios: Would like to fire off the URL 'http://192.168.20.35:3480/data_request?id=action&DeviceNum=3&serviceId=urn%3Aupnp-org%3AserviceId%3ASwitchPower1&action=SetTarget&newTargetValue=0'
2015-10-26 00:23:22.952 [DEBUG] [b.m.internal.MiosUnitConnector] - processResponse: success! loadTime=1445646973, dataVersion=646979619 devices(1) scenes(0) rooms(0) sections(0)
2015-10-26 00:23:22.953 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,device:14/PendingJobs"}, value=0
2015-10-26 00:23:22.956 [TRACE] [.b.m.i.MiosBindingProviderImpl] - getItemNamesForProperty: MATCH property 'unit:savannah,device:14/service/urn:micasaverde-com:serviceId:ZWaveNetwork1/LastPollSuccess' against BindingConfig.toProperty 'unit:savannah,device:14/service/urn:micasaverde-com:serviceId:ZWaveNetwork1/LastPollSuccess'
2015-10-26 00:23:22.957 [TRACE] [b.m.i.config.MiosBindingConfig] - createState: Converted '1445833404' to 'org.openhab.core.library.types.StringType', bound to 'class org.openhab.core.library.items.StringItem'
2015-10-26 00:23:22.957 [TRACE] [b.m.i.config.MiosBindingConfig] - transformIn: Converted value '1445833404' from StringType to more scoped type 'class org.openhab.core.library.types.StringType'
2015-10-26 00:23:22.958 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: transformation performed, from '1445833404' to '1445833404'
2015-10-26 00:23:22.958 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Incr) Updating 'MainTstatLastPollSuccess {mios="unit:savannah,device:14/service/urn:micasaverde-com:serviceId:ZWaveNetwork1/LastPollSuccess"}' to '1445833404'
2015-10-26 00:23:22.959 [TRACE] [.o.b.mios.internal.MiosBinding] - internalReceiveUpdate: itemName 'MainTstatLastPollSuccess', newState '1445833404', class 'class org.openhab.core.library.types.StringType'
2015-10-26 00:23:22.965 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND {mios="unit:savannah,device:14/service/urn:micasaverde-com:serviceId:ZWaveNetwork1/LastPollSuccess"}, value=1445833404, bound 1 time(s)
2015-10-26 00:23:22.976 [TRACE] [.b.m.i.MiosBindingProviderImpl] - getItemNamesForProperty: MATCH property 'unit:savannah,device:14/id' against BindingConfig.toProperty 'unit:savannah,device:14/id'
2015-10-26 00:23:22.978 [TRACE] [b.m.i.config.MiosBindingConfig] - createState: Converted '14' to 'org.openhab.core.library.types.DecimalType', bound to 'class org.openhab.core.library.items.NumberItem'
2015-10-26 00:23:22.979 [TRACE] [b.m.i.config.MiosBindingConfig] - transformIn: Converted value '14' from StringType to more scoped type 'class org.openhab.core.library.types.DecimalType'
2015-10-26 00:23:22.979 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: transformation performed, from '14' to '14'
2015-10-26 00:23:22.980 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Incr) Updating 'MainTstatId {mios="unit:savannah,device:14/id"}' to '14'
2015-10-26 00:23:22.980 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND {mios="unit:savannah,device:14/id"}, value=14, bound 1 time(s)
2015-10-26 00:23:22.980 [TRACE] [.o.b.mios.internal.MiosBinding] - internalReceiveUpdate: itemName 'MainTstatId', newState '14', class 'class org.openhab.core.library.types.DecimalType'
2015-10-26 00:23:22.981 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Using_2G"}, value=0
2015-10-26 00:23:22.982 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LoadTime"}, value=2015-10-23T20:36:13
2015-10-26 00:23:22.985 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/DataVersion"}, value=646979619
2015-10-26 00:23:22.987 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/UserData_DataVersion"}, value=646973057
2015-10-26 00:23:22.989 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/TimeStamp"}, value=2015-10-26T00:23:24
2015-10-26 00:23:22.989 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_on"}, value=0
2015-10-26 00:23:22.989 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_off"}, value=0
2015-10-26 00:23:22.990 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_locked"}, value=0
2015-10-26 00:23:22.990 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_unlocked"}, value=1
2015-10-26 00:23:22.991 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_tripped"}, value=0
2015-10-26 00:23:22.991 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_not_tripped"}, value=0
2015-10-26 00:23:22.992 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/failed_devices"}, value=0
2015-10-26 00:23:22.992 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/visible_devices"}, value=8
2015-10-26 00:23:22.992 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_active"}, value=0
2015-10-26 00:23:22.993 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_notactive"}, value=0
2015-10-26 00:23:22.994 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/ZWaveStatus"}, value=1
2015-10-26 00:23:22.995 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Mode"}, value=1
2015-10-26 00:23:22.999 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LocalTime"}, value=2015-10-26 00:23:24 N
2015-10-26 00:23:23.001 [DEBUG] [b.m.internal.MiosUnitConnector] - run: URI Built was 'http://192.168.20.35:3480/data_request?id=status2&LoadTime=1445646973&DataVersion=646979619&Timeout=40&MinimumDelay=0' loop '50'
2015-10-26 00:23:23.020 [DEBUG] [b.m.internal.MiosUnitConnector] - processResponse: success! loadTime=1445646973, dataVersion=646979625 devices(1) scenes(0) rooms(0) sections(0)
2015-10-26 00:23:23.021 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,device:3/PendingJobs"}, value=0
2015-10-26 00:23:23.022 [TRACE] [.b.m.i.MiosBindingProviderImpl] - getItemNamesForProperty: MATCH property 'unit:savannah,device:3/status' against BindingConfig.toProperty 'unit:savannah,device:3/status'
2015-10-26 00:23:23.024 [TRACE] [b.m.i.config.MiosBindingConfig] - createState: Converted 'PENDING' to 'org.openhab.core.library.types.StringType', bound to 'class org.openhab.core.library.items.StringItem'
2015-10-26 00:23:23.026 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: transformation performed, from '1' to 'PENDING'
2015-10-26 00:23:23.027 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Incr) Updating 'SwitchingPluginDeviceStatus {mios="unit:savannah,device:3/status"}' to 'PENDING'
2015-10-26 00:23:23.047 [TRACE] [.o.b.mios.internal.MiosBinding] - internalReceiveUpdate: itemName 'SwitchingPluginDeviceStatus', newState 'PENDING', class 'class org.openhab.core.library.types.StringType'
2015-10-26 00:23:23.057 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND {mios="unit:savannah,device:3/status"}, value=PENDING, bound 1 time(s)
2015-10-26 00:23:23.058 [TRACE] [.b.m.i.MiosBindingProviderImpl] - getItemNamesForProperty: MATCH property 'unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Target' against BindingConfig.toProperty 'unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Target'
2015-10-26 00:23:23.058 [TRACE] [b.m.i.config.MiosBindingConfig] - createState: Converted '0' to 'org.openhab.core.library.types.StringType', bound to 'class org.openhab.core.library.items.StringItem'
2015-10-26 00:23:23.058 [TRACE] [b.m.i.config.MiosBindingConfig] - transformIn: Converted value '0' from StringType to more scoped type 'class org.openhab.core.library.types.StringType'
2015-10-26 00:23:23.059 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: transformation performed, from '0' to '0'
2015-10-26 00:23:23.059 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Incr) Updating 'SwitchingPluginTarget {mios="unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Target"}' to '0'
2015-10-26 00:23:23.062 [TRACE] [.o.b.mios.internal.MiosBinding] - internalReceiveUpdate: itemName 'SwitchingPluginTarget', newState '0', class 'class org.openhab.core.library.types.StringType'
2015-10-26 00:23:23.064 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND {mios="unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Target"}, value=0, bound 1 time(s)
2015-10-26 00:23:23.065 [TRACE] [.b.m.i.MiosBindingProviderImpl] - getItemNamesForProperty: MATCH property 'unit:savannah,device:3/id' against BindingConfig.toProperty 'unit:savannah,device:3/id'
2015-10-26 00:23:23.067 [TRACE] [b.m.i.config.MiosBindingConfig] - createState: Converted '3' to 'org.openhab.core.library.types.DecimalType', bound to 'class org.openhab.core.library.items.NumberItem'
2015-10-26 00:23:23.068 [TRACE] [b.m.i.config.MiosBindingConfig] - transformIn: Converted value '3' from StringType to more scoped type 'class org.openhab.core.library.types.DecimalType'
2015-10-26 00:23:23.068 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: transformation performed, from '3' to '3'
2015-10-26 00:23:23.068 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Incr) Updating 'SwitchingPluginId {mios="unit:savannah,device:3/id"}' to '3'
2015-10-26 00:23:23.077 [TRACE] [.o.b.mios.internal.MiosBinding] - internalReceiveUpdate: itemName 'SwitchingPluginId', newState '3', class 'class org.openhab.core.library.types.DecimalType'
2015-10-26 00:23:23.081 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND {mios="unit:savannah,device:3/id"}, value=3, bound 1 time(s)
2015-10-26 00:23:23.081 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Using_2G"}, value=0
2015-10-26 00:23:23.085 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LoadTime"}, value=2015-10-23T20:36:13
2015-10-26 00:23:23.089 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/DataVersion"}, value=646979625
2015-10-26 00:23:23.091 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/UserData_DataVersion"}, value=646973057
2015-10-26 00:23:23.092 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/TimeStamp"}, value=2015-10-26T00:23:24
2015-10-26 00:23:23.092 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_on"}, value=0
2015-10-26 00:23:23.092 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_off"}, value=0
2015-10-26 00:23:23.092 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_locked"}, value=0
2015-10-26 00:23:23.092 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_unlocked"}, value=1
2015-10-26 00:23:23.092 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_tripped"}, value=0
2015-10-26 00:23:23.092 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_not_tripped"}, value=0
2015-10-26 00:23:23.092 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/failed_devices"}, value=0
2015-10-26 00:23:23.093 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/visible_devices"}, value=8
2015-10-26 00:23:23.093 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_active"}, value=0
2015-10-26 00:23:23.093 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_notactive"}, value=0
2015-10-26 00:23:23.093 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/ZWaveStatus"}, value=1
2015-10-26 00:23:23.094 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Mode"}, value=1
2015-10-26 00:23:23.094 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LocalTime"}, value=2015-10-26 00:23:24 N
2015-10-26 00:23:23.094 [DEBUG] [b.m.internal.MiosUnitConnector] - run: URI Built was 'http://192.168.20.35:3480/data_request?id=status2&LoadTime=1445646973&DataVersion=646979625&Timeout=40&MinimumDelay=0' loop '51'
2015-10-26 00:23:23.126 [DEBUG] [b.m.internal.MiosUnitConnector] - processResponse: success! loadTime=1445646973, dataVersion=646979632 devices(1) scenes(0) rooms(0) sections(0)
2015-10-26 00:23:23.128 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,device:3/PendingJobs"}, value=0
2015-10-26 00:23:23.129 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Using_2G"}, value=0
2015-10-26 00:23:23.129 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LoadTime"}, value=2015-10-23T20:36:13
2015-10-26 00:23:23.129 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/DataVersion"}, value=646979632
2015-10-26 00:23:23.130 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/UserData_DataVersion"}, value=646973057
2015-10-26 00:23:23.130 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/TimeStamp"}, value=2015-10-26T00:23:25
2015-10-26 00:23:23.130 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_on"}, value=0
2015-10-26 00:23:23.131 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_off"}, value=0
2015-10-26 00:23:23.131 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_locked"}, value=0
2015-10-26 00:23:23.131 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_unlocked"}, value=1
2015-10-26 00:23:23.131 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_tripped"}, value=0
2015-10-26 00:23:23.132 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_not_tripped"}, value=0
2015-10-26 00:23:23.132 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/failed_devices"}, value=0
2015-10-26 00:23:23.132 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/visible_devices"}, value=8
2015-10-26 00:23:23.132 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_active"}, value=0
2015-10-26 00:23:23.133 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_notactive"}, value=0
2015-10-26 00:23:23.133 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/ZWaveStatus"}, value=1
2015-10-26 00:23:23.133 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Mode"}, value=1
2015-10-26 00:23:23.133 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LocalTime"}, value=2015-10-26 00:23:25 N
2015-10-26 00:23:23.134 [DEBUG] [b.m.internal.MiosUnitConnector] - run: URI Built was 'http://192.168.20.35:3480/data_request?id=status2&LoadTime=1445646973&DataVersion=646979632&Timeout=40&MinimumDelay=0' loop '52'
2015-10-26 00:23:23.166 [DEBUG] [b.m.internal.MiosUnitConnector] - processResponse: success! loadTime=1445646973, dataVersion=646979635 devices(1) scenes(0) rooms(0) sections(0)
2015-10-26 00:23:23.166 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,device:3/PendingJobs"}, value=0
2015-10-26 00:23:23.167 [TRACE] [.b.m.i.MiosBindingProviderImpl] - getItemNamesForProperty: MATCH property 'unit:savannah,device:3/status' against BindingConfig.toProperty 'unit:savannah,device:3/status'
2015-10-26 00:23:23.167 [TRACE] [b.m.i.config.MiosBindingConfig] - createState: Converted 'SUCCESS' to 'org.openhab.core.library.types.StringType', bound to 'class org.openhab.core.library.items.StringItem'
2015-10-26 00:23:23.167 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: transformation performed, from '4' to 'SUCCESS'
2015-10-26 00:23:23.168 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Incr) Updating 'SwitchingPluginDeviceStatus {mios="unit:savannah,device:3/status"}' to 'SUCCESS'
2015-10-26 00:23:23.168 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND {mios="unit:savannah,device:3/status"}, value=SUCCESS, bound 1 time(s)
2015-10-26 00:23:23.168 [TRACE] [.o.b.mios.internal.MiosBinding] - internalReceiveUpdate: itemName 'SwitchingPluginDeviceStatus', newState 'SUCCESS', class 'class org.openhab.core.library.types.StringType'
2015-10-26 00:23:23.168 [TRACE] [.b.m.i.MiosBindingProviderImpl] - getItemNamesForProperty: MATCH property 'unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Status' against BindingConfig.toProperty 'unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Status'
2015-10-26 00:23:23.169 [TRACE] [b.m.i.config.MiosBindingConfig] - createState: Converted 'OFF' to 'org.openhab.core.library.types.OnOffType', bound to 'class org.openhab.core.library.items.SwitchItem'
2015-10-26 00:23:23.171 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: transformation performed, from '0' to 'OFF'
2015-10-26 00:23:23.171 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Incr) Updating 'SwitchingPluginStatus {mios="unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Status"}' to 'OFF'
2015-10-26 00:23:23.171 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND {mios="unit:savannah,device:3/service/urn:upnp-org:serviceId:SwitchPower1/Status"}, value=OFF, bound 1 time(s)
2015-10-26 00:23:23.171 [TRACE] [.o.b.mios.internal.MiosBinding] - internalReceiveUpdate: itemName 'SwitchingPluginStatus', newState 'OFF', class 'class org.openhab.core.library.types.OnOffType'
2015-10-26 00:23:23.172 [TRACE] [.b.m.i.MiosBindingProviderImpl] - getItemNamesForProperty: MATCH property 'unit:savannah,device:3/id' against BindingConfig.toProperty 'unit:savannah,device:3/id'
2015-10-26 00:23:23.172 [TRACE] [b.m.i.config.MiosBindingConfig] - createState: Converted '3' to 'org.openhab.core.library.types.DecimalType', bound to 'class org.openhab.core.library.items.NumberItem'
2015-10-26 00:23:23.172 [TRACE] [b.m.i.config.MiosBindingConfig] - transformIn: Converted value '3' from StringType to more scoped type 'class org.openhab.core.library.types.DecimalType'
2015-10-26 00:23:23.172 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: transformation performed, from '3' to '3'
2015-10-26 00:23:23.172 [DEBUG] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND (Incr) Updating 'SwitchingPluginId {mios="unit:savannah,device:3/id"}' to '3'
2015-10-26 00:23:23.173 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: BOUND {mios="unit:savannah,device:3/id"}, value=3, bound 1 time(s)
2015-10-26 00:23:23.173 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Using_2G"}, value=0
2015-10-26 00:23:23.173 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LoadTime"}, value=2015-10-23T20:36:13
2015-10-26 00:23:23.175 [TRACE] [.o.b.mios.internal.MiosBinding] - internalReceiveUpdate: itemName 'SwitchingPluginId', newState '3', class 'class org.openhab.core.library.types.DecimalType'
2015-10-26 00:23:23.175 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/DataVersion"}, value=646979635
2015-10-26 00:23:23.175 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/UserData_DataVersion"}, value=646973057
2015-10-26 00:23:23.179 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/TimeStamp"}, value=2015-10-26T00:23:25
2015-10-26 00:23:23.182 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_on"}, value=0
2015-10-26 00:23:23.182 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/lights_off"}, value=0
2015-10-26 00:23:23.182 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_locked"}, value=0
2015-10-26 00:23:23.182 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/doors_unlocked"}, value=1
2015-10-26 00:23:23.183 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_tripped"}, value=0
2015-10-26 00:23:23.183 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/sensors_not_tripped"}, value=0
2015-10-26 00:23:23.183 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/failed_devices"}, value=0
2015-10-26 00:23:23.183 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/visible_devices"}, value=8
2015-10-26 00:23:23.183 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_active"}, value=0
2015-10-26 00:23:23.183 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/partitions_notactive"}, value=0
2015-10-26 00:23:23.183 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/ZWaveStatus"}, value=1
2015-10-26 00:23:23.183 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/Mode"}, value=1
2015-10-26 00:23:23.183 [TRACE] [.o.b.mios.internal.MiosBinding] - internalPropertyUpdate: NOT BOUND {mios="unit:savannah,system:/LocalTime"}, value=2015-10-26 00:23:25 N
2015-10-26 00:23:23.183 [DEBUG] [b.m.internal.MiosUnitConnector] - run: URI Built was 'http://192.168.20.35:3480/data_request?id=status2&LoadTime=1445646973&DataVersion=646979635&Timeout=40&MinimumDelay=0' loop '53'

guessed · October 26, 2015, 4:47am

ok, that’s more like what I was expecting to see. What happens if you manually change the light like the URL above (in a regular browser)?

I suspect that the light is going on (or off) at the right point in time, via the script, but for some reason Vera is not detecting it as a change so it doesn’t unblock my Long-poll thread to give me the state back (this is really odd)

Is MiOS Device 3 a real switch, or something virtual on the Vera end of things?

ubergeek · October 26, 2015, 4:57am

It has the same delay…maybe I should unplug and repower it? No that doesnt help. I may try to power cyce the vera to see if that has any effect.

Its an older leviton plug-in appliance switch

guessed · October 26, 2015, 5:03am

The URL is a request for MiOS to make the change, so if there’s a problem in the [Z-Wave] Network it’s entirely possible there will be a delay before the light comes on… and thus before Vera/MiOS sends the response that it’s actually effected the change requested.

If you switch Vera itself into diagnostic mode, then you’ll see the [RAW] Z-Wave messages it’s sending as lines in /var/log/cmh/LuaUPnP.log. The relevant [raw] lines will start with 41/42, and there will be other logical “Zwave” messages in the logs around/near those.

ubergeek · October 26, 2015, 5:04am

I’m actually not sure what device 3 is now…the switchingplugin seems to be device 14 in the log, correct?

I will check further tomorrow as I need to catch a few, but i will report back, Thanks for the guidance this far

guessed · October 26, 2015, 5:09am

Device 3 is the thing you’re switching, you have a T-Stat on Device 14 and it just happened to be active at ~ the same time period.

ubergeek · October 26, 2015, 11:16am

I reset the Z wave engine through the vera interface and that took care of it. Thanks for looking at this.

Is there a way to do this through the binding? Just curious and I didn’t see it when scrolling through the docs. I thought it might be useful if it was something that might ever want to be put on a schedule…still new to vera and UI7 so not sure of the stability.

guessed · October 27, 2015, 5:21am

Good to hear your got it working. You shouldn’t need to reset Vera for this type of thing, but if you can work out the action that was initiated from within Vera (the formal URL Action used) then it’s possible to do the same thing via the MiOS binding.

I don’t recommend it, since it’d be better to sort out the real source of the issue in Vera.

Teknokill · December 21, 2020, 9:10pm

I’m so confused with this Mios Binding. I have many Z-Wave switches, but I can’t figure out if I’m supposed to create a script in order for my VeraPlus to print out in text form the JSON items list for each device. Is it a script that I can execute on my OpenHab Box in the terminal? I’m so confused. I have a Aerostick in case it doesn’t work. Since I need the Vera for my door lock I figured to keep it and use it as the Z-Wave Bridge to OpenHab.
Also, is there more latency with Mios compared to the AeroStick? My VeraPlus seems slow to me and I was wondering if I would see much more lag time if I got it working with Openhab. Does anybody feel or experienced quicker response times with the Aerostick compared to Vera?

Teknokill · December 21, 2020, 9:11pm

Can anybody kind of give me a play-by-play to setting up this binding?
I want to have all of the devices result in populating my items file in Openhab.

hafniumzinc · December 21, 2020, 9:31pm

Please don’t post the same question in multiple threads - instead, open your own.

In the meantime, there is a very comprehensive “play-by-play” in the documentation:

Note however that this is a v1 binding and not compatible with openHAB 3, which was just released today. There is no MiOS binding for OH3, as discussed here:

Teknokill · December 22, 2020, 5:04am

Hafniumzinc,

Unfortunately, I don’t share your technical knowledge since I’ve read the binding information over and over again on the link you shared, but with no success. I guess I should just take the insult in stride and take my beating, put my tail between my legs and walk away, but there have been some people in the forums who have taken the time to share a little bit of their knowledge to a neophyte, like myself. I’m not a coder and try to learn as much as I can by reading the forums, but sometimes I suffer through some issues. Your cold reply doesn’t help the spread of an open source home automation system. In fact it does the opposite and discourages people from taking on more than they can chew so they don’t have to be ostracized publicly by people like yourself, which then could be said that some wish it could be a closed system. .

hafniumzinc · December 22, 2020, 7:36am

And I am one of those.

The only “ostracism” that occurred is when I said:

Which is just standard etiquette on forums.

I’m not sure that your response is fair at all. But here’s a actual cold response: you made the same post in a couple of threads, but in neither of them did you say that you have read the documentation, or what steps you have actually tried. In fact this

Suggests that you didn’t read the documentation, because in the documentation it says Item Generation : MiOS Item Generator

The MiOS Item Generator is a free-standing tool that generates an initial openHAB Items file for a MiOS Unit.

With a link to the MiOS Item Generator. You’ve obviously clicked that link, in which case you’ve got to the section on how to use the script.

But the fact that you “can’t figure out if I’m supposed to create a script” is suspicious, because the words and links in the documentation quite clearly give you a script for you to run.

I think there’s two take aways here:

As requested in the sticky on this forum, if you want help you need to help us by telling us as much about your system, setup, configuration as possible, and describing in excruciating detail what you’ve already tried. In your case, at what exact point in the documentation do you get stuck? But as already mentioned, please start a new thread.
This is a v1 binding, as previously mentioned, and quite a tricky one to setup at that, so it’s going to take quite a bit of time to understand how it works. And as OH3 has been released, where v1 bindings no longer work, support on this particular topic will be quite sparse unfortunately.

Good luck.

Teknokill · December 22, 2020, 7:45pm

A couple of threads? 2 threads. I didn’t know which was best, since this one had not been commented upon since early October. I found the set-up thread and forgot to delete this one. Thank you for your explanation. I guess, the best thing for me to do is migrate away from Vera if I want to continue using Openhab. I don’t know if anybody has ever got the Schlage Z-Wave door lock working, but that is what is preventing me from converting over to using the Aeotec Aerostick.

Thanks for taking the time to answer me.