jmccrohan / pysolarmanv5

A python module to interact with Solarman Data Logging Sticks
MIT License
132 stars 28 forks source link

Extending support for more devices??? #62

Closed davidrapan closed 4 months ago

davidrapan commented 4 months ago

Hi @jmccrohan and @githubDante!

I have this two issues on my repo: Deye Inverter with LSW3_15_FFFF_1.0.9E Support for Ethernet Logger LSE-3

Both are somehow pointing at first to a little bit older version of Stephans integration to before he was using your lib guys. While the other one requires some additional adjustments the first kinda don't makes sense to me.

I'm now inclined to maybe add some type of a legacy support to my integration to get both flies with one hit. But shouldn't at least the first case be handled by pysolarmanv5?

Thanks, cheers!

githubDante commented 4 months ago

The error comes from the umodbus module and more exactly with the call to parse_response_adu here

The response is longer than expected. From a random Sent/Received pair where the error occurs we have the following:

./solarman-decode a5 1f 00 10 15 bb 52 b2 6e 3c 6a 02 01 b0 17 ee 00 b4 1a 00 00 62 0e b7 65 01 03 0a 32 31 30 36 32 33 34 32 35 38 30 6e 00 00 d6 15
Got args.. [a5 1f 00 10 15 bb 52 b2 6e 3c 6a 02 01 b0 17 ee 00 b4 1a 00 00 62 0e b7 65 01 03 0a 32 31 30 36 32 33 34 32 35 38 30 6e 00 00 d6 15]
Frame start: a5 (valid: true)
V5 Checksum: d6 (valid: true)
Length: 31
Control Code: 5392 (hex: 1015)
Sequence Numbers: 187 82 (hex: bb 52)
Serial Hex: b26e3c6a
Serial: 1782345394
Frame Type (Inverter): 2
Frame Status: 1
Total Time: 15603632
PowerOn Time: 6836
Offset Time: 1706495586
Frame Time: 2024-07-27 18:47:34 +0000 UTC
Checksum: 0 hex: 0000 - RTU start at: 01030a32
Data start: 25 from: 44, 17
=========== RTU Payload - [Response] =========
        Slave Address: 1
        Function Code: 3
        CRC: 0000 (valid: true)
        Quantity: 17
        Data 01030a32313036323334323538306e0000

where we can see that the response is -> 17 (bytes in total) - 4 (slave address + function code + modbus CRC) = 13 bytes which does not match to the request. Read holding registers with quantity 5 should contain only 10 bytes. The V5 sequence numbers match which lead me to believe that this is something specific to the inverter model / requested register.

As for the ethernet loggers #5 might be helpful.

githubDante commented 4 months ago

The modbus errors comes from this code:

from umodbus.client.serial import rtu
req = bytes.fromhex('01030003000575c9')
resp = bytes.fromhex('01030a32313036323334323538306e0000')
rtu.parse_response_adu(resp, req)

The data is the same as in the frames above.

davidrapan commented 4 months ago

So as I thought in that Stephan's inhouse implementation it just did not checked the structure of the data so strictly and that's why it works in there...

Thanks for that thorough analysis of the matter! Really appreciate it!

davidrapan commented 4 months ago

So according to:

2024-07-29 12:54:53.835 DEBUG (MainThread) [custom_components.solarman.api] [178????????] SENT: a5 17 00 10 45 28 00 b2 6e 3c 6a 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 3b 00 36 b4 11 96 15
2024-07-29 12:54:54.058 DEBUG (MainThread) [custom_components.solarman.api] [178????????] RECD: a5 81 00 10 15 28 e6 b2 6e 3c 6a 02 01 4f 84 ef 00 c7 1b 00 00 af f0 b7 65 01 03 6c 00 02 00 e2 00 00 00 00 c5 01 00 03 00 00 00 00 00 00 00 00 00 00 10 2e 10 18 10 4f 09 58 09 4b 09 6b 00 1e 00 1e 00 1e 13 89 51 d2 00 00 53 3d 00 00 51 de 00 00 99 dd 00 00 00 0c 00 00 05 bd 05 bd 05 bd 03 e7 00 00 00 00 00 00 00 00 00 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 12 92 00 16 12 ed 00 15 eb 4e 00 00 88 15
2024-07-29 12:54:54.059 WARNING (MainThread) [custom_components.solarman.api] Querying (59 - 112) failed. #0 [error: unpack requires a buffer of 108 bytes]

It leads me to believe it's a matter of a inverter model rather than some specific register.

