Delay on Zwave execution after command sent using MIOS Binding

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.

hafniumzinc · December 22, 2020, 7:55pm

Since October 2015! It took me a while to get used to the date formats on this forum too, but yes, it says Oct '15!

I think for future-proofing your setup, moving away from the Vera is probably the right thing to do. I’m staying stubborn, and using the Jython scripts linked in a previous post, but they’re definitely not newbie friendly, and quite specific to my case.

From the Z-Wave bindings page I can’t see that the Schlage door lock is supported - I presume there is a specific reason for this, as I thought they were quite popular devices. Perhaps @Bruce_Osborne or @chris can provide more insight?

Bruce_Osborne · December 22, 2020, 8:08pm

Which one (model)?. They make multiples. Many are rebranded.

Bruce_Osborne · December 22, 2020, 8:14pm

They did not say exactly what openHAB version they are trying to use.

hafniumzinc · December 22, 2020, 8:17pm

Sure - no harm in covering all bases within the same post.