Debug ESPHome media proxy shutdown

homeassistant/components/esphome/ffmpeg_proxy.py

@@ -131,11 +131,10 @@ class FFmpegConvertResponse(web.StreamResponse):
         self.proxy_data = proxy_data
         self.chunk_size = chunk_size
 
-    async def prepare(self, request: BaseRequest) -> AbstractStreamWriter | None:
+    async def transcode(
+        self, request: BaseRequest, writer: AbstractStreamWriter
+    ) -> None:
         """Stream url through ffmpeg conversion and out to HTTP client."""
-        writer = await super().prepare(request)
-        assert writer is not None
-
         command_args = [
             "-i",
             self.convert_info.media_url,
@@ -172,6 +171,19 @@ class FFmpegConvertResponse(web.StreamResponse):
         # Only one conversion process per device is allowed
         self.convert_info.proc = proc
 
+        write_task = self.hass.async_create_background_task(
+            self._write_ffmpeg_data(request, writer, proc), "ESPHome media proxy"
+        )
+        _LOGGER.warning("Await write_data")
+        await write_task
+        _LOGGER.warning("Done write_data")
+
+    async def _write_ffmpeg_data(
+        self,
+        request: BaseRequest,
+        writer: AbstractStreamWriter,
+        proc: asyncio.subprocess.Process,
+    ) -> None:
         assert proc.stdout is not None
         assert proc.stderr is not None
 
@@ -184,8 +196,8 @@ class FFmpegConvertResponse(web.StreamResponse):
                 and (chunk := await proc.stdout.read(self.chunk_size))
             ):
                 await writer.write(chunk)
-                await writer.drain()
         except asyncio.CancelledError:
+            _LOGGER.warning("Cancelled ffmpeg transcoding")
             raise  # don't log error
         except:
             _LOGGER.exception("Unexpected error during ffmpeg conversion")
@@ -197,6 +209,8 @@ class FFmpegConvertResponse(web.StreamResponse):
             _LOGGER.error("FFmpeg output: %s", stderr_text)
 
             raise
+        else:
+            _LOGGER.warning("Ending ffmpeg transcoding %s", self.hass.is_running)
         finally:
             # Terminate hangs, so kill is used
             if proc.returncode is None:
@@ -205,8 +219,6 @@ class FFmpegConvertResponse(web.StreamResponse):
             # Close connection
             await writer.write_eof()
 
-        return writer
-
 
 class FFmpegProxyView(HomeAssistantView):
     """FFmpeg web view to convert audio and stream back to client."""
@@ -245,6 +257,10 @@ class FFmpegProxyView(HomeAssistantView):
             convert_info.proc = None
 
         # Stream converted audio back to client
-        return FFmpegConvertResponse(
+        resp = FFmpegConvertResponse(
             self.manager, convert_info, device_id, self.proxy_data
         )
+        writer = await resp.prepare(request)
+        assert writer is not None
+        await resp.transcode(request, writer)
+        return resp

homeassistant/components/http/__init__.py

@@ -243,7 +243,9 @@ async def async_setup(hass: HomeAssistant, config: ConfigType) -> bool:
 
     async def stop_server(event: Event) -> None:
         """Stop the server."""
+        _LOGGER.warning("Stopping server start")
         await server.stop()
+        _LOGGER.warning("Stopping server done")
 
     async def start_server(*_: Any) -> None:
         """Start the server."""
@@ -644,9 +646,13 @@ class HomeAssistantHTTP:
     async def stop(self) -> None:
         """Stop the aiohttp server."""
         if self.site is not None:
+            _LOGGER.warning("Stopping site start")
             await self.site.stop()
+            _LOGGER.warning("Stopping site done")
         if self.runner is not None:
+            _LOGGER.warning("Stopping runner start")
             await self.runner.cleanup()
+            _LOGGER.warning("Stopping runner done")
 
 
 async def start_http_server_and_save_config(

homeassistant/core.py

@@ -145,7 +145,7 @@ CORE_STORAGE_MINOR_VERSION = 4
 DOMAIN = "homeassistant"
 
 # How long to wait to log tasks that are blocking
-BLOCK_LOG_TIMEOUT = 60
+BLOCK_LOG_TIMEOUT = 2
 
 type ServiceResponse = JsonObjectType | None
 type EntityServiceResponse = dict[str, ServiceResponse]
@@ -1028,7 +1028,7 @@ class HomeAssistant:
                 # continue to block. At this point we start
                 # logging all waiting tasks.
                 for task in tasks:
-                    _LOGGER.debug("Waiting for task: %s", task)
+                    _LOGGER.info("Waiting for task: %s", task)
 
     async def _await_and_log_pending(
         self, pending: Collection[asyncio.Future[Any]]
@@ -1041,7 +1041,7 @@ class HomeAssistant:
                 return
             wait_time += BLOCK_LOG_TIMEOUT
             for task in pending:
-                _LOGGER.debug("Waited %s seconds for task: %s", wait_time, task)
+                _LOGGER.info("Waited %s seconds for task: %s", wait_time, task)
 
     @overload
     @callback
@@ -1111,6 +1111,7 @@ class HomeAssistant:
                 )
 
         # Stage 1 - Run shutdown jobs
+        _LOGGER.warning("SHUTDOWN STAGE 1 START")
         try:
             async with self.timeout.async_timeout(STOPPING_STAGE_SHUTDOWN_TIMEOUT):
                 tasks: list[asyncio.Future[Any]] = []
@@ -1127,8 +1128,10 @@ class HomeAssistant:
                 " continue"
             )
             self._async_log_running_tasks("run shutdown jobs")
+        _LOGGER.warning("SHUTDOWN STAGE 1 DONE")
 
         # Stage 2 - Stop integrations
+        _LOGGER.warning("SHUTDOWN STAGE 2 START")
 
         # Keep holding the reference to the tasks but do not allow them
         # to block shutdown. Only tasks created after this point will
@@ -1149,6 +1152,7 @@ class HomeAssistant:
 
         self.set_state(CoreState.stopping)
         self.bus.async_fire_internal(EVENT_HOMEASSISTANT_STOP)
+        _LOGGER.warning("SHUTDOWN STAGE 2 WAIT")
         try:
             async with self.timeout.async_timeout(STOP_STAGE_SHUTDOWN_TIMEOUT):
                 await self.async_block_till_done()
@@ -1158,8 +1162,10 @@ class HomeAssistant:
                 " continue"
             )
             self._async_log_running_tasks("stop integrations")
+        _LOGGER.warning("SHUTDOWN STAGE 2 DONE")
 
         # Stage 3 - Final write
+        _LOGGER.warning("SHUTDOWN STAGE 3 START")
         self.set_state(CoreState.final_write)
         self.bus.async_fire_internal(EVENT_HOMEASSISTANT_FINAL_WRITE)
         try:
@@ -1173,6 +1179,7 @@ class HomeAssistant:
             self._async_log_running_tasks("final write")
 
         # Stage 4 - Close
+        _LOGGER.warning("SHUTDOWN STAGE 4 START")
         self.set_state(CoreState.not_running)
         self.bus.async_fire_internal(EVENT_HOMEASSISTANT_CLOSE)
 
@@ -1227,6 +1234,7 @@ class HomeAssistant:
 
         if self._stopped is not None:
             self._stopped.set()
+        _LOGGER.warning("SHUTDOWN STAGE 4 DONE")
 
     def _cancel_cancellable_timers(self) -> None:
         """Cancel timer handles marked as cancellable."""