eclipse-archived / smarthome

Eclipse SmartHome™ project
https://www.eclipse.org/smarthome/
Eclipse Public License 2.0
861 stars 784 forks source link

Thing channel type definition file parsing fails #4444

Open paulianttila opened 6 years ago

paulianttila commented 6 years ago

I have developed OH binding which have pretty big thing channel type definition file. XML file contains over 5000 lines. Whole file can be found here f1x45-types.xml. During OH start, binding is successfully loaded and all thing type files are correctly parsed, but if I deploy binding to OH in run time (adding jar to addon directory when OH is already running), xml file parsing fails.

2017-10-19 20:21:01.393 [WARN ] [ig.xml.osgi.XmlDocumentBundleTracker] - The XML document '/ESH-INF/thing/f1x45-types.xml' in module 'org.openhab.binding.nibeheatpump' could not be parsed:  : ParseError at [row,col]:[717,4]
Message: Stream closed :  : ParseError at [row,col]:[717,4]
Message: Stream closed
---- Debugging information ----
message             :  : ParseError at [row,col]:[717,4]
Message: Stream closed
cause-exception     : com.thoughtworks.xstream.io.StreamException
cause-message       :  : ParseError at [row,col]:[717,4]
Message: Stream closed
class               : java.util.ArrayList
required-type       : java.util.ArrayList
converter-type      : com.thoughtworks.xstream.converters.collections.CollectionConverter
path                : /thing-descriptions/channel-type[96]
line number         : 717
class[1]            : org.eclipse.smarthome.core.thing.xml.internal.ChannelTypeXmlResult
converter-type[1]   : org.eclipse.smarthome.core.thing.xml.internal.ChannelTypeConverter
class[2]            : org.eclipse.smarthome.core.thing.xml.internal.ThingDescriptionList
converter-type[2]   : org.eclipse.smarthome.core.thing.xml.internal.ThingDescriptionConverter
version             : 1.4.7
-------------------------------
com.thoughtworks.xstream.converters.ConversionException:  : ParseError at [row,col]:[717,4]
Message: Stream closed :  : ParseError at [row,col]:[717,4]
Message: Stream closed
---- Debugging information ----
message             :  : ParseError at [row,col]:[717,4]
Message: Stream closed
cause-exception     : com.thoughtworks.xstream.io.StreamException
cause-message       :  : ParseError at [row,col]:[717,4]
Message: Stream closed
class               : java.util.ArrayList
required-type       : java.util.ArrayList
converter-type      : com.thoughtworks.xstream.converters.collections.CollectionConverter
path                : /thing-descriptions/channel-type[96]
line number         : 717
class[1]            : org.eclipse.smarthome.core.thing.xml.internal.ChannelTypeXmlResult
converter-type[1]   : org.eclipse.smarthome.core.thing.xml.internal.ChannelTypeConverter
class[2]            : org.eclipse.smarthome.core.thing.xml.internal.ThingDescriptionList
converter-type[2]   : org.eclipse.smarthome.core.thing.xml.internal.ThingDescriptionConverter
version             : 1.4.7
-------------------------------
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:79) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:50) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at org.eclipse.smarthome.core.thing.xml.internal.AbstractDescriptionTypeConverter.unmarshal(AbstractDescriptionTypeConverter.java:185) [116:org.eclipse.smarthome.core.thing.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:50) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.converters.collections.AbstractCollectionConverter.readItem(AbstractCollectionConverter.java:71) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.converters.collections.CollectionConverter.addCurrentElementToCollection(CollectionConverter.java:98) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.converters.collections.CollectionConverter.populateCollection(CollectionConverter.java:91) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.converters.collections.CollectionConverter.populateCollection(CollectionConverter.java:85) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.converters.collections.CollectionConverter.unmarshal(CollectionConverter.java:80) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:50) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at org.eclipse.smarthome.core.thing.xml.internal.ThingDescriptionConverter.unmarshal(ThingDescriptionConverter.java:48) [116:org.eclipse.smarthome.core.thing.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:50) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.start(TreeUnmarshaller.java:134) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.core.AbstractTreeMarshallingStrategy.unmarshal(AbstractTreeMarshallingStrategy.java:32) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.XStream.unmarshal(XStream.java:1185) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.XStream.unmarshal(XStream.java:1169) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.XStream.fromXML(XStream.java:1115) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at com.thoughtworks.xstream.XStream.fromXML(XStream.java:1062) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at org.eclipse.smarthome.config.xml.util.XmlDocumentReader.readFromXML(XmlDocumentReader.java:82) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.parseDocuments(XmlDocumentBundleTracker.java:344) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.processBundle(XmlDocumentBundleTracker.java:331) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.access$3(XmlDocumentBundleTracker.java:326) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$2.run(XmlDocumentBundleTracker.java:302) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: com.thoughtworks.xstream.io.StreamException:  : ParseError at [row,col]:[717,4]
Message: Stream closed
    at com.thoughtworks.xstream.io.xml.StaxReader.pullNextEvent(StaxReader.java:73) ~[?:?]
    at com.thoughtworks.xstream.io.xml.AbstractPullReader.readRealEvent(AbstractPullReader.java:148) ~[?:?]
    at com.thoughtworks.xstream.io.xml.AbstractPullReader.readEvent(AbstractPullReader.java:135) ~[?:?]
    at com.thoughtworks.xstream.io.xml.AbstractPullReader.hasMoreChildren(AbstractPullReader.java:87) ~[?:?]
    at com.thoughtworks.xstream.io.ReaderWrapper.hasMoreChildren(ReaderWrapper.java:32) ~[?:?]
    at com.thoughtworks.xstream.io.ReaderWrapper.hasMoreChildren(ReaderWrapper.java:32) ~[?:?]
    at com.thoughtworks.xstream.converters.collections.CollectionConverter.populateCollection(CollectionConverter.java:89) ~[?:?]
    at com.thoughtworks.xstream.converters.collections.CollectionConverter.populateCollection(CollectionConverter.java:85) ~[?:?]
    at com.thoughtworks.xstream.converters.collections.CollectionConverter.unmarshal(CollectionConverter.java:80) ~[?:?]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) ~[?:?]
    ... 40 more
