Backup settings are truncated

[meyergru]

Whenever I backup my settings, the resulting JSON file is truncated at some arbitrary point, mostly around 1500 bytes.

This results in a corrupted JSON that cannot be used to restore the settings afterwards. This happens on a Sonoff RF Bridge, BTW and I have used the 1.12.6 release, but 1.12.5 had the issue as well.

[xoseperez]

The max size of the file might be limited by the available memory since right it created before being sent. Can you check how much free heap you have before trying to do the backu? You can use heap command from the debug window.

[xoseperez]

I guess the best option would be to "stream" the contents as they are generated...

[mcspr]

Probably, yeah.

Heap getting low looks really strange. Open websocket - it cuts 30 bytes off config :/ Would chunked response + chunked json output help this? i.e. json buffer is kept in memory and https://arduinojson.org/doc/tricks/#chunked-output is used to grab required parts (send out 512 + 512 + 512 + 512 + 265 for 2313)

Also, using old version without pretty printer does help - efa88c9#diff-e516855e6c8bb9fe30c150bcc8f9dff4 - ~500 bytes less for 96 keys - it is + 3 spaces, \r\n (plus two for brackets)

[meyergru]

I could not look at the heap size before now, since apparently, the web UI is not reachable via a proxied connection?

The free heap is 17904 bytes when the output gets truncated. So, even with a fair amount of memory, this does not work.

[mcspr]

Amending my previous reply... I did some tests since, and have some things to note:

• AsyncResponseStream already does keep printed json string in cbuf object. Changing it to chunked response does not make much difference.
• Removing webLog() from the top of config method avoids truncation. Debug code sends websocket message and immediately begins sending large config, which somehow causes tcp stack to run out of memory (?)
  This is the most direct workaround for this.
• There is similar truncation when running keys in telnet and web. Adding nop delay by calling optimistic_yield(100) at the end of debugSend() in case it has TELNET or WEB sessions active allows all data to pass.

And some calls to DEBUG_MSG can be optimized to happen less frequently (plus, they have some interesting logic for timestamping...)

[xoseperez]

Interesting... @mcspr do you mind issuing a PR with your suggested changes?
What do you mean by "interesting logic"?

[mcspr]

@xoseperez Sure. Just need to check if weblog can still work.

// about DEBUG_MSG
It allows line continuation and requires remembering how data is presented from the code before. Accidentally, while trying to reduce debugsend calls, I did replace much of these with string formatting.

espurna/code/espurna/ota.ino

Lines 238 to 239 in f1c2aa1

	DEBUG_MSG_P(PSTR("\n[OTA] Error #%u: "), error);
	if (error == OTA_AUTH_ERROR) DEBUG_MSG_P(PSTR("Auth Failed\n"));

espurna/code/espurna/utils.ino

Lines 268 to 275 in f1c2aa1

	DEBUG_MSG_P(PSTR("[INIT] SUPPORT:"));
	#if ALEXA_SUPPORT
	DEBUG_MSG_P(PSTR(" ALEXA"));
	#endif
	#if BROKER_SUPPORT
	DEBUG_MSG_P(PSTR(" BROKER"));
	#endif

e.g. for modules listing:

-    DEBUG_MSG_P(PSTR("[INIT] SUPPORT:"));
+    DEBUG_MSG_P(PSTR("[INIT] SUPPORT:%s\n"), getEspurnaModules().c_str());

PROGMEM const char espurna_modules[] =
    #if ALEXA_SUPPORT
        " ALEXA"
    #endif
    #if BROKER_SUPPORT
        " BROKER"
    #endif
...
        "";

String getEspurnaModules() {
    return FPSTR(espurna_modules);
}

[xoseperez]

(Sorry, that commit should not be linked to this issue, my bad)

[xoseperez]

#930 has been merged to dev. I have tested it and looks good. @meyergru, can you validate this fixes the issue.

[meyergru]

I have no development environment to compile dev... if anybody can provide the binary for the Sonoff bridge, I can test it. Otherwise, it will have to wait until the weekend.

[mcspr]

@meyergru here's recent git version via travis, built like releases here - https://github.com/mcspr/espurna-travis-test/releases/tag/1.13.0c

@xoseperez Would it make sense to delay sending webLog data until the next loop? I got a feeling some of the problems are from doing network request from inside async callback. Or from other log call in some other callback.

[meyergru]

Just tested that 1.13.0c version: No change. Backup was truncated.

[mcspr]

Damn :/ Only other theory I have is EEPROM somehow breaks response if called to frequently. Which is the case for both /config and keys I would also set alexaEnabled to 0 if it ain't required, so ssdp is not used that much.

Running the same build right now - heap around ~15088, 13440... Sometimes backup is truncated, sometimes it isn't. (and it should be noted that using curl to test this must be with --digest, like browser does, so it does 2 consecutive requests and with bigger header size)

[xoseperez]

Dumping the settings line by lines works fine, the drawback is that they are not alphabetically sorted...

[mcspr]

For web another solution is to just generate file blob from the form, with pure js. No TCP connections that way.

Example demonstrating this: #968

[xoseperez]

Released with 1.13.0. Closing. @meyergru and @mcspr , feel free to open again if problem persists. Or open a new issue/PR for a different approach.

[meyergru]

I just tried version 1.13.0 (the travis build), but the backup file is still corrupted and cannot be imported.
I think this is mainly because of a missing closing bracket which violates JSON syntax rules. Maybe that was forgotten in the new output scheme?

My resulting file has 125 lines and is ~3000 bytes now, so it seems as if it is not truncated other than the missing bracket.

BTW:

1. I cannot re-open the issue myself.
2. The release binaries for 1.13.0 are not online yet...

[meyergru]

Used the wrong build, all is well with 1.13.0.