Add support for sending std::vector<uint8_t> type over DC>

jeffRTC commented 3 years ago

Since send method only support std::byte and string types, I have to make a copy to cast into std::byte and if there is a direct support for std::vector it would improve performance. The case is I read from a Stream and send the data through DataChannel and I use convertJSArrayToNumberVector to get close to zero copy from JS side.

it would be also good to remove casting again to char*type when you are passing this back to the JS side since uint8_t type already match with JS Uint8

        auto rawBuffer = emscripten::convertJSArrayToNumberVector<uint8_t>(reader["value"]);

        std::vector<std::byte> buffer(rawBuffer.size() + 1);

        std::transform(rawBuffer.begin(), rawBuffer.end(), buffer.begin(), [] (uint8_t i) { 
            return std::byte(i); 
        });

        if (auto channel = dc.lock())
        {
            channel->send(buffer);
        }

jeffRTC commented 3 years ago

I found out that even above code doesn't work, it causes an error,

Uncaught TypeError: Cannot read property 'length' of undefined
    at lengthBytesUTF8 (main.js:841)
    at Object.allocUTF8FromString (main.js:5493)
    at RTCDataChannel.cb (main.js:5640)

paullouisageneau commented 3 years ago

There are a few things here:

In your example, replacing channel->send(buffer) with channel->send(std::move(buffer)) will prevent a copy when passing to the wrapper, so the only copy will be your copy.
I can't really add std::vector<uint8_t> because it must stay consistent with libdatachannel, however I can add a generic send with a pointer to data and a size.
If I'm not mistaken, the Cannot read property 'length' of undefined does not seem directly related to sending as it seems to come from the error callback of the DataChannel.

paullouisageneau commented 3 years ago

I added a method send(const byte *data, size_t size) consistent with libdatachannel in https://github.com/paullouisageneau/datachannel-wasm/commit/23d52ce357752233e5fe0b12e8f3f4a950777a31

Also the 'length' of undefined error should be addressed by https://github.com/paullouisageneau/datachannel-wasm/commit/f6c6cb716af66a0557a3d9dc81675fac9554addb

it would be also good to remove casting again to char* type when you are passing this back to the JS side since uint8_t type already match with JS Uint8

Actually the cast does not really have an importance in practice, from JS point of view the pointer is just an untyped address in the wasm heap which can be accessed with HEAPU8, HEAPU16, or HEAPU32.

jeffRTC commented 3 years ago

Thanks for this. I will have a look shortly.

"Error callback of the DataChannel"

Does that mean diff part of the code?

jeffRTC commented 3 years ago

"I can add a generic send with a pointer to data and a size"

Can you add this please?

paullouisageneau commented 3 years ago

Does that mean diff part of the code?

Yes I think so.

"I can add a generic send with a pointer to data and a size"

Can you add this please?

I added a method send(const byte *data, size_t size) in https://github.com/paullouisageneau/datachannel-wasm/commit/23d52ce357752233e5fe0b12e8f3f4a950777a31, you only need to reinterpret cast the pointer to your data to byte *.

jeffRTC commented 3 years ago

Ok.

You can see that in std::transform it causes a copy to byte vector from emscripten vector. Is there any neat way to avoid this at all?

If you can tell me how should I implement uint8_t vector type in send function it would be great. I tried to do it but ran into some things related to your virtual functions & override stuff means I even had to modify websocket.cpp just to add this...

paullouisageneau commented 3 years ago

You only need to do this:

std::vector<uint8_t> buffer = emscripten::convertJSArrayToNumberVector<uint8_t>(reader["value"]);
channel->send(reinterpret_cast<rtc::byte*>(buffer.data()), buffer.size())

jeffRTC commented 3 years ago

No copy with this way?

paullouisageneau commented 3 years ago

Nope, it won't copy this way.

jeffRTC commented 3 years ago

Ok. I used it like you said but on server side I am not seeing any messages

                dc->onMessage([this, id, wDC = make_weak_ptr(dc)](const std::variant<rtc::binary, std::string> &message) {
                    if (std::holds_alternative<rtc::binary>(message))
                    {
                        std::cout << "DEBUG: GOT BINARY" << "\n";  /// THIS NOT PRINTS so the rest code doesn't execute!! 

                        auto buffer = std::get<rtc::binary>(message);

                        std::string body(reinterpret_cast<const char *>(buffer.data()), buffer.size());

                        std::cout << "Message from " << id << " received: "
                                  << body
                                  << "\n";
                    }
                });

paullouisageneau commented 3 years ago

Could you post the exact code you use to send the message? Also, are you sure dc is stored somewhere so it is not deleted this time?

jeffRTC commented 3 years ago

dc is stored as a global var. I can send strings and view them on server but the bytes are not. You've already seen the code, but here again,

     while (true)
    {
        emscripten::val reader = stream.call<emscripten::val>("read").await();

        if (reader["done"].isTrue())
        {
            std::cout << "Stream has been ended"
                      << "\n";
            break;
        }

        auto buffer = emscripten::convertJSArrayToNumberVector<uint8_t>(reader["value"]);

        if (auto channel = dc.lock())
        {
            channel->send(reinterpret_cast<rtc::byte*>(buffer.data()), buffer.size());
        }
    }

paullouisageneau commented 3 years ago

Are you sure the send method is actually called? (in particular, are you sure the dc.lock() succeeds?)

jeffRTC commented 3 years ago

dc.lock works and send method actually called.

    if (auto channel = dc.lock())
    {
        std::cout << "Hey" << "\n";
        channel->send(reinterpret_cast<rtc::byte*>(buffer.data()), buffer.size());
    }

"Hey" prints too.

I can even send STRINGS but RTC::BYTE is hiding!!

jeffRTC commented 3 years ago

