Issues with Serial?

brownjl · March 23, 2020, 8:28pm

I have been having issues with my 2.5 install since upgrading from 2.4 and not sure how to fix it. After a period of time I see 100% cpu usage and in the logs I see regular errors around usb bridge devices I have plugged in (plugwise, rfxcom).

I have fully rebuilt my pc (ubuntu 18.04) and using docker I have the latest stable snapshot installed (2.5.3). I built the config from scratch, freshly installed the bindings I have and the things, but not created any items yet. Still seeing the same issue. I even tried swapped out my plugwise hardware too.

Heres a copy of my openhab.conf :

https://pastebin.com/NdPBy9zH

As you can see I am regularly getting read errors on the two bindings (both using ftdi usb drivers) which occasionally causes 100% cpu,

Anyone else seen the same or can suggest how I debug this. The systems been great since 2.0 until now

Thanks

James

Bruce_Osborne · March 23, 2020, 8:36pm

Did you mean to paste your configuration? You just pasted normal level logs.

Your Docker serial port mapping is an important piece of the puzzle. We cannot guess your configuration.

wborn · March 23, 2020, 8:42pm

I’m also using the Plugwise binding with OH 2.5.3 on Ubuntu 18.04 with Docker on an Intel NUC and it works fine for me. So it’s probably some sort of configuration issue.

wborn · March 23, 2020, 8:54pm

If you’re using the Alpine based Docker container you might want to use to the Debian based Docker container instead which should have less issues.

brownjl · March 23, 2020, 9:25pm

To build the docker image I use;

docker run -d --name=openhab --net=host --tty   
	-v /etc/localtime:/etc/localtime:ro   
	-v /etc/timezone:/etc/timezone:ro   
	-v /opt/openhab/conf:/openhab/conf   -v /opt/openhab/userdata:/openhab/userdata   -v /opt/openhab/addons:/openhab/addons   -v /opt/openhab/java:/openhab/.java -v /opt/openhab/tools:/openhab/tools  
	--device=/dev/ttyACM0 --device=/dev/ttyUSBrfx   --device=/dev/ttyUSBpw      
	-e OPENHAB_HTTP_PORT=9070   -e OPENHAB_HTTPS_PORT=9071   
	-e EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSBrfx:/dev/ttyUSBpw:/dev/ttyACM0"   
	-e USER_ID=9001   -e GROUP_ID=9001   openhab/openhab:2.5.3

I have the serial ports names configured using udev rules;

SUBSYSTEM=="tty", ATTRS{idVendor}=="0403", ATTRS{product}=="RFXtrx433", SYMLINK+="ttyUSBrfx", GROUP="dialout", MODE="0666"
SUBSYSTEM=="tty", ATTRS{idVendor}=="0403", ATTRS{idProduct}=="6001", ATTRS{serial}=="A700drC5", SYMLINK+="ttyUSBpw", GROUP="dialout", MODE="0666"

I configured both rfxcom and plugwise things manually, confs below. .

Plugwise;

Bridge plugwise:stick:000D6F0000998DEE "Plugwise Stick" @ "Other" [ serialPort="/dev/ttyUSBpw", messageWaitTime=200 ]

