[W] | [p1reader:227] | Unknown data format (0x00). Resetting.

doe81 commented 1 year ago

Issue Description

I get [W] | [p1reader:227] | Unknown data format (0x00). Resetting. It seemed to happen more often during periods of low load.

S34U18 (Sanxing SX631) / Vattenfall

Log

11:51:45 | [D] | [switch:055] | 'p1_cts': Sending state ON
11:51:45 | [D] | [switch:012] | 'status_led' Turning ON.
11:51:45 | [D] | [switch:055] | 'status_led': Sending state ON
11:51:45 | [W] | [p1reader:227] | Unknown data format (0x00). Resetting.
11:51:45 | [D] | [switch:016] | 'p1_cts' Turning OFF.
11:51:45 | [D] | [switch:055] | 'p1_cts': Sending state OFF
11:51:46 | [D] | [switch:016] | 'status_led' Turning OFF.
11:51:46 | [D] | [switch:055] | 'status_led': Sending state OFF
11:51:54 | [D] | [sensor:093] | 'p1mini WiFi Signal': Sending state -72.00000 dBm with 0 decimals of accuracy
11:51:56 | [D] | [switch:012] | 'p1_cts' Turning ON.
11:51:56 | [D] | [switch:055] | 'p1_cts': Sending state ON
11:51:56 | [D] | [switch:012] | 'status_led' Turning ON.
11:51:56 | [D] | [switch:055] | 'status_led': Sending state ON
11:51:59 | [D] | [p1reader:221] | ASCII data format
11:51:59 | [D] | [switch:016] | 'p1_cts' Turning OFF.
11:51:59 | [D] | [switch:055] | 'p1_cts': Sending state OFF
11:51:59 | [D] | [p1reader:282] | CRC verification OK
11:52:00 | [D] | [p1reader:328] | Could not parse value from line '/AUX5U18SEH13F10029'
11:52:00 | [D] | [p1reader:328] | Could not parse value from line '0-0:96.1.0(38303034363937333432383437313035303538393236)'
11:52:00 | [D] | [p1reader:328] | Could not parse value from line '0-0:1.0.0(230528105200W)'
11:52:00 | [D] | [sensor:093] | 'Cumulative Active Import': Sending state 232.07600 kWh with 3 decimals of accuracy
11:52:00 | [D] | [sensor:093] | 'Cumulative Active Export': Sending state 1331.51794 kWh with 3 decimals of accuracy
11:52:00 | [D] | [sensor:093] | 'Cumulative Reactive Import': Sending state 0.86900 kvarh with 3 decimals of accuracy
11:52:00 | [D] | [sensor:093] | 'Cumulative Reactive Export': Sending state 314.38101 kvarh with 3 decimals of accuracy
11:52:00 | [D] | [sensor:093] | 'Momentary Active Import': Sending state 0.00000 kW with 3 decimals of accuracy
11:52:00 | [D] | [sensor:093] | 'Momentary Active Export': Sending state 3.65900 kW with 3 decimals of accuracy
11:52:00 | [D] | [sensor:093] | 'Momentary Reactive Import': Sending state 0.00000 kvar with 3 decimals of accuracy
11:52:00 | [D] | [sensor:093] | 'Momentary Reactive Export': Sending state 0.86200 kvar with 3 decimals of accuracy
11:52:01 | [D] | [sensor:093] | 'Momentary Active Import Phase 1': Sending state 0.00000 kW with 3 decimals of accuracy
11:52:01 | [D] | [sensor:093] | 'Momentary Active Export Phase 1': Sending state 1.06200 kW with 3 decimals of accuracy
11:52:01 | [D] | [sensor:093] | 'Momentary Active Import Phase 2': Sending state 0.00000 kW with 3 decimals of accuracy
11:52:01 | [D] | [sensor:093] | 'Momentary Active Export Phase 2': Sending state 1.30900 kW with 3 decimals of accuracy
11:52:01 | [D] | [sensor:093] | 'Momentary Active Import Phase 3': Sending state 0.00000 kW with 3 decimals of accuracy
11:52:01 | [D] | [sensor:093] | 'Momentary Active Export Phase 3': Sending state 1.28700 kW with 3 decimals of accuracy
11:52:01 | [D] | [sensor:093] | 'Momentary Reactive Import Phase 1': Sending state 0.00000 kvar with 3 decimals of accuracy
11:52:01 | [D] | [sensor:093] | 'Current Phase 1': Sending state 4.80000 A with 1 decimals of accuracy
11:52:04 | [D] | [sensor:093] | 'p1mini WiFi Signal': Sending state -72.00000 dBm with 0 decimals of accuracy
11:52:07 | [D] | [switch:012] | 'p1_cts' Turning ON.
11:52:07 | [D] | [switch:055] | 'p1_cts': Sending state ON
11:52:07 | [D] | [switch:012] | 'status_led' Turning ON.
11:52:07 | [D] | [switch:055] | 'status_led': Sending state ON
11:52:07 | [W] | [p1reader:227] | Unknown data format (0x00). Resetting.
11:52:07 | [D] | [switch:016] | 'p1_cts' Turning OFF.
11:52:07 | [D] | [switch:055] | 'p1_cts': Sending state OFF
11:52:07 | [D] | [switch:016] | 'status_led' Turning OFF.
11:52:07 | [D] | [switch:055] | 'status_led': Sending state OFF
11:52:14 | [D] | [sensor:093] |