jmccrohan commented 4 months ago

Hi @davidrapan,

2024-07-29 12:54:53.835 DEBUG (MainThread) [custom_components.solarman.api] [178????????] SENT: a5 17 00 10 45 28 00 b2 6e 3c 6a 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 3b 00 36 b4 11 96 15
2024-07-29 12:54:54.058 DEBUG (MainThread) [custom_components.solarman.api] [178????????] RECD: a5 81 00 10 15 28 e6 b2 6e 3c 6a 02 01 4f 84 ef 00 c7 1b 00 00 af f0 b7 65 01 03 6c 00 02 00 e2 00 00 00 00 c5 01 00 03 00 00 00 00 00 00 00 00 00 00 10 2e 10 18 10 4f 09 58 09 4b 09 6b 00 1e 00 1e 00 1e 13 89 51 d2 00 00 53 3d 00 00 51 de 00 00 99 dd 00 00 00 0c 00 00 05 bd 05 bd 05 bd 03 e7 00 00 00 00 00 00 00 00 00 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 12 92 00 16 12 ed 00 15 eb 4e 00 00 88 15
2024-07-29 12:54:54.059 WARNING (MainThread) [custom_components.solarman.api] Querying (59 - 112) failed. #0 [error: unpack requires a buffer of 108 bytes]

What inverter is this?

The parsing fails because the Modbus frame should be 113 bytes, but is in fact 115 bytes. Note the two additional 00 00 bytes at the end of the Modbus frame (prior to the V5 checksum 88 and the V5 trailer 15. If you remove the 00 00 bytes, you have valid Modbus frame, but you'd also need to recompute the V5 checksum to have a valid V5 frame.

I'm somewhat reluctant to try to put hacks into Pysolarmanv5 to accommodate it as it is clearly out of spec. However, if we can manage to do it in a clean way we can consider it.

@githubDante That V5 decoder is very slick indeed. Would you consider adding it to utils?

Cheers, Jon

davidrapan commented 4 months ago

Hey @jmccrohan,

Totally understand that, but by original poster words there is many ppl who are forced to use older Stephans integration which is not using pysolarmanv5 :-/ So maybe it is in spec but not that common? Or could be older version of it? I'm just guessing cause there are also some people who claims that V4 works with your lib (backward compatibility is great but I'm not sure we can call it that, haha). But It just confirms to me that the solarman protocol is a terrible mess and I admire your work guys that you were able to reverse engineer it.

What inverter is this?

I'm acting more like a middle man here so I'll get back to you on that.

@githubDante That V5 decoder is very slick indeed. Would you consider adding it to utils?

I second this!

davidrapan commented 4 months ago

I just noticed that the response was decoded with:

CRC: 0000 (valid: true)

So it instead considered those added zeros as CRC instead of

30 6e

Why it says it's valid though?

davidrapan commented 4 months ago

I got another one (But this one is proly not really related):

