Reconcile mbed trace and greentea

[ithinuel]

Description

This PR fixes the broken output of netsocket tests when mbed_trace is enabled.
Without this fix both outputs get intermingled and hardly readable by humans (for the traces) and by machines (as greentea's tokens also get messed up).

Note:
There might be a better solution than adding greentea_serial-> before each printf. If so please let me know and I will update this PR accordingly.

Pull request type

[x] Fix
[ ] Refactor
[ ] Target update
[ ] Functionality change
[ ] Docs update
[ ] Test update
[ ] Breaking change

Reviewers

Release Notes

[ciarmcom]

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

[kjbracey]

This is a step in the wrong direction vis-a-vis my abstraction issue #6674.

Also, from my investigations on that I concluded that GreenteaSerial was based on RawSerial as it was trying to avoid mutexes, so it can be used from interrupt. Is that no longer the case?

If it's very few places needing IRQ output, maybe they could be changed...

My ideal would be for the whole thing to be reworked to use just stdin and stdout (or STDOUT_FILENO for any places trying for IRQ output). And beyond that it would ideally use platform.stdio-buffered-serial to improve reliability.

Since that issue was originally filed, a couple of improvements to FileHandle/UARTSerial have been made which mean it may be more feasible:

#9797 (can now suspend buffered input, which would be necessary for some power tests)
#8076 (buffered output now has a synchronous fallback to work from IRQs)

[ithinuel]

The idea behind this is to make the serial output usable and reliable when mixing test's payload (greentea's tokens), unity's assert messages, mbed_traces and general printf output as found in a lot of tests in mbed.

As mentioned in the PR desc this might not be the best solution and I would be glad to update this PR accordingly.

The general issue I face here is that outputs aren't synchronized.

• mbed_trace has builtin support for synchronizing its output.
  that is what is introduced here for some of the tests I used.
• Greentea has no synchronisation support and will output when ever it has to print something.
• Unity uses putc.
• printf (aka stdout ?) do not seem to lock the output or do not expose a facility to synchronize with mbed_trace and other output source.

Not being able to read traces while developing/validating a feature/driver in mbed is really painful.

Outputting from an interrupt (using printfs etc) sounds fundamentally wrong to me so the use of mutexes is perfectly fine. A mutex is (arguably) the most "OS friendly" approach.

Ideally all the sources should be able to and should do agree on "who's taking the hand on the output ?" and wait until the output is actually available.

PS:
I will make another pr for the commit 97379d9 as it is not really part of this story.

[SeppoTakalo]

Test cases serve a second purpose on being our example applications, and therefore I’m very much against of them relying some undocumented Greentea internals.

I

[ithinuel]

@SeppoTakalo Thanks for your review.
Could you please elaborate on what do you mean by "relying some undocumented Greentea internal" ?
mbed_trace api is pretty well documented and ::lock & ::unlock are part of RawSerial's api

[kjbracey]

printf (aka stdout ?) do not seem to lock the output or do not expose a facility to synchronize with mbed_trace and other output source.

Indeed - you need some sort of other wrapper for all your output. In icetea, cmd_printf serves that purpose, and it gives you that lock without relying on the internals of any particular output device - the lock is outside the C library printf.

