Openhab resets serial connection with my gateway every couple seconds

pawlo999 · May 16, 2020, 9:54pm

Hei, I am unable to find reason why my connection gets reset. Openhab is running on W10 now, maybe there is some kind bug there. Apart from disconnecting everything works well (all sensors, relays…)

23:49:25.243 [INFO ] [smarthome.event.ItemStateChangedEvent] - mysensors_distance_gateway_distance_0_2_lastupdate changed from 2020-05-16T23:49:22.000+0200 to 2020-05-16T23:49:25.000+0200
23:49:25.243 [WARN ] [orsAbstractConnection$MySensorsReader] - Exception on reading from connection
java.text.ParseException: class java.text.ParseException : Message length is not > 4
        at org.openhab.binding.mysensors.internal.protocol.message.MySensorsMessage.parse(MySensorsMessage.java:346) ~[bundleFile:?]
        at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:342) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
23:49:25.252 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Request disconnection flag setted to: true
23:49:25.280 [INFO ] [ocol.serial.MySensorsSerialConnection] - Connection request disconnection...
23:49:25.282 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Request disconnection flag setted to: false
23:49:25.289 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Shutting down serial connection!
23:49:25.290 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Stopping Writer thread
23:49:25.293 [WARN ] [orsAbstractConnection$MySensorsWriter] - Interrupted MySensorsWriter
23:49:25.296 [DEBUG] [orsAbstractConnection$MySensorsReader] - Stopping Reader thread
23:49:25.298 [WARN ] [orsAbstractConnection$MySensorsReader] - Interrupted MySensorsReader

openhab> Error 0x5 at src/windows/termios.c(889): Access is denied.

Error 0x6 at src/windows/termios.c(512): The handle is invalid.

TimO · May 18, 2020, 11:40am

Please enable debug output for the binding and post the output that occurs before and when the above error is shown.

Enter log:set DEBUG org.openhab.binding.mysensors and log:tail to receive debug messages.

pawlo999 · May 18, 2020, 12:52pm

Under, attached whole 2 runs, first successful and error that sometimes keeps coming for a while after disconnection

