openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.88k stars 3.58k forks source link

[smartmeter] Missing exception handling #4462

Closed ggzengel closed 5 years ago

ggzengel commented 5 years ago

@msteigenberger I just migrated to OH2.4.0 and I'm happy that smartmeter still works like a charm. Thanks again for your work.

While running OH2.40 I can see an exception after stressing OH with missing onewire sensors. The main problem is the onewire binding but I think smartmeter shouldn't throw exceptions to systems syslog.

00:47:24.346 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'onewire:owserver:server1' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)

While stressing the poll interval from smartmeter raises from 2 sec to 90 sec and smartmeter gets a timeout. The strange thing is that CPU load is nearby 0.

In openhab I see:

00:47:24.293 [WARN ] [nding.smartmeter.internal.MeterDevice] - Failed to read: The source did not signal an event for 30 seconds and has been terminated.. Closing connection and trying again in 2 seconds...; smartmeter:meter:EHZ_WP
java.util.concurrent.TimeoutException: The source did not signal an event for 30 seconds and has been terminated.
    at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:139) [231:org.openhab.binding.smartmeter:2.4.0]
    at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:170) [231:org.openhab.binding.smartmeter:2.4.0]
    at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:260) [231:org.openhab.binding.smartmeter:2.4.0]
    at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:225) [231:org.openhab.binding.smartmeter:2.4.0]
    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) [?:?]
00:47:24.295 [WARN ] [nding.smartmeter.internal.MeterDevice] - Failed to read: The source did not signal an event for 30 seconds and has been terminated.. Closing connection and trying again in 2 seconds...; smartmeter:meter:EHZ_PV
java.util.concurrent.TimeoutException: The source did not signal an event for 30 seconds and has been terminated.
    at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:139) [231:org.openhab.binding.smartmeter:2.4.0]
    at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:170) [231:org.openhab.binding.smartmeter:2.4.0]
    at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:260) [231:org.openhab.binding.smartmeter:2.4.0]
    at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:225) [231:org.openhab.binding.smartmeter:2.4.0]
    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) [?:?]
00:47:24.296 [WARN ] [nding.smartmeter.internal.MeterDevice] - Failed to read: The source did not signal an event for 30 seconds and has been terminated.. Closing connection and trying again in 2 seconds...; smartmeter:meter:EHZ_MAIN
java.util.concurrent.TimeoutException: The source did not signal an event for 30 seconds and has been terminated.
    at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:139) [231:org.openhab.binding.smartmeter:2.4.0]
    at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:170) [231:org.openhab.binding.smartmeter:2.4.0]
    at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker$BooleanRunnable.run(ExecutorScheduler.java:260) [231:org.openhab.binding.smartmeter:2.4.0]
    at io.reactivex.internal.schedulers.ExecutorScheduler$ExecutorWorker.run(ExecutorScheduler.java:225) [231:org.openhab.binding.smartmeter:2.4.0]
    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) [?:?]

In syslog I see:

