Hello sample modem_ppp_is_byte_expected warning

Golioth Device Help
1

Description

I have a EG91 modem connected to an ESP32 talking to the Golioth cloud via the hello example. The message transmission to Golioth seems to be reliable as far as I can tell, however, when I bump the modem log level up to DBG with CONFIG_MODEM_MODULES_LOG_LEVEL_DBG=y I’m getting a flood of the following logs:

--- 92 messages dropped ---
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x88 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xc0 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x88 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x7d because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x3e because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x44 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x84 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x58 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x64 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x36 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x89 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xd8 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x4a because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xd9 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x33 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xdf because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x7d because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x35 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x59 because 0x7e was expected.
[00:00:37.856,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xf9 because 0x7e was expected.
[00:00:37.856,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2f because 0x7e was expected.
[00:00:37.876,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:37.877,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
[00:00:37.998,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:37.998,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
[00:00:38.018,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:38.018,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
[00:00:38.018,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:38.018,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
[00:00:38.038,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:38.039,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
[00:00:38.039,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:38.039,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
--- 187 messages dropped ---

It seems as if the PPP connection is dropping data. I’m worried about the long term stability of this.

The standard Zephyr cellular_modem sample does not produce the modem_ppp_is_byte_expected log output.

Any thoughts?

Steps to Reproduce

Flash Golioth’s hello sample targeting esp32s3_devkitc and enable CONFIG_MODEM_MODULES_LOG_LEVEL_DBG=y

Expected Behavior

PPP frames to not be dropped.

Actual Behavior

PPP frames are being dropped.

Environment

*** Booting Zephyr OS build v4.2.0-1093-g9b5aa6b2f47a ***
*** Golioth Firmware SDK v0.20.0 ***

Logs and Console Output

--- 92 messages dropped ---
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x88 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xc0 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x88 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x7d because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x3e because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x44 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x84 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x58 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x64 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x36 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x89 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xd8 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x4a because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xd9 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x33 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xdf because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x7d because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x35 because 0x7e was expected.
[00:00:37.855,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x59 because 0x7e was expected.
[00:00:37.856,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xf9 because 0x7e was expected.
[00:00:37.856,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2f because 0x7e was expected.
[00:00:37.876,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:37.877,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
[00:00:37.998,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:37.998,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
[00:00:38.018,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:38.018,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
[00:00:38.018,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:38.018,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
[00:00:38.038,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:38.039,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
[00:00:38.039,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:38.039,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 81)
--- 187 messages dropped ---
3

Hey @eric,

after a quick look, it appears those logs are coming from the RX state machine, specifically when it’s in MODEM_PPP_RECEIVE_STATE_HDR_SOF, where only 0x7E is considered valid. Any non-0x7E byte gets logged as “dropped,” so what you’re seeing is just debug noise, not actual PPP data loss.

If you want to verify this, enable CONFIG_NET_STATISTICS_PPP and monitor ppp->stats.drop (or run net stats in the shell) while traffic is flowing. That’ll show you if any real frame drops are happening.

Also worth noting, Golioth isn’t in charge of the underlying Zephyr networking stack. The hello sample uses the network connection logic from our Firmware SDK examples, which you can freely modify or extend to better suit your needs.

1 Like
4

Great! Thank you for your quick response @marko . I’ll monitor the statistics and otherwise ignore the debug noise.

1 Like