search

aiortc / aiortc

WebRTC and ORTC implementation for Python using asyncio
BSD 3-Clause "New" or "Revised" License
4.15k stars 750 forks source link

Data channel stuck in connecting state while still receiving messages on it #1045

Closed tfoldi closed 6 months ago

tfoldi commented 7 months ago

I am sure I am the stupid but any help appreciated. I am trying to establish a connection to a WebRTC server while I am on the offering side. The connection seems to be established, and I can actually see messages arriving from the other side. However, whem I trying to reply back on the channel I see that the channel state is connecting, so I cannot send anything on that channel.

How can I receive data on this channel? The on-message callback is fired, but not the on-open. What could be the issue? 

INFO:__main__:Connected to the robot
INFO:__main__:Received message: {"type":"validation","data":"vyFLgIg9SRVRRrqEUXy"}
INFO:__main__:Sending validation message vyFLgIg9SRVRRrqEUXy
ERROR:__main__:Data channel is not open. State is connecting

The class I am using:

class Go2Connection:
    def __init__(self, ip=None, token=None):
        self.pc = RTCPeerConnection()

        self.audio_track = Go2AudioTrack()
        self.video_track = Go2CvVideo()

        # Create and add a data channel
        self.data_channel = self.pc.createDataChannel("data")
        self.data_channel.on("open", self.on_data_channel_open)
        self.data_channel.on("message", self.on_data_channel_message)

    async def generate_offer(self):
        offer = await self.pc.createOffer()
        await self.pc.setLocalDescription(offer)
        return offer.sdp

    async def connect(self):
        logger.info("Connected to the robot")

    def on_data_channel_open(self):
        logger.info("Data channel is open")

    def on_data_channel_message(self, message):
        logger.info("Received message: %s", message)
        message = json.loads(message)
        if message.get("type") == "validation":
            self.validate(message)

    def validate(self, message):
        if message.get("data") == "Validation Ok.":
            self.validation_result = "SUCCESS"
        else:
            logger.info("Sending validation message %s", message.get("data"))
            self.publish(
                "",
                self.encrypt_key(message.get("data")),
                DATA_CHANNEL_TYPE["VALIDATION"],
            )

    def publish(self, topic, data, msg_type):
        if not self.data_channel or not self.data_channel.readyState == "open":
            logger.error(
                "Data channel is not open. State is %s", self.data_channel.readyState
            )
            return
        payload = {
            "type": msg_type or DATA_CHANNEL_TYPE["MESSAGE"],
            "topic": topic,
            "data": data,
        }
        logger.info("Sending payload %s", json.dumps(payload))
        self.data_channel.send(json.dumps(payload))
        logger.info("Payload sent")

Full debug logs:

DEBUG:asyncio:Using selector: KqueueSelector
DEBUG:aiortc.rtcpeerconnection:RTCPeerConnection() setLocalDescription(offer)
v=0
o=- 3917156215 3917156215 IN IP4 0.0.0.0
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic:WMS *
m=application 9 DTLS/SCTP 5000
c=IN IP4 0.0.0.0
a=mid:0
a=sctpmap:5000 webrtc-datachannel 65535
a=max-message-size:65536
a=ice-ufrag:SFAG
a=ice-pwd:VdlINQpC8xsizlgpPOPQ7c
a=fingerprint:sha-256 85:AB:22:8C:77:34:0A:B7:AC:3F:50:06:BF:62:A6:4E:38:36:9C:B4:92:A9:11:1C:3E:C3:92:1F:B6:9D:A7:EF
a=setup:actpass

