Modbus stops without any errors

jomojomo95 · August 30, 2020, 4:09pm

Yea that’s the thing the rest of the system seems to work just fine.
I have room temperatures and humidity charted without any interrupts.
My zwave devices / network also work just fine without any problems for at least half a year now.
That was my biggest concern upgrading the system as I had massive problems with zwave in the past but all went well without any disrupts.

A colleague of mine also has the same E3DC setup with 1:1 thing, item, rule and sitemap setup running with a 2.5.6 OH installation without any issues.
I think that the problem might have something to do with some system dependencies as it was running just fine before the system upgrade. But to be honest I don’t know where to start and how to narrow it down further.

ssalonen · August 30, 2020, 6:07pm

Do you have full logs to send me please?
how does the last success item update? Does it stop updating?
how does the last error item update? Does it stop updating?

Can you also execute the following two commands in karaf console when the polling stops

threads --locks --monitors

and

threads

The output of those commands should help to understand what the binding is doing.

jomojomo95 · August 31, 2020, 9:19am

Here is a link to the full log until the stop: https://drive.google.com/file/d/1eHwmozB9kaXq06blvVx8PFD4OdJ9l2nG/view?usp=sharing

Is there any way to upload or insert larger log files to the Forum? I tried attaching it to my last post but only got 502 or “maximum file size” errors.

I’ll do the Karaf commands on the next stop.

ssalonen · August 31, 2020, 3:44pm

Some people attach zipped files renamed as pdf, example modbus_DEBUG_log.zip.pdf (57.4 KB)

It’s a kind of workaround

ssalonen · August 31, 2020, 3:45pm

Thanks for the logs… Why there is nothing else except log messages from modbus binding?

rossko57 · September 2, 2020, 9:35am

Comment - unrelated thread, but involves discovery and deadlocked stoppages. The mention of sunspec here makes me wonder if this too is about discovery (which most modbus users will not be using)

Kim_Andersen · September 2, 2020, 11:51am

It seems like I just hit this issue as well this morning. I´m not at home rigth now, but I can tell from the openhab app (and remote) that all modbus states has stopped. Everything else seems to run just fine, just modbus not updating anymore.

Kim_Andersen · September 2, 2020, 4:38pm

I at home now. And as suspected I seem to have the same issue. All pollers and data things are online, but no updates at all.
I first restarted the modbus binding from Karaf. The only result was, that all pollers and data things went offline.
Then I retstarted the io.transport from karaf. After that, all things came online, at I started to receive updates again.

jomojomo95 · September 2, 2020, 5:55pm

I’ve put the smarthome.event to WARN as I wanted to spare my SD-Card, just set it back to INFO for further testing.

It stopped this morning again after I set it back to a 6s poll rate, before it was running 2 days with 10s.

Here is the “threads --locks --monitors”: threads --locks --monitors.txt (77.4 KB)

And here the “threads” output: threads.txt (68.8 KB)

Here are the logs from today: https://drive.google.com/drive/folders/1TVDN-fSX2NTaNfEFRAlHydV3gRrt7iZ1?usp=sharing

ssalonen · September 2, 2020, 5:57pm

This makes sense… I can see from thread dump that the connection handling is somehow buggy and it basically gets stuck waiting for a “free” connection

My trouble is that so far I am not able to reproduce this, making troubleshooting and fixes very slow. Do you have easy means to get the erratic behavior?

ssalonen · September 2, 2020, 6:03pm

Does anyone have a possibly for keeping the logging on for longer periods of time? I might have a means for a more extensive diagnostics but that will generate a lot logs

Kim_Andersen · September 2, 2020, 6:14pm

I will setup seperate logging for this when I have had some dinner. (in an hour or two). Then I´ll let it run in debug mode (or do you want trace mode)?
I guess I should log the io.transport? Or do you want me to log the binding? (or both perhaps) ?

My fear is the logfiles will grow pretty quickly. Hopefully it will show some issue before it gets overwritten. I normally log 10 files at 10MB each.

