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

Issue 831074 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Apr 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug

Blocking:
issue 829310



Sign in to add a comment

"ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0" is flaky

Project Member Reported by chromium...@appspot.gserviceaccount.com, Apr 10 2018

Issue description

"ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0" is flaky.

This issue was created automatically by the chromium-try-flakes app. Please find the right owner to fix the respective test/step and assign this issue to them. If the step/test is infrastructure-related, please add Infra-Troopers label and change issue status to Untriaged. When done, please remove the issue from Sheriff Bug Queue by removing the Sheriff-Chromium label.

We have detected 4 recent flakes. List of all flakes can be found at https://chromium-try-flakes.appspot.com/all_flake_occurrences?key=ahVzfmNocm9taXVtLXRyeS1mbGFrZXNyRgsSBUZsYWtlIjtFeGVjdXRlRGVmYXVsdFRhc2tPbkRvd25sb2Fkcy9GaWxlTWFuYWdlckJyb3dzZXJUZXN0LlRlc3QvMAw.

Flaky tests should be disabled within 30 minutes unless culprit CL is found and reverted. Please see more details here: https://sites.google.com/a/chromium.org/dev/developers/tree-sheriffs/sheriffing-bug-queues#triaging-auto-filed-flakiness-bugs

This flaky test/step was previously tracked in  issue 699171 .
 