2024-07-29 16:26:36.229 DEBUG (MainThread) [custom_components.solarman] async_setup_entry({'data': {'name': 'Solarman', 'inverter_discovery': True, 'inverter_host': '192.168.10.52', 'inverter_serial': 4176382624, 'inverter_port': 8899, 'inverter_mb_slave_id': 1, 'lookup_file': 'deye_hybrid.yaml', 'battery_nominal_voltage': 48, 'battery_life_cycle_rating': 6000}, 'disabled_by': None, 'domain': 'solarman', 'entry_id': '01J3ZE3X2CHZRAHA6FZMGDVZ2C', 'minor_version': 1, 'options': {'name': 'Solarman', 'inverter_discovery': True, 'inverter_host': '192.168.10.52', 'inverter_serial': 4176382624, 'inverter_port': 8899, 'inverter_mb_slave_id': 1, 'lookup_file': 'deye_hybrid.yaml', 'battery_nominal_voltage': 48, 'battery_life_cycle_rating': 6000}, 'pref_disable_new_entities': False, 'pref_disable_polling': False, 'source': 'user', 'title': 'Solarman', 'unique_id': None, 'version': 1})
2024-07-29 16:26:36.229 DEBUG (MainThread) [custom_components.solarman.discovery] discover
2024-07-29 16:26:36.236 DEBUG (MainThread) [custom_components.solarman.discovery] _discover: [192.168.10.52, E8FDF87C2F24, 4176382624]
2024-07-29 16:26:37.366 DEBUG (MainThread) [custom_components.solarman.api] {'connections': {('mac', 'e8:fd:f8:7c:2f:24')}, 'identifiers': {('solarman', 4176382624)}, 'name': 'Solarman', 'manufacturer': 'Deye', 'model': 'HYBRID', 'serial_number': 4176382624}
2024-07-29 16:26:37.366 DEBUG (MainThread) [custom_components.solarman] async_setup: coordinator.async_config_entry_first_refresh
2024-07-29 16:26:37.366 DEBUG (MainThread) [custom_components.solarman.parser] Defaults for update_interval: 10, code: 3, min_span: 25, digits: 6
2024-07-29 16:26:37.367 DEBUG (MainThread) [custom_components.solarman.api] Scheduling 4 query requests. #0
2024-07-29 16:26:37.367 DEBUG (MainThread) [custom_components.solarman.api] Querying (3 - 14) ...
2024-07-29 16:26:37.367 INFO (MainThread) [custom_components.solarman.api] Connecting to 192.168.10.52:8899
2024-07-29 16:26:37.392 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] SENT: a5 17 00 10 45 9b 00 a0 8a ee f8 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 03 00 0c b5 cf b0 15
2024-07-29 16:26:37.482 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] RECD: a5 2b 00 10 15 9b b4 a0 8a ee f8 02 01 89 e2 35 00 58 12 00 00 12 c4 71 66 01 03 18 32 32 31 30 32 39 30 32 35 33 00 01 00 00 12 0c 07 00 00 00 01 14 12 12 50 f4 22 15
2024-07-29 16:26:37.483 DEBUG (MainThread) [custom_components.solarman.api] Querying succeeded.
2024-07-29 16:26:37.483 DEBUG (MainThread) [custom_components.solarman.api] Querying (59 - 112) ...
2024-07-29 16:26:37.483 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-29 16:26:37.503 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] Successful reconnect
2024-07-29 16:26:37.503 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] SENT: a5 17 00 10 45 9c 00 a0 8a ee f8 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 3b 00 36 b4 11 54 15
2024-07-29 16:26:37.683 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] RECD: a5 7f 00 10 15 9c b5 a0 8a ee f8 02 01 8a e2 35 00 58 12 00 00 12 c4 71 66 01 03 6c 00 04 00 13 00 00 00 00 1e 7b 00 00 00 09 00 09 00 00 00 00 0e c5 00 00 0e a7 00 00 09 7e 00 00 00 00 00 17 00 00 00 00 13 7d 00 00 00 00 00 00 00 00 00 00 00 00 15 f4 00 00 00 00 00 00 16 12 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 3e 00 5c 01 4c 00 51 13 55 7a 15
2024-07-29 16:26:37.684 DEBUG (MainThread) [custom_components.solarman.api] Querying succeeded.
2024-07-29 16:26:37.685 DEBUG (MainThread) [custom_components.solarman.api] Querying (150 - 195) ...
2024-07-29 16:26:37.685 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-29 16:26:37.703 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] Successful reconnect
2024-07-29 16:26:37.703 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] SENT: a5 17 00 10 45 9d 00 a0 8a ee f8 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 96 00 2e 25 fa 02 15
2024-07-29 16:26:37.876 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] RECD: a5 6f 00 10 15 9d b6 a0 8a ee f8 02 01 8a e2 35 00 58 12 00 00 12 c4 71 66 01 03 5c 0a be 07 08 14 50 12 8e f7 2c 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 c2 48 1a 15
2024-07-29 16:26:37.877 DEBUG (MainThread) [custom_components.solarman.api] Querying succeeded.
2024-07-29 16:26:37.877 DEBUG (MainThread) [custom_components.solarman.api] Querying (244 - 279) ...
2024-07-29 16:26:37.877 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-29 16:26:37.895 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] Successful reconnect
2024-07-29 16:26:37.896 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] SENT: a5 17 00 10 45 9e 00 a0 8a ee f8 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 f4 00 24 04 23 5f 15
2024-07-29 16:26:39.919 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] RECD: a5 10 00 10 15 9e b7 a0 8a ee f8 02 01 8c e2 35 00 5a 12 00 00 12 c4 71 66 05 00 5e 15
2024-07-29 16:26:39.920 WARNING (MainThread) [custom_components.solarman.api] Querying (244 - 279) failed. #0 [V5FrameError: V5 frame does not contain a valid Modbus RTU frame]
2024-07-29 16:26:40.920 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 4
2024-07-29 16:26:40.921 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-29 16:26:40.941 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] Successful reconnect
2024-07-29 16:26:40.941 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] SENT: a5 17 00 10 45 9f 00 a0 8a ee f8 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 f4 00 24 04 23 60 15
2024-07-29 16:26:42.983 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] RECD: a5 10 00 10 15 9f b8 a0 8a ee f8 02 01 8f e2 35 00 5e 12 00 00 12 c4 71 66 05 00 67 15
2024-07-29 16:26:42.984 WARNING (MainThread) [custom_components.solarman.api] Querying (244 - 279) failed. #0 [V5FrameError: V5 frame does not contain a valid Modbus RTU frame]
2024-07-29 16:26:43.985 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 3
2024-07-29 16:26:43.985 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-29 16:26:44.008 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] Successful reconnect
2024-07-29 16:26:44.008 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] SENT: a5 17 00 10 45 a0 00 a0 8a ee f8 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 f4 00 24 04 23 61 15
2024-07-29 16:26:46.040 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] RECD: a5 10 00 10 15 a0 b9 a0 8a ee f8 02 01 92 e2 35 00 61 12 00 00 12 c4 71 66 05 00 6f 15
2024-07-29 16:26:46.040 WARNING (MainThread) [custom_components.solarman.api] Querying (244 - 279) failed. #0 [V5FrameError: V5 frame does not contain a valid Modbus RTU frame]
2024-07-29 16:26:47.041 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 2
2024-07-29 16:26:47.042 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-29 16:26:47.064 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] Successful reconnect
2024-07-29 16:26:47.064 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] SENT: a5 17 00 10 45 a1 00 a0 8a ee f8 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 f4 00 24 04 23 62 15
2024-07-29 16:26:51.067 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] RECD: a5 10 00 10 15 a1 ba a0 8a ee f8 02 01 97 e2 35 00 66 12 00 00 12 c4 71 66 05 00 7b 15
2024-07-29 16:26:51.067 WARNING (MainThread) [custom_components.solarman.api] Querying (244 - 279) failed. #0 [V5FrameError: V5 frame does not contain a valid Modbus RTU frame]
2024-07-29 16:26:52.069 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 1
2024-07-29 16:26:52.070 DEBUG (MainThread) [custom_components.solarman.api] Reader Task done: False, cancelled: False.
2024-07-29 16:26:52.097 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] Successful reconnect
2024-07-29 16:26:52.097 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] SENT: a5 17 00 10 45 a2 00 a0 8a ee f8 02 00 00 00 00 00 00 00 00 00 00 00 00 00 00 01 03 00 f4 00 24 04 23 63 15
2024-07-29 16:26:54.125 DEBUG (MainThread) [custom_components.solarman.api] [4176382624] RECD: a5 10 00 10 15 a2 bb a0 8a ee f8 02 01 9a e2 35 00 69 12 00 00 12 c4 71 66 05 00 83 15
2024-07-29 16:26:54.126 WARNING (MainThread) [custom_components.solarman.api] Querying (244 - 279) failed. #0 [V5FrameError: V5 frame does not contain a valid Modbus RTU frame]
2024-07-29 16:26:55.127 DEBUG (MainThread) [custom_components.solarman.api] Querying attempts left: 0, aborting.
2024-07-29 16:26:55.127 DEBUG (MainThread) [custom_components.solarman.api] Request failed. [Previous Status: Disconnected]
2024-07-29 16:26:55.127 INFO (MainThread) [custom_components.solarman.api] Disconnecting from 192.168.10.52:8899
2024-07-29 16:26:55.128 DEBUG (MainThread) [custom_components.solarman.coordinator] Finished fetching Solarman data in 17.762 seconds (success: False)
2024-07-29 16:26:55.129 DEBUG (MainThread) [custom_components.solarman.coordinator] async_shutdown
2024-07-29 16:26:55.129 INFO (MainThread) [custom_components.solarman.api] Disconnecting from 192.168.10.52:8899
2024-07-29 16:26:55.129 DEBUG (MainThread) [custom_components.solarman.api] Connection lost can be during closing ignored.

