UDP debug skips some DEBUG_MSG_P

[xoseperez]

Originally reported by: P.B. (Bitbucket: PieBru, GitHub: PieBru)

---

Hi, simultaneously comparing console, telnet and UDP debug outputs, the UDP output skips some rows, always the same rows here.
UDP networking is inherently unreliable, but IMO this problem is on the ESP side only.
UDP debug output is very handy, but as I've experienced below it can be misleading. If others can reproduce this issue, I suggest to deprecate it until solved.

The "help" command show the same output on serial and telnet consoles:

#!arduino
Available commands:
> COMMANDS
> CRASH
> DEL
> DICTIONARIES
> EEPROM.DUMP
> ERASE.CONFIG
> FACTORY.RESET
> GET
> GPIO
> HEAP
> HELP
> INFO
> KEYS
> MQTT.RESET
> PUBLISH
> RELAY
> RESET
> SELECT
> SET
> SUBSCRIBE
> UNSUBSCRIBE
> UPTIME
> WIFI.RESET
> WIFI.SCAN
+OK

However, the UDP debug console every time shows only:

#!arduino
Available commands:
> COMMANDS
> CRASH
> DEL
> DICTIONARIES
> EEPROM.DUMP
> ERASE.CONFIG

_udp_debug beginPacket(), write(), endPacket() are executed for all output rows, but not all UDP frames leave the ESP.

By looking at the sources I'm not able to see any significant cause, so I think it can be a sort of "overrun" on the udp send in the ESP.

Piero

[xoseperez]

The UDP library is synchronous so all packets are sent. Maybe the issue is on the receiving part? You can try adding a "nice_delay(10)" in the debug.ino module after the UDP endPacket commands.

[PieBru]

TL;DR IMO it' isn't a network issue, it seems an underlying UDP stack problem. In my test env it's soved by adding delay(1) immediately after the _udp_debug.endPacket()

It may be confirmed by adding the following snippet inside loop() and experimenting with DEBUG_UDP_LOSS_RELAX:
0 --> loss of messages, mostly when flooding (buffering) more than 80 characters without any delay();
-1 --> some messages lost;
1 or more --> all messages reach the receiver, at least when no other heavy background tasks hog the CPU.

    #define DEBUG_UDP_LOSS                  1       // Enable debugging the loss of UDP messages when flooding
    #if DEBUG_UDP_LOSS
        #define DEBUG_UDP_LOSS_DELAY        1000    // ms
        #define DEBUG_UDP_LOSS_COUNT10      25      // Group send these strings of 10 characters
        #define DEBUG_UDP_LOSS_RELAX        0       // ms, 0 = disable, -1 = yield()
        static unsigned long last_udp1 = 0;
        static unsigned count_udp1 = 0;
        char msg_udp1[12];
        memcpy(msg_udp1, "-X12345678", 11);
        if (millis() - last_udp1 > DEBUG_UDP_LOSS_DELAY) {
            last_udp1 = millis();
            DEBUG_MSG_P(PSTR("\n[UDP]%04u"), count_udp1++);   // 10 characters
            for (unsigned i = 0; i < DEBUG_UDP_LOSS_COUNT10-1; i++) {
                *(msg_udp1+1) = 'A' + i;    // Mark each group of 10 characters, it's udeful to pinpoint what's missing
                DEBUG_MSG_P(PSTR("%s"), msg_udp1);   // 10 characters
                #if DEBUG_UDP_LOSS_RELAX
                    if (DEBUG_UDP_LOSS_RELAX > 0) 
                        delay(DEBUG_UDP_LOSS_RELAX);
                    else
                        yield();
                #endif
            }
            DEBUG_MSG_P(PSTR("\n"));
        }
    #endif  //DEBUG_UDP_LOSS

I tryed with a stock Wemos D1 mini and ESPURNA_CORE

[env:espurna-core-4MB]
platform = ${common.platform}
framework = arduino
board = d1_mini
board_flash_mode = dout
lib_deps = ${common.lib_deps}
lib_ignore = ${common.lib_ignore}
build_flags = ${common.build_flags} -DESPURNA_CORE -DMANUFACTURER=\"ESP\" -DDEVICE=\"CORE\"
monitor_baud = 115200
extra_scripts = ${common.extra_scripts}

Piero

[xoseperez]

Thanks for testing this @PieBru. I have added the delay to the code in the dev branch.

[xoseperez]

This is staged for release.