Labels: OS-Chrome
[ RUN      ] ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0
[31113:31113:0409/083022.081232:WARNING:user_policy_manager_factory_chromeos.cc(188)] No policy loaded for known non-enterprise user
[31113:31113:0409/083022.089668:WARNING:user_session_manager.cc(1067)] Attempting to save user password for non enterprise user.
[31113:31113:0409/083022.185914:ERROR:network_type_pattern.cc(134)] NetworkTypePattern: wifi: Can not match empty type.
[31113:31113:0409/083022.186162:ERROR:network_type_pattern.cc(134)] NetworkTypePattern: wifi: Can not match empty type.
[31113:31113:0409/083022.186555:ERROR:network_type_pattern.cc(134)] NetworkTypePattern: wifi: Can not match empty type.
[31113:31113:0409/083022.186627:ERROR:network_type_pattern.cc(134)] NetworkTypePattern: wifi: Can not match empty type.
[31113:31113:0409/083022.753171:INFO:CONSOLE(4989)] "Requesting volume list.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (4989)
[31113:31113:0409/083022.780525:INFO:CONSOLE(1164)] "Cache database creating or upgrading.", source: chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/background_scripts.js (1164)
[31113:31113:0409/083022.789598:INFO:CONSOLE(4991)] "Volume list fetched with: 2 items.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (4991)
[31113:31113:0409/083022.790786:INFO:CONSOLE(5001)] "Initializing volume: downloads:.org.chromium.Chromium.V1cKQr", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5001)
[31113:31113:0409/083022.790932:INFO:CONSOLE(5404)] "Requesting file system.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5404)
[31113:31113:0409/083022.791282:INFO:CONSOLE(5001)] "Initializing volume: drive:drive-user", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5001)
[31113:31113:0409/083022.791418:INFO:CONSOLE(5404)] "Requesting file system.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5404)
[31113:31113:0409/083022.824634:FATAL:private_api_file_system.cc(810)] Check failed: external_backend->CanHandleType(file_system_url.type()). GURL: type: -1
#0 0x0000043c0a8c base::debug::StackTrace::StackTrace()
#1 0x0000043db9cb logging::LogMessage::~LogMessage()
#2 0x000001d094cf extensions::FileManagerPrivateInternalResolveIsolatedEntriesFunction::RunAsync()
#3 0x000006ae952f ChromeAsyncExtensionFunction::Run()
#4 0x00000321eb12 ExtensionFunction::RunWithValidation()
#5 0x00000322120b extensions::ExtensionFunctionDispatcher::DispatchWithCallbackInternal()
#6 0x000003220daf extensions::ExtensionFunctionDispatcher::Dispatch()
#7 0x0000032442aa extensions::ExtensionWebContentsObserver::OnRequest()
#8 0x000003244129 _ZN3IPC8MessageTI29ExtensionHostMsg_Request_MetaNSt3__15tupleIJ31ExtensionHostMsg_Request_ParamsEEEvE8DispatchIN10extensions28ExtensionWebContentsObserverES9_N7content15RenderFrameHostEMS9_FvPSB_RKS4_EEEbPKNS_7MessageEPT_PT0_PT1_T2_
#9 0x000003244072 extensions::ExtensionWebContentsObserver::OnMessageReceived()
#10 0x000006ae9f21 extensions::ChromeExtensionWebContentsObserver::OnMessageReceived()
#11 0x000002fa63b2 content::WebContentsImpl::OnMessageReceived()
#12 0x000002c8d2a4 content::RenderFrameHostImpl::OnMessageReceived()
#13 0x000002e75c4b content::RenderProcessHostImpl::OnMessageReceived()
#14 0x000005460241 IPC::ChannelProxy::Context::OnDispatchMessage()
#15 0x0000016e84cb _ZN4base8internal7InvokerINS0_9BindStateIMN13safe_browsing12_GLOBAL__N_125FakeSafeBrowsingUIManagerEFvRKNSt3__112basic_stringIcNS6_11char_traitsIcEENS6_9allocatorIcEEEEEJ13scoped_refptrIS5_ESC_EEEFvvEE7RunOnceEPNS0_13BindStateBaseE
#16 0x0000043c1325 base::debug::TaskAnnotator::RunTask()
#17 0x00000447a919 base::internal::IncomingTaskQueue::RunTask()
#18 0x0000043e3e2b base::MessageLoop::RunTask()
#19 0x0000043e41ba base::MessageLoop::DeferOrRunPendingTask()
#20 0x0000043e441c base::MessageLoop::DoWork()
#21 0x0000043e64d9 base::MessagePumpLibevent::Run()
#22 0x0000043e3759 base::MessageLoop::Run()
#23 0x00000440e489 base::RunLoop::Run()
#24 0x000004a37103 content::RunMessageLoop()
#25 0x000001485c18 file_manager::FileManagerBrowserTestBase::RunTestMessageLoop()
#26 0x000001485a9d file_manager::FileManagerBrowserTestBase::StartTest()
#27 0x000004a1306d content::BrowserTestBase::ProxyRunTestOnMainThreadLoop()
#28 0x00000451a1bf ChromeBrowserMainParts::PreMainMessageLoopRunImpl()
#29 0x000004518f5a ChromeBrowserMainParts::PreMainMessageLoopRun()
#30 0x000001a73571 chromeos::ChromeBrowserMainPartsChromeos::PreMainMessageLoopRun()
#31 0x000002b4d1c1 content::BrowserMainLoop::PreMainMessageLoopRun()
#32 0x000002f7ead5 content::StartupTaskRunner::RunAllTasksNow()
#33 0x000002b4bc42 content::BrowserMainLoop::CreateStartupTasks()
#34 0x000002b4fc83 content::BrowserMainRunnerImpl::Initialize()
#35 0x000002b49592 content::BrowserMain()
#36 0x000004376d4d content::ContentMainRunnerImpl::Run()
#37 0x00000647a622 service_manager::Main()
#38 0x0000043753c4 content::ContentMain()
#39 0x000004a12bfb content::BrowserTestBase::SetUp()
#40 0x0000044d23b0 InProcessBrowserTest::SetUp()
#41 0x000001eec2e1 testing::Test::Run()
#42 0x000001eecea0 testing::TestInfo::Run()
#43 0x000001eed387 testing::TestCase::Run()
#44 0x000001ef8877 testing::internal::UnitTestImpl::RunAllTests()
#45 0x000001ef83fe testing::UnitTest::Run()
#46 0x0000044e6c02 base::TestSuite::Run()
#47 0x0000043b4565 ChromeTestSuiteRunner::RunTestSuite()
#48 0x000004a338e7 content::LaunchTests()
#49 0x0000043b4a24 LaunchChromeTests()
#50 0x0000043b44fe main
#51 0x7fe207515f45 __libc_start_main
#52 0x0000005dde1a _start
[1018/1018] ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0 (CRASHED)
Labels: -Sheriff-Chromium
Owner: noel@chromium.org
Status: Assigned (was: Untriaged)

