SML Reader - how to integrate

msteigenberger · June 1, 2018, 9:15pm

Which protocol mode are you using?
Just tested it: turned on TV -> after a second I saw the change.
But I’m only testing SML. Does it work for you with previous versions? (you can download with link from one of previous posts).

Joerg_Schreiner · June 2, 2018, 9:32am

Hi,
I also get a lot of CRC errors with java exceptions after updating to OpenHAB 2.3 and untilizing your latest JAR out of this thread.

2018-06-02 11:02:56.840 [ERROR] [ing.meterreader.internal.MeterDevice] - Failed to read: java.io.IOException: wrong crc. Closing connection and trying again…; meterreader:meter:a98e9c5c
java.lang.RuntimeException: java.io.IOException: wrong crc
at com.google.common.base.Throwables.propagate(Throwables.java:160) ~[23:com.google.guava:18.0.0]
at org.openhab.binding.meterreader.connectors.ConnectorBase.lambda$0(ConnectorBase.java:82) ~[244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.functions.Functions$Array2Func.apply(Functions.java:529) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.functions.Functions$Array2Func.apply(Functions.java:516) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableZip$ZipCoordinator.drain(FlowableZip.java:241) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableZip$ZipSubscriber.onNext(FlowableZip.java:383) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.processors.UnicastProcessor.drainFused(UnicastProcessor.java:254) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.processors.UnicastProcessor.drain(UnicastProcessor.java:287) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.processors.UnicastProcessor.onNext(UnicastProcessor.java:349) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.processors.SerializedProcessor.onNext(SerializedProcessor.java:103) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableRepeatWhen$WhenSourceSubscriber.again(FlowableRepeatWhen.java:170) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableRetryWhen$RetryWhenSubscriber.onError(FlowableRetryWhen.java:77) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.checkTerminate(FlowableFlatMap.java:566) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.drainLoop(FlowableFlatMap.java:374) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.drain(FlowableFlatMap.java:366) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.innerError(FlowableFlatMap.java:605) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableFlatMap$InnerSubscriber.onError(FlowableFlatMap.java:668) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableCreate$BaseEmitter.error(FlowableCreate.java:288) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableCreate$BaseEmitter.tryOnError(FlowableCreate.java:277) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableCreate$BaseEmitter.onError(FlowableCreate.java:270) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:75) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.Flowable.subscribe(Flowable.java:14291) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.Flowable.subscribe(Flowable.java:14237) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:163) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableOnBackpressureDrop$BackpressureDropSubscriber.onNext(FlowableOnBackpressureDrop.java:84) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableBuffer$PublisherBufferExactSubscriber.onNext(FlowableBuffer.java:126) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.operators.flowable.FlowableInterval$IntervalSubscriber.run(FlowableInterval.java:93) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at io.reactivex.internal.schedulers.ScheduledDirectPeriodicTask.run(ScheduledDirectPeriodicTask.java:38) [244:org.openhab.binding.meterreader:2.3.0.201804202130]
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [?:?]
at java.util.concurrent.FutureTask.runAndReset(Unknown Source) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(Unknown Source) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
at java.lang.Thread.run(Unknown Source) [?:?]

msteigenberger · June 15, 2018, 8:49pm

@Joerg_Schreiner: Didn’t you get this in the past? Are there any reads that are working?

Joerg_Schreiner · June 24, 2018, 8:19am

Sorry for the late answer. I was on vacation.
Yess, a lot of other reads are working and no, I haven’t got this in the past.
Maybe one or two CRC errors a week, but without any JAVA exceptions.

Additional infos:
2018-06-24 09:17:50.178 [INFO ] [ing.meterreader.internal.MeterDevice] - Opening connection to meterreader:meter:a98e9c5c
2018-06-24 09:20:40.198 [WARN ] [ader.internal.sml.SmlSerialConnector] - 1. reading attempt failed: wrong crc. Retrying COM5…
2018-06-24 09:20:40.199 [WARN ] [ader.internal.sml.SmlSerialConnector] - Delaying retry by PT1S
2018-06-24 09:29:01.182 [WARN ] [ader.internal.sml.SmlSerialConnector] - 2. reading attempt failed: wrong crc. Retrying COM5…
2018-06-24 09:29:01.183 [WARN ] [ader.internal.sml.SmlSerialConnector] - Delaying retry by PT2S
2018-06-24 09:32:23.204 [WARN ] [ader.internal.sml.SmlSerialConnector] - 3. reading attempt failed: wrong crc. Retrying COM5…
2018-06-24 09:32:23.206 [WARN ] [ader.internal.sml.SmlSerialConnector] - Delaying retry by PT3S
2018-06-24 09:35:36.220 [ERROR] [ing.meterreader.internal.MeterDevice] - Failed to read: java.io.IOException: wrong crc. Closing connection and trying again…; meterreader:meter:a98e9c5c
Then, it works again for quite a while.

