OH2 Z-Wave refactoring and testing... and SECURITY

chris · February 17, 2018, 4:54pm

There’s another thread on this over here -:

Seems to be reported in the dev version and the master version so I don’t think it’s the binding as such. It might be a problem with combining configuration sources as there are two sources in the ZWave binding - the xml files, and some internal definitions. I suspect this might be broken now as only the internal definitions appear to be displayed…

dbadia · February 17, 2018, 11:07pm

@chris

Sorry, I must updated the wrong one. Here is the correct file:
https://pastebin.com/fnNJe9Xg
Look for these errors:

com.thoughtworks.xstream.converters.ConversionException: The document is invalid, it contains further unsupported data

@sihui

Thanks for the suggestion, but these aren’t files I created, the they are the ones in the binding jar, such as:

/ESH-INF/thing/fibaro_fgsd002_0_0.xml
/ESH-INF/thing/inovelli_nzw37_0_0.xml

sihui · February 17, 2018, 11:21pm

Sorry, somehow quoted the wrong post, answer was meant for another user.

paulfaure · February 18, 2018, 1:14am

For what its worth, here are the debug logs where I get the message about missing NodeID.
http://faure.ca/~paul/missing_node_id.txt

chris · February 18, 2018, 9:34am

There’s not a lot I can say really. I’ve no idea why the system isn’t passing the configuration into the binding, but as I said earlier, the binding doesn’t have any visibility of how you are configuring your system. Clearly the binding is working, or it wouldn’t work for anyone. There must be something else in the system that is preventing the configuration from being passed through, although it did work when I tested it here.

bdigiovine · February 18, 2018, 12:20pm

Chris

Sorry to bother you again. I added my debug log about 14 days ago. I haven’t seen a response.

Is there more that I can do to help you understand my issue. I am stuck and not sure I know what to do next.

Thanks.

chris · February 18, 2018, 12:34pm

Sorry - I missed that (I was unwell at the time ). However I can’t really use short excerpts of the logs - I really need to see a debug log of the initialisation. I don’t care if it’s 10MB - it’s a lot more useful that 10 lines.

bdigiovine · February 18, 2018, 9:25pm

Thanks for getting back to me.

I have uploaded the entirety of my bedug session on the attached pdf.

I hope that’s OK.

B

debug zwave 020318.pdf (440.0 KB)

chris · February 18, 2018, 9:51pm

I’m not quite sure what the log is - I guess it’s been filtered on node 3? In any case, it’s not got the information that I need and it seems to be some sort of combination with the events log?

