From 98d5d092a7f564668e5a376e6a0e04158d14a230 Mon Sep 17 00:00:00 2001 From: Erik Date: Mon, 28 Oct 2024 11:09:23 +0100 Subject: [PATCH] Debug ESPHome media proxy shutdown --- .../components/esphome/ffmpeg_proxy.py | 32 ++++++++++++++----- homeassistant/components/http/__init__.py | 6 ++++ homeassistant/core.py | 14 ++++++-- 3 files changed, 41 insertions(+), 11 deletions(-) diff --git a/homeassistant/components/esphome/ffmpeg_proxy.py b/homeassistant/components/esphome/ffmpeg_proxy.py index 8f24a478738..1e56c069e32 100644 --- a/homeassistant/components/esphome/ffmpeg_proxy.py +++ b/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 diff --git a/homeassistant/components/http/__init__.py b/homeassistant/components/http/__init__.py index a8721720dfb..84499a0feec 100644 --- a/homeassistant/components/http/__init__.py +++ b/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( diff --git a/homeassistant/core.py b/homeassistant/core.py index 0e6e6e3bd5b..d8db9ad1c97 100644 --- a/homeassistant/core.py +++ b/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."""