14:50:01.018 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Connecting to COM3 [baudRate:115200]
14:50:01.086 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Serial port event listener started
14:50:01.092 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Successfully connected to serial port.
14:50:01.104 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:01.993 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;9;0 MCO:BGN:INIT GW,CP=R-NGA---,FQ=16,REL=255,VER=2.3.2
14:50:01.996 [INFO ] [ors.internal.gateway.MySensorsGateway] - Node 0 available again!
14:50:02.004 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;9;5 MCO:BGN:BFR
14:50:02.008 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;14;Gateway startup complete.
14:50:02.012 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;0;0;17;2.3.2
14:50:02.013 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Presentation Message received
14:50:02.015 [WARN ] [ors.internal.gateway.MySensorsGateway] - Presented child is alredy present in gateway
14:50:02.017 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;11;Multisensor
14:50:02.019 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;12;0.1
14:50:02.020 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;0;0;0;7;
14:50:02.026 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Presentation Message received
14:50:02.027 [WARN ] [ors.internal.gateway.MySensorsGateway] - Presented child is alredy present in gateway
14:50:02.029 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;1;0;0;6;
14:50:02.034 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Presentation Message received
14:50:02.043 [WARN ] [ors.internal.gateway.MySensorsGateway] - Presented child is alredy present in gateway
14:50:02.047 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;2;0;0;15;
14:50:02.050 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Presentation Message received
14:50:02.053 [WARN ] [ors.internal.gateway.MySensorsGateway] - Presented child is alredy present in gateway
14:50:02.056 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;3;0;0;16;
14:50:02.062 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Presentation Message received
14:50:02.064 [WARN ] [ors.internal.gateway.MySensorsGateway] - Presented child is alredy present in gateway
14:50:02.066 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;4;0;0;3;
14:50:02.071 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Presentation Message received
14:50:02.073 [WARN ] [ors.internal.gateway.MySensorsGateway] - Presented child is alredy present in gateway
14:50:02.075 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;5;0;0;3;
14:50:02.080 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Presentation Message received
14:50:02.083 [WARN ] [ors.internal.gateway.MySensorsGateway] - Presented child is alredy present in gateway
14:50:02.087 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;6;0;0;35;
14:50:02.112 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Presentation Message received
14:50:02.117 [WARN ] [ors.internal.gateway.MySensorsGateway] - Presented child is alredy present in gateway
14:50:02.119 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;7;0;0;20;
14:50:02.124 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Presentation Message received
14:50:02.126 [WARN ] [ors.internal.gateway.MySensorsGateway] - Presented child is alredy present in gateway
14:50:02.127 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;9;20 MCO:BGN:STP
14:50:02.149 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:02.166 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;2;2.3.2
14:50:02.167 [DEBUG] [orsAbstractConnection$MySensorsReader] - Good,Gateway is up and running! (Ver:2.3.2)
14:50:02.172 [DEBUG] [sensors.factory.MySensorsCacheFactory] - Writing on cache given_ids, content: [0]
14:50:02.175 [INFO ] [ocol.serial.MySensorsSerialConnection] - Successfully connected to MySensors Bridge.
14:50:02.175 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:gateway' changed from OFFLINE to ONLINE
14:50:02.221 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to ONLINE for device: mysensors:ir:gateway:ir_0_7
14:50:02.223 [DEBUG] [sensors.handler.MySensorsThingHandler] - Event listener for node 0-7 not registered yet, registering...
14:50:02.227 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:ir:gateway:ir_0_7' changed from OFFLINE to ONLINE
14:50:02.227 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to ONLINE for device: mysensors:temperature:gateway:temperature_0_1
14:50:02.230 [DEBUG] [sensors.handler.MySensorsThingHandler] - Event listener for node 0-1 not registered yet, registering...
14:50:02.235 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to ONLINE for device: mysensors:light:gateway:light_0_5
14:50:02.237 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_1' changed from OFFLINE to ONLINE
14:50:02.237 [DEBUG] [sensors.handler.MySensorsThingHandler] - Event listener for node 0-5 not registered yet, registering...
14:50:02.240 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to ONLINE for device: mysensors:light:gateway:light_0_4
14:50:02.242 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light:gateway:light_0_5' changed from OFFLINE to ONLINE
14:50:02.243 [DEBUG] [sensors.handler.MySensorsThingHandler] - Event listener for node 0-4 not registered yet, registering...
14:50:02.249 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light:gateway:light_0_4' changed from OFFLINE to ONLINE
14:50:02.249 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to ONLINE for device: mysensors:light-level:gateway:light-level_0_3
14:50:02.252 [DEBUG] [sensors.handler.MySensorsThingHandler] - Event listener for node 0-3 not registered yet, registering...
14:50:02.254 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to ONLINE for device: mysensors:temperature:gateway:temperature_0_8
14:50:02.255 [DEBUG] [sensors.handler.MySensorsThingHandler] - Event listener for node 0-8 not registered yet, registering...
14:50:02.257 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to ONLINE for device: mysensors:temperature:gateway:temperature_0_9
14:50:02.258 [DEBUG] [sensors.handler.MySensorsThingHandler] - Event listener for node 0-9 not registered yet, registering...
14:50:02.260 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to ONLINE for device: mysensors:distance:gateway:distance_0_2
14:50:02.262 [DEBUG] [sensors.handler.MySensorsThingHandler] - Event listener for node 0-2 not registered yet, registering...
14:50:02.257 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light-level:gateway:light-level_0_3' changed from OFFLINE to ONLINE
14:50:02.277 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_8' changed from OFFLINE to ONLINE
14:50:02.279 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to ONLINE for device: mysensors:moisture:gateway:moisture_0_6
14:50:02.281 [DEBUG] [sensors.handler.MySensorsThingHandler] - Event listener for node 0-6 not registered yet, registering...
14:50:02.281 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_9' changed from OFFLINE to ONLINE
14:50:02.283 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to ONLINE for device: mysensors:humidity:gateway:humidity_0_0
14:50:02.285 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:distance:gateway:distance_0_2' changed from OFFLINE to ONLINE
14:50:02.286 [DEBUG] [sensors.handler.MySensorsThingHandler] - Event listener for node 0-0 not registered yet, registering...
14:50:02.288 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:moisture:gateway:moisture_0_6' changed from OFFLINE to ONLINE
14:50:02.291 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:gateway:humidity_0_0' changed from OFFLINE to ONLINE
14:50:03.076 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: Nie odnaleziono czujnika BMP085 / BMP180
14:50:03.078 [WARN ] [orsAbstractConnection$MySensorsReader] - Exception on reading from connection
java.text.ParseException: class java.text.ParseException : Message length is not > 4
        at org.openhab.binding.mysensors.internal.protocol.message.MySensorsMessage.parse(MySensorsMessage.java:346) ~[bundleFile:?]
        at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:342) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