DEBUG:aiortc.rtcpeerconnection:RTCPeerConnection() iceGatheringState new -> gathering
DEBUG:aioice.ice:Connection(0) protocol(0) connection_made(<_SelectorDatagramTransport fd=6 read=idle write=<idle, bufsize=0>>)
DEBUG:aioice.ice:Connection(0) protocol(0) > ('142.251.19.127', 19302) Message(message_method=Method.BINDING, message_class=Class.REQUEST, transaction_id=b'\xd6\xbe\xd28\x0e\x93\xa7~\xdb\xe9d\xb1')
DEBUG:aioice.ice:Connection(0) protocol(0) < ('142.251.19.127', 19302) Message(message_method=Method.BINDING, message_class=Class.RESPONSE, transaction_id=b'\xd6\xbe\xd28\x0e\x93\xa7~\xdb\xe9d\xb1')
DEBUG:aiortc.rtcpeerconnection:RTCPeerConnection() iceGatheringState gathering -> complete
INFO:__main__:Sending offer to the signaling server at http://192.168.88.93:8081/offer
INFO:__main__:Received answer from server
DEBUG:__main__:{'type': 'answer', 'sdp': 'v=0\r\no=- 68193079 2 IN IP4 127.0.0.1\r\ns=-\r\nt=0 0\r\na=group:BUNDLE 0\r\na=msid-semantic: WMS myKvsVideoStream\r\nm=application 9 UDP/DTLS/SCTP webrtc-datachannel\r\nc=IN IP4 127.0.0.1\r\na=candidate:2 1 udp 2130706431 FD34:DA26:3057:A4AD:7C60:01F4:0AB3:A087 36442 typ host raddr ::/0 rport 0 generation 0 network-cost 999\r\na=candidate:1 1 udp 2130706431 FD34:DA26:3057:A4AD:A5E5:AC92:835A:4F85 48206 typ host raddr ::/0 rport 0 generation 0 network-cost 999\r\na=candidate:0 1 udp 2130706431 192.168.88.93 42994 typ host raddr 0.0.0.0 rport 0 generation 0 network-cost 999\r\na=rtcp:9 IN IP4 0.0.0.0\r\na=ice-ufrag:jo9T\r\na=ice-pwd:Br9iMBQakkjey3bBxIkChGJV\r\na=fingerprint:sha-256 23:2D:4E:23:6F:89:3D:0A:8F:E3:CE:78:87:6B:85:73:6F:E7:58:32:B2:34:30:34:7F:BF:93:AF:2A:B6:E6:86\r\na=setup:active\r\na=mid:0\r\na=sctp-port:5000\r\n', 'id': 'STA_localNetwork'}
DEBUG:aiortc.rtcpeerconnection:RTCPeerConnection() setRemoteDescription(answer)
v=0
o=- 68193079 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic: WMS myKvsVideoStream
m=application 9 UDP/DTLS/SCTP webrtc-datachannel
c=IN IP4 127.0.0.1
a=candidate:2 1 udp 2130706431 FD34:DA26:3057:A4AD:7C60:01F4:0AB3:A087 36442 typ host raddr ::/0 rport 0 generation 0 network-cost 999
a=candidate:1 1 udp 2130706431 FD34:DA26:3057:A4AD:A5E5:AC92:835A:4F85 48206 typ host raddr ::/0 rport 0 generation 0 network-cost 999
a=candidate:0 1 udp 2130706431 192.168.88.93 42994 typ host raddr 0.0.0.0 rport 0 generation 0 network-cost 999
a=rtcp:9 IN IP4 0.0.0.0
a=ice-ufrag:jo9T
a=ice-pwd:Br9iMBQakkjey3bBxIkChGJV
a=fingerprint:sha-256 23:2D:4E:23:6F:89:3D:0A:8F:E3:CE:78:87:6B:85:73:6F:E7:58:32:B2:34:30:34:7F:BF:93:AF:2A:B6:E6:86
a=setup:active
a=mid:0
a=sctp-port:5000

