MQTT connection issues and strange PPP state transitions (IDFGH-16633)

[txf-]

Answers checklist.

• I have read the documentation for esp-protocols components and the issue is not addressed there.
• I have updated my esp-protocols branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

General issue report

I'm currently trying to debug MQTT tls handshake connection problems. This problem arose spontaneously in the system after a few hours. After this point even restarting everything, it always hits this problem.

Is there any explanation for why after being in PPP phase 266, it then goes 267,265, and finally 262, which I assume means the PPP connection gets dropped? Could a power issue be the cause of this? Does the modem need more power when it starts sending TCP packets?

I (24925) Comm: set apn: AT+CGDCONT=1,"IP","iot.1nce.net"
I (24934) Comm: Operator Name: MEO 1nce.net, act:7
I (24938) Comm: Signal quality: rssi[31]=-52, ber=99

I (24977) Comm: set data mode
I (24980) command_lib: generic_command
I (24985) command_lib: generic_command command ATE0

I (24993) command_lib: Response: ATE0
OK

I (24996) command_lib: generic_command
I (25000) command_lib: generic_command command AT+CGDCONT=1,"IP","iot.1nce.net"

I (25036) command_lib: Response: 
OK

I (25037) command_lib: generic_command
I (25038) command_lib: generic_command command ATD*99#

I (25046) command_lib: Response: 
CONNECT 150000000

I (25048) Comm: PPP state changed event 259
I (25052) Comm: PPP state changed event 262
I (25068) Comm: PPP state changed event 263
I (25068) Comm: PPP state changed event 265
I (25102) esp-netif_lwip-ppp: Connected
I (25102) esp-netif_lwip-ppp: Name Server1: 8.8.8.8
I (25102) esp-netif_lwip-ppp: Name Server2: 8.8.4.4
I (25106) Comm: Modem Connect to PPP Server
I (25111) Comm: ~~~~~~~~~~~~~~
I (25115) Comm: IP          : 10.21.136.1
I (25120) Comm: Netmask     : 255.255.255.255
I (25125) Comm: Gateway     : 10.64.64.64
I (25129) Comm: Name Server1: 8.8.8.8
I (25134) Comm: Name Server2: 8.8.4.4
I (25138) Comm: ~~~~~~~~~~~~~~
I (25142) Comm: GOT ip event!!!
I (25146) Comm: PPP state changed event 266

I (27057) Comm: Waiting for IP address

I (27357) Comm: MQTT not connected, error count 0
I (27357) Comm: start MQTT
I (27357) Comm: Connecting to MQTT broker
I (27359) mqtt: MQTT_EVENT_BEFORE_CONNECT
I (27365) Comm: Waiting for MQTT broker

I (40068) Comm: PPP state changed event 267
I (40068) Comm: PPP state changed event 265
I (40069) Comm: PPP state changed event 262
E (40071) esp-tls-mbedtls: mbedtls_ssl_handshake returned -0x004C
I (40078) esp-tls-mbedtls: Certificate verified.
E (40083) esp-tls: Failed to open new connection
E (40089) TRANSPORT_BASE: Failed to open a new connection
E (40095) MQTT_CLIENT: Error transport connect
E (40100) mqtt: MQTT_EVENT_ERROR
I (40104) mqtt: Last errno string (Success)
W (40109) mqtt: MQTT_EVENT_DISCONNECTED
I (40613) Comm: stop MQTT

[david-cermak]

Yes, modems usually draw more current when sending data (probably happens when exchanging certificates during the handshake).
If you're seeing these events, and they're coming a few seconds after TCP connection I'd suspect the server is not actively terminating the PPP session -- you can check the lines to be sure, or enable PPP-debug logs.
Does the modem respond to AT commands immediately after the connection failed? Asking to see if the modem switched to command mode -- which would suggest power supply issues.

[txf-]

Does the modem respond to AT commands immediately after the connection failed? Asking to see if the modem switched to command mode -- which would suggest power supply issues.

As far as I can tell the modem does not switch to command node, as my state machine returned to sending dce->sync commands with no response. I had to add a return return to command mode, before it would respond to AT.

Since adding this and adding larger bulk capacitors, what happens is that I get the event NETIF_PPP_PHASE_TERMINATE after calling the return to command mode, then my state machine starts from the beginning and the connection is established and the things function as expected (always on the second cycle if it fails on the first).