ssalonen · September 2, 2020, 6:30pm

Trace level logging of transport would be most useful and hopefully reveal the issue… Unfortunately it is quite a lot of log lines, so not sure if defaults are enough to keep all the logs. They do compress well if you are concerned of disk space.

jomojomo95 · September 2, 2020, 6:31pm

If you give me some instruction how to set it up without the logs overwriting I will of course do more tests / logs.

ssalonen · September 2, 2020, 6:53pm

thanks @jomojomo95. You can find log configuration in org.ops4j.pax.logging.cfg located in userdata folder (see here).

This post seems to have relevant details Again: Rotating Log

jomojomo95 · September 2, 2020, 7:29pm

Thanks, I’ve started the TRACE logging of the modbus transport.

2020-09-02 21:23:38.076 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@ff7be7

2020-09-02 21:23:38.078 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] -> true

2020-09-02 21:23:38.079 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]...

2020-09-02 21:23:38.081 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] (endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]) age 227ms is over the reconnectAfterMillis=0ms limit or has been connection time (1599074617854) is after the "disconnectBeforeConnectedMillis"=-1 -> disconnecting.

2020-09-02 21:23:38.088 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]

2020-09-02 21:23:38.090 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]

2020-09-02 21:23:38.092 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] took 14 ms

2020-09-02 21:23:38.093 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID f70e3137-9747-477e-94ab-2134323a0d84]

2020-09-02 21:23:38.094 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 254 ms, connection: 32, transaction=18, callback=177} [operation ID f70e3137-9747-477e-94ab-2134323a0d84]

2020-09-02 21:23:38.096 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (6000ms) poll task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f] finished at 1599074618096. Was started at millis: 1599074617839 (=duration of 257 millis)

2020-09-02 21:23:40.279 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (evict) Connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] (endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]) age 2424ms is over the reconnectAfterMillis=0ms limit or has been connection time (1599074617854) is after the "disconnectBeforeConnectedMillis"=-1 -> disconnecting.

2020-09-02 21:23:40.282 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - destroyObject for connection TCPMasterConnection@1c54e2f[socket=Socket[addr=/192.168.2.141,port=502,localport=60746]] and endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] -> closing the connection

==> /var/log/openhab2/events.log <==

2020-09-02 21:23:43.473 [vent.ItemStateChangedEvent] - dndFunction changed from OFF to ON

2020-09-02 21:23:43.645 [vent.ItemStateChangedEvent] - historyTime changed from 20 to 3206

2020-09-02 21:23:43.651 [vent.ItemStateChangedEvent] - historyArea changed from 22.845 to 3183.075

2020-09-02 21:23:43.653 [vent.ItemStateChangedEvent] - historyArea changed from 3183.075 to 22.845

2020-09-02 21:23:43.656 [vent.ItemStateChangedEvent] - historyTime changed from 3206 to 20

2020-09-02 21:23:43.658 [vent.ItemStateChangedEvent] - dndFunction changed from ON to OFF

==> /var/log/openhab2/openhab.log <==

2020-09-02 21:23:44.098 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (6000ms) poll task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]. Current millis: 1599074624097

2020-09-02 21:23:44.100 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Starting new operation with task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]. Trying to get connection [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.102 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f] (oneOff=false)! Waiting for connection. Idle connections for this endpoint: 0, and active 0 [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.103 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Created connection TCPMasterConnection@958429[socket=<null>] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]

2020-09-02 21:23:44.107 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Waited 0ms (interTransactionDelayMillis 60ms) before giving returning connection TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502], to ensure delay between transactions.

2020-09-02 21:23:44.109 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - borrowing connection (got Optional[TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]]]) for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] took 5 ms

