Shuhei: can you please take a look at this bug

The first one I looked at was a Chrome crash in ui.MashLogin:

2018/11/28 08:09:59 Running ui.MashLogin
2018/11/28 08:09:59 Restarting ui job
2018/11/28 08:10:02 Waiting for org.chromium.SessionManager D-Bus service
2018/11/28 08:10:02 Asking session_manager to enable Chrome testing
2018/11/28 08:10:02 Waiting for Chrome to write its debugging port to /home/chronos/DevToolsActivePort
2018/11/28 08:10:07 Removing cryptohome for testuser@gmail.com
2018/11/28 08:10:07 Finding OOBE DevTools target
2018/11/28 08:10:07 Connecting to Chrome at ws://127.0.0.1:38541/devtools/page/3C8A70AE357C6A932D10F5034E8EA3C7
2018/11/28 08:10:08 Error: [mash_login.go:26] Chrome login failed: cdp.Runtime: Enable: websocket: close 1006 (abnormal closure): unexpected EOF

[ash:4487:4487:1128/081005.675403:FATAL:weak_ptr.cc(28)] Check failed: (sequence_checker_).CalledOnValidSequence(). WeakPtrs must be checked on the same sequenced thread.
#0 0x579bab3f10bf base::debug::StackTrace::StackTrace()
#1 0x579bab34610b logging::LogMessage::~LogMessage()
#2 0x579bab34c634 base::internal::WeakReference::IsValid()
#3 0x579ba7fe1443 _ZN4base8internal7InvokerINS0_9BindStateIMN2ui12_GLOBAL__N_116OzonePlatformGbmEFvN4mojo16InterfaceRequestINS3_5ozone5mojom12DeviceCursorEEEEJNS_7WeakPtrIS5_EEEEEFvSB_EE3RunEPNS0_13BindStateBaseEOSB_
#4 0x579ba7fe1237 _ZN15service_manager14CallbackBinderIN2ui5ozone5mojom12DeviceCursorEJEE11RunCallbackERKN4base17RepeatingCallbackIFvN4mojo16InterfaceRequestIS4_EEEEESA_
#5 0x579ba7fe12b5 _ZN4base8internal7InvokerINS0_9BindStateIPFvRKNS_17RepeatingCallbackIFvN4mojo16InterfaceRequestIN2ui5ozone5mojom12DeviceCursorEEEEEESA_EJSC_SA_EEEFvvEE7RunOnceEPNS0_13BindStateBaseE
#6 0x579bab4169d7 base::debug::TaskAnnotator::RunTask()
#7 0x579bab34fddf base::MessageLoopImpl::RunTask()
#8 0x579bab350492 base::MessageLoopImpl::DoWork()
#9 0x579bab4125a9 base::MessagePumpLibevent::Run()
#10 0x579bab34f8b5 base::MessageLoopImpl::Run()
#11 0x579bab37a026 base::RunLoop::Run()
#12 0x579baac81587 content::UtilityMain()
#13 0x579baae7d489 content::ContentMainRunnerImpl::Run()
#14 0x579baae8519a service_manager::Main()
#15 0x579baae7b7a1 content::ContentMain()
#16 0x579ba73b473f ChromeMain
#17 0x7a17059bc736 __libc_start_main
#18 0x579ba73b4569 _start

https://ci.chromium.org/p/chromium/builders/luci.chromium.try/chromeos-amd64-generic-rel/140062

2018/11/27 19:04:18 Running ui.MashLogin
2018/11/27 19:04:18 Restarting ui job
2018/11/27 19:04:21 Waiting for org.chromium.SessionManager D-Bus service
2018/11/27 19:04:21 Asking session_manager to enable Chrome testing
2018/11/27 19:04:21 Waiting for Chrome to write its debugging port to /home/chronos/DevToolsActivePort
2018/11/27 19:04:25 Removing cryptohome for testuser@gmail.com
2018/11/27 19:04:25 Finding OOBE DevTools target
2018/11/27 19:04:25 Connecting to Chrome at ws://127.0.0.1:43861/devtools/page/E76BB78E4C484D80BFF35442A003C84C
2018/11/27 19:04:26 Error: [mash_login.go:26] Chrome login failed: cdp.Runtime: Enable: websocket: close 1006 (abnormal closure): unexpected EOF