(If this was POSIX, you could use flockfile(stdout), which locks against the built-in mutex for stdio, but we don't have this - it would need to be integrated into each C library).

Outputting from an interrupt (using printfs etc) sounds fundamentally wrong to me so the use of mutexes is perfectly fine.

I agree, but it appears that Greentea is very specifically using unlocked RawSerial to support that, from the history. I don't know if it's true that the interrupt output has been eliminated, but if so, then I would very strongly want to press forward with #6674 and eliminate GreenteaSerial, not start building it up.

Or, alternatively, you could keep it as your "locking wrapper", but it should just be based on calling stdout, not an underlying RawSerial.

[SeppoTakalo]

@ithinuel By undocumented I meant greentea_serial

It is an internal object of Greentea framework, and therefore should not be touched by application.

Test cases should only rely on documented application APIs and test framework APIs.

[ithinuel]

alternatively, would that be ok to have greentea, unity & the tests to use mbed_trace to generate the output ?

[cmonr]

@ithinuel How can this be progressed? Are you still waiting for feedback, per your last comment?

[ithinuel]

@cmonr Indeed, more feedback would be greatly appreciated.
This lack of synchronisation not only makes it painful to debug when using any type of output (printfs or mbed_trace) but makes any tests using log as part of their normal process unstable.
This must be fixed.

[NirSonnenschein]

@ithinuel : note this now also requires a re-base.

[0xc0170]

This needs further discussion. Agree with above points, we should continue in #6674 and this can be closed now.

[ithinuel]

@NirSonnenschein @0xc0170 I would update/rebase once a consensus is found.

#6674 is not much about synchronisation of the various output sources though.
The inconsistency of output method used in libs, tests and test framework.
Namely : mbed_trace, printf, greentea_serial and putc (in unity).

A thing that would be a good start is to define if it's not already defined and actually apply the decision for :

• A standard way to output things in mbed.
  Should we alway use mbed_trace or printf ? How should we make sure that our output does not get intermingled with an other driver's/thread's output ?
• A standard way to select the interface used by the standard outputs.
  Could be a file, a serial interface (UART, CDC endpoint), a network socket...

[adbridge]

@NirSonnenschein @0xc0170 I would update/rebase once a consensus is found.

#6674 is not much about synchronisation of the various output sources though.
The inconsistency of output method used in libs, tests and test framework.
Namely : mbed_trace, printf, greentea_serial and putc (in unity).

A thing that would be a good start is to define if it's not already defined and actually apply the decision for :

* A standard way to output things in mbed.
  Should we alway use `mbed_trace` or `printf` ? How should we make sure that our output does not get intermingled with an other driver's/thread's output ?

* A standard way to select the interface used by the standard outputs.
  Could be a file, a serial interface (UART, CDC endpoint), a network socket...

@kjbracey-arm Do you have an opinion on this ?

[0xc0170]

This needs further discussion. Agree with above points, we should continue in #6674 and this can be closed now.

Let's move to the issue and close this, it's not going anywhere at the moment. It can be reopened with further updates/comments.

[ithinuel]

@0xc0170
as mentioned in #9954 (comment)

#6674 is not much about synchronisation of the various output sources though.
The inconsistency of output method used in libs, tests and test framework.
Namely : mbed_trace, printf, greentea_serial and putc (in unity).

[0Grit]

@ithinuel I've always been in the embedded realm but my short stint with android forever scarred my view of embedded development.

Would a logcat like interface and Log type class potentially provide a path to bringing this all together?

I'm not the one to architect it but,
greentea log, unit test log..., debug log, app log, lib log... command-line log

[ithinuel]

Would a logcat like interface and Log type class potentially provide a path to bringing this all together?

From what I understood this was more or less the intent of mbed_trace.
The thing is that some (potentially a lot of) part of mbed-os and its libraries are using output methods that are not aware of each other (printf, putc/puts, mbed_trace and raw Serial).

The resulting design expected to solve this issue may imply a lot of changes in a lot of libraries.
A solution that I think would seem valid would be that :

• printf, puts, puts & greentea output to mbed_trace (maybe using a short cut to avoid the line prefix)
• mbed_trace manages where the output is expected to go a serial port, a socket, a file or any other Writable object.

This would allow to have a coherent/synchronised output while minimising the risk of breaking existing code.
But this has a cost, mbed_trace might be too heavy for the simplest use-cases and the flexibility of selecting the output(s?) must be implemented & used with care to avoid any recursive loging (like a file handler trying to log that it's trying to write some log).

@0xc0170 @kjbracey-arm I'm aware of GH limitation's on the number of comments on a PR. Should we open a tracking issue for resolving this topic and/or use some other procedure ?

[kjbracey]

From what I understood this was more or less the intent of mbed_trace.

Indeed. mbed_trace doesn't necessarily go to the serial port. Could go to a memory buffer or a network interface. It's an abstraction for a "log" channel, that also avoids any assumption that it be a file handle - totally platform independent.

The thing is that some (potentially a lot of) part of mbed-os and its libraries are using output methods that are not aware of each other (printf, putc/puts, mbed_trace and raw Serial).

They don't need to be aware of each other, necessarily. Except that if you are using one physical output for two logical channels, there is an issue. If the serial is receiving both greentea output and logging, then something is needed to stop them becoming totally garbled.

Icetea deals with this by ensuring it initialises mbed_trace with a mutex, and uses the same mutex in its cmd_printf calls, with both cmd_output and trace_output going to the same serial port. Even during interactive typing, it copes correctly as log output occurs in the background while you're entering a command, redrawing the current input line as necessary.

Programs should in general work fine with tracing disabled, as should tests, but occasionally some tests end up wanting to check for internal state there's no API to access, in which case they "cheat" by getting the tests to look for specific trace output. I'd say that is a cheat, but it's not frowned on that hard.

The CLI interface must work interactively fine without trace enabled - so you have to make sure that a command like "route print" sends its output to stdout, not to mbed_trace!

printf, puts, puts & greentea output to mbed_trace (maybe using a short cut to avoid the line prefix)

mbed_trace is definitely a higher-level than printf. It's a portable application-level helper that may or may not send output to stdout. If other people are using stdout at the same time, then you can marshall it with a shared mutex - cmd_printf helps do that. But we can't really reimplement the C library stdout.

I'm aware of GH limitation's on the number of comments on a PR.

I'm not. Are we about to hit it?

Should we open a tracking issue for resolving this topic and/or use some other procedure ?

Sure.

[ithinuel]

@kjbracey-arm I faced it on #6782 (comment)

We can continue this discussion in #11202.