2020-09-02 21:23:44.111 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Executing task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f] (oneOff=false)! Connection received in 7 ms [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.112 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Operation with task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]. Got a connection successfully [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.114 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Try 1 out of 3 [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.115 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Ensuring that enough time passes before retrying again. Sleeping if necessary [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.117 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Sleep ended, slept 0 [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.118 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Going execute transaction with request request (FC=READ_MULTIPLE_REGISTERS): 00 00 00 00 00 06 01 03 00 00 00 68  [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.127 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Response for read request (FC=3, transaction ID=55588): d9 24 00 00 00 d3 01 03 d0 e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00  [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.129 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Calling read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@73eb7c

2020-09-02 21:23:44.131 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:e3dc:polling received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3], registers = ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00)))

2020-09-02 21:23:44.137 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Consumption channels updated: {modbus:data:e3dc:polling:Consumption:number=629}. readValueType=int32_swap, readIndex=Optional[71], readSubIndex(or 0)=0, extractIndex=71 -> numeric value 629 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

==> /var/log/openhab2/events.log <==

2020-09-02 21:23:44.139 [vent.ItemStateChangedEvent] - E3DC_Haus changed from 634 to 629

==> /var/log/openhab2/openhab.log <==

2020-09-02 21:23:44.144 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:PV_Inverter channels updated: {modbus:data:e3dc:polling:PV_Inverter:number=0}. readValueType=int32_swap, readIndex=Optional[67], readSubIndex(or 0)=0, extractIndex=67 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.163 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Battery channels updated: {modbus:data:e3dc:polling:Battery:number=630.0}. readValueType=int32_swap, readIndex=Optional[69], readSubIndex(or 0)=0, extractIndex=69 -> numeric value -630 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

==> /var/log/openhab2/events.log <==

2020-09-02 21:23:44.168 [vent.ItemStateChangedEvent] - E3DC_Battery changed from 636.0 to 630.0

==> /var/log/openhab2/openhab.log <==

2020-09-02 21:23:44.169 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Grid channels updated: {modbus:data:e3dc:polling:Grid:number=-1}. readValueType=int32_swap, readIndex=Optional[73], readSubIndex(or 0)=0, extractIndex=73 -> numeric value -1 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

==> /var/log/openhab2/events.log <==

2020-09-02 21:23:44.180 [vent.ItemStateChangedEvent] - E3DC_Netz changed from -2 to -1

2020-09-02 21:23:44.188 [vent.ItemStateChangedEvent] - E3DC_Battery_charge changed from 636.0 to 630.0

2020-09-02 21:23:44.191 [vent.ItemStateChangedEvent] - E3DC_Netz_provide changed from -2 to -1

==> /var/log/openhab2/openhab.log <==

2020-09-02 21:23:44.196 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:External channels updated: {modbus:data:e3dc:polling:External:number=0.0}. readValueType=int32_swap, readIndex=Optional[75], readSubIndex(or 0)=0, extractIndex=75 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.202 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:SelfConsumption channels updated: {modbus:data:e3dc:polling:SelfConsumption:number=99}. readValueType=uint8, readIndex=Optional[81], readSubIndex(or 0)=0, extractIndex=162 -> numeric value 99 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.208 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Autarky channels updated: {modbus:data:e3dc:polling:Autarky:number=99}. readValueType=uint8, readIndex=Optional[81], readSubIndex(or 0)=1, extractIndex=163 -> numeric value 99 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.214 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:SoC channels updated: {modbus:data:e3dc:polling:SoC:number=80}. readValueType=uint16, readIndex=Optional[82], readSubIndex(or 0)=0, extractIndex=82 -> numeric value 80 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.220 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Emergency_Power_Status channels updated: {modbus:data:e3dc:polling:Emergency_Power_Status:number=2}. readValueType=uint16, readIndex=Optional[83], readSubIndex(or 0)=0, extractIndex=83 -> numeric value 2 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.226 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Charge_Lock channels updated: {modbus:data:e3dc:polling:EMS_Charge_Lock:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=0, extractIndex=1344 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.231 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_DisCharge_Lock channels updated: {modbus:data:e3dc:polling:EMS_DisCharge_Lock:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=1, extractIndex=1345 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.237 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Emergency_Power channels updated: {modbus:data:e3dc:polling:EMS_Emergency_Power:number=1}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=2, extractIndex=1346 -> numeric value 1 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.242 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Wather_Based channels updated: {modbus:data:e3dc:polling:EMS_Wather_Based:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=3, extractIndex=1347 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.251 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Output_Cut channels updated: {modbus:data:e3dc:polling:EMS_Output_Cut:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=4, extractIndex=1348 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.260 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Charge_Lock_Time channels updated: {modbus:data:e3dc:polling:EMS_Charge_Lock_Time:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=5, extractIndex=1349 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.269 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_DisCharge_Lock_Time channels updated: {modbus:data:e3dc:polling:EMS_DisCharge_Lock_Time:number=0}. readValueType=bit, readIndex=Optional[84], readSubIndex(or 0)=6, extractIndex=1350 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.277 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String1_Voltage channels updated: {modbus:data:e3dc:polling:String1_Voltage:number=58}. readValueType=uint16, readIndex=Optional[95], readSubIndex(or 0)=0, extractIndex=95 -> numeric value 58 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.286 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String2_Voltage channels updated: {modbus:data:e3dc:polling:String2_Voltage:number=65}. readValueType=uint16, readIndex=Optional[96], readSubIndex(or 0)=0, extractIndex=96 -> numeric value 65 and boolValue=true. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.294 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String3_Voltage channels updated: {modbus:data:e3dc:polling:String3_Voltage:number=0}. readValueType=uint16, readIndex=Optional[97], readSubIndex(or 0)=0, extractIndex=97 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.303 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String1_Current channels updated: {modbus:data:e3dc:polling:String1_Current:number=0}. readValueType=uint16, readIndex=Optional[98], readSubIndex(or 0)=0, extractIndex=98 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.312 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String2_Current channels updated: {modbus:data:e3dc:polling:String2_Current:number=0}. readValueType=uint16, readIndex=Optional[99], readSubIndex(or 0)=0, extractIndex=99 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.320 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String3_Current channels updated: {modbus:data:e3dc:polling:String3_Current:number=0}. readValueType=uint16, readIndex=Optional[100], readSubIndex(or 0)=0, extractIndex=100 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.329 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String1_Power channels updated: {modbus:data:e3dc:polling:String1_Power:number=0}. readValueType=uint16, readIndex=Optional[101], readSubIndex(or 0)=0, extractIndex=101 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.337 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String2_Power channels updated: {modbus:data:e3dc:polling:String2_Power:number=0}. readValueType=uint16, readIndex=Optional[102], readSubIndex(or 0)=0, extractIndex=102 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.345 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String3_Power channels updated: {modbus:data:e3dc:polling:String3_Power:number=0}. readValueType=uint16, readIndex=Optional[103], readSubIndex(or 0)=0, extractIndex=103 -> numeric value 0 and boolValue=false. Registers ModbusRegisterArrayImpl(e3 dc 01 02 00 88 45 33 2f 44 43 20 47 6d 62 48 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 53 31 30 20 45 20 41 49 4f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 2d 37 30 32 30 32 33 30 31 30 30 32 39 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 50 31 30 5f 32 30 32 30 5f 30 36 32 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 fd 8a ff ff 02 75 00 00 ff ff ff ff 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 50 00 02 00 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 3a 00 41 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]

2020-09-02 21:23:44.347 [TRACE] [modbus.internal.ModbusLibraryWrapper] - Called read response callback org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f for request ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]. Response was net.wimpi.modbus.msg.ReadMultipleRegistersResponse@73eb7c

2020-09-02 21:23:44.349 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Validating endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] connection TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]] -> true

2020-09-02 21:23:44.352 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - Passivating connection TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]...

2020-09-02 21:23:44.354 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - (passivate) Connection TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]] (endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]) age 246ms is over the reconnectAfterMillis=0ms limit or has been connection time (1599074624107) is after the "disconnectBeforeConnectedMillis"=-1 -> disconnecting.

