dbus: Fix a subtle butterfly-effect bug in handling incoming messages

libdbus does bookkeeping of the number of bytes in the incoming message
queue implicitly, and asks client code (chrome) to stop monitoring the
underlying socket, as soon as it exceeds a certain number, which is set
to 63MB as of now.

This caused a DCHECK failure (and could break the D-Bus message
dispatching with Release builds) because the bookkeeping happned on the
UI thread via a seemingly harmless call to dbus_message_unref(), but we
cannot stop monitoring from UI thread.

This patch fixes (or works around) the problem by deleting incoming
messages on D-Bus thread, so the bookkeeping is done on D-Bus thread.

Note that we don't have to change exported_object.cc, as the method call
message is deleted on the D-Bus thread in
ExportedObject::OnMethodCompleted()

The following is a stacktrace of the DCHECK failure. Here,
dbus::Response (method reply) is deleted on UI thread, that results
in a call to dbus::Bus::OnToggleWatch, which should only be called on
the D-Bus thread, hence crashed as a DCHECK failure


Backtrace:
	base::debug::StackTrace::StackTrace() [0x517972]
	logging::LogMessage::~LogMessage() [0x4b3a57] <- crashing because we are not
	base::ThreadRestrictions::AssertIOAllowed() [0x4f0b35]
	dbus::Bus::AssertOnDBusThread() [0x45ceb6] <- checking if we are on the right thread
	dbus::Bus::OnToggleWatch() [0x45d0c1]
	dbus::Bus::OnToggleWatchThunk() [0x45d45d]  <-- the change is notified.
	_dbus_watch_list_toggle_watch [0x7f35e0a15245]
	protected_change_watch [0x7f35e09f2eef]
	_dbus_connection_toggle_watch_unlocked [0x7f35e09f302e]
	check_read_watch [0x7f35e0a1332d]   <-- what? why checking socket status here??
	socket_live_messages_changed [0x7f35e0a1436c]
	live_messages_size_notify [0x7f35e0a11996]
	_dbus_counter_adjust [0x7f35e0a0c098]
	free_size_counter [0x7f35e0a04423]
	_dbus_list_foreach [0x7f35e0a180d9]
	dbus_message_cache_or_finalize [0x7f35e0a0446b]
	dbus_message_unref [0x7f35e0a05e7e]   <-- releasing a message
	dbus::Message::~Message() [0x46abbb]
	dbus::Response::~Response() [0x470478]
	scoped_ptr<>::~scoped_ptr() [0x41e99f]
	dbus::ObjectProxy::RunResponseCallback() [0x472095]

BUG=126217
TEST=added unit tests

Review URL: https://chromiumcodereview.appspot.com/10492005

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

2 files changed, 69 insertions, 1 deletions

diff --git a/dbus/end_to_end_async_unittest.cc b/dbus/end_to_end_async_unittest.cc
index d5e278f..7715f7d 100644
--- a/dbus/end_to_end_async_unittest.cc
+++ b/dbus/end_to_end_async_unittest.cc
@@ -20,6 +20,14 @@
 #include "dbus/test_service.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
