Unittests failure can trigger cascading failures in d2sqlite3

[Geod24]

Take the following log

Type 'Node' implements more than one interface: make sure the one describing the REST server is the first one
Linking...
To force a rebuild of up-to-date targets, run again with --force.
Running ./build/agora-unittests
Module tests failed: agora.consensus.EnrollmentManager
core.exception.AssertError@source/agora/consensus/EnrollmentManager.d(961): Assertion failure
----------------
??:? _d_assert [0x109316427]
??:? void agora.consensus.EnrollmentManager.__unittest_L946_C1() [0x108a07828]
??:? agora.consensus.EnrollmentManager.__unittest [0x108a07a0f]
??:? void agora.test.Base.customModuleUnitTester().runTest(agora.test.Base.customModuleUnitTester().ModTest) [0x1089867f1]
??:? int agora.test.Base.customModuleUnitTester().__foreachbody4(ref agora.test.Base.customModuleUnitTester().ModTest) [0x108986b30]
??:? void std.parallelism.ParallelForeach!(agora.test.Base.customModuleUnitTester().ModTest[]).ParallelForeach.opApply(scope int delegate(ref agora.test.Base.customModuleUnitTester().ModTest)).doIt() [0x108d4dae1]
??:? void std.parallelism.TaskPool.doJob(std.parallelism.AbstractTask*) [0x109299670]
??:? void std.parallelism.TaskPool.startWorkLoop() [0x10929981a]
??:? thread_entryPoint [0x10931f814]
??:? _pthread_start [0x7fff6d1a1108]
2020-04-17 13:28:09,255 Info [agora.consensus.ValidatorSet] - Rejected already existing enrollment, Data was: { utxo_key: 0x4aa53a00b320d8e78a9a322eb631b43c47eafc30b7c411e55ed87c192b3083f1ad943d18ff430142f3fcaa0f0f8ff1d93f701502122eabfb6db7810fa79ad749, random_seed: 0x5bca78fca96ef868f997bf2dc2e3ff9d50493ab2c5127167305b25ffeb813b823b28ca61f3eca54aa8a3e653d97db5c17814df833b63a66931445e2bd57549e2, cycle_length: 1008, enroll_sig: 0x0307ab19eb4451c150bbf5199ffa3408808ae4d3ad39c63a3c2d2e86918ecabebb7c0f399c793c944023168d63b6053b0f691495342e6d01731fe609867ac132 }
2020-04-17 13:28:09,339 Info [agora.consensus.ValidatorSet] - Invalid enrollment data: Enrollment signature verification has an error., Data was: { utxo_key: 0xe9cf4dea98f10a4c312e1f0e52860b1d1854080a283950fd11e40c7737ec5a2af7ea10244b56a0156602ec85c8c19848ce6d1b7940639453ce1d03da365075a0, random_seed: 0xe667ad5396df6360aae6282e2e8ff3a37ff8be0cabafe096da42009766dc4642f925c4016f2637fe9f65f002693392549f90c5c34e7300020dae998ff5770ad2, cycle_length: 1008, enroll_sig: 0x069f5a4e32813063f20226593c8850cf066ee637316dccbabe2399473f6dc457f9019ee097bcb3fc63edd23c2734b9ece03a0b1f7866953a5636552527df67d0 }
2020-04-17 13:28:09,340 Info [agora.consensus.ValidatorSet] - Rejected already existing enrollment, Data was: { utxo_key: 0xe9cf4dea98f10a4c312e1f0e52860b1d1854080a283950fd11e40c7737ec5a2af7ea10244b56a0156602ec85c8c19848ce6d1b7940639453ce1d03da365075a0, random_seed: 0x00a92eac7c03eea4942d588320a3092baf10d115876607c7ee546492ab8e90104ad3d81ef96a759eaab062ab8279d8ed49bae22c9c477dc2f1226fb2ade95c73, cycle_length: 1008, enroll_sig: 0x09b4cc315e1b8ec09bbcbf2c316e214d5a4a57a6688d020a9f79e79e8205eb79f9019ee097bcb3fc63edd23c2734b9ece03a0b1f7866953a5636552527df67d0 }
Error: clean-up of Database incorrectly depends on destructors called by the GC.
Info: :memory:
0   agora-unittests                     0x000000010931cbbe _D4core7runtime18runModuleUnitTestsUZ19unittestSegvHandlerUNbiPSQCk3sys5posix6signal9siginfo_tPvZv + 62
1   libsystem_platform.dylib            0x00007fff6d1955fd _sigtramp + 29
2   agora-unittests                     0x000000010932b20e _D2gc4impl12conservativeQw3Gcx10smallAllocMFNbmKmkxC8TypeInfoZPv + 574
3   agora-unittests                     0x0000000109326ab9 _D2gc4impl12conservativeQw14ConservativeGC__T9runLockedS_DQCeQCeQCcQCnQBs12mallocNoSyncMFNbmkKmxC8TypeInfoZPvS_DQEgQEgQEeQEp10mallocTimelS_DQFiQFiQFgQFr10numMallocslTmTkTmTxQCzZQFcMFNbKmKkKmKxQDsZQDl + 89
4   agora-unittests                     0x00000001093299d3 _DThn16_2gc4impl12conservativeQw14ConservativeGC6qallocMFNbmkxC8TypeInfoZS4core6memory8BlkInfo_ + 83
5   agora-unittests                     0x0000000109331e1d gc_qalloc + 29
6   agora-unittests                     0x000000010931c162 _D4core6memory2GC6qallocFNaNbmkxC8TypeInfoZSQBqQBo8BlkInfo_ + 18
7   agora-unittests                     0x000000010933f938 _D2rt8lifetime12__arrayAllocFmKS4core6memory8BlkInfo_xC8TypeInfoxQlZQBl + 200
8   agora-unittests                     0x000000010934315c _d_arrayappendcTX + 1484
9   agora-unittests                     0x0000000108974ba4 _D5agora4test14NetworkManager17__unittest_L54_C1FZ7BadNode13getBlocksFromMFNfmkZAxSQDd9consensus4data5BlockQg + 276
10  agora-unittests                     0x000000010898da31 _D6geod249LocalRest__T9RemoteAPITC5agora4test4Base7TestAPIZQBl13handleCommandFSQCzQCv7CommandQCiSQDrQDn9FilterAPIZv + 11761
11  agora-unittests                     0x00000001089acc42 _D6geod249LocalRest__T9RemoteAPITC5agora4test4Base7TestAPIZQBl__T7spawnedTCQBpQBm14NetworkManager17__unittest_L54_C1FZ7BadNodeZQCkFSQFa11concurrency3TidSQEp6common6ConfigQhPOSQGr8RegistryQjZ__T6handleTSQHsQHo7CommandZQyMFQuZ9__lambda2MFZv + 178
12  agora-unittests                     0x0000000108eed219 _D6geod2411concurrency14FiberScheduler6createMFNbDFZvZ4wrapMFZv + 25
13  agora-unittests                     0x000000010931eb2c fiber_entryPoint + 92
Program exited with code -11
dub test  41.86s user 3.62s system 121% cpu 37.434 total

