Smartmeter Binding throws "unable to open port" after a while

[Bruce_Osborne]

You mention crc errors. Are you sure your serial cable and device are good?

[thomas_letsch_de (Thomas Letsch)]

Hi Bruce,

not quite sure. The USB cable is quite long and the readers are not professionally attached

But until now (OH 2.4) the binding just sometimes reported a CRC error but continued to work. After the update the port in use exceptions occurred.

[thomas_letsch_de (Thomas Letsch)]

Another small thing I recognized:
When disabling the Thing in the PaperUI, I see the following exception in the logs:
2020-03-10 12:26:58.394 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method ‘ThingHandler.dispose()’ on ‘org.openhab.binding.smartmeter.internal.SmartMeterHandler@190a997’: null
java.lang.NullPointerException: null
at org.openhab.binding.smartmeter.internal.SmartMeterHandler.dispose(SmartMeterHandler.java:133) ~[?:?]
at sun.reflect.GeneratedMethodAccessor52.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_222]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_222]
at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]
at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
2020-03-10 12:26:58.407 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while disposing handler of thing ‘smartmeter:meter:44427816’: null
java.lang.NullPointerException: null
at org.openhab.binding.smartmeter.internal.SmartMeterHandler.dispose(SmartMeterHandler.java:133) ~[?:?]
at sun.reflect.GeneratedMethodAccessor52.invoke(Unknown Source) ~[?:?]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_222]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_222]
at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?]
at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]

[Bruce_Osborne]

@thomas_letsch_de

The USB cable is quite long

USB 2 has a 5 meter limit on cable length.

[thomas_letsch_de (Thomas Letsch)]

@Bruce_Osborne

USB 2 has a 5 meter limit on cable length.

Yes, good point, but this should be no problem, mine is about 3m

[rossko57]

@thomas_letsch_de

After the update the port in use exceptions occurred.

Possibly related

Is nrjavaserial still maintained?

Hi all, It looks like nrjavaserial fork used by openHAB is not patched against a certain race condition fixed in the upstream project: https://github.com/NeuronRobotics/nrjavaserial/commit/f010deeb3c0367f469be338f3edf8f6528322063 Compare that to openHAB implementation: An user seemed to hit this bug as reported here: Problem with modbus binding with dynamic on/off I noticed that there are no issues enabled in the openhab/nrjavaserial. Is it still maintained or how is it kept up-to-date w…

[thomas_letsch_de (Thomas Letsch)]

first thing, I changed the refresh rate again to the default 30 sec. It was on 5sec to get faster updates. This seems to reduce the errors reported.
I just scanned through my log file and this is the overview of errors reported there (after an OH restart yesterday):
2020-03-10 17:58:19.194 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: Termination sequence is wrong. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-10 17:58:51.773 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: wrong crc. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-10 19:56:10.454 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: Termination sequence is wrong. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-10 19:56:42.974 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: wrong crc. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-10 21:33:21.613 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: Termination sequence is wrong. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-10 21:33:54.174 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: wrong crc. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-11 00:38:54.029 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: Termination sequence is wrong. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-11 00:39:26.537 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: wrong crc. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-11 03:16:01.347 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: Termination sequence is wrong. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-11 03:16:33.852 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: wrong crc. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-11 03:31:34.906 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: wrong crc. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-11 05:11:19.548 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: Termination sequence is wrong. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-11 05:11:52.098 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: wrong crc. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-11 08:57:10.595 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: wrong crc. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-11 09:29:14.078 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: Termination sequence is wrong. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816
2020-03-11 09:29:46.644 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: wrong crc. Closing connection and trying again in 2 seconds…; smartmeter:meter:44427816

Every few hours there is an error. Most of the time it complains about the termination sequence and the subsequent read fails with wrong crc.

The system is stable for now, perhaps it got better with the increased refresh rate…

Regards,
Thomas

[noppes123 (Ron)]

Looks like your hardware setup is not in a good shape. These CRC errors are supposed to be very rare!