Comment 3 by noel@chromium.org, Apr 10 2018

Cc: yamaguchi@chromium.org fukino@chromium.org
Reading flakiness dashboard results for browser_tests (with patch)

https://test-results.appspot.com/dashboards/flakiness_dashboard.html#testType=browser_tests%20(with%20patch)&tests=ExecuteDefaultTaskOnDownloads%2FFileManagerBrowserTest.Test%2F0

Find the first black-box failure, labelled 7, click it to go to the build log:

http://build.chromium.org/p/tryserver.chromium.chromiumos/builders/linux-chromeos-rel/builds/97470

On that build log page, select the check box called "Non-Green Only" in the "Steps and Logfiles" section, shows ...

browser_tests (with patch) browser_tests (with patch)
Run on OS: 'Ubuntu-14.04'
Max pending time: 0:33:11.767580 (shard #7)
Max shard duration: 0:11:15.401550 (shard #3)
failures:
PagePasswordsAnalyserTest.ElementsWithDuplicateIds
PagePasswordsAnalyserTest.InferredUsernameAutocompleteAttributes
PagePasswordsAnalyserTest.PasswordFieldNotInForm
DefaultTaskDialog/FileManagerBrowserTest.Test/0
PagePasswordsAnalyserTest.PasswordFormTooComplex
PagePasswordsAnalyserTest.InferredPasswordAutocompleteAttributes
PagePasswordsAnalyserTest.PasswordFormWithoutUsernameField
PagePasswordsAnalyserTest.PasswordFieldWithAndWithoutAutocomplete
stdout

Huh? ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0 is not indicated as a failure in that list.  Is the flakiness dashboard wrong?

No it is not: click the 'stdout' link for browser_tests (with patch)
https://logs.chromium.org/v/?s=chromium%2Fbb%2Ftryserver.chromium.chromiumos%2Flinux-chromeos-rel%2F97470%2F%2B%2Frecipes%2Fsteps%2Fbrowser_tests__with_patch_%2F0%2Fstdout

Search for ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0 to see this test failing in _multiple_ ways.

Moral of this story: the flakiness dashboard is not wrong here, but it does require careful reading to work out what is going on.

ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0 fails in multiple ways, including the failure stack shown in #1  issue 804413 , which happens once only in the stdout log.  It would be pre-mature to dup this bug to  issue 804413 , given that that is not the only way this test fails.

Comment 4 by noel@chromium.org, Apr 10 2018

> We have detected 4 recent flakes. List of all flakes can be found at https://chromium-try-flakes.appspot.com/all_flake_occurrences?key=ahVzfmNocm9taXVtLXRyeS1mbGFrZXNyRgsSBUZsYWtlIjtFeGVjdXRlRGVmYXVsdFRhc2tPbkRvd25sb2Fkcy9GaWxlTWFuYWdlckJyb3dzZXJUZXN0LlRlc3QvMAw.

Milo provides build logs too, first log in the link above is for a try run at 2018-04-09 22:53:11 UTC.  Clicking it takes us to the build log.

https://ci.chromium.org/buildbot/tryserver.chromium.chromiumos/linux-chromeos-rel/96655

mus_browser_tests (with patch) mus_browser_tests (with patch)
Run on OS: 'Ubuntu-14.04'
Max pending time: 0:34:47.383750 (shard #0)
Max shard duration: 0:09:11.557850 (shard #2)
failures:
ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0
stdout

Again, click the 'stdout' link and search for ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0

Same result: ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0 fails in multiple ways, including the failure stack shown in #1  issue 804413 , which happens once only in this stdout log.

The most common mode of failure is:

ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0
[23078:23078:0409/183158.639464:WARNING:user_policy_manager_factory_chromeos.cc(188)] No policy loaded for known non-enterprise user
[23078:23078:0409/183158.667131:WARNING:user_session_manager.cc(1067)] Attempting to save user password for non enterprise user.
[23078:23078:0409/183159.067256:ERROR:network_type_pattern.cc(134)] NetworkTypePattern: wifi: Can not match empty type.
[23078:23078:0409/183159.067652:ERROR:network_type_pattern.cc(134)] NetworkTypePattern: wifi: Can not match empty type.
[23078:23078:0409/183159.068345:ERROR:network_type_pattern.cc(134)] NetworkTypePattern: wifi: Can not match empty type.
[23078:23078:0409/183159.068482:ERROR:network_type_pattern.cc(134)] NetworkTypePattern: wifi: Can not match empty type.
[23078:23078:0409/183200.509021:INFO:CONSOLE(4989)] "Requesting volume list.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (4989)
[23078:23078:0409/183200.659061:INFO:CONSOLE(4991)] "Volume list fetched with: 2 items.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (4991)
[23078:23078:0409/183200.659233:INFO:CONSOLE(5001)] "Initializing volume: downloads:.org.chromium.Chromium.JXKf6u", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5001)
[23078:23078:0409/183200.659379:INFO:CONSOLE(5404)] "Requesting file system.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5404)
[23078:23078:0409/183200.676432:INFO:CONSOLE(5001)] "Initializing volume: drive:drive-user", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5001)
[23078:23078:0409/183200.676652:INFO:CONSOLE(5404)] "Requesting file system.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5404)
[23078:23078:0409/183200.732883:INFO:CONSOLE(0)] "Unchecked runtime.lastError while running fileSystem.requestFileSystem: Volume not found.
    at chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/background_scripts.js:1539:27
    at chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/background_scripts.js:1538:28
    at ImageLoader.<anonymous> (chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/background_scripts.js:1537:43)", source: chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/_generated_background_page.html (0)
[23078:23078:0409/183200.733069:INFO:CONSOLE(1164)] "Cache database creating or upgrading.", source: chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/background_scripts.js (1164)
[23078:23078:0409/183200.750388:INFO:CONSOLE(1566)] "Failed to mount a file system: downloads:.org.chromium.Chromium.JXKf6u because of: Volume not found.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_scripts.js (1566)
[23078:23078:0409/183200.750757:INFO:CONSOLE(5005)] "Initialized volume: downloads:.org.chromium.Chromium.JXKf6u", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5005)
[23078:23078:0409/183200.924176:INFO:CONSOLE(5452)] "File system obtained: drive:drive-user", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5452)
[23078:23078:0409/183200.924861:INFO:CONSOLE(5005)] "Initialized volume: drive:drive-user", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5005)
[23078:23078:0409/183200.925133:INFO:CONSOLE(5009)] "Initialized all volumes.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5009)
[23078:23078:0409/183200.925415:INFO:CONSOLE(5404)] "Requesting file system.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5404)
[23078:23078:0409/183200.956972:INFO:CONSOLE(5452)] "File system obtained: downloads:Downloads", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5452)
[23078:23078:0409/183201.118470:INFO:CONSOLE(4321)] "Waiting for the result of openMainWindow", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (4321)
[1,207722368:01:32:01.185796] Native Client module will be loaded at base address 0x000062f900000000
[23078:23078:0409/183201.350442:INFO:CONSOLE(4318)] "Received the result of openMainWindow", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (4318)
[23078:23078:0409/183201.594890:INFO:CONSOLE(0)] "Styling master document from stylesheets defined in HTML Imports is deprecated. Please refer to https://goo.gl/EGXzpw for possible migration paths.", source:  (0)
[23078:23078:0409/183204.188664:INFO:CONSOLE(2493)] "Video thumbnail error: ", source: chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/background_scripts.js (2493)
[1,207722368:01:32:04.613267] Native Client module will be loaded at base address 0x00004c7300000000
[1,207722368:01:32:04.691441] Native Client module will be loaded at base address 0x00005fa500000000
[23078:23078:0409/183204.760413:INFO:CONSOLE(0)] "[FAIL] executeDefaultTaskOnDownloads: API Test Error in executeDefaultTaskOnDownloads: The error count is not 0.
Actual: 1
Expected: 0
Error
    at Object.handleRequest (extensions::binding:64:27)
    at Object.<anonymous> (extensions::binding:374:32)
    at Object.<anonymous> (extensions::test:243:18)
    at Object.handleRequest (extensions::binding:64:27)
    at Object.<anonymous> (extensions::binding:374:32)
    at chrome-extension://oobinhbdbiehknkpbpejbbpdbkdjmoco/test_util.js:36:17", source: chrome-extension://oobinhbdbiehknkpbpejbbpdbkdjmoco/_generated_background_page.html (0)
