You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
Membrane.RTC.Engine.Endpoint.Forwarder crashes with key not found error in ExICE.Priv.CandidatePair.
This happens in a setup with forwarder (Fishjam) pushing a stream to Broadcaster via WHIP. It occurs in about 90% of cases.
10:04:03.414 request_id=GCyjPjJooy2QMTwAAAAB [info] POST /api/whip/42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37
10:04:03.474 request_id=GCyjPjJooy2QMTwAAAAB [info] Received offer for #PID<0.16107.0>
10:04:03.481 request_id=GCyjPjJooy2QMTwAAAAB [info] Sent answer for #PID<0.16107.0>
10:04:03.481 [info] Added new input 42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37 (#PID<0.16107.0>)
10:04:03.481 request_id=GCyjPjJooy2QMTwAAAAB [info] Sent 201 in 67ms
10:04:03.594 request_id=GCyjPj0eWkiQMTwAAADB [info] PATCH /api/resource/42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37
10:04:03.594 request_id=GCyjPj0eWkiQMTwAAADB [info] Sent 204 in 220µs
10:04:03.702 request_id=GCyjPkONjcCQMTwAAAEB [info] PATCH /api/resource/42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37
10:04:03.702 request_id=GCyjPkONjcCQMTwAAAEB [info] Sent 204 in 381µs
10:04:03.912 [info] Input 42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37 (#PID<0.16107.0>) has successfully connected
10:04:23.420 [warning] Peer connection #PID<0.16107.0> state changed to `failed`. Terminating
10:04:23.420 [info] Input 42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37: process #PID<0.16107.0> exited with reason :shutdown
The text was updated successfully, but these errors were encountered:
Membrane.RTC.Engine.Endpoint.Forwardercrashes with key not found error inExICE.Priv.CandidatePair.This happens in a setup with forwarder (Fishjam) pushing a stream to Broadcaster via WHIP. It occurs in about 90% of cases.
versions:
Repos are private, please dm me for a access if needed.
Fishjam log (click)
{ "time": "2025-03-14T10:03:59.589Z", "severity": "info", "message": "Initialize room with id: 42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37", "metadata": { "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37" } } { "time": "2025-03-14T10:03:59.589Z", "severity": "info", "message": "Forwarder added successfully", "metadata": { "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37" } } { "time": "2025-03-14T10:03:59.590Z", "severity": "info", "message": "Created room \"42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37\"", "metadata": {} } { "time": "2025-03-14T10:03:59.690Z", "severity": "info", "message": "Added peer \"ebf20841-5281-49b6-aae9-c5b7ebf0a24d\"", "metadata": { "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37" } } { "time": "2025-03-14T10:03:59.863Z", "severity": "info", "message": "New incoming peer WebSocket connection, accepting", "metadata": {} } { "time": "2025-03-14T10:03:59.900Z", "severity": "info", "message": "Peer \"ebf20841-5281-49b6-aae9-c5b7ebf0a24d\" connected", "metadata": { "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37" } } { "time": "2025-03-14T10:03:59.900Z", "severity": "info", "message": "Peer ebf20841-5281-49b6-aae9-c5b7ebf0a24d connected to room", "metadata": { "sdk_version": "web-0.14.0" } } { "time": "2025-03-14T10:03:59.938Z", "severity": "info", "message": "Peer ebf20841-5281-49b6-aae9-c5b7ebf0a24d metadata updated: %{\"peer\" => %{\"displayName\" => \"321321\"}, \"server\" => %{\"username\" => \"321321\"}}", "metadata": { "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37" } } { "time": "2025-03-14T10:03:59.938Z", "severity": "info", "message": "<0.58209.0>/{:endpoint, \"ebf20841-5281-49b6-aae9-c5b7ebf0a24d\"}/ endpoint ready, endpoints: [%{id: \"ebf20841-5281-49b6-aae9-c5b7ebf0a24d\", type: Membrane.RTC.Engine.Endpoint.ExWebRTC, metadata: %{\"peer\" => %{\"displayName\" => \"321321\"}, \"server\" => %{\"username\" => \"321321\"}}}, %{id: \"6ad7b3e6-545f-4c63-977d-3cc9b1d33bfc\", type: Membrane.RTC.Engine.Endpoint.Forwarder, metadata: nil}]", "metadata": {} } { "time": "2025-03-14T10:04:00.050Z", "severity": "info", "message": "<0.58209.0>/{:endpoint, \"ebf20841-5281-49b6-aae9-c5b7ebf0a24d\"}/:connection_handler new track %ExWebRTC.MediaStreamTrack{id: 55263343955721097883120689774, kind: :video, streams: [], rids: [\"l\", \"m\", \"h\"]}", "metadata": {} } { "time": "2025-03-14T10:04:00.051Z", "severity": "info", "message": "Track ebf20841-5281-49b6-aae9-c5b7ebf0a24d:28226220-2fce-4dce-87bc-b949d250b39f added, peer_id: ebf20841-5281-49b6-aae9-c5b7ebf0a24d", "metadata": { "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37" } } { "time": "2025-03-14T10:04:00.879Z", "severity": "warn", "message": "Passed the same remote credentials to be set. Ignoring.", "metadata": {} } { "time": "2025-03-14T10:04:00.882Z", "severity": "info", "message": "<0.58209.0>/{:endpoint, \"ebf20841-5281-49b6-aae9-c5b7ebf0a24d\"}/:connection_handler new track %ExWebRTC.MediaStreamTrack{id: 27784212130035643392460420376, kind: :audio, streams: [\"6e505d2a-9647-42e9-b067-d8d56fbc592b\"], rids: nil}", "metadata": {} } { "time": "2025-03-14T10:04:00.887Z", "severity": "info", "message": "Track ebf20841-5281-49b6-aae9-c5b7ebf0a24d:ac9aee60-a9ff-49f6-bcb3-9069ad17a68b added, peer_id: ebf20841-5281-49b6-aae9-c5b7ebf0a24d", "metadata": { "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37" } } { "time": "2025-03-14T10:04:00.887Z", "severity": "info", "message": "<0.58209.0>/{:endpoint, \"6ad7b3e6-545f-4c63-977d-3cc9b1d33bfc\"}/ Got audio and video track. Starting negotation with broadcaster...", "metadata": {} } { "time": "2025-03-14T10:04:01.511Z", "severity": "info", "message": "<0.58209.0>/{:endpoint, \"6ad7b3e6-545f-4c63-977d-3cc9b1d33bfc\"}/ Succesfully connected to broadcaster", "metadata": {} } { "time": "2025-03-14T10:04:09.984Z", "severity": "info", "message": "{\"bytesSent\":2138970,\"firCount\":0,\"frameHeight\":720,\"frameWidth\":1280,\"framesEncoded\":187,\"framesPerSecond\":24,\"framesSent\":187,\"id\":\"OT01V2816997115\",\"nackCount\":3,\"packetsSent\":1933,\"pliCount\":1,\"retransmittedPacketsSent\":60,\"totalPacketSendDelay\":27.187244,\"type\":\"outbound-rtp\"}", "metadata": { "track_id": "OT01V2816997115", "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37", "peer_id": "ebf20841-5281-49b6-aae9-c5b7ebf0a24d", "rtc_stats_type": "outbound-rtp" } } { "time": "2025-03-14T10:04:09.984Z", "severity": "info", "message": "{\"bytesSent\":195702,\"firCount\":0,\"frameHeight\":180,\"frameWidth\":320,\"framesEncoded\":219,\"framesPerSecond\":24,\"framesSent\":219,\"id\":\"OT01V3233486553\",\"nackCount\":2,\"packetsSent\":304,\"pliCount\":0,\"retransmittedPacketsSent\":5,\"totalPacketSendDelay\":3.490369,\"type\":\"outbound-rtp\"}", "metadata": { "track_id": "OT01V3233486553", "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37", "peer_id": "ebf20841-5281-49b6-aae9-c5b7ebf0a24d", "rtc_stats_type": "outbound-rtp" } } { "time": "2025-03-14T10:04:09.984Z", "severity": "info", "message": "{\"bytesSent\":545358,\"firCount\":0,\"frameHeight\":360,\"frameWidth\":640,\"framesEncoded\":216,\"framesPerSecond\":24,\"framesSent\":216,\"id\":\"OT01V421993928\",\"nackCount\":1,\"packetsSent\":585,\"pliCount\":0,\"retransmittedPacketsSent\":13,\"totalPacketSendDelay\":7.039211,\"type\":\"outbound-rtp\"}", "metadata": { "track_id": "OT01V421993928", "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37", "peer_id": "ebf20841-5281-49b6-aae9-c5b7ebf0a24d", "rtc_stats_type": "outbound-rtp" } } { "time": "2025-03-14T10:04:11.506Z", "severity": "error", "message": "GenServer #PID<0.58221.0> terminating\n** (KeyError) key 69514443062572013245424570947 not found in: %{\n 57880509074679002956150741853 => %ExICE.Priv.CandidatePair{\n id: 57880509074679002956150741853,\n local_cand_id: 52478115911183563555233399530,\n remote_cand_id: 71493956163136135705695245364,\n priority: 7998392938176446462,\n nominate?: false,\n nominated?: true,\n state: :succeeded,\n valid?: true,\n succeeded_pair_id: 57880509074679002956150741853,\n discovered_pair_id: 57880509074679002956150741853,\n keepalive_timer: #Reference<0.3141675825.1099694085.176433>,\n last_seen: -576392624063\n }\n}\n :erlang.map_get(69514443062572013245424570947, %{57880509074679002956150741853 => %ExICE.Priv.CandidatePair{id: 57880509074679002956150741853, local_cand_id: 52478115911183563555233399530, remote_cand_id: 71493956163136135705695245364, priority: 7998392938176446462, nominate?: false, nominated?: true, state: :succeeded, valid?: true, succeeded_pair_id: 57880509074679002956150741853, discovered_pair_id: 57880509074679002956150741853, keepalive_timer: #Reference<0.3141675825.1099694085.176433>, last_seen: -576392624063}})\n (ex_ice 0.9.4) lib/ex_ice/priv/ice_agent.ex:1664: ExICE.Priv.ICEAgent.handle_keepalive_response/5\n (ex_ice 0.9.4) lib/ex_ice/priv/ice_agent.ex:1265: ExICE.Priv.ICEAgent.do_handle_stun_message/5\n (ex_ice 0.9.4) lib/ex_ice/ice_agent.ex:393: ExICE.ICEAgent.handle_info/2\n (stdlib 6.0.1) gen_server.erl:2173: :gen_server.try_handle_info/3\n (stdlib 6.0.1) gen_server.erl:2261: :gen_server.handle_msg/6\n (stdlib 6.0.1) proc_lib.erl:329: :proc_lib.init_p_do_apply/3\nLast message: {:udp, {:\"$inet\", :gen_udp_socket, {#PID<0.58268.0>, {:\"$socket\", #Reference<0.3141675825.1100087298.78788>}}}, {10, 240, 44, 135}, 52000, <<1, 1, 0, 44, 33, 18, 164, 66, 17, 233, 69, 189, 61, 226, 192, 56, 54, 204, 26, 166, 0, 32, 0, 8, 0, 1, 234, 51, 43, 226, 134, 66, 0, 8, 0, 20, 48, 57, 132, 146, 57, 119, 71, 106, 250, ...>>}", "metadata": { "error": { "initial_call": null, "reason": "** (KeyError) key 69514443062572013245424570947 not found in: %{\n 57880509074679002956150741853 => %ExICE.Priv.CandidatePair{\n id: 57880509074679002956150741853,\n local_cand_id: 52478115911183563555233399530,\n remote_cand_id: 71493956163136135705695245364,\n priority: 7998392938176446462,\n nominate?: false,\n nominated?: true,\n state: :succeeded,\n valid?: true,\n succeeded_pair_id: 57880509074679002956150741853,\n discovered_pair_id: 57880509074679002956150741853,\n keepalive_timer: #Reference<0.3141675825.1099694085.176433>,\n last_seen: -576392624063\n }\n}\n :erlang.map_get(69514443062572013245424570947, %{57880509074679002956150741853 => %ExICE.Priv.CandidatePair{id: 57880509074679002956150741853, local_cand_id: 52478115911183563555233399530, remote_cand_id: 71493956163136135705695245364, priority: 7998392938176446462, nominate?: false, nominated?: true, state: :succeeded, valid?: true, succeeded_pair_id: 57880509074679002956150741853, discovered_pair_id: 57880509074679002956150741853, keepalive_timer: #Reference<0.3141675825.1099694085.176433>, last_seen: -576392624063}})\n (ex_ice 0.9.4) lib/ex_ice/priv/ice_agent.ex:1664: ExICE.Priv.ICEAgent.handle_keepalive_response/5\n (ex_ice 0.9.4) lib/ex_ice/priv/ice_agent.ex:1265: ExICE.Priv.ICEAgent.do_handle_stun_message/5\n (ex_ice 0.9.4) lib/ex_ice/ice_agent.ex:393: ExICE.ICEAgent.handle_info/2\n (stdlib 6.0.1) gen_server.erl:2173: :gen_server.try_handle_info/3\n (stdlib 6.0.1) gen_server.erl:2261: :gen_server.handle_msg/6\n (stdlib 6.0.1) proc_lib.erl:329: :proc_lib.init_p_do_apply/3\n" } } } { "time": "2025-03-14T10:04:11.512Z", "severity": "error", "message": "<0.58209.0>/{:endpoint, \"6ad7b3e6-545f-4c63-977d-3cc9b1d33bfc\"}/ Terminating with reason: {:membrane_child_crash, :connection_handler, {{:badkey, 69514443062572013245424570947}, [{:erlang, :map_get, [69514443062572013245424570947, %{57880509074679002956150741853 => %ExICE.Priv.CandidatePair{id: 57880509074679002956150741853, local_cand_id: 52478115911183563555233399530, remote_cand_id: 71493956163136135705695245364, priority: 7998392938176446462, nominate?: false, nominated?: true, state: :succeeded, valid?: true, succeeded_pair_id: 57880509074679002956150741853, discovered_pair_id: 57880509074679002956150741853, keepalive_timer: #Reference<0.3141675825.1099694085.176433>, last_seen: -576392624063}}], [error_info: %{module: :erl_erts_errors}]}, {ExICE.Priv.ICEAgent, :handle_keepalive_response, 5, [file: ~c\"lib/ex_ice/priv/ice_agent.ex\", line: 1664]}, {ExICE.Priv.ICEAgent, :do_handle_stun_message, 5, [file: ~c\"lib/ex_ice/priv/ice_agent.ex\", line: 1265]}, {ExICE.ICEAgent, :handle_info, 2, [file: ~c\"lib/ex_ice/ice_agent.ex\", line: 393]}, {:gen_server, :try_handle_info, 3, [file: ~c\"gen_server.erl\", line: 2173]}, {:gen_server, :handle_msg, 6, [file: ~c\"gen_server.erl\", line: 2261]}, {:proc_lib, :init_p_do_apply, 3, [file: ~c\"proc_lib.erl\", line: 329]}]}}", "metadata": {} } { "time": "2025-03-14T10:04:11.513Z", "severity": "error", "message": "Forwarder crashed with reason: {:membrane_child_crash, :connection_handler, {{:badkey, 69514443062572013245424570947}, [{:erlang, :map_get, [69514443062572013245424570947, %{57880509074679002956150741853 => %ExICE.Priv.CandidatePair{id: 57880509074679002956150741853, local_cand_id: 52478115911183563555233399530, remote_cand_id: 71493956163136135705695245364, priority: 7998392938176446462, nominate?: false, nominated?: true, state: :succeeded, valid?: true, succeeded_pair_id: 57880509074679002956150741853, discovered_pair_id: 57880509074679002956150741853, keepalive_timer: #Reference<0.3141675825.1099694085.176433>, last_seen: -576392624063}}], [error_info: %{module: :erl_erts_errors}]}, {ExICE.Priv.ICEAgent, :handle_keepalive_response, 5, [file: ~c\"lib/ex_ice/priv/ice_agent.ex\", line: 1664]}, {ExICE.Priv.ICEAgent, :do_handle_stun_message, 5, [file: ~c\"lib/ex_ice/priv/ice_agent.ex\", line: 1265]}, {ExICE.ICEAgent, :handle_info, 2, [file: ~c\"lib/ex_ice/ice_agent.ex\", line: 393]}, {:gen_server, :try_handle_info, 3, [file: ~c\"gen_server.erl\", line: 2173]}, {:gen_server, :handle_msg, 6, [file: ~c\"gen_server.erl\", line: 2261]}, {:proc_lib, :init_p_do_apply, 3, [file: ~c\"proc_lib.erl\", line: 329]}]}}, terminating room: #PID<0.58206.0>", "metadata": { "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37" } } { "time": "2025-03-14T10:04:11.514Z", "severity": "info", "message": "Removed peer \"ebf20841-5281-49b6-aae9-c5b7ebf0a24d\" from room \"42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37\"", "metadata": { "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37" } } { "time": "2025-03-14T10:04:11.514Z", "severity": "info", "message": "Peer socket stopped because room stopped", "metadata": { "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37", "peer_id": "ebf20841-5281-49b6-aae9-c5b7ebf0a24d" } } { "time": "2025-03-14T10:04:11.515Z", "severity": "info", "message": "Peer socket terminates with reason :normal", "metadata": { "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37", "peer_id": "ebf20841-5281-49b6-aae9-c5b7ebf0a24d" } } { "time": "2025-03-14T10:04:11.514Z", "severity": "error", "message": "GenServer {Fishjam.RoomRegistry, \"42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37\"} terminating\n** (stop) :forwarder_crashed\nLast message: %Membrane.RTC.Engine.Message.EndpointCrashed{endpoint_id: \"6ad7b3e6-545f-4c63-977d-3cc9b1d33bfc\", endpoint_type: Membrane.RTC.Engine.Endpoint.Forwarder, reason: {:membrane_child_crash, :connection_handler, {{:badkey, 69514443062572013245424570947}, [{:erlang, :map_get, [69514443062572013245424570947, %{57880509074679002956150741853 => %ExICE.Priv.CandidatePair{id: 57880509074679002956150741853, local_cand_id: 52478115911183563555233399530, remote_cand_id: 71493956163136135705695245364, priority: 7998392938176446462, nominate?: false, nominated?: true, state: :succeeded, valid?: true, succeeded_pair_id: 57880509074679002956150741853, discovered_pair_id: 57880509074679002956150741853, keepalive_timer: #Reference<0.3141675825.1099694085.176433>, last_seen: -576392624063}}], [error_info: %{module: :erl_erts_errors}]}, {ExICE.Priv.ICEAgent, :handle_keepalive_response, 5, [file: ~c\"lib/ex_ice/priv/ice_agent.ex\", line: 1664]}, {ExICE.Priv.ICEAgent, :do_handle_stun_message, 5, [file: ~c\"lib/ex_ice/priv/ice_agent.ex\", line: 1265]}, {ExICE.ICEAgent, :handle_info, 2, [file: ~c\"lib/ex_ice/ice_agent.ex\", line: 393]}, {:gen_server, :try_handle_info, 3, [file: ~c\"gen_server.erl\", line: 2173]}, {:gen_server, :handle_msg, 6, [file: ~c\"gen_server.erl\", line: 2261]}, {:proc_lib, :init_p_do_apply, 3, [file: ~c\"proc_lib.erl\", line: 329]}]}}}", "metadata": { "error": { "initial_call": null, "reason": "{:forwarder_crashed, []}" }, "room_id": "42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37" } } { "time": "2025-03-14T10:04:11.516Z", "severity": "warn", "message": "Process 42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37 is down with reason: :forwarder_crashed", "metadata": {} } { "time": "2025-03-14T10:04:12.142Z", "severity": "info", "message": "New incoming peer WebSocket connection, accepting", "metadata": {} } { "time": "2025-03-14T10:04:12.182Z", "severity": "warn", "message": "Cannot get state of \"42c6-ba4b-05928b42a763-3537376138636462313433323433636138643433393534383362383139333632-666973686a616d4031302e3234302e33342e37\", the room's process doesn't exist anymore", "metadata": {} } { "time": "2025-03-14T10:04:12.182Z", "severity": "warn", "message": "Couldn't find room for the peer", "metadata": {} } { "time": "2025-03-14T10:04:12.182Z", "severity": "info", "message": "Peer socket terminates with reason :normal", "metadata": {} }Broadcaster log (click)
The text was updated successfully, but these errors were encountered: