Intermittent connection with RealtimeModel - no handshake TLS

[kikohs]

Hello, New to livekit, I've struggling for the past days.

livekit==0.18.0
livekit-agents==0.11.1
livekit-api==0.7.1
livekit-plugins-deepgram==0.6.9
livekit-plugins-openai==0.10.5
livekit-protocol==0.6.0

I run the same code, sometimes I connect to the Voice agent, sometimes not. I run exactly the example defaut code:

    LOG.info("Setup AI assistant")
    agent = multimodal.MultimodalAgent(
        model=openai.realtime.RealtimeModel(
            instructions=instructions,
            voice="alloy",
            temperature=0.8,
            max_response_output_tokens="inf",
            modalities=["text", "audio"],
            turn_detection=openai.realtime.ServerVadOptions(
                threshold=0.5,
                silence_duration_ms=200,
                prefix_padding_ms=300,
            ),
            api_key=CONFIG.get('openai_api_key'),
        ),
        fnc_ctx=fnc_ctx
    )
    agent.start(ctx.room, participant)

    async def entrypoint(ctx: JobContext):
      LOG.info("Entrypoint worker")
      await ctx.connect(auto_subscribe=AutoSubscribe.AUDIO_ONLY)
      participant = await ctx.wait_for_participant()

      await setup_ai_assistant(ctx, participant)

    if __name__ == "__main__":
        cli.run_app(WorkerOptions(entrypoint_fnc=entrypoint, worker_type=WorkerType.ROOM))

I've noticed that we have a double request (as reported in another issue), when all goes well I get this and it works perfectly.