Screenshot_20230528_103434_Home Assistant 20230528_105151

Beaky2000 commented 1 year ago

This is a weird one. First I though it would be an unreliable connection causing noise on the serial line, but since the error is always in the same place and with the same "noise" (0x00), that seems unlikely.

My second thought was that the meter might send some extra (0x00) byte(s) after the regular data, but if that was the case, every other attempt to read would be successful, since the error recovery would remove any extra data from the buffer. And if I understand your graphs corerctly, there are long periods of time when you do not get any valid data, right?

One thing you could try, if you want, is to increase the error recovery time. This is a long shot, but if the meter gets into some bad state which it can't get out of because new data is beeing requested too quickly, this might help. On this line in the code: else if (500 < loop_start_time - m_error_recovery_time) ChangeState(states::WAITING); 500 is the time in milliseconds to wait and discard any data recevied in case of an error. You could try to increase to say 30000 for 30 seconds and see if it helps. Like I said, it is a long shot.

You could also try and request updates less often and see if the meter behaves better. The default is 2 seconds and can be changed in the yaml file or via a sensor for Home Assistant.

Other than that I think I would want to dump the contents of the buffer after that incorrect 0x00. If I created a branch which did this, would you be able to test it and report back?

doe81 commented 1 year ago

This is a weird one. First I though it would be an unreliable connection causing noise on the serial line, but since the error is always in the same place and with the same "noise" (0x00), that seems unlikely.

Could it be caused by my bad soldering skills? 😶‍🌫️

One thing you could try, if you want, is to increase the error recovery time. This is a long shot, but if the meter gets into some bad state which it can't get out of because new data is beeing requested too quickly, this might help. On this line in the code: else if (500 < loop_start_time - m_error_recovery_time) ChangeState(states::WAITING); 500 is the time in milliseconds to wait and discard any data recevied in case of an error. You could try to increase to say 30000 for 30 seconds and see if it helps. Like I said, it is a long shot.

You could also try and request updates less often and see if the meter behaves better. The default is 2 seconds and can be changed in the yaml file or via a sensor for Home Assistant.

I tested the update frequency and it still gets the same error. Also implementing the code above didn't really help more than the 30sec wait when the error showed up.

The stages thing is that I update relatively frequently during times of load. During the daytime when I have my solar plant exporting to the grid or during night time when I'm charging the car. But during times of low load, i get this error all the time. My first thought was that it was limiting the updates on the P1 port due to no/smal activity. But a friend said that his meter updates all the time.

Other than that I think I would want to dump the contents of the buffer after that incorrect 0x00. If I created a branch which did this, would you be able to test it and report back?

Sure let's try that.

Beaky2000 commented 1 year ago

While I see some room for improvement with your soldering, I doubt that is the problem, but if you can get that tidied up, it won't hurt. Also, how long is the cable? Shorter cables are always better when it comes to avoiding interference.

Does your friend also run a p1mini? On the exact same kind of meter?

I will see when I have time to implement logging of the data discarded in the error recovery state.

Beaky2000 commented 1 year ago

Ok, I have added the logging to the main branch. Update to the latest version and see what the log says efter the error!

doe81 commented 1 year ago

Seems to be 0

