Implemented VLOG() et al.

Implemented VLOG(), VLOG_IF(), VLOG_IS_ON().  Added --v and --vmodule
switches.

Changed some spammy sync-related logs to use VLOG.

BUG=56965
TEST=New unittests

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

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

base/base.gyp

@@ -161,6 +161,7 @@
         'utf_string_conversions_unittest.cc',
         'values_unittest.cc',
         'version_unittest.cc',
+        'vlog_unittest.cc',
         'waitable_event_unittest.cc',
         'waitable_event_watcher_unittest.cc',
         'watchdog_unittest.cc',

base/base.gypi

@@ -291,6 +291,8 @@
           'utf_string_conversions.h',
           'values.cc',
           'values.h',
+          'vlog.cc',
+          'vlog.h',
           'waitable_event.h',
           'waitable_event_posix.cc',
           'waitable_event_watcher.h',

base/base_switches.cc

@@ -31,6 +31,16 @@ const char kNoMessageBox[]                  = "no-message-box";
 // to the test framework that the current process is a child process.
 const char kTestChildProcess[]              = "test-child-process";
 
+// Gives the default maximal active V-logging level; 0 is the default.
+// Normally positive values are used for V-logging levels.
+const char kV[]                             = "v";
+
+// Gives the per-module maximal V-logging levels to override the value
+// given by --v.  E.g. "my_module=2,foo*=3" would change the logging
+// level for all code in source files "my_module.*" and "foo*.*"
+// ("-inl" suffixes are also disregarded for this matching).
+const char kVModule[]                       = "vmodule";
+
 // Will wait for 60 seconds for a debugger to come to attach to the process.
 const char kWaitForDebugger[]               = "wait-for-debugger";
 

base/base_switches.h

@@ -17,6 +17,8 @@ extern const char kFullMemoryCrashReport[];
 extern const char kNoErrorDialogs[];
 extern const char kNoMessageBox[];
 extern const char kTestChildProcess[];
+extern const char kV[];
+extern const char kVModule[];
 extern const char kWaitForDebugger[];
 
 }  // namespace switches

base/logging.cc

@@ -51,10 +51,12 @@ typedef pthread_mutex_t* MutexHandle;
 #include "base/process_util.h"
 #include "base/string_piece.h"
 #include "base/utf_string_conversions.h"