I haven’t checked, but it is not unlikely that the handling of connection errors has changed in the new code and is causing some new issues with your specific setup.

Having said that, the fact that some hardware device or setup worked for (quite) a while is in no way proof that it is still in good shape. Anything can break any moment. And it might just have been that somehow the cable has accidentally been touched lately…

[rossko57]

… or some new unrelated device has introduced interference. I would imagine a meter signal cable is running amongst power feed cables.

To add to what @noppes123 says, the Modbus issue I pointed at involved a serial error that ought to be recoverable causing a port hangup instead. Something in the shared system serial module.
The hangup is likely a new issue … the underlying recoverable errors could have been there forever, usually recovered.

[Bruce_Osborne]

@rossko57

or some new unrelated device has introduced interference.

Good point. I do not think USB cable is shielded.

[thomas_letsch_de (Thomas Letsch)]

Thanks for your analysis!

I will now look into my hardware setup in detail and try to get rid of these errors.

Regards,
Thomas

[cwi (Carl Wilhelm Ihne)]

I come across the very same effect, with 2 of those sensors connected to Raspi via USB, both running into the same crc error resonably often, every few minutes. It usually recovers in next query, but stresses system and OH with broken connection and re-establishment. With OH 2.3 connection was stable, issue appears since 2.4. So might lead to the reported issue around nrjavaserial?

[Schneie (Markus Faus)]

Hi,
I use smartmeter with Rasp-Installation OH2.5 and this works fine for several month.
Now I installed Ubuntu-VM in QNAP-453d with my OH2.5 installation and the smartmeter-Bindung throws the same Error as above.
I tried also a new, fresh Installation on VM with same effect.
The Binding works five minutes, then stops with the “wrong crc” message.
But the ttyUSB0 ist active on maschine.
After OH restart, works five minutes, then stops…
Any ideas?

[Markus2020 (Markus)]

Dear community,

seems like I‘m running into the same issue. I have been using Volkszaehler for monitoring my power meter for 1.5 years without issues, now I want to move everything to openHAB to avoid a hybrid solution running both.

My power meter is an EasyMeter Q3M and I use the common USB infrared sensor/reader from Weidmann. Cable I’m using is the original USB cable from Weidmann which seems to be just a standard cable without any special shielding etc. – I ordered a new (better?) USB cable and ferrit rings to see if the CRC issues are caused by the main power cable which runs parallel to the USB cable. I will let you know about the outcome. Hardware wise this is my last straw.

This is my thing:

smartmeter:meter:BinderPower     [port="/dev/strom", mode="SML", baudrate=9600, refresh=10] {}

My CRC error sequence from the logs/events, everything is handled within a few seconds. Warning, error, opening, running - every few minutes the same story.

==> /var/log/openhab2/openhab.log <==
2021-01-08 10:18:34.381 [WARN ] [ding.smartmeter.internal.MeterDevice] - Failed to read: wrong crc. Closing connection and trying again in 2 seconds...; smartmeter:meter:BinderPower
java.io.IOException: wrong crc
	at org.openmuc.jsml.transport.MessageExtractor.handleEnd(MessageExtractor.java:112) ~[bundleFile:?]
	at org.openmuc.jsml.transport.MessageExtractor.waitForStopSequence(MessageExtractor.java:88) ~[bundleFile:?]
	at org.openmuc.jsml.transport.MessageExtractor.getSmlMessage(MessageExtractor.java:42) ~[bundleFile:?]
	at org.openmuc.jsml.transport.Transport.getSMLFile(Transport.java:101) ~[bundleFile:?]
	at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:95) ~[bundleFile:?]
	at org.openhab.binding.smartmeter.internal.sml.SmlSerialConnector.readNext(SmlSerialConnector.java:1) ~[bundleFile:?]
	at org.openhab.binding.smartmeter.connectors.ConnectorBase.emitValues(ConnectorBase.java:152) ~[bundleFile:?]
	at org.openhab.binding.smartmeter.connectors.ConnectorBase.lambda$2(ConnectorBase.java:123) ~[bundleFile:?]
	at io.reactivex.internal.operators.flowable.FlowableCreate.subscribeActual(FlowableCreate.java:71) [bundleFile:?]
	at io.reactivex.Flowable.subscribe(Flowable.java:14479) [bundleFile:?]
	at io.reactivex.Flowable.subscribe(Flowable.java:14426) [bundleFile:?]
	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:163) [bundleFile:?]
	at io.reactivex.internal.operators.flowable.FlowableTimer$TimerSubscriber.run(FlowableTimer.java:76) [bundleFile:?]
	at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:38) [bundleFile:?]
	at io.reactivex.internal.schedulers.ScheduledDirectTask.call(ScheduledDirectTask.java:26) [bundleFile:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]