14:50:03.080 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;9;1029 MCO:REG:NOT NEEDED
14:50:03.081 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;255;3;0;9;1035 MCO:BGN:INIT OK,TSP=NA
14:50:03.083 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;2;1;0;13;10
14:50:03.085 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Node 0 found in gateway
14:50:03.086 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Child 2 found in node 0
14:50:03.090 [DEBUG] [sensors.handler.MySensorsThingHandler] - Updating channel: distance(V_DISTANCE) value to: 10
14:50:03.096 [INFO ] [smarthome.event.ItemStateChangedEvent] - mysensors_distance_gateway_distance_0_2_lastupdate changed from 2020-05-18T14:43:51.000+0200 to 2020-05-18T14:50:03.000+0200
14:50:03.093 [DEBUG] [sensors.handler.MySensorsThingHandler] - Setting last update for node/child 0/2 to 2020-05-18T14:50:03.000+0200
14:50:03.101 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: Odległość: 10 cm
14:50:03.103 [WARN ] [orsAbstractConnection$MySensorsReader] - Exception on reading from connection
java.text.ParseException: class java.text.ParseException : Message length is not > 4
        at org.openhab.binding.mysensors.internal.protocol.message.MySensorsMessage.parse(MySensorsMessage.java:346) ~[bundleFile:?]
        at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:342) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
14:50:03.106 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: Failed reading temperature from DHT!
14:50:03.107 [WARN ] [orsAbstractConnection$MySensorsReader] - Exception on reading from connection
java.text.ParseException: class java.text.ParseException : Message length is not > 4
        at org.openhab.binding.mysensors.internal.protocol.message.MySensorsMessage.parse(MySensorsMessage.java:346) ~[bundleFile:?]
        at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:342) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
14:50:03.111 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: Failed reading humidity from DHT
14:50:03.112 [WARN ] [orsAbstractConnection$MySensorsReader] - Exception on reading from connection
java.text.ParseException: class java.text.ParseException : Message length is not > 4
        at org.openhab.binding.mysensors.internal.protocol.message.MySensorsMessage.parse(MySensorsMessage.java:346) ~[bundleFile:?]
        at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:342) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
14:50:03.114 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;3;1;0;23;37
14:50:03.117 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Node 0 found in gateway
14:50:03.121 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Child 3 found in node 0
14:50:03.123 [DEBUG] [sensors.handler.MySensorsThingHandler] - Updating channel: light-level(V_LIGHT_LEVEL) value to: 37
14:50:03.126 [INFO ] [smarthome.event.ItemStateChangedEvent] - mysensors_light_level_gateway_light_level_0_3_light_level changed from 48 to 37
14:50:03.128 [DEBUG] [sensors.handler.MySensorsThingHandler] - Setting last update for node/child 0/3 to 2020-05-18T14:50:03.000+0200
14:50:03.129 [INFO ] [smarthome.event.ItemStateChangedEvent] - mysensors_light_level_gateway_light_level_0_3_lastupdate changed from 2020-05-18T14:43:48.000+0200 to 2020-05-18T14:50:03.000+0200
14:50:03.130 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: Oświetlenie :386
14:50:03.132 [WARN ] [orsAbstractConnection$MySensorsReader] - Exception on reading from connection
java.text.ParseException: class java.text.ParseException : Message length is not > 4
        at org.openhab.binding.mysensors.internal.protocol.message.MySensorsMessage.parse(MySensorsMessage.java:346) ~[bundleFile:?]
        at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:342) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
14:50:03.146 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;6;1;0;37;3
14:50:03.149 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Node 0 found in gateway
14:50:03.151 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Child 6 found in node 0
14:50:03.153 [DEBUG] [sensors.handler.MySensorsThingHandler] - Updating channel: level(V_LEVEL) value to: 3
14:50:03.157 [DEBUG] [sensors.handler.MySensorsThingHandler] - Setting last update for node/child 0/6 to 2020-05-18T14:50:03.000+0200
14:50:03.158 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: Wilgotność gleby :3%
14:50:03.159 [INFO ] [smarthome.event.ItemStateChangedEvent] - mysensors_moisture_gateway_moisture_0_6_level changed from 0 to 3
14:50:03.160 [WARN ] [orsAbstractConnection$MySensorsReader] - Exception on reading from connection
java.text.ParseException: class java.text.ParseException : Message length is not > 4
        at org.openhab.binding.mysensors.internal.protocol.message.MySensorsMessage.parse(MySensorsMessage.java:346) ~[bundleFile:?]
        at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:342) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