+#include "base/vlog.h"
 
 namespace logging {
 
 bool g_enable_dcheck = false;
+VlogInfo* g_vlog_info = NULL;
 
 const char* const log_severity_names[LOG_NUM_SEVERITIES] = {
   "INFO", "WARNING", "ERROR", "ERROR_REPORT", "FATAL" };
@@ -329,8 +331,20 @@ void BaseInitLoggingImpl(const PathChar* new_log_file,
                          LoggingDestination logging_dest,
                          LogLockingState lock_log,
                          OldFileDeletionState delete_old) {
+  CommandLine* command_line = CommandLine::ForCurrentProcess();
   g_enable_dcheck =
-      CommandLine::ForCurrentProcess()->HasSwitch(switches::kEnableDCHECK);
+      command_line->HasSwitch(switches::kEnableDCHECK);
+  delete g_vlog_info;
+  g_vlog_info = NULL;
+  // Don't bother initializing g_vlog_info unless we use one of the
+  // vlog switches.
+  if (command_line->HasSwitch(switches::kV) ||
+      command_line->HasSwitch(switches::kVModule)) {
+    g_vlog_info =
+        new VlogInfo(command_line->GetSwitchValueASCII(switches::kV),
+                     command_line->GetSwitchValueASCII(switches::kVModule));
+  }
+
   LoggingLock::Init(lock_log, new_log_file);
 
   LoggingLock logging_lock;
@@ -367,6 +381,13 @@ int GetMinLogLevel() {
   return min_log_level;
 }
 
+int GetVlogLevelHelper(const char* file, size_t N) {
+  DCHECK_GT(N, 0U);
+  return g_vlog_info ?
+      g_vlog_info->GetVlogLevel(base::StringPiece(file, N - 1)) :
+      VlogInfo::kDefaultVlogLevel;
+}
+
 void SetLogFilterPrefix(const char* filter)  {
   if (log_filter_prefix) {
     delete log_filter_prefix;

base/logging.h

@@ -74,6 +74,39 @@
 //
 // which is syntactic sugar for {,D}LOG_IF(FATAL, assert fails) << assertion;
 //
+// There are "verbose level" logging macros.  They look like
+//
+//   VLOG(1) << "I'm printed when you run the program with --v=1 or more";
+//   VLOG(2) << "I'm printed when you run the program with --v=2 or more";
+//
+// These always log at the INFO log level (when they log at all).
+// The verbose logging can also be turned on module-by-module.  For instance,
+//    --vmodule=profile=2,icon_loader=1,browser_*=3 --v=0
+// will cause:
+//   a. VLOG(2) and lower messages to be printed from profile.{h,cc}
+//   b. VLOG(1) and lower messages to be printed from icon_loader.{h,cc}
+//   c. VLOG(3) and lower messages to be printed from files prefixed with
+//      "browser"
+//   d. VLOG(0) and lower messages to be printed from elsewhere
+//
+// The wildcarding functionality shown by (c) supports both '*' (match
+// 0 or more characters) and '?' (match any single character) wildcards.
+//
+// There's also VLOG_IS_ON(n) "verbose level" condition macro. To be used as
+//
+//   if (VLOG_IS_ON(2)) {
+//     // do some logging preparation and logging
+//     // that can't be accomplished with just VLOG(2) << ...;
+//   }
+//
+// There is also a VLOG_IF "verbose level" condition macro for sample
+// cases, when some extra computation and preparation for logs is not
+// needed.
+//
+//   VLOG_IF(1, (size > 1024))
+//      << "I'm printed when size is more than 1024 and when you run the "
+//         "program with --v=1 or more";
+//
 // We also override the standard 'assert' to use 'DLOG_ASSERT'.
 //
 // Lastly, there is:
@@ -177,6 +210,15 @@ void SetMinLogLevel(int level);
 // Gets the current log level.
 int GetMinLogLevel();
 
+// Gets the current vlog level for the given file (usually taken from
+// __FILE__).
+template <size_t N>
+int GetVlogLevel(const char (&file)[N]) {
+  return GetVlogLevelHelper(file, N);
+}
+// Note that |N| is the size *with* the null terminator.
+int GetVlogLevelHelper(const char* file_start, size_t N);
+
 // Sets the log filter prefix.  Any log message below LOG_ERROR severity that
 // doesn't start with this prefix with be silently ignored.  The filter defaults
 // to NULL (everything is logged) if this function is not called.  Messages
@@ -279,13 +321,25 @@ const LogSeverity LOG_DFATAL_LEVEL = LOG_FATAL;
 // impossible to stream something like a string directly to an unnamed
 // ostream. We employ a neat hack by calling the stream() member
 // function of LogMessage which seems to avoid the problem.
+//
+// We can't do any caching tricks with VLOG_IS_ON() like the
+// google-glog version since it requires GCC extensions.  This means
+// that using the v-logging functions in conjunction with --vmodule
+// may be slow.
+#define VLOG_IS_ON(verboselevel) \
+  (logging::GetVlogLevel(__FILE__) >= (verboselevel))
 
 #define LOG(severity) COMPACT_GOOGLE_LOG_ ## severity.stream()
 #define SYSLOG(severity) LOG(severity)
+#define VLOG(verboselevel) LOG_IF(INFO, VLOG_IS_ON(verboselevel))
+
+// TODO(akalin): Add more VLOG variants, e.g. VPLOG.
 
 #define LOG_IF(severity, condition) \
   !(condition) ? (void) 0 : logging::LogMessageVoidify() & LOG(severity)
 #define SYSLOG_IF(severity, condition) LOG_IF(severity, condition)
+#define VLOG_IF(verboselevel, condition) \
+  LOG_IF(INFO, (condition) && VLOG_IS_ON(verboselevel))
 
 #define LOG_ASSERT(condition)  \
   LOG_IF(FATAL, !(condition)) << "Assert failed: " #condition ". "

base/string_util.cc

@@ -1113,9 +1113,10 @@ struct NextCharUTF16 {
   }
 };
 
-bool MatchPattern(const std::string& eval, const std::string& pattern) {
+bool MatchPattern(const base::StringPiece& eval,
-  return MatchPatternT(eval.c_str(), eval.c_str() + eval.size(),
+                  const base::StringPiece& pattern) {
-                       pattern.c_str(), pattern.c_str() + pattern.size(),
+  return MatchPatternT(eval.data(), eval.data() + eval.size(),
+                       pattern.data(), pattern.data() + pattern.size(),
                        0, NextCharUTF8());
 }
 

base/string_util.h

@@ -558,7 +558,8 @@ bool ElideString(const std::wstring& input, int max_len, std::wstring* output);
 // string can contain wildcards like * and ?
 // The backslash character (\) is an escape character for * and ?
 // We limit the patterns to having a max of 16 * or ? characters.
-bool MatchPattern(const std::string& string, const std::string& pattern);
+bool MatchPattern(const base::StringPiece& string,
+                  const base::StringPiece& pattern);
 bool MatchPattern(const string16& string, const string16& pattern);
 
 // Hack to convert any char-like type to its unsigned counterpart.

base/vlog.cc

@@ -0,0 +1,69 @@
+// Copyright (c) 2010 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 "base/vlog.h"
+
+#include "base/basictypes.h"
+#include "base/string_number_conversions.h"
+#include "base/string_split.h"
+#include "base/string_util.h"
+
+namespace logging {
+
+const int VlogInfo::kDefaultVlogLevel = 0;
+
+VlogInfo::VlogInfo(const std::string& v_switch,
+                   const std::string& vmodule_switch)
+    : max_vlog_level_(kDefaultVlogLevel) {
+  typedef std::pair<std::string, std::string> KVPair;
+  if (!base::StringToInt(v_switch, &max_vlog_level_)) {
+    LOG(WARNING) << "Parsed v switch \""
+                 << v_switch << "\" as " << max_vlog_level_;
+  }
+  std::vector<KVPair> kv_pairs;
+  if (!base::SplitStringIntoKeyValuePairs(
+          vmodule_switch, '=', ',', &kv_pairs)) {
+    LOG(WARNING) << "Could not fully parse vmodule switch \""
+                 << vmodule_switch << "\"";
+  }
+  for (std::vector<KVPair>::const_iterator it = kv_pairs.begin();
+       it != kv_pairs.end(); ++it) {
+    int vlog_level = kDefaultVlogLevel;
+    if (!base::StringToInt(it->second, &vlog_level)) {
+      LOG(WARNING) << "Parsed vlog level for \""
+                   << it->first << "=" << it->second
+                   << "\" as " << vlog_level;
+    }
+    vmodule_levels_.push_back(std::make_pair(it->first, vlog_level));
+  }
+}
+
+int VlogInfo::GetVlogLevel(const base::StringPiece& file) {
+  if (!vmodule_levels_.empty()) {
+    base::StringPiece module(file);
+    base::StringPiece::size_type last_slash_pos =
+        module.find_last_of("\\/");
+    if (last_slash_pos != base::StringPiece::npos) {
+      module.remove_prefix(last_slash_pos + 1);
+    }
+    base::StringPiece::size_type extension_start = module.find('.');
+    module = module.substr(0, extension_start);
+    static const char kInlSuffix[] = "-inl";
+    static const int kInlSuffixLen = arraysize(kInlSuffix) - 1;
+    if (module.ends_with(kInlSuffix)) {
+      module.remove_suffix(kInlSuffixLen);
+    }
+    for (std::vector<VmodulePattern>::const_iterator it =
+             vmodule_levels_.begin(); it != vmodule_levels_.end(); ++it) {
+      // TODO(akalin): Use a less-heavyweight version of MatchPattern
+      // (we can pretty much assume we're dealing with ASCII).
+      if (MatchPattern(module, it->first)) {
+        return it->second;
+      }
+    }
+  }
+  return max_vlog_level_;
+}
+
+}  // namespace

base/vlog.h

@@ -0,0 +1,51 @@
+// Copyright (c) 2010 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.
+
+#ifndef BASE_VLOG_H_
+#define BASE_VLOG_H_
+#pragma once
+
+#include <cstddef>
+#include <string>
+#include <utility>
+#include <vector>
+
+#include "base/basictypes.h"
+#include "base/string_piece.h"
+
+namespace logging {
+
+// A helper class containing all the settings for vlogging.
+class VlogInfo {
+ public:
+  // |v_switch| gives the default maximal active V-logging level; 0 is
+  // the default.  Normally positive values are used for V-logging
+  // levels.
+  //
+  // |vmodule_switch| gives the per-module maximal V-logging levels to
+  // override the value given by |v_switch|.
+  // E.g. "my_module=2,foo*=3" would change the logging level for all
+  // code in source files "my_module.*" and "foo*.*" ("-inl" suffixes
+  // are also disregarded for this matching).
+  VlogInfo(const std::string& v_switch,
+           const std::string& vmodule_switch);
+
+  // Returns the vlog level for a given file (usually taken from
+  // __FILE__).
+  int GetVlogLevel(const base::StringPiece& file);
+
+  static const int kDefaultVlogLevel;
+
+ private:
+  typedef std::pair<std::string, int> VmodulePattern;
+
+  int max_vlog_level_;
+  std::vector<VmodulePattern> vmodule_levels_;
+
+  DISALLOW_COPY_AND_ASSIGN(VlogInfo);
+};
+
+}  // namespace logging
+
+#endif  // BASE_VLOG_H_

base/vlog_unittest.cc

@@ -0,0 +1,105 @@
+// Copyright (c) 2010 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 "base/vlog.h"
+
+#include "base/basictypes.h"
+#include "base/logging.h"
+#include "base/time.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace logging {
+
+namespace {
+
+class VlogTest : public testing::Test {
+};
+
+TEST_F(VlogTest, NoVmodule) {
+  EXPECT_EQ(0, VlogInfo("", "").GetVlogLevel("test1"));
+  EXPECT_EQ(0, VlogInfo("0", "").GetVlogLevel("test2"));
+  EXPECT_EQ(0, VlogInfo("blah", "").GetVlogLevel("test3"));
+  EXPECT_EQ(0, VlogInfo("0blah1", "").GetVlogLevel("test4"));
+  EXPECT_EQ(1, VlogInfo("1", "").GetVlogLevel("test5"));
+  EXPECT_EQ(5, VlogInfo("5", "").GetVlogLevel("test6"));
+}
+
+TEST_F(VlogTest, Vmodule) {
+  const char kVSwitch[] = "-1";
+  const char kVModuleSwitch[] =
+      "foo=,bar=0,baz=blah,,qux=0blah1,quux=1,corge=5";
+  VlogInfo vlog_info(kVSwitch, kVModuleSwitch);
+  EXPECT_EQ(-1, vlog_info.GetVlogLevel("/path/to/grault.cc"));
+  EXPECT_EQ(0, vlog_info.GetVlogLevel("/path/to/foo.cc"));
+  EXPECT_EQ(0, vlog_info.GetVlogLevel("D:\\Path\\To\\bar-inl.mm"));
+  EXPECT_EQ(-1, vlog_info.GetVlogLevel("D:\\path\\to what/bar_unittest.m"));
+  EXPECT_EQ(0, vlog_info.GetVlogLevel("baz.h"));
+  EXPECT_EQ(0, vlog_info.GetVlogLevel("/another/path/to/qux.h"));
+  EXPECT_EQ(1, vlog_info.GetVlogLevel("/path/to/quux"));
+  EXPECT_EQ(5, vlog_info.GetVlogLevel("c:\\path/to/corge.h"));
+}
+
+#define BENCHMARK(iters, elapsed, code)                         \
+  do {                                                          \
+    base::TimeTicks start = base::TimeTicks::Now();             \
+    for (int i = 0; i < iters; ++i) code;                       \
+    base::TimeTicks end = base::TimeTicks::Now();               \
+    elapsed = end - start;                                      \
+    double cps = iters / elapsed.InSecondsF();                  \
+    LOG(INFO) << cps << " cps (" << elapsed.InSecondsF()        \
+              << "s elapsed)";                                  \
+  } while (0)
+
+double GetSlowdown(const base::TimeDelta& base,
+                   const base::TimeDelta& elapsed) {
+  return elapsed.InSecondsF() / base.InSecondsF();
+}
+
+
+TEST_F(VlogTest, Perf) {
+  const char* kVlogs[] = {
+    "/path/to/foo.cc",
+    "C:\\path\\to\\bar.h",
+    "/path/to/not-matched.mm",
+    "C:\\path\\to\\baz-inl.mm",
+    "C:\\path\\to\\qux.mm",
+    "/path/to/quux.mm",
+    "/path/to/another-not-matched.mm",
+  };
+  const int kVlogCount = arraysize(kVlogs);
+
+  base::TimeDelta null_elapsed;
+  {
+    VlogInfo null_vlog_info("", "");
+    BENCHMARK(10000000, null_elapsed, {
+      EXPECT_NE(-1, null_vlog_info.GetVlogLevel(kVlogs[i % kVlogCount]));
+    });
+  }
+
+  {
+    VlogInfo small_vlog_info("0", "foo=1,bar=2,baz=3,qux=4,quux=5");
+    base::TimeDelta elapsed;
+    BENCHMARK(10000000, elapsed, {
+      EXPECT_NE(-1, small_vlog_info.GetVlogLevel(kVlogs[i % kVlogCount]));
+    });
+    LOG(INFO) << "slowdown = " << GetSlowdown(null_elapsed, elapsed)
+              << "x";
+  }
+
+  {
+    VlogInfo pattern_vlog_info("0", "fo*=1,ba?=2,b*?z=3,*ux=4,?uux=5");
+    base::TimeDelta elapsed;
+    BENCHMARK(10000000, elapsed, {
+      EXPECT_NE(-1, pattern_vlog_info.GetVlogLevel(kVlogs[i % kVlogCount]));
+    });
+    LOG(INFO) << "slowdown = " << GetSlowdown(null_elapsed, elapsed)
+              << "x";
+  }
+}
+
+#undef BENCHMARK
+
+}  // namespace
+
+}  // namespace logging

chrome/browser/sync/notifier/cache_invalidation_packet_handler.cc

@@ -46,17 +46,17 @@ class CacheInvalidationListenTask : public buzz::XmppTask {
   virtual ~CacheInvalidationListenTask() {}
 
   virtual int ProcessStart() {
-    LOG(INFO) << "CacheInvalidationListenTask started";
+    VLOG(2) << "CacheInvalidationListenTask started";
     return STATE_RESPONSE;
   }
 
   virtual int ProcessResponse() {
     const buzz::XmlElement* stanza = NextStanza();
     if (stanza == NULL) {
-      LOG(INFO) << "CacheInvalidationListenTask blocked";
+      VLOG(2) << "CacheInvalidationListenTask blocked";
       return STATE_BLOCKED;
     }
-    LOG(INFO) << "CacheInvalidationListenTask response received";
+    VLOG(2) << "CacheInvalidationListenTask response received";
     std::string data;
     if (GetCacheInvalidationIqPacketData(stanza, &data)) {
       callback_->Run(data);
@@ -71,14 +71,14 @@ class CacheInvalidationListenTask : public buzz::XmppTask {
   }
 
   virtual bool HandleStanza(const buzz::XmlElement* stanza) {
-    LOG(INFO) << "Stanza received: "
+    VLOG(1) << "Stanza received: "
               << notifier::XmlElementToString(*stanza);
     if (IsValidCacheInvalidationIqPacket(stanza)) {
-      LOG(INFO) << "Queueing stanza";
+      VLOG(2) << "Queueing stanza";
       QueueStanza(stanza);
       return true;
     }
-    LOG(INFO) << "Stanza skipped";
+    VLOG(2) << "Stanza skipped";
     return false;
   }
 
@@ -128,10 +128,10 @@ class CacheInvalidationSendMessageTask : public buzz::XmppTask {
     scoped_ptr<buzz::XmlElement> stanza(
         MakeCacheInvalidationIqPacket(to_jid_, task_id(), msg_,
                                       seq_, sid_));
-    LOG(INFO) << "Sending message: "
+    VLOG(1) << "Sending message: "
               << notifier::XmlElementToString(*stanza.get());
     if (SendStanza(stanza.get()) != buzz::XMPP_RETURN_OK) {
-      LOG(INFO) << "Error when sending message";
+      VLOG(2) << "Error when sending message";
       return STATE_ERROR;
     }
     return STATE_RESPONSE;
@@ -140,23 +140,23 @@ class CacheInvalidationSendMessageTask : public buzz::XmppTask {
   virtual int ProcessResponse() {
     const buzz::XmlElement* stanza = NextStanza();
     if (stanza == NULL) {
-      LOG(INFO) << "CacheInvalidationSendMessageTask blocked...";
+      VLOG(2) << "CacheInvalidationSendMessageTask blocked...";
       return STATE_BLOCKED;
     }
-    LOG(INFO) << "CacheInvalidationSendMessageTask response received: "
+    VLOG(2) << "CacheInvalidationSendMessageTask response received: "
               << notifier::XmlElementToString(*stanza);
     // TODO(akalin): Handle errors here.
     return STATE_DONE;
   }
 
   virtual bool HandleStanza(const buzz::XmlElement* stanza) {
-    LOG(INFO) << "Stanza received: "
+    VLOG(1) << "Stanza received: "
               << notifier::XmlElementToString(*stanza);
     if (!MatchResponseIq(stanza, to_jid_, task_id())) {
-      LOG(INFO) << "Stanza skipped";
+      VLOG(2) << "Stanza skipped";
       return false;
     }
-    LOG(INFO) << "Queueing stanza";
+    VLOG(2) << "Queueing stanza";
     QueueStanza(stanza);
     return true;
   }

chrome/browser/sync/notifier/chrome_invalidation_client.cc

@@ -96,7 +96,7 @@ void ChromeInvalidationClient::Invalidate(
     invalidation::Closure* callback) {
   DCHECK(non_thread_safe_.CalledOnValidThread());
   DCHECK(invalidation::IsCallbackRepeatable(callback));
-  LOG(INFO) << "Invalidate: " << InvalidationToString(invalidation);
+  VLOG(1) << "Invalidate: " << InvalidationToString(invalidation);
   syncable::ModelType model_type;
   if (ObjectIdToRealModelType(invalidation.object_id(), &model_type)) {
     listener_->OnInvalidate(model_type);
@@ -112,7 +112,7 @@ void ChromeInvalidationClient::InvalidateAll(
     invalidation::Closure* callback) {
   DCHECK(non_thread_safe_.CalledOnValidThread());
   DCHECK(invalidation::IsCallbackRepeatable(callback));
-  LOG(INFO) << "InvalidateAll";
+  VLOG(1) << "InvalidateAll";
   listener_->OnInvalidateAll();
   RunAndDeleteClosure(callback);
 }
@@ -121,7 +121,7 @@ void ChromeInvalidationClient::AllRegistrationsLost(
     invalidation::Closure* callback) {
   DCHECK(non_thread_safe_.CalledOnValidThread());
   DCHECK(invalidation::IsCallbackRepeatable(callback));
-  LOG(INFO) << "AllRegistrationsLost";
+  VLOG(1) << "AllRegistrationsLost";
   registration_manager_->MarkAllRegistrationsLost();
   RunAndDeleteClosure(callback);
 }
@@ -131,7 +131,7 @@ void ChromeInvalidationClient::RegistrationLost(
     invalidation::Closure* callback) {
   DCHECK(non_thread_safe_.CalledOnValidThread());
   DCHECK(invalidation::IsCallbackRepeatable(callback));
-  LOG(INFO) << "RegistrationLost: " << ObjectIdToString(object_id);
+  VLOG(1) << "RegistrationLost: " << ObjectIdToString(object_id);
   syncable::ModelType model_type;
   if (ObjectIdToRealModelType(object_id, &model_type)) {
     registration_manager_->MarkRegistrationLost(model_type);

jingle/notifier/base/xmpp_connection.cc

@@ -121,12 +121,12 @@ void XmppConnection::OnStateChange(buzz::XmppEngine::State state) {
 
 void XmppConnection::OnInputLog(const char* data, int len) {
   DCHECK(non_thread_safe_.CalledOnValidThread());
-  LOG(INFO) << "XMPP Input: " << base::StringPiece(data, len);
+  VLOG(2) << "XMPP Input: " << base::StringPiece(data, len);
 }
 
 void XmppConnection::OnOutputLog(const char* data, int len) {
   DCHECK(non_thread_safe_.CalledOnValidThread());
-  LOG(INFO) << "XMPP Output: " << base::StringPiece(data, len);
+  VLOG(2) << "XMPP Output: " << base::StringPiece(data, len);
 }
 
 void XmppConnection::ClearClient() {