I modified the send function on your JS code as follows,

        rtcSendMessage: function(dc, pBuffer, size) {
            var dataChannel = WEBRTC.dataChannelsMap[dc];
            if(dataChannel.readyState != 'open') return 0;
            if(size >= 0) {
                var heapBytes = new Uint8Array(Module['HEAPU8'].buffer, pBuffer, size);
                console.log(heapBytes)
                try{
                dataChannel.send(heapBytes.buffer);
                } catch(err) {
                    console.log(err)
                }
                return size;
            }

I can see that heapBytes has successfully logged into console and no errors.

According to the MDN https://developer.mozilla.org/en-US/docs/Web/API/RTCDataChannel/send ,

Send method can throw an exception if the message has been failed to send.

I see no errors logged.

Let me know if you need to see something specific on chrome://webrtc-internals/

paullouisageneau commented 3 years ago

OK, then it appears sending works fine, the issue must be at reception. When you say "on server side", is it also in a browser or is it compiled natively with libdatachannel?

jeffRTC commented 3 years ago

Native libdatachannel on server not browser

jeffRTC commented 3 years ago

Here, I could see hey prints but std::holds_alternative<rtc::binary> fails


                dc->onMessage([this, id, wDC = make_weak_ptr(dc)](const std::variant<rtc::binary, std::string> &message) {
                    std::cout << "hey" << "\n";
                    if (std::holds_alternative<rtc::binary>(message))
                    {

paullouisageneau commented 3 years ago

I couldn't reproduce the behavior when sending binary data from a browser to libdatachannel. Does the binary data arrives as a string in your setup?

By the way, do you use the correct submodule version of libdatachannel? (i.e., obtained with git submodule update --recursive)

jeffRTC commented 3 years ago

I'm not using submodule of this repo. I'm using your native repo on server side.

Apparently, dc->onMessage get called because I send a string in dc->onOpen and now I removed it. I see that it's not getting called anymore.

Means the server doesn't receive binary type at all.

But with Strings - I again checked, it works fine.

paullouisageneau commented 3 years ago

OK, could you please post the verbose libdatachannel log on the server side ?

paullouisageneau commented 3 years ago

What size is the binary message you are trying to send?

jeffRTC commented 3 years ago

Size is 19

2020-11-29 17:49:30.671 DEBUG [1166629] [rtc::{anonymous}::doInit@46] Global initialization
2020-11-29 17:49:30.673 VERB  [1166629] [rtc::PeerConnection::PeerConnection@48] Creating PeerConnection
2020-11-29 17:49:30.673 VERB  [1166629] [rtc::PeerConnection::setRemoteDescription@118] Setting remote description: v=0
o=- 571098302157712800 0 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic:WMS *
a=setup:actpass
a=ice-ufrag:+60M
a=ice-pwd:B1djhrQCnJUjOQFVijrxMcZv
a=ice-options:trickle
a=fingerprint:sha-256 27:26:68:6F:F4:56:B7:46:A8:B5:A8:D9:3A:2E:E1:64:50:CD:CD:F4:C9:51:EC:7B:DB:34:21:20:CB:E5:43:86
m=application 9 UDP/DTLS/SCTP webrtc-datachannel
c=IN IP4 0.0.0.0
a=bundle-only
a=mid:0
a=sendrecv
a=ice-options:trickle
a=sctp-port:5000
a=max-message-size:262144

2020-11-29 17:49:30.674 DEBUG [1166629] [rtc::IceTransport::IceTransport@327] Initializing ICE transport (libnice)
2020-11-29 17:49:30.674 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Created NiceStream (1 created, 0 destroyed)
2020-11-29 17:49:30.674 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Created NiceComponent (1 created, 0 destroyed)
2020-11-29 17:49:30.674 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : allocating stream id 1 (0x7efe3c01b3f0)
2020-11-29 17:49:30.674 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Property set, role is already "controlling".
2020-11-29 17:49:30.702 DEBUG [1166629] [rtc::IceTransport::IceTransport@415] Using STUN server "stun.services.mozilla.com:3478"
2020-11-29 17:49:30.702 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Property set, changing role to "controlled".
2020-11-29 17:49:30.703 DEBUG [1166629] [rtc::PeerConnection::processLocalDescription@749] Reciprocating application in local description, mid="0"
2020-11-29 17:49:30.785 INFO  [1166629] [rtc::PeerConnection::changeGatheringState@888] Changed gathering state to in_progress
2020-11-29 17:49:30.785 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : In ICE-FULL mode, starting candidate gathering.
2020-11-29 17:49:30.785 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : UPnP property Disabled
2020-11-29 17:49:30.785 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Failed to convert address to string for interface ‘lo’.
2020-11-29 17:49:30.785 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Failed to convert address to string for interface ‘eth0’.
2020-11-29 17:49:30.785 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Interface:  lo
2020-11-29 17:49:30.785 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: IP Address: 127.0.0.1
2020-11-29 17:49:30.785 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Ignoring loopback interface
2020-11-29 17:49:30.785 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Interface:  eth0
2020-11-29 17:49:30.785 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: IP Address: HIDDEN_FOR_PRIVACY
2020-11-29 17:49:30.785 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Interface:  lo
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: IP Address: ::1
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Ignoring loopback interface
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Interface:  eth0
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: IP Address: HIDDEN_FOR_PRIVACY
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Interface:  eth0
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: IP Address: fe80::f03c:92ff:fe64:cdfd%eth0
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Trying to create host candidate on port 15198
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Component 0x7efe3c01bbc0: Attach source (stream 1).
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Attaching source 0x7efe3c0242b0 (socket 0x7efe3c0146e0, FD 21) to context 0x7efe3c0113d0
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Trying to create host candidate on port 7691
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Component 0x7efe3c01bbc0: Attach source (stream 1).
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Attaching source 0x7efe3c024410 (socket 0x7efe3c025480, FD 22) to context 0x7efe3c0113d0
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Trying to create host candidate on port 29349
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Could not set IPV6 socket ToS: Protocol not available
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Component 0x7efe3c01bbc0: Attach source (stream 1).
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Attaching source 0x7efe3c0276e0 (socket 0x7efe3c0254f0, FD 23) to context 0x7efe3c0113d0
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Adding new srv-rflx candidate discovery 0x7efe3c027840
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : discovery tick #1 with list 0x7efe3c010cc0 (1)
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : discovery - scheduling cand type 1 addr 52.87.201.4.
2020-11-29 17:49:30.786 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : stream 1 component 1 STATE-CHANGE disconnected -> gathering.
2020-11-29 17:49:30.785 VERB  [1166659] [rtc::PeerConnection::processLocalDescription@828] Issuing local description: v=0
o=rtc 896040576 0 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic:WMS *
a=setup:active
a=ice-ufrag:3Zej
a=ice-pwd:0Pv7RULDyaXPDeSZCA45Rd
a=ice-options:trickle
a=fingerprint:sha-256 6E:EA:D2:44:F1:19:26:7D:17:60:E8:AC:FA:2C:DB:07:B5:0F:31:DE:6E:54:A2:13:69:80:A1:9B:06:88:4E:1B
m=application 9 UDP/DTLS/SCTP webrtc-datachannel
c=IN IP4 0.0.0.0
a=bundle-only
a=mid:0
a=sendrecv
a=ice-options:trickle
a=sctp-port:5000
a=max-message-size:262144

Gathering State: in_progress
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::Candidate::resolve@85] Resolving candidate (mode=simple): 1 1 UDP 2013266431 HIDDEN_FOR_PRIVACY15198 typ host
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::Candidate::resolve@161] Resolved candidate: 1 1 UDP 2013266431 HIDDEN_FOR_PRIVACY15198 typ host
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::Candidate::resolve@85] Resolving candidate (mode=simple): 2 1 UDP 2013266430 HIDDEN_FOR_PRIVACY 7691 typ host
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::Candidate::resolve@161] Resolved candidate: 2 1 UDP 2013266430 HIDDEN_FOR_PRIVACY 7691 typ host
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::Candidate::resolve@85] Resolving candidate (mode=simple): 3 1 UDP 2013266429 HIDDEN_FOR_PRIVACY 29349 typ host
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::Candidate::resolve@161] Resolved candidate: 3 1 UDP 2013266429 HIDDEN_FOR_PRIVACY 29349 typ host
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::PeerConnection::addRemoteCandidate@205] Adding remote candidate: a=candidate:1802928054 1 udp 2122262783 2602:ff50::37:c1bf:b4a2:a258:6ec 53451 typ host generation 0 ufrag +60M network-id 4
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::Candidate::resolve@85] Resolving candidate (mode=simple): 1802928054 1 udp 2122262783 2602:ff50::37:c1bf:b4a2:a258:6ec 53451 typ host generation 0 ufrag +60M network-id 4
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::Candidate::resolve@161] Resolved candidate: 1802928054 1 udp 2122262783 HIDDEN_FOR_PRIVACY 53451 typ host generation 0 ufrag +60M network-id 4
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: set_remote_candidates 1 1
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Adding UDP remote candidate with addr [HIDDEN_FOR_PRIVACY]:53451 for s1/c1. U/P '(null)'/'(null)' prio: 2122262783
2020-11-29 17:49:30.787 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : creating a new pair
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e030 state FROZEN (priv_add_new_check_pair)
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : new pair 0x7efe3c03e030 : [fe80::f03c:92ff:fe64:cdfd]:15198 --> [HIDDEN_FOR_PRIVACY]:53451
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : added a new pair 0x7efe3c03e030 with foundation '1:1802928054' to stream 1 component 1.
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : stream 1 component 1 STATE-CHANGE gathering -> connecting.
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : creating a new pair
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e0e0 state FROZEN (priv_add_new_check_pair)
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : new pair 0x7efe3c03e0e0 : [HIDDEN_FOR_PRIVACY]:7691 --> [HIDDEN_FOR_PRIVACY]:53451
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : added a new pair 0x7efe3c03e0e0 with foundation '2:1802928054' to stream 1 component 1.
2020-11-29 17:49:30.788 INFO  [1166629] [rtc::PeerConnection::changeState@873] Changed state to connecting
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::PeerConnection::addRemoteCandidate@205] Adding remote candidate: a=candidate:4201576948 1 udp 2122194687 HIDDEN_FOR_PRIVACY 53452 typ host generation 0 ufrag +60M network-id 1
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::Candidate::resolve@85] Resolving candidate (mode=simple): 4201576948 1 udp 2122194687 HIDDEN_FOR_PRIVACY 53452 typ host generation 0 ufrag +60M network-id 1
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::Candidate::resolve@161] Resolved candidate: 4201576948 1 udp 2122194687 HIDDEN_FOR_PRIVACY 53452 typ host generation 0 ufrag +60M network-id 1
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: set_remote_candidates 1 1
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Adding UDP remote candidate with addr [HIDDEN_FOR_PRIVACY]:53452 for s1/c1. U/P '(null)'/'(null)' prio: 2122194687
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : creating a new pair
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e190 state FROZEN (priv_add_new_check_pair)
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : new pair 0x7efe3c03e190 : [HIDDEN_FOR_PRIVACY]:29349 --> [HIDDEN_FOR_PRIVACY]:53452
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : added a new pair 0x7efe3c03e190 with foundation '3:4201576948' to stream 1 component 1.
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::PeerConnection::addRemoteCandidate@205] Adding remote candidate: a=candidate:2999745851 1 udp 2122129151 HIDDEN_FOR_PRIVACY 53453 typ host generation 0 ufrag +60M network-id 2
2020-11-29 17:49:30.787 VERB  [1166657] [rtc::PeerConnection::processLocalCandidate@842] Issuing local candidate: a=candidate:1 1 UDP 2013266431 HIDDEN_FOR_PRIVACY15198 typ host
Adding Candidate
2020-11-29 17:49:30.788 VERB  [1166657] [rtc::PeerConnection::processLocalCandidate@842] Issuing local candidate: a=candidate:2 1 UDP 2013266430 HIDDEN_FOR_PRIVACY 7691 typ host
Adding Candidate
2020-11-29 17:49:30.788 VERB  [1166657] [rtc::PeerConnection::processLocalCandidate@842] Issuing local candidate: a=candidate:3 1 UDP 2013266429 HIDDEN_FOR_PRIVACY 29349 typ host
Adding Candidate
State: connecting
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::Candidate::resolve@85] Resolving candidate (mode=simple): 2999745851 1 udp 2122129151 HIDDEN_FOR_PRIVACY 53453 typ host generation 0 ufrag +60M network-id 2
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::Candidate::resolve@161] Resolved candidate: 2999745851 1 udp 2122129151 HIDDEN_FOR_PRIVACY 53453 typ host generation 0 ufrag +60M network-id 2
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: set_remote_candidates 1 1
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Adding UDP remote candidate with addr [HIDDEN_FOR_PRIVACY]:53453 for s1/c1. U/P '(null)'/'(null)' prio: 2122129151
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : creating a new pair
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e240 state FROZEN (priv_add_new_check_pair)
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : new pair 0x7efe3c03e240 : [HIDDEN_FOR_PRIVACY]:29349 --> [HIDDEN_FOR_PRIVACY]:53453
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : added a new pair 0x7efe3c03e240 with foundation '3:2999745851' to stream 1 component 1.
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::PeerConnection::addRemoteCandidate@205] Adding remote candidate: a=candidate:917165150 1 udp 2122063615 HIDDEN_FOR_PRIVACY 53454 typ host generation 0 ufrag +60M network-id 3
2020-11-29 17:49:30.788 VERB  [1166629] [rtc::Candidate::resolve@85] Resolving candidate (mode=simple): 917165150 1 udp 2122063615 HIDDEN_FOR_PRIVACY 53454 typ host generation 0 ufrag +60M network-id 3
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::Candidate::resolve@161] Resolved candidate: 917165150 1 udp 2122063615 HIDDEN_FOR_PRIVACY 53454 typ host generation 0 ufrag +60M network-id 3
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: set_remote_candidates 1 1
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Adding UDP remote candidate with addr [HIDDEN_FOR_PRIVACY]:53454 for s1/c1. U/P '(null)'/'(null)' prio: 2122063615
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : creating a new pair
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e2f0 state FROZEN (priv_add_new_check_pair)
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : new pair 0x7efe3c03e2f0 : [HIDDEN_FOR_PRIVACY]:29349 --> [HIDDEN_FOR_PRIVACY]:53454
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : added a new pair 0x7efe3c03e2f0 with foundation '3:917165150' to stream 1 component 1.
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::PeerConnection::addRemoteCandidate@205] Adding remote candidate: a=candidate:636846918 1 tcp 1518283007 2602:ff50::37:c1bf:b4a2:a258:6ec 9 typ host tcptype active generation 0 ufrag +60M network-id 4
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::Candidate::resolve@85] Resolving candidate (mode=simple): 636846918 1 tcp 1518283007 2602:ff50::37:c1bf:b4a2:a258:6ec 9 typ host tcptype active generation 0 ufrag +60M network-id 4
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::Candidate::resolve@161] Resolved candidate: 636846918 1 tcp 1518283007 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag +60M network-id 4
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: set_remote_candidates 1 1
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::PeerConnection::addRemoteCandidate@205] Adding remote candidate: a=candidate:3035432196 1 tcp 1518214911 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag +60M network-id 1
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::Candidate::resolve@85] Resolving candidate (mode=simple): 3035432196 1 tcp 1518214911 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag +60M network-id 1
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::Candidate::resolve@161] Resolved candidate: 3035432196 1 tcp 1518214911 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag +60M network-id 1
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: set_remote_candidates 1 1
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::PeerConnection::addRemoteCandidate@205] Adding remote candidate: a=candidate:4233069003 1 tcp 1518149375 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag +60M network-id 2
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::Candidate::resolve@85] Resolving candidate (mode=simple): 4233069003 1 tcp 1518149375 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag +60M network-id 2
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::Candidate::resolve@161] Resolved candidate: 4233069003 1 tcp 1518149375 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag +60M network-id 2
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: set_remote_candidates 1 1
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::PeerConnection::addRemoteCandidate@205] Adding remote candidate: a=candidate:2015963310 1 tcp 1518083839 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag +60M network-id 3
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::Candidate::resolve@85] Resolving candidate (mode=simple): 2015963310 1 tcp 1518083839 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag +60M network-id 3
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::Candidate::resolve@161] Resolved candidate: 2015963310 1 tcp 1518083839 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag +60M network-id 3
2020-11-29 17:49:30.789 VERB  [1166629] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: set_remote_candidates 1 1
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Pair 0x7efe3c03e030 with s/c-id 1/1 (1:1802928054) unfrozen.
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e030 state WAITING (priv_conn_check_unfreeze_next)
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Pair 0x7efe3c03e0e0 with s/c-id 1/1 (2:1802928054) unfrozen.
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e0e0 state WAITING (priv_conn_check_unfreeze_next)
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Pair 0x7efe3c03e190 with s/c-id 1/1 (3:4201576948) unfrozen.
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e190 state WAITING (priv_conn_check_unfreeze_next)
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Pair 0x7efe3c03e240 with s/c-id 1/1 (3:2999745851) unfrozen.
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e240 state WAITING (priv_conn_check_unfreeze_next)
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Pair 0x7efe3c03e2f0 with s/c-id 1/1 (3:917165150) unfrozen.
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e2f0 state WAITING (priv_conn_check_unfreeze_next)
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e030 state IN_PROGRESS (priv_conn_check_initiate)
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC REQ [fe80::f03c:92ff:fe64:cdfd]:15198 --> [HIDDEN_FOR_PRIVACY]:53451, socket=21, pair=0x7efe3c03e030 (c-id:1), tie=16199083266985692841, username='+60M:3Zej' (9), password='B1djhrQCnJUjOQFVijrxMcZv' (24), prio=1845494271, controlled.
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn_check_send: set cand_use=0 (aggressive nomination).
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: conncheck created 88 - 0x7efe18003640
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : timer set to 125ms, waiting+in_progress=5, nb_active=1
2020-11-29 17:49:30.813 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : stream 1: timer tick #1: 0 frozen, 1 in-progress, 4 waiting, 0 succeeded, 0 discovered, 0 nominated, 0 waiting-for-nom, 0 valid.
2020-11-29 17:49:30.838 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e0e0 state IN_PROGRESS (priv_conn_check_initiate)
2020-11-29 17:49:30.838 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC REQ [HIDDEN_FOR_PRIVACY]:7691 --> [HIDDEN_FOR_PRIVACY]:53451, socket=22, pair=0x7efe3c03e0e0 (c-id:1), tie=16199083266985692841, username='+60M:3Zej' (9), password='B1djhrQCnJUjOQFVijrxMcZv' (24), prio=1845494270, controlled.
2020-11-29 17:49:30.838 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn_check_send: set cand_use=0 (aggressive nomination).
2020-11-29 17:49:30.838 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: conncheck created 88 - 0x7efe18005430
2020-11-29 17:49:30.839 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : timer set to 125ms, waiting+in_progress=5, nb_active=1
2020-11-29 17:49:30.864 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e190 state IN_PROGRESS (priv_conn_check_initiate)
2020-11-29 17:49:30.864 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC REQ [HIDDEN_FOR_PRIVACY]:29349 --> [HIDDEN_FOR_PRIVACY]:53452, socket=23, pair=0x7efe3c03e190 (c-id:1), tie=16199083266985692841, username='+60M:3Zej' (9), password='B1djhrQCnJUjOQFVijrxMcZv' (24), prio=1845494269, controlled.
2020-11-29 17:49:30.864 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn_check_send: set cand_use=0 (aggressive nomination).
2020-11-29 17:49:30.864 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: conncheck created 88 - 0x7efe18005f50
2020-11-29 17:49:30.864 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : timer set to 125ms, waiting+in_progress=5, nb_active=1
2020-11-29 17:49:30.879 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53451 (100 octets) :
2020-11-29 17:49:30.879 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 :  1:1 Adding valid source candidate: HIDDEN_FOR_PRIVACY:53451 trans: 0
2020-11-29 17:49:30.879 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53451', socket=22, len=92, cand=0x7efe3c017540 (c-id:1), use-cand=1.
2020-11-29 17:49:30.879 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Found a matching pair 0x7efe3c03e0e0 (2:1802928054) (IN_PROGRESS) ...
2020-11-29 17:49:30.879 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e0e0 added for a triggered check.
2020-11-29 17:49:30.879 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e0e0 state IN_PROGRESS (priv_add_pair_to_triggered_check_queue)
2020-11-29 17:49:30.879 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e0e0 (2:1802928054) is in-progress, will be nominated on response receipt.
2020-11-29 17:49:30.879 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53451 (76 octets) :
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : stun_bind_process/conncheck for 0x7efe3c03e0e0: controlled,res=success,stun#=0.
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e0e0 MATCHED.
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e0e0 state SUCCEEDED (priv_process_response_check_for_reflexive)
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Updating nominated flag (UDP): ok_pair=0x7efe3c03e0e0 (0/1) p=0x7efe3c03e0e0 (0/1) (ucnc/mnora)
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : marking pair 0x7efe3c03e0e0 (2:1802928054) as nominated (aggressive nomination, controlled, mark_on_response=1).
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : changing SELECTED PAIR for component 1: 2:1802928054 (prio:8646913479229198847).
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: setting SELECTED PAIR for component 1: 2:1802928054 (prio:8646913479229198847).
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : stun_bind_keepalive for pair 0x7efe3c01bc30 res 28.
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : resending STUN on 3 to keep the candidate alive.
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Local selected pair: 1:1 2 UDP HIDDEN_FOR_PRIVACY:7691 HOST
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Remote selected pair: 1:1 1802928054 UDP HIDDEN_FOR_PRIVACY:53451 HOST
2020-11-29 17:49:30.885 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : stream 1 component 1 STATE-CHANGE connecting -> connected.
2020-11-29 17:49:30.886 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:30.886 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:30.886 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e030 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 17:49:30.886 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e190 will not be retransmitted.
2020-11-29 17:49:30.886 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e240 removed.
2020-11-29 17:49:30.886 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e2f0 removed.
2020-11-29 17:49:30.886 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 17:49:30.886 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 17:49:30.886 DEBUG [1166667] [rtc::DtlsTransport::DtlsTransport@58] Initializing DTLS transport (GnuTLS)
2020-11-29 17:49:30.886 DEBUG [1166667] [rtc::DtlsTransport::start@105] Starting DTLS recv thread
2020-11-29 17:49:30.886 VERB  [1166668] [rtc::IceTransport::send@596] Send size=215
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53451 (100 octets) :
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53451', socket=22, len=92, cand=0x7efe3c017540 (c-id:1), use-cand=1.
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Found a matching pair 0x7efe3c03e0e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : nothing to do for pair 0x7efe3c03e0e0.
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e030 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e190 will not be retransmitted.
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : marking pair 0x7efe3c03e0e0 (2:1802928054) as nominated
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e030 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e190 will not be retransmitted.
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 17:49:30.928 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 17:49:30.933 VERB  [1166667] [rtc::IceTransport::RecvCallback@699] Incoming size=639
2020-11-29 17:49:30.933 VERB  [1166667] [rtc::DtlsTransport::incoming@142] Incoming size=639
2020-11-29 17:49:30.940 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 :STUN transaction retransmitted on pair 0x7efe3c03e030 (timer=2/3 2/250ms).
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53451 (100 octets) :
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53451', socket=22, len=92, cand=0x7efe3c017540 (c-id:1), use-cand=1.
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Found a matching pair 0x7efe3c03e0e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : nothing to do for pair 0x7efe3c03e0e0.
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e030 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e190 will not be retransmitted.
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : marking pair 0x7efe3c03e0e0 (2:1802928054) as nominated
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e030 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e190 will not be retransmitted.
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 17:49:30.978 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 17:49:30.990 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Retransmissions failed, giving up on pair 0x7efe3c03e190
2020-11-29 17:49:30.990 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Failed pair is [HIDDEN_FOR_PRIVACY]:29349 --> [HIDDEN_FOR_PRIVACY]:53452
2020-11-29 17:49:30.990 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e190 state FAILED (candidate_check_pair_fail)
2020-11-29 17:49:30.990 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:30.990 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:30.990 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e030 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 17:49:30.990 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 17:49:31.029 VERB  [1166667] [rtc::IceTransport::RecvCallback@699] Incoming size=639
2020-11-29 17:49:31.029 VERB  [1166667] [rtc::DtlsTransport::incoming@142] Incoming size=639
2020-11-29 17:49:31.110 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53454 (96 octets) :
2020-11-29 17:49:31.110 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 :  1:1 Adding valid source candidate: HIDDEN_FOR_PRIVACY:53454 trans: 0
2020-11-29 17:49:31.110 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53454', socket=23, len=80, cand=0x7efe3c03f000 (c-id:1), use-cand=0.
2020-11-29 17:49:31.110 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Adding a triggered check to conn.check list (local=0x7efe3c017390).
2020-11-29 17:49:31.110 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : creating a new pair
2020-11-29 17:49:31.110 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e2f0 state WAITING (priv_add_new_check_pair)
2020-11-29 17:49:31.110 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : new pair 0x7efe3c03e2f0 : [HIDDEN_FOR_PRIVACY]:29349 --> [HIDDEN_FOR_PRIVACY]:53454
2020-11-29 17:49:31.110 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : added a new pair 0x7efe3c03e2f0 with foundation '3:917165150' to stream 1 component 1.
2020-11-29 17:49:31.110 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e2f0 state IN_PROGRESS (priv_add_pair_to_triggered_check_queue)
2020-11-29 17:49:31.110 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 17:49:31.127 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC REQ [HIDDEN_FOR_PRIVACY]:29349 --> [HIDDEN_FOR_PRIVACY]:53454, socket=23, pair=0x7efe3c03e2f0 (c-id:1), tie=16199083266985692841, username='+60M:3Zej' (9), password='B1djhrQCnJUjOQFVijrxMcZv' (24), prio=1845494268, controlled.
2020-11-29 17:49:31.127 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn_check_send: set cand_use=0 (aggressive nomination).
2020-11-29 17:49:31.127 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: conncheck created 88 - 0x7efe1800f3c0
2020-11-29 17:49:31.127 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : timer set to 100ms, waiting+in_progress=2, nb_active=1
2020-11-29 17:49:31.145 VERB  [1166668] [rtc::IceTransport::send@596] Send size=984
2020-11-29 17:49:31.152 VERB  [1166668] [rtc::IceTransport::send@596] Send size=91
2020-11-29 17:49:31.152 VERB  [1166668] [rtc::IceTransport::send@596] Send size=413
2020-11-29 17:49:31.152 VERB  [1166668] [rtc::IceTransport::send@596] Send size=14
2020-11-29 17:49:31.152 VERB  [1166668] [rtc::IceTransport::send@596] Send size=53
2020-11-29 17:49:31.158 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53454 (64 octets) :
2020-11-29 17:49:31.158 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : stun_bind_process/conncheck for 0x7efe3c03e2f0: controlled,res=success,stun#=0.
2020-11-29 17:49:31.158 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e2f0 MATCHED.
2020-11-29 17:49:31.159 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e2f0 state SUCCEEDED (priv_process_response_check_for_reflexive)
2020-11-29 17:49:31.159 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Updating nominated flag (UDP): ok_pair=0x7efe3c03e2f0 (0/0) p=0x7efe3c03e2f0 (0/0) (ucnc/mnora)
2020-11-29 17:49:31.159 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:31.159 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:31.159 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e030 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 17:49:31.159 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 17:49:31.159 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 17:49:31.200 VERB  [1166667] [rtc::IceTransport::RecvCallback@699] Incoming size=1181
2020-11-29 17:49:31.200 VERB  [1166667] [rtc::DtlsTransport::incoming@142] Incoming size=1181
2020-11-29 17:49:31.200 VERB  [1166667] [rtc::IceTransport::RecvCallback@699] Incoming size=53
2020-11-29 17:49:31.200 VERB  [1166667] [rtc::DtlsTransport::incoming@142] Incoming size=53
2020-11-29 17:49:31.201 VERB  [1166667] [rtc::IceTransport::RecvCallback@699] Incoming size=73
2020-11-29 17:49:31.201 VERB  [1166667] [rtc::DtlsTransport::incoming@142] Incoming size=73
2020-11-29 17:49:31.203 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 :STUN transaction retransmitted on pair 0x7efe3c03e030 (timer=3/3 15/125ms).
2020-11-29 17:49:31.328 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Retransmissions failed, giving up on pair 0x7efe3c03e030
2020-11-29 17:49:31.328 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Failed pair is [fe80::f03c:92ff:fe64:cdfd]:15198 --> [HIDDEN_FOR_PRIVACY]:53451
2020-11-29 17:49:31.328 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e030 state FAILED (candidate_check_pair_fail)
2020-11-29 17:49:31.328 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:31.328 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:31.328 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : stream 1 component 1 STATE-CHANGE connected -> ready.
2020-11-29 17:49:31.328 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 17:49:31.328 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : waiting 1000 msecs before checking for failed components.
2020-11-29 17:49:31.753 INFO  [1166668] [rtc::DtlsTransport::runRecvLoop@179] DTLS handshake finished
2020-11-29 17:49:31.753 DEBUG [1166668] [rtc::SctpTransport::SctpTransport@95] Initializing SCTP transport
2020-11-29 17:49:31.753 DEBUG [1166668] [rtc::SctpTransport::connect@237] SCTP connecting
2020-11-29 17:49:31.758 VERB  [1166668] [rtc::SctpTransport::handleWrite@518] Handle write, len=100
2020-11-29 17:49:31.758 VERB  [1166668] [rtc::DtlsTransport::send@123] Send size=100
2020-11-29 17:49:31.758 VERB  [1166668] [rtc::IceTransport::send@596] Send size=129
2020-11-29 17:49:31.759 VERB  [1166668] [rtc::SctpTransport::incoming@318] Incoming size=44
2020-11-29 17:49:31.759 VERB  [1166668] [rtc::SctpTransport::handleWrite@518] Handle write, len=356
2020-11-29 17:49:31.759 VERB  [1166668] [rtc::DtlsTransport::send@123] Send size=356
2020-11-29 17:49:31.759 VERB  [1166668] [rtc::IceTransport::send@596] Send size=385
2020-11-29 17:49:31.806 VERB  [1166667] [rtc::IceTransport::RecvCallback@699] Incoming size=321
2020-11-29 17:49:31.806 VERB  [1166667] [rtc::DtlsTransport::incoming@142] Incoming size=321
2020-11-29 17:49:31.806 VERB  [1166668] [rtc::SctpTransport::incoming@318] Incoming size=292
2020-11-29 17:49:31.806 VERB  [1166667] [rtc::IceTransport::RecvCallback@699] Incoming size=337
2020-11-29 17:49:31.806 VERB  [1166667] [rtc::DtlsTransport::incoming@142] Incoming size=337
2020-11-29 17:49:31.807 VERB  [1166668] [rtc::SctpTransport::handleSend@511] Handle send, free=1048576
2020-11-29 17:49:31.807 VERB  [1166668] [rtc::SctpTransport::handleWrite@518] Handle write, len=260
2020-11-29 17:49:31.807 VERB  [1166668] [rtc::DtlsTransport::send@123] Send size=260
2020-11-29 17:49:31.807 VERB  [1166668] [rtc::IceTransport::send@596] Send size=289
2020-11-29 17:49:31.807 VERB  [1166668] [rtc::SctpTransport::incoming@318] Incoming size=308
2020-11-29 17:49:31.807 VERB  [1166668] [rtc::SctpTransport::handleRecv@478] Handle recv, len=23
2020-11-29 17:49:31.807 VERB  [1166668] [rtc::SctpTransport::processNotification@601] Processing notification, type=1
2020-11-29 17:49:31.807 INFO  [1166668] [rtc::SctpTransport::processNotification@607] SCTP connected
2020-11-29 17:49:31.807 INFO  [1166668] [rtc::PeerConnection::changeState@873] Changed state to connected
State: connected
2020-11-29 17:49:31.808 VERB  [1166668] [rtc::SctpTransport::handleRecv@478] Handle recv, len=21
2020-11-29 17:49:31.808 VERB  [1166668] [rtc::SctpTransport::processData@535] Process data, size=21
2020-11-29 17:49:31.808 VERB  [1166668] [rtc::SctpTransport::send@282] Send size=1
2020-11-29 17:49:31.808 VERB  [1166668] [rtc::SctpTransport::trySendMessage@358] SCTP try send size=1
2020-11-29 17:49:31.808 VERB  [1166668] [rtc::SctpTransport::handleWrite@518] Handle write, len=36
2020-11-29 17:49:31.808 VERB  [1166668] [rtc::DtlsTransport::send@123] Send size=36
2020-11-29 17:49:31.808 VERB  [1166668] [rtc::IceTransport::send@596] Send size=65
2020-11-29 17:49:31.808 VERB  [1166668] [rtc::SctpTransport::trySendMessage@413] SCTP sent size=1
DataChannel from abc+tgjio label abc+tgjio
2020-11-29 17:49:31.808 VERB  [1166659] [rtc::SctpTransport::send@282] Send size=5
2020-11-29 17:49:31.808 VERB  [1166659] [rtc::SctpTransport::trySendMessage@358] SCTP try send size=5
2020-11-29 17:49:31.808 VERB  [1166659] [rtc::SctpTransport::handleWrite@518] Handle write, len=36
2020-11-29 17:49:31.809 VERB  [1166659] [rtc::DtlsTransport::send@123] Send size=36
2020-11-29 17:49:31.809 VERB  [1166659] [rtc::IceTransport::send@596] Send size=65
2020-11-29 17:49:31.809 VERB  [1166659] [rtc::SctpTransport::trySendMessage@413] SCTP sent size=5
2020-11-29 17:49:31.809 VERB  [1166668] [rtc::SctpTransport::handleWrite@518] Handle write, len=28
2020-11-29 17:49:31.809 VERB  [1166668] [rtc::DtlsTransport::send@123] Send size=28
2020-11-29 17:49:31.809 VERB  [1166668] [rtc::IceTransport::send@596] Send size=57
2020-11-29 17:49:31.854 VERB  [1166667] [rtc::IceTransport::RecvCallback@699] Incoming size=45
2020-11-29 17:49:31.854 VERB  [1166667] [rtc::DtlsTransport::incoming@142] Incoming size=45
2020-11-29 17:49:31.854 VERB  [1166668] [rtc::SctpTransport::incoming@318] Incoming size=16
2020-11-29 17:49:31.855 VERB  [1166667] [rtc::IceTransport::RecvCallback@699] Incoming size=57
2020-11-29 17:49:31.855 VERB  [1166667] [rtc::DtlsTransport::incoming@142] Incoming size=57
2020-11-29 17:49:31.855 VERB  [1166668] [rtc::SctpTransport::incoming@318] Incoming size=28
2020-11-29 17:49:31.856 VERB  [1166668] [rtc::SctpTransport::handleSend@511] Handle send, free=1048571
2020-11-29 17:49:31.909 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53451 (100 octets) :
2020-11-29 17:49:31.910 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53451', socket=22, len=92, cand=0x7efe3c017540 (c-id:1), use-cand=1.
2020-11-29 17:49:31.910 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Found a matching pair 0x7efe3c03e0e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 17:49:31.910 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : nothing to do for pair 0x7efe3c03e0e0.
2020-11-29 17:49:31.910 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:31.910 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:31.910 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 17:49:31.910 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : marking pair 0x7efe3c03e0e0 (2:1802928054) as nominated
2020-11-29 17:49:31.910 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:31.910 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:31.910 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 17:49:31.910 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 17:49:32.057 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : discovery tick #51 with list 0x7efe3c010cc0 (1)
2020-11-29 17:49:32.069 VERB  [1166667] [rtc::IceTransport::RecvCallback@699] Incoming size=57
2020-11-29 17:49:32.069 VERB  [1166667] [rtc::DtlsTransport::incoming@142] Incoming size=57
2020-11-29 17:49:32.069 VERB  [1166668] [rtc::SctpTransport::incoming@318] Incoming size=28
2020-11-29 17:49:32.069 VERB  [1166668] [rtc::SctpTransport::handleSend@511] Handle send, free=1048576
2020-11-29 17:49:32.069 VERB  [1166668] [rtc::SctpTransport::handleRecv@478] Handle recv, len=12
2020-11-29 17:49:32.069 VERB  [1166668] [rtc::SctpTransport::processNotification@601] Processing notification, type=10
2020-11-29 17:49:32.069 VERB  [1166668] [rtc::SctpTransport::processNotification@623] SCTP dry event
2020-11-29 17:49:32.107 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : stream 1: timer tick #51: 0 frozen, 0 in-progress, 0 waiting, 2 succeeded, 0 discovered, 1 nominated, 1 waiting-for-nom, 2 valid.
2020-11-29 17:49:32.308 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : checking for failed components now.
2020-11-29 17:49:32.308 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:32.308 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:32.308 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 17:49:32.308 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : priv_conn_check_tick_agent_locked: stopping conncheck timer
2020-11-29 17:49:32.308 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : changing conncheck state to COMPLETED.
2020-11-29 17:49:32.809 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : bind discovery timed out, aborting discovery item.
2020-11-29 17:49:32.809 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Candidate gathering FINISHED, stopping discovery timer.
2020-11-29 17:49:32.809 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: gathered UDP local candidate : [fe80::f03c:92ff:fe64:cdfd]:15198 for s1/c1. U/P '(null)'/'(null)'
2020-11-29 17:49:32.809 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: gathered UDP local candidate : [HIDDEN_FOR_PRIVACY]:7691 for s1/c1. U/P '(null)'/'(null)'
2020-11-29 17:49:32.809 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: gathered UDP local candidate : [HIDDEN_FOR_PRIVACY]:29349 for s1/c1. U/P '(null)'/'(null)'
2020-11-29 17:49:32.809 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : creating a new pair
2020-11-29 17:49:32.809 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e240 state FROZEN (priv_add_new_check_pair)
2020-11-29 17:49:32.809 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : new pair 0x7efe3c03e240 : [HIDDEN_FOR_PRIVACY]:29349 --> [HIDDEN_FOR_PRIVACY]:53453
2020-11-29 17:49:32.810 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : added a new pair 0x7efe3c03e240 with foundation '3:2999745851' to stream 1 component 1.
2020-11-29 17:49:32.810 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : stream 1 component 1 STATE-CHANGE ready -> connected.
2020-11-29 17:49:32.810 INFO  [1166667] [rtc::PeerConnection::changeGatheringState@888] Changed gathering state to complete
Gathering State: complete
2020-11-29 17:49:32.841 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53451 (100 octets) :
2020-11-29 17:49:32.841 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53451', socket=22, len=92, cand=0x7efe3c017540 (c-id:1), use-cand=1.
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Found a matching pair 0x7efe3c03e0e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : nothing to do for pair 0x7efe3c03e0e0.
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : pair 0x7efe3c03e240 removed.
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : stream 1 component 1 STATE-CHANGE connected -> ready.
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : marking pair 0x7efe3c03e0e0 (2:1802928054) as nominated
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 17:49:32.842 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53451 (100 octets) :
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53451', socket=22, len=92, cand=0x7efe3c017540 (c-id:1), use-cand=1.
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Found a matching pair 0x7efe3c03e0e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : nothing to do for pair 0x7efe3c03e0e0.
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : marking pair 0x7efe3c03e0e0 (2:1802928054) as nominated
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 17:49:35.342 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53451 (100 octets) :
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53451', socket=22, len=92, cand=0x7efe3c017540 (c-id:1), use-cand=1.
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : Found a matching pair 0x7efe3c03e0e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : nothing to do for pair 0x7efe3c03e0e0.
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : marking pair 0x7efe3c03e0e0 (2:1802928054) as nominated
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Finding highest priority for component 1
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: Agent 0x7efe3c019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 17:49:37.889 VERB  [1166667] [rtc::IceTransport::LogCallback@734] nice: agent_recv_message_unlocked: Valid STUN packet received.