Caused by: javax.xml.stream.XMLStreamException: ParseError at [row,col]:[717,4]
Message: Stream closed
    at com.sun.org.apache.xerces.internal.impl.XMLStreamReaderImpl.next(XMLStreamReaderImpl.java:599) ~[?:?]
    at com.thoughtworks.xstream.io.xml.StaxReader.pullNextEvent(StaxReader.java:58) ~[?:?]
    at com.thoughtworks.xstream.io.xml.AbstractPullReader.readRealEvent(AbstractPullReader.java:148) ~[?:?]
    at com.thoughtworks.xstream.io.xml.AbstractPullReader.readEvent(AbstractPullReader.java:135) ~[?:?]
    at com.thoughtworks.xstream.io.xml.AbstractPullReader.hasMoreChildren(AbstractPullReader.java:87) ~[?:?]
    at com.thoughtworks.xstream.io.ReaderWrapper.hasMoreChildren(ReaderWrapper.java:32) ~[?:?]
    at com.thoughtworks.xstream.io.ReaderWrapper.hasMoreChildren(ReaderWrapper.java:32) ~[?:?]
    at com.thoughtworks.xstream.converters.collections.CollectionConverter.populateCollection(CollectionConverter.java:89) ~[?:?]
    at com.thoughtworks.xstream.converters.collections.CollectionConverter.populateCollection(CollectionConverter.java:85) ~[?:?]
    at com.thoughtworks.xstream.converters.collections.CollectionConverter.unmarshal(CollectionConverter.java:80) ~[?:?]
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) ~[?:?]
    ... 40 more
2017-10-19 20:21:01.459 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channels for channel group 'sensor' for thing type 'nibeheatpump:f1x45-udp:nibe', because channel group type 'nibeheatpump:f1x45-sensor-group-channels' could not be found.
2017-10-19 20:21:01.460 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channels for channel group 'setting' for thing type 'nibeheatpump:f1x45-udp:nibe', because channel group type 'nibeheatpump:f1x45-setting-group-channels' could not be found.
2017-10-19 20:21:01.535 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occurred while initializing handler of thing 'nibeheatpump:f1x45-udp:nibe': Thread was interrupted.
java.lang.IllegalStateException: Thread was interrupted.
    at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:85) ~[?:?]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:67) ~[?:?]
    at org.eclipse.smarthome.core.thing.internal.ThingManager.doInitializeHandler(ThingManager.java:633) ~[?:?]
    at org.eclipse.smarthome.core.thing.internal.ThingManager.initializeHandler(ThingManager.java:568) ~[?:?]
    at org.eclipse.smarthome.core.thing.internal.ThingManager.registerAndInitializeHandler(ThingManager.java:955) ~[?:?]
    at org.eclipse.smarthome.core.thing.internal.ThingManager.lambda$2(ThingManager.java:937) ~[?:?]
    at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:890) ~[?:?]
    at java.util.concurrent.CopyOnWriteArraySet.forEach(CopyOnWriteArraySet.java:404) ~[?:?]
    at org.eclipse.smarthome.core.thing.internal.ThingManager.lambda$1(ThingManager.java:934) ~[?:?]
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) ~[?:?]
    at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) ~[?:?]
    at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948) ~[?:?]
    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) ~[?:?]
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) ~[?:?]
    at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) ~[?:?]
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) ~[?:?]
    at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
    at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418) ~[?:?]
    at org.eclipse.smarthome.core.thing.internal.ThingManager.handleThingHandlerFactoryAddition(ThingManager.java:933) ~[?:?]
    at org.eclipse.smarthome.core.thing.internal.ThingManager.onReadyMarkerAdded(ThingManager.java:921) ~[?:?]
    at org.eclipse.smarthome.core.internal.service.ReadyServiceImpl.lambda$0(ReadyServiceImpl.java:48) ~[?:?]
    at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) [?:?]
    at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193) [?:?]
    at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175) [?:?]
    at java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1691) [?:?]
    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481) [?:?]
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471) [?:?]
    at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) [?:?]
    at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) [?:?]
    at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) [?:?]
    at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:418) [?:?]
    at org.eclipse.smarthome.core.internal.service.ReadyServiceImpl.notifyTrackers(ReadyServiceImpl.java:75) [108:org.eclipse.smarthome.core:0.9.0.201709260841]
    at org.eclipse.smarthome.core.internal.service.ReadyServiceImpl.markReady(ReadyServiceImpl.java:48) [108:org.eclipse.smarthome.core:0.9.0.201709260841]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.registerReadyMarker(XmlDocumentBundleTracker.java:361) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.finishBundle(XmlDocumentBundleTracker.java:311) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.processBundle(XmlDocumentBundleTracker.java:334) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker.access$3(XmlDocumentBundleTracker.java:326) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at org.eclipse.smarthome.config.xml.osgi.XmlDocumentBundleTracker$2.run(XmlDocumentBundleTracker.java:302) [107:org.eclipse.smarthome.config.xml:0.9.0.201709260841]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
    at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.lang.InterruptedException
    at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:404) ~[?:?]
    at java.util.concurrent.FutureTask.get(FutureTask.java:204) ~[?:?]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:194) ~[?:?]
    at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:83) ~[?:?]
    ... 44 more

