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

trowbridgec · 2019-11-13T20:18:08Z

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 · 2019-11-13T20:18:30Z

@maclobdell @ARMmbed/team-embeddedplanet @ithinuel

ciarmcom · 2019-11-13T22:00:26Z

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

0xc0170 · 2019-11-14T10:24:30Z

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 · 2019-11-14T10:44:28Z

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

SeppoTakalo · 2019-11-14T11:53:12Z

@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 · 2019-11-14T12:03:23Z

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 · 2019-11-14T13:45:48Z

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 · 2019-11-14T13:50:35Z

@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 · 2019-11-14T15:51:59Z

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

mbed-ci · 2019-11-14T17:29:07Z

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 · 2019-11-14T21:39:00Z

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 · 2019-11-14T22:10:52Z

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

kivaisan · 2019-11-15T07:13:41Z

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 · 2019-11-15T09:32:43Z

@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 · 2019-11-15T09:42:35Z

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.

TESTS/integration/fs-threaded/main.cpp

kivaisan · 2019-11-15T09:47:21Z

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 · 2019-11-15T10:53:49Z

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 · 2019-11-15T11:31:12Z

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 · 2019-11-15T13:08:17Z

@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 · 2019-11-15T13:11:45Z

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 · 2019-11-15T14:19:31Z

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

trowbridgec · 2019-11-15T14:22:03Z

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

adbridge · 2019-11-15T14:22:28Z

CI started

mbed-ci · 2019-11-15T15:01:56Z

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 · 2019-11-15T17:23:43Z

CI restarted

mbed-ci · 2019-11-15T18:43:32Z

Test run: SUCCESS

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

ciarmcom requested review from ithinuel, maclobdell and a team November 13, 2019 22:00

ciarmcom added the needs: review label Nov 13, 2019

0xc0170 removed the request for review from a team November 14, 2019 10:25

0xc0170 added the release-version: 5.14.2 label Nov 14, 2019

0xc0170 approved these changes Nov 14, 2019

View reviewed changes

trowbridgec changed the title ~~Replace calls to printf() with new wrapper function print_to_console()~~ Replace calls to printf() with mbed-trace in netsocket tests Nov 14, 2019

maclobdell approved these changes Nov 14, 2019

View reviewed changes

adbridge added needs: CI and removed needs: review labels Nov 14, 2019

trowbridgec force-pushed the update-ep-agora-target branch from 600ea40 to 0592e95 Compare November 14, 2019 22:08

kjbracey reviewed Nov 15, 2019

View reviewed changes

TESTS/integration/fs-threaded/main.cpp Outdated Show resolved Hide resolved

40Grit mentioned this pull request Nov 15, 2019

Tracking issue for output synchronisation between mbed_trace, printf... #11202

Closed

trowbridgec force-pushed the update-ep-agora-target branch from 0592e95 to eac84ad Compare November 15, 2019 14:07

trowbridgec force-pushed the update-ep-agora-target branch from eac84ad to e59fbe5 Compare November 15, 2019 14:21

kjbracey approved these changes Nov 15, 2019

View reviewed changes

Switch to using mbed-trace for greentea test debug output

a1edbb9

trowbridgec force-pushed the update-ep-agora-target branch from e59fbe5 to a1edbb9 Compare November 15, 2019 16:18

0xc0170 removed the needs: CI label Nov 16, 2019

0xc0170 merged commit ee46d03 into ARMmbed:master Nov 16, 2019

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

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

Uh oh!

Conversation

trowbridgec commented Nov 13, 2019

Description (required)

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

Documentation (Details of any document updates required)

Pull request type (required)

Test results (required)

Reviewers (optional)

@maclobdell @ithinuel

Release Notes (required for feature/major PRs)

Summary of changes

Impact of changes

Migration actions required

Uh oh!

trowbridgec commented Nov 13, 2019

Uh oh!

ciarmcom commented Nov 13, 2019

Uh oh!

0xc0170 commented Nov 14, 2019

Uh oh!

0xc0170 commented Nov 14, 2019

Uh oh!

SeppoTakalo commented Nov 14, 2019

Uh oh!

kjbracey commented Nov 14, 2019

Uh oh!

0xc0170 commented Nov 14, 2019

Uh oh!

trowbridgec commented Nov 14, 2019

Uh oh!

maclobdell left a comment

Choose a reason for hiding this comment

Uh oh!

0xc0170 commented Nov 14, 2019

Uh oh!

mbed-ci commented Nov 14, 2019

Test run: FAILED

Uh oh!

maclobdell commented Nov 14, 2019

Uh oh!

trowbridgec commented Nov 14, 2019

Uh oh!

kivaisan commented Nov 15, 2019

Uh oh!

40Grit commented Nov 15, 2019

Uh oh!

kjbracey commented Nov 15, 2019

Uh oh!

Uh oh!

kivaisan commented Nov 15, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

adbridge commented Nov 15, 2019

Uh oh!

kjbracey commented Nov 15, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

trowbridgec commented Nov 15, 2019

Uh oh!

kjbracey commented Nov 15, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

adbridge commented Nov 15, 2019

Uh oh!

trowbridgec commented Nov 15, 2019

Uh oh!

adbridge commented Nov 15, 2019

Uh oh!

mbed-ci commented Nov 15, 2019

Test run: FAILED

Uh oh!

0xc0170 commented Nov 15, 2019

Uh oh!

mbed-ci commented Nov 15, 2019

Test run: SUCCESS

Uh oh!

Uh oh!

@maclobdell
@ithinuel

kivaisan commented Nov 15, 2019 •

edited

Loading

kjbracey commented Nov 15, 2019 •

edited

Loading

kjbracey commented Nov 15, 2019 •

edited

Loading