paullouisageneau commented 3 years ago

It seems your libdatachannel version is a bit old, could you please try with the last version and repost the log if it still doesn't work?

jeffRTC commented 3 years ago

Updated and doesn't work.

Here is log again,

2020-11-29 18:48:07.859 DEBUG [1173902] [rtc::InitLogger@40] Logger initialized
Server listening on port 8081
2020-11-29 18:48:13.061 DEBUG [1173903] [rtc::{anonymous}::doInit@46] Global initialization
2020-11-29 18:48:13.064 VERB  [1173903] [rtc::PeerConnection::PeerConnection@62] Creating PeerConnection
2020-11-29 18:48:13.064 VERB  [1173903] [rtc::PeerConnection::setRemoteDescription@203] Setting remote description: v=0
o=- 941261822490256288 0 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic:WMS *
a=setup:actpass
a=ice-ufrag:I/Af
a=ice-pwd:MewgfUuJ2TGybttxXraUPd7D
a=ice-options:trickle
a=fingerprint:sha-256 C0:A6:47:49:08:E4:F0:F7:93:3E:D5:4C:03:6F:CE:09:0F:18:B6:E4:53:74:BB:74:D0:18:EE:67:14:E4:57:23
m=application 9 UDP/DTLS/SCTP webrtc-datachannel
c=IN IP4 0.0.0.0
a=bundle-only
a=mid:0
a=sendrecv
a=ice-options:trickle
a=sctp-port:5000
a=max-message-size:262144

