Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging into logfile stops working after lots of content has to be written in a short time #1674

Closed
Slider0007 opened this issue Dec 23, 2022 · 7 comments
Labels
bot-reply Rolling Build bug Something isn't working

Comments

@Slider0007
Copy link
Collaborator

Slider0007 commented Dec 23, 2022

The Problem

After lots of content has to be written to the logfile in a short time (e.g. DEBUG loglevel + publishing HA discovery topcis after start of the device + Webinterface access) the writing into the log file stops working and negativly impact the rest of the system. This is reproducable. Only a reboot fixes the problem. Starting with lower log level (reduced amount of data to be logged), no issues at all.

##############################################
Test with latest rolling Remove unnecessary null pointer checks

Lofgile size: ca. 300KB

Serial log:

I (22162) SNTP: Time is synced with NTP Server 192.168.2.1
I (22172) GPIO: read GPIO config and init GPIO
I (22182) GPIO: GPIO init completed, handler is disabled
I (22202) MQTT IF: Init
I (22222) MQTT IF: Client started, waiting for established connection...
I (22242) MQTT IF: Connected to broker
I (22272) TFLITE SERVER: Round #1 started
I (32272) MQTT SERVER: MQTT - Sending Homeassistant Discovery Topics (Meter Type: water, Value Unit: m³ , Rate Unit: m³/h)...
E (32332) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32342) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32342) diskio_sdmmc: sdmmc_write_blocks failed (257)

Logfile:

[0d00h00m20s] 2022-12-23T19:16:10 <INF> [MQTT IF] Init
[0d00h00m20s] 2022-12-23T19:16:10 <INF> [MQTT IF] Client started, waiting for established connection...
[0d00h00m20s] 2022-12-23T19:16:10 <INF> [MQTT IF] Connected to broker
[0d00h00m20s] 2022-12-23T19:16:10 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/connection, content: connected (msg_id=1)
[0d00h00m20s] 2022-12-23T19:16:10 <DBG> [MQTT IF] topic water/WaterMeterTest/ctrl/flow_start subscribe successful, msg_id=2
[0d00h00m20s] 2022-12-23T19:16:10 <DBG> [TFLITE SERVER] ----------------------------------------------------------------
[0d00h00m30s] 2022-12-23T19:16:20 <INF> [MQTT SERVER] MQTT - Sending Homeassistant Discovery Topics (Meter Type: water, Value Unit: m³ , Rate Unit: m³/h)...
[0d00h00m30s] 2022-12-23T19:16:20 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/uptime/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-uptime", "obje.. (msg_id=3)
[0d00h00m30s] 2022-12-23T19:16:20 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/MAC/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-MAC", "object_.. (msg_id=4)
[0d00h00m30s] 2022-12-23T19:16:20 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/hostname/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-hostname", "ob.. (msg_id=5)
[0d00h00m30s] 2022-12-23T19:16:20 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/freeMem/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-freeMem", "obj.. (msg_id=6)
[0d00h00m30s] 2022-12-23T19:16:20 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/wifiRSSI/config, c --> stops logging in between

###############################################
Same setup - test with rolling before commit "Logfile write optimization": Trigger a flow start by REST API or MQTT

logfile size: ca. 300KB
If the logfile is < ca. 100KB --> no missing messages

Serial log:

I (22330) MQTT IF: Init
I (22360) MQTT IF: Client started, waiting for established connection...
I (22370) GPIO: read GPIO config and init GPIO
I (22400) GPIO: GPIO init completed, handler is disabled
I (22420) TFLITE SERVER: Round #1 started
I (22430) MQTT IF: Connected to broker
I (32490) MQTT SERVER: MQTT - Sending Homeassistant Discovery Topics (Meter Type: water, Value Unit: m³ , Rate Unit: m³/h)...
E (32560) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32570) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32580) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32580) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32590) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (32590) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (32620) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32620) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32630) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (32630) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (32640) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (32640) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (32650) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (32650) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (32670) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (32670) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (32690) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32690) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32720) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (32720) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (32750) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32750) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32760) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (32760) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (32790) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32790) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32800) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (32800) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (32820) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32820) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32840) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32840) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32860) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32860) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32920) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (32920) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (32980) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (32980) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (33050) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (33120) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (33140) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (33160) diskio_sdmmc: sdmmc_read_blocks failed (257)
--> way more write error message