INFO:__main__:Connected to the robot
DEBUG:aiortc.rtcicetransport:RTCIceTransport(controlling) - new -> checking
DEBUG:aiortc.rtcpeerconnection:RTCPeerConnection() iceConnectionState new -> checking
DEBUG:aiortc.rtcpeerconnection:RTCPeerConnection() connectionState new -> connecting
INFO:aioice.ice:Connection(0) Check CandidatePair(('192.168.88.98', 50160) -> ('192.168.88.93', 42994)) State.FROZEN -> State.WAITING
INFO:aioice.ice:Connection(0) Check CandidatePair(('192.168.88.98', 50160) -> ('192.168.88.93', 42994)) State.WAITING -> State.IN_PROGRESS
DEBUG:aioice.ice:Connection(0) protocol(0) > ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.REQUEST, transaction_id=b'P\xe6t\xff\xfc\x1eM\x0c\x11oF\x8c')
DEBUG:aioice.ice:Connection(0) protocol(0) < ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.RESPONSE, transaction_id=b'P\xe6t\xff\xfc\x1eM\x0c\x11oF\x8c')
INFO:aioice.ice:Connection(0) Check CandidatePair(('192.168.88.98', 50160) -> ('192.168.88.93', 42994)) State.IN_PROGRESS -> State.SUCCEEDED
INFO:aioice.ice:Connection(0) ICE completed
DEBUG:aiortc.rtcicetransport:RTCIceTransport(controlling) - checking -> completed
DEBUG:aiortc.rtcpeerconnection:RTCPeerConnection() iceConnectionState checking -> completed
DEBUG:aiortc.rtcdtlstransport:RTCDtlsTransport(server) - State.NEW -> State.CONNECTING
DEBUG:aioice.ice:Connection(0) protocol(0) < ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.REQUEST, transaction_id=b'\x1b\x8bI\xcf\x1e\xaf\x17(\xe88\x12\xd6')
DEBUG:aioice.ice:Connection(0) protocol(0) > ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.RESPONSE, transaction_id=b'\x1b\x8bI\xcf\x1e\xaf\x17(\xe88\x12\xd6')
DEBUG:aioice.ice:Connection(0) protocol(0) < ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.INDICATION, transaction_id=b'i\xc2\x96\xfd\x96\x87T\xef\x86%)\xb1')
DEBUG:aiortc.rtcdtlstransport:RTCDtlsTransport(server) x DTLS handshake negotiated SRTP_AES128_CM_SHA1_80
DEBUG:aiortc.rtcdtlstransport:RTCDtlsTransport(server) - DTLS handshake complete
DEBUG:aiortc.rtcdtlstransport:RTCDtlsTransport(server) - State.CONNECTING -> State.CONNECTED
DEBUG:aiortc.rtcpeerconnection:RTCPeerConnection() connectionState connecting -> connected
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) > InitChunk(flags=0)
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) - T1(InitChunk) start
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) - State.CLOSED -> State.COOKIE_WAIT
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) < InitChunk(flags=0)
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) < InitAckChunk(flags=0)
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) - T1(InitChunk) cancel
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) - Peer supports 300 outbound streams, 300 max inbound streams
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) > CookieEchoChunk(flags=0)
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) - T1(CookieEchoChunk) start
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) - State.COOKIE_WAIT -> State.COOKIE_ECHOED
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) < CookieAckChunk(flags=0)
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) - T1(CookieEchoChunk) cancel
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) - State.COOKIE_ECHOED -> State.ESTABLISHED
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) > DataChunk(flags=3, tsn=4247946063, stream_id=1, stream_seq=0)
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) - T3 start
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) < DataChunk(flags=3, tsn=4076147729, stream_id=1, stream_seq=0)
INFO:__main__:Received message: {"type":"validation","data":"v2bVTeC8YCEcqtDsjuL"}
INFO:__main__:Sending validation message v2bVTeC8YCEcqtDsjuL
ERROR:__main__:Data channel is not open. State is connecting
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) > SackChunk(flags=0, advertised_rwnd=1048576, cumulative_tsn=4076147729, gaps=[])
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) < DataChunk(flags=3, tsn=4076147730, stream_id=1, stream_seq=1)
INFO:__main__:Received message: {"type":"validation","data":"v2bVTeC8YCEcqtDsjuL"}
INFO:__main__:Sending validation message v2bVTeC8YCEcqtDsjuL
ERROR:__main__:Data channel is not open. State is connecting
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) > SackChunk(flags=0, advertised_rwnd=1048576, cumulative_tsn=4076147730, gaps=[])
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) < SackChunk(flags=0, advertised_rwnd=131072, cumulative_tsn=4247946063, gaps=[])
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) - T3 cancel
DEBUG:aioice.ice:Connection(0) protocol(0) > ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.REQUEST, transaction_id=b'\xff#\xae\x1f\x9b\xba\nb\xccm\xe5\xe8')
DEBUG:aioice.ice:Connection(0) protocol(0) < ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.RESPONSE, transaction_id=b'\xff#\xae\x1f\x9b\xba\nb\xccm\xe5\xe8')
DEBUG:aioice.ice:Connection(0) protocol(0) > ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.REQUEST, transaction_id=b'g\xa8\x95\xc4\xff\xab\xc4\xc0\xaa\xc8\x04\x8b')
DEBUG:aioice.ice:Connection(0) protocol(0) < ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.RESPONSE, transaction_id=b'g\xa8\x95\xc4\xff\xab\xc4\xc0\xaa\xc8\x04\x8b')
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) < DataChunk(flags=3, tsn=4076147731, stream_id=1, stream_seq=2)
INFO:__main__:Received message: {"type":"rtc_inner_req","info":{"req_type":"rtt_probe_send_from_mechine","send_time_stamp":1708167428,"uuid":"b09f9868-89f6-4cd6-bb07-d78385a0ff6c"}}
DEBUG:aiortc.rtcsctptransport:RTCSctpTransport(client) > SackChunk(flags=0, advertised_rwnd=1048576, cumulative_tsn=4076147731, gaps=[])
DEBUG:aioice.ice:Connection(0) protocol(0) < ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.INDICATION, transaction_id=b'i\xc2\x96\xfd\x96\x87T\xef\x86%)\xb1')
DEBUG:aioice.ice:Connection(0) protocol(0) > ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.REQUEST, transaction_id=b'\xbf\xde\xa0\xdd\x13\xdf\x81\xdb\xf2\xa2\xbc\xf5')
DEBUG:aioice.ice:Connection(0) protocol(0) < ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.RESPONSE, transaction_id=b'\xbf\xde\xa0\xdd\x13\xdf\x81\xdb\xf2\xa2\xbc\xf5')
DEBUG:aioice.ice:Connection(0) protocol(0) > ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.REQUEST, transaction_id=b'C\xb8(PA\xbe\x06\xd7ejq~')
DEBUG:aioice.ice:Connection(0) protocol(0) < ('192.168.88.93', 42994) Message(message_method=Method.BINDING, message_class=Class.RESPONSE, transaction_id=b'C\xb8(PA\xbe\x06\xd7ejq~')

