New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 910493 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Last visit > 30 days ago
Closed: Dec 6
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug
Flaky-Test: WallpaperControllerTest.AddFirstWallpaperAnimationEndCallback



Sign in to add a comment

WallpaperControllerTest.AddFirstWallpaperAnimationEndCallback is flaky

Project Member Reported by Findit, Nov 30

Issue description


Flaky test: WallpaperControllerTest.AddFirstWallpaperAnimationEndCallback
Sample failed build due to flakiness: https://ci.chromium.org/buildbot/chromium.memory/Linux%20Chromium%20OS%20ASan%20LSan%20Tests%20%281%29/30347
Test output log: https://chromium-swarm.appspot.com/task?id=417c55000efd5b10
Culprit (70.0% confidence): r611895
Analysis: https://findit-for-me.appspot.com/waterfall/flake?key=ag9zfmZpbmRpdC1mb3ItbWVy1QELEhdNYXN0ZXJGbGFrZUFuYWx5c2lzUm9vdCKeAWNocm9taXVtLm1lbW9yeS9MaW51eCBDaHJvbWl1bSBPUyBBU2FuIExTYW4gVGVzdHMgKDEpLzMwMzQ3L2FzaF91bml0dGVzdHMvVjJGc2JIQmhjR1Z5UTI5dWRISnZiR3hsY2xSbGMzUXVRV1JrUm1seWMzUlhZV3hzY0dGd1pYSkJibWx0WVhScGIyNUZibVJEWVd4c1ltRmphdz09DAsSE01hc3RlckZsYWtlQW5hbHlzaXMYAQw

Please revert the culprit, or disable the test and find the appropriate owner.

If the culprit above is wrong, please file a bug using this link:
https://bugs.chromium.org/p/chromium/issues/entry?status=Unconfirmed&labels=Pri-1,Test-Findit-Wrong&components=Tools%3ETest%3EFindit%3EFlakiness&summary=%5BFindit%5D%20Flake%20Analyzer%20-%20Wrong%20result%20for%20WallpaperControllerTest.AddFirstWallpaperAnimationEndCallback&comment=Link%20to%20Analysis%3A%20https://findit-for-me.appspot.com/waterfall/flake?key=ag9zfmZpbmRpdC1mb3ItbWVy1QELEhdNYXN0ZXJGbGFrZUFuYWx5c2lzUm9vdCKeAWNocm9taXVtLm1lbW9yeS9MaW51eCBDaHJvbWl1bSBPUyBBU2FuIExTYW4gVGVzdHMgKDEpLzMwMzQ3L2FzaF91bml0dGVzdHMvVjJGc2JIQmhjR1Z5UTI5dWRISnZiR3hsY2xSbGMzUXVRV1JrUm1seWMzUlhZV3hzY0dGd1pYSkJibWx0WVhScGIyNUZibVJEWVd4c1ltRmphdz09DAsSE01hc3RlckZsYWtlQW5hbHlzaXMYAQw