[ash:4517:4523:1127/190424.189033:FATAL:weak_ptr.cc(28)] Check failed: (sequence_checker_).CalledOnValidSequence(). WeakPtrs must be checked on the same sequenced thread.
#0 0x5882b15d699f base::debug::StackTrace::StackTrace()
#1 0x5882b152bbfb logging::LogMessage::~LogMessage()
#2 0x5882b1532124 base::internal::WeakReference::IsValid()
#3 0x5882ad90f4a1 _ZN4base8internal23QueryCancellationTraitsINS0_9BindStateIMN3net12_GLOBAL__N_114DnsHTTPAttemptEFvPNS3_10URLRequestEiEJNS_7WeakPtrIS5_EES7_iEEEEEbPKNS0_13BindStateBaseENSD_21CancellationQueryModeE
#4 0x5882b1512caa base::internal::CallbackBase::IsCancelled()
#5 0x5882b1535e48 base::MessageLoopImpl::DoWork()
#6 0x5882b1537f5a base::MessagePumpDefault::Run()
#7 0x5882b15353a5 base::MessageLoopImpl::Run()
#8 0x5882b155fb16 base::RunLoop::Run()
#9 0x5882b15a88da base::Thread::Run()
#10 0x5882b15a8c68 base::Thread::ThreadMain()
#11 0x5882b15e9da8 base::(anonymous namespace)::ThreadFunc()
#12 0x7f9af0f192b8 <unknown>
#13 0x7f9af03dbfad clone

https://ci.chromium.org/p/chromium/builders/luci.chromium.try/chromeos-amd64-generic-rel/140523 looks the same as #3.

2018/11/28 08:52:55 Running ui.MashLogin
2018/11/28 08:52:55 Restarting ui job
2018/11/28 08:52:57 Waiting for org.chromium.SessionManager D-Bus service
2018/11/28 08:52:57 Asking session_manager to enable Chrome testing
2018/11/28 08:52:57 Waiting for Chrome to write its debugging port to /home/chronos/DevToolsActivePort
2018/11/28 08:53:01 Removing cryptohome for testuser@gmail.com
2018/11/28 08:53:01 Finding OOBE DevTools target
2018/11/28 08:53:01 Connecting to Chrome at ws://127.0.0.1:34473/devtools/page/0EE4E7B56D592651E6371D4789A5E230
2018/11/28 08:53:01 Error: [mash_login.go:26] Chrome login failed: unexpected EOF

[ash:4407:4413:1128/085300.134115:FATAL:weak_ptr.cc(28)] Check failed: (sequence_checker_).CalledOnValidSequence(). WeakPtrs must be checked on the same sequenced thread.
#0 0x56a7ebfaf78f base::debug::StackTrace::StackTrace()
#1 0x56a7ebf047db logging::LogMessage::~LogMessage()
#2 0x56a7ebf0ad04 base::internal::WeakReference::IsValid()
#3 0x56a7e82db661 _ZN4base8internal23QueryCancellationTraitsINS0_9BindStateIMN3net12_GLOBAL__N_114DnsHTTPAttemptEFvPNS3_10URLRequestEiEJNS_7WeakPtrIS5_EES7_iEEEEEbPKNS0_13BindStateBaseENSD_21CancellationQueryModeE
#4 0x56a7ebeeb88a base::internal::CallbackBase::IsCancelled()
#5 0x56a7ebf0ea28 base::MessageLoopImpl::DoWork()
#6 0x56a7ebf10b3a base::MessagePumpDefault::Run()
#7 0x56a7ebf0df85 base::MessageLoopImpl::Run()
#8 0x56a7ebf386f6 base::RunLoop::Run()
#9 0x56a7ebf816ca base::Thread::Run()
#10 0x56a7ebf81a58 base::Thread::ThreadMain()
#11 0x56a7ebfc2b98 base::(anonymous namespace)::ThreadFunc()
#12 0x7b52ffcc42b8 <unknown>
#13 0x7b52ff186fad clone