Error line varies

2017-10-19 20:43:02.653 [WARN ] [ig.xml.osgi.XmlDocumentBundleTracker] - The XML document '/ESH-INF/thing/f1x45-types.xml' in module 'org.openhab.binding.nibeheatpump' could not be parsed:  : ParseError at [row,col]:[2214,4]
Message: Stream closed :  : ParseError at [row,col]:[2214,4]
htreu commented 6 years ago

Although this is really strange behaviour, does it help to split the 5k line channel-type definition into smaller chunks? Does parsing on start up succeed every time, and parsing during runtime deployment fail every time?

paulianttila commented 6 years ago

Does parsing on start up succeed every time, and parsing during runtime deployment fail every time?

Yes, I have tested it over 10 times. I meet this problem half an year ago, when I started to migrate my OH1 system to OH2. I updated the latest snapshot yesterday with the same result. I run my "production" system in NUC (Celeron J3455). I have pretty busy production system. Currently 28 bindings + 23 UI, persistence, transformation, misc, etc addons. Around 1000 items.

I tried to reproduce the problem with clean OH install (latest snapshot) and just this one problematic binding. Problem does not occur in this environment (MacBook Pro 2,5 GHz Intel Core i7).

does it help to split the 5k line channel-type definition into smaller chunks?

I have not tested. But I remember that when I first meat the problem I quickly generated thin version, which only had channels which I really needed (around 25 channels). Full file contains over 700 channels. With this thin version I didn't see this problem.

htreu commented 6 years ago

Just a wild guess but this may also be a memory issue: You could try to give your openHAB instance some more memory? btw: what Java version does your openHAB run on? could you post the output of java --version from the NUC system?

paulianttila commented 6 years ago

I have installed openHAB via openHABian. Java is updated many times. I will increase memory next time when I need to restart the OH, even I have not seen (ever) any OutOfMemory exceptions.

openhab> shell:info                                                                                                                                              19:20:18
Karaf
  Karaf version               4.1.2
  Karaf home                  /usr/share/openhab2/runtime
  Karaf base                  /var/lib/openhab2
  OSGi Framework              org.eclipse.osgi-3.11.3.v20170209-1843

JVM
  Java Virtual Machine        Java HotSpot(TM) 64-Bit Server VM version 25.144-b01
  Version                     1.8.0_144
  Vendor                      Oracle Corporation
  Pid                         10308
  Uptime                      4 days 22 hours
  Total compile time          11 minutes
Threads
  Live threads                271
  Daemon threads              130
  Peak                        274
  Total started               2516093
Memory
  Current heap size           195,858 kbytes
  Maximum heap size           974,848 kbytes
  Committed heap size         249,856 kbytes
  Pending objects             0
  Garbage collector           Name = 'G1 Young Generation', Collections = 151779, Time = 43 minutes
  Garbage collector           Name = 'G1 Old Generation', Collections = 0, Time = 0.000 seconds
Classes
  Current classes loaded      24,429
  Total classes loaded        1,285,010
  Total classes unloaded      1,260,581
Operating system
  Name                        Linux version 4.4.0-96-generic
  Architecture                amd64
  Processors                  4
htreu commented 6 years ago

Yes, memory looks good from the logs. But the difference between parsing at startup and at runtime points to some environmental effects. What about splitting the channel definitions into several files: If this fixes the issue right now maybe its the most easy way to overcome this situation. Is there a logical difference in channel types which allows sane splitting?

paulianttila commented 6 years ago

Just increased the OH memory

Memory
  Current heap size           594,944 kbytes
  Maximum heap size           2,097,152 kbytes
  Committed heap size         1,048,576 kbytes

It didn't solve the problem. If I remove and then add jar file to addon folder, I see the same parsing failure. After failure, if I stop and then start the bundle from osgi console it start without parsing problems.

Really weird.