But here is more about registers cause first 3 of 4 got through...

githubDante commented 4 months ago

The model of the inverter is DEYE String << something >>. It's visible in the TXT file in the ha-solarman bug report.

The CRC is 0 (0x0000) in both cases and is valid, which leads to a pattern. Probably a firmware bug. It looks like the inverter is adding bytes to the frame in order the CRC code to reach 0. The question is where are those extra bytes.

With the request for the inverter serial number (address 3, quantity 5) there is a 0x0a ('\n') before the serial and 0x6e after it, just before the CRC code. If we remove them the serial number of the inverter becomes 21062342580 but this is still 1 byte longer than expected. As I have access to other DEYE inverters and looking at their serial numbers the correct one in this case should be 2106234258.

But here is more about registers cause first 3 of 4 got through...

The rest are MODBUS exceptions. Incorrect registers maybe ?!?

As for the decoder. It's written in Go and probably it's not suitable for the utils dir, plus the source code is ugly (experimental). I can easily rewrite it in Python though.

githubDante commented 4 months ago

Decoded frames:

./solarman-decode a5 81 00 10 15 28 e6 b2 6e 3c 6a 02 01 4f 84 ef 00 c7 1b 00 00 af f0 b7 65 01 03 6c 00 02 00 e2 00 00 00 00 c5 01 00 03 00 00 00 00 00 00 00 00 00 00 10 2e 10 18 10 4f 09 58 09 4b 09 6b 00 1e 00 1e 00 1e 13 89 51 d2 00 00 53 3d 00 00 51 de 00 00 99 dd 00 00 00 0c 00 00 05 bd 05 bd 05 bd 03 e7 00 00 00 00 00 00 00 00 00 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 12 92 00 16 12 ed 00 15 eb 4e 00 00 88 15 
Got args.. [a5 81 00 10 15 28 e6 b2 6e 3c 6a 02 01 4f 84 ef 00 c7 1b 00 00 af f0 b7 65 01 03 6c 00 02 00 e2 00 00 00 00 c5 01 00 03 00 00 00 00 00 00 00 00 00 00 10 2e 10 18 10 4f 09 58 09 4b 09 6b 00 1e 00 1e 00 1e 13 89 51 d2 00 00 53 3d 00 00 51 de 00 00 99 dd 00 00 00 0c 00 00 05 bd 05 bd 05 bd 03 e7 00 00 00 00 00 00 00 00 00 10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 12 92 00 16 12 ed 00 15 eb 4e 00 00 88 15]
Frame start: a5 (valid: true)
V5 Checksum: 88 (valid: true)
Length: 129
Control Code: 5392 (hex: 1015)
Sequence Numbers: 40 230 (hex: 28 e6)
Serial Hex: b26e3c6a
Serial: 1782345394
Frame Type (Inverter): 2
Frame Status: 1
Total Time: 15696975
PowerOn Time: 7111
Offset Time: 1706553519
Frame Time: 2024-07-29 12:53:25 +0000 UTC
Checksum: 0 hex: 0000 - RTU start at: 01036c00
Data start: 25 from: 142, 115
=========== RTU Payload - [Response] =========
        Slave Address: 1
        Function Code: 3
        CRC: 0000 (valid: true)
        Quantity: 115
        Data 01036c000200e200000000c501000300000000000000000000102e1018104f0958094b096b001e001e001e138951d20000533d000051de000099dd0000000c000005bd05bd05bd03e70000000000000000001000000000000000000000000000000000000000001292001612ed0015eb4e0000