James, mind assigning this? All of the failures I've seen are Chrome aborts due to threading issues in ui.MashLogin.

msw, could this be related to the recent ozone / GPU stuff?

If not, feel free to assign back to me and I can look more.

This looks like a problem in the ash process (see the tag at front of log line):
[ash:4517:4523:1127/190424.189033:FATAL:weak_ptr.cc(28)] Check failed: (sequence_checker_).CalledOnValidSequence(). WeakPtrs must be checked on the same sequenced thread.

estade, I seem to recall many mash browser_tests failures with this assertion. Do you know offhand if we figured out a root cause for any of them?

Dan, those logs come from "isolated out" right?

bpastene, did this builder recently turn on DCHECKs? This is a DCHECK failure.

> Dan, those logs come from "isolated out" right?

Yes, I got the test output from stdout and the Chrome crashes from the VM logs at "shard #0 isolated out". I looked in the chrome log file with a timestamp matching the test's message about restarting Chrome for testing.

CC'ing folks that should know more about DnsHTTPAttempt threading issues.
Any help is appreciated, I don't have a solid lead at this point.

> bpastene, did this builder recently turn on DCHECKs? This is a DCHECK failure.

Not recently. DCHECKs have been on for that bot for a few months now (ra1694874de3980b98b88324da9fe06fff7a54bc1)