==> /var/log/openhab2/events.log <==
2021-01-08 10:18:34.489 [hingStatusInfoChangedEvent] - 'smartmeter:meter:BinderPower' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): wrong crc

==> /var/log/openhab2/openhab.log <==
2021-01-08 10:18:36.490 [INFO ] [ding.smartmeter.internal.MeterDevice] - Opening connection to smartmeter:meter:BinderPower

==> /var/log/openhab2/events.log <==
2021-01-08 10:18:46.591 [hingStatusInfoChangedEvent] - 'smartmeter:meter:BinderPower' changed from OFFLINE (COMMUNICATION_ERROR): wrong crc to ONLINE

Maybe this input might help in this regard.

[Markus2020 (Markus)]

Dear colleagues,

I received my new (better?) USB cable yesterday as well as a package of different sizes of ferrite rings/cores. Before I had up to two CRC issues per minute in openHAB, now it’s fine. I cannot say if the issue already existed with Volkszaehler, maybe there is no logging for CRC issues implemented. At least I didn’t notice.

After I attached the new cable with two ferrite rings/cores on each end of the cable my logs regarding the CRC issues went crazy. After I restarted openHAB (not the Raspberry Pi itself) the issue almost seems to be solved. I encountered two CRC issues yesterday and so far zero for today.

I cannot determine if a simple restart of openHAB solved it or if the invest of ~20€ for the cable and ferrite cores/rings are the fix.

It would be nice if someone else might be willing to purchase similar items and give some feedback.

I purchased the following items on Amazon (let me know if links like these are not allowed here, but maybe it helps for some users):

ROLINE GOLD USB Kabel 2.0 HighSpeed I Typ A - Mini B: Amazon.de: Computer &...

Ferrite Ring, Kbinan 20 Stück ferritkerne Clip-on Ferrite Ring Core RFI EMI...

Thanks and best regards,
Markus

[Tuny (Sebastian)]

Hi, is your problem still solved?

I have the same problem running OH3.1.0 M2 on an Odroid C4.

I randomly receive the “Wrong CRC” messages and at some point, the «smart meter» thing can not connect to the serial port anymore and the communication stays offline. From that point no more data can be read from the meter and I have to restart openhab.

I also changed the USB-Cable (from 5m to 2m) but still the same error.

Looking into the logs gives output like this. Anyone got an idea?

~$ dmesg --human|tail

[ +0,000769] cp210x ttyUSB0: failed set request 0x7 status: -32

[ +0,017139] cp210x ttyUSB0: failed set request 0x7 status: -32

[ +0,003254] cp210x ttyUSB0: failed set request 0x7 status: -32

[ +2,007947] cp210x ttyUSB0: failed set request 0x7 status: -32

[ +0,004078] cp210x ttyUSB0: failed set request 0x7 status: -32

[Mär 9 17:30] cp210x ttyUSB0: failed set request 0x7 status: -32

[ +0,001602] cp210x ttyUSB0: failed set request 0x7 status: -32

[ +0,098042] cp210x ttyUSB0: failed set request 0x7 status: -32

[ +2,017156] cp210x ttyUSB0: failed set request 0x7 status: -32

