room_finished event for the room arrives after 13...
# ask-ai
g
room_finished event for the room arrives after 13+ seconds why ? how to reduce this delay?
t
Thanks for reaching out, Vrishabh. I'm an AI assistant and I'm here to help. Give me a moment while I research this topic.
Could you provide more details about the delay in the
room_finished
event? For example: • Are you using any specific SDK or API version? • Does this delay occur consistently or only under certain conditions? • Are there any specific configurations or customizations in your setup? This information will help us investigate the issue further.
g
1. LiveKit Agents: Version 1.1.1+ 2. It always happens after I close the room. The room finished event is delayed. It was sent after a couple of seconds. 3. Deployed on Modal serverless platform Using event-driven webhook architecture with WorkerType.ROOM Let me know if you need more information or clarification
t
Hey there! I totally appreciate you sharing those details with me. To help us get to the bottom of this, I'm wondering if you could shed a bit more light on a few things: • Do you notice any other background activities happening when the room closes that might be playing a role in this delay? • Have you spotted any hints of network slowness or performance hiccups on the Modal serverless side? • Is there any special custom code in your webhook handler that might be adding some extra processing time? Digging into these details will help us track down exactly what's causing the holdup with the room_finished event. I'm here to help you solve this! 🕵️‍♀️
g
Yes, there are several background activities that happen during room closure: 1. Participant Disconnection Tracking:
Copy code
python
   # We track each participant leaving and wait for all to disconnect
   if len(connected_participants) == 0:
       session_active = False
       asyncio.create_task(delayed_shutdown(ctx))
2. Multi-layer Agent Cleanup: - Agent session cleanup - BitHuman avatar session cleanup (
bithuman.AvatarSession
) - Participant tracking cleanup - Room event listener cleanup 3. Built-in 2-second Delay:
Copy code
python
   async def delayed_shutdown(ctx: JobContext):
       await asyncio.sleep(2)  # We intentionally wait 2 seconds
Modal Serverless Performance: - Cold starts: Possible but our functions are pre-warmed - Function cancellation: We use
function_call.cancel()
which might not be immediate - Modal Dict operations: We're using persistent storage for session tracking Custom Webhook Handler Processing: Our webhook handler has some custom logic that might add time:
Copy code
python
# Session tracking with Modal Dict
if room_sid in room_sessions:
    call_id = room_sessions.pop(room_sid)  # Dict operation
    function_call = FunctionCall.from_id(call_id)  # Function lookup
    function_call.cancel()  # Cancellation request
