mhendriks / P1-Dongel-ESP32

P1-Dongel-ESP32
MIT License
29 stars 15 forks source link

Missing data after wifi outage; faulthy timestamp? #55

Closed HanSjak closed 2 months ago

HanSjak commented 3 months ago

After an outage of wifi I expierienced that the dongle does not write data records when wifi is down. I expected P1-telegram timestamps would be sufficient to write proper records to RNG-files. Is it possible to improve this behaviour?

I tested it stopping wifi at 09h40. With wifi up again at 12h35 I found, after the last correct record in RNGhours.json {"date":"24062308","values":[ 51 etc. :

{"date":"24062312","values":[ 5160.037, 6912.558, 0.097, 0.000, 0.000, 0.000]}, {"date":"24062312","values":[ 5160.086, 6912.558, 0.097, 0.000, 0.000, 0.000]},

The first of these should have a 'timestamp' 24062311 instead of . . . .12 Data in that record is problably the value at around 12h35 instead of 12h00. The second record looks fine.

mhendriks commented 3 months ago

in version 4.8.19 some issues are solved regarding Wifi connectivity. Please try this version.

HanSjak commented 3 months ago

Thank you for quick response! I tried to test after succesfully installing v4.8.19 over 4.8.18, Stopped wifi at 18h25 yesterday. Started it at 00h05, but then I couldn't get contact with the dongle. May be caused by my lack of patience! The dongle asked for wifi info, I tried to fill in the form several times, still no contact.

This morning at about 9, to my surprise, after disconnecting the dongle 2 minutes from P!, I could look after the dongle and downloaded the files. There is no difference compared to my first test. RNGhours: Last records before wifi-down are looking ok {"date":"24062515","values":[  5164.585,  6916.815,     0.097,     0.000,     0.000,     0.000]}, {"date":"24062516","values":[  5164.585,  6916.994,     0.097,     0.000,     0.000,     0.000]}, {"date":"24062517","values":[  5164.585,  6917.228,     0.097,     0.000,     0.000,     0.000]}, Again two records with the same timestamp: {"date":"24062608","values":[  5165.244,  6918.311,     0.097,     0.000,     0.000,     0.000]}, {"date":"24062608","values":[  5165.244,  6918.313,     0.097,     0.000,     0.000,     0.000]},

Log files: Last 12 recs of P1_log.old: {"time":"2024-06-25 18:25:56","log":"Wifi failed to connect and hit timeout"} {"time":"2024-06-25 18:25:56","reboot":"Software reset digital core","reboots":5287} {"time":"2024-06-25 18:25:56","log":"Wifi Starting"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 0 | rssi: 0 | channel : 0"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 2 | rssi: 0 | channel : 6"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 10 | rssi: 0 | channel : 1"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 3 | rssi: 0 | channel : 1"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 11 | rssi: 0 | channel : 1"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 10 | rssi: 0 | channel : 1"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 2 | rssi: 0 | channel : 1"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 1 | rssi: 0 | channel : 1"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 11 | rssi: 0 | channel : 6"} P1.log: Series of wifi events and Software resets upto Software reset digital core","reboots":5294 followed by: {"time":"2024-06-25 18:25:56","log":"Wifi Starting"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 0 | rssi: 0 | channel : 0"} many of the like {"time":"2024-06-25 18:25:56","log":"WiFi-event : 1 | rssi: 0 | channel : 1"} {"time":"2024-06-25 18:25:56","reboot":"Vbat power on reset","reboots":5295} {"time":"2024-06-25 18:25:56","log":"Wifi Starting"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 0 | rssi: 0 | channel : 0"} many of the like {"time":"2024-06-25 18:25:56","log":"WiFi-event : 4 | rssi: -22 | channel : 1"} {"time":"2024-06-25 18:25:56","log":"Connected to 7C:FF:4D:28:09:07. Asking for IP address"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 7 | rssi: -21 | channel : 1"} {"time":"2024-06-25 18:25:56","log":"Wifi Connected"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 13 | rssi: -21 | channel : 1"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 11 | rssi: -21 | channel : 1"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 10 | rssi: -21 | channel : 1"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 11 | rssi: -21 | channel : 1"} {"time":"2024-06-26 08:58:56","log":"MQTT: ... connection FAILED! Will try again in 10 sec"}

In earlier test I didn't get the MQTT . . . failed logging. Does this information help you?

mhendriks commented 3 months ago

Thanks for the information.

This line is interesting

{"time":"2024-06-25 18:25:56","reboot":"Vbat power on reset","reboots":5295}

too many reboots and the reason is power failure. This is because manually reconnect or power issues from the smart meter. Did/Could you try a usb adapter as power supply?

There are some wifi issues too (RSSI is okay). But those could be the result of a bad power supply.

The MQTT warnings are new in the 4.8.19

HanSjak commented 3 months ago

All of the reboots except one due to software reset "{"time":"2024-06-25 18:25:56","reboot":"Software reset digital core","reboots":5287}" Only one line "reboot":"Vbat power on reset","reboots":5295}" which was caused by disconnecting the dongle at 08h58 the morning after I started the test. Red led is visible without any signals of 'weakness'. Nevertheless I 'll start a test with connected power supply.

HanSjak commented 3 months ago

As I said, all except one of the reboots is due to "Software reset". During my two weeks absence with wifi shut off the number of reboots increased from prox. 129 to 5032! Without any Vbat power reboot. Even with adapter I see no better outcome. Now, running version 4.8.19 it looks worse. RNGhours is not properly changed in time. To check this I did an other test shutting off wifi at 12h16.

At 09h10 download RNGhours: recno {"actSlot": 5,"data":[ 1 {"date":"24062402","values":[ 5163.598, 6912.558, 0.097, 0.000, 0.000, 0.000]}, ... .. 38 {"date":"24062515","values":[ 5164.585, 6916.815, 0.097, 0.000, 0.000, 0.000]}, 39 {"date":"24062516","values":[ 5164.585, 6916.994, 0.097, 0.000, 0.000, 0.000]}, 40 {"date":"24062517","values":[ 5164.585, 6917.228, 0.097, 0.000, 0.000, 0.000]}, 41 {"date":"24062608","values":[ 5165.244, 6918.311, 0.097, 0.000, 0.000, 0.000]}, 42 {"date":"24062318","values":[ 5162.597, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 43 {"date":"24062319","values":[ 5162.769, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 44 {"date":"24062320","values":[ 5163.005, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 45 {"date":"24062321","values":[ 5163.167, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 46 {"date":"24062322","values":[ 5163.297, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 47 {"date":"24062323","values":[ 5163.380, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 48 {"date":"24062400","values":[ 5163.470, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 49 {"date":"24062401","values":[ 5163.535, 6912.558, 0.097, 0.000, 0.000, 0.000]} 50 ]}

At 12h10 download RNGhours: actSlot is increased to 8 but no new recs placed in ring!! recno {"actSlot": 8,"data":[ 1 {"date":"24062402","values":[ 5163.598, 6912.558, 0.097, 0.000, 0.000, 0.000]}, . . . . 38 {"date":"24062515","values":[ 5164.585, 6916.815, 0.097, 0.000, 0.000, 0.000]}, 39 {"date":"24062516","values":[ 5164.585, 6916.994, 0.097, 0.000, 0.000, 0.000]}, 40 {"date":"24062517","values":[ 5164.585, 6917.228, 0.097, 0.000, 0.000, 0.000]}, 41 {"date":"24062608","values":[ 5165.244, 6918.311, 0.097, 0.000, 0.000, 0.000]}, 42 {"date":"24062318","values":[ 5162.597, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 43 {"date":"24062319","values":[ 5162.769, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 44 {"date":"24062320","values":[ 5163.005, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 45 {"date":"24062321","values":[ 5163.167, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 46 {"date":"24062322","values":[ 5163.297, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 47 {"date":"24062323","values":[ 5163.380, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 48 {"date":"24062400","values":[ 5163.470, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 49 {"date":"24062401","values":[ 5163.535, 6912.558, 0.097, 0.000, 0.000, 0.000]} 50 ]}

Another try by shutting off wifi at 12h16 and starting it again at 12h39 At 12h47 I could 'see' the dongle, downloading RNGhours supplied the same data as the one above. Download at 13h10 RNGhours: actSlot is increased by 1 which is ok, but no new record inserted in ring. recno {"actSlot": 9,"data":[ 1 {"date":"24062402","values":[ 5163.598, 6912.558, 0.097, 0.000, 0.000, 0.000]}, . . . 38 {"date":"24062515","values":[ 5164.585, 6916.815, 0.097, 0.000, 0.000, 0.000]}, 39 {"date":"24062516","values":[ 5164.585, 6916.994, 0.097, 0.000, 0.000, 0.000]}, 40 {"date":"24062517","values":[ 5164.585, 6917.228, 0.097, 0.000, 0.000, 0.000]}, 41 {"date":"24062608","values":[ 5165.244, 6918.311, 0.097, 0.000, 0.000, 0.000]}, 42 {"date":"24062318","values":[ 5162.597, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 43 {"date":"24062319","values":[ 5162.769, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 44 {"date":"24062320","values":[ 5163.005, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 45 {"date":"24062321","values":[ 5163.167, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 46 {"date":"24062322","values":[ 5163.297, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 47 {"date":"24062323","values":[ 5163.380, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 48 {"date":"24062400","values":[ 5163.470, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 49 {"date":"24062401","values":[ 5163.535, 6912.558, 0.097, 0.000, 0.000, 0.000]} 50 ]}

Download at 14h10 RNGhours: actSlot is increased by 1 which is again ok, but no new records inserted in ring. recno {"actSlot":10,"data":[ 1 {"date":"24062402","values":[ 5163.598, 6912.558, 0.097, 0.000, 0.000, 0.000]}, . . . 38 {"date":"24062515","values":[ 5164.585, 6916.815, 0.097, 0.000, 0.000, 0.000]}, 39 {"date":"24062516","values":[ 5164.585, 6916.994, 0.097, 0.000, 0.000, 0.000]}, 40 {"date":"24062517","values":[ 5164.585, 6917.228, 0.097, 0.000, 0.000, 0.000]}, 41 {"date":"24062608","values":[ 5165.244, 6918.311, 0.097, 0.000, 0.000, 0.000]}, 42 {"date":"24062318","values":[ 5162.597, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 43 {"date":"24062319","values":[ 5162.769, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 44 {"date":"24062320","values":[ 5163.005, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 45 {"date":"24062321","values":[ 5163.167, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 46 {"date":"24062322","values":[ 5163.297, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 47 {"date":"24062323","values":[ 5163.380, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 48 {"date":"24062400","values":[ 5163.470, 6912.558, 0.097, 0.000, 0.000, 0.000]}, 49 {"date":"24062401","values":[ 5163.535, 6912.558, 0.097, 0.000, 0.000, 0.000]} 50 ]}

There is no new logging output in P1.log after the lines which indicate the start of wifi at 12h16 (in reality 12h39!) If you like to see the continuous list of loggings I can post it here.

HanSjak commented 3 months ago

Version 4.8.19 does not write meterreadings in the RNG-files, however actSlot is properly increased. So I switched back to 4.8.18.

Below I summarize some points I experienced when wifi is shut down for some time (version 4.8.18):

Logging lines: During wifi is down: {"time":"2024-06-25 18:25:56","log":"WiFi-event : 10 | rssi: 0 | channel : 6"} . . . . {"time":"2024-06-25 18:25:56","log":"WiFi-event : 11 | rssi: 0 | channel : 6"} {"time":"2024-06-25 18:25:56","log":"Wifi failed to connect and hit timeout"} {"time":"2024-06-25 18:25:56","reboot":"Software reset digital core","reboots":5288} {"time":"2024-06-25 18:25:56","log":"Wifi Starting"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 0 | rssi: 0 | channel : 0"} . . . . {"time":"2024-06-25 18:25:56","log":"WiFi-event : 11 | rssi: 0 | channel : 6"} {"time":"2024-06-25 18:25:56","log":"Wifi failed to connect and hit timeout"} {"time":"2024-06-25 18:25:56","reboot":"Software reset digital core","reboots":5289} {"time":"2024-06-25 18:25:56","log":"Wifi Starting"} {"time":"2024-06-25 18:25:56","log":"WiFi-event : 0 | rssi: 0 | channel : 0"} . . . .

After wifi is up again: "WiFi-event : 5 | rssi: 0 | channel : 1" :::: "Connected to 7C:FF:4D:28:09:07. Asking for IP address"} {"time":"2024-06-23 09:46:07","log":"WiFi-event : 7 | rssi: -22 | channel : 1"} {"time":"2024-06-23 09:46:07","log":"Wifi Connected"} {"time":"2024-06-23 12:51:11","log":"WiFi-event : 5 | rssi: 0 | channel : 1"}

mhendriks commented 3 months ago

When the wifi connection is broken for ±1 minute the dongle will reboot in the 4.8.19 version. This is new because in some other cases the dongle is not available when there is a wifi problem / channel switch / maintenance moment.

HanSjak commented 2 months ago

Does this implie that after wifi connection is down more then 1 minute, writing RNG files stops till wifi is up again and the then following succesfull reboot?

I wonder if it is easy to add a flag in Frontend that says continue with updating RNG files without checking wifi. In that case, when wifi is broken, one has to reboot manually disconnecting the dongle from P1 during a short time to use the web interface again, and RNG files are updated properly.

mhendriks commented 2 months ago

After 1 minute the dongle will reboot. At new startup it discovered no known wifi network and will try for a while. After this it will be forced in hotspot mode. After booting the dongle will write in RNG files after connection to the wifi network. The behaviour is as designed :-( In the future there will be a flag to prevent the reboot mode ...

But the 4.8.x version is using 99.9% of the program storage. The 4.9.x is new and using a different partioning = more program space and less data storage. In this version a flag will be implemented ... something NoRebootOnNoWiFi

HanSjak commented 2 months ago

Wonderful when you can do this! Thank you!!