14:50:03.161 [INFO ] [smarthome.event.ItemStateChangedEvent] - mysensors_moisture_gateway_moisture_0_6_lastupdate changed from 2020-05-18T14:43:42.000+0200 to 2020-05-18T14:50:03.000+0200
14:50:03.163 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Request disconnection flag setted to: true
14:50:09.113 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: Failed reading temperature from DHT!
14:50:09.117 [WARN ] [orsAbstractConnection$MySensorsReader] - Exception on reading from connection
java.text.ParseException: class java.text.ParseException : Message length is not > 4
        at org.openhab.binding.mysensors.internal.protocol.message.MySensorsMessage.parse(MySensorsMessage.java:346) ~[bundleFile:?]
        at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:342) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
14:50:09.121 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Request disconnection flag setted to: true
14:50:09.123 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: Failed reading humidity from DHT
14:50:09.124 [WARN ] [orsAbstractConnection$MySensorsReader] - Exception on reading from connection
java.text.ParseException: class java.text.ParseException : Message length is not > 4
        at org.openhab.binding.mysensors.internal.protocol.message.MySensorsMessage.parse(MySensorsMessage.java:346) ~[bundleFile:?]
        at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:342) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
14:50:09.127 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Request disconnection flag setted to: true
14:50:09.130 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;3;1;0;23;38
14:50:09.132 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Node 0 found in gateway
14:50:09.133 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Child 3 found in node 0
14:50:09.135 [DEBUG] [sensors.handler.MySensorsThingHandler] - Updating channel: light-level(V_LIGHT_LEVEL) value to: 38
14:50:09.139 [DEBUG] [sensors.handler.MySensorsThingHandler] - Setting last update for node/child 0/3 to 2020-05-18T14:50:09.000+0200
14:50:09.141 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: Oświetlenie :396
14:50:09.141 [INFO ] [smarthome.event.ItemStateChangedEvent] - mysensors_light_level_gateway_light_level_0_3_light_level changed from 37 to 38
14:50:09.142 [WARN ] [orsAbstractConnection$MySensorsReader] - Exception on reading from connection
java.text.ParseException: class java.text.ParseException : Message length is not > 4
        at org.openhab.binding.mysensors.internal.protocol.message.MySensorsMessage.parse(MySensorsMessage.java:346) ~[bundleFile:?]
        at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:342) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
14:50:09.145 [INFO ] [smarthome.event.ItemStateChangedEvent] - mysensors_light_level_gateway_light_level_0_3_lastupdate changed from 2020-05-18T14:50:03.000+0200 to 2020-05-18T14:50:09.000+0200
14:50:09.147 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Request disconnection flag setted to: true
14:50:09.148 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;6;1;0;37;0
14:50:09.155 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Node 0 found in gateway
14:50:09.159 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Child 6 found in node 0
14:50:09.160 [DEBUG] [sensors.handler.MySensorsThingHandler] - Updating channel: level(V_LEVEL) value to: 0
14:50:09.164 [INFO ] [smarthome.event.ItemStateChangedEvent] - mysensors_moisture_gateway_moisture_0_6_level changed from 3 to 0
14:50:09.164 [DEBUG] [sensors.handler.MySensorsThingHandler] - Setting last update for node/child 0/6 to 2020-05-18T14:50:09.000+0200
14:50:09.167 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: Wilgotność gleby :0%
14:50:09.168 [INFO ] [smarthome.event.ItemStateChangedEvent] - mysensors_moisture_gateway_moisture_0_6_lastupdate changed from 2020-05-18T14:50:03.000+0200 to 2020-05-18T14:50:09.000+0200
14:50:09.169 [WARN ] [orsAbstractConnection$MySensorsReader] - Exception on reading from connection
java.text.ParseException: class java.text.ParseException : Message length is not > 4
        at org.openhab.binding.mysensors.internal.protocol.message.MySensorsMessage.parse(MySensorsMessage.java:346) ~[bundleFile:?]
        at org.openhab.binding.mysensors.internal.protocol.MySensorsAbstractConnection$MySensorsReader.run(MySensorsAbstractConnection.java:342) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]
