(No comment was entered for this change.)

Here's another one. As per cmasone's suggestion, I'm going to disable the test.

http://chromeos-botmaster.mtv.corp.google.com:8026/builders/x86-zgb-binary/builds/1487/steps/VMTest/logs/stdio

Looking at the logs in these failures, I see this:


10/12 05:25:10 DEBUG|     httpd:0120| Translated path: /usr/local/autotest/tests/desktopui_UrlFetch/hello.html
10/12 05:25:10 DEBUG|     httpd:0051| localhost - - [12/Oct/2011 05:25:10] "GET /hello.html HTTP/1.1" 200 -


Which means that the locally running web server got the request and returned a 200.  As such, it seems that the problem is on the pyauto side.

Commit: 0fff243573ea9b4d9da17ee83f9cb430647ac169
 Email: mnissler@chromium.org

Disable desktopui_UrlFetch.not-live, it's flaky.

BUG=chromium-os:21566
TEST=None

Change-Id: Ia83d8e8cf92aeeb1ecc8ca564bd33c6036fe1984
Reviewed-on: http://gerrit.chromium.org/gerrit/9942
Commit-Ready: Mattias Nissler <mnissler@chromium.org>
Tested-by: Mattias Nissler <mnissler@chromium.org>
Reviewed-by: Chris Masone <cmasone@chromium.org>
Commit-Ready: Luigi Semenzato <semenzato@chromium.org>
Reviewed-by: Luigi Semenzato <semenzato@chromium.org>

M	client/site_tests/suite_Smoke/control

This is disabled so it's not closing trees any more, but still needs to be fixed and reenabled.

I'm seeing that chrome is indeed failing to navigate URLs after login.

Happens on both the VM and device. Chrome cannot open URLs for a while immediately after login. I've been able to repro it manually as well (ie no automation at all, although it's a little hard).

I'm on 1193.6.0

(No comment was entered for this change.)

Since I can easily this manually, and this also affects restoring of URLs after login, this issue will be faced by users as well, who'll see chrome's throbber spinning endlessly. Once chrome reaches this state, no additional URLs can be opened in any tabs.

I tried dumping the state from chrome://net-internals, but that save-dialog box freezes as well.

Anybody have suggestions?

Xiyuan and Antoine debugged on my machine. When this happens gpu process is busy at ~50% cpu, and killing it makes things go fine.

Stack trace from gpu process, renderer:

GPU process
#0  0x77748416 in __kernel_vsyscall ()
#1  0x76a1444b in write () from /build/x86-mario/lib/libpthread.so.0
#2  0x08e7fbdc in base::MessagePumpLibevent::ScheduleWork (this=0xcbb9240) at base/message_pump_libevent.cc:293
#3  0x08eb2d86 in MessageLoop::AddToIncomingQueue (this=0x7531a0dc, pending_task=0x7fe11ba8) at base/message_loop.cc:653
#4  0x08eb3c3f in MessageLoop::PostDelayedTask (this=0x7531a0dc, from_here=..., task=0xd625ec0, delay_ms=0) at base/message_loop.cc:280
#5  0x08eb6f63 in base::MessageLoopProxyImpl::PostTaskHelper (this=0xcc05c00, from_here=..., task=0xd625ec0, delay_ms=0, nestable=true)
    at base/message_loop_proxy_impl.cc:110
#6  0x08eb7124 in base::MessageLoopProxyImpl::PostTask (this=0xcc05c00, from_here=..., task=0xd625ec0) at base/message_loop_proxy_impl.cc:18
#7  0x097e821c in IPC::ChannelProxy::Send (this=0xcc30ec0, message=0x198b5dc0) at ipc/ipc_channel_proxy.cc:357
#8  0x097f28f1 in IPC::SyncChannel::SendWithTimeout (this=0xcc30ec0, message=0x198b5dc0, timeout_ms=-1) at ipc/ipc_sync_channel.cc:406
#9  0x097ec85d in IPC::SyncChannel::Send (this=0xcc30ec0, message=0x198b5dc0) at ipc/ipc_sync_channel.cc:401
#10 0x097d8296 in GpuChannel::Send (this=0xcd84b40, message=0x198b5dc0) at content/common/gpu/gpu_channel.cc:117
#11 0x097d9b57 in GpuCommandBufferStub::Send (this=0xcc12f20, message=0x198b5dc0) at content/common/gpu/gpu_command_buffer_stub.cc:121
#12 0x097da475 in GpuCommandBufferStub::OnGetStateFast (this=0xcc12f20, reply_message=0x198b5dc0)
    at content/common/gpu/gpu_command_buffer_stub.cc:336