Best thing is to simply provide the log file - as it comes from OH - as a text file (ie not PDF as I then need to export it so the log reader can process it. Please don’t filter the log though.

Thanks.

bdigiovine · February 19, 2018, 1:01pm

Chris

Here is what my log:list shows me:

Logger │ Level
───────────────────────────────────────────────────┼──────
ROOT │ WARN
javax.jmdns │ ERROR
org.apache.karaf.jaas.modules.audit │ INFO
org.apache.karaf.kar.internal.KarServiceImpl │ ERROR
org.apache.karaf.shell.support │ OFF
org.eclipse.smarthome │ INFO
org.jupnp │ ERROR
org.openhab │ INFO
org.openhab.binding.zwave │ DEBUG
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime │ OFF
smarthome.event │ INFO
smarthome.event.InboxUpdatedEvent │ ERROR
smarthome.event.ItemAddedEvent │ ERROR
smarthome.event.ItemRemovedEvent │ ERROR
smarthome.event.ItemStateEvent │ ERROR
smarthome.event.ThingAddedEvent │ ERROR
smarthome.event.ThingRemovedEvent │ ERROR
smarthome.event.ThingStatusInfoEvent │ ERROR

Should I have DEBUG at the root level rather than just for org.openhab.binding.zwave?

Bruno

chris · February 19, 2018, 1:26pm

No - just zwave is fine. The issue is not to filter the log which I think you have as I’ve not seen any received data. I think you probably filtered with a “grep node 3” or something like that? This is what removes the useful (and necessary) information.

bdigiovine · February 19, 2018, 3:24pm

Chris

Hope this works. I removed my lock and then added it back. It continues to not have security enabled. I then went into Karaf and instituted log:display. What I got is too long to enter in a post and I can’t attach a txt file so I limited the info to the end of the Checking list (the list went on for pages and was just an alphabetical list of every zwave device (I think). The end of the list is below. There was nothing before the list…

Thanks again.

B

10:12:14.690 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - Checking zwave:kichler_15dc200_00_000
10:12:14.691 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - Checking zwave:kwikset_914trl_00_000
10:12:14.696 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
10:12:14.717 [DEBUG] [org.openhab.binding.zwave            ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=373, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
10:12:14.720 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:654457c4:node2' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to UNINITIALIZED
10:12:14.727 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:654457c4:node2' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
10:12:14.742 [DEBUG] [org.openhab.binding.zwave            ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=374, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
10:12:14.754 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:654457c4:node2.
10:12:14.756 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:654457c4:node2' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
10:12:14.760 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:654457c4:node2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
10:12:14.762 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Controller status changed to ONLINE.
10:12:14.764 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Controller is ONLINE. Starting device initialisation.
10:12:14.770 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'zwave:device:654457c4:node2' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
10:12:14.790 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating node properties.
10:12:14.792 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:654457c4:node2' has been updated.
10:12:14.810 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:654457c4:node2' has been updated.
10:12:14.811 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating node properties. MAN=144
10:12:14.812 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating node properties. MAN=144. SET. Was 144
10:12:14.813 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Properties synchronised
10:12:14.830 [DEBUG] [ave.internal.protocol.ZWaveController] - Event listener added.
10:12:14.831 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:654457c4:node2' has been updated.
10:12:14.831 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node...
10:12:14.833 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising cmd channel zwave:device:654457c4:node2:lock_door for OnOffType
10:12:14.834 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising state channel zwave:device:654457c4:node2:lock_door for OnOffType
10:12:14.836 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising cmd channel zwave:device:654457c4:node2:alarm_number for DecimalType
10:12:14.837 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising state channel zwave:device:654457c4:node2:alarm_number for DecimalType
10:12:14.838 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising cmd channel zwave:device:654457c4:node2:alarm_raw for StringType
10:12:14.839 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising state channel zwave:device:654457c4:node2:alarm_raw for StringType
10:12:14.840 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising cmd channel zwave:device:654457c4:node2:battery-level for PercentType
10:12:14.841 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising state channel zwave:device:654457c4:node2:battery-level for PercentType
10:12:14.842 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling intialised at 1800 seconds - start in 1584000 milliseconds.
10:12:14.843 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 2: Device initialisation complete.
10:12:14.847 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'zwave:device:654457c4:node2' has been updated.
10:12:17.286 [ERROR] [home.binding.wemo.handler.WemoHandler] - Failed to get actual state for device 'wemo:lightswitch:Lightswitch-1_0-221628K1300679': Could not call WeMo
10:12:17.834 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:0210:00178846e016:16' changed from ONLINE to OFFLINE: Hue bridge reports light as not reachable.
10:12:33.197 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeSent
10:12:33.199 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
10:12:33.200 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
10:12:33.201 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
10:12:33.202 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
10:12:33.203 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
10:12:33.204 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 4A 05 01 46 F1
10:12:33.206 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 4A 05 01 46 F1
10:12:33.207 [ERROR] [ding.zwave.handler.ZWaveSerialHandler] - Got I/O exception Input/output error in writeArray during sending. exiting thread.
10:12:33.208 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 3135: Transaction Start type AddNodeToNetwork
10:12:33.209 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3135: [WAIT_REQUEST] requiresResponse=true callback: 70
10:12:33.210 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
10:12:33.211 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
10:12:33.212 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
10:12:33.214 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Feb 19 10:12:38 EST 2018 - 5000ms
10:12:33.215 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 3135: [WAIT_REQUEST] requiresResponse=true callback: 70
10:12:33.216 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
10:12:33.218 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Feb 19 10:12:38 EST 2018 - 4996ms
10:12:38.213 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
10:12:38.216 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 3135: Timeout at state WAIT_REQUEST. 3 retries remaining.
10:12:38.217 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 3135: Transaction is current transaction, so clearing!!!!!
10:12:38.218 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 3135: Transaction CANCELLED
10:12:38.219 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
10:12:38.221 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:3135 CANCELLED
10:12:38.223 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
10:12:38.230 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
10:12:38.231 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
10:12:38.233 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
10:12:47.309 [ERROR] [home.binding.wemo.handler.WemoHandler] - Failed to get actual state for device 'wemo:lightswitch:Lightswitch-1_0-221628K130068A': Could not call WeMo
10:12:48.224 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion timer at IncludeDone
10:12:58.817 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:0210:00178846e016:14' changed from OFFLINE: Hue bridge reports light as not reachable. to ONLINE
10:13:09.070 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'hue:0210:00178846e016:15' changed from OFFLINE: Hue bridge reports light as not reachable. to ONLINE
10:13:19.521 [ERROR] [home.binding.wemo.handler.WemoHandler] - Failed to get actual state for device 'wemo:lightswitch:Lightswitch-1_0-221612K1300F95': Could not call WeMo

chris · February 19, 2018, 4:07pm

Sorry, but I really need the full log from the point the inclusion starts (ie the discovery command is sent from the UI), up till when it fails. Can you email it to me at chris -at- cd-jackson.com?

bdigiovine · February 19, 2018, 4:08pm

Sure. Can you tell me how I get more of the log? As I noted, the log:display command did not seem to start early enough.

B

CFU · February 19, 2018, 4:43pm

I have the same problem my locks dont include secure anymore i will post a log in a moment

here is the log from initializing inclusion to the end, the lock i added is node 5, node 3 is a lock i added before both Schlage

Not sure if the XML folder is of any interest…

node 5 xml:

<node>
  <homeId>0x2</homeId>
  <nodeId>5</nodeId>
  <version>4</version>
  <manufacturer>0x3b</manufacturer>
  <deviceId>0x5044</deviceId>
  <deviceType>0x6349</deviceType>
  <listening>false</listening>
  <frequentlyListening>true</frequentlyListening>
  <routing>true</routing>
  <security>false</security>
  <beaming>true</beaming>
  <maxBaudRate>40000</maxBaudRate>
  <sleepDelay>1000</sleepDelay>
  <associationGroups class="concurrent-hash-map"/>
  <endpoints class="concurrent-hash-map">
    <entry>
      <int>0</int>
      <endPoint>
        <deviceClass>
          <basicDeviceClass>BASIC_TYPE_ROUTING_SLAVE</basicDeviceClass>
          <genericDeviceClass>GENERIC_TYPE_ENTRY_CONTROL</genericDeviceClass>
          <specificDeviceClass>SPECIFIC_TYPE_SECURE_KEYPAD_DOOR_LOCK</specificDeviceClass>
        </deviceClass>
        <endpointId>0</endpointId>
        <secureCommandClasses/>
        <supportedCommandClasses class="concurrent-hash-map">
          <entry>
            <commandClass>COMMAND_CLASS_APPLICATION_STATUS</commandClass>
            <COMMAND__CLASS__APPLICATION__STATUS>
              <version>1</version>
              <instances>1</instances>
              <versionSupported>1</versionSupported>
            </COMMAND__CLASS__APPLICATION__STATUS>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_FIRMWARE_UPDATE_MD</commandClass>
            <COMMAND__CLASS__FIRMWARE__UPDATE__MD>
              <version>1</version>
              <instances>1</instances>
              <versionSupported>2</versionSupported>
            </COMMAND__CLASS__FIRMWARE__UPDATE__MD>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_NO_OPERATION</commandClass>
            <COMMAND__CLASS__NO__OPERATION>
              <version>1</version>
              <instances>1</instances>
              <versionSupported>1</versionSupported>
            </COMMAND__CLASS__NO__OPERATION>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_VERSION</commandClass>
            <COMMAND__CLASS__VERSION>
              <version>1</version>
              <instances>1</instances>
              <versionSupported>1</versionSupported>
              <libraryType>LIB_SLAVE_ROUTING</libraryType>
              <protocolVersion>3.42</protocolVersion>
              <applicationVersion>113.22</applicationVersion>
            </COMMAND__CLASS__VERSION>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_BASIC</commandClass>
            <COMMAND__CLASS__BASIC>
              <version>1</version>
              <instances>1</instances>
              <versionSupported>1</versionSupported>
              <isGetSupported>true</isGetSupported>
            </COMMAND__CLASS__BASIC>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_MANUFACTURER_SPECIFIC</commandClass>
            <COMMAND__CLASS__MANUFACTURER__SPECIFIC>
              <version>1</version>
              <instances>1</instances>
              <versionSupported>1</versionSupported>
              <initSerialNumber>false</initSerialNumber>
              <deviceManufacturer>59</deviceManufacturer>
              <deviceType>25417</deviceType>
              <deviceId>20548</deviceId>
            </COMMAND__CLASS__MANUFACTURER__SPECIFIC>
          </entry>
          <entry>
            <commandClass>COMMAND_CLASS_SECURITY</commandClass>
            <COMMAND__CLASS__SECURITY>
              <version>1</version>
              <instances>1</instances>
              <versionSupported>1</versionSupported>
            </COMMAND__CLASS__SECURITY>
          </entry>
        </supportedCommandClasses>
      </endPoint>
    </entry>
  </endpoints>
  <nodeNeighbors>
    <int>1</int>
    <int>2</int>
    <int>3</int>
    <int>4</int>
  </nodeNeighbors>
  <lastReceived>2018-02-19 16:50:37.145 UTC</lastReceived>
</node>

chris · February 19, 2018, 5:10pm

The log is stored in the userdata/logs folder - it’s called openhab.log.

chris · February 19, 2018, 5:13pm

I would guess that you need to reset the lock before including it. From the log you can see that the device (presumably node 5?) is already included before you start inclusion -:

bdigiovine · February 19, 2018, 6:54pm

Just sent an email. Thanks again.

B

chris · February 19, 2018, 7:25pm

What node are you including? I don’t see any node being added - all nodes seem to be known before the inclusion is started -:

Maybe the device needs to be reset first?

The log is also a bit strange in that there are no receive frames logged in the whole log file . I don’t really believe that’s possible - if it is real, then I would assume nothing at all is working.

It might pay for you to take a look at your logs in the log viewer to see if you can get the logs viewing properly.

Emilio · February 19, 2018, 7:45pm

First, I want to thank all whom contribute to the development of OpenHAB! It’s great that a open system with support for so many devices exists.

I’ve recently migrated to the _February 8th 2.3.0-SNAPSHOT version _ of the Z-Wave binding in OpenHAB 2.2 release build to get security support. I’ll report my results here.

What works (and wasn’t on the 2.1 SNAPSHOT version, non security Z-Wave binding I was previously using):

The Z-Wave network viewer in HABMIN now automatically shows the correct neighbors.
Secure inclusion. Aeon Labs Garage Door Controller.

Some minor issues:

SWITCH_missing.png735×419 15.2 KB
The first item is displayed differently from all others. The type isn’t reported, see the red box. Also, when creating a thing, the type isn’t appended to the last part of the name. I’ve deleted the channel, item and XML, ran discover again and re-added the thing + item. The result is the same.
In HABMIN the Association Groups, Controller updates isn’t set for (most) devices after a restart of OpenHAB. Most devices continue to work normally.
I have two Fibaro Door and Window Sensors 2. They work ever since the updates done in 2017 to support the newer version of these devices, however when restarting OpenHAB they tend to be marked as OFFLINE. After I restore the Association Groups, Controller updates to openHAB controller and wakeup the devices several times the usually come ONLINE. After I restart of OpenHAB I have to go though this procedure again.
The Fibaro Door and Window Sensors 2 Contact channel is renamed to DoorSensor. This is something to keep in mind when re-creating items since its default name will change, breaking existing rules.

Emilio