Debugging Dead Connection MS800

[popopirat]

Hi all,
since about 1 week I loose the connection from Proxy to my inverter at about 5 am every morning. Before that it worked well for 4 months.

In my proxy.log I can detect the following from the last output of yesterday:

'yesterday 16:54:44  INFO | data | [] GEN3: total.Daily_Generation : 1.5kWh'

'yesterday 16:54:44  INFO | data | [] GEN3: total.Total_Generation : 1047.28kWh'
'yesterday 16:59:48  INFO | data | [] GEN3: grid.Output_Power : 9.4W'
'yesterday 17:04:52  INFO | data | [] GEN3: grid.Output_Power : 7.8W'
'yesterday 17:09:57  INFO | data | [] GEN3: grid.Output_Power : 6.8W'
'yesterday 17:15:01  INFO | data | [] GEN3: grid.Output_Power : 5.5W'
'yesterday 17:20:05  INFO | data | [] GEN3: grid.Output_Power : 3.3W'
'yesterday 17:25:09  INFO | data | [] GEN3: env.Inverter_Status : 2'
'yesterday 17:25:09  INFO | data | [] GEN3: grid.Output_Power : 0.0W'
'yesterday 17:31:04  INFO | conn | [G3:1] Accept connection from ('$INVERTER_IP', 56747)'
'yesterday 17:31:19  INFO | conn | [G3:2] Accept connection from ('$INVERTER_IP', 57314)'
'yesterday 17:31:33  INFO | conn | [G3:3] Accept connection from ('$INVERTER_IP', 52381)'
'yesterday 17:31:47  INFO | conn | [G3:4] Accept connection from ('$INVERTER_IP', 54434)'
'yesterday 17:32:00  INFO | conn | [G3:5] Accept connection from ('$INVERTER_IP', 59170)'
'yesterday 17:32:13  INFO | conn | [G3:6] Accept connection from ('$INVERTER_IP', 57018)'
'yesterday 17:32:26  INFO | conn | [G3:7] Accept connection from ('$INVERTER_IP', 53861)'
'yesterday 17:32:38  INFO | conn | [G3:8] Accept connection from ('$INVERTER_IP', 51718)'
'yesterday 17:36:14 WARNING | conn | [:0] Dead connection timeout (360s) for ('172.17.0.2', 5005)'
'yesterday 17:36:14  INFO | conn | [:0] Server loop stopped for r('$INVERTER_IP', 53506)'
'yesterday 17:37:44 WARNING | conn | [G3:1] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'yesterday 17:37:44  INFO | conn | [G3:1] Server loop stopped for r('$INVERTER_IP', 56747)'

With the Dead connection then repeating for three minutes. After that (sunset) there are no messages until erasing numbers at midnight and next sunrise where the inverter should power up again.

Log for today;

'today 00:00:00  INFO | root | Clear daily counters at midnight'