[23078:23078:0409/183204.761587:INFO:CONSOLE(0)] "Uncaught (in promise) chrome.test.failure", source: chrome-extension://oobinhbdbiehknkpbpejbbpdbkdjmoco/_generated_background_page.html (0)
../../chrome/browser/chromeos/file_manager/file_manager_browsertest_base.cc:600: Failure
Failed
Failed 1 of 1 tests
[23078:23078:0409/183204.852546:ERROR:frame_sink_provider_impl.cc(37)] No RenderWidgetHost exists with id 3 in process 6
[23078:23112:0409/183204.895727:WARNING:discardable_shared_memory_manager.cc(436)] Some MojoDiscardableSharedMemoryManagerImpls are still alive. They will be leaked.
[23078:23078:0409/183204.948019:WARNING:event_router.cc(421)] Not all file watchers are removed. This can happen when the Files app is open during shutdown.
[23078:24394:0409/183204.978945:WARNING:internal_linux.cc(64)] Failed to read /proc/23114/stat
[23078:23078:0409/183204.986292:WARNING:pref_notifier_impl.cc(23)] Pref observer found at shutdown.
[23078:23078:0409/183204.986327:WARNING:pref_notifier_impl.cc(23)] Pref observer found at shutdown.
[  FAILED  ] ExecuteDefaultTaskOnDownloads/FileManagerBrowserTest.Test/0, where GetParam() = (0, 0x9fe2e99 pointing to "executeDefaultTaskOnDownloads") (6736 ms)