Logfile:

[0d00h00m20s] 2022-12-23T19:36:52 <INF> [MQTT IF] Init
[0d00h00m20s] 2022-12-23T19:36:52 <INF> [MQTT IF] Client started, waiting for established connection...
[0d00h00m20s] 2022-12-23T19:36:52 <DBG> [TFLITE SERVER] ----------------------------------------------------------------
[0d00h00m20s] 2022-12-23T19:36:52 <INF> [TFLITE SERVER] Round #1 started
[0d00h00m24s] 2022-12-23T19:36:56 <DBG> [MAIN SERVER] info_get_handler
[0d00h00m24s] 2022-12-23T19:36:56 <DBG> [MAIN SERVER] info_get_handler
[0d00h00m24s] 2022-12-23T19:36:56 <DBG> [MAIN SERVER] info_get_handler
[0d00h00m26s] 2022-12-23T19:36:58 <DBG> [MAIN SERVER] info_get_handler
[0d00h00m27s] 2022-12-23T19:36:58 <DBG> [MAIN SERVER] info_get_handler
[0d00h00m30s] 2022-12-23T19:37:02 <INF> [MQTT SERVER] MQTT - Sending Homeassistant Discovery Topics (Meter Type: water, Value Unit: m³ , Rate Unit: m³/h)...
[0d00h00m30s] 2022-12-23T19:37:02 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/uptime/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-uptime", "obje.. (msg_id=3)
[0d00h00m30s] 2022-12-23T19:37:02 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/MAC/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-MAC", "object_.. (msg_id=4)

--> MISSING MESSAGES

[0d00h00m30s] 2022-12-23T19:37:02 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/test_error/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-test_error", ".. (msg_id=22)

--> MISSING MESSAGE

[0d00h00m31s] 2022-12-23T19:37:02 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/test_rate_per_time_unit/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-test_rate_per_.. (msg_id=23)

--> MISSING MESSAGE

[0d00h00m31s] 2022-12-23T19:37:02 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/test_timestamp/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-test_timestamp.. (msg_id=25)
[0d00h00m31s] 2022-12-23T19:37:02 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/test_json/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-test_json", "o.. (msg_id=26)

--> MISSING MESSAGE

[0d00h00m31s] 2022-12-23T19:37:02 <DBG> [MQTT SERVER] Publishing static MQTT topics...
[0d00h00m31s] 2022-12-23T19:37:02 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/MAC, content: 40:22:D8:04:DF:A8 (msg_id=28)
[0d00h00m31s] 2022-12-23T19:37:02 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/IP, content: 192.168.2.20 (msg_id=29)

--> MISSING MESSAGE

[0d00h00m31s] 2022-12-23T19:37:02 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/interval, content: 2.0 (msg_id=31)
[0d00h00m31s] 2022-12-23T19:37:02 <DBG> [MQTT SERVER] Publishing system MQTT topics...
[0d00h00m31s] 2022-12-23T19:37:02 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/uptime, content: 17 (msg_id=32)

--> MISSING MESSAGE

[0d00h00m31s] 2022-12-23T19:37:03 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/status, content: Take Image (msg_id=36)
[0d00h00m40s] 2022-12-23T19:37:12 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/status, content: Aligning (msg_id=37)
[0d00h00m56s] 2022-12-23T19:37:28 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/status, content: Digitalization of ROIs (msg_id=38)
[0d00h00m56s] 2022-12-23T19:37:28 <DBG> [CNN] doFlow after alignment
[0d00h00m57s] 2022-12-23T19:37:28 <DBG> [OTA FILE] log_get_last_part_handler

[0d00h00m56s] 2022-12-23T19:37:28 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/status, content: Digitalization of ROIs (msg_id=38)
[0d00h00m56s] 2022-12-23T19:37:28 <DBG> [CNN] doFlow after alignment
[0d00h00m57s] 2022-12-23T19:37:28 <DBG> [OTA FILE] log_get_last_part_handler

Version

Rolling

Logfile

See text

Expected Behavior

No response

Screenshots

No response

