Error output improvements #8076

kjbracey · 2018-09-11T08:57:17Z

Description

Make mbed_error_printf not serial specific
Ensure serial buffer is flushed before error output
sync output devices on exit, as well as fflush
Rename mbed_error_vfprintf to mbed_error_vprintf
~~Add format checking to mbed_error_printf et al~~
Don't overrun in long error prints - indicate truncation
~~Split up and tidy "assertation" message"~~

Fixes #7363 - possibly others I need to find.

Pull request type

[ ] Fix
[ ] Refactor
[ ] Target update
[X] Functionality change
[ ] Breaking change

kjbracey · 2018-09-11T09:00:49Z

FAO @JammuKekkonen

kjbracey · 2018-09-11T09:04:16Z

I note that this output routine was conditional on DEVICE_SERIAL. Possibly it should have (also) been conditional on DEVICE_STDIO_MESSAGES, and the new version should do that? I'm not 100% clear on DEVICE_STDIO_MESSAGES intent and implementation - presumably it's trying to stop stdio routines being pulled in, but it can't be terribly effective if asserts, fault handlers etc are all using vsnprintf.

jeromecoutant · 2018-09-11T09:09:58Z

I'm not 100% clear on DEVICE_STDIO_MESSAGES intent and implementation

Agree :-) #5658

kjbracey · 2018-09-11T15:15:50Z

Going to add a couple more format-checking directives where applicable (eg error and debug), and I still need to do the consequent build warning clean-up.

kjbracey · 2018-09-12T11:12:39Z

Actually, the extra "printf" format check stuff provokes a significantly wider cleanup, not relevant to the core issues here, so I'll take that out from this PR.

deepikabhavnani · 2018-10-05T14:52:34Z

@SenRamakri - Please review

deepikabhavnani

👍 Looks good to me

deepikabhavnani · 2018-10-05T15:09:09Z

drivers/UARTSerial.cpp

@@ -143,6 +160,10 @@ ssize_t UARTSerial::write(const void *buffer, size_t length)
        return 0;
    }

+    if (core_util_in_critical_section()) {
+        return write_unbuffered(buf_ptr, length);


Should we advertise after this change, that printf from ISR is valid?

Even after this, printf from ISR isn't valid - you'll hit a FILE mutex inside the C library. What may work is write(STDERR_FILENO), which avoids the C library, but that in turn will depend on what exactly stderr is hooked to.

And we don't absolutely stop the user redirecting stderr to a File, eg using freopen.

The potential write from ISR is a "last resort" - it has nothing else it can reasonably do. I don't think we should absolutely require that write to stderr work from interrupts, but we can encourage people to try to use stderr devices that can handle this.

kjbracey · 2018-10-08T09:41:19Z

This conflicts with #8255. I will remove the relevant commit to avoid the conflict.

cmonr · 2018-10-08T18:56:47Z

For clarity: this needs #8255 to come in first.

kjbracey · 2018-10-09T07:59:50Z

I've already removed the bit about assert, so this and #8255 no longer interfere with each other.

TeroJaasko · 2018-10-15T10:31:40Z

platform/mbed_board.c

-            }
-            serial_putc(&stdio_uart, buffer[i]);
-            stdio_out_prev = buffer[i];
+    char buffer[132];