'today 04:56:16  INFO | conn | [G3:9] Accept connection from ('$INVERTER_IP', 50977)'
'today 04:56:28  INFO | conn | [G3:10] Accept connection from ('$INVERTER_IP', 52570)'
'today 04:56:40  INFO | conn | [G3:11] Accept connection from ('$INVERTER_IP', 49486)'
'today 04:56:52  INFO | conn | [G3:12] Accept connection from ('$INVERTER_IP', 61000)'
'today 04:57:03  INFO | conn | [G3:13] Accept connection from ('$INVERTER_IP', 58477)'
'today 04:57:15  INFO | conn | [G3:14] Accept connection from ('$INVERTER_IP', 61975)'
'today 04:57:26  INFO | conn | [G3:15] Accept connection from ('$INVERTER_IP', 55396)'
'today 04:57:38  INFO | conn | [G3:16] Accept connection from ('$INVERTER_IP', 52497)'
'today 04:59:58  INFO | conn | [G3:17] Accept connection from ('$INVERTER_IP', 53061)'
'today 05:00:11  INFO | conn | [G3:18] Accept connection from ('$INVERTER_IP', 50757)'
'today 05:00:23  INFO | conn | [G3:19] Accept connection from ('$INVERTER_IP', 61490)'
'today 05:00:36  INFO | conn | [G3:20] Accept connection from ('$INVERTER_IP', 50267)'
'today 05:00:49  INFO | conn | [G3:21] Accept connection from ('$INVERTER_IP', 60266)'
'today 05:01:02  INFO | conn | [G3:22] Accept connection from ('$INVERTER_IP', 50464)'
'today 05:01:15  INFO | conn | [G3:23] Accept connection from ('$INVERTER_IP', 65151)'
'today 05:01:29  INFO | conn | [G3:24] Accept connection from ('$INVERTER_IP', 50737)'
'today 05:01:43  INFO | conn | [G3:25] Accept connection from ('$INVERTER_IP', 49611)'
'today 05:02:56 WARNING | conn | [G3:9] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:02:56  INFO | conn | [G3:9] Server loop stopped for r('$INVERTER_IP', 50977)'
'today 05:03:08 WARNING | conn | [G3:10] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:03:08  INFO | conn | [G3:10] Server loop stopped for r('$INVERTER_IP', 52570)'
'today 05:03:20 WARNING | conn | [G3:11] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:03:20  INFO | conn | [G3:11] Server loop stopped for r('$INVERTER_IP', 49486)'
'today 05:03:32 WARNING | conn | [G3:12] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:03:32  INFO | conn | [G3:12] Server loop stopped for r('$INVERTER_IP', 61000)'
'today 05:03:43 WARNING | conn | [G3:13] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:03:43  INFO | conn | [G3:13] Server loop stopped for r('$INVERTER_IP', 58477)'
'today 05:03:55 WARNING | conn | [G3:14] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:03:55  INFO | conn | [G3:14] Server loop stopped for r('$INVERTER_IP', 61975)'
'today 05:04:06 WARNING | conn | [G3:15] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:04:06  INFO | conn | [G3:15] Server loop stopped for r('$INVERTER_IP', 55396)'
'today 05:04:18 WARNING | conn | [G3:16] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:04:18  INFO | conn | [G3:16] Server loop stopped for r('$INVERTER_IP', 52497)'
'today 05:06:38 WARNING | conn | [G3:17] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:06:38  INFO | conn | [G3:17] Server loop stopped for r('$INVERTER_IP', 53061)'
'today 05:06:51 WARNING | conn | [G3:18] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:06:51  INFO | conn | [G3:18] Server loop stopped for r('$INVERTER_IP', 50757)'
'today 05:07:03 WARNING | conn | [G3:19] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:07:03  INFO | conn | [G3:19] Server loop stopped for r('$INVERTER_IP', 61490)'
'today 05:07:16 WARNING | conn | [G3:20] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:07:16  INFO | conn | [G3:20] Server loop stopped for r('$INVERTER_IP', 50267)'
'today 05:07:29 WARNING | conn | [G3:21] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:07:29  INFO | conn | [G3:21] Server loop stopped for r('$INVERTER_IP', 60266)'
'today 05:07:42 WARNING | conn | [G3:22] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:07:42  INFO | conn | [G3:22] Server loop stopped for r('$INVERTER_IP', 50464)'
'today 05:07:55 WARNING | conn | [G3:23] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:07:55  INFO | conn | [G3:23] Server loop stopped for r('$INVERTER_IP', 65151)'
'today 05:08:09 WARNING | conn | [G3:24] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:08:09  INFO | conn | [G3:24] Server loop stopped for r('$INVERTER_IP', 50737)'
'today 05:08:23 WARNING | conn | [G3:25] Dead connection timeout (400s) for ('172.17.0.2', 5005)'
'today 05:08:23  INFO | conn | [G3:25] Server loop stopped for r('$INVERTER_IP', 49611)'
'today 06:45:55  INFO | conn | [G3:26] Accept connection from ('$INVERTER_IP', 62717)'
'today 06:46:00  INFO | data | [] GEN3: collector.Collector_Fw_Version : RSW_400_V1.00.17'
'today 06:46:01  INFO | data | [] GEN3: env.Inverter_Status : 1'
'today 06:46:01  INFO | data | [] GEN3: grid.Output_Power : 117.1W'
'today 06:46:01  INFO | data | [] GEN3: total.Daily_Generation : 0.04kWh'
'today 06:46:01  INFO | data | [] GEN3: total.Total_Generation : 1047.32kWh'
'today 06:46:01  INFO | data | [] GEN3: inverter.Max_Designed_Power : -1W'
'today 06:46:01  INFO | data | [] GEN3: inverter.Output_Coefficient : 100.0%'
'today 06:46:01  INFO | data | [] GEN3: inverter.Version : V5.0.11'
'today 06:51:06  INFO | data | [] GEN3: grid.Output_Power : 124.4W'
'today 06:51:06  INFO | data | [] GEN3: total.Daily_Generation : 0.05kWh'
'today 06:51:06  INFO | data | [] GEN3: total.Total_Generation : 1047.33kWh'
'today 06:56:10  INFO | data | [] GEN3: grid.Output_Power : 93.8W'
'today 06:56:10  INFO | data | [] GEN3: total.Daily_Generation : 0.07kWh'
'today 06:56:10  INFO | data | [] GEN3: total.Total_Generation : 1047.35kWh'

I assume the power up is at 4:56 am where the first connection after midnight occurs. Then at 5:02 I get a dead connection. The first power readings however are coming in at 6:46 (about 1:45 h after startup). You can see pretty clearly that it is not "first sun of the day" because it is already up to 117 W instead of about 10 W at this time of the day.