I see lots of "Volume not found." errors.  It seems that when these early requests for volumes, initiated from background pages, receive this error, the test enters catastrophic failure mode.  It seems the browser process is trying to tell us that the volumes wanted are not ready?  

Later in the log we see:

23078:23078:0409/183200.733069:INFO:CONSOLE(1164)] "Cache database creating or upgrading.", source: chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/background_scripts.js (1164)
[23078:23078:0409/183200.750388:INFO:CONSOLE(1566)] "Failed to mount a file system: downloads:.org.chromium.Chromium.JXKf6u because of: Volume not found.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_scripts.js (1566)
[23078:23078:0409/183200.750757:INFO:CONSOLE(5005)] "Initialized volume: downloads:.org.chromium.Chromium.JXKf6u", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5005)
[23078:23078:0409/183200.924176:INFO:CONSOLE(5452)] "File system obtained: drive:drive-user", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5452)
[23078:23078:0409/183200.924861:INFO:CONSOLE(5005)] "Initialized volume: drive:drive-user", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5005)
[23078:23078:0409/183200.925133:INFO:CONSOLE(5009)] "Initialized all volumes.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5009)
[23078:23078:0409/183200.925415:INFO:CONSOLE(5404)] "Requesting file system.", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5404)
[23078:23078:0409/183200.956972:INFO:CONSOLE(5452)] "File system obtained: downloads:Downloads", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (5452)
[23078:23078:0409/183201.118470:INFO:CONSOLE(4321)] "Waiting for the result of openMainWindow", source: chrome-extension://hhaomjibdihmijegdhdafkllkbggdgoj/background/js/background_common_scripts.js (4321)

The volumes wanted appear in hhaomjibdihmijegdhdafkllkbggdgoj, they are "obtained" per the log, which seems to be what we want.  But this happens _after the "Volume not found" error_.  Perhaps that error is enough for the FilesApp test harness to decide that the entire test has FAILED. ¯\(ツ)/¯

Comment 5 by noel@chromium.org, Apr 11 2018

Cc: mtomasz@chromium.org
Components: Platform>Apps>FileManager
Labels: CrOSFilesCategory-Testing
Adding labels, adding mtomasz@ for any advice. 
Tests install some fake volumes and for some reason the volumes were set up after the volumes were tried to load. I'd add a log here to figure out which volume (id) is failing to load:
https://cs.chromium.org/chromium/src/chrome/browser/chromeos/extensions/file_manager/private_api_misc.cc?rcl=dee931eba042a6023229ec856c987f195956aacb&l=605

