Room::close() races its own publisher renegotiation: "failed to negotiate the publisher" logged at ERROR

[lukasjoho]

When a room with published local tracks is closed from the client side (room.disconnect() in Python), roughly 1–4% of teardowns log this at ERROR:

livekit::rtc_engine::rtc_session:2338 - failed to negotiate the publisher: Rtc(RtcError { error_type: InvalidState, message: "Failed to set local offer sdp: Called in wrong state: closed" })

Occasionally the message is "CreateOffer called when PeerConnection is closed." instead.

We run voice agents with livekit-agents on LiveKit Cloud and this is our most frequent LiveKit error. Nothing custom is involved: the agents job shutdown calls room.disconnect(), which goes through the same path. As far as we can tell nothing actually breaks, since the call is already over at that point. It's just an ERROR for something the SDK does to itself while closing.

What happens

RoomSession::close unpublishes every local track before it closes the engine (room/mod.rs#L1185-L1190):

// remove published tracks
for (sid, _) in self.local_participant.track_publications().iter() {
    let _ = self.local_participant.unpublish_track(sid).await;
}

self.rtc_engine.close(reason).await;

Each unpublish_track ends with publisher_negotiation_needed() (local_participant.rs#L680), which with fast publish spawns execute_negotiation_with_retry. That task then races SessionInner::close, which sets closed and closes the publisher PC (rtc_session.rs#L2069-L2080):

• If the negotiation starts after the PC is closed, create_and_send_offer sees SignalingState::Closed and returns with a warning (peer_transport.rs#L531-L533). Fine.
• If the PC closes while the offer is being created or applied, create_offer / set_local_description fails and execute_negotiation_with_retry logs it at ERROR (rtc_session.rs#L2526).

Either way the negotiation has no purpose anymore, since the session is closing itself.

Repro

Local livekit-server --dev 1.13.7 on macOS arm64. Note that it needs a server version that enables fast publish: against 1.9.4 we got 0 errors, presumably because the debounced path only starts after the close.

Two audio tracks, wait 0.5s, disconnect(), 15 rooms in parallel:

import asyncio
import logging
import uuid

from livekit import api, rtc

URL, KEY, SECRET = "ws://127.0.0.1:7880", "devkey", "secret"
errors = 0


class CountNegotiationErrors(logging.Handler):
    def emit(self, record):
        global errors
        if "failed to negotiate the publisher" in record.getMessage():
            errors += 1


async def teardown():
    name = f"repro-{uuid.uuid4().hex}"
    token = (
        api.AccessToken(KEY, SECRET)
        .with_identity("agent")
        .with_grants(api.VideoGrants(room_join=True, room=name))
        .to_jwt()
    )
    room = rtc.Room()
    await room.connect(URL, token)
    for track_name in ("a", "b"):
        source = rtc.AudioSource(48000, 1)
        track = rtc.LocalAudioTrack.create_audio_track(track_name, source)
        await room.local_participant.publish_track(track, rtc.TrackPublishOptions())
    await asyncio.sleep(0.5)
    await room.disconnect()


async def main():
    logging.getLogger("livekit").addHandler(CountNegotiationErrors())
    for _ in range(20):
        await asyncio.gather(*(teardown() for _ in range(15)))
        await asyncio.sleep(0.4)
    print(f"{errors}/300 teardowns logged 'failed to negotiate the publisher'")


asyncio.run(main())

Python livekit	rust-sdks	ERROR per 300 teardowns (3 runs)
1.1.14	63128d01	3, 4, 11
1.1.20	5a656c4b	6, 9, 5

All errors come from the log::error! in execute_negotiation_with_retry. 1.1.20 (with #1335 closing the PC earlier) doesn't make it go away.

Possible fix

closed is set before the PC is closed, so a failed offer while closed is set is expected. Something like:

 if let Err(err) = self.publisher_pc.create_and_send_offer(OfferOptions::default()).await
 {
-    log::error!("failed to negotiate the publisher: {:?}", err);
+    if self.closed.load(Ordering::Acquire) {
+        log::debug!("publisher negotiation aborted by close: {:?}", err);
+    } else {
+        log::error!("failed to negotiate the publisher: {:?}", err);
+    }
     self.negotiation_queue.waiting_for_answer.store(false, Ordering::Release);

The same applies to the debounced path (rtc_session.rs#L2574). Alternatively, RoomSession::close could skip the renegotiation for its own unpublish loop, since the PC gets closed right after anyway. Happy to open a PR for whichever you prefer.

Related, but a different path: #1443 / #1444 (server-initiated close, where the PC is closed before the unpublish loop).