Add some more temporary traces to narrow down the cause of failure.

These will be removed once I have more data.

It looks like the keyboard hook is not seeing the WM_KEYUP message
so the loop never terminates. This should verify that.

TBR=phadjan.jr
BUG=62937
TEST=Tracking down problem in test


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

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

1 files changed, 21 insertions, 7 deletions

diff --git a/chrome/browser/automation/ui_controls_win.cc b/chrome/browser/automation/ui_controls_win.cc
index 2b41be1..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
@@ -71,12 +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);
 }
 
@@ -161,12 +181,6 @@ bool SendKeyEvent(app::KeyboardCode key, bool up) {
   return true;
 }
 
-void Checkpoint(const char* message, const base::TimeTicks& start_time) {
-  LOG(INFO) << message << " : "
-            << (base::TimeTicks::Now() - start_time).InMilliseconds()
-            << " ms" << std::flush;
-}
-
 bool SendKeyPressImpl(app::KeyboardCode key,
                       bool control, bool shift, bool alt,
                       Task* task) {