Key Observation: The delay might be coming from LiveKit waiting for our agent to fully terminate before sending
room_finished
. Our agent has extensive cleanup that includes: - Waiting for all participants to disconnect - 2-second intentional delay - Multiple async cleanup operations
t
Hey there! Thanks for sharing all those details about the event delay. It looks like we've got a few things that might be slowing things down. Let me break it down in a friendly way: • Intentional 2-second delay: There's a built-in 2-second wait that's definitely adding some extra time to the process. • Extensive cleanup operations: The agent cleanup and participant tracking is doing quite a bit of work behind the scenes, which could be contributing to the holdup. • Webhook handler processing: Your custom webhook logic might be adding a bit of extra processing time too. Want to speed things up? Here are some friendly suggestions: 1. Take a look at those cleanup operations and see if you can streamline them a bit. 2. Check if that 2-second delay is really necessary - if not, you might want to remove it. 3. Do a quick performance check on your webhook handler to spot any potential slowdowns. 4. Try simplifying the cleanup to see if it makes a difference in the event timing. If things are still feeling a bit sluggish after trying these out, we might want to dig a bit deeper and see if LiveKit is waiting on something specific. I'm totally here to help you troubleshoot further if you need! Just give me a shout if you want to chat more about it. 😊
g
2025-06-25 001247-04:00 2025-06-25 041247.245 | INFO | modal_apphandle livekit webhook131 - Received webhook event 'track_unpublished' for room: lesson-6a6bc1dc-8fdb-4483-939f-a5202beadf5c-f484c82a-8483-42d3-af08-5884964d17fa (SID: RM_DQK7U5EigBSS) 2025-06-25 001247-04:00 POST / -> 200 OK (duration: 78.0 ms, execution: 23.0 ms) 2025-06-25 001247-04:00 2025-06-25 041247.241 | INFO | agent_coreon participant disconnected280 - Participant disconnected: f484c82a-8483-42d3-af08-5884964d17fa (remaining: 0) 2025-06-25 001247-04:00 2025-06-25 041247.331 | INFO | modal_apphandle livekit webhook131 - Received webhook event 'track_unpublished' for room: lesson-6a6bc1dc-8fdb-4483-939f-a5202beadf5c-f484c82a-8483-42d3-af08-5884964d17fa (SID: RM_DQK7U5EigBSS) 2025-06-25 001247-04:00 POST / -> 200 OK (duration: 64.6 ms, execution: 22.5 ms) 2025-06-25 001247-04:00 2025-06-25 041247.256 | INFO | agent_coreon participant disconnected284 - All participants have left. Initiating graceful shutdown... 2025-06-25 001247-04:00 2025-06-25 041247.257 | INFO | agent_coredelayed shutdown292 - Shutting down agent session - no participants remaining 2025-06-25 001247-04:00 2025-06-25 041247.259 | INFO | agent_corelivekit entrypoint457 - Agent session loop ended 2025-06-25 001247-04:00 2025-06-25 041247.259 | INFO | agent_corelivekit entrypoint464 - Agent session ended for job AJ_cGQF8mgWvBjx 2025-06-25 001247-04:00 2025-06-25 041247.298 | INFO | agent_corecleanup agent session312 - Agent session cleanup initiated. Reason: All participants disconnected 2025-06-25 001247-04:00 2025-06-25 041247.298 | INFO | agent_corecleanup agent session327 - Agent session cleanup completed 2025-06-25 001247-04:00 truncate is not supported by the Google Realtime API. 2025-06-25 001247-04:00 rotate_segment called while previous segment is still being rotated 2025-06-25 001247-04:00 failed to publish transcription 2025-06-25 001247-04:00 Traceback (most recent call last): 2025-06-25 001247-04:00 File "/usr/local/lib/python3.11/site-packages/livekit/agents/voice/room_io/_output.py", line 232, in _publish_transcription 2025-06-25 001247-04:00 await self._room.local_participant.publish_transcription(transcription) 2025-06-25 001247-04:00 File "/usr/local/lib/python3.11/site-packages/livekit/rtc/participant.py", line 285, in publish_transcription 2025-06-25 001247-04:00 raise PublishTranscriptionError(cb.publish_transcription.error) 2025-06-25 001247-04:00 livekit.rtc.participant.PublishTranscriptionError: failed to send transcription, room closed: channel closed 2025-06-25 001247-04:00 failed to publish transcription 2025-06-25 001247-04:00 Traceback (most recent call last): 2025-06-25 001247-04:00 File "/usr/local/lib/python3.11/site-packages/livekit/agents/voice/room_io/_output.py", line 358, in capture_text 2025-06-25 001247-04:00 await self._writer.write(text) 2025-06-25 001247-04:00 File "/usr/local/lib/python3.11/site-packages/livekit/rtc/data_stream.py", line 295, in write 2025-06-25 001247-04:00 await self._send_chunk(chunk_msg) 2025-06-25 001247-04:00 File "/usr/local/lib/python3.11/site-packages/livekit/rtc/data_stream.py", line 213, in _send_chunk 2025-06-25 001247-04:00 raise ConnectionError(cb.send_stream_chunk.error) 2025-06-25 001247-04:00 ConnectionError: engine: connection error: engine is closed 2025-06-25 001247-04:00 failed to publish transcription 2025-06-25 001247-04:00 Traceback (most recent call last): 2025-06-25 001247-04:00 File "/usr/local/lib/python3.11/site-packages/livekit/agents/voice/room_io/_output.py", line 232, in _publish_transcription 2025-06-25 001247-04:00 await self._room.local_participant.publish_transcription(transcription) 2025-06-25 001247-04:00 File "/usr/local/lib/python3.11/site-packages/livekit/rtc/participant.py", line 285, in publish_transcription 2025-06-25 001247-04:00 raise PublishTranscriptionError(cb.publish_transcription.error) 2025-06-25 001247-04:00 livekit.rtc.participant.PublishTranscriptionError: failed to send transcription, room closed: channel closed 2025-06-25 001247-04:00 2025-06-25 041247.386 | INFO | modal_apphandle livekit webhook131 - Received webhook event 'participant_left' for room: lesson-6a6bc1dc-8fdb-4483-939f-a5202beadf5c-f484c82a-8483-42d3-af08-5884964d17fa (SID: RM_DQK7U5EigBSS) 2025-06-25 001247-04:00 2025-06-25 041247.451 | INFO | modal_apphandle livekit webhook131 - Received webhook event 'track_unpublished' for room: lesson-6a6bc1dc-8fdb-4483-939f-a5202beadf5c-f484c82a-8483-42d3-af08-5884964d17fa (SID: RM_DQK7U5EigBSS) 2025-06-25 001247-04:00 POST / -> 200 OK (duration: 85.1 ms, execution: 26.4 ms) 2025-06-25 001247-04:00 POST / -> 200 OK (duration: 233.0 ms, execution: 132.0 ms) 2025-06-25 001247-04:00 2025-06-25 041247.560 | INFO | modal_apphandle livekit webhook131 - Received webhook event 'participant_left' for room: lesson-6a6bc1dc-8fdb-4483-939f-a5202beadf5c-f484c82a-8483-42d3-af08-5884964d17fa (SID: RM_DQK7U5EigBSS) 2025-06-25 001247-04:00 POST / -> 200 OK (duration: 70.6 ms, execution: 25.2 ms) 2025-06-25 001312-04:00 2025-06-25 041312.436 | INFO | modal_apphandle livekit webhook131 - Received webhook event 'room_finished' for room: lesson-6a6bc1dc-8fdb-4483-939f-a5202beadf5c-f484c82a-8483-42d3-af08-5884964d17fa (SID: RM_DQK7U5EigBSS) 2025-06-25 001312-04:00 2025-06-25 041312.436 | INFO | modal_apphandle livekit webhook145 - Room finished. Terminating agent worker for lesson-6a6bc1dc-8fdb-4483-939f-a5202beadf5c-f484c82a-8483-42d3-af08-5884964d17fa... 2025-06-25 001312-04:00 [modal-client] 2025-06-25T041312+0000 Received a cancellation signal while processing input ('in-01JYJMHM4XHAFN2QT367JNEJZ0:1750824702128-0',) 2025-06-25 001312-04:00 2025-06-25 041312.990 | INFO | modal_apphandle livekit webhook152 - Termination signal sent to agent for room lesson-6a6bc1dc-8fdb-4483-939f-a5202beadf5c-f484c82a-8483-42d3-af08-5884964d17fa (SID: RM_DQK7U5EigBSS) with call ID fc-01JYJMHM4JC9XXGA0DSM0V5PC0. 2025-06-25 001312-04:00 2025-06-25 041312.962 | INFO | modal_apprun agent worker100 - Agent worker for lesson-6a6bc1dc-8fdb-4483-939f-a5202beadf5c-f484c82a-8483-42d3-af08-5884964d17fa was cancelled. Cleaning up... 2025-06-25 001312-04:00 2025-06-25 041312.962 | INFO | modal_apprun agent worker105 - Initiating graceful shutdown for agent in lesson-6a6bc1dc-8fdb-4483-939f-a5202beadf5c-f484c82a-8483-42d3-af08-5884964d17fa... 2025-06-25 001312-04:00 2025-06-25 041312.963 | INFO | modal_apprun agent worker107 - Agent for lesson-6a6bc1dc-8fdb-4483-939f-a5202beadf5c-f484c82a-8483-42d3-af08-5884964d17fa has been shut down cleanly. 2025-06-25 001313-04:00 POST / -> 200 OK (duration: 788.0 ms, execution: 685.0 ms) ⠴ Running (3/3 containers active)... View app at None these are the llogs
t
Hey there! Thanks for sharing those logs - I totally get what you're dealing with. 👋 Let me break down what I'm seeing in a friendly way. It looks like the room_finished event is taking a bit longer than expected, and I've got some thoughts on why that might be happening: • Intentional Delays: That 2-second delay in the
delayed_shutdown
function and some other cleanup tasks are definitely playing a role in slowing things down. • Webhook Event Handling: I noticed quite a few webhook events getting processed - things like
track_unpublished
and
participant_left
- which could be adding some extra processing time before the
room_finished
event shows up. • Errors in Transcription Publishing: Those transcription publishing errors (like "failed to send transcription, room closed") suggest some operations are trying to happen after the room is already closed, which can definitely mess with the timing. Want to speed things up? Here are some friendly suggestions: 1. See if you can streamline those cleanup processes - maybe trim down the time for tracking participant disconnections and agent session cleanup. 2. Take a look at that 2-second delay in the
delayed_shutdown
function. If it's not super crucial, you might want to reduce or remove it. 3. Try to wrap up things like transcription publishing before closing the room to avoid those pesky errors. 4. Do a little performance check on your webhook handler to spot any potential slowdowns. If things are still feeling sluggish after trying these out, we might need to dig a bit deeper with LiveKit's event handling. No worries though - I'm here to help! Got any questions? Just ask, and we'll figure this out together. 😊