ThrowTheSwitch
Poor logging for crashing tests
Example function to test in lib.c:
#include <assert.h>
void asserting(void)
{
assert(0);
}
Example test code in test_lib.c:
#include "lib.h"
void test_empty(void)
{
}
void test_asserting(void)
{
asserting();
}
When we run the test we get output like this:
🚧 Loaded project configuration from working directory.
> Using: /test/project.yml
> Working directory: /test
Ceedling set up completed in 69 milliseconds
👟 Preparing Build Paths...
👟 Collecting Test Context
--------------------------
Parsing test_lib.c for build directive macros, #includes, and test case names...
👟 Ingesting Test Configurations
--------------------------------
Collecting search paths, flags, and defines test_lib.c...
👟 Determining Files to be Generated...
👟 Mocking
----------
👟 Test Runners
---------------
Generating runner for test_lib.c...
👟 Determining Artifacts to Be Built...
👟 Building Objects
-------------------
Compiling test_lib.c...
Compiling test_lib::lib.c...
Compiling test_lib::test_lib_runner.c...
Compiling test_lib::unity.c...
👟 Building Test Executables
----------------------------
Linking test_lib.out...
👟 Executing
------------
Running test_lib.out...
☠️ ERROR: Test executable `test_lib.out` seems to have crashed -- likely terminating early due to a bad code reference.
> Produced some output but contains no final test result counts.
> Causes can include: bad memory access, stack overflow, heap error, or bad branch in source or test code.
> Consider configuring :project ↳ :use_backtrace to use the :gdb option to find the cause (see documentation).
-------------------
FAILED TEST SUMMARY
-------------------
[test/test_lib.c]
Test: test_asserting
At line (8): "Test case crashed"
-----------------------
❌ OVERALL TEST SUMMARY
-----------------------
TESTED: 2
PASSED: 1
FAILED: 1
IGNORED: 0
---------------------
BUILD FAILURE SUMMARY
---------------------
Unit test failures.
Ceedling operations completed in 326 milliseconds
Output of test_lib.out when started manually:
test_lib.c:3:test_empty:PASS
test_lib.out: src/lib.c:5: asserting: Assertion `0' failed.
Aborted (core dumped)
I would expect test_lib.out: src/lib.c:5: asserting: Assertion `0' failed. to be part of ceedling output. I have checked all report_* plugins but none of them provides the information.
Hi. You're right. It should definitely be giving a more detailed view of the output. If you up the verbosity of Ceedling, it will report the full response... but even without that the raw output should have contained this information.
Try ceedling -v=5 test:all for example, to give maximum verbosity.
Increased verbosity will show it, that is true but it also shows a lot of unnecessary output that may be confusing, especially when you use it as CI default in bigger project/company.
I agree, @KaSroka. This is a bug and the more verbose output should be restored for crashing tests.
My intent with listing the verbosity option is so that people who also agree with this issue can use it as a workaround for now.
I would like to add that when using the :use_backtrace: :gdb option, I got this output:
[tests/Utilities/test_Utilities.c]
Test: test_Utilities_DisableSkipsRefresh
At line (20): "Test case crashed (no usable `gdb` report)"
I induced an address sanitization issue in my code to test this feature, and the output is unhelpful, but the verbose output has the leak I want to see at verbosity level 4:
> Shell executed command:
`gdb -q --batch --eval-command run --command "build/test/backtrace.gdb" --args build/gcov/out/test_Utilities/test_Utilities.out -n test_Utilities_NoDisableRefreshes`
> Produced output:
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[Inferior 1 (process 525535) exited with code 01]
=================================================================
==525535==ERROR: AddressSanitizer: global-buffer-overflow on address 0x5555555faf40 at pc 0x555555563903 bp 0x7fffffffc690 sp 0x7fffffffc680
WRITE of size 4 at 0x5555555faf40 thread T0
#0 0x555555563902 in test_Utilities_NoDisableRefreshes tests/Utilities/test_Utilities.c:30
#1 0x5555555d1936 in run_test build/test/runners/test_Utilities_runner.c:84
#2 0x5555555d1a7b in main build/test/runners/test_Utilities_runner.c:122
#3 0x7ffff73cad8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58
#4 0x7ffff73cae3f in __libc_start_main_impl ../csu/libc-start.c:392
#5 0x555555563774 in _start (/home/test/build/gcov/out/test_Utilities/test_Utilities.out+0xf774)
0x5555555faf41 is located 0 bytes to the right of global variable 'mWdtDisableKick' defined in '../../../Utilities/Utilities.c:33:13' (0x5555555faf40) of size 1
'mWdtDisableKick' is ascii string ''
SUMMARY: AddressSanitizer: global-buffer-overflow tests/Utilities/test_Utilities.c:30 in test_Utilities_NoDisableRefreshes
Shadow bytes around the buggy address:
0x0aab2aab7590: f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9
0x0aab2aab75a0: f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9
0x0aab2aab75b0: f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9
0x0aab2aab75c0: f9 f9 f9 f9 00 00 00 00 00 00 00 00 00 00 00 00
0x0aab2aab75d0: 00 00 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9
=>0x0aab2aab75e0: 00 00 00 00 00 00 00 00[01]f9 f9 f9 f9 f9 f9 f9
0x0aab2aab75f0: 00 00 f9 f9 f9 f9 f9 f9 00 00 f9 f9 f9 f9 f9 f9
0x0aab2aab7600: 00 00 f9 f9 f9 f9 f9 f9 00 00 f9 f9 f9 f9 f9 f9
0x0aab2aab7610: 00 f9 f9 f9 f9 f9 f9 f9 00 00 00 f9 f9 f9 f9 f9
0x0aab2aab7620: 00 00 00 00 00 00 00 00 00 00 00 00 f9 f9 f9 f9
0x0aab2aab7630: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Shadow byte legend (one shadow byte represents 8 application bytes):
Addressable: 00
Partially addressable: 01 02 03 04 05 06 07
Heap left redzone: fa
Freed heap region: fd
Stack left redzone: f1
Stack mid redzone: f2
Stack right redzone: f3
Stack after return: f5
Stack use after scope: f8
Global redzone: f9
Global init order: f6
Poisoned by user: f7
Container overflow: fc
Array cookie: ac
Intra object redzone: bb
ASan internal: fe
Left alloca redzone: ca
Right alloca redzone: cb
Shadow gap: cc
==525535==ABORTING
warning: build/test/backtrace.gdb: No such file or directory
> And terminated with exit code: [0]
So the message is because there is no backtrace, but the error is just as helpful when detecting the sanitization error as the reason for the crash. As a temporary workaround I wrote a very simple plugin to run gdb on any test that fails. It is unideal because not all failures are worthy of running gdb, but it allows CI pipeline logs to have helpful printouts.
Here is my gdb_runner.rb plugin:
require 'ceedling/plugin'
class GdbRunner < Plugin
def post_test_fixture_execute(arg_hash)
puts "Test exit code: #{arg_hash[:shell_result][:exit_code]}..."
if arg_hash[:shell_result][:exit_code] != 0
failing_test = arg_hash[:test_name]
puts "Running gdb for #{failing_test}..."
system("gdb -ex run -ex quit --args #{arg_hash[:executable]}")
end
end
end
which is included in project.yml when in file "../plugins/gdb_runner/lib/gdb_runner.rb":
:plugins:
:load_paths:
- "../plugins"
:enabled:
- gdb_runner
Example output now with running ceedling:
Running test_Utilities.out...
☠️ ERROR: Test executable `test_Utilities.out` seems to have crashed -- likely terminating early due to a bad code reference.
> Produced some output but contains no final test result counts.
> Causes can include: bad memory access, stack overflow, heap error, or bad branch in source or test code.
> Consider configuring :project ↳ :use_backtrace to use the :gdb option to find the cause (see documentation).
Test exit code: 2...
Running gdb for test_Utilities...
GNU gdb (Ubuntu 12.1-0ubuntu1~22.04.2) 12.1
Copyright (C) 2022 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from build/gcov/out/test_Utilities/test_Utilities.out...
Starting program: /home/build/gcov/out/test_Utilities/test_Utilities.out
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
=================================================================
==531833==ERROR: AddressSanitizer: global-buffer-overflow on address 0x5555555faf40 at pc 0x555555563896 bp 0x7fffffffc6d0 sp 0x7fffffffc6c0
READ of size 4 at 0x5555555faf40 thread T0
#0 0x555555563895 in test_Utilities_DisableSkipsRefresh tests/Utilities/test_Utilities.c:23
#1 0x5555555d1936 in run_test build/test/runners/test_Utilities_runner.c:84
#2 0x5555555d1a5d in main build/test/runners/test_Utilities_runner.c:121
#3 0x7ffff73cad8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58
#4 0x7ffff73cae3f in __libc_start_main_impl ../csu/libc-start.c:392
#5 0x555555563774 in _start (/home/build/gcov/out/test_Utilities/test_Utilities.out+0xf774)
0x5555555faf41 is located 0 bytes to the right of global variable 'mWdtDisableKick' defined in '../../../Utilities/Utilities.c:33:13' (0x5555555faf40) of size 1
SUMMARY: AddressSanitizer: global-buffer-overflow tests/Utilities/test_Utilities.c:23 in test_Utilities_DisableSkipsRefresh
Shadow bytes around the buggy address:
0x0aab2aab7590: f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9
0x0aab2aab75a0: f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9
0x0aab2aab75b0: f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9
0x0aab2aab75c0: f9 f9 f9 f9 00 00 00 00 00 00 00 00 00 00 00 00
0x0aab2aab75d0: 00 00 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9 f9
=>0x0aab2aab75e0: 00 00 00 00 00 00 00 00[01]f9 f9 f9 f9 f9 f9 f9
0x0aab2aab75f0: 00 00 f9 f9 f9 f9 f9 f9 00 00 f9 f9 f9 f9 f9 f9
0x0aab2aab7600: 00 00 f9 f9 f9 f9 f9 f9 00 00 f9 f9 f9 f9 f9 f9
0x0aab2aab7610: 00 f9 f9 f9 f9 f9 f9 f9 00 00 00 f9 f9 f9 f9 f9
0x0aab2aab7620: 00 00 00 00 00 00 00 00 00 00 00 00 f9 f9 f9 f9
0x0aab2aab7630: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Shadow byte legend (one shadow byte represents 8 application bytes):
Addressable: 00
Partially addressable: 01 02 03 04 05 06 07
Heap left redzone: fa
Freed heap region: fd
Stack left redzone: f1
Stack mid redzone: f2
Stack right redzone: f3
Stack after return: f5
Stack use after scope: f8
Global redzone: f9
Global init order: f6
Poisoned by user: f7
Container overflow: fc
Array cookie: ac
Intra object redzone: bb
ASan internal: fe
Left alloca redzone: ca
Right alloca redzone: cb
Shadow gap: cc
==531833==ABORTING
[Inferior 1 (process 531833) exited with code 01]
-------------------
FAILED TEST SUMMARY
-------------------
[tests/Utilities/test_Utilities.c]
Test: test_Utilities_DisableSkipsRefresh
At line (20): "Test case crashed"
Test: test_Utilities_NoDisableRefreshes
At line (28): "Test case crashed"
[tests/Utilities/test_Utilities.c]
Test: test_Utilities_DisableSkipsRefresh
At line (20): "Test case crashed"
Test: test_Utilities_NoDisableRefreshes
At line (28): "Test case crashed"
-----------------------
❌ OVERALL TEST SUMMARY
-----------------------
TESTED: 2
PASSED: 0
FAILED: 2
IGNORED: 0
---------------------
BUILD FAILURE SUMMARY
---------------------
Unit test failures.
Ceedling operations completed in 28.62 seconds
Thanks for the plugin. As you basically run the test binary using GDB I think it has the same effect as just running the test binary, so it may be simplified a bit. I will try it later, thanks!
Yes, so this generates same output as running directly. My version below.
require 'ceedling/plugin'
class CrashLog < Plugin
def post_test_fixture_execute(arg_hash)
if arg_hash[:shell_result][:exit_code] != 0
failing_test = arg_hash[:test_name]
message = "💥 Logs for crashing test #{failing_test}"
puts ""
puts "-" * (message.length + 1)
puts message
puts "-" * (message.length + 1)
system("#{arg_hash[:executable]}")
end
end
end
@KaSroka I like that a lot more, I'll throw that into the custom module instead to simplify output, thanks for sharing!
What is the difference between custom module and plugin when it comes to output?
Sorry, I meant plugin. I will use your class body instead of piping to gdb executable again so that I don't get all of the gdb output that is unimportant.