Additional Context

No response

@Slider0007 Slider0007 added the bug Something isn't working label Dec 23, 2022
@caco3
Copy link
Collaborator

caco3 commented Dec 23, 2022

wifiRSSI/config, c --> stops logging in between

hmm, thats very odd! My change should not have an impact of the writing of a single line (only to keep the file open between the lines)

E (32560) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32570) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32580) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32580) diskio_sdmmc: sdmmc_write_blocks failed (257)
E (32590) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (32590) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt

This indicates that it tries to open the file but fails. Again this seems to have another root cause (the diskio issue).

@caco3
Copy link
Collaborator

caco3 commented Dec 23, 2022

@Slider0007
I made a branch https://github.com/jomjol/AI-on-the-edge-device/tree/make-logfile-handling-configurable which revert that change again (its now configurable), see 5689d04#diff-a5c6a0ed44b03e2ff5087444da192eebc406d83608ee0a046cb552e2e4707649R22

Can you test if the issue is the same?

@Slider0007
Copy link
Collaborator Author

Slider0007 commented Dec 23, 2022

@caco3: I've just tested with your branch version. Now the behaviour is the same than in "the old days". Why more errors in serial log but system is kept running and responsive.

Whenver the logfile is almost zero size or log level is less than DEBUG, no messages are missing.

Serial log:

I (15892) LOGFILE: Log Level set to DEBUG
I (15892) GPIO: read GPIO config and init GPIO
I (15912) GPIO: GPIO init completed, handler is disabled
I (15942) MQTT IF: Init
I (15962) MQTT IF: Client started, waiting for established connection...
I (15992) MQTT IF: Connected to broker
I (16062) TFLITE SERVER: Round #1 started
I (19372) BLINK: Flash - done
I (26052) MQTT SERVER: MQTT - Sending Homeassistant Discovery Topics (Meter Type: water, Value Unit: m³ , Rate Unit: m³/h)...
E (26222) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (26222) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (26232) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (26242) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (26252) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (26252) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (26352) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (26352) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (26512) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (26512) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (26552) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (26552) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (26562) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (26562) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
E (26572) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (26572) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt
I (34262) OTA FILE: uri: /log
I (34272) OTA FILE: File contains 313842 bytes
I (71232) POSTPROC: main: Raw: 444.66769, Value: , Status: Neg. Rate - Read:  - Raw: 444.66769 - Pre: 990.67669
I (71302) POSTPROC: test: Raw: 4.6, Value: , Status: Neg. Rate - Read:  - Raw: 4.6 - Pre: 9.7
I (71702) TFLITE SERVER: Round #1 completed
I (72882) OTA FILE: uri: /log
I (72892) OTA FILE: File contains 321964 bytes

Logfile:

[0d00h00m14s] 2022-12-23T23:24:40 <INF> [MQTT IF] Init
[0d00h00m14s] 2022-12-23T23:24:40 <INF> [MQTT IF] Client started, waiting for established connection...
[0d00h00m14s] 2022-12-23T23:24:40 <DBG> [TFLITE SERVER] ----------------------------------------------------------------
[0d00h00m14s] 2022-12-23T23:24:40 <INF> [TFLITE SERVER] Round #1 started
[0d00h00m24s] 2022-12-23T23:24:50 <INF> [MQTT SERVER] MQTT - Sending Homeassistant Discovery Topics (Meter Type: water, Value Unit: m³ , Rate Unit: m³/h)...
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/uptime/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-uptime", "obje.. (msg_id=3)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/MAC/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-MAC", "object_.. (msg_id=4)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/hostname/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-hostname", "ob.. (msg_id=5)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/freeMem/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-freeMem", "obj.. (msg_id=6)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/wifiRSSI/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-wifiRSSI", "ob.. (msg_id=7)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/CPUtemp/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-CPUtemp", "obj.. (msg_id=8)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/interval/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-interval", "ob.. (msg_id=9)

--> MISSING