Thing plugwise:circleplus:000D6F0000768D80 "Socket: Xbox One" (plugwise:stick:000D6F0000998DEE) @ "Ronans Bedroom"   [ macAddress="000D6F0000768D80" ]
Thing plugwise:circle:000D6F000076A355 "Socket: TV" (plugwise:stick:000D6F0000998DEE) @ "Ronans Bedroom"   [ macAddress="000D6F000076A355" ]
Thing plugwise:circle:000D6F000076B224 "Socket: TV" (plugwise:stick:000D6F0000998DEE) @ "Living Room"   [ macAddress="000D6F000076B224" ]
Thing plugwise:circle:000D6F00007695B4 "Socket: TV" (plugwise:stick:000D6F0000998DEE) @ "Elis Bedroom"   [ macAddress="000D6F00007695B4" ]
Thing plugwise:circle:000D6F000076B607 "Socket: TV" (plugwise:stick:000D6F0000998DEE) @ "Master Bedroom"   [ macAddress="000D6F000076B607" ]
Thing plugwise:circle:000D6F0000769CE9 "Socket: Nightlight" (plugwise:stick:000D6F0000998DEE) @ "Ronans Bedroom"   [ macAddress="000D6F0000769CE9" ]
Thing plugwise:circle:000D6F0000769CCA "Socket: Lights" (plugwise:stick:000D6F0000998DEE) @ "Garden"   [ macAddress="000D6F0000769CCA" ]
Thing plugwise:circle:000D6F0000769CE8 "Socket: Xbox One S" (plugwise:stick:000D6F0000998DEE) @ "Elis Bedroom"   [ macAddress="000D6F0000769CE8" ]
Thing plugwise:circle:000D6F000076A489 "Socket: James Blanket" (plugwise:stick:000D6F0000998DEE) @ "Master Bedroom"   [ macAddress="000D6F000076A489" ]
Thing plugwise:circle:000D6F000076A94A "Socket: Sarahs Blanket" (plugwise:stick:000D6F0000998DEE) @ "Master Bedroom"   [ macAddress="000D6F000076A94A" ]

Thing plugwise:circle:000D6F000076A947 "Socket: Spare 76A947" (plugwise:stick:000D6F0000998DEE) @ "Other"   [ macAddress="000D6F000076A947", temporarilyNotInNetwork=true ]
Thing plugwise:circle:000D6F000076A955 "Socket: Spare 76A955" (plugwise:stick:000D6F0000998DEE) @ "Other"   [ macAddress="000D6F000076A955", temporarilyNotInNetwork=true ]
Thing plugwise:circle:000D6F000076AB55 "Socket: Spare 76AB55" (plugwise:stick:000D6F0000998DEE) @ "Other"   [ macAddress="000D6F000076AB55", temporarilyNotInNetwork=true ]

And rfxcom;

Bridge rfxcom:bridge:usb0 [ serialPort="/dev/ttyUSBrfx", disableDiscovery=true, ignoreConfig=true ] {
        Thing lighting5 15904048_1 "Spare_1" @ "Other"  [ deviceId="15904048.1", subType="LIGHTWAVERF" ]
        Thing lighting5 15904048_16 "Spare_16" @ "Other" [ deviceId="15904048.16", subType="LIGHTWAVERF" ]
        Thing lighting5 15902746_1 "Master1_1" @ "Master Bedroom"  [ deviceId="15902746.1", subType="LIGHTWAVERF" ]
        Thing lighting5 15902746_16 "Master1_16" @ "Master Bedroom" [ deviceId="15902746.16", subType="LIGHTWAVERF" ]
        Thing lighting5 15950555_1 "Master2_1" @ "Master Bedroom"  [ deviceId="15950555.1", subType="LIGHTWAVERF" ]
        Thing lighting5 15950555_16 "Master2_16" @ "Master Bedroom" [ deviceId="15950555.16", subType="LIGHTWAVERF" ]
        Thing lighting5 15922882_1 "Button_1" @ "Ronans Bedroom"  [ deviceId="15922882.1", subType="LIGHTWAVERF" ]
        Thing lighting5 15922882_16 "Button_16" @ "Ronans Bedroom"  [ deviceId="15922882.16", subType="LIGHTWAVERF" ]
        Thing lighting5 15902032_1 "Button_1" @ "Elis Bedroom" [ deviceId="15902032.1", subType="LIGHTWAVERF" ]
        Thing lighting5 15902032_16 "Button_16" @ "Elis Bedroom" [ deviceId="15902032.16", subType="LIGHTWAVERF" ]

        Thing temperaturehumidity 62210 "TemperatureHumidity" @ "Kitchen" [ deviceId="62210", subType="TH2" ]
        Thing temperaturehumidity 54789 "TemperatureHumidity" @ "Master Bedroom" [ deviceId="54789", subType="TH2" ]
        Thing temperaturehumidity 62468 "TemperatureHumidity" @ "Attic" [ deviceId="62468", subType="TH2" ]
        Thing temperaturehumidity 58887 "TemperatureHumidity" @ "Garden" [ deviceId="58887", subType="TH2" ]

        Thing energy 3602 "Owl" @ "Other"   [ deviceId="3602", subType="ELEC2" ]

        Thing lighting2 81412_10 "Door" @ "Ronans Bedroom" [ deviceId="81412.10", subType="AC" ]
        Thing lighting2 89312_10 "Door" @ "Elis Bedroom" [ deviceId="89312.10", subType="AC" ]

        Thing chime 187 "Doorbell" @ "Garden" [ deviceId="187", subType="BYRONSX" ]
}