davidrapan commented 4 months ago

Inverter which has the longer responses (that string type with incorrect? serial) is DEYE SUN-9K-G03 with logger LSW3_15_FFFF_1.0.9E

githubDante commented 4 months ago

Actually @jmccrohan is right about the zeroes at the end. Just passed this through the deye-controller:

req = bytes.fromhex('01030003000575c9')
resp = bytes.fromhex('01030a32313036323334323538306e0000')
resp = bytes.fromhex('01030a32313036323334323538306e')
rtu.parse_response_adu(resp, req)
[12849, 12342, 12851, 13362, 13624]
from deye_controller.modbus.protocol import DeviceSerialNumber
serial = DeviceSerialNumber()
serial.value = rtu.parse_response_adu(resp, req)
serial.format()
'2106234258'

so my comment above is a bit off.

Edit: The decoder also shows the CRC as valid without the zeroes:

python solarman_decoder.py a5 1f 00 10 15 bb 52 b2 6e 3c 6a 02 01 b0 17 ee 00 b4 1a 00 00 62 0e b7 65 01 03 0a 32 31 30 36 32 33 34 32 35 38 30 6e d6 15
Frame start: a5 (valid: True)
V5 Checksum: d6 (valid: True)
Length: 31
Control Code: 5392 (hex: 1510)
Sequence numbers: (187, 82) (hex: bb 52)
Serial Hex: 6a3c6eb2
Serial: 1782345394
Frame Type (Inverter): 2
Frame Status: 1
Total Time: 15603632
PowerOn Time: 6836
Offset Time: 1706495586
Frame Time: 2024-07-27 18:47:34
Checksum: 12398 hex: 306e - RTU start at: 01030a3231
========== RTU Payload - [Response] ==========
        Slave address: 1
        Function code: 3
        CRC: 306e (valid: True)
        Quantity: 17
        Data: 01030a32313036323334323538306e