#13 0x097ded19 in DispatchToMethod<GpuCommandBufferStub, void (GpuCommandBufferStub::*)(IPC::Message*), IPC::Message&> (this=0xcc12f20, message=...)
    at ./base/tuple.h:715
#14 DispatchDelayReplyWithSendParams<GpuCommandBufferStub, void (GpuCommandBufferStub::*)(IPC::Message*)> (this=0xcc12f20, message=...)
    at ./ipc/ipc_message_utils.h:1102
#15 DispatchDelayReply<GpuCommandBufferStub, void (GpuCommandBufferStub::*)(IPC::Message*)> (this=0xcc12f20, message=...)
    at ./content/common/gpu/gpu_messages.h:341
#16 GpuCommandBufferStub::OnMessageReceived (this=0xcc12f20, message=...) at content/common/gpu/gpu_command_buffer_stub.cc:95
#17 0x097ae23c in MessageRouter::RouteMessage (this=0xcd84b88, msg=...) at content/common/message_router.cc:46
#18 0x097d968a in HandleMessage (this=0xcd84b40) at content/common/gpu/gpu_channel.cc:240
#19 GpuChannel::HandleMessage (this=0xcd84b40) at content/common/gpu/gpu_channel.cc:229
#20 0x097d3d73 in DispatchToMethod<GpuChannel, void (GpuChannel::*)()> (this=0x1c1a7380) at ./base/tuple.h:537
#21 ScopedRunnableMethodFactory<GpuChannel>::RunnableMethod<void (GpuChannel::*)(), Tuple0>::Run (this=0x1c1a7380) at ./base/task.h:189
#22 0x08ee5c10 in base::subtle::TaskClosureAdapter::Run (this=0xd625db0) at base/task.cc:71
#23 0x08eaec10 in base::internal::Invoker1<false, base::internal::InvokerStorage1<void (base::subtle::TaskClosureAdapter::*)(), base::subtle::TaskClosureAdapter*>, void (base::subtle::TaskClosureAdapter::*)()>::DoInvoke (base=0x1c467ba0) at ./base/bind_internal.h:596
#24 0x08eafe24 in Run (this=0x7fe13e1c, pending_task=...) at ./base/callback.h:269
#25 MessageLoop::RunTask (this=0x7fe13e1c, pending_task=...) at base/message_loop.cc:495
#26 0x08eb2694 in MessageLoop::DeferOrRunPendingTask (this=0x7fe13e1c, pending_task=...) at base/message_loop.cc:509
#27 0x08eb2bc4 in DoWork (this=0x7fe13e1c) at base/message_loop.cc:699
#28 MessageLoop::DoWork (this=0x7fe13e1c) at base/message_loop.cc:678
#29 0x08ef3d39 in base::MessagePumpGlib::HandleDispatch (this=0xcbb9400) at base/message_pump_glib.cc:275
#30 0x08ef3d9f in (anonymous namespace)::WorkSourceDispatch (source=0xcbb9440, unused_func=0, unused_data=0x0) at base/message_pump_glib.cc:108
#31 0x774b7f6a in g_main_dispatch (context=0xcbc2930) at gmain.c:2441
#32 g_main_context_dispatch (context=0xcbc2930) at gmain.c:3011
#33 0x774ba220 in g_main_context_iterate (context=0xcbc2930, block=<value optimized out>, dispatch=1, self=0xcc05f00) at gmain.c:3089
#34 0x774ba6fe in g_main_context_iteration (context=0xcbc2930, may_block=0) at gmain.c:3152
#35 0x08ef4391 in base::MessagePumpGtk::RunOnce (this=0xcbb9400, context=0xcbc2930, block=false) at base/message_pump_gtk.cc:41
#36 0x08ef33f9 in base::MessagePumpGlib::RunWithDispatcher (this=0xcbb9400, delegate=0x7fe13e1c, dispatcher=0x0) at base/message_pump_glib.cc:206
#37 0x08ef34bd in base::MessagePumpGlib::Run (this=0xcbb9400, delegate=0x7fe13e1c) at base/message_pump_glib.cc:298
#38 0x08eb3fd2 in MessageLoop::RunInternal (this=0x7fe13e1c) at base/message_loop.cc:453
#39 0x08eb41ff in RunHandler (this=0x7fe13e1c) at base/message_loop.cc:426
#40 MessageLoop::Run (this=0x7fe13e1c) at base/message_loop.cc:341
#41 0x08e085b4 in GpuMain (parameters=...) at content/gpu/gpu_main.cc:116
#42 0x08e07e1b in RunNamedProcessTypeMain (argc=7, argv=0x7fe14874, delegate=0x7fe14770) at content/app/content_main.cc:261
#43 content::ContentMain (argc=7, argv=0x7fe14874, delegate=0x7fe14770) at content/app/content_main.cc:451
#44 0x0806c33f in ChromeMain (argc=7, argv=0x7fe14874) at chrome/app/chrome_main.cc:32
#45 0x0806c2c4 in main (argc=7, argv=0x7fe14874) at chrome/app/chrome_exe_main_gtk.cc:18