Then I'd add logs to the test setup where we insert test volumes:
https://cs.chromium.org/chromium/src/chrome/browser/chromeos/file_manager/file_manager_browsertest_base.cc?rcl=ccfe03413996bb808b9e25d4c494a089798b636f&l=507

Then check if the volume_ids match. If we fail to load a volume which is not a test volume, then that's weird. If we're failing to load a volume which is a test volume, then are we using the same volume manager? Or maybe there is some race between test cases?

Comment 7 by atotic@chromium.org, Apr 13 2018

I've just hit something similar today:

https://ci.chromium.org/buildbot/tryserver.chromium.chromiumos/linux-chromeos-rel/101570 

mus_browser_tests (with patch)
failed:
Transfer/FileManagerBrowserTest.Test/2

Looking at the last 200 linux-chromeos-rel builds, looks like 20 (10%!!!) have failed the same way, different flavors of file test failures.

Comment 8 by noel@chromium.org, Apr 16 2018

#7 atotic@ Thanks for the report, bear with us while we fix.

Comment 9 by noel@chromium.org, Apr 16 2018

#6 mtomasz@ adding the logging you suggested helped, thank you.  And you mentioned 

> "Or maybe there is some race between test cases?"

That is exactly the cause.  The traces show that the File Manager application is running (and goes looking for volumes via FSP, etc) early in a browser test.

Adding some logging to FileManagerBrowserTestBase setup methods and StartTest() shows that the running File Manager App went looking for volumes _well before_ SetUpOnMainThread() and StartTest() are called.

SetUpOnMainThread() creates the test Downloads volume, but there is a chance the running File Manager App won't see that volume ... because it has already looked for volumes and failed or crashed with:

 - URL cracking failures, per #1 aka  issue 804413 , 
 - or failures like #2

I was able to reproduce #1 and #2 locally using a DEBUG build, adding a 3 second delay to VolumeManager creation / registration (from an idea that yamaguchi-san@ noted in  https://crbug.com/804413#c37 )

void VolumeManager::Initialize() {
  ...

  // Register 'Downloads' folder for the profile to the file system.
  const base::FilePath downloads =
      file_manager::util::GetDownloadsFolderForProfile(profile_);

  +LOG(INFO) << this << " VolumeManager::Initialize sleep(3) ....";
  +sleep(3);
  +LOG(INFO) << this << " VolumeManager::Initialize sleep(3) done";

  const bool success = RegisterDownloadsMountPoint(profile_, downloads);
  DCHECK(success);

  ...
}

Adding even more logging to VolumeManger to show when the test Downloads folder is created, via VolumeManager::RegisterDownloadsDirectoryForTesting(), due to the creation request made for the test Downloads volume SetUpOnMainThread().

That logging shows that a Downloads already exists, and the code must swap it out and replace it with the test Downloads directory.  And all this while the test is running.  Little wonder then why most of the FileManagerBrowserTests suite flakes in MSAN/ASAN/DEBUG, and in many cases in RELEASE.

Comment 10 by noel@chromium.org, Apr 16 2018

One option for a fix is to make the various test extensions [used to drive the browser test and loaded in StartTest()], tell the extension under test (e.g., File Manager App) to close its background page via the RemoteCall JS interface.

The idea being that, as the test proceeds, the File Manager App under test would be recreated _after StartTest()_, and hence _after_ the test Downloads directory it should read from has been created.

Works not too bad for #2, but can still exhibit crashes like #1.  Not to worry, it gave me the seed idea for a better approach ... 

Comment 11 by noel@chromium.org, Apr 16 2018

I will start uploaded / landing some patches in preparation for a general fix.

Aside: another thing I noticed from trace logs in #4

[23078:23078:0409/183200.732883:INFO:CONSOLE(0)] "Unchecked runtime.lastError while running fileSystem.requestFileSystem: Volume not found.
    at chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/background_scripts.js:1539:27
    at chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/background_scripts.js:1538:28
    at ImageLoader.<anonymous> (chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/background_scripts.js:1537:43)", source: chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/_generated_background_page.html (0)

