Zwave deserialization errors with 1.80

Hello, brand stinkin’ newbie for openhab, so please bear with!

Running an aeon zstick 5 on windows 7. Openhab 1.80 . persistence is through mysql running on the same box. (Aeon stick is actually a subordinate controller to my Vera Edge until I really land on my feet with openHAB… in case it matters! The aeon stick is explicitly configured not to be the master zwave controller.)

I have a reasonably large zwave network (49 nodes), so I’m taking it slowly, dipping one toe in the water and then the next. So far I’ve set up items files for my (5) aeon home energy monitors and a few of my aeon smart switches.

basic HEM example:

Number	WHOLE_HOUSE_WATTS	"Whole House Total [%.01f] Watts"	<line>	{ zwave="88:0:command=METER,meter_scale=E_W" }
Number	WHOLE_HOUSE_WATTS_PHASE1	"Whole House Phase 1 [%.01f] Watts"	<line>	(GF_Power)		{ zwave="88:1:command=METER,meter_scale=E_W" }
Number	WHOLE_HOUSE_WATTS_PHASE2	"Whole House Phase 2 [%.01f] Watts"	<line>	(GF_Power)		{ zwave="88:2:command=METER,meter_scale=E_W" }

super-de-duper basic smartswitch example (energy reporting only):

Number BAS_NETWORK_RACK "Basement Network Rack [%f] Watts" <line> (GF_Power)  {zwave="23:0:command=METER,meter_scale=E_W"}

…and these seem to work fine. In the openHAB window (and events log), I get messages like this:

2016-02-10 13:45:12 - WHOLE_HOUSE_WATTS state updated to 1844.64
2016-02-10 13:45:12 - WHOLE_HOUSE_WATTS state updated to 1844.64
2016-02-10 13:45:12 - WHOLE_HOUSE_WATTS_PHASE1 state updated to 490.44
2016-02-10 13:45:12 - WHOLE_HOUSE_WATTS_PHASE2 state updated to 1354.2

Problem is that nothing seems to be getting stored in persistence. habmin1 will graph four values from hours and hours ago. If I look at the data table, it shows four values from hours ago and then the current value.

I’m suspecting something has gone wrong, but I’m not exactly sure where to look.

I’m suspecting that it has something to do with deserialization errors I’m getting from my three GE/Jasco switches. Example:

2016-02-10 12:39:57.481 [ERROR] [b.z.i.protocol.ZWaveController] - NODE 52: Restore from config: Error deserialising XML file. com.thoughtworks.xstream.converters.ConversionException:  : ParseError at [row,col]:[52,32]
Message: Character reference "&# :  : ParseError at [row,col]:[52,32]
Message: Character reference "&#
---- Debugging information ----
message             :  : ParseError at [row,col]:[52,32]
Message: Character reference "&#
cause-exception     : com.thoughtworks.xstream.io.StreamException
cause-message       :  : ParseError at [row,col]:[52,32]
Message: Character reference "&#
class               : java.lang.String
required-type       : java.lang.String
converter-type      : com.thoughtworks.xstream.converters.SingleValueConverterWrapper
wrapped-converter   : com.thoughtworks.xstream.converters.basic.StringConverter
path                : /node/supportedCommandClasses/entry[4]/nameLocationCommandClass/name
line number         : 52
class[1]            : org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveNodeNamingCommandClass
converter-type[1]   : com.thoughtworks.xstream.converters.reflection.ReflectionConverter
class[2]            : java.util.HashMap
converter-type[2]   : com.thoughtworks.xstream.converters.collections.MapConverter
class[3]            : org.openhab.binding.zwave.internal.protocol.ZWaveNode
version             : 1.4.6
-------------------------------