Joerg_Schreiner · August 9, 2018, 10:11am

Hi,
I haven’t got any feedback, but I was able to solve the problem and I want to share it with you.
My issue was, that I had an older version of the jar file in the addons folder with the filetype renamed.
(xxxx.jar -> xxx.jar.old)
It seems, as if OpenHAB is ignoring the filetype and is executing every file in the folder expecting it to be a JAR file.
This led th the consequence that both versions were running at the same time and produced these errors.
I think, I will file an issue @OpenHAB as this behaviour is at least irritating.

halloween · August 18, 2018, 9:39am

I have a little problem with the meterreader binding for my sml readers.

They worked a logn time with the script from the first post. A few months ago i changed my configuration and installed the sml meterreader binding. It worked good. But since i made a few snapshots update the last month, after some time (maybe 20 minutes) the meterreader doenst provide any new data. If i make a openhab service restart, it immediately starts wokring again for another few minutes.

I didn´t change configuration in paper ui. It is all the same like before.

I changed to meterreader 2.3 binding, but still no success.

In paper ui my two readers are still online all the time.

I use the ir-readers from udo from volkszahler.org

halloween · August 21, 2018, 8:03am

@msteigenberger

Do you need further informations or logfiles for localizing the error?

What do i need to provide?

My sml-meterreader binding starts rerading after a service restart of openhab and stops reading about 20-30 minutes after that.

halloween · August 21, 2018, 9:17am

When shutting down openhab service i can see this messages in the openhab.log

Maybe it can help?

2018-08-21 11:16:07.046 [WARN ] [ome.core.thing.internal.ThingManager] - Disposing handler for thing 'meterreader:meter:770bed4f' takes more than 5000ms.

2018-08-21 11:16:07.049 [ERROR] [ader.internal.sml.SmlSerialConnector] - Failed to close serial output stream

java.io.IOException: null

	at gnu.io.RXTXPort$SerialOutputStream.flush(RXTXPort.java:1225) [191:com.neuronrobotics.nrjavaserial:3.14.0]

	at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:141) [?:?]

	at java.io.DataOutputStream.flush(DataOutputStream.java:123) [?:?]

	at java.io.FilterOutputStream.close(FilterOutputStream.java:158) [?:?]

	at org.openhab.binding.meterreader.internal.sml.SmlSerialConnector.closeConnection(SmlSerialConnector.java:143) [186:org.openhab.binding.meterreader:2.3.0.201804040440]

	at org.openhab.binding.meterreader.internal.MeterDevice$1.cancel(MeterDevice.java:148) [186:org.openhab.binding.meterreader:2.3.0.201804040440]

	at org.openhab.binding.meterreader.internal.MeterReaderHandler.cancelRead(MeterReaderHandler.java:102) [186:org.openhab.binding.meterreader:2.3.0.201804040440]

	at org.openhab.binding.meterreader.internal.MeterReaderHandler.dispose(MeterReaderHandler.java:97) [186:org.openhab.binding.meterreader:2.3.0.201804040440]

	at sun.reflect.GeneratedMethodAccessor319.invoke(Unknown Source) ~[?:?]

	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]

	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]

	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [94:org.eclipse.smarthome.core:0.10.0.201808130936]

	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201808130936]

	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]

	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) [?:?]

	Suppressed: java.io.IOException

		at gnu.io.RXTXPort$SerialOutputStream.flush(RXTXPort.java:1225) [191:com.neuronrobotics.nrjavaserial:3.14.0]

		at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:141) [?:?]

		at java.io.FilterOutputStream.close(FilterOutputStream.java:158) [?:?]

		at java.io.FilterOutputStream.close(FilterOutputStream.java:159) [?:?]

		at org.openhab.binding.meterreader.internal.sml.SmlSerialConnector.closeConnection(SmlSerialConnector.java:143) [186:org.openhab.binding.meterreader:2.3.0.201804040440]

		at org.openhab.binding.meterreader.internal.MeterDevice$1.cancel(MeterDevice.java:148) [186:org.openhab.binding.meterreader:2.3.0.201804040440]

		at org.openhab.binding.meterreader.internal.MeterReaderHandler.cancelRead(MeterReaderHandler.java:102) [186:org.openhab.binding.meterreader:2.3.0.201804040440]

		at org.openhab.binding.meterreader.internal.MeterReaderHandler.dispose(MeterReaderHandler.java:97) [186:org.openhab.binding.meterreader:2.3.0.201804040440]

		at sun.reflect.GeneratedMethodAccessor319.invoke(Unknown Source) ~[?:?]

		at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]

		at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]

		at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [94:org.eclipse.smarthome.core:0.10.0.201808130936]

		at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201808130936]

		at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]

		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) [?:?]