2020-09-02 21:23:44.361 [TRACE] [ing.ModbusSlaveConnectionFactoryImpl] - ...Passivated connection TCPMasterConnection@958429[socket=Socket[addr=/192.168.2.141,port=502,localport=60818]] for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]

2020-09-02 21:23:44.363 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returned connection to pool for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]

2020-09-02 21:23:44.365 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - returning connection for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] took 16 ms

2020-09-02 21:23:44.367 [TRACE] [rt.modbus.internal.ModbusManagerImpl] - Connection was returned to the pool, ending operation [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.368 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 269 ms, connection: 24, transaction=8, callback=220} [operation ID 558c6cb6-1dc1-41a5-81b5-30f42cedc0a6]

2020-09-02 21:23:44.370 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Execution of scheduled (6000ms) poll task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f] finished at 1599074624370. Was started at millis: 1599074624097 (=duration of 273 millis)

2020-09-02 21:23:46.387 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>

2020-09-02 21:23:46.391 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 0, length 104, done: false, canceled: false, delay: 3981. Full task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]

2020-09-02 21:23:46.394 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 1, remaining space 2147483647. Active threads 1

2020-09-02 21:23:46.396 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

Kim_Andersen · September 2, 2020, 7:38pm

I´m not worried about disk space. I´m worried that the error will appear and dissapear from the logfil, before I get the chance to grap it. But lets see how it goes.