2020-11-29 18:48:13.064 VERB  [1173903] [rtc::PeerConnection::validateRemoteDescription@930] Remote description looks valid
2020-11-29 18:48:13.064 VERB  [1173903] [rtc::PeerConnection::initIceTransport@399] Starting ICE transport
2020-11-29 18:48:13.065 DEBUG [1173903] [rtc::IceTransport::IceTransport@339] Initializing ICE transport (libnice)
2020-11-29 18:48:13.065 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Created NiceStream (1 created, 0 destroyed)
2020-11-29 18:48:13.065 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Created NiceComponent (1 created, 0 destroyed)
2020-11-29 18:48:13.065 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : allocating stream id 1 (0x7fe78801b620)
2020-11-29 18:48:13.065 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Property set, role is already "controlling".
2020-11-29 18:48:13.077 DEBUG [1173903] [rtc::IceTransport::IceTransport@427] Using STUN server "stun.services.mozilla.com:3478"
2020-11-29 18:48:13.077 INFO  [1173903] [rtc::PeerConnection::changeSignalingState@1210] Changed signaling state to have-remote-offer
2020-11-29 18:48:13.077 VERB  [1173903] [rtc::PeerConnection::setLocalDescription@119] Setting local description, type=answer
2020-11-29 18:48:13.077 VERB  [1173903] [rtc::PeerConnection::initIceTransport@399] Starting ICE transport
2020-11-29 18:48:13.077 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Property set, changing role to "controlled".
2020-11-29 18:48:13.077 DEBUG [1173903] [rtc::PeerConnection::processLocalDescription@959] Reciprocating application in local description, mid="0"
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::PeerConnection::processLocalDescription@1069] Issuing local description: v=0
o=rtc 1977994949 0 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=msid-semantic:WMS *
a=setup:active
a=ice-ufrag:+Q4s
a=ice-pwd:P5ffIs9N6eV/D6mYh45dOp
a=ice-options:trickle
a=fingerprint:sha-256 D6:42:17:9E:C7:D9:FC:D5:83:04:E0:66:6C:33:1C:90:B1:6C:EC:72:EC:D2:1D:04:2C:AB:3E:9C:F6:E0:86:4C
m=application 9 UDP/DTLS/SCTP webrtc-datachannel
c=IN IP4 0.0.0.0
a=bundle-only
a=mid:0
a=sendrecv
a=ice-options:trickle
a=sctp-port:5000
a=max-message-size:262144