davidrapan commented 4 months ago

I just wonder if this is a unicorn type of a "bug" or it does affect more devices....

Yeah that's why I was talking about those zeroes in the CRC as they are obviously there cause of that.... huh.

davidrapan commented 4 months ago

That invalid V5Frame looks real weird.. Guess there will be somehow messed up the registries it requests:

py solarman_decoder.py a5 10 00 10 15 a2 bb a0 8a ee f8 02 01 9a e2 35 00 69 12 00 00 12 c4 71 66 05 00 83 15
Frame start: a5 (valid: True)
V5 Checksum: 83 (valid: True)
Length: 16
Control Code: V5CtrlCode.V5Response
Sequence numbers: (162, 187) (hex: a2 bb)
Serial Hex: f8ee8aa0
Serial: 4176382624
Frame Type (Inverter): 2
Frame Status: 1
Total Time: 3531418
PowerOn Time: 4713
Offset Time: 1718731794
Frame Time: 2024-07-29 15:45:25+00:00
Checksum: 1280 hex: 500 - RTU start at: 05008315
========== RTU Payload - [Response] ==========
        Slave address: 5
        Function code: 0
        CRC: ffff (valid: False)
        Quantity: 2
        Data: 0500

Had to try the tool, hh, thanks @githubDante!

jmccrohan commented 4 months ago

@davidrapan I've been thinking about how we could incorporate this into pysolarmanv5.

To recap, the issue is that these problematic devices are sending valid V5 frames (header, length, V5 checksum and trailer are all correct), but have these additional 00 00 bytes tacked on to the end of the encapsulated Modbus frame. These are outside of the Modbus spec, and are not correct. I'm not sure how closely you looked at the pysolarmanv5 internals, but the library doesn't do any Modbus parsing itself, and defers to uModbus for that.

