mbed-os-5.3.0-rc2: sockets do not work for NUCLEO_F746ZG in IAR

[geky]

Description

• Type: Bug
• Priority: Major

Bug

mbed-os-example-sockets

Target NUCLEO_F746ZG Toolchain: IAR

Toolchain version: IAR ANSI C/C++ Compiler V7.80.2.11947/W32 for ARM

meed-os sha: mbed-os-5.3.0-rc2

Expected behavior Socket example works

Actual behavior Compilation succeeds, but example hands after bringing up the network

[0xc0170]

cc @adustm @bcostm

[adustm]

Hello @geky I never used this example before. Do you confirm that it used to work in the past with NUCLEO_F746ZG ? Is it working with other toolchains ? Cheers Armelle

[adustm]

Hello @geky I have been able to reproduce an issue within mbed-os tests and IAR

    calling mbedhtrun: mbedhtrun -m NUCLEO_F746ZG -p COM67:9600 -f ".build/tests/NUCLEO_F746ZG/IAR/features/FEATURE_LWIP/TESTS/mbedmicro-net/udp_echo_client/udp_echo_client.bin" -d D: -C 4 -c shell -t 08160221054560033A01F928 -e "features\FEATURE_LWIP\TESTS\mbedmicro-net\host_tests"
mbedgt: mbed-host-test-runner: started
[1481217024.49][HTST][INF] host test executor ver. 1.1.3
[1481217024.49][HTST][INF] copy image onto target...
[1481217024.49][COPY][INF] Waiting up to 60 sec for '08160221054560033A01F928' mount point (current is 'D:')...
        1 file(s) copied.