2020-11-29 18:48:13.290 INFO  [1173903] [rtc::PeerConnection::changeSignalingState@1210] Changed signaling state to stable
2020-11-29 18:48:13.290 INFO  [1173903] [rtc::PeerConnection::changeGatheringState@1199] Changed gathering state to in-progress
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : In ICE-FULL mode, starting candidate gathering.
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : UPnP property Disabled
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Failed to convert address to string for interface ‘lo’.
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Failed to convert address to string for interface ‘eth0’.
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Interface:  lo
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: IP Address: 127.0.0.1
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Ignoring loopback interface
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Interface:  eth0
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: IP Address: HIDDEN_FOR_PRIVACY
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Interface:  lo
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: IP Address: ::1
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Ignoring loopback interface
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Interface:  eth0
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: IP Address: HIDDEN_FOR_PRIVACY
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Interface:  eth0
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: IP Address: HIDDEN_FOR_PRIVACY%eth0
2020-11-29 18:48:13.290 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Trying to create host candidate on port 27864
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Component 0x7fe78801bd40: Attach source (stream 1).
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Attaching source 0x7fe788025070 (socket 0x7fe788014ae0, FD 19) to context 0x7fe788011610
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Trying to create host candidate on port 59682
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Component 0x7fe78801bd40: Attach source (stream 1).
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Attaching source 0x7fe7880251d0 (socket 0x7fe788025880, FD 20) to context 0x7fe788011610
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Trying to create host candidate on port 47816
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Could not set IPV6 socket ToS: Protocol not available
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Component 0x7fe78801bd40: Attach source (stream 1).
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Attaching source 0x7fe788027a10 (socket 0x7fe7880258f0, FD 21) to context 0x7fe788011610
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Adding new srv-rflx candidate discovery 0x7fe788027b70
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : discovery tick #1 with list 0x7fe788010ec0 (1)
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : discovery - scheduling cand type 1 addr 52.87.201.4.
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : stream 1 component 1 STATE-CHANGE disconnected -> gathering.
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::Candidate::parse@98] Parsing candidate: 1 1 UDP 2013266431 HIDDEN_FOR_PRIVACY 27864 typ host
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::Candidate::resolve@142] Resolving candidate (mode=simple): HIDDEN_FOR_PRIVACY 27864
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::Candidate::resolve@174] Resolved candidate: HIDDEN_FOR_PRIVACY 27864
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::PeerConnection::processLocalCandidate@1086] Issuing local candidate: a=candidate:1 1 UDP 2013266431 HIDDEN_FOR_PRIVACY 27864 typ host
Gathering State: in-progress
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::Candidate::parse@98] Parsing candidate: 2 1 UDP 2013266430 HIDDEN_FOR_PRIVACY 59682 typ host
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::Candidate::resolve@142] Resolving candidate (mode=simple): HIDDEN_FOR_PRIVACY 59682
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::Candidate::resolve@174] Resolved candidate: HIDDEN_FOR_PRIVACY 59682
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::PeerConnection::processLocalCandidate@1086] Issuing local candidate: a=candidate:2 1 UDP 2013266430 HIDDEN_FOR_PRIVACY 59682 typ host
Adding Candidate
2020-11-29 18:48:13.291 VERB  [1173903] [rtc::Candidate::parse@98] Parsing candidate: 3 1 UDP 2013266429 HIDDEN_FOR_PRIVACY 47816 typ host
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::Candidate::resolve@142] Resolving candidate (mode=simple): HIDDEN_FOR_PRIVACY 47816
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::Candidate::resolve@174] Resolved candidate: HIDDEN_FOR_PRIVACY 47816
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::PeerConnection::processLocalCandidate@1086] Issuing local candidate: a=candidate:3 1 UDP 2013266429 HIDDEN_FOR_PRIVACY 47816 typ host
Adding Candidate
Adding Candidate
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::Candidate::parse@98] Parsing candidate: 1802928054 1 udp 2122262783 HIDDEN_FOR_PRIVACY 53874 typ host generation 0 ufrag I/Af network-id 4
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::PeerConnection::addRemoteCandidate@303] Adding remote candidate: a=candidate:1802928054 1 udp 2122262783 HIDDEN_FOR_PRIVACY 53874 typ host generation 0 ufrag I/Af network-id 4
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::Candidate::resolve@142] Resolving candidate (mode=simple): HIDDEN_FOR_PRIVACY 53874
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::Candidate::resolve@174] Resolved candidate: HIDDEN_FOR_PRIVACY 53874
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: set_remote_candidates 1 1
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Adding UDP remote candidate with addr [HIDDEN_FOR_PRIVACY]:53874 for s1/c1. U/P '(null)'/'(null)' prio: 2122262783
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : creating a new pair
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e830 state FROZEN (priv_add_new_check_pair)
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : new pair 0x7fe78803e830 : [HIDDEN_FOR_PRIVACY]:27864 --> [HIDDEN_FOR_PRIVACY]:53874
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : added a new pair 0x7fe78803e830 with foundation '1:1802928054' to stream 1 component 1.
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : stream 1 component 1 STATE-CHANGE gathering -> connecting.
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : creating a new pair
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e8e0 state FROZEN (priv_add_new_check_pair)
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : new pair 0x7fe78803e8e0 : [HIDDEN_FOR_PRIVACY]:59682 --> [HIDDEN_FOR_PRIVACY]:53874
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : added a new pair 0x7fe78803e8e0 with foundation '2:1802928054' to stream 1 component 1.
2020-11-29 18:48:13.292 INFO  [1173903] [rtc::PeerConnection::changeState@1182] Changed state to connecting
State: connecting
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::Candidate::parse@98] Parsing candidate: 4201576948 1 udp 2122194687 HIDDEN_FOR_PRIVACY 53875 typ host generation 0 ufrag I/Af network-id 1
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::PeerConnection::addRemoteCandidate@303] Adding remote candidate: a=candidate:4201576948 1 udp 2122194687 HIDDEN_FOR_PRIVACY 53875 typ host generation 0 ufrag I/Af network-id 1
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::Candidate::resolve@142] Resolving candidate (mode=simple): HIDDEN_FOR_PRIVACY 53875
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::Candidate::resolve@174] Resolved candidate: HIDDEN_FOR_PRIVACY 53875
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: set_remote_candidates 1 1
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Adding UDP remote candidate with addr [HIDDEN_FOR_PRIVACY]:53875 for s1/c1. U/P '(null)'/'(null)' prio: 2122194687
2020-11-29 18:48:13.292 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : creating a new pair
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e990 state FROZEN (priv_add_new_check_pair)
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : new pair 0x7fe78803e990 : [HIDDEN_FOR_PRIVACY]:47816 --> [HIDDEN_FOR_PRIVACY]:53875
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : added a new pair 0x7fe78803e990 with foundation '3:4201576948' to stream 1 component 1.
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::parse@98] Parsing candidate: 2999745851 1 udp 2122129151 HIDDEN_FOR_PRIVACY 53876 typ host generation 0 ufrag I/Af network-id 2
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::PeerConnection::addRemoteCandidate@303] Adding remote candidate: a=candidate:2999745851 1 udp 2122129151 HIDDEN_FOR_PRIVACY 53876 typ host generation 0 ufrag I/Af network-id 2
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::resolve@142] Resolving candidate (mode=simple): HIDDEN_FOR_PRIVACY 53876
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::resolve@174] Resolved candidate: HIDDEN_FOR_PRIVACY 53876
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: set_remote_candidates 1 1
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Adding UDP remote candidate with addr [HIDDEN_FOR_PRIVACY]:53876 for s1/c1. U/P '(null)'/'(null)' prio: 2122129151
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : creating a new pair
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803ea40 state FROZEN (priv_add_new_check_pair)
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : new pair 0x7fe78803ea40 : [HIDDEN_FOR_PRIVACY]:47816 --> [HIDDEN_FOR_PRIVACY]:53876
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : added a new pair 0x7fe78803ea40 with foundation '3:2999745851' to stream 1 component 1.
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::parse@98] Parsing candidate: 917165150 1 udp 2122063615 HIDDEN_FOR_PRIVACY 53877 typ host generation 0 ufrag I/Af network-id 3
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::PeerConnection::addRemoteCandidate@303] Adding remote candidate: a=candidate:917165150 1 udp 2122063615 HIDDEN_FOR_PRIVACY 53877 typ host generation 0 ufrag I/Af network-id 3
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::resolve@142] Resolving candidate (mode=simple): HIDDEN_FOR_PRIVACY 53877
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::resolve@174] Resolved candidate: HIDDEN_FOR_PRIVACY 53877
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: set_remote_candidates 1 1
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Adding UDP remote candidate with addr [HIDDEN_FOR_PRIVACY]:53877 for s1/c1. U/P '(null)'/'(null)' prio: 2122063615
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : creating a new pair
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803eaf0 state FROZEN (priv_add_new_check_pair)
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : new pair 0x7fe78803eaf0 : [HIDDEN_FOR_PRIVACY]:47816 --> [HIDDEN_FOR_PRIVACY]:53877
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : added a new pair 0x7fe78803eaf0 with foundation '3:917165150' to stream 1 component 1.
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::parse@98] Parsing candidate: 636846918 1 tcp 1518283007 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag I/Af network-id 4
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::PeerConnection::addRemoteCandidate@303] Adding remote candidate: a=candidate:636846918 1 tcp 1518283007 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag I/Af network-id 4
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::resolve@142] Resolving candidate (mode=simple): HIDDEN_FOR_PRIVACY 9
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::resolve@174] Resolved candidate: HIDDEN_FOR_PRIVACY 9
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: set_remote_candidates 1 1
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::parse@98] Parsing candidate: 3035432196 1 tcp 1518214911 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag I/Af network-id 1
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::PeerConnection::addRemoteCandidate@303] Adding remote candidate: a=candidate:3035432196 1 tcp 1518214911 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag I/Af network-id 1
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::resolve@142] Resolving candidate (mode=simple): HIDDEN_FOR_PRIVACY 9
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::resolve@174] Resolved candidate: HIDDEN_FOR_PRIVACY 9
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: set_remote_candidates 1 1
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::parse@98] Parsing candidate: 4233069003 1 tcp 1518149375 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag I/Af network-id 2
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::PeerConnection::addRemoteCandidate@303] Adding remote candidate: a=candidate:4233069003 1 tcp 1518149375 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag I/Af network-id 2
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::resolve@142] Resolving candidate (mode=simple): HIDDEN_FOR_PRIVACY 9
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::Candidate::resolve@174] Resolved candidate: HIDDEN_FOR_PRIVACY 9
2020-11-29 18:48:13.293 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: set_remote_candidates 1 1
2020-11-29 18:48:13.294 VERB  [1173903] [rtc::Candidate::parse@98] Parsing candidate: 2015963310 1 tcp 1518083839 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag I/Af network-id 3
2020-11-29 18:48:13.294 VERB  [1173903] [rtc::PeerConnection::addRemoteCandidate@303] Adding remote candidate: a=candidate:2015963310 1 tcp 1518083839 HIDDEN_FOR_PRIVACY 9 typ host tcptype active generation 0 ufrag I/Af network-id 3
2020-11-29 18:48:13.294 VERB  [1173903] [rtc::Candidate::resolve@142] Resolving candidate (mode=simple): HIDDEN_FOR_PRIVACY 9
2020-11-29 18:48:13.294 VERB  [1173903] [rtc::Candidate::resolve@174] Resolved candidate: HIDDEN_FOR_PRIVACY 9
2020-11-29 18:48:13.294 VERB  [1173903] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: set_remote_candidates 1 1
2020-11-29 18:48:13.317 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Pair 0x7fe78803e830 with s/c-id 1/1 (1:1802928054) unfrozen.
2020-11-29 18:48:13.317 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e830 state WAITING (priv_conn_check_unfreeze_next)
2020-11-29 18:48:13.317 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Pair 0x7fe78803e8e0 with s/c-id 1/1 (2:1802928054) unfrozen.
2020-11-29 18:48:13.317 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e8e0 state WAITING (priv_conn_check_unfreeze_next)
2020-11-29 18:48:13.317 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Pair 0x7fe78803e990 with s/c-id 1/1 (3:4201576948) unfrozen.
2020-11-29 18:48:13.317 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e990 state WAITING (priv_conn_check_unfreeze_next)
2020-11-29 18:48:13.317 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Pair 0x7fe78803ea40 with s/c-id 1/1 (3:2999745851) unfrozen.
2020-11-29 18:48:13.317 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803ea40 state WAITING (priv_conn_check_unfreeze_next)
2020-11-29 18:48:13.317 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Pair 0x7fe78803eaf0 with s/c-id 1/1 (3:917165150) unfrozen.
2020-11-29 18:48:13.317 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803eaf0 state WAITING (priv_conn_check_unfreeze_next)
2020-11-29 18:48:13.318 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e830 state IN_PROGRESS (priv_conn_check_initiate)
2020-11-29 18:48:13.318 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC REQ [HIDDEN_FOR_PRIVACY]:27864 --> [HIDDEN_FOR_PRIVACY]:53874, socket=19, pair=0x7fe78803e830 (c-id:1), tie=12465938710344014198, username='I/Af:+Q4s' (9), password='MewgfUuJ2TGybttxXraUPd7D' (24), prio=1845494271, controlled.
2020-11-29 18:48:13.318 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn_check_send: set cand_use=0 (aggressive nomination).
2020-11-29 18:48:13.318 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: conncheck created 88 - 0x7fe778003640
2020-11-29 18:48:13.318 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : timer set to 125ms, waiting+in_progress=5, nb_active=1
2020-11-29 18:48:13.318 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : stream 1: timer tick #1: 0 frozen, 1 in-progress, 4 waiting, 0 succeeded, 0 discovered, 0 nominated, 0 waiting-for-nom, 0 valid.
2020-11-29 18:48:13.343 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e8e0 state IN_PROGRESS (priv_conn_check_initiate)
2020-11-29 18:48:13.343 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC REQ [HIDDEN_FOR_PRIVACY]:59682 --> [HIDDEN_FOR_PRIVACY]:53874, socket=20, pair=0x7fe78803e8e0 (c-id:1), tie=12465938710344014198, username='I/Af:+Q4s' (9), password='MewgfUuJ2TGybttxXraUPd7D' (24), prio=1845494270, controlled.
2020-11-29 18:48:13.343 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn_check_send: set cand_use=0 (aggressive nomination).
2020-11-29 18:48:13.343 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: conncheck created 88 - 0x7fe778005430
2020-11-29 18:48:13.343 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : timer set to 125ms, waiting+in_progress=5, nb_active=1
2020-11-29 18:48:13.368 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e990 state IN_PROGRESS (priv_conn_check_initiate)
2020-11-29 18:48:13.368 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC REQ [HIDDEN_FOR_PRIVACY]:47816 --> [HIDDEN_FOR_PRIVACY]:53875, socket=21, pair=0x7fe78803e990 (c-id:1), tie=12465938710344014198, username='I/Af:+Q4s' (9), password='MewgfUuJ2TGybttxXraUPd7D' (24), prio=1845494269, controlled.
2020-11-29 18:48:13.368 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn_check_send: set cand_use=0 (aggressive nomination).
2020-11-29 18:48:13.369 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: conncheck created 88 - 0x7fe778005f50
2020-11-29 18:48:13.369 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : timer set to 125ms, waiting+in_progress=5, nb_active=1
2020-11-29 18:48:13.379 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53874 (100 octets) :
2020-11-29 18:48:13.379 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 :  1:1 Adding valid source candidate: HIDDEN_FOR_PRIVACY:53874 trans: 0
2020-11-29 18:48:13.379 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53874', socket=20, len=92, cand=0x7fe788017540 (c-id:1), use-cand=1.
2020-11-29 18:48:13.379 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Found a matching pair 0x7fe78803e8e0 (2:1802928054) (IN_PROGRESS) ...
2020-11-29 18:48:13.379 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e8e0 added for a triggered check.
2020-11-29 18:48:13.379 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e8e0 state IN_PROGRESS (priv_add_pair_to_triggered_check_queue)
2020-11-29 18:48:13.379 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e8e0 (2:1802928054) is in-progress, will be nominated on response receipt.
2020-11-29 18:48:13.379 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 18:48:13.391 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53874 (76 octets) :
2020-11-29 18:48:13.391 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : stun_bind_process/conncheck for 0x7fe78803e8e0: controlled,res=success,stun#=0.
2020-11-29 18:48:13.391 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e8e0 MATCHED.
2020-11-29 18:48:13.391 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e8e0 state SUCCEEDED (priv_process_response_check_for_reflexive)
2020-11-29 18:48:13.391 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Updating nominated flag (UDP): ok_pair=0x7fe78803e8e0 (0/1) p=0x7fe78803e8e0 (0/1) (ucnc/mnora)
2020-11-29 18:48:13.391 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : marking pair 0x7fe78803e8e0 (2:1802928054) as nominated (aggressive nomination, controlled, mark_on_response=1).
2020-11-29 18:48:13.391 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : changing SELECTED PAIR for component 1: 2:1802928054 (prio:8646913479229198847).
2020-11-29 18:48:13.391 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: setting SELECTED PAIR for component 1: 2:1802928054 (prio:8646913479229198847).
2020-11-29 18:48:13.391 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : stun_bind_keepalive for pair 0x7fe78801bdb0 res 28.
2020-11-29 18:48:13.391 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : resending STUN on 3 to keep the candidate alive.
2020-11-29 18:48:13.391 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Local selected pair: 1:1 2 UDP HIDDEN_FOR_PRIVACY:59682 HOST
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Remote selected pair: 1:1 1802928054 UDP HIDDEN_FOR_PRIVACY:53874 HOST
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : stream 1 component 1 STATE-CHANGE connecting -> connected.
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e830 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e990 will not be retransmitted.
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803ea40 removed.
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803eaf0 removed.
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::PeerConnection::initDtlsTransport@462] Starting DTLS transport
2020-11-29 18:48:13.392 DEBUG [1173929] [rtc::DtlsTransport::DtlsTransport@58] Initializing DTLS transport (GnuTLS)
2020-11-29 18:48:13.392 VERB  [1173929] [rtc::Transport::registerIncoming@57] Registering incoming callback
2020-11-29 18:48:13.392 DEBUG [1173929] [rtc::DtlsTransport::start@105] Starting DTLS recv thread
2020-11-29 18:48:13.393 VERB  [1173934] [rtc::IceTransport::send@621] Send size=215
2020-11-29 18:48:13.427 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53874 (100 octets) :
2020-11-29 18:48:13.427 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53874', socket=20, len=92, cand=0x7fe788017540 (c-id:1), use-cand=1.
2020-11-29 18:48:13.427 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Found a matching pair 0x7fe78803e8e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 18:48:13.427 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : nothing to do for pair 0x7fe78803e8e0.
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e830 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e990 will not be retransmitted.
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : marking pair 0x7fe78803e8e0 (2:1802928054) as nominated
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e830 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e990 will not be retransmitted.
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 18:48:13.428 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 18:48:13.440 VERB  [1173929] [rtc::IceTransport::RecvCallback@731] Incoming size=639
2020-11-29 18:48:13.441 VERB  [1173929] [rtc::DtlsTransport::incoming@143] Incoming size=639
2020-11-29 18:48:13.444 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 :STUN transaction retransmitted on pair 0x7fe78803e830 (timer=2/3 2/250ms).
2020-11-29 18:48:13.476 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53874 (100 octets) :
2020-11-29 18:48:13.476 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53874', socket=20, len=92, cand=0x7fe788017540 (c-id:1), use-cand=1.
2020-11-29 18:48:13.476 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Found a matching pair 0x7fe78803e8e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 18:48:13.476 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : nothing to do for pair 0x7fe78803e8e0.
2020-11-29 18:48:13.476 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:13.477 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:13.477 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e830 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 18:48:13.477 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e990 will not be retransmitted.
2020-11-29 18:48:13.477 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 18:48:13.477 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : marking pair 0x7fe78803e8e0 (2:1802928054) as nominated
2020-11-29 18:48:13.477 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:13.477 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:13.477 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e830 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 18:48:13.477 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e990 will not be retransmitted.
2020-11-29 18:48:13.477 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 18:48:13.477 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 18:48:13.520 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Retransmissions failed, giving up on pair 0x7fe78803e990
2020-11-29 18:48:13.520 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Failed pair is [HIDDEN_FOR_PRIVACY]:47816 --> [HIDDEN_FOR_PRIVACY]:53875
2020-11-29 18:48:13.520 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e990 state FAILED (candidate_check_pair_fail)
2020-11-29 18:48:13.520 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:13.520 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:13.520 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e830 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 18:48:13.520 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 1 valid, c-id 1.
2020-11-29 18:48:13.538 VERB  [1173929] [rtc::IceTransport::RecvCallback@731] Incoming size=639
2020-11-29 18:48:13.538 VERB  [1173929] [rtc::DtlsTransport::incoming@143] Incoming size=639
2020-11-29 18:48:13.608 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53877 (96 octets) :
2020-11-29 18:48:13.608 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 :  1:1 Adding valid source candidate: HIDDEN_FOR_PRIVACY:53877 trans: 0
2020-11-29 18:48:13.608 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53877', socket=21, len=80, cand=0x7fe78803f800 (c-id:1), use-cand=0.
2020-11-29 18:48:13.608 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Adding a triggered check to conn.check list (local=0x7fe788017390).
2020-11-29 18:48:13.608 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : creating a new pair
2020-11-29 18:48:13.608 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803eaf0 state WAITING (priv_add_new_check_pair)
2020-11-29 18:48:13.608 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : new pair 0x7fe78803eaf0 : [HIDDEN_FOR_PRIVACY]:47816 --> [HIDDEN_FOR_PRIVACY]:53877
2020-11-29 18:48:13.608 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : added a new pair 0x7fe78803eaf0 with foundation '3:917165150' to stream 1 component 1.
2020-11-29 18:48:13.608 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803eaf0 state IN_PROGRESS (priv_add_pair_to_triggered_check_queue)
2020-11-29 18:48:13.608 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 18:48:13.621 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC REQ [HIDDEN_FOR_PRIVACY]:47816 --> [HIDDEN_FOR_PRIVACY]:53877, socket=21, pair=0x7fe78803eaf0 (c-id:1), tie=12465938710344014198, username='I/Af:+Q4s' (9), password='MewgfUuJ2TGybttxXraUPd7D' (24), prio=1845494268, controlled.
2020-11-29 18:48:13.622 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn_check_send: set cand_use=0 (aggressive nomination).
2020-11-29 18:48:13.622 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: conncheck created 88 - 0x7fe77800f270
2020-11-29 18:48:13.622 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : timer set to 100ms, waiting+in_progress=2, nb_active=1
2020-11-29 18:48:13.648 VERB  [1173934] [rtc::IceTransport::send@621] Send size=983
2020-11-29 18:48:13.648 VERB  [1173934] [rtc::IceTransport::send@621] Send size=91
2020-11-29 18:48:13.648 VERB  [1173934] [rtc::IceTransport::send@621] Send size=413
2020-11-29 18:48:13.648 VERB  [1173934] [rtc::IceTransport::send@621] Send size=14
2020-11-29 18:48:13.648 VERB  [1173934] [rtc::IceTransport::send@621] Send size=53
2020-11-29 18:48:13.653 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53877 (64 octets) :
2020-11-29 18:48:13.654 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : stun_bind_process/conncheck for 0x7fe78803eaf0: controlled,res=success,stun#=0.
2020-11-29 18:48:13.654 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803eaf0 MATCHED.
2020-11-29 18:48:13.654 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803eaf0 state SUCCEEDED (priv_process_response_check_for_reflexive)
2020-11-29 18:48:13.654 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Updating nominated flag (UDP): ok_pair=0x7fe78803eaf0 (0/0) p=0x7fe78803eaf0 (0/0) (ucnc/mnora)
2020-11-29 18:48:13.654 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:13.654 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:13.654 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e830 kept IN_PROGRESS because priority 8646913483524166143 is higher than currently nominated pair 8646913479229198847
2020-11-29 18:48:13.654 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 18:48:13.654 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 18:48:13.697 VERB  [1173929] [rtc::IceTransport::RecvCallback@731] Incoming size=1181
2020-11-29 18:48:13.697 VERB  [1173929] [rtc::DtlsTransport::incoming@143] Incoming size=1181
2020-11-29 18:48:13.697 VERB  [1173929] [rtc::IceTransport::RecvCallback@731] Incoming size=53
2020-11-29 18:48:13.697 VERB  [1173929] [rtc::DtlsTransport::incoming@143] Incoming size=53
2020-11-29 18:48:13.698 VERB  [1173929] [rtc::IceTransport::RecvCallback@731] Incoming size=73
2020-11-29 18:48:13.698 VERB  [1173929] [rtc::DtlsTransport::incoming@143] Incoming size=73
2020-11-29 18:48:13.698 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 :STUN transaction retransmitted on pair 0x7fe78803e830 (timer=3/3 5/125ms).
2020-11-29 18:48:13.824 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Retransmissions failed, giving up on pair 0x7fe78803e830
2020-11-29 18:48:13.824 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Failed pair is [HIDDEN_FOR_PRIVACY]:27864 --> [HIDDEN_FOR_PRIVACY]:53874
2020-11-29 18:48:13.824 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803e830 state FAILED (candidate_check_pair_fail)
2020-11-29 18:48:13.824 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:13.824 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:13.824 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : stream 1 component 1 STATE-CHANGE connected -> ready.
2020-11-29 18:48:13.824 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 18:48:13.825 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : waiting 1000 msecs before checking for failed components.
2020-11-29 18:48:14.249 INFO  [1173934] [rtc::DtlsTransport::runRecvLoop@187] DTLS handshake finished
2020-11-29 18:48:14.249 VERB  [1173934] [rtc::PeerConnection::initSctpTransport@533] Starting SCTP transport
2020-11-29 18:48:14.250 DEBUG [1173934] [rtc::SctpTransport::SctpTransport@95] Initializing SCTP transport
2020-11-29 18:48:14.250 VERB  [1173934] [rtc::Transport::registerIncoming@57] Registering incoming callback
2020-11-29 18:48:14.250 DEBUG [1173934] [rtc::SctpTransport::connect@243] SCTP connecting
2020-11-29 18:48:14.255 VERB  [1173934] [rtc::SctpTransport::handleWrite@562] Handle write, len=100
2020-11-29 18:48:14.255 VERB  [1173934] [rtc::DtlsTransport::send@123] Send size=100
2020-11-29 18:48:14.255 VERB  [1173934] [rtc::IceTransport::send@621] Send size=129
2020-11-29 18:48:14.255 VERB  [1173934] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Could not set IPV6 socket ToS: Protocol not available
2020-11-29 18:48:14.255 VERB  [1173934] [rtc::SctpTransport::incoming@324] Incoming size=44
2020-11-29 18:48:14.255 VERB  [1173934] [rtc::SctpTransport::handleWrite@562] Handle write, len=356
2020-11-29 18:48:14.255 VERB  [1173934] [rtc::DtlsTransport::send@123] Send size=356
2020-11-29 18:48:14.256 VERB  [1173934] [rtc::IceTransport::send@621] Send size=385
2020-11-29 18:48:14.303 VERB  [1173929] [rtc::IceTransport::RecvCallback@731] Incoming size=321
2020-11-29 18:48:14.303 VERB  [1173929] [rtc::DtlsTransport::incoming@143] Incoming size=321
2020-11-29 18:48:14.303 VERB  [1173934] [rtc::SctpTransport::incoming@324] Incoming size=292
2020-11-29 18:48:14.303 VERB  [1173929] [rtc::IceTransport::RecvCallback@731] Incoming size=337
2020-11-29 18:48:14.303 VERB  [1173929] [rtc::DtlsTransport::incoming@143] Incoming size=337
2020-11-29 18:48:14.304 VERB  [1173934] [rtc::SctpTransport::handleWrite@562] Handle write, len=260
2020-11-29 18:48:14.304 VERB  [1173934] [rtc::DtlsTransport::send@123] Send size=260
2020-11-29 18:48:14.304 VERB  [1173934] [rtc::IceTransport::send@621] Send size=289
2020-11-29 18:48:14.304 VERB  [1173934] [rtc::SctpTransport::incoming@324] Incoming size=308
2020-11-29 18:48:14.304 VERB  [1173934] [rtc::SctpTransport::handleWrite@562] Handle write, len=32
2020-11-29 18:48:14.304 VERB  [1173934] [rtc::DtlsTransport::send@123] Send size=32
2020-11-29 18:48:14.305 VERB  [1173934] [rtc::IceTransport::send@621] Send size=61
2020-11-29 18:48:14.305 VERB  [1173934] [rtc::SctpTransport::handleUpcall@546] Handle upcall
2020-11-29 18:48:14.305 VERB  [1173924] [rtc::SctpTransport::doRecv@356] SCTP recv, len=23
2020-11-29 18:48:14.305 VERB  [1173924] [rtc::SctpTransport::processNotification@646] Processing notification, type=1
2020-11-29 18:48:14.305 INFO  [1173924] [rtc::SctpTransport::processNotification@652] SCTP connected
2020-11-29 18:48:14.305 INFO  [1173924] [rtc::PeerConnection::changeState@1182] Changed state to connected
State: connected
2020-11-29 18:48:14.305 VERB  [1173924] [rtc::SctpTransport::doRecv@356] SCTP recv, len=21
2020-11-29 18:48:14.305 VERB  [1173924] [rtc::SctpTransport::processData@580] Process data, size=21
2020-11-29 18:48:14.306 VERB  [1173924] [rtc::SctpTransport::send@288] Send size=1
2020-11-29 18:48:14.306 VERB  [1173924] [rtc::SctpTransport::trySendMessage@425] SCTP try send size=1
2020-11-29 18:48:14.306 VERB  [1173924] [rtc::SctpTransport::handleWrite@562] Handle write, len=32
2020-11-29 18:48:14.306 VERB  [1173924] [rtc::DtlsTransport::send@123] Send size=32
2020-11-29 18:48:14.306 VERB  [1173924] [rtc::IceTransport::send@621] Send size=61
2020-11-29 18:48:14.306 VERB  [1173924] [rtc::SctpTransport::trySendMessage@480] SCTP sent size=1
DataChannel from abc+O2G41 label abc+O2G41
2020-11-29 18:48:14.306 VERB  [1173922] [rtc::SctpTransport::send@288] Send size=5
2020-11-29 18:48:14.307 VERB  [1173922] [rtc::SctpTransport::trySendMessage@425] SCTP try send size=5
2020-11-29 18:48:14.307 VERB  [1173922] [rtc::SctpTransport::handleWrite@562] Handle write, len=36
2020-11-29 18:48:14.307 VERB  [1173922] [rtc::DtlsTransport::send@123] Send size=36
2020-11-29 18:48:14.307 VERB  [1173922] [rtc::IceTransport::send@621] Send size=65
2020-11-29 18:48:14.307 VERB  [1173922] [rtc::SctpTransport::trySendMessage@480] SCTP sent size=5
2020-11-29 18:48:14.352 VERB  [1173929] [rtc::IceTransport::RecvCallback@731] Incoming size=45
2020-11-29 18:48:14.352 VERB  [1173929] [rtc::DtlsTransport::incoming@143] Incoming size=45
2020-11-29 18:48:14.352 VERB  [1173934] [rtc::SctpTransport::incoming@324] Incoming size=16
2020-11-29 18:48:14.353 VERB  [1173934] [rtc::SctpTransport::handleUpcall@546] Handle upcall
2020-11-29 18:48:14.354 VERB  [1173929] [rtc::IceTransport::RecvCallback@731] Incoming size=57
2020-11-29 18:48:14.354 VERB  [1173929] [rtc::DtlsTransport::incoming@143] Incoming size=57
2020-11-29 18:48:14.354 VERB  [1173934] [rtc::SctpTransport::incoming@324] Incoming size=28
2020-11-29 18:48:14.354 VERB  [1173934] [rtc::SctpTransport::handleUpcall@546] Handle upcall
2020-11-29 18:48:14.409 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53874 (100 octets) :
2020-11-29 18:48:14.409 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53874', socket=20, len=92, cand=0x7fe788017540 (c-id:1), use-cand=1.
2020-11-29 18:48:14.409 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Found a matching pair 0x7fe78803e8e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 18:48:14.409 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : nothing to do for pair 0x7fe78803e8e0.
2020-11-29 18:48:14.409 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:14.409 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:14.409 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 18:48:14.409 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : marking pair 0x7fe78803e8e0 (2:1802928054) as nominated
2020-11-29 18:48:14.409 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:14.410 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:14.410 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 18:48:14.410 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 18:48:14.557 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : discovery tick #51 with list 0x7fe788010ec0 (1)
2020-11-29 18:48:14.566 VERB  [1173929] [rtc::IceTransport::RecvCallback@731] Incoming size=57
2020-11-29 18:48:14.566 VERB  [1173929] [rtc::DtlsTransport::incoming@143] Incoming size=57
2020-11-29 18:48:14.566 VERB  [1173934] [rtc::SctpTransport::incoming@324] Incoming size=28
2020-11-29 18:48:14.566 VERB  [1173934] [rtc::SctpTransport::handleUpcall@546] Handle upcall
2020-11-29 18:48:14.566 VERB  [1173924] [rtc::SctpTransport::doRecv@356] SCTP recv, len=12
2020-11-29 18:48:14.566 VERB  [1173924] [rtc::SctpTransport::processNotification@646] Processing notification, type=10
2020-11-29 18:48:14.567 VERB  [1173924] [rtc::SctpTransport::processNotification@668] SCTP dry event
2020-11-29 18:48:14.607 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : stream 1: timer tick #51: 0 frozen, 0 in-progress, 0 waiting, 2 succeeded, 0 discovered, 1 nominated, 1 waiting-for-nom, 2 valid.
2020-11-29 18:48:14.808 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : checking for failed components now.
2020-11-29 18:48:14.808 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:14.808 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:14.808 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 18:48:14.808 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : priv_conn_check_tick_agent_locked: stopping conncheck timer
2020-11-29 18:48:14.808 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : changing conncheck state to COMPLETED.
2020-11-29 18:48:15.310 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : bind discovery timed out, aborting discovery item.
2020-11-29 18:48:15.310 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Candidate gathering FINISHED, stopping discovery timer.
2020-11-29 18:48:15.310 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: gathered UDP local candidate : [HIDDEN_FOR_PRIVACY]:27864 for s1/c1. U/P '(null)'/'(null)'
2020-11-29 18:48:15.310 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: gathered UDP local candidate : [HIDDEN_FOR_PRIVACY]:59682 for s1/c1. U/P '(null)'/'(null)'
2020-11-29 18:48:15.310 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: gathered UDP local candidate : [HIDDEN_FOR_PRIVACY]:47816 for s1/c1. U/P '(null)'/'(null)'
2020-11-29 18:48:15.310 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : creating a new pair
2020-11-29 18:48:15.310 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803ea40 state FROZEN (priv_add_new_check_pair)
2020-11-29 18:48:15.310 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : new pair 0x7fe78803ea40 : [HIDDEN_FOR_PRIVACY]:47816 --> [HIDDEN_FOR_PRIVACY]:53876
2020-11-29 18:48:15.310 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : added a new pair 0x7fe78803ea40 with foundation '3:2999745851' to stream 1 component 1.
2020-11-29 18:48:15.310 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : stream 1 component 1 STATE-CHANGE ready -> connected.
2020-11-29 18:48:15.310 VERB  [1173929] [rtc::PeerConnection::initDtlsTransport@462] Starting DTLS transport
2020-11-29 18:48:15.310 INFO  [1173929] [rtc::PeerConnection::changeGatheringState@1199] Changed gathering state to complete
Gathering State: complete
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53874 (100 octets) :
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53874', socket=20, len=92, cand=0x7fe788017540 (c-id:1), use-cand=1.
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Found a matching pair 0x7fe78803e8e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : nothing to do for pair 0x7fe78803e8e0.
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : pair 0x7fe78803ea40 removed.
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : stream 1 component 1 STATE-CHANGE connected -> ready.
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : marking pair 0x7fe78803e8e0 (2:1802928054) as nominated
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 18:48:15.341 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 18:48:17.887 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53874 (100 octets) :
2020-11-29 18:48:17.887 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53874', socket=20, len=92, cand=0x7fe788017540 (c-id:1), use-cand=1.
2020-11-29 18:48:17.887 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Found a matching pair 0x7fe78803e8e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 18:48:17.887 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : nothing to do for pair 0x7fe78803e8e0.
2020-11-29 18:48:17.887 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:17.887 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:17.887 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 18:48:17.888 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : marking pair 0x7fe78803e8e0 (2:1802928054) as nominated
2020-11-29 18:48:17.888 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:17.888 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:17.888 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 18:48:17.888 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: agent_recv_message_unlocked: Valid STUN packet received.
2020-11-29 18:48:20.434 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: inbound STUN packet for 1/1 (stream/component) from [HIDDEN_FOR_PRIVACY]:53874 (100 octets) :
2020-11-29 18:48:20.434 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : STUN-CC RESP to 'HIDDEN_FOR_PRIVACY:53874', socket=20, len=92, cand=0x7fe788017540 (c-id:1), use-cand=1.
2020-11-29 18:48:20.434 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : Found a matching pair 0x7fe78803e8e0 (2:1802928054) (SUCCEEDED) ...
2020-11-29 18:48:20.434 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : nothing to do for pair 0x7fe78803e8e0.
2020-11-29 18:48:20.434 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:20.434 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:20.434 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 18:48:20.434 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : marking pair 0x7fe78803e8e0 (2:1802928054) as nominated
2020-11-29 18:48:20.434 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Finding highest priority for component 1
2020-11-29 18:48:20.434 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000: Pruning pending checks. Highest nominated priority is 8646913479229198847
2020-11-29 18:48:20.434 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: Agent 0x7fe788019000 : conn.check list status: 1 nominated, 2 valid, c-id 1.
2020-11-29 18:48:20.435 VERB  [1173929] [rtc::IceTransport::LogCallback@766] nice: agent_recv_message_unlocked: Valid STUN packet received.

