Python runtime: stop a backend's log from deadlocking two threads

docs/source/using-executorch-runtime-integration.md

@@ -36,33 +36,45 @@ To register a custom PAL implementation, take the following steps:
 - Create an instance of the [PalImpl](https://github.com/pytorch/executorch/blob/7b39a0ce63bfb5124d4d29cfb6c8af85a3c580ba/runtime/platform/platform.h#L163) struct.
   - Set one or more fields to custom PAL function implementations. Leave fields as null to use the default platform implementation.
   - The PalImpl struct provides a [create](https://github.com/pytorch/executorch/blob/7b39a0ce63bfb5124d4d29cfb6c8af85a3c580ba/runtime/platform/platform.h#L168) method for this purpose.
-- Call `executorch::platform::register_pal(pal_impl)` to register the implementation.
+- Call `executorch::runtime::register_pal(pal_impl)` to register the implementation.
   - This can be done from as as a global constructor, as in the example below.
 
-Here is a complete example from [pybindings.cpp](https://github.com/pytorch/executorch/blob/7b39a0ce63bfb5124d4d29cfb6c8af85a3c580ba/extension/pybindings/pybindings.cpp#L1178), where logs are redirected to show up properly in a Python notebook environment.
+Here is a complete example that writes each log line to stderr.
 
 ```cpp
+#include <cstdio>
+
+#include <executorch/runtime/platform/platform.h>
+
 namespace {
-  void emit_log_message(
-      et_timestamp_t timestamp,
-      et_pal_log_level_t level,
-      const char* filename,
-      ET_UNUSED const char* function,
-      size_t line,
-      const char* message,
-      ET_UNUSED size_t length) {
-    std::cerr << "[" << filename << ":" << line << "] " << message << std::endl;
-  }
-
-  runtime::PalImpl build_pal() {
-    return runtime::PalImpl::create(emit_log_message, __FILE__);
-  }
-
-  // Update PAL to redirect logs.
-  ET_UNUSED bool registration_result = runtime::register_pal(build_pal());
+
+void emit_log_message(
+    ET_UNUSED et_timestamp_t timestamp,
+    ET_UNUSED et_pal_log_level_t level,
+    const char* filename,
+    ET_UNUSED const char* function,
+    size_t line,
+    const char* message,
+    size_t length) {
+  std::fprintf(
+      stderr, "[%s:%zu] %.*s\n", filename, line, static_cast<int>(length), message);
+  std::fflush(stderr);
 }
+
+ET_UNUSED const bool registered = executorch::runtime::register_pal(
+    executorch::runtime::PalImpl::create(emit_log_message, __FILE__));
+
+} // namespace
 ```
 
+The Python bindings register their PAL the same way, in
+[pybindings.cpp](https://github.com/pytorch/executorch/blob/main/extension/pybindings/pybindings.cpp).
+A backend can log while it holds a lock, and a log function that writes to
+Python at that moment can deadlock with another thread that waits for that lock,
+so their log function never calls Python. Their
+[README](https://github.com/pytorch/executorch/blob/main/extension/pybindings/README.md#note)
+says where their lines go.
+
 ### Weak Symbol Override
 ExecuTorch also provides a link-time method to override the PAL using weak symbols. This method is primarily maintained for backwards compatibility.
 

extension/pybindings/README.md

@@ -235,4 +235,29 @@ CMAKE_ARGS="-DEXECUTORCH_BUILD_VULKAN=ON" ./install_executorch.sh
 This class is currently empty and serves as a placeholder for future methods and attributes.
 - `verify_result_with_bundled_expected_output(method_name: str, testset_idx: int, rtol: float = 1e-5, atol: float = 1e-8)`: Verify result with bundled expected output.
 ## Note
-Runtime logs are forwarded to Python stderr.
+Runtime logs go straight to the process's stderr as they are logged, where a
+Windows console shows text that is not ASCII in its own code page. If Python
+has replaced `sys.stderr`, for example with pytest's `capsys`,
+`contextlib.redirect_stderr` or in Jupyter, the lines a binding call logs wait
+until the call returns and then go to `sys.stderr`. They wait rather than go to
+Python at once because a backend can log while it holds a lock, and writing to
+Python at that moment could deadlock with another thread. On Linux and macOS,
+lines also wait once the process's stderr is a pipe that stays full for a tenth
+of a second, so a call cannot hang on a pipe that a Python thread in the same
+process empties, as under `wurlitzer.pipes()`. On macOS, a pipe that has not
+grown past 16 KiB counts as full once it holds 512 bytes, because macOS reports
+room in such a pipe that it may not have. A call keeps up to 64 KiB of waiting
+lines; past that it keeps about the newest 32 to 64 KiB and says how many
+earlier bytes it left out. A fatal line and the lines waiting before it go
+straight to the process's stderr while it has room, since an abort usually
+follows. Any other crash or hang of the process loses the lines still waiting.
+
+On Linux with Python before 3.13.8, a daemon thread never writes its lines
+through Python, because at exit Python can stop such a thread in the middle of
+that write, which crashes the process. Its lines go straight to the process's
+stderr as far as there is room.
+
+Lines logged outside a call always go straight to the process's stderr: on
+another thread, while an object is destroyed, or by other ExecuTorch modules
+such as the LLM runner. In a Jupyter kernel on Linux or macOS, enough such
+lines while a thread holds the GIL can fill the kernel's pipe and hang it.