[ST - NUCLEO_F429 + wifi] : not able to connect to device connector when trace is on

[anttiylitokola]

There is now some timing issue most probably in the driver side. With following patch client gets stuck even the traces are disabled. With 5ms delay problem occurs every time, changing to 2ms client works fine.
[delay.zip]
Can someone in the driver side check this a bit more?

Cloned from ARMmbed/mbed-os-example-client#223.

Check the last comment from the above issue.

[yogpan01]

@geky Can you please have a look into this ? This is a serious issue as all of our WiFi driver use this as reference design for porting and bug on this driver will result in having all of other ported drivers to carry the same issue.
@MarceloSalazar FYI. I think you have observed lot of these issues with different WiFi drivers and combination of new boards and ESP drivers, please prirotize this issue.

[geky]

Did a bit of investigation, I think we've tracked down the issue.

Short story:
Update to the most recent version of the esp8266 driver, this has been fixed since #21. This will require a firmware update.

Long story:
We found this odd DNS issue a while back when our network here in Austin changed ARMmbed/mbed-os#3926. But it didn't occur consistently, making it difficult to track down. As a part of the update to the 2.0 firmware, we adopted AT+CIPDOMAIN as a workaround to move the DNS queries to the device side.

Since then, one of our new members took over the issue earlier this week and we were able to narrow down the issue to the fact that we were sending a larger packet then necessary for the DNS query. Since the DNS header contains the number of entries in the packet, we thought this was innocuous, but apparently some DNS servers use the packet size instead, causing spurious format errors based on the contents on the uninitialized memory.

@kjbracey-arm actually put up a fix for this as a part of a separate issue ARMmbed/mbed-os#4274

So why does this issue crop up after an arbitrary delay? My best guess is that the memory is used by some other process in the meanwhile, changing the uninitialized memory from innocuous zeros to more problematic data.

@anttiylitokola can you check if updating the firmware fixes these issues?

If so I'll create an esp8266 release to indicate that we're currently at a stable point.

[anttiylitokola]

@geky, No luck with the latest firmware either. I think the firmware update went through fine since I got the green finish button in ESP8266 download tool.
Firmware is taken from here:
https://developer.mbed.org/media/uploads/sarahmarshy/esp8266_v2.0_firmware.zip