and 

[23078:23078:0409/183204.188664:INFO:CONSOLE(2493)] "Video thumbnail error: ", source: chrome-extension://pmfjbimdmchhbnneeidfognadeopoehp/background_scripts.js (2493)

I didn't know if they were relevant to this bug or not, when I first saw them.
  
Turns out that they are _irrelevant_ to this bug; they are just silly noise in our trace logs that distractingly hint about a possible error\, where there is fact none.

Would be nice to get rid of them, but that is not my focus ATM.  My focus is to remove the systemic flake failure cause in the FileManagerBrowserTests suite:

 "If you want to use a resource during testing, then ensuring that resource is
  ready, before the app under test starts and looks for it, and before testing
  even begins, is the well-known recipe for success".

Without that, systemic flakiness results.
Project Member

Comment 12 by bugdroid1@chromium.org, Apr 16 2018

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

commit 9d31e1caf65200790d00199728b193a1dcc11c42
Author: Noel Gordon <noel@chromium.org>
Date: Mon Apr 16 04:25:45 2018

Document integration tests sendTestMessage and add error checking

The integration test extensions send messages to the system under test
and also to the browser test harness (messages head in both directions
no matter how you depict the test system).

Add commentary to sendTestMessage to state where (or to whom) messages
are sent to. Explain the expected message format, add code to throw if
callers don't use that format (throw breaks browser tests).

