Modbus TCP bridge stuck in onExecuteWrite state after disable/enable

agendek · February 4, 2025, 8:54pm

Hi,

I’m running openems with goodwe inverter and having issue that modbus bridge stuck in onExecuteWrite state after disabling modbus component and then enabling it. 100% reproducible all the time.

log showing the moment of modbus bridge blocking:

2025-02-04T21:20:41,667 [modbus0 ] INFO  [e.modbus.api.task.AbstractTask]   Execute FC16WriteRegisters [batteryInverter0;unitid=247;ref=47511/0xb997;length=2] Elapsed [262ms]
2025-02-04T21:20:41,667 [modbus0 ] INFO  [ker.internal.CycleTasksManager] [modbus0] State: WRITE -> WAIT_BEFORE_READ (getNextTask)
2025-02-04T21:20:41,667 [modbus0 ] INFO  [ker.internal.CycleTasksManager] [modbus0] State: WAIT_BEFORE_READ -> READ_AFTER_WRITE (onWaitDelayTaskFinished)
2025-02-04T21:20:42,106 [modbus0 ] INFO  [e.modbus.api.task.AbstractTask]   Execute FC3ReadHoldingRegisters [batteryInverter0;unitid=247;priority=LOW;ref=47905/0xbb21;length=2] Elapsed [438ms]
2025-02-04T21:20:42,166 [modbus0 ] INFO  [e.modbus.api.task.AbstractTask]   Execute FC3ReadHoldingRegisters [meter0;unitid=247;priority=HIGH;ref=36005/0x8ca5;length=10] Elapsed [59ms]
2025-02-04T21:20:42,229 [modbus0 ] INFO  [e.modbus.api.task.AbstractTask]   Execute FC3ReadHoldingRegisters [battery0;unitid=247;priority=HIGH;ref=35180/0x896c;length=2] Elapsed [62ms]
2025-02-04T21:20:42,291 [modbus0 ] INFO  [e.modbus.api.task.AbstractTask]   Execute FC3ReadHoldingRegisters [battery0;unitid=247;priority=HIGH;ref=37007/0x908f;length=2] Elapsed [61ms]
2025-02-04T21:20:42,305 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [modbus0] Modified DISABLED Bridge.Modbus.Tcp
2025-02-04T21:20:42,306 [modbus0 ] ERROR [e.modbus.api.task.AbstractTask]   Execute failed FC3ReadHoldingRegisters [batteryInverter0;unitid=247;priority=HIGH;ref=35182/0x896e;length=2] Elapsed [14ms] ModbusIOException: Executing transaction 00 DC 00 00 00 06 F7 03 89 6E 00 02 failed (tried 1 times) General exception - failed to read - Socket closed
2025-02-04T21:20:42,309 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [ctrlFixActivePower0] Deactivate Controller.Ess.FixActivePower
2025-02-04T21:20:42,311 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [ctrlBalancing0] Deactivate Controller.Symmetric.Balancing
2025-02-04T21:20:42,313 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [ctrlFixStateOfCharge0] Deactivate Controller.Ess.FixStateOfCharge
2025-02-04T21:20:42,314 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [ess0] Deactivate Ess.Generic.ManagedSymmetric
2025-02-04T21:20:42,314 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [battery0] Deactivate GoodWe.BMS.BatteryInfo
2025-02-04T21:20:42,315 [c7e92cf)] INFO  [ker.internal.TasksSupplierImpl] [modbus0] Remove Protocol for [battery0] with [4] tasks
2025-02-04T21:20:42,317 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [charger1] Deactivate GoodWe.Charger-PV2
2025-02-04T21:20:42,319 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [batteryInverter0] Deactivate GoodWe.BatteryInverter
2025-02-04T21:20:42,319 [c7e92cf)] INFO  [ker.internal.TasksSupplierImpl] [modbus0] Remove Protocol for [batteryInverter0] with [5] tasks
2025-02-04T21:20:42,321 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [meter0] Deactivate GoodWe.Grid-Meter
2025-02-04T21:20:42,321 [c7e92cf)] INFO  [ker.internal.TasksSupplierImpl] [modbus0] Remove Protocol for [meter0] with [2] tasks
2025-02-04T21:20:42,322 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [meter1] Deactivate GoodWe.Load-Meter
2025-02-04T21:20:42,323 [c7e92cf)] INFO  [ker.internal.TasksSupplierImpl] [modbus0] Remove Protocol for [meter1] with [2] tasks
2025-02-04T21:20:42,332 [_cycle  ] INFO  [ebuglog.ControllerDebugLogImpl] [ctrlDebugLog0] _componentManager[Defective:meter0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.Grid-Meter.1ec9addf-a2c1-46af-97b4-941cd7955bd7))(|(id=modbus0))))] ess0[Unsatisfied reference for battery ((&(enabled=true)(!(service.pid=Ess.Generic.ManagedSymmetric.001a7084-6268-443f-8998-d4ca99129cd5))(|(id=battery0)))),batteryInverter ((&(enabled=true)(!(service.pid=Ess.Generic.ManagedSymmetric.001a7084-6268-443f-8998-d4ca99129cd5))(|(id=batteryInverter0))))] battery0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.BMS.BatteryInfo.e72e7d8e-770f-4d4f-970c-646ac54d74f7))(|(id=modbus0))))] batteryInverter0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.BatteryInverter.68e89c94-17bf-4a6d-98ef-32bc28e1cd36))(|(id=modbus0))))] meter1[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.Load-Meter.dea258fa-22f3-43e6-839c-86bbc2427d74))(|(id=modbus0))))]] _sum[State:Ok]
2025-02-04T21:20:42,403 [modbus0 ] INFO  [e.modbus.api.task.AbstractTask]   Execute FC3ReadHoldingRegisters [batteryInverter0;unitid=247;priority=HIGH;ref=35182/0x896e;length=2] Elapsed [96ms]
2025-02-04T21:20:43,332 [_cycle  ] INFO  [ebuglog.ControllerDebugLogImpl] [ctrlDebugLog0] _componentManager[Defective:meter0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.Grid-Meter.1ec9addf-a2c1-46af-97b4-941cd7955bd7))(|(id=modbus0))))] ess0[Unsatisfied reference for battery ((&(enabled=true)(!(service.pid=Ess.Generic.ManagedSymmetric.001a7084-6268-443f-8998-d4ca99129cd5))(|(id=battery0)))),batteryInverter ((&(enabled=true)(!(service.pid=Ess.Generic.ManagedSymmetric.001a7084-6268-443f-8998-d4ca99129cd5))(|(id=batteryInverter0))))] battery0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.BMS.BatteryInfo.e72e7d8e-770f-4d4f-970c-646ac54d74f7))(|(id=modbus0))))] batteryInverter0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.BatteryInverter.68e89c94-17bf-4a6d-98ef-32bc28e1cd36))(|(id=modbus0))))] meter1[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.Load-Meter.dea258fa-22f3-43e6-839c-86bbc2427d74))(|(id=modbus0))))]|State:FAULT: A configured OpenEMS Component was not activated] _sum[State:Fault]
2025-02-04T21:20:44,331 [_cycle  ] INFO  [ebuglog.ControllerDebugLogImpl] [ctrlDebugLog0] _componentManager[Defective:meter0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.Grid-Meter.1ec9addf-a2c1-46af-97b4-941cd7955bd7))(|(id=modbus0))))] ess0[Unsatisfied reference for battery ((&(enabled=true)(!(service.pid=Ess.Generic.ManagedSymmetric.001a7084-6268-443f-8998-d4ca99129cd5))(|(id=battery0)))),batteryInverter ((&(enabled=true)(!(service.pid=Ess.Generic.ManagedSymmetric.001a7084-6268-443f-8998-d4ca99129cd5))(|(id=batteryInverter0))))] battery0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.BMS.BatteryInfo.e72e7d8e-770f-4d4f-970c-646ac54d74f7))(|(id=modbus0))))] batteryInverter0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.BatteryInverter.68e89c94-17bf-4a6d-98ef-32bc28e1cd36))(|(id=modbus0))))] meter1[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.Load-Meter.dea258fa-22f3-43e6-839c-86bbc2427d74))(|(id=modbus0))))]|State:FAULT: A configured OpenEMS Component was not activated] _sum[State:Fault]
2025-02-04T21:20:45,333 [_cycle  ] INFO  [ebuglog.ControllerDebugLogImpl] [ctrlDebugLog0] _componentManager[Defective:meter0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.Grid-Meter.1ec9addf-a2c1-46af-97b4-941cd7955bd7))(|(id=modbus0))))] ess0[Unsatisfied reference for battery ((&(enabled=true)(!(service.pid=Ess.Generic.ManagedSymmetric.001a7084-6268-443f-8998-d4ca99129cd5))(|(id=battery0)))),batteryInverter ((&(enabled=true)(!(service.pid=Ess.Generic.ManagedSymmetric.001a7084-6268-443f-8998-d4ca99129cd5))(|(id=batteryInverter0))))] battery0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.BMS.BatteryInfo.e72e7d8e-770f-4d4f-970c-646ac54d74f7))(|(id=modbus0))))] batteryInverter0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.BatteryInverter.68e89c94-17bf-4a6d-98ef-32bc28e1cd36))(|(id=modbus0))))] meter1[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.Load-Meter.dea258fa-22f3-43e6-839c-86bbc2427d74))(|(id=modbus0))))]|State:FAULT: A configured OpenEMS Component was not activated] _sum[State:Fault]
2025-02-04T21:20:46,331 [_cycle  ] INFO  [ebuglog.ControllerDebugLogImpl] [ctrlDebugLog0] _componentManager[Defective:meter0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.Grid-Meter.1ec9addf-a2c1-46af-97b4-941cd7955bd7))(|(id=modbus0))))] ess0[Unsatisfied reference for battery ((&(enabled=true)(!(service.pid=Ess.Generic.ManagedSymmetric.001a7084-6268-443f-8998-d4ca99129cd5))(|(id=battery0)))),batteryInverter ((&(enabled=true)(!(service.pid=Ess.Generic.ManagedSymmetric.001a7084-6268-443f-8998-d4ca99129cd5))(|(id=batteryInverter0))))] battery0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.BMS.BatteryInfo.e72e7d8e-770f-4d4f-970c-646ac54d74f7))(|(id=modbus0))))] batteryInverter0[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.BatteryInverter.68e89c94-17bf-4a6d-98ef-32bc28e1cd36))(|(id=modbus0))))] meter1[Unsatisfied reference for Modbus ((&(enabled=true)(!(service.pid=GoodWe.Load-Meter.dea258fa-22f3-43e6-839c-86bbc2427d74))(|(id=modbus0))))]|State:FAULT: A configured OpenEMS Component was not activated] _sum[State:Fault]
2025-02-04T21:20:47,171 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [modbus0] Modified Bridge.Modbus.Tcp
2025-02-04T21:20:47,203 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [battery0] Activate GoodWe.BMS.BatteryInfo
2025-02-04T21:20:47,205 [c7e92cf)] INFO  [ker.internal.TasksSupplierImpl] [modbus0] Add Protocol for [battery0] with [4] tasks
2025-02-04T21:20:47,221 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [batteryInverter0] Activate GoodWe.BatteryInverter
2025-02-04T21:20:47,222 [c7e92cf)] INFO  [ker.internal.TasksSupplierImpl] [modbus0] Add Protocol for [batteryInverter0] with [5] tasks
2025-02-04T21:20:47,224 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [ess0] Activate Ess.Generic.ManagedSymmetric
2025-02-04T21:20:47,227 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [ctrlFixActivePower0] Activate DISABLED Controller.Ess.FixActivePower
2025-02-04T21:20:47,230 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [ctrlFixStateOfCharge0] Activate DISABLED Controller.Ess.FixStateOfCharge
2025-02-04T21:20:47,232 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [charger1] Activate DISABLED GoodWe.Charger-PV2
2025-02-04T21:20:47,236 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [meter0] Activate GoodWe.Grid-Meter
2025-02-04T21:20:47,236 [c7e92cf)] INFO  [ker.internal.TasksSupplierImpl] [modbus0] Add Protocol for [meter0] with [2] tasks
2025-02-04T21:20:47,238 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [ctrlBalancing0] Activate DISABLED Controller.Symmetric.Balancing
2025-02-04T21:20:47,241 [c7e92cf)] INFO  [onent.AbstractOpenemsComponent] [meter1] Activate GoodWe.Load-Meter
2025-02-04T21:20:47,242 [c7e92cf)] INFO  [ker.internal.TasksSupplierImpl] [modbus0] Add Protocol for [meter1] with [2] tasks
2025-02-04T21:20:47,329 [_cycle  ] INFO  [ker.internal.CycleTasksManager] [modbus0] State: READ_AFTER_WRITE unchanged (in onBeforeProcessImage) Delay [0] CYCLE_TIME_TOO_SHORT after PreviousDelay [76ms] -> reduce to [38ms]
2025-02-04T21:20:47,333 [_cycle  ] INFO  [temachine.AbstractStateMachine] [ess0] Changing StateMachine from [UNDEFINED] to [START_BATTERY]
2025-02-04T21:20:47,337 [_cycle  ] INFO  [ebuglog.ControllerDebugLogImpl] [ctrlDebugLog0] _sum[State:Ok] battery0[UNDEFINED, UNDEFINED, UNDEFINED] batteryInverter0[AllowedAC:UNDEFINED;UNDEFINED] ess0[Startbattery|SoC:UNDEFINED|L:UNDEFINED|Allowed:0;0] meter0[L:UNDEFINED] meter1[P:UNDEFINED, E:UNDEFINED] modbus0[CycleDelay:0 ms]
2025-02-04T21:20:47,339 [_cycle  ] INFO  [rter.GoodWeBatteryInverterImpl] [batteryInverter0] Goodwe power 0
2025-02-04T21:20:47,339 [_cycle  ] INFO  [ker.internal.CycleTasksManager] [modbus0] State: READ_AFTER_WRITE -> WRITE (onExecuteWrite)
2025-02-04T21:20:48,329 [_cycle  ] INFO  [ker.internal.CycleTasksManager] [modbus0] State: WRITE unchanged (in onBeforeProcessImage) Delay [0] (time is invalid)
2025-02-04T21:20:48,335 [_cycle  ] INFO  [ebuglog.ControllerDebugLogImpl] [ctrlDebugLog0] _sum[State:Ok] battery0[UNDEFINED, UNDEFINED, UNDEFINED] batteryInverter0[AllowedAC:0;0 W] ess0[Startbattery|SoC:UNDEFINED|L:UNDEFINED|Allowed:0;0] meter0[L:UNDEFINED] meter1[P:UNDEFINED, E:UNDEFINED] modbus0[CycleDelay:0 ms]
2025-02-04T21:20:48,335 [_cycle  ] INFO  [rter.GoodWeBatteryInverterImpl] [batteryInverter0] Goodwe power 0
2025-02-04T21:20:48,336 [_cycle  ] INFO  [ker.internal.CycleTasksManager] [modbus0] State: WRITE -> WRITE (onExecuteWrite)
2025-02-04T21:20:49,329 [_cycle  ] INFO  [ker.internal.CycleTasksManager] [modbus0] State: WRITE unchanged (in onBeforeProcessImage) Delay [0] (time is invalid)

Sn0w3y · February 4, 2025, 9:00pm

Strange, more than 10000 (i guess) devices are out there without this Problem.

Can you post your Config of modbus bridge?

agendek · February 5, 2025, 6:48am

my config:

.../config/Bridge/Modbus/Tcp/b248dbf3-683c-41d8-a5df-759b7c7e92cf.config        
:org.apache.felix.configadmin.revision:=L"45"
alias=""
enabled=B"true"
id="modbus0"
intervalBetweenAccesses=I"0"
invalidateElementsAfterReadErrors=I"1"
ip="192.168.8.103"
logVerbosity="READS_AND_WRITES_DURATION_TRACE_EVENTS"
port=I"502"
service.factoryPid="Bridge.Modbus.Tcp"
service.pid="Bridge.Modbus.Tcp.b248dbf3-683c-41d8-a5df-759b7c7e92cf"

Sn0w3y · February 5, 2025, 7:31am

I would recommend to use Modbus RTU on GoodWe Devices as Modbus TCP is not the stablest Implementation on these Devices