Flaky test_framework tests

[rlenferink]

Between different test runs some of the test_framework tests fail:

[  FAILED  ] 3 tests, listed below:
[  FAILED  ] ScheduledEventTestSuite.CxxOneShotScheduledEventTest
[  FAILED  ] ScheduledEventTestSuite.CxxOneShotScheduledEventRAIITest
[  FAILED  ] ScheduledEventTestSuite.CxxWaitForScheduledEventTest

It is not always that all three fail, I have also seen cases where only e.g. the ScheduledEventTestSuite.CxxOneShotScheduledEventRAIITest test fails.

Built and run with cmake -DCMAKE_BUILD_TYPE=RelWithDebInfo -DENABLE_TESTING=ON .. && make -j && ctest --output-on-failure

To test the 'flakyness', I ran only the test_framework with for i in $(seq 0 50); do ctest --output-on-failure -R test_framework; done. Out of the 50 results I had:

• 2 failures for ScheduledEventTestSuite.CxxOneShotScheduledEventRAIITest
• 1 failure for ScheduledEventTestSuite.CxxScheduledEventTest
• 47 succeeding tests

==== Log of first test failure ===

ScheduledEventTestSuite.CxxWaitForScheduledEventTest

[ RUN      ] ScheduledEventTestSuite.CxxWaitForScheduledEventTest
[2023-09-26T17:06:34] [   info] [celix_framework] [framework_start:476] Celix framework started
[2023-09-26T17:06:34] [  trace] [celix_framework] [framework_start:477] Celix framework started with uuid 93d47aae-62e6-476e-8bb3-d62389caa4ea
[2023-09-26T17:06:34] [  debug] [celix_framework] Framework started event received -> registering framework.ready condition service
[2023-09-26T17:06:34] [  debug] [celix_framework] [celix_framework_scheduleEvent:2534] Added scheduled event '' (id=0) for bundle 'celix_framework' (id=0).
/home/rlenferink/workspace/asf/celix/celix-container/libs/framework/gtest/src/ScheduledEventTestSuite.cc:672: Failure
Value of: success
  Actual: false
Expected: true
/home/rlenferink/workspace/asf/celix/celix-container/libs/framework/gtest/src/ScheduledEventTestSuite.cc:675: Failure
Expected equality of these values:
  1
  count.load()
    Which is: 0
/home/rlenferink/workspace/asf/celix/celix-container/libs/framework/gtest/src/ScheduledEventTestSuite.cc:687: Failure
Value of: success
  Actual: false
Expected: true
/home/rlenferink/workspace/asf/celix/celix-container/libs/framework/gtest/src/ScheduledEventTestSuite.cc:690: Failure
Expected equality of these values:
  2
  count.load()
    Which is: 0
[2023-09-26T17:06:34] [  debug] [celix_framework] [celix_framework_processScheduledEvents:1394] Removing processed scheduled event '' (id=0) for bundle if 0.
[2023-09-26T17:06:34] [  trace] [celix_framework] [celix_framework_shutdownAsync:1143] Start shutdown thread for framework 93d47aae-62e6-476e-8bb3-d62389caa4ea
[2023-09-26T17:06:34] [  trace] [celix_framework] [celix_bundleContext_cleanup:115] Cleaning up bundle context `celix_framework` (id=0)
[2023-09-26T17:06:34] [  trace] [celix_framework] [framework_shutdown:1096] Celix framework shutting down
[2023-09-26T17:06:34] [  trace] [celix_framework] [celix_framework_stopAndJoinEventQueue:1081] Stop and joining event loop thread for framework 93d47aae-62e6-476e-8bb3-d62389caa4ea
[2023-09-26T17:06:34] [  debug] [celix_framework] [celix_framework_stopAndJoinEventQueue:1090] Joined event loop thread for framework 93d47aae-62e6-476e-8bb3-d62389caa4ea
[  FAILED  ] ScheduledEventTestSuite.CxxWaitForScheduledEventTest (221 ms)

ScheduledEventTestSuite.CxxOneShotScheduledEventRAIITest

[ RUN      ] ScheduledEventTestSuite.CxxOneShotScheduledEventRAIITest
[2023-09-26T17:06:33] [   info] [celix_framework] [framework_start:476] Celix framework started
[2023-09-26T17:06:33] [  trace] [celix_framework] [framework_start:477] Celix framework started with uuid 7b172375-5258-4f0a-8af1-8bcdcf7b85a0
[2023-09-26T17:06:33] [  debug] [celix_framework] Framework started event received -> registering framework.ready condition service
[2023-09-26T17:06:33] [  debug] [celix_framework] [celix_framework_scheduleEvent:2534] Added scheduled event 'test cxx one-shot' (id=0) for bundle 'celix_framework' (id=0).
/home/rlenferink/workspace/asf/celix/celix-container/libs/framework/gtest/src/ScheduledEventTestSuite.cc:515: Failure
Expected equality of these values:
  1
  count.load()
    Which is: 0
/home/rlenferink/workspace/asf/celix/celix-container/libs/framework/gtest/src/ScheduledEventTestSuite.cc:519: Failure
Value of: removed.load()
  Actual: false