[1481217031.99][HTST][INF] starting host test process...
[1481217032.83][CONN][INF] starting connection process...
[1481217032.83][CONN][INF] notify event queue about extra 60 sec timeout for serial port pooling
[1481217032.83][CONN][INF] initializing serial port listener...
[1481217032.84][SERI][INF] serial(port=COM67, baudrate=9600, timeout=0.01)
[1481217032.84][PLGN][INF] Waiting up to 60 sec for '08160221054560033A01F928' serial port (current is 'COM67')...
[1481217032.85][HTST][INF] setting timeout to: 60 sec
[1481217034.03][SERI][INF] reset device using 'default' plugin...
[1481217034.28][SERI][INF] waiting 1.00 sec after reset
[1481217035.28][SERI][INF] wait for it...
[1481217035.31][SERI][TXD] mbedmbedmbedmbedmbedmbedmbedmbedmbedmbed
[1481217035.31][CONN][INF] sending up to 2 __sync packets (specified with --sync=2)
[1481217035.31][CONN][INF] sending preamble '67053784-2907-4111-899c-57088e338f8f'
[1481217035.36][SERI][TXD] {{__sync;67053784-2907-4111-899c-57088e338f8f}}
[1481217035.41][CONN][RXD] mbedmbedmbedmbedmbedmbedmbedmbed
[1481217035.46][CONN][INF] found SYNC in stream: {{__sync;67053784-2907-4111-899c-57088e338f8f}} it is #0 sent, queued...
[1481217035.47][HTST][INF] sync KV found, uuid=67053784-2907-4111-899c-57088e338f8f, timestamp=1481217035.462000
[1481217035.48][CONN][INF] found KV pair in stream: {{__version;1.3.0}}, queued...
[1481217035.48][HTST][INF] DUT greentea-client version: 1.3.0
[1481217035.50][CONN][INF] found KV pair in stream: {{__timeout;20}}, queued...
[1481217035.51][HTST][INF] setting timeout to: 20 sec
[1481217035.54][CONN][INF] found KV pair in stream: {{__host_test_name;udp_echo_client}}, queued...
[1481217035.54][HTST][INF] host test class: '<class 'udp_echo_client.UDPEchoClientTest'>'
[1481217035.54][HTST][INF] host test setup() call...
[1481217035.54][HTST][INF] CALLBACKs updated
[1481217035.54][HTST][INF] host test detected: udp_echo_client
[1481217052.15][CONN][RXD] UDP client IP Address is MlÖ]‚ù†çD99@ãšºÆìžú‹2Â+²ÞNf×Êr™¹¶‘(jïLÙ/ÉPOç•W3gùF‘BPØì´gMþYƹŒÖßšYGâ‹ÖŸ qBÚ•û÷Žù“20
[1481217052.16][CONN][INF] found KV pair in stream: {{host_ip; }}, queued...
[1481217052.19][SERI][TXD] {{host_ip;None}}
[1481217052.21][CONN][INF] found KV pair in stream: {{host_port; }}, queued...
[1481217052.22][SERI][TXD] {{host_port;0}}
[1481217052.28][CONN][RXD] MBED: UDP Server IP address received: None:0
[1481217052.31][CONN][RXD] [00] sent...-3005 Bytes
[1481217052.33][CONN][RXD] [00] recv...-3005 Bytes
[1481217052.36][CONN][INF] found KV pair in stream: {{max_heap_usage;0}}, queued...
[1481217052.36][HTST][ERR] orphan event in main phase: {{max_heap_usage;0}}, timestamp=1481217052.358000
[1481217052.37][CONN][INF] found KV pair in stream: {{end;failure}}, queued...
[1481217052.37][HTST][INF] __notify_complete(False)
[1481217052.39][CONN][INF] found KV pair in stream: {{__exit;0}}, queued...
[1481217052.39][HTST][INF] __exit(0)
[1481217052.39][HTST][INF] __exit_event_queue received
[1481217052.39][HTST][INF] test suite run finished after 16.89 sec...
[1481217052.40][CONN][INF] received special even '__host_test_finished' value='True', finishing
[1481217052.41][HTST][INF] CONN exited with code: 0
[1481217052.42][HTST][INF] No events in queue
[1481217052.42][HTST][INF] stopped consuming events
[1481217052.42][HTST][INF] host test result() call skipped, received: False
[1481217052.42][HTST][INF] calling blocking teardown()
[1481217052.42][HTST][INF] teardown() finished
[1481217052.42][HTST][INF] {{result;failure}}
mbedgt: checking for GCOV data...
mbedgt: mbed-host-test-runner: stopped and returned 'FAIL'
mbedgt: test case summary event not found
    no test case report present, assuming test suite to be a single test case!
    test suite: features-feature_lwip-tests-mbedmicro-net-udp_echo_client
    test case: features-feature_lwip-tests-mbedmicro-net-udp_echo_client
mbedgt: test on hardware with target id: 08160221054560033A01F928
mbedgt: test suite 'features-feature_lwip-tests-mbedmicro-net-udp_echo_client' ....................... FAIL in 28.87 sec
    test case: 'features-feature_lwip-tests-mbedmicro-net-udp_echo_client' ....................... FAIL in 28.87 sec
mbedgt: test case summary: 0 passes, 1 failure
mbedgt: all tests finished!
mbedgt: shuffle seed: 0.2629446001
mbedgt: test suite report:
+-------------------+---------------+-----------------------------------------------------------+--------+--------------------+-------------+
| target            | platform_name | test suite                                                | result | elapsed_time (sec) | copy_method |
+-------------------+---------------+-----------------------------------------------------------+--------+--------------------+-------------+
| NUCLEO_F746ZG-IAR | NUCLEO_F746ZG | features-feature_lwip-tests-mbedmicro-net-udp_echo_client | FAIL   | 28.87              | shell       |
+-------------------+---------------+-----------------------------------------------------------+--------+--------------------+-------------+

The same test goes well with GCC_ARM for instance I would like to investigate the strange characters returned by the get_IP_address(); but unfortunately, I cannot export the project.

mbed export -i iar -m nucleo_f746zg
usage: project.py [-h] [-m MCU] [-i IDE] [-c] [-p PROGRAM] [-n PROGRAM] [-b]
                  [-L] [-S] [-E] [--source SOURCE_DIR] [-D MACROS]
                  [--profile PROFILE] [--update-packs]
project.py: error: NUCLEO_F746ZG not supported by iar
[mbed] ERROR: "python" returned error code 2.
[mbed] ERROR: Command "python -u C:\MCDGitW601\mbed\tools\project.py -i iar -m nucleo_f746zg --source ." in "C:\MCDGitW601\mbed"

Does anyone have a clue for that ? Cheers Armelle

[geky]

Hi Armelle, I don't know if the NUCLEO_F746ZG has worked before, though it does work with both the ARM compiler and gcc.

Unfortunately, it looks like the board does not support exporting to the IAR IDE.

[bridadan]

This target is supported by uvision though, perhaps you can use that instead to debug? Thanks for looking into this @adustm!

[geky]

@bridadan It's an iar only issue

Unless there is some clever way to debug iar builds in uvision...

[bridadan]

Ah duh, totally missed that part *facepalm*

[theotherjimmy]

hey, @geky I fixed the iar export issue in #3413 You should be able to export to IAR and debug now.

[adustm]

Hello all, I have been able to investigate more in details. The issue seems to be the snprintf function is giving garbage result with IAR in this code : https://github.com/ARMmbed/mbed-os/blob/master/features/FEATURE_LWIP/lwip-interface/lwip_stack.c#L322

    snprintf(lwip_mac_addr, 19, "%02x:%02x:%02x:%02x:%02x:%02x",
            mac[0], mac[1], mac[2], mac[3], mac[4], mac[5]);

(for instance as previously stated [1481217052.15][CONN][RXD] UDP client IP Address is MlÖ]‚ù†çD99@�ã�šºÆìžú‹2�Â+�²ÞNf×Êr™¹¶‘�(jïLÙ/ÉP�Oç•W3g�ùF‘�BPØì´gMþ�YƹŒ�����ÖßšYG�â‹ÖŸ�� qBÚ•û÷Ž�ù“20 instead of [1481217052.15][CONN][RXD] UDP client IP Address is 192.168.1.100)

I was certain it had worked before then I tried the same code on several mbed versions Now I am at the point where it works on mbed-lib_rev124 / mbed-os-5.1.2 and it does not work on mbed-lib_rev125 / mbed-os-5.1.3

This specific function did not change between both revisions, so I am suspecting an IAR build option, but I can't find it... Does anyone have an idea why this snprintf function is failing with IAR, between those 2 revisions ?

The main code I am using is extracted from udp_echo_client test :

//#if !FEATURE_LWIP // use this for latest mbed revisions
#if !FEATURE_IPV4 // use this for old mbed revisions
    #error [NOT_SUPPORTED] LWIP not supported for this target
#endif

#include "mbed.h"
#include "EthernetInterface.h"
#include "UDPSocket.h"
#include "greentea-client/test_env.h"

#ifndef MBED_CFG_UDP_CLIENT_ECHO_BUFFER_SIZE
#define MBED_CFG_UDP_CLIENT_ECHO_BUFFER_SIZE 256
#endif

int main() {
    printf("start udp_echo_client\n");
    EthernetInterface eth;
    eth.connect();
    printf("UDP client IP Address is %s\n", eth.get_ip_address());
    eth.disconnect();
    printf("finished\n");
}

Any help is welcome

Kind regards Armelle

[bridadan]

@adustm Thanks for narrowing down the issue, that helps a lot. I will try to reproduce this today.

[bridadan]

Hi @adustm, I managed to narrow down the breaking commit.

This was the first broken commit: 8238d2230b8a63b11a087492356019f2674253ba, which came from this PR: https://github.com/ARMmbed/mbed-os/pull/2473

I don't know how to suggest a fix, but hopefully that's enough to help you or anyone else tracking this issue to find a fix!

[adustm]

Ok, I have spent a few hours on this one and eventually managed to understand the issue. The ethernet buffers are located in the SRAM1 memory that has data cache enable. Extract from the mbed.map:

DMARxDscrTab            0x20012aa4    0x80  Data  Gb  stm32f7_emac.o [8]
DMATxDscrTab            0x20012b24    0x80  Data  Gb  stm32f7_emac.o [8]
Rx_Buff                 0x20012ba4  0x17d0  Data  Gb  stm32f7_emac.o [8]
Tx_Buff                 0x20014374  0x17d0  Data  Gb  stm32f7_emac.o [8]

The DMA descriptors are written by the CPU, and kept in cache. The Ethernet IP is then reading the DMA descriptor in the SRAM1 memory, that does not contains the requested information (still in cache) You can see in the Reference Manual of STM32F746 that we set an address for the DMA descriptor to the ETH registers, and that the IP is reading this address directly. http://www.st.com/resource/en/reference_manual/dm00124865.pdf page 1586 for ETH_DMATDLAR

It used to work before because those buffers' allocation was hard coded on 0x2000xxxx This memory is the DTCM ram, 0 wait state, no cache. It can remain like this, but it is not the best performance choice (because when Ethernet is accessing the datas, the CPU is blocked).

The best choice is then to use SRAM1 and disable the data cache. The SRAM1 and SRAM2 are really fast and the system performance should not suffer from this choice. I'll create a PR for that. Kind regards Armelle

[geky]

That is a really interesting bug, thanks for tracking it down and keeping us up to date!