Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

TSAN DelayActivation/TimerImplTest.ChangeTimerForwardsToNonZeroBeforeRun/0 flake #12532

Closed
dio opened this issue Aug 7, 2020 · 3 comments · Fixed by #12795
Closed

TSAN DelayActivation/TimerImplTest.ChangeTimerForwardsToNonZeroBeforeRun/0 flake #12532

dio opened this issue Aug 7, 2020 · 3 comments · Fixed by #12795
Assignees
@antoniovicente
Labels
area/test flakes help wanted Needs help!

Comments

@dio
Copy link
Member

dio commented Aug 7, 2020 

[ RUN      ] DelayActivation/TimerImplTest.ChangeTimerForwardsToNonZeroBeforeRun/0
unknown file: Failure

Unexpected mock function call - returning directly.
    Function call: ready()
Google Mock tried the following 1 expectation, but it didn't match:

test/common/event/dispatcher_impl_test.cc:613: EXPECT_CALL(watcher2, ready())...
         Expected: all pre-requisites are satisfied
           Actual: the following immediate pre-requisites are not satisfied:
test/common/event/dispatcher_impl_test.cc:612: pre-requisite #0
                   (end of pre-requisites)
         Expected: to be called once
           Actual: never called - unsatisfied and active

exec ${PAGER:-/usr/bin/less} "$0" || exit 1
Executing tests from //test/common/event:dispatcher_impl_test
-----------------------------------------------------------------------------
[==========] Running 44 tests from 9 test suites.
[----------] Global test environment set-up.
[----------] 4 tests from SchedulableCallbackImplTest
[ RUN      ] SchedulableCallbackImplTest.ScheduleCurrentAndCancel
[       OK ] SchedulableCallbackImplTest.ScheduleCurrentAndCancel (1 ms)
[ RUN      ] SchedulableCallbackImplTest.ScheduleNextAndCancel
[       OK ] SchedulableCallbackImplTest.ScheduleNextAndCancel (1 ms)
[ RUN      ] SchedulableCallbackImplTest.ScheduleOrder
[       OK ] SchedulableCallbackImplTest.ScheduleOrder (1 ms)
[ RUN      ] SchedulableCallbackImplTest.ScheduleChainingAndCancellation
[       OK ] SchedulableCallbackImplTest.ScheduleChainingAndCancellation (2 ms)
[----------] 4 tests from SchedulableCallbackImplTest (5 ms total)

[----------] 1 test from DeferredDeleteTest
[ RUN      ] DeferredDeleteTest.DeferredDelete
[       OK ] DeferredDeleteTest.DeferredDelete (1 ms)
[----------] 1 test from DeferredDeleteTest (1 ms total)

[----------] 1 test from DeferredTaskTest
[ RUN      ] DeferredTaskTest.DeferredTask
[       OK ] DeferredTaskTest.DeferredTask (1 ms)
[----------] 1 test from DeferredTaskTest (1 ms total)

[----------] 6 tests from DispatcherImplTest
[ RUN      ] DispatcherImplTest.InitializeStats
[       OK ] DispatcherImplTest.InitializeStats (5 ms)
[ RUN      ] DispatcherImplTest.Post
[       OK ] DispatcherImplTest.Post (2 ms)
[ RUN      ] DispatcherImplTest.RunPostCallbacksLocking
[       OK ] DispatcherImplTest.RunPostCallbacksLocking (3 ms)
[ RUN      ] DispatcherImplTest.Timer
[       OK ] DispatcherImplTest.Timer (3 ms)
[ RUN      ] DispatcherImplTest.TimerWithScope
[       OK ] DispatcherImplTest.TimerWithScope (53 ms)
[ RUN      ] DispatcherImplTest.IsThreadSafe
[       OK ] DispatcherImplTest.IsThreadSafe (3 ms)
[----------] 6 tests from DispatcherImplTest (70 ms total)

[----------] 1 test from NotStartedDispatcherImplTest
[ RUN      ] NotStartedDispatcherImplTest.IsThreadSafe
[       OK ] NotStartedDispatcherImplTest.IsThreadSafe (0 ms)
[----------] 1 test from NotStartedDispatcherImplTest (1 ms total)

[----------] 2 tests from DispatcherMonotonicTimeTest
[ RUN      ] DispatcherMonotonicTimeTest.UpdateApproximateMonotonicTime
[       OK ] DispatcherMonotonicTimeTest.UpdateApproximateMonotonicTime (0 ms)
[ RUN      ] DispatcherMonotonicTimeTest.ApproximateMonotonicTime
[       OK ] DispatcherMonotonicTimeTest.ApproximateMonotonicTime (1 ms)
[----------] 2 tests from DispatcherMonotonicTimeTest (1 ms total)

[----------] 1 test from TimerImplTimingTest
[ RUN      ] TimerImplTimingTest.TheoreticalTimerTiming
TestRandomGenerator running with seed 67947800
[       OK ] TimerImplTimingTest.TheoreticalTimerTiming (32613 ms)
[----------] 1 test from TimerImplTimingTest (32613 ms total)