(gdb) f 12
#12 0x097da475 in GpuCommandBufferStub::OnGetStateFast (this=0xcc12f20, reply_message=0x198b5dc0)
    at content/common/gpu/gpu_command_buffer_stub.cc:336
336	  Send(reply_message);


(gdb) p *command_buffer_.ptr_
$17 = {<gpu::CommandBuffer> = {_vptr.CommandBuffer = 0xc531e68}, ring_buffer_ = {ptr = 0x74199000, size = 1048576, shared_memory = 0xcde1d60}, 
  num_entries_ = 262144, get_offset_ = 5069, put_offset_ = 5069, put_offset_change_callback_ = {ptr_ = 0xcd79d50}, parse_error_callback_ = {
    ptr_ = 0xcd79d40}, registered_objects_ = {<std::_Vector_base<gpu::Buffer, std::allocator<gpu::Buffer> >> = {
      _M_impl = {<std::allocator<gpu::Buffer>> = {<__gnu_cxx::new_allocator<gpu::Buffer>> = {<No data fields>}, <No data fields>}, 
        _M_start = 0xcda0600, _M_finish = 0xcda0714, _M_end_of_storage = 0xcda07e0}}, <No data fields>}, unused_registered_object_elements_ = {
    _M_t = {
      _M_impl = {<std::allocator<std::_Rb_tree_node<int> >> = {<__gnu_cxx::new_allocator<std::_Rb_tree_node<int> >> = {<No data fields>}, <No data fields>}, _M_key_compare = {<std::binary_function<int, int, bool>> = {<No data fields>}, <No data fields>}, _M_header = {_M_color = std::_S_red, 
          _M_parent = 0x0, _M_left = 0xcbc1a54, _M_right = 0xcbc1a54}, _M_node_count = 0}}}, token_ = 52, generation_ = 1332870, 
  error_ = gpu::error::kNoError, context_lost_reason_ = 2002962896}



Renderer