[20:20:12][D][sensor:093]: 'p1mini WiFi Signal': Sending state -64.00000 dBm with 0 decimals of accuracy
[20:20:21][D][switch:012]: 'p1_cts' Turning ON.
[20:20:21][D][switch:055]: 'p1_cts': Sending state ON
[20:20:21][D][switch:012]: 'status_led' Turning ON.
[20:20:21][D][switch:055]: 'status_led': Sending state ON
[20:20:21][W][p1reader:249]: Unknown data format (0x00). Resetting.
[20:20:21][D][switch:016]: 'p1_cts' Turning OFF.
[20:20:21][D][switch:055]: 'p1_cts': Sending state OFF
[20:20:21][D][switch:016]: 'status_led' Turning OFF.
[20:20:21][D][switch:055]: 'status_led': Sending state OFF
[20:20:21][W][p1reader:218]: Discarding: 0000000000
[20:20:22][D][sensor:093]: 'p1mini WiFi Signal': Sending state -71.00000 dBm with 0 decimals of accuracy
[20:20:31][D][switch:012]: 'p1_cts' Turning ON.
[20:20:31][D][switch:055]: 'p1_cts': Sending state ON
[20:20:31][D][switch:012]: 'status_led' Turning ON.
[20:20:31][D][switch:055]: 'status_led': Sending state ON
[20:20:31][W][p1reader:249]: Unknown data format (0x00). Resetting.
[20:20:31][D][switch:016]: 'p1_cts' Turning OFF.
[20:20:31][D][switch:055]: 'p1_cts': Sending state OFF
[20:20:32][D][switch:016]: 'status_led' Turning OFF.
[20:20:32][D][switch:055]: 'status_led': Sending state OFF
[20:20:32][D][sensor:093]: 'p1mini WiFi Signal': Sending state -70.00000 dBm with 0 decimals of accuracy
[20:20:42][D][switch:012]: 'p1_cts' Turning ON.
[20:20:42][D][switch:055]: 'p1_cts': Sending state ON
[20:20:42][D][switch:012]: 'status_led' Turning ON.
[20:20:42][D][switch:055]: 'status_led': Sending state ON
[20:20:42][D][sensor:093]: 'p1mini WiFi Signal': Sending state -69.00000 dBm with 0 decimals of accuracy
[20:20:43][D][p1reader:243]: ASCII data format
[20:20:43][D][switch:016]: 'p1_cts' Turning OFF.
[20:20:43][D][switch:055]: 'p1_cts': Sending state OFF
[20:20:43][D][p1reader:304]: CRC verification OK
[20:20:43][D][p1reader:350]: Could not parse value from line '/AUX5U18SEH13F10029'
[20:20:43][D][p1reader:350]: Could not parse value from line '0-0:96.1.0(38303034363937333432383437313035303538393236)'
[20:20:43][D][p1reader:350]: Could not parse value from line '0-0:1.0.0(230529192045W)'
[20:20:43][D][sensor:093]: 'Cumulative Active Import': Sending state 240.39900 kWh with 3 decimals of accuracy
[20:20:43][D][sensor:093]: 'Cumulative Active Export': Sending state 1455.36206 kWh with 3 decimals of accuracy
[20:20:43][D][sensor:093]: 'Cumulative Reactive Import': Sending state 0.93100 kvarh with 3 decimals of accuracy
[20:20:43][D][sensor:093]: 'Cumulative Reactive Export': Sending state 339.43201 kvarh with 3 decimals of accuracy
[20:20:43][D][sensor:093]: 'Momentary Active Import': Sending state 0.00000 kW with 3 decimals of accuracy
[20:20:43][D][sensor:093]: 'Momentary Active Export': Sending state 0.23200 kW with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Reactive Import': Sending state 0.00000 kvar with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Reactive Export': Sending state 0.82800 kvar with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Active Import Phase 1': Sending state 0.06300 kW with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Active Export Phase 1': Sending state 0.00000 kW with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Active Import Phase 2': Sending state 0.00000 kW with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Active Export Phase 2': Sending state 0.14800 kW with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Active Import Phase 3': Sending state 0.00000 kW with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Active Export Phase 3': Sending state 0.14700 kW with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Reactive Import Phase 1': Sending state 0.00000 kvar with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Reactive Export Phase 1': Sending state 0.37700 kvar with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Reactive Import Phase 2': Sending state 0.00000 kvar with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Reactive Export Phase 2': Sending state 0.27700 kvar with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Reactive Import Phase 3': Sending state 0.00000 kvar with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Momentary Reactive Export Phase 3': Sending state 0.17300 kvar with 3 decimals of accuracy
[20:20:44][D][sensor:093]: 'Voltage Phase 1': Sending state 234.20000 V with 1 decimals of accuracy
[20:20:44][D][sensor:093]: 'Voltage Phase 2': Sending state 234.60001 V with 1 decimals of accuracy
[20:20:44][D][sensor:093]: 'Voltage Phase 3': Sending state 236.70000 V with 1 decimals of accuracy
[20:20:44][D][sensor:093]: 'Current Phase 1': Sending state 1.90000 A with 1 decimals of accuracy
[20:20:44][D][sensor:093]: 'Current Phase 2': Sending state 1.40000 A with 1 decimals of accuracy
[20:20:44][D][sensor:093]: 'Current Phase 3': Sending state 1.10000 A with 1 decimals of accuracy
[20:20:44][D][switch:016]: 'status_led' Turning OFF.
[20:20:44][D][switch:055]: 'status_led': Sending state OFF
[20:20:44][D][p1reader:467]: Cycle times: Message = 1352 ms (80 loops), Processing = 251 ms (6 loops), (Total = 1603 ms) [1]
[20:20:52][D][sensor:093]: 'p1mini WiFi Signal': Sending state -72.00000 dBm with 0 decimals of accuracy
[20:20:53][D][switch:012]: 'p1_cts' Turning ON.
[20:20:53][D][switch:055]: 'p1_cts': Sending state ON
[20:20:53][D][switch:012]: 'status_led' Turning ON.
[20:20:53][D][switch:055]: 'status_led': Sending state ON
[20:20:53][W][p1reader:249]: Unknown data format (0x00). Resetting.
[20:20:53][D][switch:016]: 'p1_cts' Turning OFF.
[20:20:53][D][switch:055]: 'p1_cts': Sending state OFF
[20:20:53][D][switch:016]: 'status_led' Turning OFF.
[20:20:53][D][switch:055]: 'status_led': Sending state OFF
[20:20:53][W][p1reader:218]: Discarding: 00
[20:21:02][D][sensor:093]: 'p1mini WiFi Signal': Sending state -73.00000 dBm with 0 decimals of accuracy
[20:21:04][D][switch:012]: 'p1_cts' Turning ON.
[20:21:04][D][switch:055]: 'p1_cts': Sending state ON
[20:21:04][D][switch:012]: 'status_led' Turning ON.
[20:21:04][D][switch:055]: 'status_led': Sending state ON
[20:21:04][W][p1reader:249]: Unknown data format (0x00). Resetting.
[20:21:04][D][switch:016]: 'p1_cts' Turning OFF.
[20:21:04][D][switch:055]: 'p1_cts': Sending state OFF
[20:21:04][D][switch:016]: 'status_led' Turning OFF.
[20:21:04][D][switch:055]: 'status_led': Sending state OFF
[20:21:04][W][p1reader:218]: Discarding: 0000
[20:21:12][D][sensor:093]: 'p1mini WiFi Signal': Sending state -72.00000 dBm with 0 decimals of accuracy
[20:21:14][D][switch:012]: 'p1_cts' Turning ON.
[20:21:14][D][switch:055]: 'p1_cts': Sending state ON
[20:21:14][D][switch:012]: 'status_led' Turning ON.
[20:21:14][D][switch:055]: 'status_led': Sending state ON
[20:21:18][D][p1reader:243]: ASCII data format
[20:21:18][D][switch:016]: 'p1_cts' Turning OFF.
[20:21:18][D][switch:055]: 'p1_cts': Sending state OFF
[20:21:18][D][p1reader:304]: CRC verification OK