Any help appreciated! Thanks!

tfoldi commented 7 months ago

If in the offer I added all other media transceivers, then the connection does not even succeed:

DEBUG:aioice.ice:Connection(1) protocol(2) > ('192.168.88.93', 39544) Message(message_method=Method.BINDING, message_class=Class.ERROR, transaction_id=b'\xc3\x049\x11\x04N\x16C\xDEBUG:asyncio:Using selector: KqueueSelector
DEBUG:__main__:Generating offer
DEBUG:__main__:v=0
o=- 3917168175 3917168175 IN IP4 0.0.0.0
s=-
t=0 0
a=group:BUNDLE 0 1 2
a=msid-semantic:WMS *
m=video 9 UDP/TLS/RTP/SAVPF 97 98 99 100 101 102
c=IN IP4 0.0.0.0
a=recvonly
a=extmap:1 urn:ietf:params:rtp-hdrext:sdes:mid
a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=mid:0
a=msid:629e3ba5-0908-4bcf-8b75-4330644cd911 fc00fa91-af4d-4611-8d51-e6b52f27c165
a=rtcp:9 IN IP4 0.0.0.0
a=rtcp-mux
a=ssrc-group:FID 4290109814 2322942264
a=ssrc:4290109814 cname:254f701a-e71d-4147-855e-50bf9154d433
a=ssrc:2322942264 cname:254f701a-e71d-4147-855e-50bf9154d433
a=rtpmap:97 VP8/90000
a=rtcp-fb:97 nack
a=rtcp-fb:97 nack pli
a=rtcp-fb:97 goog-remb
a=rtpmap:98 rtx/90000
a=fmtp:98 apt=97
a=rtpmap:99 H264/90000
a=rtcp-fb:99 nack
a=rtcp-fb:99 nack pli
a=rtcp-fb:99 goog-remb
a=fmtp:99 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42001f
a=rtpmap:100 rtx/90000
a=fmtp:100 apt=99
a=rtpmap:101 H264/90000
a=rtcp-fb:101 nack
a=rtcp-fb:101 nack pli
a=rtcp-fb:101 goog-remb
a=fmtp:101 level-asymmetry-allowed=1;packetization-mode=1;profile-level-id=42e01f
a=rtpmap:102 rtx/90000
a=fmtp:102 apt=101
a=ice-ufrag:WRkS
a=ice-pwd:0hyy8NirLCi0UOW4BUoUMM
a=fingerprint:sha-256 AA:4A:E8:F7:A8:F9:9D:F8:58:E1:30:07:05:D0:32:70:D0:C7:FB:77:74:55:05:0E:70:2B:72:1C:34:CA:CA:7C
a=setup:actpass
m=audio 9 UDP/TLS/RTP/SAVPF 96 0 8
c=IN IP4 0.0.0.0
a=sendrecv

In wireshark I see the following:

image

If anyone has any idea, I would love to hear and appreciate it!

Thanks!