Interestingly, I get a reading in the manufacturer APP for the time missing between first power-up and the first power report at 06:46. Therefore, I suspect there is some issue where the inverter bypasses my pihole DNS?!

How can I debug this issue?

And: What is the IP 172.17.0.2? Is this the tsun-proxy IP (because it shows up in my MQTT Server as connecting client)? Or is it the tsun cloud server?

I would appreciate any help to guide me to a solution on how to debug this!

Cheers!

[s-allius]

Hi,

for details you will find two log files in the log directory of your container. The trace.log will give you more details, since there is a dump of each packet from and to your inverter.
The 400sec timeout is a timeout, if the proxy have never received more than one packet on the new established connection. So I assume that you inverter establish a TCP connection but never send a packet und 6:45...

The IP 172.17.0.x comes from you docker. The container (Proxy, MQTT-broker and HA) are connected over an internal network (in docker). And incoming connections from you inverter are NATed with the IP address of the gateway of this network. If you use portioner you will find this under networks

Cheers Stefan.

[popopirat]

Hi Stefan,
thanks for your great tool and answer!

The IP 172.17.0.x comes from you docker. The container (Proxy, MQTT-broker and HA) are connected over an internal network (in docker). And incoming connections from you inverter are NATed with the IP address of the gateway of this network. If you use portioner you will find this under networks

That is good news, I was a little worried that somehow some chinese server had gotten my mqtt details and got in via the inverter...

Regarding the trace.log.yesterday:
There is the last message at 17:25 when I also have the 0.0 W power output. After that it ends, so I guess that means the inverter is shutdown due to darkness.

For the trace.log of today it starts at 6:45:

'today 06:45:55 INFO | tracer | Received from ('$INVERTER_IP', 62717): BufLen: 48 HdrLen: 23 DtaLen: 25
2 0000 | 00 00 00 2c 10 52 31 37 45 37 34 30 37 30 32 31 | ...,.R17E7407021
3 0010 | 41 30 45 30 43 91 00 08 73 6f 6c 61 72 68 75 62 | A0E0C...solarhub
4 0020 | 0f 73 6f 6c 61 72 68 75 62 40 31 32 33 34 35 36 | .solarhub@123456'
5 'today 06:45:55 INFO | msg | > Ctl: 0x91 (State.received) Msg: 'msg_contact_info''
6 'today 06:45:55 INFO | msg | name: b'solarhub''
7 'today 06:45:55 INFO | msg | mail: b'solarhub@123456''
8 'today 06:45:55 INFO | msg | < Ctl: 0x91 Msg: 'msg_contact_info''
9 'today 06:45:55 INFO | tracer | Transmit to ('$INVERTER_IP', 62717):
10 0000 | 00 00 00 14 10 52 31 37 45 37 34 30 37 30 32 31 | .....R17E7407021
11 0010 | 41 30 45 30 43 91 00 01 | A0E0C...'
12 'today 06:45:59 INFO | tracer | Received from ('$INVERTER_IP', 62717): BufLen: 23 HdrLen: 23 DtaLen: 0
13 0000 | 00 00 00 13 10 52 31 37 45 37 34 30 37 30 32 31 | .....R17E7407021
14 0010 | 41 30 45 30 43 91 22 | A0E0C."'
15 'today 06:45:59 INFO | msg | > Ctl: 0x91 (State.received) Msg: 'msg_get_time''
16 'today 06:45:59 INFO | msg | < Ctl: 0x91 Msg: 'msg_get_time''
17 'today 06:45:59 INFO | tracer | Transmit to ('$INVERTER_IP', 62717):

So this means the inverter has not send any packets to the server before that, even though it is well past sunrise, therefore powered up.

From the

'today 05:01:43 INFO | conn | [G3:25] Accept connection from ('$INVERTER_IP', 49611)'

we know that the inverter was at least connected to the network, right?
Is there a way to debug why it never sent anything or is it just some weird internal magic of the inverter?

Furthermore, how all of this got to my attention was when the micro inverter disappeared from my homeassistant some days ago and I got this