[ +0,005807] cp210x ttyUSB0: failed set request 0x7 status: -32

~$ dmesg | grep USB

[27416.939672] cp210x ttyUSB0: failed set request 0x7 status: -32

[27418.956828] cp210x ttyUSB0: failed set request 0x7 status: -32

[27418.962635] cp210x ttyUSB0: failed set request 0x7 status: -32

Infromation about USB-device:

~$ lsusb
Bus 002 Device 002: ID 2109:0817 VIA Labs, Inc. USB3.0 Hub
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 004: ID 0403:6001 Future Technology Devices International, Ltd FT232 Serial (UART) IC
Bus 001 Device 003: ID 10c4:ea60 Silicon Labs CP210x UART Bridge
Bus 001 Device 002: ID 2109:2817 VIA Labs, Inc. USB2.0 Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

[thomas_letsch_de (Thomas Letsch)]

Actually I have two brand new USB cable around here for quite a while. Since its not easy to exchange the old ones, I didn’t do it yet.
For the time being I have built a workaround script that just restarts my OH (or even the raspi itself) if there are some errors :-):

#!/bin/bash

# ANY_OFFLINE calculation:
# 1. We check every openhab thing
# curl http://localhost:8080/rest/things
# 2. Pipe it to jq
# jq
# 3. Build an Array of OFFLINE things
# 3.1. Array
# [...]
# 3.2. Check every element of thing array array to be OFFLINE
# .[] | select(.statusInfo.status=="OFFLINE")
# 3.3. Extract the UID
# | .UID
# 3.4. Filter only smartmeter things
# | startswith("smartmeter") | select(. == true)
# 4. From the resulting array of booleans check of any is true (means there exists an OFFLINE element from smartmeter)
# [...] | any
# Result is true / false
echo "Running check for offline things..."

ANY_OFFLINE=$(/usr/bin/curl --silent http://localhost:8080/rest/things | /usr/bin/jq --raw-output '[.[] | select(.statusInfo.status=="OFFLINE") | .UID | startswith("smartmeter") | select(. == true)] | any')

if [ "$ANY_OFFLINE" == "false" ]; then
  echo "$(date): Online" >> /tmp/offline_log.txt
  rm -f /tmp/smartmeter_offline
  exit 0
fi

if [ -f /tmp/smartmeter_offline ]; then
  rm -f /tmp/smartmeter_offline
  echo "$(date): Offline" >> /tmp/offline_log.txt
  FAILED_MODEM_LINES=$(cat /var/log/syslog | grep "failed to get modem status" | wc -l)
  INPUT_OVERRUN_LINES=$(cat /var/log/syslog | grep ttyUSB | grep "input overrun" | wc -l)
  if (($FAILED_MODEM_LINES > 10)) || (($INPUT_OVERRUN_LINES > 10)); then 
      echo "Rebooting now!" >> /tmp/offline_log.txt
      /sbin/reboot --reboot 
  else
      echo "Restarting OH now!" >> /tmp/offline_log.txt
    systemctl restart openhab2.service
  fi
else
  echo "$(date): Offline" >> /tmp/offline_log.txt
  touch /tmp/smartmeter_offline
fi

Since this OH instance is only for my smart meters and other less important sensors, I can live with some restarts once a while.
My plan is to re-do most of this and exchange the cables once I switch to OH3 and then a Raspi4 with a docker based installation.

Regards,
Thomas

[Tuny (Sebastian)]

Thank you. That is quite a hard workaround, but at the moment I don´t see any alternative…
Are you using OH2?

[rossko57]

@thomas_letsch_de

I see a few CRC errors and then an exception “unable to open port”:

As seen in other bindings, there does appear to be some problem in the common underlying serial library, which appears to manifest as serial port locking out during what should be a “routine” error recovery sequence.
Tagging the github issue as this may be what you are seeing too,

Serial ports getting blocked after some re-connecting

[LuiSauberhorn (Lui)]

Any news on that topic?