The actual failure is happening in this piece of code:
https://github.com/bpfkorea/agora/blob/864d2efffd1ffebf3980651dab642e90ed72bc9e/source/agora/consensus/EnrollmentManager.d#L946-L962

However, there is a subsequent unittest failure which shouldn't be here. This means the unittests are not as independent as they should. This is most likely due to d2sqlite3 and needs investigation.

[Geod24]

For clarity, there is no bug in the EnrollmentManager here, the assert rightfully triggered during development. This issue is only about the fact that the observed behavior is different from the expected behavior.

[AndrejMitrovic]

I think there is something broken with scope (exit):

import core.stdc.stdio;

class C
{
    int line;
    this (int line = __LINE__) { this.line = line; }

    void shutdown ()
    {
        printf("shutdown at %d\n", this.line);
    }

    ~this ()
    {
        printf("dtor at %d\n", this.line);
    }
}

void main ()
{
    auto c = new C;
    scope (exit) c.shutdown();
    bool False;
    assert(False);
}

This prints:

dtor at 21

Where is the shutdown call??

If I change it to scope(failure) it does the right thing:

void main ()
{
    auto c = new C;
    scope (failure) c.shutdown();
    bool False;
    assert(False);
}

This prints:

shutdown at 21
dtor at 21

And take a look at this test-case:

void main ()
{
    auto c = new C;
    scope (exit) c.shutdown();
    scope (exit) c.shutdown();
    bool False;
    assert(False);
}

Prints:

shutdown at 21
dtor at 21

WTF? We need two scope(exit)'s to force at least one to run?

I'm perplexed..

[Geod24]

So, scope is not guaranteed to be run on assertion failure.
However, assert in unittest behaves differently. I think we should try this within unittest block to be sure.

[AndrejMitrovic]

So, scope is not guaranteed to be run on assertion failure.

Is this documented anywhere?

However, assert in unittest behaves differently. I think we should try this within unittest block to be sure.

I get the same effects in a unittest block.

[Geod24]

Is this documented anywhere?

I can only find this statement:

The first AssignExpression must evaluate to true. If it does not, an Assert Failure has occurred and the program enters an Invalid State.
[...]
Undefined Behavior: Once in an Invalid State the behavior of the continuing execution of the program is undefined.

I remember it being discussed, but I could also find this statement which directly contradicts my claim:

If code detects an error like "out of memory," then an Error is thrown with a message saying "Out of memory". The function call stack is unwound, looking for a handler for the Error. Finally blocks are executed as the stack is unwound. If an error handler is found, execution resumes there. If not, the default Error handler is run, which displays the message and terminates the program.

Emphasis mine.

[Geod24]

Well here goes: dlang/dmd#6896

[AndrejMitrovic]

I wonder if we should change our asserts into enforce in the unittests. It's the only way we'll get proper cleanup code to run..

[Geod24]

You mean everywhere ?

[AndrejMitrovic]

I think this was resolved with the begin/commit/end SQLite calls. Please reopen if it appears again.