Could this buffer size be configurable? Now we have one rare MBED_ASSERT()ion failure in CI, which only logs part of the filename:
mbed assertation failed: FALSE, file: ./mbed-os/targets/TARGET_STM/TARGET_STM32F4/TARGET_STM32F439xI/TARGET_MODULE_UBLOX_ODIN_W�°��DY��`—��Ý<
I suppose it would be better to have only the N trailing chars from the filename, but that might be a bigger change.

This does partially address that assert issue; and both a commit I removed and #8255 address the other half.

This commit will make that be mbed assertation failed: FALSE, file: ./mbed-os/targets/TARGET_STM/TARGET_STM32F4/TARGET_STM32F439xI/TARGET_MODULE_UBLOX_ODIN_W...\n

Which is an improvement - the \n means that you'll see the line in GreenTea, so you at least get the FALSE. (Moral of that story - use meaningful expressions in your asserts).

The commit I used to have here broke the assert up into 4 prints, so it was less likely to overflow and even if the filename was truncated you'd still see the line number.

#8255 does the same job by passing through to mbed_error, which also breaks up the prints.

Still, I can see there may be a desire for bigger buffer. Sadly, I can't see any way to get the "tail" of a printf, so can't break it up in to bits - you need a buffer to hold the entire formatted string.

Alternatively, how about avoiding the need for a big buffer by having mbed_error_puts instead, and using that for potentially-long things like the filename?

Was trying to implement and use mbed_error_puts, but I realise now that #8255 does impose its own very heavy truncation. It munges the full filename into its "context" structure, if MBED_CONF_ERROR_FILENAME_CAPTURE_ENABLED is on, then outputs that.

You might only get the first 16 characters.

Having a line number and non-garbage error print is definitely a step forward;). Could the filename trimming be done at mbed_assert_internal(), https://github.com/ARMmbed/mbed-os/blob/master/platform/mbed_assert.c#L25?
That mbed_error_puts() would fix the problem completely, without need for trimming at all.

Yes, mbed_assert_internal could use puts, or trim itself. But I've pulled back from any changes to that to defer to #8255. But as I said, that introduces a pile of new problems - or at least applies its existing problems to mbed_assert.

kjbracey · 2018-10-16T08:21:42Z

I don't understand the "jenkins-ci/cloud-client-test" failure indicated here. I see red here, yellow on its own summary page, but can't find anything other than green and pass on individual parts of the test.

cmonr · 2018-10-16T15:06:24Z

It's not an easy find.

[Test K64F IAR] Traceback (most recent call last):
[Test K64F IAR] File "/builds/ws/mbed-os-ci_cloud-client-test@2/mbed-clitest/mbed_clitest/bench.py", line 1217, in run
[Test K64F IAR] self.__setup_bench()
[Test K64F IAR] File "/builds/ws/mbed-os-ci_cloud-client-test@2/mbed-clitest/mbed_clitest/bench.py", line 1501, in __setup_bench
[Test K64F IAR] self.logger)
[Test K64F IAR] File "/builds/ws/mbed-os-ci_cloud-client-test@2/mbed-clitest/mbed_clitest/bench.py", line 852, in _validate_dut_configs
[Test K64F IAR] raise EnvironmentError("Binary not found")
[Test K64F IAR] EnvironmentError: Binary not found

That being said, I'm not sure why it can't find the binary.
@ARMmbed/mbed-os-test Thoughts?

Use write() on current output device instead - this works on the assumption that write() is safe to call from critical section. UARTSerial has previously been upgraded to support this, and this also improves the behaviour when buffered serial is in use - the current buffered output will be fully flushed before outputting the error message.

Mbed retarget does an `fflush` on stdout and stderr on exit - this flushes the C library buffers (if it is buffering), but doesn't flush any device buffers (eg UARTSerial's TX buffer). Add sync() calls to the output device to do this.

Name vfprintf doesn't make sense - if we have mbed_error_printf, this is vprintf.

vsprintf returns the amount it would have written if the buffer had been big enough, but we used that value directly when outputting, thus overrunning memory and dumping stack contents. Indicate truncation by inserting an ellipsis and newline. Slightly increase the buffer size, so that we don't slightly decrease the maximum printable characters because of the ellipsis insertion. Partially addresses ARMmbed#6850 by forcing a newline when truncation happens - often truncation will drop a newline and prevent a flush.

kjbracey · 2018-10-17T10:40:33Z

It seems that was the IAR compilation error you found here, but I've no idea how you did.

Seems like it should be easier to find that compilation error, if it's only that job doing an IAR build on initial PR push?

cmonr · 2018-10-17T15:21:22Z

@kjbracey-arm It was similar to that one, but not the same.

After looking at this PR, I figured out how to navigate that CI job. The tldr is that the test was expecting two binaries, so I figured out which build was missing a test, and searched for the build failure. Also logged a bug since the build job was not properly failing.

For reference, the build error that was being seen yesterday with this PR:

[K66F:IAR] [Error] mbed_board.c@89,0: [Pe118]: a void function may not return a value

cmonr · 2018-10-17T15:21:38Z

/morph build

cmonr · 2018-10-17T15:22:50Z

Er, is this still needed, or deos #8441 superceed this PR, since #8441 has these same commits?

mbed-ci · 2018-10-17T18:42:24Z

Build : SUCCESS

Build number : 3389
Build artifacts/logs : http://mbed-os.s3-website-eu-west-1.amazonaws.com/?prefix=builds/8076/

Triggering tests

/morph test
/morph export-build
/morph mbed2-build

mbed-ci · 2018-10-17T19:52:21Z

Exporter Build : SUCCESS

Build number : 3020
Build artifacts/logs : http://mbed-os.s3-website-eu-west-1.amazonaws.com/?prefix=builds/exporter/8076/

mbed-ci · 2018-10-17T23:41:58Z

Test : SUCCESS

Build number : 3190
Test logs :http://mbed-os-logs.s3-website-us-west-1.amazonaws.com/?prefix=logs/8076/3190

kjbracey · 2018-10-18T09:40:59Z

Er, is this still needed, or deos #8441 superceed this PR, since #8441 has these same commits?

#8441 is a follow-on, still needs review - this can proceed.

kjbracey force-pushed the error_stderr branch from 48e7cc0 to 9e6c0fa Compare September 11, 2018 09:21

kjbracey mentioned this pull request Sep 11, 2018

NRF52 serial: Fix UART console RX #8046

Merged

cmonr requested review from SenRamakri and a team and removed request for SenRamakri September 11, 2018 15:44

cmonr added needs: review release-version: 5.11.0-rc1 labels Sep 11, 2018

deepikabhavnani requested a review from SenRamakri September 11, 2018 16:27

kjbracey force-pushed the error_stderr branch 2 times, most recently from 7b1bd05 to 9fd97b0 Compare September 12, 2018 11:29

This was referenced Oct 4, 2018

Do not assume serial can be used for printing in faulthandler #7363

Closed

Error path tightening: use MBED_NORETURN; add+use core_util_atomic_flag #8328

Merged

Change behaviour of mbed_asert to use mbed_error instead of mbed_die #8255

Merged

deepikabhavnani approved these changes Oct 5, 2018

View reviewed changes

deepikabhavnani reviewed Oct 5, 2018

View reviewed changes

SenRamakri approved these changes Oct 5, 2018

View reviewed changes

kjbracey force-pushed the error_stderr branch from 9fd97b0 to 2da2977 Compare October 8, 2018 09:45

cmonr added the needs: preceding PR label Oct 8, 2018

kjbracey removed the needs: preceding PR label Oct 9, 2018

kjbracey force-pushed the error_stderr branch from 2da2977 to c74903f Compare October 12, 2018 12:34

TeroJaasko reviewed Oct 15, 2018

View reviewed changes

kjbracey mentioned this pull request Oct 16, 2018

More mbed_error refinements #8441

Merged

kjbracey force-pushed the error_stderr branch from c74903f to 68d8ef2 Compare October 17, 2018 09:50

kjbracey added 5 commits October 17, 2018 12:55

Add support for UARTSerial::write from critical section

1094c08

Sync output devices on exit

d05c60e

Mbed retarget does an `fflush` on stdout and stderr on exit - this flushes the C library buffers (if it is buffering), but doesn't flush any device buffers (eg UARTSerial's TX buffer). Add sync() calls to the output device to do this.

mbed_error_vfprintf -> mbed_error_vprintf

c989845

Name vfprintf doesn't make sense - if we have mbed_error_printf, this is vprintf.

kjbracey force-pushed the error_stderr branch from 68d8ef2 to 2df322c Compare October 17, 2018 09:55

cmonr added needs: CI and removed needs: review labels Oct 17, 2018

cmonr added ready for merge and removed needs: CI labels Oct 17, 2018

cmonr merged commit e698f0b into ARMmbed:master Oct 18, 2018

cmonr removed the ready for merge label Oct 18, 2018

kjbracey deleted the error_stderr branch October 25, 2018 13:46

kjbracey mentioned this pull request Mar 6, 2019

Reconcile mbed trace and greentea #9954

Closed

marcemmers mentioned this pull request Apr 8, 2019

Printing fault information fails if console is not initialized #10344

Closed

Error output improvements #8076

Error output improvements #8076

Uh oh!

Conversation

kjbracey commented Sep 11, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

Pull request type

Uh oh!

kjbracey commented Sep 11, 2018

Uh oh!

kjbracey commented Sep 11, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jeromecoutant commented Sep 11, 2018

Uh oh!

kjbracey commented Sep 11, 2018

Uh oh!

kjbracey commented Sep 12, 2018

Uh oh!

deepikabhavnani commented Oct 5, 2018

Uh oh!

deepikabhavnani left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

kjbracey commented Oct 8, 2018

Uh oh!

cmonr commented Oct 8, 2018

Uh oh!

kjbracey commented Oct 9, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

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

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

kjbracey commented Oct 16, 2018

Uh oh!

cmonr commented Oct 16, 2018

Uh oh!

kjbracey commented Oct 17, 2018

Uh oh!

cmonr commented Oct 17, 2018

Uh oh!

cmonr commented Oct 17, 2018

Uh oh!

cmonr commented Oct 17, 2018

Uh oh!

mbed-ci commented Oct 17, 2018

Triggering tests

Uh oh!

mbed-ci commented Oct 17, 2018

Uh oh!

mbed-ci commented Oct 17, 2018

Uh oh!

kjbracey commented Oct 18, 2018

Uh oh!

Uh oh!

kjbracey commented Sep 11, 2018 •

edited

Loading

kjbracey commented Sep 11, 2018 •

edited

Loading

kjbracey Oct 15, 2018 •

edited

Loading