Tried also with mbed-os patch (ARMmbed/mbed-os#4274) but no difference there. Sometimes the DNS query goes through but then the next send event fails with socket error.

[geky]

@anttiylitokola, thanks for checking, the mbed OS patch should have fixed the issue on the old firmware, so the issue must be elsewhere. Will continue looking.

Sidenote: I can't reproduce the issue with your delay patch, but can reproduce ARMmbed/mbed-os-example-client#223 with trace enabled (on NUCLEO_F429ZI).

[geky]

Hm, this line seems to be the problem:
https://github.com/ARMmbed/mbed-client-classic/blob/6b5141649ffb109e5f0a201b0866b6aff795e6d5/source/m2mconnectionhandlerpimpl.cpp#L86

The trace log halts after that line, and no more logging comes from trace or the esp8266 (the esp8266 continues the dns resolution on the K64F):

[DBG ][mClt]: init_socket - port 0
[DBG ][mClt]: init_socket - OUT
[DBG ][mClt]: resolve_server_address - Using TCP
AT> AT+CIPSTART=0,
[DBG ][mClt]: send_receive_event : _socket_state: ESocketStateConnectBeingCalled, ignoring event

Comment out that line and the client example proceeds to work just fine:

[DBG ][mClt]: init_socket - OUT
[DBG ][mClt]: resolve_server_address - Using TCP
AT> AT+CIPSTART=0,"TCP","169.45.82.18",5684
AT<
AT< AT+CIPSTART=0,"TCP","169.45.82.18",5684
AT< 0,CONNECT
AT<
AT= OK
[INFO][mClt]: pal_connect(): success
[DBG ][mClt]: M2MConnectionSecurityPimpl::init
[DBG ][mClt]: M2MConnectionSecurityPimpl::init - ret 0

Dropping into the debugger quickly reveals some red flags. Here's the stack trace:

#0     frame=0x2002fe28 pc=0x0000ad38 in M2MConnectionHandlerPimpl::send_receive_event (this=0x2000bfc8) at ./mbed-client/mbed-client-classic/source/m2mconnectionhandlerpimpl.cpp:87
#1-4   frame=0x2002fe30 pc=0x0000ada0 in socket_event_handler () at ./mbed-client/mbed-client-classic/source/m2mconnectionhandlerpimpl.cpp:105
#5-9   frame=0x2002fe78 pc=0x00042334 in TCPSocket::event (this=0x2000e680) at ./mbed-os/features/netsocket/TCPSocket.cpp:202
#10-14 frame=0x2002fed0 pc=0x00007d90 in ESP8266Interface::event (this=0x20000b9c <wifi>) at ./easy-connect/esp8266-driver/ESP8266Interface.cpp:279
#15-19 frame=0x2002ff20 pc=0x0000667e in BufferedSerial::rxIrq (this=0x20000ba4 <wifi+8>) at ./easy-connect/esp8266-driver/ESP8266/ATParser/BufferedSerial/BufferedSerial.cpp:123
#20    frame=0x2002ff78 pc=0x0001d058 in mbed::SerialBase::_irq_handler (id=536873892, irq_type=RxIrq) at ./mbed-os/drivers/SerialBase.cpp:88
#21    frame=0x2002ff98 pc=0x00048ce0 in uart_irq (transmit_empty=0, receive_full=32, index=3) at ./mbed-os/targets/TARGET_Freescale/TARGET_MCUXpresso_MCUS/TARGET_MCU_K64F/serial_api.c:147
#22    frame=0x2002ffa8 pc=0x00048d98 in uart3_irq () at ./mbed-os/targets/TARGET_Freescale/TARGET_MCUXpresso_MCUS/TARGET_MCU_K64F/serial_api.c:172
#23    <signal handler called>

Well that looks like interrupt context.

Here's how socket_event_handler is registered:

• M2MConnectionHandlerPimpl calls pal_asynchronousSocket - m2mconnectionhandlerpimpl.cpp:711
• pal_asynchronousSocket calls pal_plat_asynchronousSocket - pal_network.c:372
• pal_plat_asynchronousSocket calls Socket::attach - pal_plat_network.cpp:729

Now I can't vouch for the pal, but the socket attach function (here, recently renamed to sigio, this is where the esp8266 becomes involved) does warn about interrupt context:

The callback may be called in an interrupt context and should not
perform expensive operations such as recv/send calls.

So a trace call is happening in interrupt context? That doesn't sound right.

@jupe (I'm not really sure who's responsible for trace at the moment, so sorry to bother you), trace can't really support interrupt contexts right? Looking around it seems to end up calling the stdlib's puts function (here) and snprintf function (here), both of which are probably too heavy for interrupt contexts.

Oh huh, looks like there was a similar issue with tr_debug in mbed-client's irq context:
ARMmbed/mbed-client-classic#31

What a small world.

So I'm guessing the solution is to just move those debug statements out of debugging. The M2MConnectionSecurityPimpl class already uses the nanostack event loop for this purpose, so either these debug statements can be moved there, or just dropped if they're not needed.

It looks like the source of this issue came from here ARMmbed/mbed-client-classic#65. It seems like a pretty innocent mistake.

@anttiylitokola, but this leaves me a bit confused, because the delay patch doesn't seem related at all. With a clean checkout and your patch applied, I can't reproduce your issue with the NUCLEO_F429ZI+GCC_ARM or K64F+GCC_ARM on any of the build profiles. Am I missing something? Do you still run into the issue with ARMmbed/mbed-os#4274 applied and the tr_debug lines commented out?

[jupe]

yeah its not safe to call traces from interrupt context because it uses puts which takes awhile. Hmm could we detect somehow when call traces from irq and add some irq prefix for those prints to avoid "mysterious" problems in future?

[adustm]

Hi @geky : my status is in ARMmbed/mbed-os-example-client#223

[anttiylitokola]

@geky, I'm still hitting the same problem. Just made a fresh clone of mbed-cloud-client-example-source-internal(TAG: RR1.2.0-EA) repo and the problem still occurs on my end. Firmware is updated, tr_debug removed from the interrupt context and no luck. Sometimes the bootstrap flow goes through but then it fails to mDS registration...

What makes this weird is when I'm running mbed-client-testapp binary on the same device using exact same release and the server environment it works :)

[geky]

@jupe, ooh, that's a good idea, we were thinking about just asserting if in interrupt context, but didn't want to prevent actually debugging traces in irq.

@anttiylitokola, that seems to be a different repository that I don't have access to, does https://github.com/ARMmbed/mbed-cloud-client-example also show the issue?

[JanneKiiskila]

@geky - you can use the repo you mentioned and use that same tag, you'll get the same content.