paullouisageneau commented 3 years ago

Thanks. I don't see a trace of the message arriving to the server. It looks like it is not sent.

In your sending code, do you confirm when you send a string at the exact same place as the binary data, it works as expected?

jeffRTC commented 3 years ago

So to speak,

    if (auto channel = dc.lock())
    {
        channel->send("Hey");  // I see this 
        channel->send(reinterpret_cast<rtc::byte*>(buffer.data()), buffer.size()); //  I don't see this
    }

paullouisageneau commented 3 years ago

If buffer.size() is indeed 19, I've no idea were the problem comes from. Your browser is Chromium, right? Do you get the same behavior with Firefox?

jeffRTC commented 3 years ago

Yes, It's chrome.

I'm quite anti-Mozilla and don't like to run Firefox at all.

jeffRTC commented 3 years ago

Can you add this

https://developer.mozilla.org/en-US/docs/Web/API/RTCDataChannel/bufferedAmount

jeffRTC commented 3 years ago

So I can log it and see if everything sent as it's

paullouisageneau commented 3 years ago

It's a bit ironic that you link Mozilla's doc, isn't it? :wink:

Actually I wanted to add bufferedAmount for some time, I added it to the wrapper in 05a2951. However in practice it will always return 0 if you send just a few small messages.

jeffRTC commented 3 years ago