(gdb) bt
#0  0x776fc416 in __kernel_vsyscall ()
#1  0x769c55d5 in pthread_cond_wait () from /build/x86-mario/lib/libpthread.so.0
#2  0x08edf626 in base::ConditionVariable::Wait (this=0x7ff57dec) at base/synchronization/condition_variable_posix.cc:35
#3  0x08ee1e34 in base::WaitableEvent::WaitMany (raw_waitables=0x7ff580a0, count=2) at base/synchronization/waitable_event_posix.cc:268
#4  0x097f2440 in IPC::SyncChannel::WaitForReply (context=0xdb3cc30, pump_messages_event=0x0) at ipc/ipc_sync_channel.cc:453
#5  0x097f27d5 in IPC::SyncChannel::SendWithTimeout (this=0xdc61940, message=0xf3c46c0, timeout_ms=-1) at ipc/ipc_sync_channel.cc:437
#6  0x097ec85d in IPC::SyncChannel::Send (this=0xdc61940, message=0xf3c46c0) at ipc/ipc_sync_channel.cc:401
#7  0x0aa8855d in GpuChannelHost::Send (this=0xdb1da20, message=0xf3c46c0) at content/renderer/gpu/gpu_channel_host.cc:192
#8  0x0aacc2fe in Send (this=0xdb03a50, msg=0xf3c46c0) at content/renderer/gpu/command_buffer_proxy.cc:438
#9  CommandBufferProxy::Send (this=0xdb03a50, msg=0xf3c46c0) at content/renderer/gpu/command_buffer_proxy.cc:433
#10 0x0aacca9c in CommandBufferProxy::FlushSync (this=0xdb03a50, put_offset=5071, last_known_get=5069)
    at content/renderer/gpu/command_buffer_proxy.cc:202
#11 0x0abb2642 in gpu::CommandBufferHelper::FlushSync (this=0xdc61b40) at gpu/command_buffer/client/cmd_buffer_helper.cc:57
#12 0x0abb298e in gpu::CommandBufferHelper::WaitForToken (this=0xdc61b40, token=53) at gpu/command_buffer/client/cmd_buffer_helper.cc:115
#13 0x0aea0ee1 in gpu::RingBuffer::FreeOldestBlock (this=0xdc5eaa0) at gpu/command_buffer/client/ring_buffer.cc:35
#14 0x0aea1548 in gpu::RingBuffer::Alloc (this=0xdc5eaa0, size=1044480) at gpu/command_buffer/client/ring_buffer.cc:59
#15 0x0abbdcfc in Alloc (this=0xdc5ea80, xoffset=0, yoffset=204, width=1280, height=719, format=6408, type=5121, pixels=0xeace008)
    at gpu/command_buffer/client/../client/../client/ring_buffer.h:137
#16 Alloc (this=0xdc5ea80, xoffset=0, yoffset=204, width=1280, height=719, format=6408, type=5121, pixels=0xeace008)
    at gpu/command_buffer/client/../client/gles2_implementation.h:219
#17 gpu::gles2::GLES2Implementation::ReadPixels (this=0xdc5ea80, xoffset=0, yoffset=204, width=1280, height=719, format=6408, type=5121, 
    pixels=0xeace008) at gpu/command_buffer/client/gles2_implementation.cc:1974
#18 0x0aa8f553 in WebGraphicsContext3DCommandBufferImpl::readPixels (this=0xdb038f0, a1=0, a2=0, a3=1280, a4=923, a5=6408, a6=5121, a7=0xeace008)
    at content/renderer/gpu/webgraphicscontext3d_command_buffer_impl.cc:885
#19 0x09868efc in readPixels (this=0xdc766b0, a1=0, a2=0, a3=1280, a4=923, a5=6408, a6=5121, a7=0xeace008)
    at third_party/WebKit/Source/WebKit/chromium/src/GraphicsContext3DChromium.cpp:662
#20 WebCore::GraphicsContext3D::readPixels (this=0xdc766b0, a1=0, a2=0, a3=1280, a4=923, a5=6408, a6=5121, a7=0xeace008)
    at third_party/WebKit/Source/WebKit/chromium/src/GraphicsContext3DChromium.cpp:1158
#21 0x09ba13f6 in WebCore::LayerRendererChromium::getFramebufferPixels (this=0xdb6f280, pixels=0xeace008, rect=...)
    at third_party/WebKit/Source/WebCore/platform/graphics/chromium/LayerRendererChromium.cpp:498