Looking at the history of the test (from the link in c#0), it appears these flakes started around 10/31:
https://findit-for-me.appspot.com/flake/occurrences?key=ag9zfmZpbmRpdC1mb3ItbWVyPwsSBUZsYWtlIjRjaHJvbWl1bUBjaHJvbWVfYWxsX3Rhc3RfdGVzdHNAY2hyb21lX2FsbF90YXN0X3Rlc3RzDA&show_all_occurrences=1
(If needed, I could scrape together a visual graph of flakes over time to pin-down exactly when it started.)

Given the frequency of MessageLoop in the traces, and give the timing, maybe something slipped in in bug 891670 that caused the flakiness?

+CC altimin@, just in case work for Issue 891670 is related

For those new to the thread, ui.MashLogin runs Chrome for Chrome OS in a Chrome OS VM with --enable-features=Mash. The feature flag runs the Chrome OS UI code in //ash in an out-of-process mojo service. This is all vaguely similar to how network service works.

Not a whole lot of insight from the DNS perspective with so little to go off from the stacktrace above.  Looks like some callback with a reference to a weakptr to something under DnsHTTPAttempt is getting deleted on an unexpected thread.  All PostTasks around the DnsHTTPAttempt post to the current sequence or thread, so I don't think the issue is directly there.  Hard to say much more unless we can figure out what the callback is or where it's posted.

In general, most of the network stack assumes (and requires that) it's all running and interacted with on a single thread.  So if something in Mash is making //net calls and deleting the created objects on different threads, we could end up with weird behavior like this.

mohsen, could this be an ozone init threading issue?

Comment #2 has this reference:
OzonePlatformGbmEFvN4mojo16InterfaceRequestINS3_5ozone5mojom12DeviceCursor

It's not clear to me this is related to DnsHTTPAttempt. The ash process should not be making DNS requests.

Also, per rockot@:

"you definitely cannot rely on BindState template symbols to be accurate.
they are frequently folded together.
the only thing you can be sure of is that the actual offending BindState specialization matches that one in terms of underlying structure layout"

It's hard to know much about where this task is coming from.

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

commit c3828a4f2dae0976fb73ae57dce9655d9c1750d6
Author: James Cook <jamescook@chromium.org>
Date: Wed Nov 28 23:33:23 2018

Disable tast test ui.MashLogin on Chrome OS VMs

Flaky DCHECKs in the ash process, likely threading issues.

Bug: 909736
Change-Id: I080d1a30b415e10a33bb957711c0f4a68328c7ba
Reviewed-on: https://chromium-review.googlesource.com/c/1354345
Reviewed-by: Dan Erat <derat@chromium.org>
Commit-Queue: James Cook <jamescook@chromium.org>
Cr-Commit-Position: refs/heads/master@{#611934}
[modify] https://crrev.com/c3828a4f2dae0976fb73ae57dce9655d9c1750d6/chromeos/BUILD.gn

I don't think this is related to DnsHTTPAttempt. I put some logging in the constructor and we don't seem to create any DnsHTTPAttempt objects at all, either on linux-chromeos or when running Chrome for Chrome OS in a VM.

The good news is that I can repro with the instructions at go/cros-vm by deploying a release-with-dchecks build into the VM.

I don't have much insight into a root cause, though. MessageLoop folks, are there any tricks I could use to figure out who is posting this task?

Is the FROM_HERE helpful?

Removing Sheriff-Chromium since this is assigned and under investigation.

[-self] since it appears DNS involvement has been ruled out.

mohsen, can you take a look at this?

I think this is an ozone-initialization threading problem in OzonePlatformGbm. 

When I log the FROM_HERE of every posted task in the ash process I see this:

[ash:4251:4257:1129/090136.109813:ERROR:message_loop_impl.cc(445)] JAMES DoWork GpuHost@../../services/ws/gpu_host/gpu_host.cc:110
[ash:4251:4257:1129/090136.110895:ERROR:vaapi_wrapper.cc(324)] vaInitialize failed: unknown libva error
[ash:4251:4257:1129/090136.186101:ERROR:message_loop_impl.cc(445)] JAMES DoWork PostAsyncTaskOnce@../../ui/ozone/platform/drm/gpu/proxy_helpers.h:31
[ash:4251:4257:1129/090136.186144:FATAL:weak_ptr.cc(28)] Check failed: (sequence_checker_).CalledOnValidSequence(). WeakPtrs must be checked on the same sequenced thread.

PostAsyncTaskOnce is used by CreateSafeOnceCallback in proxy_helpers.h:
https://cs.chromium.org/chromium/src/ui/ozone/platform/drm/gpu/proxy_helpers.h?rcl=6ba57378eab35effa02c2225aedcdb248bb17f54&l=56

If I create my own copy of PostAsyncTaskOnce (so the FROM_HERE macros expand to a useful location) I get this:

localhost /var/log/ui # grep 5547 ui.20181129-093302     
[ash:5541:5547:1129/093305.198623:ERROR:message_loop_impl.cc(445)] JAMES DoWork GpuHost@../../services/ws/gpu_host/gpu_host.cc:110
[ash:5541:5547:1129/093305.199700:ERROR:vaapi_wrapper.cc(324)] vaInitialize failed: unknown libva error
[ash:5541:5547:1129/093305.199837:ERROR:ozone_platform_gbm.cc(86)] JAMES new OzonePlatformGbm
[ash:5541:5547:1129/093305.199885:ERROR:ozone_platform_gbm.cc(306)] JAMES AfterSandboxEntry
[ash:5541:5547:1129/093305.278716:ERROR:message_loop_impl.cc(445)] JAMES DoWork MyPostAsyncTaskOnce@../../ui/ozone/platform/drm/ozone_platform_gbm.cc:69
^^^^^^^^^^ This is the bad task
[ash:5541:5547:1129/093305.278754:FATAL:weak_ptr.cc(28)] Check failed: (sequence_checker_).CalledOnValidSequence(). WeakPtrs must be checked on the same sequenced thread.
#0 0x5cd60eadeecf base::debug::StackTrace::StackTrace()
#1 0x5cd60ea33e6b logging::LogMessage::~LogMessage()
#2 0x5cd60ea3a394 base::internal::WeakReference::IsValid()
#3 0x5cd60aeca751 _ZN4base8internal23QueryCancellationTraitsINS0_9BindStateIMN3net12_GLOBAL__N_114DnsHTTPAttemptEFvPNS3_10URLRequestEiEJNS_7WeakPtrIS5_EES7_iEEEEEbPKNS0_13BindStateBaseENSD_21CancellationQueryModeE
#4 0x5cd60ea1af1a base::internal::CallbackBase::IsCancelled()
#5 0x5cd60ea3e16f base::MessageLoopImpl::DoWork()
#6 0x5cd60ea4026a base::MessagePumpDefault::Run()
#7 0x5cd60ea3d615 base::MessageLoopImpl::Run()
#8 0x5cd60ea67e26 base::RunLoop::Run()
#9 0x5cd60eab0e4a base::Thread::Run()
#10 0x5cd60eab11d8 base::Thread::ThreadMain()
#11 0x5cd60eaf22d8 base::(anonymous namespace)::ThreadFunc()
#12 0x79738dedd2b8 <unknown>
#13 0x79738d39ffad clone

So I suspect this code in OzonePlatformGbm:

  // The DRM thread needs to be started late because we need to wait for the
  // sandbox to start. This entry point in the Ozne API gives platforms
  // flexibility in handing this requirement.
  void AfterSandboxEntry() override {
    CHECK(drm_thread_proxy_) << "AfterSandboxEntry before InitializeForGPU is "
                                "invalid startup order.\n";
    // Defer the actual startup of the DRM thread to here.
    auto safe_binding_resquest_drainer = CreateSafeOnceCallback(base::BindOnce(
        &OzonePlatformGbm::DrainBindingRequests, weak_factory_.GetWeakPtr()));

    drm_thread_proxy_->StartDrmThread(std::move(safe_binding_resquest_drainer));
  }

I've also seen the backtrace in comment 1. That might be a different problem, but looks related to DeviceCursor in OzonePlatformGbm.

sky and I theorize that sometimes AfterSandboxEntry is running on the wrong thread.

I noticed from logs that OzonePlatformGbm is sometimes created on the main thread and sometimes created on a different thread. That seems odd.

ui.LATEST:[ash:3961:3961:1129/101821.764492:ERROR:ozone_platform_gbm.cc(86)] JAMES new OzonePlatformGbm
                    ^^^^ main thread

ui.LATEST:[ash:4088:4094:1129/101822.995439:ERROR:ozone_platform_gbm.cc(86)] JAMES new OzonePlatformGbm
                    ^^^^ different thread

CL with logging: https://chromium-review.googlesource.com/c/chromium/src/+/1355251

My repro:
* Setup go/cros-vm
* Patch in logging CL
* cros chrome-sdk --board=amd64-generic --download-vm --log-level=info
* Edit out_amd64-generic/args.gn to set dcheck_always_on = true
* autoninja -C out_$SDK_BOARD/Release/ chromiumos_preflight
* deploy_chrome --build-dir=out_$SDK_BOARD/Release --to=localhost --port=9222 --target-dir=/usr/local/chrome --mount-dir=/opt/google/chrome --nostrip
* cros_run_vm_test --cmd -- local_test_runner ui.MashLogin

FYI: after https://chromium-review.googlesource.com/c/chromiumos/chromite/+/1355541 lands repro step 3 will need to be:
cros chrome-sdk --board=amd64-generic --download-vm --log-level=info --gn-extra-args=dcheck_always_on=true

And repro step 4 can be skipped.

Thanks James for the details and repro steps.

The problem as I understand is that OzonePlatformGbm has weak pointer factory that is used to generate weak pointers in two places to run callbacks on later:
1) AddInterfaces() which creates interface binders that run on the main thread.
2) AfterSandboxEntry() which creates a callback to run DrainBindingRequests() after DRM thread is started. This callback is run on GPU thread.