14:50:09.171 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Request disconnection flag setted to: true
14:50:12.178 [INFO ] [ocol.serial.MySensorsSerialConnection] - Connection request disconnection...
14:50:12.181 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Request disconnection flag setted to: false
14:50:12.183 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Shutting down serial connection!
14:50:12.185 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Stopping Writer thread
14:50:12.188 [WARN ] [orsAbstractConnection$MySensorsWriter] - Interrupted MySensorsWriter
14:50:12.197 [DEBUG] [orsAbstractConnection$MySensorsReader] - Stopping Reader thread
14:50:12.215 [WARN ] [orsAbstractConnection$MySensorsReader] - Interrupted MySensorsReader
14:50:15.224 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:ir:gateway:ir_0_7' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
14:50:15.226 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to OFFLINE for device: mysensors:light-level:gateway:light-level_0_3
14:50:15.226 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to OFFLINE for device: mysensors:light:gateway:light_0_4
14:50:15.226 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to OFFLINE for device: mysensors:light:gateway:light_0_5
14:50:15.226 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to OFFLINE for device: mysensors:ir:gateway:ir_0_7
14:50:15.226 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to OFFLINE for device: mysensors:temperature:gateway:temperature_0_1
14:50:15.229 [DEBUG] [sensors.factory.MySensorsCacheFactory] - Writing on cache given_ids, content: [0]
14:50:15.228 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_1' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
14:50:15.236 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light:gateway:light_0_5' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
14:50:15.237 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Connecting to COM3 [baudRate:115200]
14:50:15.238 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to OFFLINE for device: mysensors:distance:gateway:distance_0_2
14:50:15.237 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to OFFLINE for device: mysensors:temperature:gateway:temperature_0_8
14:50:15.237 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to OFFLINE for device: mysensors:temperature:gateway:temperature_0_9
14:50:15.237 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light:gateway:light_0_4' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
14:50:15.239 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to OFFLINE for device: mysensors:humidity:gateway:humidity_0_0
14:50:15.238 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to OFFLINE for device: mysensors:moisture:gateway:moisture_0_6
14:50:15.244 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light-level:gateway:light-level_0_3' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
14:50:15.248 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_8' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
14:50:15.252 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_9' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
14:50:15.256 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:distance:gateway:distance_0_2' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
14:50:15.260 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:moisture:gateway:moisture_0_6' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
14:50:15.262 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:gateway:humidity_0_0' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
14:50:15.264 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:gateway' changed from ONLINE to OFFLINE
14:50:15.265 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:ir:gateway:ir_0_7' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (BRIDGE_OFFLINE)
14:50:15.268 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_1' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (BRIDGE_OFFLINE)
14:50:15.270 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light:gateway:light_0_5' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (BRIDGE_OFFLINE)
14:50:15.272 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light:gateway:light_0_4' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (BRIDGE_OFFLINE)
14:50:15.277 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light-level:gateway:light-level_0_3' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (BRIDGE_OFFLINE)
14:50:15.279 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_8' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (BRIDGE_OFFLINE)
14:50:15.281 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_9' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (BRIDGE_OFFLINE)
14:50:15.283 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:distance:gateway:distance_0_2' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (BRIDGE_OFFLINE)
14:50:15.285 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:moisture:gateway:moisture_0_6' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (BRIDGE_OFFLINE)
14:50:15.287 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:gateway:humidity_0_0' changed from OFFLINE (COMMUNICATION_ERROR) to OFFLINE (BRIDGE_OFFLINE)
14:50:15.289 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:ir:gateway:ir_0_7' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
14:50:15.291 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_1' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
14:50:15.294 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light:gateway:light_0_5' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
14:50:15.296 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light:gateway:light_0_4' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
14:50:15.298 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:light-level:gateway:light-level_0_3' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
14:50:15.300 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:distance:gateway:distance_0_2' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
14:50:15.302 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_8' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
14:50:15.305 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:temperature:gateway:temperature_0_9' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
14:50:15.309 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:humidity:gateway:humidity_0_0' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
14:50:15.311 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'mysensors:moisture:gateway:moisture_0_6' changed from OFFLINE (BRIDGE_OFFLINE) to OFFLINE
14:50:15.536 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Serial port event listener started
14:50:15.539 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Successfully connected to serial port.
14:50:15.543 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:16.543 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:17.544 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:18.544 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:19.545 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:20.545 [ERROR] [ocol.serial.MySensorsSerialConnection] - Cannot start reading/writing thread, probably sync message (I_VERSION) not received. Try set startupCheckEnabled to false
14:50:20.550 [DEBUG] [sensors.factory.MySensorsCacheFactory] - Writing on cache given_ids, content: [0]
14:50:20.553 [ERROR] [ocol.serial.MySensorsSerialConnection] - Failed connecting to bridge...next retry in 10 seconds (Retry No.:0)
14:50:20.555 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Shutting down serial connection!
14:50:20.557 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Stopping Writer thread
14:50:20.559 [WARN ] [orsAbstractConnection$MySensorsWriter] - Interrupted MySensorsWriter
14:50:20.563 [DEBUG] [orsAbstractConnection$MySensorsReader] - Stopping Reader thread
14:50:20.570 [WARN ] [orsAbstractConnection$MySensorsReader] - Interrupted MySensorsReader
14:50:23.734 [DEBUG] [sensors.factory.MySensorsCacheFactory] - Writing on cache given_ids, content: [0]
14:50:33.738 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Connecting to COM3 [baudRate:115200]
14:50:34.155 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Serial port event listener started
14:50:34.157 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Successfully connected to serial port.
14:50:34.161 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:35.160 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:36.161 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:37.161 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:38.161 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
14:50:39.162 [ERROR] [ocol.serial.MySensorsSerialConnection] - Cannot start reading/writing thread, probably sync message (I_VERSION) not received. Try set startupCheckEnabled to false
14:50:39.165 [DEBUG] [sensors.factory.MySensorsCacheFactory] - Writing on cache given_ids, content: [0]