#22 0x09b510cb in WebCore::CCLayerTreeHostImpl::readback (this=0xdc5c5a0, pixels=0xeace008, rect=...)
    at third_party/WebKit/Source/WebCore/platform/graphics/chromium/cc/CCLayerTreeHostImpl.cpp:122
#23 0x09b53aab in compositeAndReadback (this=0xdc5c570, pixels=0xeace008, rect=...)
    at third_party/WebKit/Source/WebCore/platform/graphics/chromium/cc/CCSingleThreadProxy.cpp:83
#24 WebCore::CCSingleThreadProxy::compositeAndReadback (this=0xdc5c570, pixels=0xeace008, rect=...)
    at third_party/WebKit/Source/WebCore/platform/graphics/chromium/cc/CCSingleThreadProxy.cpp:71
#25 0x09b4f57f in WebCore::CCLayerTreeHost::compositeAndReadback (this=0xdb3cb60, pixels=0xeace008, rect=...)
    at third_party/WebKit/Source/WebCore/platform/graphics/chromium/cc/CCLayerTreeHost.cpp:175
#26 0x0983dbc7 in WebKit::WebViewImpl::doPixelReadbackToCanvas (this=0xdb15c80, canvas=0x7ff58ebc, rect=...)
    at third_party/WebKit/Source/WebKit/chromium/src/WebViewImpl.cpp:1111
#27 0x0983de17 in WebKit::WebViewImpl::paint (this=0xdb15c80, canvas=0x7ff58ebc, rect=...)
    at third_party/WebKit/Source/WebKit/chromium/src/WebViewImpl.cpp:1134
#28 0x08d38e7d in PaintViewIntoCanvas (view=0xdb15c80, canvas=...) at chrome/renderer/chrome_render_view_observer.cc:166
#29 0x08d3a2ba in ChromeRenderViewObserver::CaptureFrameThumbnail (this=0xdb00a00, view=0xdb15c80, w=212, h=132, thumbnail=0x7ff594c0, 
    score=0x7ff594a8) at chrome/renderer/chrome_render_view_observer.cc:940
#30 0x08d3ada0 in ChromeRenderViewObserver::CaptureThumbnail (this=0xdb00a00) at chrome/renderer/chrome_render_view_observer.cc:920
#31 0x08d3b4c2 in ChromeRenderViewObserver::CapturePageInfo (this=0xdb00a00, load_id=1, preliminary_capture=false)
    at chrome/renderer/chrome_render_view_observer.cc:860
#32 0x08d37fab in DispatchToMethod<ChromeRenderViewObserver, void (ChromeRenderViewObserver::*)(int, bool), int, bool> (this=0xdcb49a0)
    at ./base/tuple.h:554
#33 ScopedRunnableMethodFactory<ChromeRenderViewObserver>::RunnableMethod<void (ChromeRenderViewObserver::*)(int, bool), Tuple2<int, bool> >::Run (
    this=0xdcb49a0) at ./base/task.h:189
#34 0x08ee5c10 in base::subtle::TaskClosureAdapter::Run (this=0xdc9a900) at base/task.cc:71
#35 0x08eaec10 in base::internal::Invoker1<false, base::internal::InvokerStorage1<void (base::subtle::TaskClosureAdapter::*)(), base::subtle::TaskClosureAdapter*>, void (base::subtle::TaskClosureAdapter::*)()>::DoInvoke (base=0xdcb49c0) at ./base/bind_internal.h:596
#36 0x08eafe24 in Run (this=0x7ff5a84c, pending_task=...) at ./base/callback.h:269
#37 MessageLoop::RunTask (this=0x7ff5a84c, pending_task=...) at base/message_loop.cc:495
#38 0x08eb2694 in MessageLoop::DeferOrRunPendingTask (this=0x7ff5a84c, pending_task=...) at base/message_loop.cc:509
#39 0x08eb2a37 in DoDelayedWork (this=0x7ff5a84c, next_delayed_work_time=0xdb49630) at base/message_loop.cc:737
#40 MessageLoop::DoDelayedWork (this=0x7ff5a84c, next_delayed_work_time=0xdb49630) at base/message_loop.cc:709
#41 0x08eb7746 in base::MessagePumpDefault::Run (this=0xdb49620, delegate=0x7ff5a84c) at base/message_pump_default.cc:27

