Replace calls to printf() with mbed-trace in netsocket tests

[trowbridgec]

Description (required)

Summary of change (What the change is for and why)

While troubleshooting why our cellular-enabled target (EP_AGORA) was failing some netsocket tests (DNS, TCP, UDP), we determined that the caused seemed to be related to serial output synchronization issues similar to what @ithinuel described in #9954 and #11202. Whenever the Greentea test would hit a printf() the test would hang and subsequent test cases would timeout. By replacing the calls to printf() with a new wrapper function called print_to_console() (which internally calls printf() if MBED_CONF_APP_DISABLE_LOGGING is not defined) in this PR, all of the tests passed without issue on our target.

For reference here is an example of an mbed_app.config file used with our target to pass the tests:

{
    "config": {
        "disable-logging": {
            "help": "Disable printf in print_to_console()",
            "value": null
        }
    },
    "target_overrides": {
        "EP_AGORA": {
            "nsapi.default-cellular-apn": "\"APN\"",
            "target.network-default-interface-type": "CELLULAR",
            "lwip.ipv4-enabled": true,
            "lwip.ipv6-enabled": true,
            "lwip.ethernet-enabled": false,
            "lwip.ppp-enabled": true,
            "lwip.tcp-enabled": true,
            "platform.stdio-convert-newlines": true,
            "platform.stdio-baud-rate": 9600,
            "platform.default-serial-baud-rate": 9600,
            "platform.stdio-buffered-serial": true,
            "lwip.mem-size": 22000,
            "nsapi.dns-response-wait-time": 60000,
            "disable-logging": true
        }
    }
}

Documentation (Details of any document updates required)

---

Pull request type (required)

[x] Patch update (Bug fix / Target update / Docs update / Test update / Refactor)
[] Feature update (New feature / Functionality change / New API)
[] Major update (Breaking change E.g. Return code change / API behaviour change)

---

Test results (required)

[] No Tests required for this change (E.g docs only update)
[x] Covered by existing mbed-os tests (Greentea or Unittest)
[] Tests / results supplied as part of this PR

---

Reviewers (optional)

@maclobdell
@ithinuel

Release Notes (required for feature/major PRs)

Summary of changes

Impact of changes

Migration actions required

[trowbridgec]

@maclobdell @ARMmbed/team-embeddedplanet @ithinuel

[ciarmcom]

@trowbridgec, thank you for your changes.
@ithinuel @maclobdell @ARMmbed/mbed-os-test @ARMmbed/mbed-os-ipcore @ARMmbed/mbed-os-maintainers please review.

[0xc0170]

Reading emac tests , we have there trace levels:

Test cases have different trace levels based on how much tracing can be done without affecting the performance of the test case. Configure tracing using SET\_TRACE\_LEVEL macro.

or using mbed_trace, rather than this custom wrapper?

[0xc0170]

@ARMmbed/mbed-os-ipcore Please review, this PR should be part of 5.14.2

[SeppoTakalo]

@ARMmbed/mbed-os-maintainers What is the best practice regarding console outputs and printf() when running Greentea test?

Are we supposed to print out anything at all?

[kjbracey-arm]

Printing should be okay as long as you only do it when the PC is waiting for a result. Otherwise it's a risk of breaking the protocol.

I think I'd advocate using mbed_trace, and having it off by default - people can turn it on to investigate failures. But others spend more time working with tests than me.

[0xc0170]

This is one of the grey areas. Most of the time test does not print anything by default, should not.

I think I'd advocate using mbed_trace, and having it off by default - people can turn it on to investigate failures. But others spend more time working with tests than me.

+1. @trowbridgec can we update this to use trace as proposed?

[trowbridgec]

@0xc0170 That sounds good to me. I've already tested that using trace also resolves this issue.

I'll commit the changes shortly for the tests we've been having issues with, however it occurs to me now that there may be other tests using printf() which should be converted to using trace.

[maclobdell]

LGTM

[0xc0170]

CI started. It might fail as there is master known issue

[mbed-ci]

Test run: FAILED

Summary: 1 of 4 test jobs failed
Build number : 1
Build artifacts

Failed test jobs:

• jenkins-ci/mbed-os-ci_build-ARM

[maclobdell]

As this is critical, I hope this can be merged and released in 5.14.2 as is. @trowbridgec - in the future, in cases where you update your changes based on feedback, it is much preferred that you squash your commits down to one and force push back to your branch. This makes the git history cleaner. Since this is at a critical stage, I don't think that this is necessary right now, but it is good practice for later.

[trowbridgec]

@maclobdell I added similar fixes to the integration tests and squashed my commits.

[kivaisan]

I think this will make tracing those even worse and potentially break test results completely. Enabling mbed-traces will most probably trace much more info than just these test case prints and as by default traces are not synced between threads. This causes greentea's own prints to getting corrupted resulting in failures to be reported even though test itself passed ok.
This would be ok if greentea would also use mbed-trace and trace locks are set.

[40Grit]