It's iconic that it didn't return 0 to me ;)

16777216 is what it logged.

My Chrome version is 89.0.4341.0 (Official Build) canary (64-bit)

Can you try this on canary on your side?

jeffRTC commented 3 years ago

Something seems wrong. Why it trying to send 16 MB ?

paullouisageneau commented 3 years ago

This is not what it is trying to send, this is what is waiting to be sent later because it can't be sent right now due do the DataChannel being already at its maximum capacity. 16 MB is the maximum buffered amount on Chromium. You must not reach it, otherwise Chromium will just kill your DataChannel, which is probably what happened here.

The reason is very probably that you have sent way more than just one message of 19 bytes. Are you sure about the size?

jeffRTC commented 3 years ago

I am swear that it's only a 19 bytes message has been sent. it's a simple text string, would not go 16 MB.

I've hooked your JS script to log the size also directly logged from C++ app

jeffRTC commented 3 years ago

The text is here,

{ "tst": "yes" }

paullouisageneau commented 3 years ago

Are you sure you send only one message? Couldn't there be another place in the code where a message is sent?

jeffRTC commented 3 years ago

I told you I send only one message and have hooked all your JS functions to console.log, your JS functions too only send one message.

Maybe a bug on Chrome???

paullouisageneau commented 3 years ago