(gdb) up 10
#10 0x0aacca9c in CommandBufferProxy::FlushSync (this=0xdb03a50, put_offset=5071, last_known_get=5069)
    at content/renderer/gpu/command_buffer_proxy.cc:202
202	      if (Send(new GpuCommandBufferMsg_GetStateFast(route_id_,

+apatrick in case he has an idea.

At the time of the break, there were 2 renderers and the GPU process spinning. The test loads a new page right after login, I assume it's in the state where about:blank is the current renderer, and loading the page attempts to switch to a new renderer. Because the about:blank renderer is (somehow) making the GPU process spin, so the new page doesn't load. Once you kill the GPU process, everything comes back to normal. Note that on Chrome OS, we use --force-compositing-mode, so about:blank also uses the GPU process.


We got the machine into the bogus state, and attached a debugger to the gpu process and the first renderer. The stack trace above are the result.


The renderer shows that it's trying to Finish, by doing a FlushSync loop, setting 'put' to 5071 and waiting until 'get' gets there.
The GPU process is sending the current state, which shows that put == get = 5069. So the GPU process doesn't progress...

I'm not sure how that's possible, since the previous AsyncFlush should have set 'put' to at 5071.

One thing I noticed is that CommandBufferService::context_lost_reason_ is bogus (not initialized), but I couldn't see anywhere where that would have an impact.


While trying to debug more, I ran into the issue that the GPU watchdog would kill the GPU process. However, when disabling it, we couldn't reproduce the issue anymore.
I don't know that the GPU watchdog is causing this directly, but it changes the timing making this race possibly more likely.

I suspect this is caused by http://codereview.chromium.org/8198017/

Aka https://code.google.com/p/chromium/issues/detail?id=102214

Antoine, any progress here?
All automation on chromeos that involves navigating to a URL is blocked because of this.

(No comment was entered for this change.)

Happens even when you're already logged in. So removing the 'logged in' part from the title.

(No comment was entered for this change.)

Do we need more date here? 

I've got a fix for chromium:102214 checked in, and soon I'll merge in into M16. I'm not sure if anything is necessary after that.

(No comment was entered for this change.)

Merged to M16. Looks like someone needs to reenable the tests.

(No comment was entered for this change.)

Have the tests been re-enabled? If not, can you pls reassign to whomever will do that? 

It looks like you disabled these tests, so could you reenable them?

I'm enabling in https://gerrit.chromium.org/gerrit/11295

Commit: b78346cf403dadf4f0413ff74190f1e22a687b4f
 Email: nirnimesh@chromium.org

Enable desktopui_UrlFetch test in smoke suite.

The corresponding chrome bug is fixed now.

BUG=chromium-os:21566
TEST=smoke suite should be green.

Change-Id: Iff48a3265751d7c4a379930fc3a215cc40db6519
Reviewed-on: https://gerrit.chromium.org/gerrit/11295
Reviewed-by: Chris Masone <cmasone@chromium.org>
Commit-Ready: Nirnimesh <nirnimesh@chromium.org>
Tested-by: Nirnimesh <nirnimesh@chromium.org>

M	client/site_tests/suite_Smoke/control

Test was reenabled by nirnimesh. Close the issue?

(No comment was entered for this change.)

Didn't see it in 1193.49.0. Closing for a now.

Claiming completed work to iteration-42

(No comment was entered for this change.)

(No comment was entered for this change.)

We are seeing flaky failures of this type - Timeout waiting to open http://localhost:8000/hello.html  See https://code.google.com/p/chromium-os/issues/detail?id=25123.  Perhaps someone on this bug can help?

Please open a new bug and reference this bug if relevant.

(No comment was entered for this change.)

(No comment was entered for this change.)