Dec 28 00:47:24 openhab2 karaf[11123]: io.reactivex.exceptions.UndeliverableException: The exception could not be delivered to the consumer because it has already canceled/disposed the flow or the exception has nowhere to go to begin with. Further reading: https://github.com/ReactiveX/RxJava/wiki/What's-different-in-2.0#error-handling | java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.plugins.RxJavaPlugins.onError(RxJavaPlugins.java:367)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate$BaseEmitter.onError(FlowableCreate.java:275)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:74)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14479)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14426)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:163)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableTimer$TimerSubscriber.run(FlowableTimer.java:76)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.FutureTask.run(FutureTask.java:266)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.lang.Thread.run(Thread.java:748)
Dec 28 00:47:24 openhab2 karaf[11123]: Caused by: java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.getInIfOpen(BufferedInputStream.java:159)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.available(BufferedInputStream.java:410)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.FilterInputStream.available(FilterInputStream.java:168)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.fillBufferWithTimeout(MessageExtractor.java:170)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.waitForStopSequence(MessageExtractor.java:69)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.getSmlMessage(MessageExtractor.java:42)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.Transport.getSMLFile(Transport.java:101)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:88)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:1)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.emitValues(ConnectorBase.java:149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.lambda$2(ConnectorBase.java:120)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:71)
Dec 28 00:47:24 openhab2 karaf[11123]: #011... 12 more
Dec 28 00:47:24 openhab2 karaf[11123]: Exception in thread "ESH-thingHandler-5" io.reactivex.exceptions.UndeliverableException: The exception could not be delivered to the consumer because it has already canceled/disposed the flow or the exception has nowhere to go to begin with. Further reading: https://github.com/ReactiveX/RxJava/wiki/What's-different-in-2.0#error-handling | java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.plugins.RxJavaPlugins.onError(RxJavaPlugins.java:367)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate$BaseEmitter.onError(FlowableCreate.java:275)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:74)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14479)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14426)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:163)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableTimer$TimerSubscriber.run(FlowableTimer.java:76)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.FutureTask.run(FutureTask.java:266)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.lang.Thread.run(Thread.java:748)
Dec 28 00:47:24 openhab2 karaf[11123]: Caused by: java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.getInIfOpen(BufferedInputStream.java:159)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.available(BufferedInputStream.java:410)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.FilterInputStream.available(FilterInputStream.java:168)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.fillBufferWithTimeout(MessageExtractor.java:170)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.waitForStopSequence(MessageExtractor.java:69)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.getSmlMessage(MessageExtractor.java:42)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.Transport.getSMLFile(Transport.java:101)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:88)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:1)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.emitValues(ConnectorBase.java:149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.lambda$2(ConnectorBase.java:120)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:71)
Dec 28 00:47:24 openhab2 karaf[11123]: #011... 12 more
Dec 28 00:47:24 openhab2 karaf[11123]: io.reactivex.exceptions.UndeliverableException: The exception could not be delivered to the consumer because it has already canceled/disposed the flow or the exception has nowhere to go to begin with. Further reading: https://github.com/ReactiveX/RxJava/wiki/What's-different-in-2.0#error-handling | java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.plugins.RxJavaPlugins.onError(RxJavaPlugins.java:367)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate$BaseEmitter.onError(FlowableCreate.java:275)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:74)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14479)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14426)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:163)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableTimer$TimerSubscriber.run(FlowableTimer.java:76)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.FutureTask.run(FutureTask.java:266)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.lang.Thread.run(Thread.java:748)
Dec 28 00:47:24 openhab2 karaf[11123]: Caused by: java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.getInIfOpen(BufferedInputStream.java:159)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.available(BufferedInputStream.java:410)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.FilterInputStream.available(FilterInputStream.java:168)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.fillBufferWithTimeout(MessageExtractor.java:170)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.waitForStopSequence(MessageExtractor.java:69)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.getSmlMessage(MessageExtractor.java:42)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.Transport.getSMLFile(Transport.java:101)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:88)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:1)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.emitValues(ConnectorBase.java:149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.lambda$2(ConnectorBase.java:120)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:71)
Dec 28 00:47:24 openhab2 karaf[11123]: #011... 12 more
Dec 28 00:47:24 openhab2 karaf[11123]: Exception in thread "ESH-thingHandler-1" io.reactivex.exceptions.UndeliverableException: The exception could not be delivered to the consumer because it has already canceled/disposed the flow or the exception has nowhere to go to begin with. Further reading: https://github.com/ReactiveX/RxJava/wiki/What's-different-in-2.0#error-handling | java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.plugins.RxJavaPlugins.onError(RxJavaPlugins.java:367)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate$BaseEmitter.onError(FlowableCreate.java:275)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:74)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14479)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14426)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:163)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableTimer$TimerSubscriber.run(FlowableTimer.java:76)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.FutureTask.run(FutureTask.java:266)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.lang.Thread.run(Thread.java:748)
Dec 28 00:47:24 openhab2 karaf[11123]: Caused by: java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.getInIfOpen(BufferedInputStream.java:159)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.available(BufferedInputStream.java:410)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.FilterInputStream.available(FilterInputStream.java:168)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.fillBufferWithTimeout(MessageExtractor.java:170)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.waitForStopSequence(MessageExtractor.java:69)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.getSmlMessage(MessageExtractor.java:42)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.Transport.getSMLFile(Transport.java:101)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:88)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:1)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.emitValues(ConnectorBase.java:149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.lambda$2(ConnectorBase.java:120)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:71)
Dec 28 00:47:24 openhab2 karaf[11123]: #011... 12 more
Dec 28 00:47:24 openhab2 karaf[11123]: io.reactivex.exceptions.UndeliverableException: The exception could not be delivered to the consumer because it has already canceled/disposed the flow or the exception has nowhere to go to begin with. Further reading: https://github.com/ReactiveX/RxJava/wiki/What's-different-in-2.0#error-handling | java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.plugins.RxJavaPlugins.onError(RxJavaPlugins.java:367)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate$BaseEmitter.onError(FlowableCreate.java:275)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:74)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14479)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14426)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:163)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableTimer$TimerSubscriber.run(FlowableTimer.java:76)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.FutureTask.run(FutureTask.java:266)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.lang.Thread.run(Thread.java:748)
Dec 28 00:47:24 openhab2 karaf[11123]: Caused by: java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.getInIfOpen(BufferedInputStream.java:159)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.available(BufferedInputStream.java:410)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.FilterInputStream.available(FilterInputStream.java:168)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.fillBufferWithTimeout(MessageExtractor.java:170)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.waitForStopSequence(MessageExtractor.java:69)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.getSmlMessage(MessageExtractor.java:42)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.Transport.getSMLFile(Transport.java:101)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:88)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:1)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.emitValues(ConnectorBase.java:149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.lambda$2(ConnectorBase.java:120)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:71)
Dec 28 00:47:24 openhab2 karaf[11123]: #011... 12 more
Dec 28 00:47:24 openhab2 karaf[11123]: Exception in thread "ESH-thingHandler-2" io.reactivex.exceptions.UndeliverableException: The exception could not be delivered to the consumer because it has already canceled/disposed the flow or the exception has nowhere to go to begin with. Further reading: https://github.com/ReactiveX/RxJava/wiki/What's-different-in-2.0#error-handling | java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.plugins.RxJavaPlugins.onError(RxJavaPlugins.java:367)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate$BaseEmitter.onError(FlowableCreate.java:275)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:74)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14479)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.Flowable.subscribe(Flowable.java:14426)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:163)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableTimer$TimerSubscriber.run(FlowableTimer.java:76)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.FutureTask.run(FutureTask.java:266)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.lang.Thread.run(Thread.java:748)
Dec 28 00:47:24 openhab2 karaf[11123]: Caused by: java.io.IOException: Stream closed
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.getInIfOpen(BufferedInputStream.java:159)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.BufferedInputStream.available(BufferedInputStream.java:410)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at java.io.FilterInputStream.available(FilterInputStream.java:168)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.fillBufferWithTimeout(MessageExtractor.java:170)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.waitForStopSequence(MessageExtractor.java:69)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.MessageExtractor.getSmlMessage(MessageExtractor.java:42)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openmuc.jsml.transport.Transport.getSMLFile(Transport.java:101)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:88)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:1)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.emitValues(ConnectorBase.java:149)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at org.openhab.binding.smartmeter.connectors.ConnectorBase.lambda$2(ConnectorBase.java:120)
Dec 28 00:47:24 openhab2 karaf[11123]: #011at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:71)
Dec 28 00:47:24 openhab2 karaf[11123]: #011... 12 more

