Add moar logging for "Couldn't load plug-in" errors.

ipc/ipc_sync_channel.cc

 // Copyright (c) 2012 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 "ipc/ipc_sync_channel.h"
 
 #include "base/bind.h"
 #include "base/lazy_instance.h"
 #include "base/location.h"
 #include "base/logging.h"
@@ skipping 284 matching lines @@
 }
 
 bool SyncChannel::SyncContext::TryToUnblockListener(const Message* msg) {
   base::AutoLock auto_lock(deserializers_lock_);
   if (deserializers_.empty() ||
       !SyncMessage::IsMessageReplyTo(*msg, deserializers_.back().id)) {
     return false;
   }
 
   if (!msg->is_reply_error()) {
-    deserializers_.back().send_result = deserializers_.back().deserializer->
+    bool send_result = deserializers_.back().deserializer->
         SerializeOutputParameters(*msg);
+    deserializers_.back().send_result = send_result;
+    LOG_IF(ERROR, !send_result) << "Couldn't deserialize reply message";
+  } else {
+    LOG(ERROR) << "Received error reply";

[piman, 2012/08/10 17:06:15]

I'm afraid this is going to be spammy. There's quite a few places in Chrome
where we return "error" messages under certain legitimate conditions.
If we're going to land this, we should file a bug to remove it.

[Bernhard Bauer, 2012/08/13 07:39:35]

Added a TODO. FWIW, in my (casual) testing this didn't add much more noisiness
to the output that what is already present (we log all Javascript console
messages, for example).

   }
   deserializers_.back().done_event->Signal();
 
   return true;
 }
 
 void SyncChannel::SyncContext::Clear() {
   CancelPendingSends();
   received_sync_msgs_->RemoveContext(this);
   Context::Clear();
@@ skipping 14 matching lines @@
 
   if (msg.should_unblock()) {
     received_sync_msgs_->QueueMessage(msg, this);
     return true;
   }
 
   return Context::OnMessageReceivedNoFilter(msg);
 }
 
 void SyncChannel::SyncContext::OnChannelError() {
   CancelPendingSends();

[piman, 2012/08/10 17:06:15]

I think this is going to be one of the most common modes of failure for Send().
When we get a channel error, for example because the other side closed the
channel, we get here, cancel the Sends, so that they pop out with send_result
still false - that's not caught by your other logs.
You may want to add logging here.

[Bernhard Bauer, 2012/08/13 07:39:35]

Good catch! Added logging.

   shutdown_watcher_.StopWatching();
   Context::OnChannelError();
 }
 
 void SyncChannel::SyncContext::OnChannelOpened() {
   shutdown_watcher_.StartWatching(shutdown_event_, this);
   Context::OnChannelOpened();
 }
 
 void SyncChannel::SyncContext::OnChannelClosed() {
@@ skipping 68 matching lines @@
 
 bool SyncChannel::SendWithTimeout(Message* message, int timeout_ms) {
   if (!message->is_sync()) {
     ChannelProxy::Send(message);
     return true;
   }
 
   // *this* might get deleted in WaitForReply.
   scoped_refptr<SyncContext> context(sync_context());
   if (context->shutdown_event()->IsSignaled()) {
+    LOG(ERROR) << "shutdown event is signaled";
     delete message;
     return false;
   }
 
   DCHECK(sync_messages_with_no_timeout_allowed_ ||
          timeout_ms != base::kNoTimeout);
   SyncMessage* sync_msg = static_cast<SyncMessage*>(message);
   context->Push(sync_msg);
   int message_id = SyncMessage::GetMessageId(*sync_msg);
   WaitableEvent* pump_messages_event = sync_msg->pump_messages_event();
@@ skipping 93 matching lines @@
   // Ideally we only want to watch this object when running a nested message
   // loop.  However, we don't know when it exits if there's another nested
   // message loop running under it or not, so we wouldn't know whether to
   // stop or keep watching.  So we always watch it, and create the event as
   // manual reset since the object watcher might otherwise reset the event
   // when we're doing a WaitMany.
   dispatch_watcher_.StartWatching(sync_context()->GetDispatchEvent(), this);
 }
 
 }  // namespace IPC