EDIT - Logging runs now.

EDit again…
I kept an eye on the logfiles… Seems like it takes about 20MB in file size every 7 minutes. Thats HUGE!
In order to catch the issue when it happens it requires at least 12 hours of logfiles. Thats aprox 2GB of data…

I wonder if there is a way to stop the logging (save the existing logfiles from beeing overwritten) when the issue happens?

ssalonen · September 3, 2020, 6:46am

Well… I guess logging will reduce drastically when polling stops

Kim_Andersen · September 3, 2020, 7:14am

Hopefully
Atm I have set the logging to 20 files and 50MB each. Thats aprox 1GB and aprox 6 hours of logging. I Hope to catch it with this.

jomojomo95 · September 5, 2020, 11:15am

After 2 days without any stops (idk why) I had a stop today again but sadly I could not log it with trace as I did the karaf trace setting first and afterwards changed the logs settings, this must have stop the trace logging I guess.
I changed the logging to trace again and see the traces coming in.

FYI this are the traces of the stopped behavior, it still tries to poll but without any Item changes:

2020-09-05 13:10:33.134 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>

2020-09-05 13:10:33.137 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 0, length 104, done: false, canceled: false, delay: -9650810. Full task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]

2020-09-05 13:10:33.140 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 0, remaining space 2147483647. Active threads 2

2020-09-05 13:10:33.143 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

2020-09-05 13:10:43.146 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>

2020-09-05 13:10:43.150 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 0, length 104, done: false, canceled: false, delay: -9660822. Full task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]

2020-09-05 13:10:43.154 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 0, remaining space 2147483647. Active threads 2

2020-09-05 13:10:43.159 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

2020-09-05 13:10:53.163 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - <POLL MONITOR>

2020-09-05 13:10:53.168 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduled poll task. FC: READ_MULTIPLE_REGISTERS, start 0, length 104, done: false, canceled: false, delay: -9670840. Full task BasicPollTask@b1c543[request=ModbusPollerThingHandler.ModbusPollerReadRequest@763aa5[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3],endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502],resultCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f,failureCallback=org.openhab.binding.modbus.handler.ModbusPollerThingHandler$ReadCallbackDelegator@3c127f]

2020-09-05 13:10:53.171 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - POLL MONITOR: scheduledThreadPoolExecutor queue size: 0, remaining space 2147483647. Active threads 2

2020-09-05 13:10:53.174 [TRACE] [ternal.ModbusManagerImpl.PollMonitor] - </POLL MONITOR>

I’ll restart the binding and will report as I have a stop again.