[----------] 2 tests from TimerUtilsTest
[ RUN      ] TimerUtilsTest.TimerNegativeValueThrows
[       OK ] TimerUtilsTest.TimerNegativeValueThrows (0 ms)
[ RUN      ] TimerUtilsTest.TimerValueConversion
[       OK ] TimerUtilsTest.TimerValueConversion (0 ms)
[----------] 2 tests from TimerUtilsTest (0 ms total)

[----------] 26 tests from DelayActivation/TimerImplTest
[ RUN      ] DelayActivation/TimerImplTest.TimerEnabledDisabled/0
[       OK ] DelayActivation/TimerImplTest.TimerEnabledDisabled/0 (11 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerEnabledDisabled/1
[       OK ] DelayActivation/TimerImplTest.TimerEnabledDisabled/1 (8 ms)
[ RUN      ] DelayActivation/TimerImplTest.ChangeTimerBackwardsBeforeRun/0
[       OK ] DelayActivation/TimerImplTest.ChangeTimerBackwardsBeforeRun/0 (14 ms)
[ RUN      ] DelayActivation/TimerImplTest.ChangeTimerBackwardsBeforeRun/1
[       OK ] DelayActivation/TimerImplTest.ChangeTimerBackwardsBeforeRun/1 (15 ms)
[ RUN      ] DelayActivation/TimerImplTest.ChangeTimerForwardsToZeroBeforeRun/0
[       OK ] DelayActivation/TimerImplTest.ChangeTimerForwardsToZeroBeforeRun/0 (15 ms)
[ RUN      ] DelayActivation/TimerImplTest.ChangeTimerForwardsToZeroBeforeRun/1
[       OK ] DelayActivation/TimerImplTest.ChangeTimerForwardsToZeroBeforeRun/1 (14 ms)
[ RUN      ] DelayActivation/TimerImplTest.ChangeTimerForwardsToNonZeroBeforeRun/0
unknown file: Failure

Unexpected mock function call - returning directly.
    Function call: ready()
Google Mock tried the following 1 expectation, but it didn't match:

test/common/event/dispatcher_impl_test.cc:613: EXPECT_CALL(watcher2, ready())...
         Expected: all pre-requisites are satisfied
           Actual: the following immediate pre-requisites are not satisfied:
test/common/event/dispatcher_impl_test.cc:612: pre-requisite #0
                   (end of pre-requisites)
         Expected: to be called once
           Actual: never called - unsatisfied and active
Stack trace:
  0x3d46b45: testing::internal::GoogleTestFailureReporter::ReportFailure()
  0x152d158: testing::internal::Expect()
  0x3d497cf: testing::internal::UntypedFunctionMockerBase::UntypedInvokeWith()
  0x1485ce8: testing::internal::FunctionMocker<>::Invoke()
  0x1485c68: Envoy::ReadyWatcher::ready()
  0x141ff7c: Envoy::Event::(anonymous namespace)::TimerImplTest_ChangeTimerForwardsToNonZeroBeforeRun_Test::TestBody()::$_35::operator()()
  0x141fed1: std::__1::__invoke<>()
  0x141fe31: std::__1::__invoke_void_return_wrapper<>::__call<>()
  0x141fdd1: std::__1::__function::__alloc_func<>::operator()()
  0x141e0a0: std::__1::__function::__func<>::operator()()
  0x1491777: std::__1::__function::__value_func<>::operator()()
  0x14916c9: std::__1::function<>::operator()()
  0x1cd6906: Envoy::Event::TimerImpl::TimerImpl()::$_0::operator()()
  0x1cd6867: Envoy::Event::TimerImpl::TimerImpl()::$_0::__invoke()
  0x3c13639: event_process_active_single_queue
  0x3c07ee8: event_process_active
  0x3c058a0: event_base_loop
  0x1cd2350: Envoy::Event::LibeventScheduler::run()
  0x1926002: Envoy::Event::DispatcherImpl::run()
  0x141ad04: Envoy::Event::(anonymous namespace)::TimerImplTest_ChangeTimerForwardsToNonZeroBeforeRun_Test::TestBody()
  0x3dbc11d: testing::internal::HandleSehExceptionsInMethodIfSupported<>()
  0x3d9ffbf: testing::internal::HandleExceptionsInMethodIfSupported<>()
  0x3d84c52: testing::Test::Run()
  0x3d85af4: testing::TestInfo::Run()
... Google Test internal frames ...

test/common/event/dispatcher_impl_test.cc:613: Failure
Actual function call count doesn't match EXPECT_CALL(watcher2, ready())...
         Expected: to be called once
           Actual: never called - unsatisfied and active
Stack trace:
  0x3d46b45: testing::internal::GoogleTestFailureReporter::ReportFailure()
  0x152d158: testing::internal::Expect()
  0x3d4a02d: testing::internal::UntypedFunctionMockerBase::VerifyAndClearExpectationsLocked()
  0x15c696b: testing::internal::FunctionMocker<>::~FunctionMocker()
  0x1cbe489: Envoy::ReadyWatcher::~ReadyWatcher()
  0x141ad2d: Envoy::Event::(anonymous namespace)::TimerImplTest_ChangeTimerForwardsToNonZeroBeforeRun_Test::TestBody()
  0x3dbc11d: testing::internal::HandleSehExceptionsInMethodIfSupported<>()
  0x3d9ffbf: testing::internal::HandleExceptionsInMethodIfSupported<>()
  0x3d84c52: testing::Test::Run()
  0x3d85af4: testing::TestInfo::Run()
... Google Test internal frames ...

[  FAILED  ] DelayActivation/TimerImplTest.ChangeTimerForwardsToNonZeroBeforeRun/0, where GetParam() = false (1239 ms)
[ RUN      ] DelayActivation/TimerImplTest.ChangeTimerForwardsToNonZeroBeforeRun/1
[       OK ] DelayActivation/TimerImplTest.ChangeTimerForwardsToNonZeroBeforeRun/1 (14 ms)
[ RUN      ] DelayActivation/TimerImplTest.ChangeLargeTimerForwardToZeroBeforeRun/0
[       OK ] DelayActivation/TimerImplTest.ChangeLargeTimerForwardToZeroBeforeRun/0 (8 ms)
[ RUN      ] DelayActivation/TimerImplTest.ChangeLargeTimerForwardToZeroBeforeRun/1
[       OK ] DelayActivation/TimerImplTest.ChangeLargeTimerForwardToZeroBeforeRun/1 (8 ms)
[ RUN      ] DelayActivation/TimerImplTest.ChangeLargeTimerForwardToNonZeroBeforeRun/0
[       OK ] DelayActivation/TimerImplTest.ChangeLargeTimerForwardToNonZeroBeforeRun/0 (15 ms)
[ RUN      ] DelayActivation/TimerImplTest.ChangeLargeTimerForwardToNonZeroBeforeRun/1
[       OK ] DelayActivation/TimerImplTest.ChangeLargeTimerForwardToNonZeroBeforeRun/1 (15 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerOrdering/0
[       OK ] DelayActivation/TimerImplTest.TimerOrdering/0 (15 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerOrdering/1
[       OK ] DelayActivation/TimerImplTest.TimerOrdering/1 (15 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerOrderAndDisableAlarm/0
[       OK ] DelayActivation/TimerImplTest.TimerOrderAndDisableAlarm/0 (16 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerOrderAndDisableAlarm/1
[       OK ] DelayActivation/TimerImplTest.TimerOrderAndDisableAlarm/1 (14 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerOrderDisableAndReschedule/0
[       OK ] DelayActivation/TimerImplTest.TimerOrderDisableAndReschedule/0 (27 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerOrderDisableAndReschedule/1
[       OK ] DelayActivation/TimerImplTest.TimerOrderDisableAndReschedule/1 (26 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerOrderAndReschedule/0
[       OK ] DelayActivation/TimerImplTest.TimerOrderAndReschedule/0 (22 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerOrderAndReschedule/1
[       OK ] DelayActivation/TimerImplTest.TimerOrderAndReschedule/1 (26 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerChaining/0
[       OK ] DelayActivation/TimerImplTest.TimerChaining/0 (11 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerChaining/1
[       OK ] DelayActivation/TimerImplTest.TimerChaining/1 (10 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerChainDisable/0
[       OK ] DelayActivation/TimerImplTest.TimerChainDisable/0 (12 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerChainDisable/1
[       OK ] DelayActivation/TimerImplTest.TimerChainDisable/1 (9 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerChainDelete/0
[       OK ] DelayActivation/TimerImplTest.TimerChainDelete/0 (10 ms)
[ RUN      ] DelayActivation/TimerImplTest.TimerChainDelete/1
[       OK ] DelayActivation/TimerImplTest.TimerChainDelete/1 (9 ms)
[----------] 26 tests from DelayActivation/TimerImplTest (1599 ms total)

[----------] Global test environment tear-down
[==========] 44 tests from 9 test suites ran. (34292 ms total)
[  PASSED  ] 43 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] DelayActivation/TimerImplTest.ChangeTimerForwardsToNonZeroBeforeRun/0, where GetParam() = false

 1 FAILED TEST
@mattklein123
Copy link
Member

cc @antoniovicente

@antoniovicente
Copy link
Contributor

/assign @antoniovicente

I can reproduce misc flakiness in TimerImplTest across multiple test cases. I don't understand the failures yet, but will try to get to the bottom of it as soon as I can.

@antoniovicente
Copy link
Contributor

I should add: this is not a TSAN issue. Flakiness happens outside TSAN. At least 4 different test cases are affected, ChangeTimerForwardsToZeroBeforeRun just happens to be the one that is most likely to flake. I don't fully understand the flakiness yet or how to mitigate it. It may make sense to disable some of these very picky and relatively unessential tests to avoid presubmit problems.

@lizan lizan mentioned this issue Aug 14, 2020
Merged
@antoniovicente antoniovicente mentioned this issue Aug 24, 2020
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@antoniovicente antoniovicente

Labels
area/test flakes help wanted Needs help!
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

[test] De-flake Timer tests antoniovicente/envoy
3 participants
@dio @mattklein123 @antoniovicente