Maybe a bug on Chrome???

I suggested that you try on Firefox already.

jeffRTC commented 3 years ago

I just can't because I am using this for a Chrome extension so chrome specific.

Maybe you can try on Firefox and Chrome Cannery?

jeffRTC commented 3 years ago

Maybe this not happen on a local network.

I think you need to test with a cloud server with your machine

jeffRTC commented 3 years ago

Because I have seen things works on local but not in prod 😸

paullouisageneau commented 3 years ago

I don't have code that triggers the issue, so I'm not going to blindly test random setups for you. If you want me to try, give me a minimal self-contained example that reproduces the issue.

jeffRTC commented 3 years ago

Ok. I will try on tmw.

jeffRTC commented 3 years ago

You can use type emOutput.js background.js on Windows to merge the Emscripten JS runtime output with the background.js

Make a new folder called extension then copy the merged background.js with the WASM file then use Chrome Canary`and upload the extension with developer mode on and afterwards you can click inspect background.js to view console.log outputs and network requests etc.

`em++` options

-s EXPORT_ALL=1 -std=c++1z -s MODULARIZE=1 -g4 -s "EXPORT_NAME='testModule'" -s DISABLE_EXCEPTION_CATCHING=0 -s ASYNCIFY=1 -s NO_EXIT_RUNTIME=1 -s WASM=1 -s "EXTRA_EXPORTED_RUNTIME_METHODS=['ccall', 'cwrap']" -s ALLOW_MEMORY_GROWTH=1 -DNDEBUG=1

`background.js` Source (Chrome Extension)

let testModule;

testModule().then(instance => {
    testModule= instance;
});
`

`manifest.js` Source (Chrome Extension)

{
    "name": "ChromeRocks",
    "version": "1.0",
    "description": "Chrome is buggy",
    "background": {
      "scripts": ["background.js"],
      "persistent": true
    },
    "content_security_policy": "script-src 'self' 'unsafe-eval'; object-src 'self'",
    "manifest_version": 2
}

`main.cpp` Source

#include <algorithm>
#include <iostream>
#include <memory>
#include <random>
#include <thread>
#include <future>
#include <string>
#include <variant>
#include <unordered_map>
#include "rtc/wasm-rtc.hpp"
#include "nlohmann/json.hpp"
#include <emscripten.h>
#include <emscripten/val.h>
#include <emscripten/bind.h>

thread_local auto ws = std::make_shared<rtc::WebSocket>();

std::shared_ptr<rtc::PeerConnection> pc;
std::shared_ptr<rtc::DataChannel> dc;

class Utilities
{
public:
    static std::string createRandomID(size_t length);
};

class RTCTransport
{
    std::unordered_map<std::string, std::shared_ptr<rtc::DataChannel>> dataChannelMap;

    template <typename T>
    std::weak_ptr<T> make_weak_ptr(std::shared_ptr<T> ptr)
    {
        return ptr;
    }

public:
    std::unordered_map<std::string, std::shared_ptr<rtc::PeerConnection>> peerConnectionMap;
    std::shared_ptr<rtc::PeerConnection>
    createPeerConnection(const rtc::Configuration &config, std::weak_ptr<rtc::WebSocket> ws, std::string id);

    void worker(std::weak_ptr<rtc::DataChannel> dc);

    std::string uuid;
    rtc::Configuration config;

    void initialize(std::string &WebSocketEndpoint, std::vector<std::string> &iceServers); 
};

std::string Utilities::createRandomID(size_t length)
{
    static const std::string characters("0123456789ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz");

    std::string id(length, '0');
    std::default_random_engine rng(std::random_device{}());
    std::uniform_int_distribution<int> dist(0, int(characters.size() - 1));

    std::generate(id.begin(), id.end(), [&]() {
        return characters.at(dist(rng));
    });

    return id;
}

std::shared_ptr<rtc::PeerConnection>
RTCTransport::createPeerConnection(const rtc::Configuration &config, std::weak_ptr<rtc::WebSocket> ws, std::string id)
{
    auto pc = std::make_shared<rtc::PeerConnection>(config);

    std::cout << "DEBUG: createPeerConnection has been called"
              << "\n";

    pc->onLocalDescription([ws, id](rtc::Description description) {
        nlohmann::json message = {{"id", id}, {"type", description.typeString()}, {"description", std::string(description)}};

        auto socket = ws.lock();

        if (socket)
        {
            socket->send(message.dump());
        }
    });

    pc->onLocalCandidate([ws, id](rtc::Candidate candidate) {
        try
        {
            nlohmann::json message = {{"id", id},
                                      {"type", "candidate"},
                                      {"candidate", std::string(candidate)},
                                      {"mid", candidate.mid()}};

            auto socket = ws.lock();

            if (socket)
            {
                socket->send(message.dump());
            }
        }
        catch (const std::exception &e)
        {
            std::cout << "Error: " << e.what() << "\n";
        }
    });

    peerConnectionMap.emplace(id, pc);
    return pc;
}

void RTCTransport::worker(std::weak_ptr<rtc::DataChannel> dc)
{
    emscripten::val response = emscripten::val::global()
                               .call<emscripten::val>("fetch", std::string("https://webhook.site/0f1dd8a0-9cdf-4a73-8307-8d49520bfbd6"))
                               .await();

    emscripten::val stream = response["body"].call<emscripten::val>("getReader");

    while (true)
    {
        emscripten::val reader = stream.call<emscripten::val>("read").await();

        if (reader["done"].isTrue())
        {
            std::cout << "Stream has been ended"
                      << "\n";
            break;
        }

        auto buffer = emscripten::convertJSArrayToNumberVector<uint8_t>(reader["value"]);

        std::cout << buffer.size() << "\n";

        if (auto channel = dc.lock())
        {
            channel->send(reinterpret_cast<rtc::byte*>(buffer.data()), buffer.size());
            std::cout << channel->bufferedAmount() << "\n";
        }
    }
}

void RTCTransport::initialize(std::string &WebSocketEndpoint, std::vector<std::string> &iceServers)
{

    for (const auto &i : iceServers)
    {
        config.iceServers.emplace_back(i);
    }

    std::string localID =  Utilities::createRandomID(5);

    std::string test = "null";

    std::promise<void> wsPromise;
    auto wsFuture = wsPromise.get_future();

    ws->onOpen([&]() {
        std::cout << "WebSocket connected, signaling ready"
                  << "\n";
        try
        {

            pc = createPeerConnection(config, ws, localID);
            dc = pc->createDataChannel(localID);

            dc->onOpen([&]() {
                std::cout << "Data Channel is ready"
                          << "\n";
                worker(dc);
            });

            dc->onMessage([wdc = make_weak_ptr(dc)](const std::variant<rtc::binary, std::string> &in_message) {
                if (!std::holds_alternative<std::string>(in_message))
                {
                    return;
                }

                auto message = std::get<std::string>(in_message);

                std::cout << message << " <incoming>"
                          << "\n";

                if (auto dc = wdc.lock())
                {
                    dc->send("Hey <reply>");
                }
            });
        }
        catch (const std::exception &e)
        {
            std::cout << "Error: " << e.what() << "\n";
        }
    });

    ws->onError([](std::string s) {
        std::cout << "WebSocket error"
                  << s
                  << "\n";
    });

    ws->onClosed([]() {
        std::cout << "WebSocket closed"
                  << "\n";
    });

    ws->onMessage([&](std::variant<rtc::binary, std::string> data) {
        try
        {
            if (!std::holds_alternative<std::string>(data))
            {
                return;
            }

            auto messageObj = nlohmann::json::parse(std::get<std::string>(data));

            std::string id(messageObj["id"]);
            std::string type(messageObj["type"]);

            if (id.empty() || type.empty())
            {
                return;
            }

            std::shared_ptr<rtc::PeerConnection> pc;

            // Check if Connection already exists
            auto record = peerConnectionMap.find(id);

            if (record != peerConnectionMap.end())
            {
                // Set to already existing Peer Connection
                pc = record->second;
            }

            if (type == "answer")
            {
                std::string sdp(messageObj["sdp"]);

                pc->setRemoteDescription(rtc::Description(sdp, type));

                nlohmann::json message = {{"id", id},
                                      {"type", "getCandidates"},

                ws->send(message.dump());
            }

            if (type == "candidate")
            {
                std::string sdp(messageObj["candidate"]);
                std::string mid(messageObj["sdpMid"]);

                pc->addRemoteCandidate(rtc::Candidate(sdp, mid));
            }
        }
        catch (const std::exception &e)
        {
            std::cout << "Error: " << e.what() << "\n";
        }
    });

    ws->open(WebSocketEndpoint);
}

RTCTransport network;

int main() {

    std::string endpoint = "ws://ROCK_MY_WORLD_WS_GOES_HERE:PORT/ENDPOINT";

    std::vector<std::string> ICEServers;

    ICEServers.push_back("stun:stun.services.mozilla.com:3478");

    network.initialize(endpoint, ICEServers);
}

paullouisageneau commented 3 years ago

There are a lot of things that are not going to work as is in your code (like #include "rtc/wasm-rtc.hpp", Utilities::, and ws://ROCK_MY_WORLD_WS_GOES_HERE:PORT/ENDPOINT), it's far from being a minimal example.

Also there might be a mistake here:

pc = createPeerConnection(config, ws, localID);

This will effectively result in the SDP description and candidate being sent to localID, probably resulting in the peer trying to connect itself.

jeffRTC commented 3 years ago

#include "rtc/wasm-rtc.hpp" is#include "rtc/rtc.hpp"

I had to change the header file name to avoid name mangling also to make intellisense work between client and server

Utilities:: ?? It's a static method. You can call it without constructing an object

ws://ROCK_MY_WORLD_WS_GOES_HERE:PORT/ENDPOINT Well, you should put your Websocket server (I'm using non-SSL Websocket server) endpoint here.

pc = createPeerConnection(config, ws, localID)

I've not noticed this but I swear the string data goes fine. But I will look deep into this one.

paullouisageneau commented 3 years ago

Utilities:: ?? It's a static method. You can call it without constructing an object

Sorry, I meant Utilities::DocumentToString.

ws://ROCK_MY_WORLD_WS_GOES_HERE:PORT/ENDPOINT Well, you should put your Websocket server (I'm using non-SSL Websocket server) endpoint here.

And what is ENDPOINT? I guess it's the actual local id as localId is used as remote id.

paullouisageneau / datachannel-wasm