Nondeterministic test failures

[dabrahams]

After make clean; make dists; make test, if I run

set -e; cd do_test ; for x in 0 1 2 3 4 5 6 7 8 9; do make && ./tap/runtests -l ../test/TESTS ; done

I'll invariably observe a failure.

This one comes up easily:

simple/rule1............ok
simple/trivial..........ok
simple/trivial1.........ABORTED (invalid test number 339)
simple/nits.............ok

Failed Set                 Fail/Total (%) Skip Stat  Failing Tests
-------------------------- -------------- ---- ----  ------------------------
simple/trivial1             109/338   32%    0    0  aborted

but I've also seen:

[test.log](https://github.com/jeffreykegler/libmarpa/files/8401410/test.log)
simple/rule1............ok
simple/trivial..........ok
simple/trivial1.........FAILED 174, 176, 178, 180, 182, 184, 186, 188, 190, 192, 194, 196, 199, 201, 203, 205, 209, 211, 213, 215, 217, 227, 234, 236, 239, 242, 251, 254, 257, 260, 263, 266, 270, 272, 275, 277, 280, 282, 286, 290, 292, 294, 296, 298, 300, 302, 305, 309, 311, 322, 335, 338
simple/nits.............ok

Failed Set                 Fail/Total (%) Skip Stat  Failing Tests
-------------------------- -------------- ---- ----  ------------------------
simple/trivial1              52/338   15%    0    0  174, 176, 178, 180, ...

Failed 52/375 tests, 86.13% okay.
Files=4,  Tests=375,  0.00 seconds (0.05 usr + 0.04 sys = 0.09 CPU)

I've attached one log of the output of a failing run of ./tap/runtests -o simple/trivial1

[dabrahams]

A couple of test logs attached test.log test2.log

[jeffreykegler]

I tried this on the master branch and cannot duplicate these failures.

Examining the logs, I note the 'A symbol is both terminal and nulling' occurs in all the test.log ones. Is this the original trivial1, or an altered version? This message occurs if you use LHS terminals, and try to mark a nulling symbol as terminal.

[dabrahams]

Yes, this is duplicated in an unaltered upstream master with the latest macOS running on an M1 Max, after git clean -fdfx.

[jeffreykegler]

Hopefully I will be able to find these via deskchecks.

[dabrahams]

I suggest ASAN and optionally, UBSAN.

[dabrahams]

ASAN reports:

1..338
ok 1 - marpa_g_symbol_is_start() expected failure; value = -2 as expected
ok 2 - marpa_g_symbol_is_start() expected failure; error as expected: 'Symbol ID is malformed'
ok 3 - marpa_g_symbol_is_start() expected failure; value = -1 as expected
ok 4 - marpa_g_symbol_is_start() expected failure; error as expected: 'No symbol with this ID exists'
ok 5 - marpa_g_symbol_is_start() success as expected
ok 6 - marpa_g_start_symbol() expected failure; value = -1 as expected
ok 7 - marpa_g_start_symbol() expected failure; error as expected: 'This grammar has no start symbol'
ok 8 - marpa_g_symbol_is_start() success as expected
ok 9 - marpa_g_start_symbol() success as expected
ok 10 - marpa_g_highest_symbol_id() success as expected
ok 11 - marpa_g_symbol_is_accessible() expected failure; value = -2 as expected
ok 12 - marpa_g_symbol_is_accessible() expected failure; error as expected: 'This grammar is not precomputed'
ok 13 - marpa_g_symbol_is_nullable() expected failure; value = -2 as expected
ok 14 - marpa_g_symbol_is_nullable() expected failure; error as expected: 'This grammar is not precomputed'
ok 15 - marpa_g_symbol_is_nulling() expected failure; value = -2 as expected
ok 16 - marpa_g_symbol_is_nulling() expected failure; error as expected: 'This grammar is not precomputed'
ok 17 - marpa_g_symbol_is_productive() expected failure; value = -2 as expected
ok 18 - marpa_g_symbol_is_productive() expected failure; error as expected: 'This grammar is not precomputed'
ok 19 - marpa_g_symbol_is_terminal() success as expected
ok 20 - marpa_g_rule_is_nullable() expected failure; value = -2 as expected
ok 21 - marpa_g_rule_is_nullable() expected failure; error as expected: 'This grammar is not precomputed'
ok 22 - marpa_g_rule_is_nulling() expected failure; value = -2 as expected
ok 23 - marpa_g_rule_is_nulling() expected failure; error as expected: 'This grammar is not precomputed'
ok 24 - marpa_g_rule_is_loop() expected failure; value = -2 as expected
ok 25 - marpa_g_rule_is_loop() expected failure; error as expected: 'This grammar is not precomputed'
ok 26 - marpa_g_rule_is_accessible() expected failure; value = -2 as expected
ok 27 - marpa_g_rule_is_accessible() expected failure; error as expected: 'This grammar is not precomputed'
ok 28 - marpa_g_rule_is_productive() expected failure; value = -2 as expected
ok 29 - marpa_g_rule_is_productive() expected failure; error as expected: 'This grammar is not precomputed'
ok 30 - marpa_g_symbol_is_terminal_set() expected failure; value = -2 as expected
ok 31 - marpa_g_symbol_is_terminal_set() expected failure; error as expected: 'Symbol ID is malformed'
ok 32 - marpa_g_symbol_is_terminal_set() expected failure; value = -1 as expected
ok 33 - marpa_g_symbol_is_terminal_set() expected failure; error as expected: 'No symbol with this ID exists'
ok 34 - marpa_g_highest_rule_id() success as expected; before precomputation
ok 35 - marpa_g_rule_length() success as expected; before precomputation
ok 36 - marpa_g_rule_length() success as expected; before precomputation
ok 37 - marpa_g_rule_lhs() success as expected; before precomputation
ok 38 - marpa_g_rule_rhs() success as expected; before precomputation
ok 39 - marpa_g_rule_rhs() success as expected; before precomputation
ok 40 - marpa_g_symbol_is_terminal_set() success as expected
ok 41 - marpa_g_symbol_is_terminal_set() expected failure; value = -2 as expected
ok 42 - marpa_g_symbol_is_terminal_set() expected failure; error as expected: 'The terminal status of the symbol is locked'
ok 43 - marpa_g_precompute() expected failure; value = -2 as expected
ok 44 - marpa_g_precompute() expected failure; error as expected: 'A symbol is both terminal and nulling'
=================================================================
==18075==ERROR: AddressSanitizer: heap-use-after-free on address 0x000107603ecc at pc 0x0001049d8b58 bp 0x00016b4392d0 sp 0x00016b4392c8
READ of size 4 at 0x000107603ecc thread T0
    #0 0x1049d8b54 in marpa_g_error marpa.w:1229
    #1 0x1049d4968 in rv_std_report marpa_m_test.c:174
    #2 0x1049cab50 in main trivial1.c:273
    #3 0x104d6d084 in start+0x200 (dyld:arm64e+0x5084)

0x000107603ecc is located 268 bytes inside of 288-byte region [0x000107603dc0,0x000107603ee0)
freed by thread T0 here:
    #0 0x10516fd44 in wrap_free+0x98 (libclang_rt.asan_osx_dynamic.dylib:arm64e+0x3fd44)
    #1 0x104a03988 in my_free marpa_ami.w:204
    #2 0x104a421c0 in grammar_free marpa.w:729
    #3 0x1049d7094 in grammar_unref marpa.w:704
    #4 0x1049d6ef8 in marpa_g_unref marpa.w:709
    #5 0x1049caacc in main trivial1.c:270
    #6 0x104d6d084 in start+0x200 (dyld:arm64e+0x5084)

previously allocated by thread T0 here:
    #0 0x10516fc08 in wrap_malloc+0x94 (libclang_rt.asan_osx_dynamic.dylib:arm64e+0x3fc08)
    #1 0x1049d6674 in my_malloc marpa_ami.w:212
    #2 0x1049d597c in marpa_g_new marpa.w:672
    #3 0x1049d3918 in marpa_g_trivial_new trivial1.c:100
    #4 0x1049c95dc in main trivial1.c:194
    #5 0x104d6d084 in start+0x200 (dyld:arm64e+0x5084)

SUMMARY: AddressSanitizer: heap-use-after-free marpa.w:1229 in marpa_g_error
Shadow bytes around the buggy address:
  0x007020ee0780: fa fa fa fa fa fa fa fa 00 00 00 00 00 00 00 00
  0x007020ee0790: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x007020ee07a0: 00 00 00 00 00 00 00 00 00 00 00 00 fa fa fa fa
  0x007020ee07b0: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
  0x007020ee07c0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
=>0x007020ee07d0: fd fd fd fd fd fd fd fd fd[fd]fd fd fa fa fa fa
  0x007020ee07e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x007020ee07f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x007020ee0800: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x007020ee0810: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x007020ee0820: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
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
==18075==ABORTING

[jeffreykegler]

Looks helpful. I will investigate.

[jeffreykegler]

AFAICT the ASAN is a false positive. The following code may be fooling ASAN.

269:  /* terminals are locked after setting, so we recreate the grammar */
270:  marpa_g_unref(g);
271:  g = marpa_g_trivial_new(&marpa_configuration);
273:  API_STD_TEST0(defaults, -2, MARPA_ERR_NO_START_SYMBOL, marpa_g_precompute, g);
275:  marpa_g_trivial_precompute(g, S_top);

Yes, g is freed at 270, but a new one is allocated at 271, before the reported ref after free. The allocation in marpa_g_trivial_new is checked, and all looks fine.

[dabrahams]

No, in fact, your defaults struct contains a reference to the old grammar, which has been deallocated. See here. That's the grammar being dereferenced.

[jeffreykegler]

Good catch. That explains a lot. I will never again so lightly besmirch the escutheon of ASAN. :-)

[jeffreykegler]

I hope the commit just referenced solves the issue. @dabrahams , perhaps you'd be willing to give it a test?

[dabrahams]

Works for me. I suggest you turn on ASAN/UBSAN in all your tests, or introduce a parallel set of tests run with these things enabled.

[jeffreykegler]

Considered fixed, as per the previous comment. I folded the change into the master branch. Absent feedback to the contrary, I will close this in a couple of days.

[jeffreykegler]

Closed as fixed, per the previous comment