unit-tests stuck on ascii

[OPNA2608]

On Linux, I'm running roughly the following inside of a WIP package script:

# fetch bootstrapped 1.09.0 tarball, unpack, enter, apply patches

# build
make bootstrap -j${cores}
make FBC="${PWD}/bin/fbc -i ${PWD}/inc" -j${buildCores}

# test (ignoring other test suites for this example)
make unit-tests UNITTEST_RUN_ARGS=--verbose -j${testCores}

# install
make install prefix=/bla/blub

This works fine until make unit-tests. It builds the tests and starts running them, but it gets stuck on:

  fbc_tests.udt_wstring_.midstmt
    ascii

After letting it sit on this for more than an hour, it never advanced further. Here is the full build log.

I'm building against NixOS unstable. I tried to reproduce this on Ubuntu 22.04 interactively but failed. Installing Nix on Ubuntu 22.04 and trying to build the package with unit-tests enabled also gets stuck.

git clone --depth 1 --branch init/fbc https://github.com/OPNA2608/nixpkgs
cd nixpkgs
vim pkgs/development/compilers/fbc/default.nix
# comment/uncomment the checkTarget lines, uncomment preCheck, comment out postCheck
nix-build . -A fbc --cores 4

Please let me know if there's anything else I can do for you to debug this.

[jayrm]

@OPNA2608 , perhaps have a look at contrib/travis/build-and-test.sh and try:

make unit-tests UNITTEST_RUN_ARGS=--verbose -j${testCores} </dev/null

My amateur explanation is that fbc executables mess with the console and redirecting some commands to /dev/null prevents these kinds of hangs.

To be honest, I didn't set-up a test to try and replicate; besides, @dkl probably has better knowledge and experience with this problem.

[OPNA2608]

Doesn't seem to help, whether I do it via make unit-tests or directly with fbc-tests:

bt1cn@NixTop:/dev/shm/FreeBASIC-1.09.0-source-bootstrap/tests
↪ time ./fbc-tests </dev/null
^C
________________________________________________________
Executed in  105.53 mins    fish           external
   usr time  105.42 mins    0.00 micros  105.42 mins
   sys time    0.00 mins  893.00 micros    0.00 mins

[dkl]

Can you run it in gdb, to see the backtrace where it gets stuck? I'm thinking something like:
Add -g to CFLAGS and pass DEBUG=1 to make unit-tests:

echo "CFLAGS := -g -O2" >config.mk
make bootstrap -j16
make FBC="${PWD}/bin/fbc -i ${PWD}/inc" -j16
make unit-tests UNITTEST_RUN_ARGS=--verbose -j16 DEBUG=1

And then:

$ cd tests
$ gdb --args ./fbc-tests --verbose
[...]
(gdb) r
[...]
<press CTRL+C after it gets stuck>
(gdb) bt

[dkl]

Well, I've given the nix example a try, and could reproduce the problem. The main issue seems to be that the unit test runs an infinite loop even though it should not.

SUITE( fbc_tests.udt_wstring_.midstmt )
	TEST( ascii )
		...
		for i1 as integer = 0 to MAX
			printf(!"ascii: i1=%zi\n", i1)
			fflush(stdout)
			for i2 as integer = 0 to MAX
				printf(!"ascii: i2=%zi\n", i2)
				fflush(stdout)
				for istart as integer = -2 to MAX+2
					printf(!"ascii: istart=%zi\n", istart)
					fflush(stdout)
					...
					for length as integer = -2 to MAX+2
						printf(!"ascii: length=%zi\n", length)
						fflush(stdout)
						...
					next
				next
			next i2
		next i1
	END_TEST
	...

In the nix build:

ascii: i1=0
ascii: i2=0
ascii: istart=-2
ascii: length=-2 after FOR
ascii: length=0 before NEXT
ascii: length=1 after FOR
ascii: length=0 before NEXT
ascii: length=1 after FOR
...

Apparently the length variable (the iterator of the inner-most for loop) is getting overwritten. It's passed to fb_WstrAssignMid(), but only by-value, so I think there must be some stack corruption and/or buffer overflowing involved. Further debugging needed...

On my normal Ubuntu it does not happen:

ascii: start
ascii: i1=0
ascii: i2=0
ascii: istart=-2
ascii: length=-2 after FOR
ascii: length=-2 before NEXT
ascii: length=-1 after FOR
ascii: length=-1 before NEXT
ascii: length=0 after FOR
ascii: length=0 before NEXT
ascii: length=1 after FOR
ascii: length=1 before NEXT

[OPNA2608]

I was about to write about the gdb log & where it gets stuck, but you ninja'd me. 😅

I think there must be some stack corruption and/or buffer overflowing involved.

This was the magic hint, I disabled the stackprotector hardening for the build and it stopped getting stuck on this test. stackprotector adds these compiler options to the GCC wrapper: -fstack-protector-strong --param ssp-buffer-size=4.

[dkl]

After some more printf-debugging, I think this should fix it: #384

There really were bogus stack writes. I was able to reproduce the hang outside nix-build on normal Ubuntu by making fbc -gen gcc use those gcc options. Also, I don't know why -fstack-protector fails to detect the bug, but AddressSanitizer finds it:

==279298==ERROR: AddressSanitizer: stack-buffer-overflow on address 0x7fffb16875e8 at pc 0x7fb7f4a01c23 bp 0x7fffb16874a0 sp 0x7fffb1686c48
WRITE of size 200 at 0x7fffb16875e8 thread T0
    #0 0x7fb7f4a01c22 in __interceptor_memset ../../../../src/libsanitizer/sanitizer_common/sanitizer_common_interceptors.inc:799
    #1 0xa3fb11 in TESTS::FBC_TESTS::UDT_WSTRING_::MIDSTMT::ASCII() (/home/daniel/fb/fbc/tests/fbc-tests+0xa3fb11)
    #2 0xcc536c in FBCU::RUN_TESTS(bool, bool) src/fbcunit.bas:649
    #3 0xcc134e in main (/home/daniel/fb/fbc/tests/fbc-tests+0xcc134e)
    #4 0x7fb7f4506d8f in __libc_start_call_main ../sysdeps/nptl/libc_start_call_main.h:58
    #5 0x7fb7f4506e3f in __libc_start_main_impl ../csu/libc-start.c:392
    #6 0x413364 in _start (/home/daniel/fb/fbc/tests/fbc-tests+0x413364)

[jayrm]

@dkl, nice, some slick debugging there. Thank-you for finding the problems in my awful test code.

[dkl]

Yea, that was an interesting dive into nix too... It's interesting that the bug didn't show up earlier though, I guess it always got lucky and ended up writing zeroes into the string buffer allocated right before/next to it (which is what it was meant to do anyways)?

It's probably possible to add a compiler warning about at least some cases like this - clearing an internal temp var (that was used to hold the value of the AddrOf() expression passed to the Byref As Any parameter), surely that will never be intentional? I might give that a try, since I remember making the same mistake.

Anyways, this can probably be closed now. The two patches can easily be backported on top of 1.09.0 as needed.