TimO · May 20, 2020, 7:44am

Do you have sensors attached to the gateway and send debug messages via serial? Looks like the binding does not like these debug output.

pawlo999 · May 20, 2020, 10:30am

Unfortunately I got the same result even without debug msg from gateway.

12:27:35.800 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;9;1;0;37;34
12:27:35.801 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Node 0 found in gateway
12:27:35.804 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Child 9 not present in node 0
12:27:35.807 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;2;1;0;13;18
12:27:35.809 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Node 0 found in gateway
12:27:35.811 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Child 2 not present in node 0
12:27:38.806 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;6;1;0;0;23.1
12:27:38.808 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Node 0 found in gateway
12:27:38.810 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Child 6 not present in node 0
12:27:38.851 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;7;1;0;4;991.5
12:27:38.853 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Node 0 found in gateway
12:27:38.855 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Child 7 not present in node 0
12:27:38.856 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;8;1;0;37;0
12:27:38.858 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Node 0 found in gateway
12:27:38.859 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Child 8 not present in node 0
12:27:38.861 [DEBUG] [orsAbstractConnection$MySensorsReader] - Message from gateway received: 0;9;1;0;37;0
12:27:38.863 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Node 0 found in gateway
12:27:38.864 [DEBUG] [ors.internal.gateway.MySensorsGateway] - Child 9 not present in node 0
12:27:39.291 [INFO ] [ocol.serial.MySensorsSerialConnection] - Connection request disconnection...
12:27:39.292 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Request disconnection flag setted to: false
12:27:39.293 [DEBUG] [ocol.serial.MySensorsSerialConnection] - Shutting down serial connection!
12:27:39.294 [DEBUG] [orsAbstractConnection$MySensorsWriter] - Stopping Writer thread
12:27:39.295 [WARN ] [orsAbstractConnection$MySensorsWriter] - Interrupted MySensorsWriter
12:27:39.300 [DEBUG] [orsAbstractConnection$MySensorsReader] - Stopping Reader thread
12:27:39.305 [WARN ] [orsAbstractConnection$MySensorsReader] - Interrupted MySensorsReader
12:27:42.308 [DEBUG] [sensors.handler.MySensorsThingHandler] - MySensors Bridge Status updated to OFFLINE for device: mysensors:temperature:gateway:temperature_0_9

bungle · March 26, 2021, 12:44am

Hi Tim,
This seems to have solved a problem i have.
What was it in the logs that made you think that the binding does not like the debug output?

thanks
b

Osborne · March 26, 2021, 7:16am

Thanks for update and quick reply. I’ll be sure to keep an eye on this thread. Looking for the same issue. Please keep sharing this type of post.

Kroger Schedule