Weak pointers to an object are expected to be accessed on a single thread, which is not the case here.

This is only an issue when GPU is run in-process in multi-process mash. When GPU is run as a standalone process, there is no separate GPU thread and both callbacks should run on main thread of Viz.

chrome_all_tast_tests is flaky.

Findit has detected 3 new flake occurrences of this test. List
of all flake occurrences can be found at:
https://findit-for-me.appspot.com/flake/occurrences?key=ag9zfmZpbmRpdC1mb3ItbWVyPwsSBUZsYWtlIjRjaHJvbWl1bUBjaHJvbWVfYWxsX3Rhc3RfdGVzdHNAY2hyb21lX2FsbF90YXN0X3Rlc3RzDA.

Since this test is still flaky, this issue has been moved back onto the Sheriff
Bug Queue if it's not already there.

If the result 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%20Detection%20-%20Wrong%20result%20for%20chrome_all_tast_tests&comment=Link%20to%20flake%20occurrences%3A%20https://findit-for-me.appspot.com/flake/occurrences?key=ag9zfmZpbmRpdC1mb3ItbWVyPwsSBUZsYWtlIjRjaHJvbWl1bUBjaHJvbWVfYWxsX3Rhc3RfdGVzdHNAY2hyb21lX2FsbF90YXN0X3Rlc3RzDA