halloween · August 21, 2018, 10:04am

And another question:

Now my Openhab-Server is in the same place where my power meters are located.

I want to move the server to another room, but my ir-readers are connected with usb to the server.

Is there a way to use a raspi3 for this and send the values to the openhab server over the network?

Maybe with nrjavaserial? Is there some documentation or a how-to to do this? I´m no linux expert…

msteigenberger · August 21, 2018, 5:39pm

@halloween: what is your refresh rate?
I see that you’re using a 2.4 snapshot of openhab (because nrjavaserial 3.14.0 is used). Did it happen also with older version?
Probably the binding waits for data from your device.Can you execute following command and paste the output here:
jstack <PID_OF_OPENHAB>
The pid you can find out with top or ps.

msteigenberger · August 21, 2018, 5:45pm

@halloween: regarding your raspi3 usecase: yes there will be. RFC2217 is been integrated into ESH now with https://github.com/eclipse/smarthome/pull/5560
The Meterreader binding is just before supporting this (actually your version is already but with a little hack).
All you need to do is to setup ser2net on your raspi3 and set the port and host in the binding’s serial port field e.g. rfc2217://192.168.xxx.xxx:3001.

halloween · August 22, 2018, 5:54am

With ps i get not openhab-process showing, only bash and one other thing.

With top i get many things, only thing which could be openhab2 process is the process java with the pid 2375.

With jstack 2375 i get “operation not allowed”

with sudo jstack 2375 i get:
2375: unabale to open socket file: target process not responding or HotSpot VM not loaded
The F option can be used when not responding…

With -F option i get many pages of thread informations… Do you need this? It is very very much…

Formerly i was on snapshot version from (the time about) 17.05.2017, i think this was already 2.4 snapshot - there all worked and sml reader never stopped. Then i made the first snapshot update end of july and then after some time sml reader stopped working. I made many snapshot updates in august, but nothing changed.

Here is the configuration of one of my power meters from paper ui:

msteigenberger · August 22, 2018, 7:50am

With -F option i get many pages of thread informations… Do you need this?

Yes I need exactly this

halloween · August 22, 2018, 8:04am

Here it is:

Too big for posting directly, so i copied it to a xml-file (txt is not allowed):

output.xml (154.2 KB)

msteigenberger · August 22, 2018, 5:39pm

It seems nrjavaserial is hanging in some native code when closing:

Thread 2674: (state = IN_NATIVE)
 - gnu.io.RXTXPort.interruptEventLoop() @bci=0 (Interpreted frame)
 - gnu.io.RXTXPort.removeEventListener() @bci=55, line=859 (Interpreted frame)
 - gnu.io.RXTXPort.close() @bci=67, line=1082 (Interpreted frame)
 - org.openhab.binding.meterreader.internal.sml.SmlSerialConnector.closeConnection() @bci=71, line=150 (Interpreted frame)

The next opening of the port is then hanging because of the native mutex:

Thread 2636: (state = BLOCKED)
 - java.lang.Thread.sleep(long) @bci=0 (Compiled frame; information may be imprecise)
 - gnu.io.RXTXPort.	() @bci=10, line=903 (Compiled frame)
 - gnu.io.RXTXPort.<init>(java.lang.String) @bci=152, line=132 (Interpreted frame)
 - gnu.io.RXTXCommDriver.getCommPort(java.lang.String, int) @bci=41, line=984 (Compiled frame)
 - gnu.io.CommPortIdentifier.open(java.lang.String, int) @bci=171, line=465 (Compiled frame)

It seems to me like this issue:

Please comment on the issue to get it more prioritized.

Note: this issue will not occur when using rfc2217 as you anyhow want to do.

halloween · August 23, 2018, 6:15am

I made a post in this issue, i hope this is enough information i provided.

halloween · August 23, 2018, 9:25am

I made some more loggings.

Now i can say you something new:

I have 2 powermeters. The first one is sending data all the time, the second one stops sending data after a while. The first powermeter maybe stops sending data after a while too, but this time is much longer.

In my persisted data i can see, that first a powermeter stops sending data and after a while the second one also stops sending, but not at the same time.

dascrip · September 12, 2018, 7:28pm