Sometimes it seems like it's not discarding anything.

[20:22:54][D][switch:016]: 'status_led' Turning OFF.
[20:22:54][D][switch:055]: 'status_led': Sending state OFF
[20:22:54][D][p1reader:467]: Cycle times: Message = 2242 ms (134 loops), Processing = 260 ms (6 loops), (Total = 2502 ms) [1]
[20:23:02][D][switch:012]: 'p1_cts' Turning ON.
[20:23:02][D][switch:055]: 'p1_cts': Sending state ON
[20:23:02][D][switch:012]: 'status_led' Turning ON.
[20:23:02][D][switch:055]: 'status_led': Sending state ON
[20:23:02][W][p1reader:249]: Unknown data format (0x00). Resetting.
[20:23:02][D][switch:016]: 'p1_cts' Turning OFF.
[20:23:02][D][switch:055]: 'p1_cts': Sending state OFF
[20:23:02][D][sensor:093]: 'p1mini WiFi Signal': Sending state -67.00000 dBm with 0 decimals of accuracy
[20:23:02][D][switch:016]: 'status_led' Turning OFF.
[20:23:02][D][switch:055]: 'status_led': Sending state OFF
[20:23:02][W][p1reader:218]: Discarding: 00
[20:23:12][D][sensor:093]: 'p1mini WiFi Signal': Sending state -71.00000 dBm with 0 decimals of accuracy
[20:23:13][D][switch:012]: 'p1_cts' Turning ON.
[20:23:13][D][switch:055]: 'p1_cts': Sending state ON
[20:23:13][D][switch:012]: 'status_led' Turning ON.
[20:23:13][D][switch:055]: 'status_led': Sending state ON
[20:23:13][W][p1reader:249]: Unknown data format (0x00). Resetting.
[20:23:13][D][switch:016]: 'p1_cts' Turning OFF.
[20:23:13][D][switch:055]: 'p1_cts': Sending state OFF
[20:23:13][D][switch:016]: 'status_led' Turning OFF.
[20:23:13][D][switch:055]: 'status_led': Sending state OFF
[20:23:13][W][p1reader:218]: Discarding: 00
[20:23:22][D][sensor:093]: 'p1mini WiFi Signal': Sending state -72.00000 dBm with 0 decimals of accuracy
[20:23:23][D][switch:012]: 'p1_cts' Turning ON.
[20:23:23][D][switch:055]: 'p1_cts': Sending state ON
[20:23:23][D][switch:012]: 'status_led' Turning ON.
[20:23:23][D][switch:055]: 'status_led': Sending state ON
[20:23:23][W][p1reader:249]: Unknown data format (0x00). Resetting.
[20:23:23][D][switch:016]: 'p1_cts' Turning OFF.
[20:23:23][D][switch:055]: 'p1_cts': Sending state OFF
[20:23:24][D][switch:016]: 'status_led' Turning OFF.
[20:23:24][D][switch:055]: 'status_led': Sending state OFF
[20:23:32][D][sensor:093]: 'p1mini WiFi Signal': Sending state -70.00000 dBm with 0 decimals of accuracy
[20:23:34][D][switch:012]: 'p1_cts' Turning ON.
[20:23:34][D][switch:055]: 'p1_cts': Sending state ON
[20:23:34][D][switch:012]: 'status_led' Turning ON.
[20:23:34][D][switch:055]: 'status_led': Sending state ON
[20:23:34][W][p1reader:249]: Unknown data format (0x00). Resetting.
[20:23:34][D][switch:016]: 'p1_cts' Turning OFF.
[20:23:34][D][switch:055]: 'p1_cts': Sending state OFF
[20:23:35][D][switch:016]: 'status_led' Turning OFF.
[20:23:35][D][switch:055]: 'status_led': Sending state OFF
[20:23:42][D][sensor:093]: 'p1mini WiFi Signal': Sending state -71.00000 dBm with 0 decimals of accuracy
[20:23:45][D][switch:012]: 'p1_cts' Turning ON.
[20:23:45][D][switch:055]: 'p1_cts': Sending state ON
[20:23:45][D][switch:012]: 'status_led' Turning ON.
[20:23:45][D][switch:055]: 'status_led': Sending state ON
[20:23:48][D][p1reader:243]: ASCII data format
[20:23:48][D][switch:016]: 'p1_cts' Turning OFF.
[20:23:48][D][switch:055]: 'p1_cts': Sending state OFF
[20:23:48][D][p1reader:304]: CRC verification OK