Automatically posted by the findit-for-me app (https://goo.gl/Ot9f7N).

I looked at the top few failures from the link in #23, and all appeared to be legitimate Chrome crashes, e.g.

2018/12/07 13:31:42 Running security.UserFilesGuest
2018/12/07 13:31:42 Restarting ui job
2018/12/07 13:31:46 Waiting for org.chromium.SessionManager D-Bus service
2018/12/07 13:31:46 Asking session_manager to enable Chrome testing
2018/12/07 13:31:46 Waiting for Chrome to write its debugging port to /home/chronos/DevToolsActivePort
2018/12/07 13:31:47 Removing cryptohome for $guest
2018/12/07 13:31:48 Finding OOBE DevTools target
2018/12/07 13:33:42 Error: [user_files_guest.go:26] Login failed: OOBE target not found: browser process 2880 exited; Chrome probably crashed
2018/12/07 13:33:42 Finished security.UserFilesGuest

I didn't dig in to try to find stack traces.

These all seem to be security.UserFilesGuest. I don't see any .dmp files in the test output (not sure where to look, though).

I do see this:

[5168:5168:1207/133517.571663:VERBOSE1:cryptohome_authenticator.cc(872)] Resolved state to 0 (CONTINUE)
[5168:5168:1207/133517.576961:ERROR:device_event_log_impl.cc(159)] [13:35:17.576] Login: cryptohome_util.cc:131 GetKeyDataEx failed with no GetKeyDataReply extension in reply.
[5168:5168:1207/133517.590991:ERROR:device_event_log_impl.cc(159)] [13:35:17.590] Login: cryptohome_authenticator.cc:208 MountEx failed. Error: 32
[5168:5168:1207/133517.591394:ERROR:device_event_log_impl.cc(159)] [13:35:17.591] Login: cryptohome_authenticator.cc:1033 Cryptohome failure: state(AuthState)=1, code(cryptohome::MountError)=32
[5168:5168:1207/133517.591440:VERBOSE1:cryptohome_authenticator.cc(872)] Resolved state to 6 (CREATE_NEW)

This isn't the same issue as the bug title.

#25: Filed issue 913153 for the top failure there, which appears to be caused by the VM running out of disk space.

The work is started and being addressed. Removing the sheriff label.

chrome_all_tast_tests is flaky.

Findit has detected 5 new flake occurrences of this test. List
of all flake occurrences can be found at:
https://findit-for-me.appspot.com/flake/occurrences?key=ag9zfmZpbmRpdC1mb3ItbWVyPwsSBUZsYWtlIjRjaHJvbWl1bUBjaHJvbWVfYWxsX3Rhc3RfdGVzdHNAY2hyb21lX2FsbF90YXN0X3Rlc3RzDA.

Since these tests are still flaky, this issue has been moved back onto the Sheriff Bug Queue if it hasn't already.

If the result 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%20Detection%20-%20Wrong%20result%3A%20chrome_all_tast_tests&comment=Link%20to%20flake%20details%3A%20https://findit-for-me.appspot.com/flake/occurrences?key=ag9zfmZpbmRpdC1mb3ItbWVyPwsSBUZsYWtlIjRjaHJvbWl1bUBjaHJvbWVfYWxsX3Rhc3RfdGVzdHNAY2hyb21lX2FsbF90YXN0X3Rlc3RzDA

Automatically posted by the findit-for-me app (https://goo.gl/Ot9f7N).

Removing again -- but maybe these test should be disabled until the fix lands?

Latest spike in flakes are due to bug 923061

This issue should now be fixed by r625015.