[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/main_raw/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-main_raw", "ob.. (msg_id=13)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/main_error/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-main_error", ".. (msg_id=14)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/main_rate_per_time_unit/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-main_rate_per_.. (msg_id=15)

--> MISSING

[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/main_timestamp/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-main_timestamp.. (msg_id=17)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/main_json/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-main_json", "o.. (msg_id=18)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/binary_sensor/water/WaterMeterTest/main_problem/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-main_problem",.. (msg_id=19)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/test_value/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-test_value", ".. (msg_id=20)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/test_raw/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-test_raw", "ob.. (msg_id=21)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/test_error/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-test_error", ".. (msg_id=22)

--> MISSING

[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: homeassistant/sensor/water/WaterMeterTest/test_rate_per_digitalization_round/config, content: { "~": "water/WaterMeterTest", "unique_id": "water/WaterMeterTest-test_rate_per_.. (msg_id=24)

--> MISSING

[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT SERVER] Publishing static MQTT topics...
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/MAC, content: 40:22:D8:04:DF:A8 (msg_id=28)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/IP, content: 192.168.2.20 (msg_id=29)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/hostname, content: WaterMeterTest (msg_id=30)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/interval, content: 2.0 (msg_id=31)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT SERVER] Publishing system MQTT topics...
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/uptime, content: 24 (msg_id=32)
[0d00h00m24s] 2022-12-23T23:24:50 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/freeMem, content: 3019811 (msg_id=33)
[0d00h00m24s] 2022-12-23T23:24:51 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/wifiRSSI, content: -65 (msg_id=34)
[0d00h00m24s] 2022-12-23T23:24:51 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/CPUtemp, content: 64 (msg_id=35)
[0d00h00m24s] 2022-12-23T23:24:51 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/status, content: Take Image (msg_id=36)
[0d00h00m32s] 2022-12-23T23:24:58 <DBG> [OTA FILE] log_get_last_part_handler
[0d00h00m34s] 2022-12-23T23:25:00 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/status, content: Aligning (msg_id=37)
[0d00h00m50s] 2022-12-23T23:25:16 <DBG> [MQTT IF] Published topic: water/WaterMeterTest/status, content: Digitalization of ROIs (msg_id=38)

@caco3
Copy link
Collaborator

caco3 commented Dec 23, 2022

But we have the same issue:

E (26222) diskio_sdmmc: sdmmc_read_blocks failed (257)
E (26222) LOGFILE: Can't open log file /sdcard/log/message/log_2022-12-23.txt

So that indicates that this issuse is not due to my change!

@Slider0007
Copy link
Collaborator Author

@caco3: After some more testing I was able to get the optimized logfile handling working on my side as well. I changed mainly only stack sizes. The positive side effect of these modifications is that the prevoius handling (open / close for every write into the logfile) is also working without any issues anymore. I tested both variants (open file and reuse handle / open/close for every write) with logfile sizes of ca. 10MB. I have for 99,9% no issues with SD read/write errors with both variants. I wasn't able to see differences.
I created a branch (based on your branch - https://github.com/jomjol/AI-on-the-edge-device/tree/make-logfile-handling-configurable) were my changes can be tested.

Two versions are available:
Default: https://github.com/jomjol/AI-on-the-edge-device/actions/runs/3777977537
Activated task debug (serial log): https://github.com/jomjol/AI-on-the-edge-device/actions/runs/3777886516

As Reference (your branch with activated TaskDebug): https://github.com/jomjol/AI-on-the-edge-device/actions/runs/3777788474

Whenever the really really rarly SD issues occured, with the new approach the system did not completly lock up anymore, but was extremly slow. This was not (or less) happening with "old style". Due to the fact that a failure free operation cannot be guranteed I would prefer a more failure-tolerant approach which tents my to stay with the old style even I would technically prefer the new verison.

An additional second positive side effect of the changes is the fact, that we'd have ca. 27kB more min. free heap (7kB --> 34kB)

@jomjol, @haverland: FYI

@Slider0007
Copy link
Collaborator Author

The stack adaptions are now included in newest rolling. They can now be tested with rolling branch. This issue should be fixed.

@github-actions
Copy link
Contributor

github-actions bot commented Jan 3, 2023

You can use the latest Automatic Build of the the rolling branch. It might already contain a fix for your issue.
Pick the most top passing entry (it has a green circle with a tick in it), then scoll down to the Artifacts and download the file named update_*.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bot-reply Rolling Build bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants