Add temporary debug logging for crbug.com/639350.

ui/base/test/ui_controls_internal_win.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "ui/base/test/ui_controls_internal_win.h"
 
 #include "base/bind.h"
 #include "base/callback.h"
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/macros.h"
 #include "base/memory/ref_counted.h"
 #include "base/single_thread_task_runner.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "ui/events/keycodes/keyboard_code_conversion_win.h"
 #include "ui/events/keycodes/keyboard_codes.h"
 
+namespace ui_controls {
+
+// TODO(msw): Remove flaky test debug logging for http://crbug.com/639350.
+bool g_crbug_639350_logging = false;
+
+namespace internal {
+
 namespace {
 
 // InputDispatcher ------------------------------------------------------------
 
 // InputDispatcher is used to listen for a mouse/keyboard event. When the
 // appropriate event is received the task is notified.
 class InputDispatcher : public base::RefCounted<InputDispatcher> {
  public:
   InputDispatcher(const base::Closure& task, WPARAM message_waiting_for);
 
@@ skipping 26 matching lines @@
 bool installed_hook_ = false;
 
 // Return value from SetWindowsHookEx.
 HHOOK next_hook_ = NULL;
 
 // If a hook is installed, this is the dispatcher.
 InputDispatcher* current_dispatcher_ = NULL;
 
 // Callback from hook when a mouse message is received.
 LRESULT CALLBACK MouseHook(int n_code, WPARAM w_param, LPARAM l_param) {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 MouseHook A";
   HHOOK next_hook = next_hook_;
   if (n_code == HC_ACTION) {
+    if (g_crbug_639350_logging)
+      LOG(ERROR) << "crbug.com/639350 MouseHook B";
     DCHECK(current_dispatcher_);
     current_dispatcher_->DispatchedMessage(w_param);
+    if (g_crbug_639350_logging)
+      LOG(ERROR) << "crbug.com/639350 MouseHook C";
   }
-  return CallNextHookEx(next_hook, n_code, w_param, l_param);
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 MouseHook D";
+  LRESULT result = CallNextHookEx(next_hook, n_code, w_param, l_param);
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 MouseHook E";
+  return result;
 }
 
 // Callback from hook when a key message is received.
 LRESULT CALLBACK KeyHook(int n_code, WPARAM w_param, LPARAM l_param) {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 KeyHook A";
   HHOOK next_hook = next_hook_;
   if (n_code == HC_ACTION) {
+    if (g_crbug_639350_logging)
+      LOG(ERROR) << "crbug.com/639350 KeyHook B";
     DCHECK(current_dispatcher_);
     if (l_param & (1 << 30)) {
+      if (g_crbug_639350_logging)
+        LOG(ERROR) << "crbug.com/639350 KeyHook C";
       // Only send on key up.
       current_dispatcher_->MatchingMessageFound();
     }
   }
-  return CallNextHookEx(next_hook, n_code, w_param, l_param);
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 KeyHook D";
+  LRESULT result = CallNextHookEx(next_hook, n_code, w_param, l_param);
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 KeyHook E";
+  return result;
 }
 
 // Installs dispatcher as the current hook.
 void InstallHook(InputDispatcher* dispatcher, bool key_hook) {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InstallHook A";
   DCHECK(!installed_hook_);
   current_dispatcher_ = dispatcher;
   installed_hook_ = true;
   if (key_hook) {
+    if (g_crbug_639350_logging)
+      LOG(ERROR) << "crbug.com/639350 InstallHook B";
     next_hook_ = SetWindowsHookEx(WH_KEYBOARD, &KeyHook, NULL,
                                   GetCurrentThreadId());
   } else {
+    if (g_crbug_639350_logging)
+      LOG(ERROR) << "crbug.com/639350 InstallHook C";
     // NOTE: I originally tried WH_CALLWNDPROCRET, but for some reason I
     // didn't get a mouse message like I do with MouseHook.
     next_hook_ = SetWindowsHookEx(WH_MOUSE, &MouseHook, NULL,
                                   GetCurrentThreadId());
   }
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InstallHook D";
   DCHECK(next_hook_);
 }
 
 // Uninstalls the hook set in InstallHook.
 void UninstallHook(InputDispatcher* dispatcher) {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 UninstallHook A";
   if (current_dispatcher_ == dispatcher) {
+    if (g_crbug_639350_logging)
+      LOG(ERROR) << "crbug.com/639350 UninstallHook B";
     installed_hook_ = false;
     current_dispatcher_ = NULL;
     UnhookWindowsHookEx(next_hook_);
   }
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 UninstallHook C";
 }
 
 InputDispatcher::InputDispatcher(const base::Closure& task,
                                  WPARAM message_waiting_for)
     : task_(task), message_waiting_for_(message_waiting_for) {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::InputDispatcher A";
   InstallHook(this, message_waiting_for == WM_KEYUP);
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::InputDispatcher B";
 }
 
 InputDispatcher::~InputDispatcher() {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::~InputDispatcher A";
   // Make sure the hook isn't installed.
   UninstallHook(this);
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::~InputDispatcher B";
 }
 
 void InputDispatcher::DispatchedMessage(WPARAM message) {
-  if (message == message_waiting_for_)
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::DispatchedMessage A";
+  if (message == message_waiting_for_) {
+    if (g_crbug_639350_logging)
+      LOG(ERROR) << "crbug.com/639350 InputDispatcher::DispatchedMessage B";
     MatchingMessageFound();
+  }
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::DispatchedMessage C";
 }
 
 void InputDispatcher::MatchingMessageFound() {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::MatchingMessageFound A";
   UninstallHook(this);
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::MatchingMessageFound B";
   // At the time we're invoked the event has not actually been processed.
   // Use PostTask to make sure the event has been processed before notifying.
   base::ThreadTaskRunnerHandle::Get()->PostTask(
       FROM_HERE, base::Bind(&InputDispatcher::NotifyTask, this));
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::MatchingMessageFound C";
 }
 
 void InputDispatcher::NotifyTask() {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::NotifyTask A";
   task_.Run();
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::NotifyTask B";
   Release();
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 InputDispatcher::NotifyTask C";
 }
 
 // Private functions ----------------------------------------------------------
 
 // Populate the INPUT structure with the appropriate keyboard event
 // parameters required by SendInput
 bool FillKeyboardInput(ui::KeyboardCode key, INPUT* input, bool key_up) {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 FillKeyboardInput A";
   memset(input, 0, sizeof(INPUT));
   input->type = INPUT_KEYBOARD;
   input->ki.wVk = ui::WindowsKeyCodeForKeyboardCode(key);
   input->ki.dwFlags = key_up ? KEYEVENTF_EXTENDEDKEY | KEYEVENTF_KEYUP :
                                KEYEVENTF_EXTENDEDKEY;
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 FillKeyboardInput B";
 
   return true;
 }
 
 }  // namespace
 
-namespace ui_controls {
-namespace internal {
-
 bool SendKeyPressImpl(HWND window,
                       ui::KeyboardCode key,
                       bool control,
                       bool shift,
                       bool alt,
                       const base::Closure& task) {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendKeyPressImpl A";
   // SendInput only works as we expect it if one of our windows is the
   // foreground window already.
   HWND target_window = (::GetActiveWindow() &&
                         ::GetWindow(::GetActiveWindow(), GW_OWNER) == window) ?
                        ::GetActiveWindow() :
                        window;
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendKeyPressImpl B";
   if (window && ::GetForegroundWindow() != target_window)
     return false;
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendKeyPressImpl C";
 
   scoped_refptr<InputDispatcher> dispatcher(
       !task.is_null() ? new InputDispatcher(task, WM_KEYUP) : NULL);
 
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendKeyPressImpl D";
+
   // If a pop-up menu is open, it won't receive events sent using SendInput.
   // Check for a pop-up menu using its window class (#32768) and if one
   // exists, send the key event directly there.
   HWND popup_menu = ::FindWindow(L"#32768", 0);
   if (popup_menu != NULL && popup_menu == ::GetTopWindow(NULL)) {
     WPARAM w_param = ui::WindowsKeyCodeForKeyboardCode(key);
     LPARAM l_param = 0;
     ::SendMessage(popup_menu, WM_KEYDOWN, w_param, l_param);
     ::SendMessage(popup_menu, WM_KEYUP, w_param, l_param);
 
     if (dispatcher.get())
       dispatcher->AddRef();
     return true;
   }
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendKeyPressImpl E";
 
   INPUT input[8] = {};  // 8, assuming all the modifiers are activated.
 
   UINT i = 0;
   if (control) {
     if (!FillKeyboardInput(ui::VKEY_CONTROL, &input[i], false))
       return false;
     i++;
   }
 
@@ skipping 27 matching lines @@
     if (!FillKeyboardInput(ui::VKEY_SHIFT, &input[i], true))
       return false;
     i++;
   }
 
   if (control) {
     if (!FillKeyboardInput(ui::VKEY_CONTROL, &input[i], true))
       return false;
     i++;
   }
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendKeyPressImpl F";
 
   if (::SendInput(i, input, sizeof(INPUT)) != i)
     return false;
 
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendKeyPressImpl G";
   if (dispatcher.get())
     dispatcher->AddRef();
 
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendKeyPressImpl H";
   return true;
 }
 
 bool SendMouseMoveImpl(long screen_x,
                        long screen_y,
                        const base::Closure& task) {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseMoveImpl A";
   // First check if the mouse is already there.
   POINT current_pos;
   ::GetCursorPos(&current_pos);
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseMoveImpl B";
   if (screen_x == current_pos.x && screen_y == current_pos.y) {
+    if (g_crbug_639350_logging)
+      LOG(ERROR) << "crbug.com/639350 SendMouseMoveImpl C";
     if (!task.is_null())
       base::ThreadTaskRunnerHandle::Get()->PostTask(FROM_HERE, task);
+    if (g_crbug_639350_logging)
+      LOG(ERROR) << "crbug.com/639350 SendMouseMoveImpl D";
     return true;
   }
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseMoveImpl E";
 
   INPUT input = { 0 };
 
   int screen_width = ::GetSystemMetrics(SM_CXSCREEN) - 1;
   int screen_height  = ::GetSystemMetrics(SM_CYSCREEN) - 1;
   LONG pixel_x  = static_cast<LONG>(screen_x * (65535.0f / screen_width));
   LONG pixel_y = static_cast<LONG>(screen_y * (65535.0f / screen_height));
 
   input.type = INPUT_MOUSE;
   input.mi.dwFlags = MOUSEEVENTF_ABSOLUTE | MOUSEEVENTF_MOVE;
   input.mi.dx = pixel_x;
   input.mi.dy = pixel_y;
 
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseMoveImpl F";
   scoped_refptr<InputDispatcher> dispatcher(
       !task.is_null() ? new InputDispatcher(task, WM_MOUSEMOVE) : NULL);
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseMoveImpl G";
 
   if (!::SendInput(1, &input, sizeof(INPUT)))
     return false;
 
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseMoveImpl H";
+
   if (dispatcher.get())
     dispatcher->AddRef();
 
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseMoveImpl I";
   return true;
 }
 
 bool SendMouseEventsImpl(MouseButton type, int state,
                          const base::Closure& task) {
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseEventsImpl A";
   DWORD down_flags = MOUSEEVENTF_ABSOLUTE;
   DWORD up_flags = MOUSEEVENTF_ABSOLUTE;
   UINT last_event;
 
   switch (type) {
     case LEFT:
       down_flags |= MOUSEEVENTF_LEFTDOWN;
       up_flags |= MOUSEEVENTF_LEFTUP;
       last_event = (state & UP) ? WM_LBUTTONUP : WM_LBUTTONDOWN;
       break;
 
     case MIDDLE:
       down_flags |= MOUSEEVENTF_MIDDLEDOWN;
       up_flags |= MOUSEEVENTF_MIDDLEUP;
       last_event = (state & UP) ? WM_MBUTTONUP : WM_MBUTTONDOWN;
       break;
 
     case RIGHT:
       down_flags |= MOUSEEVENTF_RIGHTDOWN;
       up_flags |= MOUSEEVENTF_RIGHTUP;
       last_event = (state & UP) ? WM_RBUTTONUP : WM_RBUTTONDOWN;
       break;
 
     default:
       NOTREACHED();
       return false;
   }
 
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseEventsImpl B";
   scoped_refptr<InputDispatcher> dispatcher(
       !task.is_null() ? new InputDispatcher(task, last_event) : NULL);
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseEventsImpl C";
 
   INPUT input = { 0 };
   input.type = INPUT_MOUSE;
   input.mi.dwFlags = down_flags;
   if ((state & DOWN) && !::SendInput(1, &input, sizeof(INPUT)))
     return false;
 
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseEventsImpl D";
   input.mi.dwFlags = up_flags;
   if ((state & UP) && !::SendInput(1, &input, sizeof(INPUT)))
     return false;
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseEventsImpl E";
 
   if (dispatcher.get())
     dispatcher->AddRef();
+  if (g_crbug_639350_logging)
+    LOG(ERROR) << "crbug.com/639350 SendMouseEventsImpl F";
 
   return true;
 }
 
 }  // namespace internal
 }  // namespace ui_controls