Revert 67849 - Figure out error in test PrepopulateRespectBlank.

Revert previous traces and add one targeted test.

My traces seem to indicate that something else
than a Chrome window has focus when the test fails.

Lets figure out what that is...

BUG=62937
TEST=Tracking down problem in test

Review URL: http://codereview.chromium.org/5463001

TBR=finnur@chromium.org
Review URL: http://codereview.chromium.org/5451002

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@67852 0039d316-1c4b-4281-b951-d872f2087c98

3 files changed, 55 insertions, 53 deletions

diff --git a/chrome/browser/automation/ui_controls_win.cc b/chrome/browser/automation/ui_controls_win.cc
index 25469ad..dfa2af6 100644
--- a/chrome/browser/automation/ui_controls_win.cc
+++ b/chrome/browser/automation/ui_controls_win.cc
@@ -8,6 +8,7 @@
 #include "app/keyboard_codes.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
+#include "base/string_util.h"
 #include "base/win_util.h"
 #include "base/ref_counted.h"
 #include "base/task.h"
@@ -17,6 +18,12 @@ namespace ui_controls {
 
 namespace {
 
+void Checkpoint(const char* message, const base::TimeTicks& start_time) {
+  LOG(INFO) << message << " : "
+            << (base::TimeTicks::Now() - start_time).InMilliseconds()
+            << " ms" << std::flush;
+}
+
 // InputDispatcher ------------------------------------------------------------
 
 // InputDispatcher is used to listen for a mouse/keyboard event. When the
@@ -38,7 +45,7 @@ class InputDispatcher : public base::RefCounted<InputDispatcher> {
 
   ~InputDispatcher();
 
-  // Notifies the task and release this (which should delete it).
+   // Notifies the task and release this (which should delete it).
   void NotifyTask();
 
   // The task we notify.
@@ -71,14 +78,25 @@ LRESULT CALLBACK MouseHook(int n_code, WPARAM w_param, LPARAM l_param) {
 
 // Callback from hook when a key message is received.
 LRESULT CALLBACK KeyHook(int n_code, WPARAM w_param, LPARAM l_param) {
+  base::TimeTicks start_time = base::TimeTicks::Now();
+  char msg[512];
+  base::snprintf(msg, 512, "KeyHook starts: %d", n_code);
+  Checkpoint(msg, start_time);
+
   HHOOK next_hook = next_hook_;
+  base::snprintf(msg, 512, "n_code == HC_ACTION: %d, %d",
+          l_param, !!(l_param & (1 << 30)));
+  Checkpoint(msg, start_time);
   if (n_code == HC_ACTION) {
     DCHECK(current_dispatcher_);
-    if (l_param & (1 << 30)) {
-      // Only send on key up.
+    if (l_param & (1 << 30)) {  // Only send on key up.
+      Checkpoint("MatchingMessageFound", start_time);
       current_dispatcher_->MatchingMessageFound();
+    } else {
+      Checkpoint("Not key up", start_time);
     }
   }
+  Checkpoint("KeyHook ends, calling next hook.", start_time);
   return CallNextHookEx(next_hook, n_code, w_param, l_param);
 }
 
@@ -166,77 +184,99 @@ bool SendKeyEvent(app::KeyboardCode key, bool up) {
 bool SendKeyPressImpl(app::KeyboardCode key,
                       bool control, bool shift, bool alt,
                       Task* task) {
+  base::TimeTicks start_time = base::TimeTicks::Now();
+  Checkpoint("SendKeyPressImpl starts", start_time);
+
   scoped_refptr<InputDispatcher> dispatcher(
       task ? new InputDispatcher(task, WM_KEYUP) : NULL);
 
   // 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.
+  Checkpoint("FindWindow", start_time);
   HWND popup_menu = ::FindWindow(L"#32768", 0);
   if (popup_menu != NULL && popup_menu == ::GetTopWindow(NULL)) {
+    Checkpoint("Found popup window", start_time);
     WPARAM w_param = app::WindowsKeyCodeForKeyboardCode(key);
     LPARAM l_param = 0;
+    Checkpoint("Send WM_KEYDOWN", start_time);
     ::SendMessage(popup_menu, WM_KEYDOWN, w_param, l_param);
+    Checkpoint("Send WM_KEYUP", start_time);
     ::SendMessage(popup_menu, WM_KEYUP, w_param, l_param);
 
+    Checkpoint("Send Done", start_time);
     if (dispatcher.get())
       dispatcher->AddRef();
     return true;
   }
 
-  INPUT input[8] = { 0 };  // 8, assuming all the modifiers are activated.
+  Checkpoint("Found no popup window", start_time);
+
+  INPUT input[8] = { 0 }; // 8, assuming all the modifiers are activated
 
   UINT i = 0;
   if (control) {
+    Checkpoint("FillKeyboardInput Control", start_time);
     if (!FillKeyboardInput(app::VKEY_CONTROL, &input[i], false))
       return false;
     i++;
   }
 
   if (shift) {
+    Checkpoint("FillKeyboardInput Shift", start_time);
     if (!FillKeyboardInput(app::VKEY_SHIFT, &input[i], false))
       return false;
     i++;
   }
 
   if (alt) {
+    Checkpoint("FillKeyboardInput Alt", start_time);
     if (!FillKeyboardInput(app::VKEY_MENU, &input[i], false))
       return false;
     i++;
   }
 
+  Checkpoint("FillKeyboardInput 1", start_time);
   if (!FillKeyboardInput(key, &input[i], false))
     return false;
   i++;
 
+  Checkpoint("FillKeyboardInput 2", start_time);
   if (!FillKeyboardInput(key, &input[i], true))
     return false;
   i++;
 
   if (alt) {
+    Checkpoint("FillKeyboardInput Alt2", start_time);
     if (!FillKeyboardInput(app::VKEY_MENU, &input[i], true))
       return false;
     i++;
   }
 
   if (shift) {
+    Checkpoint("FillKeyboardInput Shift2", start_time);
     if (!FillKeyboardInput(app::VKEY_SHIFT, &input[i], true))
       return false;
     i++;
   }
 
   if (control) {
+    Checkpoint("FillKeyboardInput Ctrl2", start_time);
     if (!FillKeyboardInput(app::VKEY_CONTROL, &input[i], true))
       return false;
     i++;
   }
 
+  Checkpoint("SendInput called", start_time);
   if (::SendInput(i, input, sizeof(INPUT)) != i)
     return false;
 
+  Checkpoint("SendInput done", start_time);
+
   if (dispatcher.get())
     dispatcher->AddRef();
 
+  Checkpoint("Test done", start_time);
   return true;
 }
 
diff --git a/chrome/browser/ui/views/find_bar_host_interactive_uitest.cc b/chrome/browser/ui/views/find_bar_host_interactive_uitest.cc
index 9195df5..2049eb0 100644
--- a/chrome/browser/ui/views/find_bar_host_interactive_uitest.cc
+++ b/chrome/browser/ui/views/find_bar_host_interactive_uitest.cc
@@ -3,8 +3,6 @@
 // found in the LICENSE file.
 
 #include "app/keyboard_codes.h"
-#include "base/process_util.h"
-#include "base/string_number_conversions.h"
 #include "base/string_util.h"
 #include "base/utf_string_conversions.h"
 #include "chrome/browser/find_bar_controller.h"
@@ -20,11 +18,6 @@
 #include "views/focus/focus_manager.h"
 #include "views/view.h"
 
-#if defined(OS_WIN)
-#include <windows.h>
-#include <Psapi.h>
-#endif
-
 namespace {
 
 // The delay waited after sending an OS simulated event.
@@ -51,44 +44,6 @@ void Checkpoint(const char* message, const base::TimeTicks& start_time) {
     << " ms" << std::flush;
 }
 
-// Test to make sure Chrome is in the foreground as we start testing. This is
-// required for tests that synthesize input to the Chrome window.
-bool ChromeInForeground() {
-#if defined(OS_WIN)
-  HWND window = ::GetForegroundWindow();
-  std::wstring caption;
-  std::wstring filename;
-  int len = ::GetWindowTextLength(window) + 1;
-  ::GetWindowText(window, WriteInto(&caption, len), len);
-  bool chrome_window_in_foreground =
-      (caption == L"about:blank - Google Chrome");
-  if (!chrome_window_in_foreground) {
-    DWORD process_id;
-    int thread_id = ::GetWindowThreadProcessId(window, &process_id);
-
-    base::ProcessHandle process;
-    if (base::OpenProcessHandleWithAccess(process_id,
-                                          PROCESS_QUERY_LIMITED_INFORMATION,
-                                          &process)) {
-      len = MAX_PATH;
-      if (!GetProcessImageFileName(process, WriteInto(&filename, len), len)) {
-        int error = GetLastError();
-        filename = L"Unable to read filename (error " +
-                   base::IntToString16(error) + L")";
-      }
-      base::CloseProcessHandle(process);
-    }
-  }
-  EXPECT_TRUE(chrome_window_in_foreground)
-      << "Chrome must be in the foreground when running interactive tests\n"
-      << "Process in foreground: " << filename.c_str();
-  return chrome_window_in_foreground;
-#else
-  // Windows only at the moment.
-  return true;
-#endif
-}
-
 }  // namespace
 
 IN_PROC_BROWSER_TEST_F(FindInPageTest, CrashEscHandlers) {
@@ -178,15 +133,12 @@ IN_PROC_BROWSER_TEST_F(FindInPageTest, PrepopulateRespectBlank) {
   // FindInPage on Mac doesn't use prepopulated values. Search there is global.
   return;
 #endif
+
   base::TimeTicks start_time = base::TimeTicks::Now();
   Checkpoint("Starting test server", start_time);
 
   ASSERT_TRUE(test_server()->Start());
 
-  // Make sure Chrome is in the foreground, otherwise sending input
-  // won't do anything and the test will hang.
-  ASSERT_TRUE(ChromeInForeground());
-
   // First we navigate to any page.
   Checkpoint("Navigating", start_time);
   GURL url = test_server()->GetURL(kSimplePage);
diff --git a/chrome/test/ui_test_utils.cc b/chrome/test/ui_test_utils.cc
index d6310f3..b7db307 100644
--- a/chrome/test/ui_test_utils.cc
+++ b/chrome/test/ui_test_utils.cc
@@ -341,6 +341,12 @@ bool ExecuteJavaScriptHelper(RenderViewHost* render_view_host,
   return true;
 }
 
+void Checkpoint(const char* message, const base::TimeTicks& start_time) {
+  LOG(INFO) << message << " : "
+            << (base::TimeTicks::Now() - start_time).InMilliseconds()
+            << " ms" << std::flush;
+}
+
 }  // namespace
 
 void RunMessageLoop() {
@@ -606,11 +612,13 @@ bool SendKeyPressSync(const Browser* browser,
                       bool alt,
                       bool command) {
   base::TimeTicks start_time = base::TimeTicks::Now();
+  Checkpoint("SendKeyPressSync", start_time);
 
   gfx::NativeWindow window = NULL;
   if (!GetNativeWindow(browser, &window))
     return false;
 
+  Checkpoint("SendKeyPressNotifyWhenDone", start_time);
   if (!ui_controls::SendKeyPressNotifyWhenDone(
           window, key, control, shift, alt, command,
           new MessageLoop::QuitTask())) {
@@ -620,7 +628,9 @@ bool SendKeyPressSync(const Browser* browser,
   // Run the message loop. It'll stop running when either the key was received
   // or the test timed out (in which case testing::Test::HasFatalFailure should
   // be set).
+  Checkpoint("Running loop", start_time);
   RunMessageLoop();
+  Checkpoint("Check if HasFatalFailure", start_time);
   return !testing::Test::HasFatalFailure();
 }