Now also 2.5.8 is released with the relevant fixes, no need for the manual update of modbus binding
@rossko57 was right with the wrong version, I should have double checked vie bundle:list, the PaperUI installed 2.5.7, could be a problem with my roll back to OH 2.5.6
@ssalonen should I update to OH 2.5.8 and are there any other fixes to the modbus binding not in the modbus snapshot? As described I used the 2.5.8 snapshot with OH 2.5.7 installation with the same problem and there I checked with bundle list and the 2.5.8 modbus bundles where all active.
I double checked and as thought installing the 2.5.6 Version from PaperUI wont work.
I try the update to the mentioned 2.5.8 release and report back.
Sounds good. 2.5.8 release has all the fixes as of today.
Naturally the issues you experience might be something completely different, but still it makes sense to try the latest stable version first.
Yea it seems like it’s not fixed or not a bug in the binding.
You see the modbus stopping in the Chart 1 today, after I updated to 2.5.8 yesterday.
Chart 2 shows the stops of the last week. I restarted the service ore did some changes trying to fix it and restated openhab, after that it stopped again.
I think I should try going back to the modbus 2.5.6 version to see if it is a problem with the addon or something else.
What is the best way to get the 2.5.6 jar files or do I have to go back to the 2.5.6 openhab version to?
I don’t. 2.5.8 includes more than just fixing the 2.5.7 error, as I understand it improved debug logging - which sounds helpful here.
You have looked in your openhab.log for ordinary binding reports? It’s not been explicitly mentioned here.
This is a solar system? It just looks like it is going to sleep during hours of darkness.
EDIT - while rummaging in posts, I found this which might be of interest - dedicated E3DC add-on (that sits on top of Modbus binding).
You’d want to clear up your current issue before trying though, I would think.
3 Likes
Thanks for reporting back. I wonder what’s the issue.
I am helping another user here to troubleshoot his installation: Binding Modbus 2.5.7. Stops working after unsuccessful read attempt. I wonder if this is something similar
Perhaps you try out similar steps and report back? The essential piece is the debug / trace level logging and capturing the moment when it stops working
1 Like
@ssalonen Thanks for your help.
I’ve set the polling period to 60s to simplify debugging.
After just changing the polling rate I got a few Errors on the Binding and the things, but afterwards the polling started working again without any restart.
2020-08-25 22:13:32.404 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'manuel.things'
2020-08-25 22:13:33.023 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Error getting a new connection for endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502]. Error was: java.lang.InterruptedException null
2020-08-25 22:13:33.027 [WARN ] [rt.modbus.internal.ModbusManagerImpl] - Could not connect to endpoint ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502] -- aborting request ModbusPollerThingHandler.ModbusPollerReadRequest@16f2547[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3] [operation ID 382e2da7-da45-4de0-83c0-ee33f6d06340]
2020-08-25 22:13:33.064 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:SelfConsumption 'E3DC SelfConsumption' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.075 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Autarky 'E3DC Autarky' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.097 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:SoC 'E3DC Battery SoC' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.113 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Emergency_Power_Status 'E3DC Emergency Power' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.129 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Charge_Lock 'E3DC EMS charging locked' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.481 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_DisCharge_Lock 'E3DC EMS discharging locked' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.487 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Emergency_Power 'E3DC EMS emergency enabled' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.494 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Wather_Based 'E3DC EMS weather based charging' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.500 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Output_Cut 'E3DC EMS output cut' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.506 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_Charge_Lock_Time 'E3DC EMS charge lock time' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.512 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:EMS_DisCharge_Lock_Time 'E3DC EMS discharge lock time' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.519 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String1_Voltage 'E3DC String 1 Voltage' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.525 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String2_Voltage 'E3DC String 2 Voltage' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.532 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String3_Voltage 'E3DC String 3 Voltage' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.539 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String1_Current 'E3DC String 1 Current' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.546 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String2_Current 'E3DC String 2 Current' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.553 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String3_Current 'E3DC String 3 Current' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.560 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String1_Power 'E3DC String 1 Power' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.566 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String2_Power 'E3DC String 2 Power' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
2020-08-25 22:13:33.573 [ERROR] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:String3_Power 'E3DC String 3 Power' had ModbusConnectionException error on read: ModbusConnectionException(Error connecting to endpoint=ModbusTCPSlaveEndpoint@ab6d37[address=192.168.2.141,port=502])
The debug logs are coming in now, I’ll report tomorrow after the poll stops again.
2020-08-25 22:27:25.492 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (60000ms) poll task BasicPollTask@1a0f798[request=ModbusPollerThingHandler.ModbusPollerReadRequest@a26408[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: 1598387245491
2020-08-25 22:27:25.508 [DEBUG] [bus.handler.ModbusPollerThingHandler] - Thing modbus:poller:e3dc:polling received response PollResult(result=AsyncModbusReadResult(request = ModbusPollerThingHandler.ModbusPollerReadRequest@a26408[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 f5 62 ff ff 0a ae 00 00 00 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 1d 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 37 00 3e 00 00 00 00 00 00 00 00 00 00 00 00 00 00)))
2020-08-25 22:27:25.517 [DEBUG] [ernal.handler.ModbusDataThingHandler] - Thing modbus:data:e3dc:polling:Consumption channels updated: {modbus:data:e3dc:polling:Consumption:number=2734}. readValueType=int32_swap, readIndex=Optional[71], readSubIndex(or 0)=0, extractIndex=71 -> numeric value 2734 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 f5 62 ff ff 0a ae 00 00 00 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 63 63 00 1d 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 37 00 3e 00 00 00 00 00 00 00 00 00 00 00 00 00 00) for request ModbusPollerThingHandler.ModbusPollerReadRequest@a26408[slaveId=1,functionCode=READ_MULTIPLE_REGISTERS,start=0,length=104,maxTries=3]
2020-08-25 22:27:25.522 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Modbus operation ended, timing info: {total: 28 ms, connection: 6, transaction=9, callback=13} [operation ID ebf33f83-c5a1-46b4-a5b0-237184900aca]
@rossko57 I will try fixing the modbus binding first and will probably look at the E3DC Modbus Binding afterwards.
And the chart doesn’t quite show a lot details, all the Wattage values stay the same as the things are not updating.
It seems like the binding mentions the same original post where I got the modbus / E3DC bases from. Thanks for the heads up.
1 Like
Sorry for the late feedback here are my results for now.
After I enabled the debug log, commented all items but one and set the polling rate to 60s I got now error / stops.
Next step I did was uncommenting the other items again. After that another day without any issues.
I now set the polling rate back up to 6s now error until now, I will report again tomorrow as the errors occurred after half a day or so.
Maybe I’ll see an error now or its the observer effect 
Uncommenting or commemting items should never affect how your modbus poller and data rund. There are not direct influence between them. So I would be very surprised if you get any modbus errors.
You can have items or channel links errors though. But it would have nothing to do with how modbus is setup.
@Kim_Andersen yea the commenting was more to ease the logging process in debug mode. But I#ve wanted to test step by step and didnt know if any of the Items were causing the problem.
@ssalonen As said in my last reply, I’ve set the polling rate back to 6s after that the polling stopped this night.
I’ve got no obvious errors as far as I can see.But the test shows that the problem only occours whith the small polling period. Does the Modbus binding have any maxium polling rate?
Maybe it has more to do with the update to the linux strech release and some changes theat come with it.
The last thing logged was a the modbus starting a poll at 03:27:09 :
2020-08-30 03:27:09.236 [DEBUG] [rt.modbus.internal.ModbusManagerImpl] - Executing scheduled (6000ms) poll task BasicPollTask@1b49ddc[request=ModbusPollerThingHandler.ModbusPollerReadRequest@c56322[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: 1598750829234
Your host system has a limit to how fast messages can be sent and received, so yes, of course.
But it’s measured in milliseconds, not seconds.
You should be able to reliably poll many Modbus Items once per second even on a Pi.
You might consider if your target slave can keep up. Some TCP slaves are not very good at handling the repeated TCP connect/reconnect cycles that default Modbus settings produce.
- However -
Any and all issues in these areas would produce error messages, not silently stop.
Would you double check what binding version you have running?
1 Like
Would you double check what binding version you have running?
Of course.
I have the 2.5.8 release Version running:
I see sunspec comes into the picture, but do not think that should affect anything at this level.
Are we looking at a canary in the coal mine here? i.e. a symptom not a cause. What would it look like if your loggng stopped, or i/o in general. What else goes on in your system, does it all appear functional? Other data sources getting charted normally etc.?
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.
- 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.
1 Like
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.
1 Like
Some people attach zipped files renamed as pdf, example modbus_DEBUG_log.zip.pdf (57.4 KB)
It’s a kind of workaround
Thanks for the logs… Why there is nothing else except log messages from modbus binding?
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)
1 Like