DEBUG:asyncio:Using selector: EpollSelector
2024-11-11 17:59:11,680 - DEBUG asyncio - Using selector: EpollSelector {"pid": 14382}
INFO:livekit.agents:initializing process
INFO:livekit:Entrypoint worker
2024-11-11 17:59:11,680 - INFO livekit.agents - initializing process {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
INFO:livekit.agents:process initialized
2024-11-11 17:59:11,681 - INFO livekit.agents - process initialized {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
INFO:livekit:Entrypoint worker
Entrypoint worker {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
INFO:livekit:livekit_ffi::server:133:livekit_ffi::server - initializing ffi server v0.12.2
INFO:livekit:livekit_ffi::cabi:36:livekit_ffi::cabi - initializing ffi server v0.12.2
INFO:livekit:livekit_ffi::server:133:livekit_ffi::server - initializing ffi server v0.12.2
2024-11-11 17:59:11,693 - INFO livekit - livekit_ffi::server:133:livekit_ffi::server - initializing ffi server v0.12.2 {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
INFO:livekit:livekit_ffi::cabi:36:livekit_ffi::cabi - initializing ffi server v0.12.2
2024-11-11 17:59:11,693 - INFO livekit - livekit_ffi::cabi:36:livekit_ffi::cabi - initializing ffi server v0.12.2 {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
INFO:livekit:livekit_api::signal_client::signal_stream:96:livekit_api::signal_client::signal_stream - connecting to wss://narranet-1qpii8bc.livekit.cloud/rtc?sdk=python&protocol=15&auto_subscribe=0&adaptive_stream=0&version=0.18.0&access_token=...
INFO:livekit:livekit_api::signal_client::signal_stream:96:livekit_api::signal_client::signal_stream - connecting to wss://narranet-1qpii8bc.livekit.cloud/rtc?sdk=python&protocol=15&auto_subscribe=0&adaptive_stream=0&version=0.18.0&access_token=...
2024-11-11 17:59:11,718 - INFO livekit - livekit_api::signal_client::signal_stream:96:livekit_api::signal_client::signal_stream - connecting to wss://narranet-1qpii8bc.livekit.cloud/rtc?sdk=python&protocol=15&auto_subscribe=0&adaptive_stream=0&version=0.18.0&access_token=... {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
DEBUG:livekit:rustls::anchors:150:rustls::anchors - add_parsable_certificates processed 146 valid and 0 invalid certs
DEBUG:livekit:tokio_tungstenite::tls::encryption::rustls:103:tokio_tungstenite::tls::encryption::rustls - Added 146/146 native root certificates (ignored 0)
DEBUG:livekit:rustls::client::hs:73:rustls::client::hs - No cached session for DnsName("narranet-1qpii8bc.livekit.cloud")
DEBUG:livekit:rustls::client::hs:132:rustls::client::hs - Not resuming any session
DEBUG:livekit:rustls::anchors:150:rustls::anchors - add_parsable_certificates processed 146 valid and 0 invalid certs
2024-11-11 17:59:11,744 - DEBUG livekit - rustls::anchors:150:rustls::anchors - add_parsable_certificates processed 146 valid and 0 invalid certs {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
DEBUG:livekit:tokio_tungstenite::tls::encryption::rustls:103:tokio_tungstenite::tls::encryption::rustls - Added 146/146 native root certificates (ignored 0)
2024-11-11 17:59:11,745 - DEBUG livekit - tokio_tungstenite::tls::encryption::rustls:103:tokio_tungstenite::tls::encryption::rustls - Added 146/146 native root certificates (ignored 0) {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
DEBUG:livekit:rustls::client::hs:73:rustls::client::hs - No cached session for DnsName("narranet-1qpii8bc.livekit.cloud")
2024-11-11 17:59:11,745 - DEBUG livekit - rustls::client::hs:73:rustls::client::hs - No cached session for DnsName("narranet-1qpii8bc.livekit.cloud") {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
DEBUG:livekit:rustls::client::hs:132:rustls::client::hs - Not resuming any session
2024-11-11 17:59:11,745 - DEBUG livekit - rustls::client::hs:132:rustls::client::hs - Not resuming any session {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
DEBUG:livekit:rustls::client::hs:615:rustls::client::hs - Using ciphersuite TLS13_AES_128_GCM_SHA256
DEBUG:livekit:rustls::client::tls13:142:rustls::client::tls13 - Not resuming
DEBUG:livekit:rustls::client::tls13:381:rustls::client::tls13 - TLS1.3 encrypted extensions: []
DEBUG:livekit:rustls::client::hs:472:rustls::client::hs - ALPN protocol is None
DEBUG:livekit:rustls::client::hs:615:rustls::client::hs - Using ciphersuite TLS13_AES_128_GCM_SHA256
2024-11-11 17:59:11,765 - DEBUG livekit - rustls::client::hs:615:rustls::client::hs - Using ciphersuite TLS13_AES_128_GCM_SHA256 {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
DEBUG:livekit:rustls::client::tls13:142:rustls::client::tls13 - Not resuming
2024-11-11 17:59:11,765 - DEBUG livekit - rustls::client::tls13:142:rustls::client::tls13 - Not resuming {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
DEBUG:livekit:rustls::client::tls13:381:rustls::client::tls13 - TLS1.3 encrypted extensions: []
2024-11-11 17:59:11,765 - DEBUG livekit - rustls::client::tls13:381:rustls::client::tls13 - TLS1.3 encrypted extensions: [] {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
DEBUG:livekit:rustls::client::hs:472:rustls::client::hs - ALPN protocol is None
2024-11-11 17:59:11,765 - DEBUG livekit - rustls::client::hs:472:rustls::client::hs - ALPN protocol is None {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}
DEBUG:livekit:tungstenite::handshake::client:95:tungstenite::handshake::client - Client handshake done.
DEBUG:livekit:tungstenite::handshake::client:95:tungstenite::handshake::client - Client handshake done.
2024-11-11 17:59:11,840 - DEBUG livekit - tungstenite::handshake::client:95:tungstenite::handshake::client - Client handshake done. {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}

However, 80% of the time (sometimes it takes 1 hour to work again), it stays like this:

DEBUG:asyncio:Using selector: EpollSelector
2024-11-11 18:06:46,407 - DEBUG asyncio - Using selector: EpollSelector 
INFO:livekit.agents:starting worker
2024-11-11 18:06:46,413 - INFO livekit.agents - starting worker {"version": "0.11.1", "rtc-version": "0.18.0"}
INFO:livekit.agents:registered worker
2024-11-11 18:06:46,510 - INFO livekit.agents - registered worker {"id": "AW_JWwwNcJ35VEg", "region": "France", "protocol": 15, "node_id": "NC_OMARSEILLE1A_m54Ag5b5ckqY"}

And nothing happens. I'm using the free version, is it a limitation on the livekit servers. Too many people on the free plan?

Thank you for your help

[davidzhao]

I'm not sure if it's related.. but your code is instantiating the agent outside of entrypoint. this will not behave correctly.

[kikohs]

I truncated the code. It's called in the entry point.

[davidzhao]

what is the error when these logs are printed out? upon closer inspection, these are just debug logs when TLS connection is established:

2024-11-11 17:59:11,840 - DEBUG livekit - tungstenite::handshake::client:95:tungstenite::handshake::client - Client handshake done. {"pid": 14382, "job_id": "AJ_6t9s5Wneavuv"}

[kikohs]

There is no error. The handshake happens 20% of the time.

Otherwise nothing happens and I can't connect.

I try for 10min and can't connect. Then i retry for the 10nth time and it works.

[kikohs]

I added a python client. Joining the room works perfectly all the time but the AI agent is not there. My main client is in JS.

[davidzhao]

are you using unique room names for each attempt? what you are describing sounds like the agent was not dispatched due to it joining the same room as the previous session

[kikohs]

Yes. I'm reusing the same room. I didn't know that we needed to create a new room. I have a token TTL to 1 day.

[davidzhao]

sorry for the confusion there. give it a try by using new room names. it should work well

[davidzhao]

closing the issue, feel free to reopen if you continue to have problems.

[kikohs]

Thanks. I will! Maybe the documentation can be updated.