+namespace {
+
+// See comments in ObjectProxy::RunResponseCallback() for why the number was
+// chosen.
+const int kHugePayloadSize = 64 << 20;  // 64 MB
+
+}  // namespace
+
 // The end-to-end test exercises the asynchronous APIs in ObjectProxy and
 // ExportedObject.
 class EndToEndAsyncTest : public testing::Test {
@@ -313,6 +321,23 @@ TEST_F(EndToEndAsyncTest, EchoThreeTimes) {
   EXPECT_EQ("foo", response_strings_[2]);
 }
 
+TEST_F(EndToEndAsyncTest, Echo_HugePayload) {
+  const std::string kHugePayload(kHugePayloadSize, 'o');
+
+  // Create the method call with a huge payload.
+  dbus::MethodCall method_call("org.chromium.TestInterface", "Echo");
+  dbus::MessageWriter writer(&method_call);
+  writer.AppendString(kHugePayload);
+
+  // Call the method.
+  const int timeout_ms = dbus::ObjectProxy::TIMEOUT_USE_DEFAULT;
+  CallMethod(&method_call, timeout_ms);
+
+  // This caused a DCHECK failure before. Ensure that the issue is fixed.
+  WaitForResponses(1);
+  EXPECT_EQ(kHugePayload, response_strings_[0]);
+}
+
 TEST_F(EndToEndAsyncTest, BrokenBus) {
   const char* kHello = "hello";
 
@@ -537,6 +562,16 @@ TEST_F(EndToEndAsyncTest, TestSignalFromRoot) {
   ASSERT_EQ(kMessage, root_test_signal_string_);
 }
 
+TEST_F(EndToEndAsyncTest, TestHugeSignal) {
+  const std::string kHugeMessage(kHugePayloadSize, 'o');
+
+  // Send the huge signal from the exported object.
+  test_service_->SendTestSignal(kHugeMessage);
+  // This caused a DCHECK failure before. Ensure that the issue is fixed.
+  WaitForTestSignal();
+  ASSERT_EQ(kHugeMessage, test_signal_string_);
+}
+
 class SignalReplacementTest : public EndToEndAsyncTest {
  public:
   SignalReplacementTest() {
diff --git a/dbus/object_proxy.cc b/dbus/object_proxy.cc
index ea5f330..62c0eb8 100644
--- a/dbus/object_proxy.cc
+++ b/dbus/object_proxy.cc
@@ -277,12 +277,40 @@ void ObjectProxy::RunResponseCallback(ResponseCallback response_callback,
     scoped_ptr<dbus::ErrorResponse> error_response(
         dbus::ErrorResponse::FromRawMessage(response_message));
     error_callback.Run(error_response.get());
+    // Delete the message  on the D-Bus thread. See below for why.
+    bus_->PostTaskToDBusThread(
+        FROM_HERE,
+        base::Bind(&base::DeletePointer<dbus::ErrorResponse>,
+                   error_response.release()));
   } else {
     // This will take |response_message| and release (unref) it.
     scoped_ptr<dbus::Response> response(
         dbus::Response::FromRawMessage(response_message));
     // The response is successfully received.
     response_callback.Run(response.get());
+    // The message should be deleted on the D-Bus thread for a complicated
+    // reason:
+    //
+    // libdbus keeps track of the number of bytes in the incoming message
+    // queue to ensure that the data size in the queue is manageable. The
+    // bookkeeping is partly done via dbus_message_unref(), and immediately
+    // asks the client code (Chrome) to stop monitoring the underlying
+    // socket, if the number of bytes exceeds a certian number, which is set
+    // to 63MB, per dbus-transport.cc:
+    //
+    //   /* Try to default to something that won't totally hose the system,
+    //    * but doesn't impose too much of a limitation.
+    //    */
+    //   transport->max_live_messages_size = _DBUS_ONE_MEGABYTE * 63;
+    //
+    // The monitoring of the socket is done on the D-Bus thread (see Watch
+    // class in bus.cc), hence we should stop the monitoring from D-Bus
+    // thread, not from the current thread here, which is likely UI thread.
+    bus_->PostTaskToDBusThread(
+        FROM_HERE,
+        base::Bind(&base::DeletePointer<dbus::Response>,
+                   response.release()));
+
     method_call_successful = true;
     // Record time spent for the method call. Don't include failures.
     UMA_HISTOGRAM_TIMES("DBus.AsyncMethodCallTime",
@@ -438,7 +466,12 @@ void ObjectProxy::RunMethod(base::TimeTicks start_time,
   bus_->AssertOnOriginThread();
 
   signal_callback.Run(signal);
-  delete signal;
+  // Delete the message on the D-Bus thread. See comments in
+  // RunResponseCallback().
+  bus_->PostTaskToDBusThread(
+      FROM_HERE,
+      base::Bind(&base::DeletePointer<dbus::Signal>, signal));
+
   // Record time spent for handling the signal.
   UMA_HISTOGRAM_TIMES("DBus.SignalHandleTime",
                       base::TimeTicks::Now() - start_time);