Automatically posted by the findit-for-me app (https://goo.gl/Ot9f7N).
 
Components: UI>Shell>StartScreen
Labels: OS-Chrome
Owner: wzang@chromium.org
Status: Assigned (was: Untriaged)
This test has a very high flake rate: https://test-results.appspot.com/dashboards/flakiness_dashboard.html#testType=ash_unittests&tests=WallpaperControllerTest.AddFirstWallpaperAnimationEndCallback

Failures look like this:

[ RUN      ] WallpaperControllerTest.AddFirstWallpaperAnimationEndCallback
../../ash/wallpaper/wallpaper_controller_unittest.cc:2340: Failure
Value of: is_first_callback_run
  Actual: true
Expected: false
Stack trace:
#0 0x560c6783a960 StackTraceGetter::CurrentStackTrace()
#1 0x560c6785fee7 testing::internal::UnitTestImpl::CurrentOsStackTraceExceptTop()
#2 0x560c6785f343 testing::internal::AssertHelper::operator=()
#3 0x560c6725305f ash::WallpaperControllerTest_AddFirstWallpaperAnimationEndCallback_Test::TestBody()
#4 0x560c6789e0ce testing::internal::HandleSehExceptionsInMethodIfSupported<>()

../../ash/wallpaper/wallpaper_controller_unittest.cc:2341: Failure
Value of: is_second_callback_run
  Actual: true
Expected: false
Stack trace:
#0 0x560c6783a960 StackTraceGetter::CurrentStackTrace()
#1 0x560c6785fee7 testing::internal::UnitTestImpl::CurrentOsStackTraceExceptTop()
#2 0x560c6785f343 testing::internal::AssertHelper::operator=()
#3 0x560c6725325d ash::WallpaperControllerTest_AddFirstWallpaperAnimationEndCallback_Test::TestBody()
#4 0x560c6789e0ce testing::internal::HandleSehExceptionsInMethodIfSupported<>()

../../ash/wallpaper/wallpaper_controller_unittest.cc:344: Failure
Value of: controller->GetAnimatingWidget()
  Actual: false
Expected: true
Stack trace:
#0 0x560c6783a960 StackTraceGetter::CurrentStackTrace()
#1 0x560c6785fee7 testing::internal::UnitTestImpl::CurrentOsStackTraceExceptTop()
#2 0x560c6785f343 testing::internal::AssertHelper::operator=()
#3 0x560c6725d1a9 ash::WallpaperControllerTest::RunDesktopControllerAnimation()
#4 0x560c67253299 ash::WallpaperControllerTest_AddFirstWallpaperAnimationEndCallback_Test::TestBody()
#5 0x560c6789e0ce testing::internal::HandleSehExceptionsInMethodIfSupported<>()

[  FAILED  ] WallpaperControllerTest.AddFirstWallpaperAnimationEndCallback (601 ms)
Project Member

Comment 2 by bugdroid1@chromium.org, Nov 30

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/63a52964a0c2430365bc522467bdee39eb86df2a

commit 63a52964a0c2430365bc522467bdee39eb86df2a
Author: Greg Thompson <grt@chromium.org>
Date: Fri Nov 30 09:43:04 2018

Disable WallpaperControllerTest.AddFirstWallpaperAnimationEndCallback due to flakes.

BUG= 910493 
TBR=wzang@chromium.org

Change-Id: Iba2c449b0db5842bd4d77c020bedc38b94f83415
Reviewed-on: https://chromium-review.googlesource.com/c/1356579
Commit-Queue: Greg Thompson <grt@chromium.org>
Reviewed-by: Greg Thompson <grt@chromium.org>
Cr-Commit-Position: refs/heads/master@{#612600}
[modify] https://crrev.com/63a52964a0c2430365bc522467bdee39eb86df2a/ash/wallpaper/wallpaper_controller_unittest.cc

Labels: -Sheriff-Chromium
Removing Sheriff-Chromium since the test has been disabled and the bug has an owner.
Cc: fdoray@chromium.org alexclarke@chromium.org grt@chromium.org
The original bug says:
Culprit (70.0% confidence): r611895

Can't we check if the culprit CL needs a fix, instead of disabling the test? Unfortunately this particular test is very important for Chrome OS. Chromebooks will NOT show the login screen if the logic the test is verifying is broken, given the dependency between login screen and wallpaper.

alexclarke@, could you suggest if the wallpaper test needs any changes to accommodate your change? Otherwise can I revert your CL first? I'll wait until EOD of next Monday before the revert. Thanks!


Ah, my apologies for missing the analyzer's details. r611895 does look quite suspect.
Might be unrelated but ASAN spotted a stack-use-after-scope for this and quite a few other tests:

[==========] Running 1 test from 1 test case.
[----------] Global test environment set-up.
[----------] 1 test from WallpaperControllerTest
[ RUN      ] WallpaperControllerTest.AddFirstWallpaperAnimationEndCallback
=================================================================
==258935==ERROR: AddressSanitizer: stack-use-after-scope on address 0x7f938e2b7620 at pc 0x7f93eef51c3f bp 0x7ffde31c0280 sp 0x7ffde31c0278
READ of size 4 at 0x7f938e2b7620 thread T0
    #0 0x7f93eef51c3e in gfx::Point::x() const ui/gfx/geometry/point.h:48:36
    #1 0x7f93ef45ca36 in ash::ScreenPositionController::ConvertHostPointToRelativeToRootWindow(aura::Window*, std::__1::vector<aura::Window*, std::__1::allocator<aura::Window*> > const&, gfx::Point*, aura::Window**) ash/display/screen_position_controller.cc:60:43
    #2 0x7f93ef45d8c9 in ash::ScreenPositionController::ConvertHostPointToScreen(aura::Window*, gfx::Point*) ash/display/screen_position_controller.cc:108:3
    #3 0x7f93ef55a02c in ash::AshWindowTreeHost::TranslateLocatedEvent(ui::LocatedEvent*) ash/host/ash_window_tree_host.cc:57:29
    #4 0x7f93ef56349b in ash::AshWindowTreeHostPlatform::DispatchEventFromQueue(ui::Event*) ash/host/ash_window_tree_host_platform.cc:207:5
    #5 0x7f93c4305b31 in ws::HostEventQueue::DispatchEventDontQueue(ui::Event*, bool) services/ws/host_event_queue.cc:39:29
    #6 0x7f93c4305955 in ws::HostEventQueue::DispatchOrQueueEvent(ui::Event*, bool) services/ws/host_event_queue.cc:33:5
    #7 0x7f93ef563018 in ash::AshWindowTreeHostPlatform::DispatchEvent(ui::Event*) ash/host/ash_window_tree_host_platform.cc:185:22
    #8 0x7f93ca425488 in void base::internal::FunctorTraits<void (ui::PlatformWindowDelegate::*)(ui::Event*), void>::Invoke<void (ui::PlatformWindowDelegate::*)(ui::Event*), ui::PlatformWindowDelegate*, ui::Event*>(void (ui::PlatformWindowDelegate::*)(ui::Event*), ui::PlatformWindowDelegate*&&, ui::Event*&&) base/bind_internal.h:516:12
    #9 0x7f93ca42515d in void base::internal::InvokeHelper<false, void>::MakeItSo<void (ui::PlatformWindowDelegate::*)(ui::Event*), ui::PlatformWindowDelegate*, ui::Event*>(void (ui::PlatformWindowDelegate::*&&)(ui::Event*), ui::PlatformWindowDelegate*&&, ui::Event*&&) base/bind_internal.h:616:12
    #10 0x7f93ca424f02 in void base::internal::Invoker<base::internal::BindState<void (ui::PlatformWindowDelegate::*)(ui::Event*), base::internal::UnretainedWrapper<ui::PlatformWindowDelegate> >, void (ui::Event*)>::RunImpl<void (ui::PlatformWindowDelegate::*)(ui::Event*), std::__1::tuple<base::internal::UnretainedWrapper<ui::PlatformWindowDelegate> >, 0ul>(void (ui::PlatformWindowDelegate::*&&)(ui::Event*), std::__1::tuple<base::internal::UnretainedWrapper<ui::PlatformWindowDelegate> >&&, std::__1::integer_sequence<unsigned long, 0ul>, ui::Event*&&) base/bind_internal.h:689:12
    #11 0x7f93ca424c8f in base::internal::Invoker<base::internal::BindState<void (ui::PlatformWindowDelegate::*)(ui::Event*), base::internal::UnretainedWrapper<ui::PlatformWindowDelegate> >, void (ui::Event*)>::RunOnce(base::internal::BindStateBase*, ui::Event*) base/bind_internal.h:658:12
    #12 0x7f93d91b59c1 in base::OnceCallback<void (ui::Event*)>::Run(ui::Event*) && base/callback.h:99:12
    #13 0x7f93d91b5431 in ui::DispatchEventFromNativeUiEvent(ui::Event* const&, base::OnceCallback<void (ui::Event*)>) ui/events/ozone/events_ozone.cc:26:25
    #14 0x7f93ca6aa52a in ui::X11WindowOzone::DispatchEvent(ui::Event* const&) ui/ozone/platform/x11/x11_window_ozone.cc:81:5
    #15 0x7f93d153e334 in ui::PlatformEventSource::DispatchEvent(ui::Event*) ui/events/platform/platform_event_source.cc:91:29
    #16 0x7f9399d662f9 in ui::X11EventSourceLibevent::DispatchPlatformEvent(ui::Event* const&, _XEvent*) ui/events/platform/x11/x11_event_source_libevent.cc:222:3
    #17 0x7f9399d62578 in ui::X11EventSourceLibevent::ProcessXEvent(_XEvent*) ui/events/platform/x11/x11_event_source_libevent.cc:189:5
    #18 0x7f9399d31159 in ui::X11EventSource::ExtractCookieDataDispatchEvent(_XEvent*) ui/events/platform/x11/x11_event_source.cc:248:14
    #19 0x7f9399d30f4b in ui::X11EventSource::DispatchXEvents() ui/events/platform/x11/x11_event_source.cc:141:5
    #20 0x7f9399d668ae in ui::X11EventSourceLibevent::OnFileCanReadWithoutBlocking(int) ui/events/platform/x11/x11_event_source_libevent.cc:246:17
    #21 0x7f93e89a3c88 in base::MessagePumpLibevent::FdWatchController::OnFileCanReadWithoutBlocking(int, base::MessagePumpLibevent*) base/message_loop/message_pump_libevent.cc:90:13
    #22 0x7f93e89a8007 in base::MessagePumpLibevent::OnLibeventNotification(int, short, void*) base/message_loop/message_pump_libevent.cc:329:17
    #23 0x7f93e8a0a7ea in event_process_active base/third_party/libevent/event.c:381:4
    #24 0x7f93e8a08364 in event_base_loop base/third_party/libevent/event.c:521:4
    #25 0x7f93e89a8593 in base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) base/message_loop/message_pump_libevent.cc:214:5
    #26 0x7f93e84c5d7c in base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::Run(bool) base/task/sequence_manager/thread_controller_with_message_pump_impl.cc:340:12
    #27 0x7f93e827951f in base::RunLoop::Run() base/run_loop.cc:102:14
    #28 0x7f93e827ba19 in base::RunLoop::RunUntilIdle() base/run_loop.cc:115:3
    #29 0x55b090436ffe in ash::(anonymous namespace)::RunAllTasksUntilIdle() ash/wallpaper/wallpaper_controller_unittest.cc:215:21
    #30 0x55b09048bd3f in ash::WallpaperControllerTest_AddFirstWallpaperAnimationEndCallback_Test::TestBody() ash/wallpaper/wallpaper_controller_unittest.cc:2328:3
    #31 0x55b091656fa0 in void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) third_party/googletest/src/googletest/src/gtest.cc:2447:10
    #32 0x55b091627766 in void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) third_party/googletest/src/googletest/src/gtest.cc:2502:12
    #33 0x55b0915dcf3c in testing::Test::Run() third_party/googletest/src/googletest/src/gtest.cc:2522:5
    #34 0x55b0915debff in testing::TestInfo::Run() third_party/googletest/src/googletest/src/gtest.cc:2703:11
    #35 0x55b0915e124a in testing::TestCase::Run() third_party/googletest/src/googletest/src/gtest.cc:2825:28
    #36 0x55b09160a75c in testing::internal::UnitTestImpl::RunAllTests() third_party/googletest/src/googletest/src/gtest.cc:5227:43
    #37 0x55b0916621cb in bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) third_party/googletest/src/googletest/src/gtest.cc:2447:10
    #38 0x55b09162cbf6 in bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) third_party/googletest/src/googletest/src/gtest.cc:2502:12
    #39 0x55b091609b36 in testing::UnitTest::Run() third_party/googletest/src/googletest/src/gtest.cc:4835:10
    #40 0x55b0951f7a90 in RUN_ALL_TESTS() third_party/googletest/src/googletest/include/gtest/gtest.h:2369:46
    #41 0x55b0951f0090 in base::TestSuite::Run() base/test/test_suite.cc:294:16
    #42 0x55b0903cc356 in int base::internal::FunctorTraits<int (base::TestSuite::*)(), void>::Invoke<int (base::TestSuite::*)(), ash::AshTestSuite*>(int (base::TestSuite::*)(), ash::AshTestSuite*&&) base/bind_internal.h:516:12
    #43 0x55b0903cc072 in int base::internal::InvokeHelper<false, int>::MakeItSo<int (base::TestSuite::* const&)(), ash::AshTestSuite*>(int (base::TestSuite::* const&)(), ash::AshTestSuite*&&) base/bind_internal.h:616:12
    #44 0x55b0903cbe41 in int base::internal::Invoker<base::internal::BindState<int (base::TestSuite::*)(), base::internal::UnretainedWrapper<ash::AshTestSuite> >, int ()>::RunImpl<int (base::TestSuite::* const&)(), std::__1::tuple<base::internal::UnretainedWrapper<ash::AshTestSuite> > const&, 0ul>(int (base::TestSuite::* const&)(), std::__1::tuple<base::internal::UnretainedWrapper<ash::AshTestSuite> > const&, std::__1::integer_sequence<unsigned long, 0ul>) base/bind_internal.h:689:12
    #45 0x55b0903cbc3b in base::internal::Invoker<base::internal::BindState<int (base::TestSuite::*)(), base::internal::UnretainedWrapper<ash::AshTestSuite> >, int ()>::Run(base::internal::BindStateBase*) base/bind_internal.h:671:12
    #46 0x55b09153eeae in base::OnceCallback<int ()>::Run() && base/callback.h:99:12
    #47 0x55b095207f0e in base::(anonymous namespace)::LaunchUnitTestsInternal(base::OnceCallback<int ()>, unsigned long, int, bool, base::OnceCallback<void ()>) base/test/launcher/unit_test_launcher.cc:225:38
    #48 0x55b09520798c in base::LaunchUnitTests(int, char**, base::OnceCallback<int ()>) base/test/launcher/unit_test_launcher.cc:575:10
    #49 0x55b0903cb21d in main ash/test/ash_unittests.cc:37:10
    #50 0x7f939f8aa2b0 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x202b0)

Address 0x7f938e2b7620 is located in stack of thread T0 at offset 544 in frame
    #0 0x7f93ef45c13f in ash::ScreenPositionController::ConvertHostPointToRelativeToRootWindow(aura::Window*, std::__1::vector<aura::Window*, std::__1::allocator<aura::Window*> > const&, gfx::Point*, aura::Window**) ash/display/screen_position_controller.cc:27

  This frame has 8 object(s):
    [32, 33) 'ref.tmp' (line 28)
    [48, 344) 'ref.tmp1' (line 28)
    [416, 424) 'point_in_root' (line 29)
    [448, 464) 'host_bounds' (line 32)
    [480, 496) 'ref.tmp13' (line 32)
    [512, 520) 'location_in_native' (line 54)
    [544, 560) 'ref.tmp20' (line 59) <== Memory access at offset 544 is inside this variable
    [576, 592) 'native_bounds' (line 64)
HINT: this may be a false positive if your program uses some custom stack unwind mechanism, swapcontext or vfork
      (longjmp and C++ exceptions *are* supported)

The ASAN issue seems unrelated (although that is a bug), I was able to reproduce this locally.
This test is flaky because it doesn't use mock time.  It assumes the time between issuing ShowDefaultWallpaperForTesting and RunAllTasksUntilIdle exiting is short enough.  It usually is but from instrumenting LayerAnimationElement::IsFinished I can see the deadline is only 0.005s away.

This seems to be all driven by vis::DelayBasedTimeSourceClient which uses base::TimeTicks::Now() 
which just is going to flake on slow bots.  The SequenceManager likely made this test flake more often because in debug mode it has a bunch of slow legacy sanity checking for various internals which adjusted timing enough to make this test fail more often.

Recommendations:

1. Consider using a ScopedTaskEnvironemnt with mock time.  I note this test suite uses a TestBrowserThreadBundle, I have a patch (https://chromium-review.googlesource.com/c/chromium/src/+/1352260) which will make it easier to use these together but this shouldn't be a prerequisite. Just create a ScopedTaskEnvironemnt with mock time first.
2. Consider using FakeDelayBasedTimeSourceClient and hook it up to the ScopedTaskEnvironemnt's clock
Project Member

Comment 9 by bugdroid1@chromium.org, Dec 4

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/de5b08ad02e9cf6d08910880b3c9e0d071095fd3

commit de5b08ad02e9cf6d08910880b3c9e0d071095fd3
Author: Wenzhao (Colin) Zang <wzang@chromium.org>
Date: Tue Dec 04 18:14:31 2018

Revert "Disable WallpaperControllerTest.AddFirstWallpaperAnimationEndCallback due to flakes."

This reverts commit 63a52964a0c2430365bc522467bdee39eb86df2a.

Reason for revert: The original culprit CL in  crbug.com/910493  is reverted.

Original change's description:
> Disable WallpaperControllerTest.AddFirstWallpaperAnimationEndCallback due to flakes.
> 
> BUG= 910493 
> TBR=wzang@chromium.org
> 
> Change-Id: Iba2c449b0db5842bd4d77c020bedc38b94f83415
> Reviewed-on: https://chromium-review.googlesource.com/c/1356579
> Commit-Queue: Greg Thompson <grt@chromium.org>
> Reviewed-by: Greg Thompson <grt@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#612600}

TBR=grt@chromium.org,wzang@chromium.org

# Not skipping CQ checks because original CL landed > 1 day ago.

Bug:  910493 
Change-Id: I252e1d8e302ad31d122ee5edaf28e121a73a264b
Reviewed-on: https://chromium-review.googlesource.com/c/1361444
Reviewed-by: Wenzhao (Colin) Zang <wzang@chromium.org>
Commit-Queue: Wenzhao (Colin) Zang <wzang@chromium.org>
Cr-Commit-Position: refs/heads/master@{#613602}
[modify] https://crrev.com/de5b08ad02e9cf6d08910880b3c9e0d071095fd3/ash/wallpaper/wallpaper_controller_unittest.cc

Re-enabled the test because the CL in #0 was reverted.
Project Member

Comment 11 by bugdroid1@chromium.org, Dec 6

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/82b82a8b8c4115741888bb0dfe3fcd439cff51e5

commit 82b82a8b8c4115741888bb0dfe3fcd439cff51e5
Author: Alex Clarke <alexclarke@chromium.org>
Date: Thu Dec 06 12:18:48 2018

Deflake AddFirstWallpaperAnimationEndCallback test

This test is currently flaky because it relies upon the ordering
of delayed and non delayed tasks to quit a run loop before the
very short (0.01s) animation delay is up. This patch deflakes it by
temporarily freezing time to prevent the animation from
completing before the test expects it to.

TBR=wzang@chromium.org

Bug: 863341, 891670,  910493 
Change-Id: I34cf2824c387c380134eb38b3375e6ab79de4be8
Reviewed-on: https://chromium-review.googlesource.com/c/1365244
Commit-Queue: Alex Clarke <alexclarke@chromium.org>
Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
Cr-Commit-Position: refs/heads/master@{#614322}
[modify] https://crrev.com/82b82a8b8c4115741888bb0dfe3fcd439cff51e5/ash/wallpaper/wallpaper_controller_unittest.cc

Cc: -alexclarke@chromium.org wzang@chromium.org
Owner: alexclarke@chromium.org
Thanks for the fix.
Status: Fixed (was: Assigned)

Sign in to add a comment