Based on the limited number of samples provided in this thread, it seems that the extra bytes are always 00 00 (it would be great if we could confirm this, but I suspect we won't be able to get a definitive answer on this). We can't just do a simple check if the last two bytes in the Modbus frame are 00 00 as this is a valid CRC, and it can occur in real life too:

user@host:~/src/pysolarmanv5$ ./venv/bin/python examples/crc_0000_check.py
2ca812cc7d12dd15645eddf35ae6fd86 0000
0fbe7495c7bd3e4669529eab6cea6e50 0000
2f4b93d4fad94ca4a3d13e6f1bb13bfa 0000
9117a0ad97c4df8df5d9398ecf38407d 0000
6ebaae1918959fe1230a700e35b02b60 0000
5d18621da70aba4db6be158999061261 0000
8e8a3990526d83588dc5dd91368f4ffa 0000
06c906ff1b2741560df56d1b7cf87649 0000
3d0d63e8f4dff48cd1487b6541ec6da3 0000
0940e7ca5a30513ce2c9dd2376d7dfbf 0000
733a4762ae7b7144e95971a3f8d7d018 0000
7086390a9295fdc97e9912a1ccf8e418 0000
305ddad2b11d8049439ce49a3d2fbbab 0000
a51330c57fd2f1a6f30b3b979379869c 0000
61d12b18496ec0bef7ab3c865699aa5a 0000
user@host:~/src/pysolarmanv5$ cat examples/crc_0000_check.py 
from umodbus.client.serial.redundancy_check import get_crc
from random import randbytes

if __name__ == '__main__':
    for i in range(1000000):
        frame = randbytes(16)
        #frame = bytes.fromhex('FFFF00000000000000000000000000')
        crc = get_crc(frame)
        if crc == bytes.fromhex('0000'):
            print(frame.hex() + " " + crc.hex())

I don't want to get into adding custom Modbus parsing logic to pysolarmanv5, so a possible clean solution would be to add a try-except block in _get_modbus_response() to catch that particular uModbus exception, check to see if the last two bytes of the Modbus frame are 00 00, and if they are, remove them from the end of the frame and then pass the frame to the parser again.

@githubDante thoughts?

davidrapan commented 4 months ago

@jmccrohan That makes sense only when it stays simple as that though... but as you said we proly won't find out.

And sure I totally agree that adding any modbus parsing would be really ugly.

I can try that by overriding (as I'm still adjusting some of the methods anyway)

async def _get_modbus_response(self, mb_request_frame):

and catch the exception with

except struct.error:

I guess?

githubDante commented 4 months ago

Starting to think that this is not a bug, but quite the opposite, that it's intentional. A try/except block will help, but probably a CRC check on the RTU frame without the last 2 bytes is better in this case. If the CRC is still valid then we can pass the stripped frame to the parser. There is no guarantee that the last two bytes are always zeroed.

githubDante commented 4 months ago

@davidrapan

and catch the exception with

except struct.error:

I guess?

Yes, you need to import the struct module too.

import struct
...
except struct.error as e:
    if 'requires a buffer of' in e.args[0]:
        ... extra code here in order to process the response ... 
    else:
        raise e
davidrapan commented 4 months ago

I created this monstrosity just to test the idea:

async def _get_modbus_response(self, mb_request_frame):
    """
    Overridden to catch the 00 00
    """
    mb_response_frame = await self._send_receive_modbus_frame(mb_request_frame)
    try:
        self.log.debug("[%s] MBRP: %s", self.serial, mb_response_frame.hex(" "))
        modbus_values = rtu.parse_response_adu(mb_response_frame, mb_request_frame)
    except struct.error as e:
        if not 'requires a buffer of' in e.args[0] or (mb_response_frame[-2] != 0 and mb_response_frame[-1] != 0):
            raise e
        modbus_values = rtu.parse_response_adu(mb_response_frame[0:-2], mb_request_frame)
    return modbus_values

And we will see :-) But to rather check CRC without last 2 bytes no matter the values makes more sense just based on the limited info we have.

davidrapan commented 4 months ago

So yeah it worked: 43

davidrapan commented 4 months ago

Do you guys think that we should put there the same bogus detection you @githubDante placed into that solarman decoder?

Edit: So i changed the row which decides if to raise that exception or not into:

if not 'requires a buffer of' in e.args[0] or get_crc(mb_response_frame[:-4]) != mb_response_frame[-4:-2]:

I just can't get rid of the feeling we are hunting a ghost in here or something 😆

jmccrohan commented 4 months ago

So yeah it worked: 43

Excellent!

Do you guys think that we should put there the same bogus detection you @githubDante placed into that solarman decoder?

I'm not sure I follow.

Edit: So i changed the row which decides if to raise that exception or not into:

if not 'requires a buffer of' in e.args[0] or get_crc(mb_response_frame[:-4]) != mb_response_frame[-4:-2]:

I will create a PR to add this to both sync and async versions of pysolarmanv5.

I just can't get rid of the feeling we are hunting a ghost in here or something 😆

Unfortunately its the nature of the beast when you're reverse engineering undocumented protocols!

davidrapan commented 4 months ago

I'm not sure I follow.

That was just my train of thought which did result in that changed row to rather check that crc instead of looking for zeros.

I will create a PR to add this to both sync and async versions of pysolarmanv5.

Here is the full method which is currently in my repo if you'd like:

async def _get_modbus_response(self, mb_request_frame):
    """
    Overridden to catch the trailing 00 00
    """
    mb_response_frame = await self._send_receive_modbus_frame(mb_request_frame)
    try:
        modbus_values = rtu.parse_response_adu(mb_response_frame, mb_request_frame)
    except struct.error as e:
        if not 'requires a buffer of' in e.args[0] or get_crc(mb_response_frame[:-4]) != mb_response_frame[-4:-2]:
            raise e
        modbus_values = rtu.parse_response_adu(mb_response_frame[:-2], mb_request_frame)
    return modbus_values

Unfortunately its the nature of the beast when you're reverse engineering undocumented protocols!

I mean at the end it still works very well, so...

Edit: I also asked the guy to do some follow up debug logging for us to gather some additional info about those trailing bytes.

githubDante commented 4 months ago

OK, I think I got it. What they do now is to apply the CRC check twice, which in turn adds 0x0000 at the end of the frame.

POC:

from umodbus.client.serial.redundancy_check import get_crc
import random 
def get_rand():
    r = []
    for i in range(10):  # The length of the generated array does not matter 
        r.append(random.randint(0, 255))
    return r

def double_crc(x):
    b = bytearray(x) + get_crc(x)
    return b + get_crc(b)

for i in range(10):
    u = get_rand()
    u = double_crc(u)
    print(u.hex())

6aefeb6ecd86c0adb47198960000
bac5f33e877a536b9c2ee6ce0000
6e84e9476335c7e051983d430000
fa6a88c0bbbc25f68f1bcf190000
32b70988c75093845957ccdf0000
2f3b5b86168f1f20194bdfbb0000
4dee0ed593e70224e47b00290000
61f77420298df423178780d30000
6afba21178d3b89e843a87fa0000
787e7c2d035d4500e54152450000

So it's a straight forward, if the CRC is 0x0000 it's a bogus frame and the last two bytes should be stripped.

Edit: Or at least we should double check the CRC

jmccrohan commented 4 months ago

OK, I think I got it. What they do now is to apply the CRC check twice, which in turn adds 0x0000 at the end of the frame.

POC:

from umodbus.client.serial.redundancy_check import get_crc
import random 
def get_rand():
    r = []
    for i in range(10):  # The length of the generated array does not matter 
        r.append(random.randint(0, 255))
    return r

def double_crc(x):
    b = bytearray(x) + get_crc(x)
    return b + get_crc(b)

for i in range(10):
    u = get_rand()
    u = double_crc(u)
    print(u.hex())

6aefeb6ecd86c0adb47198960000
bac5f33e877a536b9c2ee6ce0000
6e84e9476335c7e051983d430000
fa6a88c0bbbc25f68f1bcf190000
32b70988c75093845957ccdf0000
2f3b5b86168f1f20194bdfbb0000
4dee0ed593e70224e47b00290000
61f77420298df423178780d30000
6afba21178d3b89e843a87fa0000
787e7c2d035d4500e54152450000

So it's a straight forward, if the CRC is 0x0000 it's a bogus frame and the last two bytes should be stripped.

Edit: Or at least we should double check the CRC

It isn't that simple, though. This modified version of my earlier script will generate valid Modbus responses which have a valid CRC of 00 00. Short of trying to parse the Modbus frame, we don't know if the frame is valid, and if the length is correct.

user@host:~/src/pysolarmanv5$ ./venv/bin/python examples/gen_valid_0000_resp.py 
01030a389f622268f75d5145b70000
01030a1c8dcbc28df45a1ce8bb0000
01030a290149daa4c9d6d164bd0000
01030a2ddcef95ada33a894bf10000
01030a72f6ea032648d7fa9a620000
01030a2a6e0676a9a8c420bbdf0000
01030ad4caaf19aae83d9edf5d0000
01030ae690b5b969379313940d0000
01030a885f1d8bfb03321859a80000
01030a0ed5ce54c184bf0fe5f50000
01030ada4646319d703176ef330000
01030a0d49fdfc89a7c22c1b110000
01030a69abf29e868b461fc63b0000
01030a18e160d31ae04fa8c2010000
user@host:~/src/pysolarmanv5$ cat examples/gen_valid_0000_resp.py 
from umodbus.client.serial.redundancy_check import get_crc
from random import randbytes

if __name__ == '__main__':
    for i in range(1000000):
        frame = bytes.fromhex('01030A')
        frame += randbytes(10)
        crc = get_crc(frame)
        if crc == bytes.fromhex('0000'):
            print(frame.hex() + crc.hex())

The try-except solution is the best I think as it requires no additional imports, and requires no Modbus parsing in the library.

EDIT: Are you suggesting that rather than try-except we just validate the Modbus CRC before parsing, and if it fails CRC, remove the final two bytes and pass that to uModbus for parsing?

EDIT2: Forgot to mention, nice work on figuring out the bug generating the extra 00 00 bytes!

githubDante commented 4 months ago

EDIT: Are you suggesting that rather than try-except we just validate the Modbus CRC before parsing, and if it fails CRC, remove the final two bytes and pass that to uModbus for parsing?

Not exactly, the 0x0000 is still a valid CRC, as well as the two bytes before it. The check can be for applied double CRC and safely remove the last two bytes if so. Plus it can be activeted only if the response frame ends with 0x0000. ~So the try/except block even becomes unnecessary.~

~Here https://github.com/jmccrohan/pysolarmanv5/issues/62#issuecomment-2257085764 if the zeroes are removed from the end the CRC validation of the frame will fail.~ Edit: It does not fail, so the try/except block remains the only way

jmccrohan commented 4 months ago

66 merged.

davidrapan commented 4 months ago

One additional question/clarification: Is it a solarman proto or modbus bug then? (Let's assume that "Solarman" introduced that bug even in the second option though). I mean it is in the modbus part right...