Beaky2000 commented 1 year ago

This is getting stranger and stranger... Sometimes when an update is requested, the meter sends an update with correct checksum, but sometimes it sends a few zero bytes...

I also notice that even when correct data is being received, the sending of data is very slow: "Cycle times: Message = 2242 ms (134 loops)". This is over two seconds to transfer a moderate amount of data! I am starting to wonder if the meter is bad, either your particular unit or the design in general.

There is one thing that would be interesting to test, because it could affect several potential issues. It does involve more soldering though: Connect the RTS cable directly to 5V instead of D2.

This way the RTS signal will be 5V instead of the 3.3V from the ESP output, which is lower than the minimum specified value on many meters. So far I have not heard of any meters where 3.3V does not work, but it is outside of spec.
The RTS signal will be constantly high and it seems to be part of the P1 protocol that this means that the meter will send updates every 10 seconds. Maybe the meter works better in this mode.
The RTS signal will not go low as soon as those 0x00 bytes are received and maybe there will be more data giving a clue about what is going on.

doe81 commented 1 year ago

Thanks for your help. I will try that. When I'm at it is there a maximum length of the cable? Mine is ~25cm

Beaky2000 commented 1 year ago

25 cm should not be a problem. I remember one particular meter (can't remember exactly which one) specifying max 3 meters.

doe81 commented 1 year ago

When I have a high load I get some 0 sometimes up to 4. But it reads the meter successfully several times. Now when there is a very low load I get several 0 even some "e".

Tomorrow I will try to re-soldering.

This is the log with an update set to 2 sec with a low load.

21:34:20 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
21:34:20 | [W] | [p1reader:218] | Discarding: 000000000000000000
21:34:22 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
21:34:22 | [W] | [p1reader:218] | Discarding: 000000000000000000
21:34:24 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
21:34:24 | [W] | [p1reader:218] | Discarding: 0000000000000000000000
21:34:26 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
21:34:26 | [W] | [p1reader:218] | Discarding: 0000000000000000
21:34:28 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
21:34:28 | [W] | [p1reader:218] | Discarding: 00000000000000000000
21:34:30 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
21:34:30 | [W] | [p1reader:218] | Discarding: 000000e00000
21:34:32 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
21:34:32 | [W] | [p1reader:218] | Discarding: 000000000000
21:34:34 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
21:34:34 | [W] | [p1reader:218] | Discarding: 000000000000
21:34:36 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
21:34:36 | [W] | [p1reader:218] | Discarding: 000000000000
21:34:38 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.

I changed it up to 20 sec update time and I got a lot more 00000000 than was described.

23:28:55 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:28:55 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:28:55 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:28:55 | [W] | [p1reader:218] | Discarding: 00000000000000
23:29:15 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:29:15 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:29:15 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:29:15 | [W] | [p1reader:218] | Discarding: 0000000000
23:29:35 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:29:35 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:29:35 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:29:35 | [W] | [p1reader:218] | Discarding: 0000000000
23:29:55 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:29:55 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:29:55 | [W] | [p1reader:218] | Discarding: 00000000000000000000000000000000000000000000000000000000
23:30:15 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:30:15 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:30:15 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:30:15 | [W] | [p1reader:218] | Discarding: 000000000000
23:30:35 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:30:35 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:30:35 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:30:35 | [W] | [p1reader:218] | Discarding: 000000000000000000000000
23:30:55 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:30:55 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:30:55 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000
23:31:15 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:31:15 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:31:15 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000000000000000000000000000000000000000
23:31:15 | [W] | [p1reader:218] | Discarding: 000000000000000000

When I changed back to update time 0.0 updates actually came thru some time even if the Cycle times where high.

23:25:50 | [W] | [p1reader:218] | Discarding: 000000000000000000000000
23:25:50 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:25:50 | [W] | [p1reader:218] | Discarding: 00000000000000000000
23:25:55 | [W] | [p1reader:468] | Cycle times: Message = 3730 ms (226 loops), Processing = 157 ms (4 loops), (Total = 3887 ms) [1]
23:25:55 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:25:55 | [W] | [p1reader:218] | Discarding: 00000000000000000000000000
23:25:55 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:25:55 | [W] | [p1reader:218] | Discarding: 00000000000000000000
23:26:00 | [W] | [p1reader:468] | Cycle times: Message = 3741 ms (270 loops), Processing = 155 ms (4 loops), (Total = 3896 ms) [1]
23:26:00 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:26:00 | [W] | [p1reader:218] | Discarding: 000000000000000000000000
23:26:01 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:26:01 | [W] | [p1reader:218] | Discarding: 00000000000000000000
23:26:05 | [W] | [p1reader:468] | Cycle times: Message = 3698 ms (224 loops), Processing = 156 ms (4 loops), (Total = 3854 ms) [1]
23:26:05 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:26:05 | [W] | [p1reader:218] | Discarding: 000000000000000000000000000000
23:26:05 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:26:05 | [W] | [p1reader:218] | Discarding: 00000000000000000000
23:26:10 | [W] | [p1reader:468] | Cycle times: Message = 3734 ms (325 loops), Processing = 155 ms (4 loops), (Total = 3889 ms) [1]
23:26:10 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:26:10 | [W] | [p1reader:218] | Discarding: 00000000000000000000000000
23:26:15 | [W] | [p1reader:468] | Cycle times: Message = 4288 ms (263 loops), Processing = 155 ms (4 loops), (Total = 4443 ms) [1]
23:26:15 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:26:15 | [W] | [p1reader:218] | Discarding: 0000000000000000000000000000
23:26:20 | [W] | [p1reader:468] | Cycle times: Message = 4259 ms (258 loops), Processing = 156 ms (4 loops), (Total = 4415 ms) [1]
23:26:20 | [W] | [p1reader:249] | Unknown data format (0x00). Resetting.
23:26:20 | [W] | [p1reader:218] | Discarding: 000000000000000000000000
23:26:25 | [W] | [p1reader:468] | Cycle times: Message = 4288 ms (266 loops), Processing = 156 ms (4 loops), (Total = 4444 ms) [1]

Dont know if this gives any clues.

doe81 commented 1 year ago

I moved RTS to 5v.

First, I had the refresh rate up to over 10 sec and I got all the discarding. Then I moved it down to 1 sec and I still haven't seen any discarding, but it refreshes every 5 sec due to long cycle time.

22:59:46 | [W] | [p1reader:249] | Unknown data format (0x34). Resetting.
22:59:46 | [W] | [p1reader:218] | Discarding: 2e372e3028303030302e3030302a6b766172290d0a312d303a34332e372e3028
22:59:46 | [W] | [p1reader:218] | Discarding: 303030302e3030302a6b766172290d0a312d303a34342e372e3028303030302e
22:59:46 | [W] | [p1reader:218] | Discarding: 3230372a6b766172290d0a312d303a36332e372e3028303030302e3030302a6b
22:59:46 | [W] | [p1reader:218] | Discarding: 766172290d0a312d303a36342e372e3028303030302e3133362a6b766172290d
22:59:46 | [W] | [p1reader:218] | Discarding: 0a312d303a33322e372e30283233342e352a56290d0a312d303a35322e372e30
22:59:46 | [W] | [p1reader:218] | Discarding: 283233352e372a56290d0a312d303a37322e372e30283233372e352a56290d0a
22:59:46 | [W] | [p1reader:218] | Discarding: 312d303a33312e372e30283030322e392a41290d0a312d303a35312e372e3028
22:59:46 | [W] | [p1reader:218] | Discarding: 3030312e302a41290d0a312d303a37312e372e30283030302e372a41290d0a21
22:59:46 | [W] | [p1reader:218] | Discarding: 333533430d0a
22:59:58 | [W] | [p1reader:249] | Unknown data format (0x34). Resetting.
22:59:58 | [W] | [p1reader:218] | Discarding: 2e372e3028303030302e3030302a6b766172290d0a312d303a34332e372e3028
22:59:58 | [W] | [p1reader:218] | Discarding: 303030302e3030302a6b766172290d0a312d303a34342e372e3028303030302e
22:59:58 | [W] | [p1reader:218] | Discarding: 3230382a6b766172290d0a312d303a36332e372e3028303030302e3030302a6b
22:59:58 | [W] | [p1reader:218] | Discarding: 766172290d0a312d303a36342e372e3028303030302e3133362a6b766172290d
22:59:58 | [W] | [p1reader:218] | Discarding: 0a312d303a33322e372e30283233342e362a56290d0a312d303a35322e372e30
22:59:58 | [W] | [p1reader:218] | Discarding: 283233352e392a56290d0a312d303a37322e372e30283233372e372a56290d0a
22:59:58 | [W] | [p1reader:218] | Discarding: 312d303a33312e372e30283030322e392a41290d0a312d303a35312e372e3028
22:59:58 | [W] | [p1reader:218] | Discarding: 3030312e302a41290d0a312d303a37312e372e30283030302e372a41290d0a21
22:59:58 | [W] | [p1reader:218] | Discarding: 394346420d0a
23:00:10 | [W] | [p1reader:249] | Unknown data format (0x30). Resetting.
23:00:10 | [W] | [p1reader:218] | Discarding: 28303030302e3030302a6b766172290d0a312d303a34332e372e302830303030
23:00:10 | [W] | [p1reader:218] | Discarding: 2e3030302a6b766172290d0a312d303a34342e372e3028303030302e3230372a
23:00:10 | [W] | [p1reader:218] | Discarding: 6b766172290d0a312d303a36332e372e3028303030302e3030302a6b76617229
23:00:10 | [W] | [p1reader:218] | Discarding: 0d0a312d303a36342e372e3028303030302e3133362a6b766172290d0a312d30
23:00:10 | [W] | [p1reader:218] | Discarding: 3a33322e372e30283233342e302a56290d0a312d303a35322e372e3028323335
23:00:10 | [W] | [p1reader:218] | Discarding: 2e332a56290d0a312d303a37322e372e30283233372e322a56290d0a312d303a
23:00:10 | [W] | [p1reader:218] | Discarding: 33312e372e30283030322e392a41290d0a312d303a35312e372e30283030312e
23:00:10 | [W] | [p1reader:218] | Discarding: 302a41290d0a312d303a37312e372e30283030302e372a41290d0a2143363942
23:00:11 | [W] | [p1reader:218] | Discarding: 0d0a
23:00:17 | [W] | [p1reader:249] | Unknown data format (0x2D). Resetting.
23:00:17 | [W] | [p1reader:218] | Discarding: 303a32342e372e3028303030302e3030302a6b766172290d0a312d303a34332e
23:00:17 | [W] | [p1reader:218] | Discarding: 372e3028303030302e3030302a6b766172290d0a312d303a34342e372e302830
23:00:17 | [W] | [p1reader:218] | Discarding: 3030302e3230372a6b766172290d0a312d303a36332e372e3028303030302e30
23:00:17 | [W] | [p1reader:218] | Discarding: 30302a6b766172290d0a312d303a36342e372e3028303030302e3133372a6b76
23:00:17 | [W] | [p1reader:218] | Discarding: 6172290d0a312d303a33322e372e30283233332e382a56290d0a312d303a3532
23:00:17 | [W] | [p1reader:218] | Discarding: 2e372e30283233352e312a56290d0a312d303a37322e372e30283233372e302a
23:00:17 | [W] | [p1reader:218] | Discarding: 56290d0a312d303a33312e372e30283030322e392a41290d0a312d303a35312e
23:00:17 | [W] | [p1reader:218] | Discarding: 372e30283030312e302a41290d0a312d303a37312e372e30283030302e372a41
23:00:18 | [W] | [p1reader:218] | Discarding: 290d0a21323739310d0a
23:00:20 | [I] | [p1reader:478] | Cycle times: Message = 481 ms (43 loops), Processing = 155 ms (4 loops), (Total = 636 ms) [1]
23:00:25 | [W] | [p1reader:468] | Cycle times: Message = 4492 ms (272 loops), Processing = 155 ms (4 loops), (Total = 4647 ms) [1]
23:00:30 | [W] | [p1reader:468] | Cycle times: Message = 4815 ms (384 loops), Processing = 156 ms (4 loops), (Total = 4971 ms) [1]
23:00:35 | [W] | [p1reader:468] | Cycle times: Message = 4828 ms (415 loops), Processing = 156 ms (4 loops), (Total = 4984 ms) [1]
23:00:40 | [W] | [p1reader:468] | Cycle times: Message = 4822 ms (292 loops), Processing = 156 ms (4 loops), (Total = 4978 ms) [1]
23:00:45 | [W] | [p1reader:468] | Cycle times: Message = 4839 ms (293 loops), Processing = 156 ms (4 loops), (Total = 4995 ms) [1]
23:00:50 | [W] | [p1reader:468] | Cycle times: Message = 4817 ms (306 loops), Processing = 156 ms (4 loops), (Total = 4973 ms) [1]
23:00:55 | [W] | [p1reader:468] | Cycle times: Message = 4819 ms (294 loops), Processing = 155 ms (4 loops), (Total = 4974 ms) [1]
23:01:00 | [W] | [p1reader:468] | Cycle times: Message = 4844 ms (310 loops), Processing = 155 ms (4 loops), (Total = 4999 ms) [1]
23:01:05 | [W] | [p1reader:468] | Cycle times: Message = 4822 ms (292 loops), Processing = 153 ms (4 loops), (Total = 4975 ms) [1]

Beaky2000 commented 1 year ago

The errors when the refresh period is higher than the meter output period are expected, since when RTS is constantly high, the meter outputs at regular intervals (looks like every 5 seconds here, while my Sagemcom does every 10 seconds). If the p1mini has a longer period, it will not begin reading the data in time and the UART buffer will overflow and there are going to be errors like we see here.

But it is interesting that as long as the update period is short enough (you could even set it to 0), you seem to get correct measurements every 5 seconds, which is a big improvement from what you had before! (Even if it can't compete with the two updates per second I can get from my Sagemcom :) )

I suggest we let this run for a couple of days to make sure everything keeps working and in the mean time, I will think about how I would like to add software support for keeping RTS constantly high, so anyone can test this mode easily by just changing the yaml file.

Let me know if you would be willing to test an updated version to verify that it does work with your meter. If you don't want to mess with it now that you finally have it working, I understand, but it would probably be useful for new users with your kind of meter to have a verified solution.

doe81 commented 1 year ago

I can test the new update no problem. Thanks @Beaky2000 for your help 👏🏽

Beaky2000 commented 1 year ago

Ok, @doe81, I have created a new branch 'rts-always-high' for you to test and verify. The steps to do this would be:

Solder RTS back to D2
Switch to the rts-always-high branch and flash
Verify that the problems are back
Look at the Readme.md (in the branch) for instructions
Verify that the problems are solved

doe81 commented 1 year ago

Hi, I'm done @Beaky2000 I tested, and I got the error message back after re-soldering and flash the rts-always-high branch. After editing the yaml file according to the readme.md it worked.

23:41:38 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:38 | [W] | [p1reader:229] | Discarding: 0000
23:41:39 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:39 | [W] | [p1reader:229] | Discarding: 000000
23:41:40 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:40 | [W] | [p1reader:229] | Discarding: 0000000000
23:41:41 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:41 | [W] | [p1reader:229] | Discarding: 0000
23:41:48 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:48 | [W] | [p1reader:229] | Discarding: 00
23:41:48 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:48 | [W] | [p1reader:229] | Discarding: 0000000000
23:41:49 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:49 | [W] | [p1reader:229] | Discarding: 0000
23:41:50 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:50 | [W] | [p1reader:229] | Discarding: 0000
23:41:51 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:51 | [W] | [p1reader:229] | Discarding: 0000
23:41:52 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:52 | [W] | [p1reader:229] | Discarding: 00
23:41:53 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:53 | [W] | [p1reader:229] | Discarding: 0000
23:41:54 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:54 | [W] | [p1reader:229] | Discarding: 0000
23:41:55 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:55 | [W] | [p1reader:229] | Discarding: 00000000
23:41:56 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:41:57 | [W] | [p1reader:258] | Unknown data format (0x00). Resetting.
23:42:04 | [I] | [ota:349] | OTA update finished!
23:42:04 | [I] | [app:134] | Rebooting safely...
23:45:28 | [W] | [api.connection:087] | ESPHome Logs 2023.5.5 (192.168.68.104): Connection closed
23:47:15 | [I] | [ota:113] | Boot seems successful, resetting boot loop counter.

No errors since.

👍👏🏽🔝

Beaky2000 commented 1 year ago

Excellent! Then I will merge this branch into main in a couple of days!

Beaky2000 / esphome-p1mini

[W] | [p1reader:227] | Unknown data format (0x00). Resetting. #11

Issue Description

Log