'last-week 07:03:05 INFO | root | Accept connection from ('$INVERTER_IP', 62582)'
'last-week 07:03:10 INFO | data | GEN3: collector.Collector_Fw_Version : RSW_400_V1.00.17 update: True'
'last-week 07:07:14 INFO | root | Shutdown due to SIGTERM'
'last-week 07:07:14 INFO | root | Shutdown complete'
'last-week 07:07:14 INFO | root | Close MQTT Task'
'last-week 07:07:14 WARNING | conn | In loop for l('172.17.0.2', 5005) | r('$INVERTER_IP', 62881): Peer closed.'
'last-week 07:07:14 INFO | root | Server loop stopped for r('$INVERTER_IP', 62881)'
'...
'last-week 07:07:14 WARNING | conn | In loop for l('172.17.0.2', 5005) | r('$INVERTER_IP', 53444): Peer closed.'
'last-week 07:07:14 INFO | root | Server loop stopped for r('$INVERTER_IP', 53444)'.
'last-week 07:07:14 WARNING | mqtt | There are 11 pending publish calls.'
'...
'last-week 07:07:15 WARNING | conn | In loop for l('172.17.0.2', 5005) | r('$INVERTER_IP', 62582): Peer closed.'
'last-week 07:07:15 INFO | root | Server loop stopped for r('$INVERTER_IP', 62582)'
'last-week 07:07:15 WARNING | mqtt | There are 216 pending publish calls.'
'last-week 07:07:15 INFO | root | Close event loop'
'last-week 07:07:15 INFO | root | Finally, exit Server "tsun-proxy"'
'last-week 07:07:18 INFO | root | Server "tsun-proxy - " will be started'
'last-week 07:07:18 INFO | root | Initialize proxy statistics'
'last-week 07:07:18 INFO | root | Scheduler init'
'last-week 07:07:18 INFO | mqtt | start MQTT: host:192.168.178.142 port:1883 user:mqttuser'
'last-week 07:07:18 INFO | mqtt | MQTT broker connection established'
'last-week 07:07:18 INFO | root | Initialize proxy device on home assistant'
'last-week 07:10:56 INFO | root | Shutdown due to SIGTERM'
'last-week 07:10:56 INFO | root | Shutdown complete'
'last-week 07:10:56 INFO | root | Close MQTT Task'
'last-week 07:10:56 INFO | root | Close event loop'
'last-week 07:10:56 INFO | root | Finally, exit Server "tsun-proxy"'
'last-week 07:10:57 INFO | root | Server "tsun-proxy - " will be started'
'last-week 07:10:57 INFO | root | Initialize proxy statistics'
'last-week 07:10:57 INFO | root | Scheduler init'
'last-week 07:10:57 INFO | mqtt | start MQTT: host:192.168.178.142 port:1883 user:mqttuser'
'last-week 07:10:57 INFO | mqtt | MQTT broker connection established'
'last-week 07:10:57 INFO | root | Initialize proxy device on home assistant'
'last-week 16:00:07 INFO | root | Accept connection from ('$INVERTER_IP', 61242)'
'last-week 16:00:27 INFO | data | GEN3: collector.Collector_Fw_Version : RSW_400_V1.00.17 update: True'
'last-week 16:05:33 INFO | data | GEN3: collector.Collector_Fw_Version : RSW_400_V1.00.17 update: False'
'last-week 16:05:34 INFO | data | GEN3: grid.Output_Power : 41.2W update: True'
'last-week 16:05:34 INFO | data | GEN3: input.pv1.Power : 23.7W update: True'
'last-week 16:05:34 INFO | data | GEN3: input.pv2.Power : 19.3W update: True'
'last-week 16:05:34 INFO | data | GEN3: input.pv3.Power : 0.0W update: True'

I basically get the pattern that between 05:08 and approx. 2h later, nothing happens. But then, I get some weird MQTT errors of "There are XX pending publish calls.'' which counts up to over 200. Then I restarted the server and it took 9 h for the inverter to reconnect.

Is this MQTT issue related to my MQTT Server (mosquitto) which does not accept the publications? Or is it the server doing something unexpected?

Cheers!

[s-allius]

Hi popopirat,

it is important to know that in you inverter are two CPUs. One is the DSP, which controls your inverter and collect the measurements. The second is a small WiFi module, which only forward the data from the DSP to the network.
If the DSP don't supply data the WiFi Module still establishes a WiFi connection, but you never may not send any data.

in the proxy log you should see something like:

'2024-09-27 00:28:41  INFO |  msg | >   Ctl: 0x91 (State.received) Msg: 'msg_collector_data''
'2024-09-27 00:28:41  INFO |  msg | <   Ctl: 0x99 Msg: 'msg_collector_data''

for data about the WiFi module. And

'2024-09-27 00:28:42  INFO |  msg | >   Ctl: 0x91 (State.received) Msg: 'msg_inverter_data''
'2024-09-27 00:28:42  INFO |  msg | <   Ctl: 0x99 Msg: 'msg_inverter_data''

for data with measurements of your inverter.

After the first msg_inverter_data message the state will changed from receivedto ùp`in the logs.

Of course it is possible, that there are any data, which the proxy can't parse well. Maybe if you have a very old or very new message. Than you can send me a log over at least 7-10 minutes and I can check it.
But normally you should see then some increase error counters in HomeAssistants.

You can send me a trace to: DataType76@allius.de