I have a Q3MB1060 and I read the data with the USB-Reader from volkszähler.

I get data, but they are really un-logical for me and does not match to the data displayed on the meter.


21:17:01.640 [INFO ] [smarthome.event.ItemStateChangedEvent] - meterreader_meter_94c9a547_1_0_1_8_0 changed from -100811.8817 to -100811.6965
21:17:01.677 [INFO ] [smarthome.event.ItemStateChangedEvent] - meterreader_meter_94c9a547_1_0_1_8_1 changed from -100811.8817 to -100811.6965
21:17:01.744 [INFO ] [smarthome.event.ItemStateChangedEvent] - meterreader_meter_94c9a547_1_0_16_7_0 changed from 666.78 to 666.88
21:17:01.772 [INFO ] [smarthome.event.ItemStateChangedEvent] - meterreader_meter_94c9a547_1_0_36_7_0 changed from 408.18 to 407.97
21:17:01.795 [INFO ] [smarthome.event.ItemStateChangedEvent] - meterreader_meter_94c9a547_1_0_56_7_0 changed from 172.98 to 173.29
21:17:01.815 [INFO ] [smarthome.event.ItemStateChangedEvent] - meterreader_meter_94c9a547_1_0_76_7_0 changed from 85.62 to 85.61
21:17:01.860 [INFO ] [smarthome.event.ItemStateChangedEvent] - meterreader_meter_94c9a547_1_0_72_7_0 changed from 231.4 to 231.3

Why do I get for 0:1.8.1 a minus value (if this would be truth, I would be happy ;-)) The meter display it shows 1617.
The ID under 0:0.0.9 is correct, so I guess that I am not fully wrong.

Any helpful ideas here?

Anticrashpilot · September 13, 2018, 11:24am

I read all the thread like million time. But still I have problems. My meterreader thing always states: “Status: OFFLINE - COMMUNICATION_ERROR Timeout”

My setup:

QNAP NAS
Openhab 2.2.0
Volkszähler IR-Opto at USB (S0)
org.openhab.binding.meterreader-2.2.0-SNAPSHOT.jar in addon folder
serial binding installed
thing file: meterreader:meter:heating [port="/dev/ttyS0"]

These are the timeout lines in the openhab.log:
2018-09-13 13:07:39.071 [ERROR] [ader.internal.sml.SmlSerialConnector] - Error at SerialConnector.getMeterValuesInternal: Timeout
2018-09-13 13:07:39.074 [ERROR] [erreader.internal.MeterValueListener] -
java.io.IOException: Timeout
at org.openmuc.jsml.transport.MessageExtractor.fillBufferWithTimeout(MessageExtractor.java:158) ~[?:?]
at org.openmuc.jsml.transport.MessageExtractor.waitForStartSequence(MessageExtractor.java:49) ~[?:?]
at org.openmuc.jsml.transport.MessageExtractor.getSmlMessage(MessageExtractor.java:41) ~[?:?]
at org.openmuc.jsml.transport.Transport.getSMLFile(Transport.java:101) ~[?:?]
at org.openhab.binding.meterreader.internal.sml.SmlSerialConnector.getMeterValuesInternal(SmlSerialConnector.java:86) ~[?:?]
at org.openhab.binding.meterreader.internal.sml.SmlSerialConnector.getMeterValuesInternal(SmlSerialConnector.java:1) ~[?:?]
at org.openhab.binding.meterreader.connectors.ConnectorBase.getMeterValues(ConnectorBase.java:55) ~[?:?]
at org.openhab.binding.meterreader.internal.MeterDevice.lambda$1(MeterDevice.java:137) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
at java.lang.Thread.run(Thread.java:745) [?:?]

Please help me…!

Anticrashpilot · September 14, 2018, 8:32am

I found the solution myself. USB driver/rights were not placed correctly in my NAS linux:

[39356.341004] usb 1-2: new full-speed USB device number 3 using xhci_hcd
[39356.639088] [usb.001.003] /sys/devices/platform/soc/fd800000.pcie-external0/pci0001:00/0001:00:00.0/0001:01:00.0/usb1/1-2 added.

After:
mknod /dev/ttyUSB0 c 188 0
insmod /usr/local/modules/cp210x.ko

I got:
[81636.344616] usbcore: registered new interface driver cp210x
[81636.411471] usbserial: USB Serial support registered for cp210x
[81636.482535] cp210x 1-2:1.0: cp210x converter detected
[81636.545414] usb 1-2: cp210x converter now attached to ttyUSB0

And now /dev/ttyUSB0 is working and in Paper UI all detect all Channels are detectec.