Everything else is out of the box.

Not sure what base I am using with the docker image will look into it.

Bit of a loss really…

James

Bruce_Osborne · March 23, 2020, 9:36pm

That command, as written would not work. Perhaps you meant.

docker run -d --name=openhab --net=host --tty  \
	-v /etc/localtime:/etc/localtime:ro   \
	-v /etc/timezone:/etc/timezone:ro   \
	-v /opt/openhab/conf:/openhab/conf docker run -d --name=openhab --net=host --tty   \
	-v /etc/localtime:/etc/localtime:ro   \
	-v /etc/timezone:/etc/timezone:ro   \
	-v /opt/openhab/conf:/openhab/conf   -v /opt/openhab/userdata:/openhab/userdata   -v /opt/openhab/addons:/openhab/addons   -v /opt/openhab/java:/openhab/.java -v /opt/openhab/tools:/openhab/tools  \
	--device=/dev/ttyACM0 --device=/dev/ttyUSBrfx   --device=/dev/ttyUSBpw      \
	-e OPENHAB_HTTP_PORT=9070   -e OPENHAB_HTTPS_PORT=9071   \
	-e EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSBrfx:/dev/ttyUSBpw:/dev/ttyACM0"   \
	-e USER_ID=9001   -e GROUP_ID=9001   openhab/openhab:2.5.3  -v /opt/openhab/userdata:/openhab/userdata   -v /opt/openhab/addons:/openhab/addons   -v /opt/openhab/java:/openhab/.java -v /opt/openhab/tools:/openhab/tools  \
	--device=/dev/ttyACM0 --device=/dev/ttyUSBrfx   --device=/dev/ttyUSBpw     \ 
	-e OPENHAB_HTTP_PORT=9070   -e OPENHAB_HTTPS_PORT=9071   \
	-e EXTRA_JAVA_OPTS="-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSBrfx:/dev/ttyUSBpw:/dev/ttyACM0"  \ 
	-e USER_ID=9001   -e GROUP_ID=9001   openhab/openhab:2.5.3

brownjl · March 23, 2020, 9:37pm

Thanks Bruce, yes I just split out into separate lines to ease reading. Should have adding the backslashes!

Bruce_Osborne · March 23, 2020, 9:39pm

the default is to use Debian

Distributions:

debian for Debian 10 “buster” (default when not specified in tag)

alpine for Alpine 3.10

from Docker

brownjl · March 23, 2020, 9:42pm

Yes missed it was the default, but tried specifying the flag debian (deleted the old and all configs/userdata to build a fresh build with just those configs above) and see the same result in the logs not have it running long enough yet to see if it causes 100% cpu.

openhab.log