Note that this node (#52) and the other two that have deserialization errors are not referenced by any device in /config/items/. I simply haven’t gotten that far yet in telling openHAB about my z-wave network. So I’m kind of at a loss as to where to go from here; it seems as though it’s barfing on something internally.

Any suggestions appreciated, again I’m a complete openHAB newbie so it’s super possible I’m just missing something simple.

Thanks!

Well couldn’t leave well enough alone, so started digging.

Looks like the root cause of the deserialization errors are due to NULLs being inserted into the persistance XML files.

I had three nodes that were having deserialization errors. Node 35, 52, and 106. The only thing in common with all of them is that they’re GE/Jasco switches. (Two dimmers and one switch.)

For node 35, here’s a section of what I found in the XML file (the line that the deserializer flagged is marked with an asterisk, not present in the original file):

node 35    [row 99, col 33]:
    <entry>
      <commandClass>NODE_NAMING</commandClass>
      <nameLocationCommandClass>
        <version>1</version>
        <instances>1</instances>
        <initialiseName>true</initialiseName>
        <initialiseLocation>true</initialiseLocation>
*       <name>Garage lights&#x0;&#x0;&#x0;</name>
      </nameLocationCommandClass>
    </entry>

For node 52:

*    <entry>
      <commandClass>VERSION</commandClass>
      <versionCommandClass>
        <version>1</version>
        <instances>1</instances>
        <libraryType>LIB_CONTROLLER_BRIDGE</libraryType>
        <protocolVersion>3.40</protocolVersion>
        <applicationVersion>3.35</applicationVersion>
      </versionCommandClass>
    </entry>

But my spidey sense told me there was no way “entry” was the problem. A section earlier for node 52, however, I found some more embedded NULLs:

 <nameLocationCommandClass>
                <version>1</version>
                <instances>1</instances>
                <initialiseName>true</initialiseName>
                <initialiseLocation>true</initialiseLocation>
                <name>Patio Lights&#x0;&#x0;&#x0;&#x0;</name>
              </nameLocationCommandClass>

And finally in node106.xml, I found embedded NULLs as well:

    <entry>
      <commandClass>NODE_NAMING</commandClass>
      <nameLocationCommandClass>
        <version>1</version>
        <instances>1</instances>
        <initialiseName>true</initialiseName>
        <initialiseLocation>true</initialiseLocation>
*       <name>UH Stair light&#x0;&#x0;</name>
      </nameLocationCommandClass>
    </entry>

Once I excised those embedded NULLs and restarted openHAB, no more deserialization problem!

(Jury is still out on my persistence problem.)

1 Like

Well, trouble in river city still. If I stop openhab and restart it, the NULLs jump back into the XML files and cause the deserialization error again.

Suggestions?

I’d suggest checking the names of the items in your items file. Does the items file contain the failing items (eg. “Garage Lights”), and do the nulls exist there?

Two out of the three devices that cause deserialization errors have no items associated with them whatsoever. The XML persistence data seems to have come from the zwave binding itself, from a device scan / network walk.

The third device (“DINING ROOM LIGHTS”) does have an item defined for it, but it’s very pedestrian. No NULLs in it, either. :wink:

Dimmer DINING_ROOM_LIGHTS_LEVEL "Dining Room Lights [%d %%]" (GF_Lamps, GF_Dining_Room)  {zwave="107:0:command=SWITCH_MULTILEVEL,refresh_interval=0,restore_last_value=true"}

I kicked my openhab VM on to write this and noticed some more fun… looks like the source of the NULLs is in the zwave data coming back across the radio, and it’s not getting digested well:

2016-02-15 01:27:59.516 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node name: LR Dining Room L
2016-02-15 01:27:59.571 [ERROR] [.c.ZWaveNodeNamingCommandClass] - NODE 107 : Node Name report error in message length
2016-02-15 01:27:59.573 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node location: null
2016-02-15 01:27:59.742 [INFO ] [runtime.busevents             ] - DINING_ROOM_LIGHTS_LEVEL state updated to 0
2016-02-15 01:27:59.800 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node name: LR Dining Room L
2016-02-15 01:27:59.856 [ERROR] [.c.ZWaveNodeNamingCommandClass] - NODE 107 : Node Name report error in message length
2016-02-15 01:27:59.858 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node location: null
2016-02-15 01:27:59.915 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node name: LR Dining Room L
2016-02-15 01:27:59.972 [ERROR] [.c.ZWaveNodeNamingCommandClass] - NODE 107 : Node Name report error in message length
2016-02-15 01:27:59.974 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node location: null
2016-02-15 01:28:00.034 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node name: LR Dining Room L
2016-02-15 01:28:00.097 [ERROR] [.c.ZWaveNodeNamingCommandClass] - NODE 107 : Node Name report error in message length
2016-02-15 01:28:00.098 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node location: null
2016-02-15 01:28:00.169 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node name: LR Dining Room L
2016-02-15 01:28:00.222 [ERROR] [.c.ZWaveNodeNamingCommandClass] - NODE 107 : Node Name report error in message length
2016-02-15 01:28:00.223 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node location: null
2016-02-15 01:28:00.282 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node name: LR Dining Room L
2016-02-15 01:28:00.336 [ERROR] [.c.ZWaveNodeNamingCommandClass] - NODE 107 : Node Name report error in message length
2016-02-15 01:28:00.337 [INFO ] [.c.ZWaveNodeNamingCommandClass] - NODE 107: Node location: null
2016-02-15 01:28:00.339 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 107: Node advancer: Retries exceeded at DYNAMIC_VALUES

Woo, it’s officially a bug! (4046). Hopefully to be fixed for 1.90. (Not fatal if it isn’t, just in the “mild annoyance” category.)

And re-reading this thread to close the loop, my persistence issue had nothing to do with the deserialization problem… bad config file on my part was the root cause for that problem.

I’ve had a quick look at this and it’s probably an error with the NodeNaming command class…

Thanks for all the hard work! If there’s anything I can do to assist don’t hesitate to ask!