@kivaisan Are saying that this change is not worth the effects that will be caused when trying to debug a test and trace is enabled?

[kjbracey-arm]

This isn't enabling the trace by default (I believe), so the output is prevented, so should be okay for CI.

For human testing, turning on the trace will also turn on any internal trace, but that should be addressable by setting the level appropriately. However, all the trace here is at "debug" level which would be problematic. Turning on that will by default give you all other internal traces. Most of it should be at least "info" level.

But you could still filter by the "GRNT" trace group.

[kivaisan]

Would it be feasible to change greentea itself to use mbed-trace when mbed-trace is enabled? Then it would enable use of mbed_trace_mutex_wait_function_set / mbed_trace_mutex_release_function_set to prevent output corruption?

[adbridge]

Would it be feasible to change greentea itself to use mbed-trace when mbed-trace is enabled? Then it would enable use of mbed_trace_mutex_wait_function_set / mbed_trace_mutex_release_function_set to prevent output corruption?

In terms of this as a general idea I will leave others more knowledgeable in this area to comment. However, irrespective of that it is certainly not feasible within the current timescales. Technically code freeze for 5.14.2 was yesterday so if this PR is to come in , it needs to do so at the very latest by Monday....

[kjbracey-arm]

Would it be feasible to change greentea itself to use mbed-trace when mbed-trace is enabled?

It should be quite feasible for it to claim a mutex that is registered with mbed_trace_mutex_wait_function_set around its own comms output. Probably only a couple of adjustment points needed.

A small number of tests do output from interrupt though, which is why it's still using RawSerial generally (#6674), but most tests could use a mutex.

If this PR is leaving trace off, so the reduction in output fixes a CI, then it could go to 5.14.2 as-is, and a follow-up could add that mutex to make turning trace on work better.

[trowbridgec]

@kivaisan This PR is not turning on mbed-trace by default for greentea tests; it is merely converting calls to printf() within greentea tests to use mbed-trace functions instead. By default, mbed-trace is disabled (https://github.com/ARMmbed/mbed-os/blob/master/features/frameworks/mbed-trace/mbed_lib.json#L6):

{
    "name": "mbed-trace",
    "config": {
        "enable": {
            "help": "Used to globally enable traces.",
            "value": null
        },
        "max-level": {
            "help": "This flag is used to optimize the code size. For example, setting trace optimization level to TRACE_LEVEL_INFO will define all tr_debug() macros empty, which reduces the binary size. The possible optimization levels are TRACE_LEVEL_DEBUG, TRACE_LEVEL_INFO, TRACE_LEVEL_WARN, TRACE_LEVEL_ERROR and TRACE_LEVEL_CMD. To set the output tracing level, please use mbed_trace_config_set(TRACE_ACTIVE_LEVEL_INFO). The possible tracing levels for mbed_trace_config_set() are TRACE_ACTIVE_LEVEL_ALL, TRACE_ACTIVE_LEVEL_DEBUG (same as ALL), TRACE_ACTIVE_LEVEL_INFO, TRACE_ACTIVE_LEVEL_WARN, TRACE_ACTIVE_LEVEL_ERROR, TRACE_ACTIVE_LEVEL_CMD and TRACE_LEVEL_NONE.",
            "value": null,
            "macro_name": "MBED_TRACE_MAX_LEVEL"

        },
        "fea-ipv6": {
            "help": "Used to globally disable ipv6 tracing features.",
            "value": null
        },
        "allocator": {
            "value": "malloc",
            "macro_name": "MEM_ALLOC"
        },
        "deallocator": {
            "value": "free",
            "macro_name": "MEM_FREE"
        }

    }
}

For human testing, turning on the trace will also turn on any internal trace, but that should be addressable by setting the level appropriately. However, all the trace here is at "debug" level which would be problematic. Turning on that will by default give you all other internal traces. Most of it should be at least "info" level.

But you could still filter by the "GRNT" trace group.

@kjbracey-arm That's a good point...I can switch to using tr_info()/tr_error() when appropriate.

[kjbracey-arm]

That's a good point...I can switch to using tr_info()/tr_error() when appropriate.

As a general rule, debug level should not normally (need to) be shown except when you really are debugging - I believe IceTea defaults to showing info and above.

Anything vaguely interesting for a test run should be at least "info". Ideally we would have had the extra "notice" level between "info" and "warning" to be even more selective, but we don't.

(In the Linux kernel you can't even turn on "debug" globally IIRC - you'd turn it on per module).

[adbridge]

@kjbracey-arm could you please re-review update? I will put into CI in the meantime

[trowbridgec]

Sorry, I had to fix an astyle issue...please re-review.

[adbridge]

CI started

[mbed-ci]

Test run: FAILED

Summary: 1 of 4 test jobs failed
Build number : 2
Build artifacts

Failed test jobs:

• jenkins-ci/mbed-os-ci_build-GCC_ARM

[0xc0170]

CI restarted

[mbed-ci]

Test run: SUCCESS

Summary: 5 of 5 test jobs passed
Build number : 3
Build artifacts