2020-03-23 21:36:00.576 [WARN ] [g.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 10.30.232.10
2020-03-23 21:36:01.224 [WARN ] [g.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 10.30.232.10
2020-03-23 21:36:02.470 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rfx.things'
2020-03-23 21:36:02.488 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'pw.things'
2020-03-23 21:36:03.201 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-03-23 21:36:03.579 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://172.17.0.1:9070
2020-03-23 21:36:03.579 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://172.17.0.1:9071
2020-03-23 21:36:03.792 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2020-03-23 21:36:03.837 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
2020-03-23 21:36:03.887 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui


2020-03-23 21:36:24.355 [WARN ] [se.internal.PlugwiseMessageProcessor] - Plugwise protocol message error: 00D001FB
01D00DF008EE11FDF006D0EFF6A
00D1015AA
2020-03-23 21:36:25.333 [WARN ] [gwise.internal.PlugwiseMessageSender] - Error sending: No ACK received after 1 second: 003E000D6F0000768D802642
2020-03-23 21:36:26.535 [WARN ] [gwise.internal.PlugwiseMessageSender] - Error sending: No ACK received after 1 second: 0023000D6F000076B6078BC0
2020-03-23 21:36:27.736 [WARN ] [gwise.internal.PlugwiseMessageSender] - Error sending: No ACK received after 1 second: 003E000D6F000076B60743BA
2020-03-23 21:36:28.938 [WARN ] [gwise.internal.PlugwiseMessageSender] - Error sending: No ACK received after 1 second: 003E000D6F0000768D802642
00030C70303006006D0547015AE4[se.internal.PlugwiseMessageProcessor] - Plugwise protocol message error: 00030CDF
#ASeusNdIf:Suc A:0060098E#ASeusNdIf:DsiainMC
0DF00667
0203006006674300040015599033E84222E
00030C39
00D501CC07881210047B147CE
003F0D35000D6F000076B60715241C0001457A1E14
2020-03-23 21:36:30.139 [WARN ] [gwise.internal.PlugwiseMessageSender] - Error sending: No ACK received after 1 second: 003E000D6F000076B60743BA
2020-03-23 21:36:41.738 [ERROR] [internal.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
00D201B8 21:39:34.303 [WARN ] [se.internal.PlugwiseMessageProcessor] - Plugwise protocol message error: 0FD10DF007881210047D8
D30DF0066754A015AC604308630090404C0FBtnto A:
D4016D
0FD40DF006D054A015A98
6E00030CFA
2020-03-23 21:39:35.279 [WARN ] [gwise.internal.PlugwiseMessageSender] - Error sending: No ACK received after 1 second: 000D000D6F0000768D8036D2
2020-03-23 21:39:36.481 [WARN ] [gwise.internal.PlugwiseMessageSender] - Error sending: No ACK received after 1 second: 000D000D6F00007695B40848
F0DF006D0050657020600788B2FA3 ] [se.internal.PlugwiseMessageProcessor] - Plugwise protocol message error: 000F0C73
 ENIGPN NCS:Mcd A3272DAE
 ADE x2
00D201D5
 EDN IGUIAS:ai:0A03C237F30D7A6E
2020-03-23 21:39:37.682 [WARN ] [gwise.internal.PlugwiseMessageSender] - Error sending: No ACK received after 1 second: 000D000D6F0000769CE92ADA
2020-03-23 21:39:38.742 [ERROR] [internal.handler.RFXComBridgeHandler] - Error occurred: Timeout during packet read
2020-03-23 21:39:38.884 [WARN ] [gwise.internal.PlugwiseMessageSender] - Error sending: No ACK received after 1 second: 000D000D6F000076B607532A
2020-03-23 21:39:40.310 [WARN ] [gwise.internal.PlugwiseMessageSender] - Error sending: No ACK received after 1 second: 000D000D6F000076B224D9EB

wborn · March 24, 2020, 8:24am

Does it work if you mount the serial ports into the container directly without using the udev generated links? Those will probably point to files the container can’t access. I only have one USB stick so don’t use udev rules. You can find a lot more people having issues with udev and Docker. They resort to mounting /dev into the container or running it in priviledged mode which is not that optimal of course.

brownjl · March 24, 2020, 9:59am

Will give it a go later.

I left this reduced config running over night and again it hit 100% at some point over night (stay there till I kill it)

I’ve just split out the rxfcom and plugwise binding into there own openhab docker instances to see which is causing me the trouble.

Thanks

James