Bug:  831074 
Cq-Include-Trybots: master.tryserver.chromium.linux:closure_compilation
Change-Id: Ia8085b3ebd28b7b001e7a5bfae4d883cdbd5660e
Reviewed-on: https://chromium-review.googlesource.com/1013359
Reviewed-by: Tomasz Mikolajewski <mtomasz@chromium.org>
Commit-Queue: Noel Gordon <noel@chromium.org>
Cr-Commit-Position: refs/heads/master@{#550932}
[modify] https://crrev.com/9d31e1caf65200790d00199728b193a1dcc11c42/ui/file_manager/integration_tests/test_util.js

Project Member

Comment 13 by bugdroid1@chromium.org, Apr 16 2018

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

commit 7aad60eb00959cf298c3078ac50da4d2a22b477c
Author: Noel Gordon <noel@chromium.org>
Date: Mon Apr 16 05:49:25 2018

Re-order key steps in FileManagerBrowserTestBase

One part of solving the issue at hand was to examine the call order of
the browser test setup routines. Moreover setup routines should prefer
CHECK (fail fast with a stack trace).

SetUpCommandLine happens just after SetUp: move them together, and put
them in call-order.

SetUpOnMainThread happens just before StartTest, so move them together
similarly. SetUpOnMainThread needs a Profile to work at all. Add CHECK
(to make that need somewhat clearer), and prefer CHECK in this routine
body in general (it's a setup routine).

StartTest is called right after SetUpOnMainThread: every test resource
needed for testing is (or should be) ready at that time. Add LOG(INFO)
here to show when StartTest is called, relative all other LOG tracing,
since any test-related output that appears before this point indicates
that "things have gone horribly wrong".

Bug:  831074 
Change-Id: I725413ad53592cb430ecf669e7ad2c50fdddead4
Reviewed-on: https://chromium-review.googlesource.com/1013838
Commit-Queue: Noel Gordon <noel@chromium.org>
Reviewed-by: Tomasz Mikolajewski <mtomasz@chromium.org>
Cr-Commit-Position: refs/heads/master@{#550937}
[modify] https://crrev.com/7aad60eb00959cf298c3078ac50da4d2a22b477c/chrome/browser/chromeos/file_manager/file_manager_browsertest_base.cc

Project Member

Comment 14 by bugdroid1@chromium.org, Apr 17 2018

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

commit a583f32687c0178446c4123bb238c2b1161ea6c7
Author: Noel Gordon <noel@chromium.org>
Date: Tue Apr 17 03:10:17 2018

Move FileManagerBrowserTestBase::SetUpInProcessBrowserTestFixture

In a FileManagerBrowserTest...SetUpInProcessBrowserTestFixture happens
after SetUpCommandLine and before SetUpOnMainThread. Move it there, so
its code location in this file is in call-order.

Bug:  831074 
Change-Id: I999a057c3163ebe13146a54c44d8ba3deb7e0d8c
Reviewed-on: https://chromium-review.googlesource.com/1013783
Reviewed-by: Tomasz Mikolajewski <mtomasz@chromium.org>
Reviewed-by: Tatsuhisa Yamaguchi <yamaguchi@chromium.org>
Commit-Queue: Noel Gordon <noel@chromium.org>
Cr-Commit-Position: refs/heads/master@{#551228}
[modify] https://crrev.com/a583f32687c0178446c4123bb238c2b1161ea6c7/chrome/browser/chromeos/file_manager/file_manager_browsertest_base.cc

Project Member

Comment 15 by bugdroid1@chromium.org, Apr 17 2018

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

commit ce92ada91522695758a70d18e960194e5f071895
Author: Noel Gordon <noel@chromium.org>
Date: Tue Apr 17 08:30:34 2018

Rid our system of persistent FileManagerBrowserTest flakiness

Postpone the creation of the FilesApp component extensions AudioPlayer
FileManager, Gallery, and VideoPlayer in browser testing. Not doing so
leads to systemic browser test failures (flakiness) per the bugs.

Fix: prepare test resources first, load the component extensions, then
start testing. Failure was the component extensions were active before
the file resources needed by the tests were ready, causing flake-fails
when the component extensions tried to access those resources.

Bug:  831074 ,  804413 ,  829310 
Cq-Include-Trybots: master.tryserver.chromium.linux:closure_compilation
Change-Id: Ie794bac638f48c3855e0c1f1609e59aa615c31dd
Reviewed-on: https://chromium-review.googlesource.com/1013823
Commit-Queue: Noel Gordon <noel@chromium.org>
Reviewed-by: Naoki Fukino <fukino@chromium.org>
Reviewed-by: Tomasz Mikolajewski <mtomasz@chromium.org>
Reviewed-by: Tatsuhisa Yamaguchi <yamaguchi@chromium.org>
Cr-Commit-Position: refs/heads/master@{#551279}
[modify] https://crrev.com/ce92ada91522695758a70d18e960194e5f071895/chrome/browser/chromeos/file_manager/file_manager_browsertest_base.cc

Comment 16 by noel@chromium.org, Apr 17 2018

Bots are much improved after #15.  Various clean-up opportunities in the browser test and in the file manager JS abound.  Filed  issue 833834  about it.

Comment 17 Deleted

Comment 18 by noel@chromium.org, Apr 17 2018

Was watching Delete/FileManagerBrowserTest.Test/1 for example, and it no longer flakes.  The browser test PASSES internally, but it sometimes hits an unrelated FATAL about frame sink providers.

That problem is already reported on  issue 829306 .

Comment 19 Deleted

Comment 20 Deleted

Comment 21 by noel@chromium.org, Apr 18 2018

Cc: atotic@chromium.org
#7 atotic@ noted the failure rate of Transfer/FileManagerBrowserTest.Test/2 was 10%.  Looking at that test on the flakiness dashboard after #15, its failure rate is about 0.

Comment 22 by noel@chromium.org, Apr 19 2018

Blocking: 829310

Comment 23 by noel@chromium.org, Apr 19 2018

Cc: vasi...@chromium.org
Checked #18, #21 again, looking good.  

+vasilii@ thank you for making a one-bug, one-issue report (c.f.  issue 804413  as counter example).

Also +mtomasz, fukino-san, and yamaguchi-san: thanks for the pro-top guidance throughout.

Comment 24 by noel@chromium.org, Apr 19 2018

Status: Fixed (was: Assigned)

Comment 25 by noel@chromium.org, Apr 19 2018

_pro-top_ -> pro-tip of course, but whatevs, we're done here and the FilesApp folks can now move forward with test enabled.  

Next phase would be re-enable disabled tests in RELEASE, and then eventually in DEEUG/MSAN/ASAN too.  All that will be the subject of new bugs.

Sign in to add a comment