Print a warning when a message channel is used on the wrong thread. (#42928)

Fixes flutter/flutter#128746

Prints a warning the first time a platform channel sends a message from the wrong thread with instructions/link to the site about how to fix this.

Author: dnfield

ci/licenses_golden/licenses_flutter

@@ -899,6 +899,7 @@ ORIGIN: ../../../flutter/fml/memory/ref_ptr.h + ../../../flutter/LICENSE
 ORIGIN: ../../../flutter/fml/memory/ref_ptr_internal.h + ../../../flutter/LICENSE
 ORIGIN: ../../../flutter/fml/memory/task_runner_checker.cc + ../../../flutter/LICENSE
 ORIGIN: ../../../flutter/fml/memory/task_runner_checker.h + ../../../flutter/LICENSE
+ORIGIN: ../../../flutter/fml/memory/thread_checker.cc + ../../../flutter/LICENSE
 ORIGIN: ../../../flutter/fml/memory/thread_checker.h + ../../../flutter/LICENSE
 ORIGIN: ../../../flutter/fml/memory/weak_ptr.h + ../../../flutter/LICENSE
 ORIGIN: ../../../flutter/fml/memory/weak_ptr_internal.cc + ../../../flutter/LICENSE
@@ -3577,6 +3578,7 @@ FILE: ../../../flutter/fml/memory/ref_ptr.h
 FILE: ../../../flutter/fml/memory/ref_ptr_internal.h
 FILE: ../../../flutter/fml/memory/task_runner_checker.cc
 FILE: ../../../flutter/fml/memory/task_runner_checker.h
+FILE: ../../../flutter/fml/memory/thread_checker.cc
 FILE: ../../../flutter/fml/memory/thread_checker.h
 FILE: ../../../flutter/fml/memory/weak_ptr.h
 FILE: ../../../flutter/fml/memory/weak_ptr_internal.cc

fml/BUILD.gn

@@ -47,6 +47,7 @@ source_set("fml") {
     "memory/ref_ptr_internal.h",
     "memory/task_runner_checker.cc",
     "memory/task_runner_checker.h",
+    "memory/thread_checker.cc",
     "memory/thread_checker.h",
     "memory/weak_ptr.h",
     "memory/weak_ptr_internal.cc",

fml/logging.cc

@@ -72,61 +72,78 @@ LogMessage::LogMessage(LogSeverity severity,
   }
 }
 
+// static
+thread_local std::ostringstream* LogMessage::capture_next_log_stream_ = nullptr;
+
+void CaptureNextLog(std::ostringstream* stream) {
+  LogMessage::CaptureNextLog(stream);
+}
+
+// static
+void LogMessage::CaptureNextLog(std::ostringstream* stream) {
+  LogMessage::capture_next_log_stream_ = stream;
+}
+
 LogMessage::~LogMessage() {
 #if !defined(OS_FUCHSIA)
   stream_ << std::endl;
 #endif
 
+  if (capture_next_log_stream_) {
+    *capture_next_log_stream_ << stream_.str();
+    capture_next_log_stream_ = nullptr;
+  } else {
 #if defined(FML_OS_ANDROID)
-  android_LogPriority priority =
-      (severity_ < 0) ? ANDROID_LOG_VERBOSE : ANDROID_LOG_UNKNOWN;
-  switch (severity_) {
-    case LOG_INFO:
-      priority = ANDROID_LOG_INFO;
-      break;
-    case LOG_WARNING:
-      priority = ANDROID_LOG_WARN;
-      break;
-    case LOG_ERROR:
-      priority = ANDROID_LOG_ERROR;
-      break;
-    case LOG_FATAL:
-      priority = ANDROID_LOG_FATAL;
-      break;
-  }
-  __android_log_write(priority, "flutter", stream_.str().c_str());
+    android_LogPriority priority =
+        (severity_ < 0) ? ANDROID_LOG_VERBOSE : ANDROID_LOG_UNKNOWN;
+    switch (severity_) {
+      case LOG_INFO:
+        priority = ANDROID_LOG_INFO;
+        break;
+      case LOG_WARNING:
+        priority = ANDROID_LOG_WARN;
+        break;
+      case LOG_ERROR:
+        priority = ANDROID_LOG_ERROR;
+        break;
+      case LOG_FATAL:
+        priority = ANDROID_LOG_FATAL;
+        break;
+    }
+    __android_log_write(priority, "flutter", stream_.str().c_str());
 #elif defined(FML_OS_IOS)
-  syslog(LOG_ALERT, "%s", stream_.str().c_str());
+    syslog(LOG_ALERT, "%s", stream_.str().c_str());
 #elif defined(OS_FUCHSIA)
-  fx_log_severity_t fx_severity;
-  switch (severity_) {
-    case LOG_INFO:
-      fx_severity = FX_LOG_INFO;
-      break;
-    case LOG_WARNING:
-      fx_severity = FX_LOG_WARNING;
-      break;
-    case LOG_ERROR:
-      fx_severity = FX_LOG_ERROR;
-      break;
-    case LOG_FATAL:
-      fx_severity = FX_LOG_FATAL;
-      break;
-    default:
-      if (severity_ < 0) {
-        fx_severity = fx_log_severity_from_verbosity(-severity_);
-      } else {
-        // Unknown severity. Use INFO.
+    fx_log_severity_t fx_severity;
+    switch (severity_) {
+      case LOG_INFO:
         fx_severity = FX_LOG_INFO;
-      }
-  }
-  fx_logger_log_with_source(fx_log_get_logger(), fx_severity, nullptr, file_,
-                            line_, stream_.str().c_str());
+        break;
+      case LOG_WARNING:
+        fx_severity = FX_LOG_WARNING;
+        break;
+      case LOG_ERROR:
+        fx_severity = FX_LOG_ERROR;
+        break;
+      case LOG_FATAL:
+        fx_severity = FX_LOG_FATAL;
+        break;
+      default:
+        if (severity_ < 0) {
+          fx_severity = fx_log_severity_from_verbosity(-severity_);
+        } else {
+          // Unknown severity. Use INFO.
+          fx_severity = FX_LOG_INFO;
+        }
+    }
+    fx_logger_log_with_source(fx_log_get_logger(), fx_severity, nullptr, file_,
+                              line_, stream_.str().c_str());
 #else
-  // Don't use std::cerr here, because it may not be initialized properly yet.
-  fprintf(stderr, "%s", stream_.str().c_str());
-  fflush(stderr);
+    // Don't use std::cerr here, because it may not be initialized properly yet.
+    fprintf(stderr, "%s", stream_.str().c_str());
+    fflush(stderr);
 #endif
+  }
 
   if (severity_ >= LOG_FATAL) {
     KillProcess();

fml/logging.h

@@ -12,6 +12,8 @@
 
 namespace fml {
 
+void CaptureNextLog(std::ostringstream* stream);
+
 class LogMessageVoidify {
  public:
   void operator&(std::ostream&) {}
@@ -27,7 +29,12 @@ class LogMessage {
 
   std::ostream& stream() { return stream_; }
 
+  static void CaptureNextLog(std::ostringstream* stream);
+
  private:
+  // This is a raw pointer so that we avoid having a non-trivially-destructible
+  // static. It is only ever for use in unit tests.
+  static thread_local std::ostringstream* capture_next_log_stream_;
   std::ostringstream stream_;
   const LogSeverity severity_;
   const char* file_;

fml/memory/thread_checker.cc

@@ -0,0 +1,11 @@
+// Copyright 2013 The Flutter 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 "flutter/fml/memory/thread_checker.h"
+
+namespace fml {
+
+thread_local bool ThreadChecker::disable_next_failure_ = false;
+
+}

fml/memory/thread_checker.h

@@ -29,12 +29,25 @@ namespace fml {
 // |CalledOnValidThread()| that lies in Release builds seems bad. Moreover,
 // there's a small space cost to having even an empty class. )
 class ThreadChecker final {
+ public:
+  static void DisableNextThreadCheckFailure() { disable_next_failure_ = true; }
+
+ private:
+  static thread_local bool disable_next_failure_;
+
  public:
 #if defined(FML_OS_WIN)
   ThreadChecker() : self_(GetCurrentThreadId()) {}
   ~ThreadChecker() {}
 
-  bool IsCreationThreadCurrent() const { return GetCurrentThreadId() == self_; }
+  bool IsCreationThreadCurrent() const {
+    bool result = GetCurrentThreadId() == self_;
+    if (!result && disable_next_failure_) {
+      disable_next_failure_ = false;
+      return true;
+    }
+    return result;
+  }
 
  private:
   DWORD self_;
@@ -48,6 +61,10 @@ class ThreadChecker final {
   bool IsCreationThreadCurrent() const {
     pthread_t current_thread = pthread_self();
     bool is_creation_thread_current = !!pthread_equal(current_thread, self_);
+    if (disable_next_failure_ && !is_creation_thread_current) {
+      disable_next_failure_ = false;
+      return true;
+    }
 #ifdef __APPLE__
     // TODO(https://github.com/flutter/flutter/issues/45272): Implement for
     // other platforms.

shell/common/shell.cc

@@ -996,7 +996,24 @@ void Shell::OnPlatformViewSetViewportMetrics(const ViewportMetrics& metrics) {
 void Shell::OnPlatformViewDispatchPlatformMessage(
     std::unique_ptr<PlatformMessage> message) {
   FML_DCHECK(is_setup_);
-  FML_DCHECK(task_runners_.GetPlatformTaskRunner()->RunsTasksOnCurrentThread());
+#if FLUTTER_RUNTIME_MODE == FLUTTER_RUNTIME_MODE_DEBUG
+  if (!task_runners_.GetPlatformTaskRunner()->RunsTasksOnCurrentThread()) {
+    std::scoped_lock lock(misbehaving_message_channels_mutex_);
+    auto inserted = misbehaving_message_channels_.insert(message->channel());
+    if (inserted.second) {
+      FML_LOG(ERROR)
+          << "The '" << message->channel()
+          << "' channel sent a message from native to Flutter on a "
+             "non-platform thread. Platform channel messages must be sent on "
+             "the platform thread. Failure to do so may result in data loss or "
+             "crashes, and must be fixed in the plugin or application code "
+             "creating that channel.\n"
+             "See https://docs.flutter.dev/platform-integration/"
+             "platform-channels#channels-and-platform-threading for more "
+             "information.";
+    }
+  }
+#endif  // FLUTTER_RUNTIME_MODE == FLUTTER_RUNTIME_MODE_DEBUG
 
   // The static leak checker gets confused by the use of fml::MakeCopyable.
   // NOLINTNEXTLINE(clang-analyzer-cplusplus.NewDeleteLeaks)

shell/common/shell.h

@@ -412,6 +412,12 @@ class Shell final : public PlatformView::Delegate,
       std::function<bool(const ServiceProtocol::Handler::ServiceProtocolMap&,
                          rapidjson::Document*)>;
 
+  /// A collection of message channels (by name) that have sent at least one
+  /// message from a non-platform thread. Used to prevent printing the error log
+  /// more than once per channel, as a badly behaving plugin may send multiple
+  /// messages per second indefinitely.
+  std::mutex misbehaving_message_channels_mutex_;
+  std::set<std::string> misbehaving_message_channels_;
   const TaskRunners task_runners_;
   const fml::RefPtr<fml::RasterThreadMerger> parent_raster_thread_merger_;
   std::shared_ptr<ResourceCacheLimitCalculator>

shell/common/shell_test.cc

@@ -25,6 +25,11 @@ ShellTest::ShellTest()
                    ThreadHost::Type::Platform | ThreadHost::Type::IO |
                        ThreadHost::Type::UI | ThreadHost::Type::RASTER) {}
 
+void ShellTest::SendPlatformMessage(Shell* shell,
+                                    std::unique_ptr<PlatformMessage> message) {
+  shell->OnPlatformViewDispatchPlatformMessage(std::move(message));
+}
+
 void ShellTest::SendEnginePlatformMessage(
     Shell* shell,
     std::unique_ptr<PlatformMessage> message) {

shell/common/shell_test.h

@@ -56,6 +56,9 @@ class ShellTest : public FixtureTest {
 
   fml::TimePoint GetLatestFrameTargetTime(Shell* shell) const;
 
+  void SendPlatformMessage(Shell* shell,
+                           std::unique_ptr<PlatformMessage> message);
+
   void SendEnginePlatformMessage(Shell* shell,
                                  std::unique_ptr<PlatformMessage> message);