Expected: true
[2023-09-26T17:06:33] [  trace] [celix_framework] [celix_scheduledEvent_process:177] Processing scheduled event test cxx one-shot for bundle id 0
[2023-09-26T17:06:33] [  debug] [celix_framework] [celix_framework_processScheduledEvents:1394] Removing processed one-shot scheduled event 'test cxx one-shot' (id=0) for bundle if 0.
[2023-09-26T17:06:33] [  trace] [celix_framework] [celix_framework_shutdownAsync:1143] Start shutdown thread for framework 7b172375-5258-4f0a-8af1-8bcdcf7b85a0
[2023-09-26T17:06:33] [  trace] [celix_framework] [celix_bundleContext_cleanup:115] Cleaning up bundle context `celix_framework` (id=0)
[2023-09-26T17:06:33] [  trace] [celix_framework] [framework_shutdown:1096] Celix framework shutting down
[2023-09-26T17:06:33] [  trace] [celix_framework] [celix_framework_stopAndJoinEventQueue:1081] Stop and joining event loop thread for framework 7b172375-5258-4f0a-8af1-8bcdcf7b85a0
[2023-09-26T17:06:33] [  debug] [celix_framework] [celix_framework_stopAndJoinEventQueue:1090] Joined event loop thread for framework 7b172375-5258-4f0a-8af1-8bcdcf7b85a0
[  FAILED  ] ScheduledEventTestSuite.CxxOneShotScheduledEventRAIITest (253 ms)

ScheduledEventTestSuite.CxxOneShotScheduledEventTest

[ RUN      ] ScheduledEventTestSuite.CxxOneShotScheduledEventTest
[2023-09-26T17:06:33] [   info] [celix_framework] [framework_start:476] Celix framework started
[2023-09-26T17:06:33] [  trace] [celix_framework] [framework_start:477] Celix framework started with uuid a83db7a8-4b24-4880-9e34-b94c2f4e85fb
[2023-09-26T17:06:33] [  debug] [celix_framework] Framework started event received -> registering framework.ready condition service
[2023-09-26T17:06:33] [  debug] [celix_framework] [celix_framework_scheduleEvent:2534] Added scheduled event 'test cxx one-shot' (id=0) for bundle 'celix_framework' (id=0).
/home/rlenferink/workspace/asf/celix/celix-container/libs/framework/gtest/src/ScheduledEventTestSuite.cc:465: Failure
Expected equality of these values:
  1
  count.load()
    Which is: 0
/home/rlenferink/workspace/asf/celix/celix-container/libs/framework/gtest/src/ScheduledEventTestSuite.cc:469: Failure
Value of: removed.load()
  Actual: false
Expected: true
[2023-09-26T17:06:33] [  debug] [celix_framework] [celix_scheduledEvent_markForWakeup:215] Wakeup scheduled event 'test cxx one-shot' (id=0) for bundle id 0
[2023-09-26T17:06:33] [  trace] [celix_framework] [celix_scheduledEvent_process:177] Processing scheduled event test cxx one-shot for bundle id 0
[2023-09-26T17:06:33] [  debug] [celix_framework] [celix_framework_processScheduledEvents:1394] Removing processed one-shot scheduled event 'test cxx one-shot' (id=0) for bundle if 0.
[2023-09-26T17:06:33] [  trace] [celix_framework] [celix_framework_shutdownAsync:1143] Start shutdown thread for framework a83db7a8-4b24-4880-9e34-b94c2f4e85fb
[2023-09-26T17:06:33] [  trace] [celix_framework] [celix_bundleContext_cleanup:115] Cleaning up bundle context `celix_framework` (id=0)
[2023-09-26T17:06:33] [  trace] [celix_framework] [framework_shutdown:1096] Celix framework shutting down
[2023-09-26T17:06:33] [  trace] [celix_framework] [celix_framework_stopAndJoinEventQueue:1081] Stop and joining event loop thread for framework a83db7a8-4b24-4880-9e34-b94c2f4e85fb
[2023-09-26T17:06:33] [  debug] [celix_framework] [celix_framework_stopAndJoinEventQueue:1090] Joined event loop thread for framework a83db7a8-4b24-4880-9e34-b94c2f4e85fb
[  FAILED  ] ScheduledEventTestSuite.CxxOneShotScheduledEventTest (354 ms)

[pnoltes]

The ScheduledEventTestSuite tests scheduled events and scheduled events are - as designed - time sensitive.

I tried to allow enough error margin so that these test are not flaky, but evidently not enough.
Note that for CI testing the error margin is much larger (because the build server are virtually machines):
https://github.com/apache/celix/blob/master/libs/framework/gtest/src/ScheduledEventTestSuite.cc#L28-L34

#if defined(__APPLE__) && defined(TESTING_ON_CI)
    const int ALLOWED_ERROR_MARGIN_IN_MS = 1500;
#elif TESTING_ON_CI
    const int ALLOWED_ERROR_MARGIN_IN_MS = 1000;
#else
    const int ALLOWED_ERROR_MARGIN_IN_MS = 100;
#endif

I will look into this.

[rlenferink]

With the -DENABLE_TESTING_ON_CI=ON flag specified the test_framework doesn't seem to fail anymore. I don't think the test duration is increased that much by having it enabled (still ~12/13 seconds per test).

[PengZheng]

And as expected, #587 is not a macOS-specific issue.
We need to develop more reliable testing methods for timing sensitive tasks.