Connection timeouts with iOS/macOS

194 views
Skip to first unread message

Jan Böhme

unread,
Jan 29, 2021, 4:07:04 AM1/29/21
to BigBlueButton-Setup
Hello,

I’m having difficulties with timeouts on iOS/macOS clients trying to join an audio conference with the effect that some clients can’t ever connect. Turnservers as well as BBB-backend have been set up using bbb-install, all have a decent network connection. 

I also tried to only use turn, not turns, for the turn server connection to rule out tls / certificate problems but with no effect.


Here’s a log from safari trying to connect:

[Log] [22:22:04:0735]  INFO: clientLogger: User requested to join audio conference with mic https://BBB-SERVER/html5client/7ab5ebd28d0d066903f9363ec402d0fee931a588.js?meteor_js_resource=true:121:1155626 (7ab5ebd28d0d066903f9363ec402d0fee931a588.js, line 9)
[Log] [22:22:04:0735] DEBUG: clientLogger: Creating the user agent https://BBB-SERVER/html5client/7ab5ebd28d0d066903f9363ec402d0fee931a588.js?meteor_js_resource=true:121:1197037 (7ab5ebd28d0d066903f9363ec402d0fee931a588.js, line 9)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | Configuration: (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · allowLegacyNotifications: false (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · authorizationHa1: "" (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · authorizationPassword: NOT SHOWN (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · authorizationUsername: "" (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · autoStart: false (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · autoStop: true (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · delegate: {} (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · displayName: "w_xpoqsne0nh5k_9-bbbID-oliver weisbach" (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · forceRport: false (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · hackAllowUnregisteredOptionTags: false (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · hackIpInContact: false (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · hackViaTcp: false (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · hackViaWs: false (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · hackWssInTransport: false (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · logBuiltinEnabled: true (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · logConfiguration: true (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · logConnector: undefined (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · logLevel: "log" (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · noAnswerTimeout: 60 (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · preloadedRouteSet: [] (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · reconnectionAttempts: 0 (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · reconnectionDelay: 4 (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · sessionDescriptionHandlerFactory: (session, options) => { (sip.js, line 9602)
        // provide a default media stream factory if need be
        if (mediaStreamFactory === undefined) {
            mediaStreamFactory = Object(_media_stream_factory_default__WEBPACK_IMPORTED_MODULE_0__["defaultMediaStreamFactory"])();
        }
        // make sure we allow `0` to be passed in so timeout can be disabled
        const iceGatheringTimeout = (options === null || options === void 0 ? void 0 : options.iceGatheringTimeout) !== undefined ? options === null || options === void 0 ? void 0 : options.iceGatheringTimeout : 5000;
        // merge passed factory options into default session description configuration
        const sessionDescriptionHandlerConfiguration = {
            iceGatheringTimeout,
            peerConnectionConfiguration: Object.assign(Object.assign({}, Object(_peer_connection_configuration_default__WEBPACK_IMPORTED_MODULE_1__["defaultPeerConnectionConfiguration"])()), options === null || options === void 0 ? void 0 : options.peerConnectionConfiguration)
        };
        const logger = session.userAgent.getLogger("sip.SessionDescriptionHandler");
        return new _session_description_handler__WEBPACK_IMPORTED_MODULE_2__["SessionDescriptionHandler"](logger, mediaStreamFactory, sessionDescriptionHandlerConfiguration);
    }
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · sessionDescriptionHandlerFactoryOptions: {"peerConnectionConfiguration":{"iceServers":[{"urls":"stun:TURN-SERVER1:443"},{"urls":"stun:TURN-SERVER2:443"},{"urls":"turn:TURN-SERVER2:443?transport=tcp","credential":"ZAPXOLJnp35wkknSXYsGM6tM+X8=","username":"1611954517:w_xpoqsne0nh5k"},{"urls":"turns:TURN-SERVER1:443?transport=tcp","credential":"ZAPXOLJnp35wkknSXYsGM6tM+X8=","username":"1611954517:w_xpoqsne0nh5k"},{"urls":"turns:TURN-SERVER2:443?transport=tcp","credential":"ZAPXOLJnp35wkknSXYsGM6tM+X8=","username":"1611954517:w_xpoqsne0nh5k"},{"urls":"turn:TURN-SERVER1:443?transport=tcp","credential":"ZAPXOLJnp35wkknSXYsGM6tM+X8=","username":"1611954517:w_xpoqsne0nh5k"}],"sdpSemantics":"plan-b"}} (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · sipExtension100rel: "Unsupported" (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · sipExtensionReplaces: "Unsupported" (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · sipExtensionExtraSupported: [] (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · sipjsId: "6ee02" (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · transportConstructor: Transport (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · transportOptions: {"server":"wss://BBB-SERVER/ws?sessionToken=ekpaa7qfwiz8eoas","connectionTimeout":5000,"keepAliveInterval":30,"keepAliveDebounce":10,"traceSip":false} (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · uri: sip:w_xpoqsne0nh5k_9-bbbID-oliver%20weisbach@BBB-SERVER (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · userAgentString: "BigBlueButton" (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · viaHost: "b4mdrruim8es.invalid" (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | · register: false (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | Starting sip:w_xpoqsne0nh5k_9-bbbID-oliver%20weisbach@BBB-SERVER (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.UserAgent | Transitioned from Stopped to Started (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.Transport | Connecting wss://BBB-SERVER/ws?sessionToken=ekpaa7qfwiz8eoas (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.Transport | Transitioned from Disconnected to Connecting (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.Transport | WebSocket opened wss://BBB-SERVER/ws?sessionToken=ekpaa7qfwiz8eoas (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.Transport | Transitioned from Connecting to Connected (sip.js, line 9602)
[Log] [22:22:04:0913]  INFO: clientLogger: User agent succesfully connected https://BBB-SERVER/html5client/7ab5ebd28d0d066903f9363ec402d0fee931a588.js?meteor_js_resource=true:121:1199069 (7ab5ebd28d0d066903f9363ec402d0fee931a588.js, line 9)
[Log] Thu Jan 28 2021 22:22:04 GMT+0100 (CET) | sip.Inviter | Inviter.invite (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:05 GMT+0100 (CET) | sip.Inviter | Session 6ee02t4o2t09at2qfqlcf4jted15mu transitioned to state Establishing (sip.js, line 9602)
[Log] [22:22:05:0081]  INFO: clientLogger: Audio call session progress update https://BBB-SERVER/html5client/7ab5ebd28d0d066903f9363ec402d0fee931a588.js?meteor_js_resource=true:121:1203728 (7ab5ebd28d0d066903f9363ec402d0fee931a588.js, line 9)
[Log] Thu Jan 28 2021 22:22:05 GMT+0100 (CET) | sip.Inviter | Inviter.onTrying (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:05 GMT+0100 (CET) | sip.invite-dialog | INVITE dialog 6ee02t4o2t09at2qfqlcf4jted15mu6yerNFgKa9e5j constructed (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:05 GMT+0100 (CET) | sip.Inviter | Inviter.onAccept (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:05 GMT+0100 (CET) | sip.invite-dialog | INVITE dialog 6ee02t4o2t09at2qfqlcf4jted15mu6yerNFgKa9e5j sending ACK request (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:05 GMT+0100 (CET) | sip.Inviter | Session 6ee02t4o2t09at2qfqlcf4jted15mu transitioned to state Established (sip.js, line 9602)
[Log] [22:22:05:0148]  INFO: clientLogger: Audio call session accepted https://BBB-SERVER/html5client/7ab5ebd28d0d066903f9363ec402d0fee931a588.js?meteor_js_resource=true:121:1202589 (7ab5ebd28d0d066903f9363ec402d0fee931a588.js, line 9)
[Log] [22:22:05:0148]  INFO: clientLogger: Audio call - check if ICE is finished and FreeSWITCH is ready https://BBB-SERVER/html5client/7ab5ebd28d0d066903f9363ec402d0fee931a588.js?meteor_js_resource=true:121:1201906 (7ab5ebd28d0d066903f9363ec402d0fee931a588.js, line 9)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.invite-dialog | INVITE dialog 6ee02t4o2t09at2qfqlcf4jted15mu6yerNFgKa9e5j sending BYE request (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.invite-dialog | INVITE dialog 6ee02t4o2t09at2qfqlcf4jted15mu6yerNFgKa9e5j destroyed (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.Inviter | Session 6ee02t4o2t09at2qfqlcf4jted15mu transitioned to state Terminated (sip.js, line 9602)
[Log] [22:22:25:0151]  INFO: clientLogger: Absorbing a redundant callback message. https://BBB-SERVER/html5client/7ab5ebd28d0d066903f9363ec402d0fee931a588.js?meteor_js_resource=true:121:1193689 (7ab5ebd28d0d066903f9363ec402d0fee931a588.js, line 9)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.Inviter | Session 6ee02t4o2t09at2qfqlcf4jted15mu in state Terminated is being disposed (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.UserAgent | Stopping sip:w_xpoqsne0nh5k_9-bbbID-oliver%20weisbach@BBB-SERVER (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.UserAgent | Transitioned from Started to Stopped (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.UserAgent | Dispose of registerers (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.UserAgent | Dispose of sessions (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.UserAgent | Dispose of subscriptions (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.UserAgent | Dispose of publishers (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.UserAgent | Dispose of transport (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.Transport | Disconnecting wss://BBB-SERVER/ws?sessionToken=ekpaa7qfwiz8eoas (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.Transport | Transitioned from Connected to Disconnecting (sip.js, line 9602)
[Log] [22:22:25:0156] ERROR: clientLogger: Audio error - errorCode=1010, cause=ICE negotiation timeout after 20s https://BBB-SERVER/html5client/7ab5ebd28d0d066903f9363ec402d0fee931a588.js?meteor_js_resource=true:121:1160387 (7ab5ebd28d0d066903f9363ec402d0fee931a588.js, line 9)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.Transport | WebSocket closed wss://BBB-SERVER/ws?sessionToken=ekpaa7qfwiz8eoas (code: 1000) (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.Transport | Transitioned from Disconnecting to Disconnected (sip.js, line 9602)
[Log] Thu Jan 28 2021 22:22:25 GMT+0100 (CET) | sip.UserAgent | Dispose of core (sip.js, line 9602)


These are some measurements from the same user with different machines, some via wifi, some via ethernet cable from the same DSL line:

1) MAC-Safari/Chrome wifi ->Timeout after 20 sec / on 3rd try 18 sec ACK from Server and connect
2) MAC-Safari/Chrome wifi -> on FritzBox mesh net on another floor in the house via 3 internal hops (2xRepeater, 1x FB) -> 9 timest timeout after 25-35 sec / one time  connection after 19 sec  
3) MAC-Safari/Chrome LAN -> no Timeout / 1 attempt 14 sec ACK from Server and connection -> 3 more tests with times between 12-19 sec
4) IPAD pro Safari and wifi only -> without hops directly on Mesh at FB / 3 Timeouts after 22-35 sec / 3 connections after 18-20 sec
5) IPAD pro Safari and wifi only -> with 2 Hops  / 5 Timeouts after 22-35 sec / 1 succesful connection after almost 20 sec
6) Windows10 PC wifi with Chrome 3 Hops after 22-30sec always succesful connection
7) virtual machine with Win10 and chrome on MAC same results as in 6)

Connection attempts via LTE didn’t suffer from the problem.

So it seems the problem is with the ice connection negotiation timeout in certain network topologies. What I don’t understand is why windows clients don’t seem to be affected from the timeout, even when it takes more than 20s.


Is there anything I can do to improve the situation? Can the timeout setting be raised without having to recompile the bbb-html5-client?


Thanks for your thoughts: Jan.



signature.asc

Fred Dixon

unread,
Jan 29, 2021, 7:48:55 AM1/29/21
to BigBlueButton-.
Hi Jan,

To cross-check could you try https://test.bigbluebutton.org/ and let us know if you encounter the same timeouts there as well.

Regards,... Fred


--
You received this message because you are subscribed to the Google Groups "BigBlueButton-Setup" group.
To unsubscribe from this group and stop receiving emails from it, send an email to bigbluebutton-s...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/bigbluebutton-setup/470E8CD0-C33B-4CC4-ACF4-8EE1A0006727%40defiant-tomato.com.


--
BigBlueButton Developer

Like BigBlueButton?  Tweet us at @bigbluebutton

Jan Böhme

unread,
Jan 29, 2021, 8:36:20 AM1/29/21
to BigBlueButton-Setup
Hi Fred,

sorry, I forgot to mention, with https://test.bigbluebutton.org everything works like a charm.. Do you happen to know about the exact settings used there?

Thanks & Best: Jan.



-- 
jan böhme.   riesaer str. 32   01127 dresden  
fon +49 351 16072355

signature.asc

Jan Böhme

unread,
Feb 2, 2021, 8:26:16 AM2/2/21
to BigBlueButton-Setup
Hi,

I finally raised 

CALL_CONNECT_TIMEOUT = 60000;
ICE_NEGOTIATION_TIMEOUT = 60000;

and compiled bigbluebutton-html5. 

With those settings the clients in question were able to establish a connection without problems. Could those settings be made available for configuration or raised per default? 

Best: Jan.
signature.asc
Reply all
Reply to author
Forward
0 new messages