My config:

smartmeter:meter:EHZ_PV   "EHZ_PV"   [ port="rfc2217://192.168.180.131:3003", refresh=1, mode="SML" ] {
    Channels:
        Type 1-0_2-8-0 : 1-0_2-8-0 [
            conversionRatio=1000
        ]
}

smartmeter:meter:EHZ_MAIN "EHZ_MAIN" [ port="rfc2217://192.168.180.131:3002", refresh=1, mode="SML" ] {
    Channels:
        Type 1-0_1-8-0 : 1-0_1-8-0 [
            conversionRatio=1000
        ]
        Type 1-0_2-8-0 : 1-0_2-8-0 [
            conversionRatio=1000
        ]
        Type 1-0_15-7-0 : 1-0_15-7-0 [
            negate="1-0_1-8-0:5:1:status"
        ]
}

smartmeter:meter:EHZ_WP   "EHZ_WP"   [ port="rfc2217://192.168.180.131:3001", refresh=1, mode="SML" ] {
    Channels:
        Type 1-0_1-8-0 : 1-0_1-8-0 [
            conversionRatio=1000
        ]
}
wborn commented 5 years ago

Other bindings (e.g. Nest) set Things offline with an appropriate message whenever commands fail due to timeouts. That way logs are not filled with stack traces and users can see such problems in UIs such as Paper UI.

msteigenberger commented 5 years ago

@ggzengel: thanks for noticing this. If I get it right, the only thing that is not working is the hard-coded 30 second timeout, right? I would make it dependant on the refresh interval. The thing with the syslog is cosmetic. I will try to get this fixed as well. RxJava is doing this, as the source publisher is getting destroyed asynchronously while still waiting for a message from the device.

@wborn: The thing is set offline in the above case with an appropriate error message already. But I think it would really be better to not waste the log in case of timeouts (only a short warning message).

@ggzengel: short note about your thing configuration: conversionRatio is not supported anymore and is therefore ignored.

ggzengel commented 5 years ago

@msteigenberger The timeout is not a problem. OH was stressed by a lot of reconfiguration/testing and smartmeter works like a charm. It was only the cosmetic thing that I found an exception in /var/log/syslog.

Perhaps there should be an exception handler in ESH which catch exceptions before they are leaving the VM.

wborn commented 5 years ago

waste the log in case of timeouts (only a short warning message)

If the status message is clear enough you could also log the exception on debug. That way the full stacktrace is preserved for developers. See also the Logging Coding Guidelines:

For bindings, you should NOT log errors, if e.g. connections are dropped - this is considered to be an external problem and from a system perspective to be a normal and expected situation. The correct way to inform users about such events is to update the Thing status accordingly. Note that all events (including Thing status events) are anyhow already logged.

ggzengel commented 5 years ago

@msteigenberger After removing conversionRatio the values jumped by factor of 1000.

msteigenberger commented 5 years ago

@ggzengel: yeah, the configuration is indeed not ignored, but undocumented and not available in the configuration through PaperUI and also deprecated. You should rather use the UOM capability of OH. In your item definition you just need to mention the correct unit (like kWh).

@wborn: thanks for pointing to this!