More frequent connectivity problems after upgrading to 2.2.28

2,321 views

Skip to first unread message

Miguel Pellicer

unread,

Oct 20, 2020, 5:06:38 AM10/20/20

to BigBlueButton-Setup

Hi everyone,

I've upgraded one of our instances from BBB 2.2.23 to 2.2.28, after the upgrade we're experiencing more frequent connectivity problems (1004 without prompting any reason) and the audio test takes longer than usual.

Looks like the service is working fine but some users reported this problem and we are able to reproduce it, I tried accessing random rooms and sometimes I'm geeting 1004, after trying again it works an expected (Slower but ends working).

Thank you so much for any guidance and have a nice day.

Uğur Özbek

unread,

Oct 20, 2020, 5:13:19 AM10/20/20

to BigBlueButton-Setup

Hi, I've upgraded one of our instances from BBB 2.2.26 to 2.2.28 too, same problem I faced. When I control about:webrtc page everything works fine and mic connection is connected but echo test not ending.

20 Ekim 2020 Salı tarihinde saat 12:06:38 UTC+3 itibarıyla mpel...@entornosdeformacion.com şunları yazdı:

Fred Dixon

unread,

Oct 20, 2020, 8:54:30 AM10/20/20

to BigBlueButton-Setup

Hi Uğur,

After upgrading the packages you need to do

sudo bbb-conf --setip <hostname>

See

https://docs.bigbluebutton.org/2.2/install.html#upgrading-from-bigbluebutton-22

Regards,.. Fred

Mario Gasparoni Junior

unread,

Oct 20, 2020, 8:58:21 AM10/20/20

to BigBlueButton-Setup

1004 happens when audio/sip session ends without completing ICE negotiation.

Wondering if this is FreeSWITCH or html5client finishing the session, instead of waiting a bit more until ICE negotiation gets completed.

Could you please send some FreeSWITCH/html5 logs from the moment the problem happened?

Thanks in advance

Miguel Pellicer

unread,

Oct 20, 2020, 9:10:28 AM10/20/20

to BigBlueButton-Setup

I do that everytime I upgrade to a newer version, this happened in two different instances.

Thanks Fred!

Miguel Pellicer

unread,

Oct 20, 2020, 9:27:54 AM10/20/20

to BigBlueButton-Setup

Don't mind, thanks to you!

If you tell me which files do you want to check I'll be glad to share some traces, this is what I found related to freeswitch:

2020-10-20T05:02:42.134Z INFO o.b.f.v.f.FreeswitchApplication - Queue message: conference 72564-SCREENSHARE norecord

2020-10-20T05:02:42.135Z INFO o.b.f.v.f.FreeswitchApplication - Sending message: conference 72564-SCREENSHARE norecord

2020-10-20T05:02:45.091Z DEBUG o.b.freeswitch.RxJsonMsgHdlrActor - handling to-voice-conf-redis-channel - {"envelope":{"name":"CheckRunningAndRecordingToVoiceConfSysMsg","routing":{"sender":"bbb-apps-akka"},"timestamp":1603170165090},"core":{"header":{"name":"CheckRunningAndRecordingToVoiceConfSysMsg","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026"},"body":{"voiceConf":"72564","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026"}}}

2020-10-20T05:02:45.091Z INFO o.b.f.v.f.FreeswitchApplication - Queue message: conference 72564 xml_list

2020-10-20T05:02:45.091Z INFO o.b.f.v.f.FreeswitchApplication - Sending message: conference 72564 xml_list

2020-10-20T05:02:45.486Z DEBUG o.b.f.v.f.a.CheckFreeswitchStatusCommand - Check FreeSWITCH Status.

2020-10-20T05:02:45.487Z INFO o.b.f.v.f.a.CheckFreeswitchStatusCommand - ["UP 0 years, 0 days, 0 hours, 3 minutes, 38 seconds, 564 milliseconds, 635 microseconds","FreeSWITCH (Version 1.10.4-release git 133fc2c 2020-08-05 11:01:19Z 64bit) is ready","3 session(s) since startup","1 session(s) - peak 1, last 5min 1 ","0 session(s) per Sec out of max 30, peak 1, last 5min 1 ","1000 session(s) max","min idle cpu 0.00/96.90","Current Stack Size/Max 244K/244K"]

2020-10-20T05:02:46.491Z INFO o.b.f.v.freeswitch.ESLEventListener - Received Heartbeat from Freeswitch.

2020-10-20T05:02:52.041Z INFO o.b.f.v.freeswitch.ESLEventListener - Caller joined: conf=72564,uuid=b1fcb487-b636-4415-a195-5ed0a50edca7,memberId=3,callerId=w_pdp160xaqfq7_1-bbbID-Administrador,callerIdName=Administrador,muted=false,talking=false

2020-10-20T05:02:52.045Z DEBUG o.b.freeswitch.RxJsonMsgHdlrActor - handling to-voice-conf-redis-channel - {"envelope":{"name":"StartRecordingVoiceConfSysMsg","routing":{"sender":"bbb-apps-akka"},"timestamp":1603170172042},"core":{"header":{"name":"StartRecordingVoiceConfSysMsg","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026"},"body":{"voiceConf":"72564","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026","stream":"/var/freeswitch/meetings/9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026-661288.opus"}}}

2020-10-20T05:02:52.046Z INFO o.b.f.v.f.FreeswitchApplication - Queue message: conference 72564 record /var/freeswitch/meetings/9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026-661288.opus

2020-10-20T05:02:52.054Z INFO o.b.f.v.f.FreeswitchApplication - Sending message: conference 72564 record /var/freeswitch/meetings/9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026-661288.opus

2020-10-20T05:03:03.090Z DEBUG o.b.freeswitch.RxJsonMsgHdlrActor - handling to-voice-conf-redis-channel - {"envelope":{"name":"GetUsersStatusToVoiceConfSysMsg","routing":{"sender":"bbb-apps-akka"},"timestamp":1603170183089},"core":{"header":{"name":"GetUsersStatusToVoiceConfSysMsg","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026"},"body":{"voiceConf":"72564","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026"}}}

2020-10-20T05:03:03.091Z INFO o.b.f.v.f.FreeswitchApplication - Queue message: conference 72564 xml_list

2020-10-20T05:03:03.091Z INFO o.b.f.v.f.FreeswitchApplication - Sending message: conference 72564 xml_list

2020-10-20T05:03:03.094Z INFO o.b.f.v.f.a.GetUsersStatusCommand - Conf user. uuid=b1fcb487-b636-4415-a195-5ed0a50edca7,caller=Administrador,clientSession=1,callerId=w_pdp160xaqfq7_1-bbbID-Administrador,conf=72564,muted=false,talking=false

2020-10-20T05:03:06.494Z INFO o.b.f.v.freeswitch.ESLEventListener - Received Heartbeat from Freeswitch.

2020-10-20T05:03:08.100Z DEBUG o.b.freeswitch.RxJsonMsgHdlrActor - handling to-voice-conf-redis-channel - {"envelope":{"name":"CheckRunningAndRecordingToVoiceConfSysMsg","routing":{"sender":"bbb-apps-akka"},"timestamp":1603170188099},"core":{"header":{"name":"CheckRunningAndRecordingToVoiceConfSysMsg","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026"},"body":{"voiceConf":"72564","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026"}}}

2020-10-20T05:03:08.101Z INFO o.b.f.v.f.FreeswitchApplication - Queue message: conference 72564 xml_list

2020-10-20T05:03:08.101Z INFO o.b.f.v.f.FreeswitchApplication - Sending message: conference 72564 xml_list

2020-10-20T05:03:12.760Z INFO o.b.f.v.f.FreeswitchApplication - Queue message: conference 72564 norecord /var/freeswitch/meetings/9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026-661288.opus

2020-10-20T05:03:12.761Z INFO o.b.f.v.f.FreeswitchApplication - Queue message: conference 72564 kick all

2020-10-20T05:03:12.761Z DEBUG o.b.freeswitch.RxJsonMsgHdlrActor - handling to-voice-conf-redis-channel - {"envelope":{"name":"StopRecordingVoiceConfSysMsg","routing":{"sender":"bbb-apps-akka"},"timestamp":1603170192756},"core":{"header":{"name":"StopRecordingVoiceConfSysMsg","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026"},"body":{"voiceConf":"72564","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026","stream":"/var/freeswitch/meetings/9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026-661288.opus"}}}

2020-10-20T05:03:12.761Z DEBUG o.b.freeswitch.RxJsonMsgHdlrActor - handling to-voice-conf-redis-channel - {"envelope":{"name":"EjectAllFromVoiceConfMsg","routing":{"sender":"bbb-apps-akka"},"timestamp":1603170192756},"core":{"header":{"name":"EjectAllFromVoiceConfMsg","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026"},"body":{"voiceConf":"72564"}}}

2020-10-20T05:03:12.762Z INFO o.b.f.v.f.FreeswitchApplication - Sending message: conference 72564 norecord /var/freeswitch/meetings/9d9cd27026f3a9712fc35e61c65e935b819da501-1603170137026-661288.opus

2020-10-20T05:03:12.763Z INFO o.b.f.v.f.FreeswitchApplication - Sending message: conference 72564 kick all

2020-10-20T05:03:12.766Z INFO o.b.f.v.f.DelayedCommandSenderService - Queueing DelayedCommand.

2020-10-20T05:03:12.785Z INFO o.b.f.v.freeswitch.ESLEventListener - Caller left: conf=72564,uuid=b1fcb487-b636-4415-a195-5ed0a50edca7,memberId=3,callerId=w_pdp160xaqfq7_1-bbbID-Administrador,callerIdName=w_pdp160xaqfq7_1-bbbID-Administrador

Thanks again

Richard Alam

unread,

Oct 20, 2020, 9:48:52 AM10/20/20

to bigbluebu...@googlegroups.com

The html5 client logs are in

/var/log/nginx/bigbluebutton_html5_client.log

The FS logs are in /opt/freeswitch/log/

Richard

--
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/aadc49e3-49c0-430f-844d-2990745f62efn%40googlegroups.com.

-----
BigBlueButton Developer
http://www.bigbluebutton.org
https://github.com/bigbluebutton

Miguel Pellicer

unread,

Oct 20, 2020, 10:02:32 AM10/20/20

to BigBlueButton-Setup

Thanks Richard, makes sense, this is the log when the problem happened:

XXXXXXX = the username

my.hostname.org = my domain

my.public.ip.adress = the public address

my.local.ip.adress = the local ip adress of the server.

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [NOTICE] switch_channel.c:1118 New Channel sofia/external/w_8rfulakaa43j_...@my.hostname.org [7c1aec34-7726-4287-8935-dfa74b3096b0]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:585 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) Running State Change CS_NEW (Cur 6 Tot 21)

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] sofia.c:10279 sofia/external/w_8rfulakaa43j_...@my.hostname.org receiving invite from my.public.ip.adress:58232 version: 1.10.4-release git 133fc2c 2020-08-05 11:01:19Z 64bit

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] sofia.c:11476 Setting NAT mode based on websockets

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] sofia.c:7325 Channel sofia/external/w_8rfulakaa43j_...@my.hostname.org entering state [received][100]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] sofia.c:7335 Remote SDP:

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] sofia.c:7738 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State Change CS_NEW -> CS_INIT

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:604 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State NEW

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:585 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) Running State Change CS_INIT (Cur 6 Tot 21)

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:628 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State INIT

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_sofia.c:93 sofia/external/w_8rfulakaa43j_...@my.hostname.org SOFIA INIT

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:40 sofia/external/w_8rfulakaa43j_...@my.hostname.org Standard INIT

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:48 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State Change CS_INIT -> CS_ROUTING

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:628 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State INIT going to sleep

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:585 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) Running State Change CS_ROUTING (Cur 6 Tot 21)

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_channel.c:2332 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) Callstate Change DOWN -> RINGING

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:644 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State ROUTING

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_sofia.c:154 sofia/external/w_8rfulakaa43j_...@my.hostname.org SOFIA ROUTING

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:236 sofia/external/w_8rfulakaa43j_...@my.hostname.org Standard ROUTING

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [INFO] mod_dialplan_xml.c:637 Processing w_8rfulakaa43j_1-bbbID-XXXXXXX <w_8rfulakaa43j_1-bbbID-XXXXXXX>->echo71906 in context public

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:287 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State Change CS_ROUTING -> CS_EXECUTE

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:644 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State ROUTING going to sleep

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:651 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State EXECUTE

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_sofia.c:209 sofia/external/w_8rfulakaa43j_...@my.hostname.org SOFIA EXECUTE

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:329 sofia/external/w_8rfulakaa43j_...@my.hostname.org Standard EXECUTE

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_dptools.c:1672 SET sofia/external/w_8rfulakaa43j_...@my.hostname.org [outside_call]=[true]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [RFC2822_DATE]=[Tue, 20 Oct 2020 07:06:35 +0000]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_dptools.c:1672 SET sofia/external/w_8rfulakaa43j_...@my.hostname.org [bbb_authorized]=[true]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_dptools.c:1672 SET sofia/external/w_8rfulakaa43j_...@my.hostname.org [jb_use_timestamps]=[true]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_ivr.c:2243 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State Change CS_EXECUTE -> CS_ROUTING

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [NOTICE] switch_ivr.c:2250 Transfer sofia/external/w_8rfulakaa43j_...@my.hostname.org to XML[echo71906@default]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:651 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State EXECUTE going to sleep

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:644 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State ROUTING

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_sofia.c:145 Call appears to be already acknowledged

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_sofia.c:154 sofia/external/w_8rfulakaa43j_...@my.hostname.org SOFIA ROUTING

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:236 sofia/external/w_8rfulakaa43j_...@my.hostname.org Standard ROUTING

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [INFO] mod_dialplan_xml.c:637 Processing w_8rfulakaa43j_1-bbbID-XXXXXXX <w_8rfulakaa43j_1-bbbID-XXXXXXX>->echo71906 in context default

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:287 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State Change CS_ROUTING -> CS_EXECUTE

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:644 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State ROUTING going to sleep

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:651 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State EXECUTE

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_sofia.c:209 sofia/external/w_8rfulakaa43j_...@my.hostname.org SOFIA EXECUTE

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:329 sofia/external/w_8rfulakaa43j_...@my.hostname.org Standard EXECUTE

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_dptools.c:1672 SET sofia/external/w_8rfulakaa43j_...@my.hostname.org [vbridge]=[71906]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[opus:116:48000:20:0:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[SPEEX:99:16000:20:42200:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[SPEEX:99:8000:20:24600:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[G722:9:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[PCMU:0:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[PCMA:8:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[opus:116:48000:20:0:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[SPEEX:99:16000:20:42200:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[SPEEX:99:8000:20:24600:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[G722:9:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMA:8:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[opus:116:48000:20:0:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[SPEEX:99:16000:20:42200:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[SPEEX:99:8000:20:24600:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[G722:9:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMA:8:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[SPEEX:99:16000:20:42200:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:16000:20:42200:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:16000:20:42200:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[opus:116:48000:20:0:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[SPEEX:99:16000:20:42200:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[SPEEX:99:8000:20:24600:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[G722:9:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMU:0:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMA:8:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[opus:116:48000:20:0:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[SPEEX:99:16000:20:42200:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[SPEEX:99:8000:20:24600:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[G722:9:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMU:0:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMA:8:8000:20:64000:1]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 110@48000

2020-10-20 07:06:35.833268 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:3839 Set Codec sofia/external/w_8rfulakaa43j_...@my.hostname.org opus/48000 20 ms 960 samples 0 bits 1 channels

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_codec.c:111 sofia/external/w_8rfulakaa43j_...@my.hostname.org Original read codec set to opus:116

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:4329 Searching for rtp candidate.

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:4329 Searching for rtcp candidate.

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:4376 Look for Relay Candidates as last resort

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:4329 Searching for rtp candidate.

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:4329 Searching for rtcp candidate.

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:4382 sofia/external/w_8rfulakaa43j_...@my.hostname.org no suitable candidates found.

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5853 Set telephone-event payload to 110@48000

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_media.c:5911 sofia/external/w_8rfulakaa43j_...@my.hostname.org Set 2833 dtmf send payload to 110 recv payload to 110

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [NOTICE] switch_channel.c:3908 Hangup sofia/external/w_8rfulakaa43j_...@my.hostname.org [CS_EXECUTE] [INCOMPATIBLE_DESTINATION]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_session.c:2905 sofia/external/w_8rfulakaa43j_...@my.hostname.org skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:651 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State EXECUTE going to sleep

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:848 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) Callstate Change RINGING -> HANGUP

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:850 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State HANGUP

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_sofia.c:453 Channel sofia/external/w_8rfulakaa43j_...@my.hostname.org hanging up, cause: INCOMPATIBLE_DESTINATION

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_sofia.c:598 Responding to INVITE with: 488

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:60 sofia/external/w_8rfulakaa43j_...@my.hostname.org Standard HANGUP, cause: INCOMPATIBLE_DESTINATION

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:850 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State HANGUP going to sleep

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:620 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State Change CS_HANGUP -> CS_REPORTING

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:936 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State REPORTING

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:174 sofia/external/w_8rfulakaa43j_...@my.hostname.org Standard REPORTING, cause: INCOMPATIBLE_DESTINATION

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:936 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State REPORTING going to sleep

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:611 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State Change CS_REPORTING -> CS_DESTROY

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_session.c:1726 Session 21 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) Locked, Waiting on external entities

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [NOTICE] switch_core_session.c:1744 Session 21 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) Ended

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [NOTICE] switch_core_session.c:1748 Close Channel sofia/external/w_8rfulakaa43j_...@my.hostname.org [CS_DESTROY]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:739 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) Running State Change CS_DESTROY (Cur 5 Tot 21)

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:749 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State DESTROY

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_sofia.c:364 sofia/external/w_8rfulakaa43j_...@my.hostname.org SOFIA DESTROY

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[0] PLC[0] FEC[0]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[0] PLC[0] FEC[0]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:181 sofia/external/w_8rfulakaa43j_...@my.hostname.org Standard DESTROY

7c1aec34-7726-4287-8935-dfa74b3096b0 2020-10-20 07:06:35.833268 [DEBUG] switch_core_state_machine.c:749 (sofia/external/w_8rfulakaa43j_...@my.hostname.org) State DESTROY going to sleep

12a44d9a-1035-44a6-846a-bca3e5a8a752 2020-10-20 07:06:44.753265 [DEBUG] switch_core_media.c:3226 [VBR]: Correcting calculated ptime value from [20] to [10] to compensate for [1] lost packet(s)

12a44d9a-1035-44a6-846a-bca3e5a8a752 2020-10-20 07:06:44.833271 [DEBUG] switch_core_media.c:3226 [VBR]: Correcting calculated ptime value from [20] to [10] to compensate for [1] lost packet(s)

a8a77dea-e1ca-49be-88fb-17e511572967 2020-10-20 07:06:44.833271 [DEBUG] switch_core_media.c:3226 [VBR]: Correcting calculated ptime value from [20] to [10] to compensate for [1] lost packet(s)

12a44d9a-1035-44a6-846a-bca3e5a8a752 2020-10-20 07:06:45.253267 [DEBUG] switch_core_media.c:3226 [VBR]: Correcting calculated ptime value from [20] to [10] to compensate for [1] lost packet(s)

a8a77dea-e1ca-49be-88fb-17e511572967 2020-10-20 07:06:45.273265 [DEBUG] switch_core_media.c:3226 [VBR]: Correcting calculated ptime value from [20] to [10] to compensate for [1] lost packet(s)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [NOTICE] switch_channel.c:1118 New Channel sofia/external/w_9l4y7ptfetez_...@my.hostname.org [80971e62-6810-41fb-8342-cba433f5def4]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:585 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) Running State Change CS_NEW (Cur 6 Tot 22)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] sofia.c:10279 sofia/external/w_9l4y7ptfetez_...@my.hostname.org receiving invite from my.public.ip.adress:58274 version: 1.10.4-release git 133fc2c 2020-08-05 11:01:19Z 64bit

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] sofia.c:11476 Setting NAT mode based on websockets

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] sofia.c:7325 Channel sofia/external/w_9l4y7ptfetez_...@my.hostname.org entering state [received][100]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] sofia.c:7335 Remote SDP:

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] sofia.c:7738 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State Change CS_NEW -> CS_INIT

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:604 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State NEW

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:585 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) Running State Change CS_INIT (Cur 6 Tot 22)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:628 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State INIT

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] mod_sofia.c:93 sofia/external/w_9l4y7ptfetez_...@my.hostname.org SOFIA INIT

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:40 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Standard INIT

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:48 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State Change CS_INIT -> CS_ROUTING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:628 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State INIT going to sleep

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:585 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) Running State Change CS_ROUTING (Cur 6 Tot 22)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_channel.c:2332 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) Callstate Change DOWN -> RINGING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:644 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State ROUTING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] mod_sofia.c:154 sofia/external/w_9l4y7ptfetez_...@my.hostname.org SOFIA ROUTING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:236 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Standard ROUTING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [INFO] mod_dialplan_xml.c:637 Processing w_9l4y7ptfetez_1-bbbID-XXXXXXX <w_9l4y7ptfetez_1-bbbID-XXXXXXX>->echo71906 in context public

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:287 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State Change CS_ROUTING -> CS_EXECUTE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:644 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State ROUTING going to sleep

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:651 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State EXECUTE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] mod_sofia.c:209 sofia/external/w_9l4y7ptfetez_...@my.hostname.org SOFIA EXECUTE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:329 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Standard EXECUTE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] mod_dptools.c:1672 SET sofia/external/w_9l4y7ptfetez_...@my.hostname.org [outside_call]=[true]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_channel.c:1310 EXPORT (export_vars) [RFC2822_DATE]=[Tue, 20 Oct 2020 07:06:52 +0000]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] mod_dptools.c:1672 SET sofia/external/w_9l4y7ptfetez_...@my.hostname.org [bbb_authorized]=[true]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] mod_dptools.c:1672 SET sofia/external/w_9l4y7ptfetez_...@my.hostname.org [jb_use_timestamps]=[true]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_ivr.c:2243 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State Change CS_EXECUTE -> CS_ROUTING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [NOTICE] switch_ivr.c:2250 Transfer sofia/external/w_9l4y7ptfetez_...@my.hostname.org to XML[echo71906@default]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:651 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State EXECUTE going to sleep

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:644 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State ROUTING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] mod_sofia.c:145 Call appears to be already acknowledged

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] mod_sofia.c:154 sofia/external/w_9l4y7ptfetez_...@my.hostname.org SOFIA ROUTING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:236 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Standard ROUTING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [INFO] mod_dialplan_xml.c:637 Processing w_9l4y7ptfetez_1-bbbID-XXXXXXX <w_9l4y7ptfetez_1-bbbID-XXXXXXX>->echo71906 in context default

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:287 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State Change CS_ROUTING -> CS_EXECUTE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:644 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State ROUTING going to sleep

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:651 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State EXECUTE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] mod_sofia.c:209 sofia/external/w_9l4y7ptfetez_...@my.hostname.org SOFIA EXECUTE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_state_machine.c:329 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Standard EXECUTE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] mod_dptools.c:1672 SET sofia/external/w_9l4y7ptfetez_...@my.hostname.org [vbridge]=[71906]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[opus:116:48000:20:0:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[SPEEX:99:16000:20:42200:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[SPEEX:99:8000:20:24600:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[G722:9:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[PCMU:0:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [opus:111:48000:20:0:1]/[PCMA:8:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[opus:116:48000:20:0:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[SPEEX:99:16000:20:42200:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[SPEEX:99:8000:20:24600:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[G722:9:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMA:8:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[opus:116:48000:20:0:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[SPEEX:99:16000:20:42200:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[SPEEX:99:8000:20:24600:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[G722:9:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMA:8:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[SPEEX:99:16000:20:42200:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:16000:20:42200:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:16000:20:42200:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[opus:116:48000:20:0:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[SPEEX:99:16000:20:42200:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[SPEEX:99:8000:20:24600:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[G722:9:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMU:0:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMA:8:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[opus:116:48000:20:0:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[SPEEX:99:16000:20:42200:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[SPEEX:99:8000:20:24600:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[G722:9:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMU:0:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMA:8:8000:20:64000:1]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 110@48000

2020-10-20 07:06:52.893271 [DEBUG] mod_opus.c:613 Opus encoder: set bitrate to local settings [72000bps]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:3839 Set Codec sofia/external/w_9l4y7ptfetez_...@my.hostname.org opus/48000 20 ms 960 samples 0 bits 1 channels

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_codec.c:111 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Original read codec set to opus:116

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:4284 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.1.11:49852

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:4329 Searching for rtp candidate.

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:4338 Choose rtp candidate, index 0, 192.168.1.11:49852

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:4104 sofia/external/w_9l4y7ptfetez_...@my.hostname.org choosing family v4

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:4349 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 192.168.1.11:49852

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:4401 setting remote audio ice addr to index 0 192.168.1.11:49852 based on candidate

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:4436 Setting remote rtcp audio addr to 192.168.1.11:49852 based on candidate

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5853 Set telephone-event payload to 110@48000

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:5911 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Set 2833 dtmf send payload to 110 recv payload to 110

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:8663 AUDIO RTP [sofia/external/w_9l4y7ptfetez_...@my.hostname.org] my.local.ip.adress port 21314 -> 192.168.1.11 port 49852 codec: 111 ms: 20

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_rtp.c:4450 Starting timer [soft] 960 bytes per 20ms

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [INFO] switch_core_media.c:8845 Activating Audio ICE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [NOTICE] switch_rtp.c:4952 Activating RTP audio ICE: +v4R:2B20v2mRfwjFmzRr 192.168.1.11:49852

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:8885 Activating RTCP PORT 49852

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_rtp.c:4848 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 49852

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [INFO] switch_core_media.c:8896 Skipping RTCP ICE (Same as RTP)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [INFO] switch_rtp.c:3764 Activate RTP/RTCP audio DTLS client

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [INFO] switch_rtp.c:3927 Changing audio DTLS state from OFF to HANDSHAKE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:8977 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Set 2833 dtmf send payload to 110

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:8984 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Set 2833 dtmf receive payload to 110

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:9007 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Set rtp dtmf delay to 40

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/w_9l4y7ptfetez_...@my.hostname.org!

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_channel.c:3565 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) Callstate Change RINGING -> EARLY

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] switch_core_media.c:8645 Audio params are unchanged for sofia/external/w_9l4y7ptfetez_...@my.hostname.org.

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.893271 [DEBUG] mod_sofia.c:898 Local SDP sofia/external/w_9l4y7ptfetez_...@my.hostname.org:

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.913269 [DEBUG] sofia.c:7325 Channel sofia/external/w_9l4y7ptfetez_...@my.hostname.org entering state [completed][200]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:52.973267 [DEBUG] sofia.c:7325 Channel sofia/external/w_9l4y7ptfetez_...@my.hostname.org entering state [ready][200]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:54.113269 [NOTICE] switch_rtp.c:1301 Auto Changing audio stun/rtp/dtls port from 192.168.1.11:49852 to 95.60.149.34:49852 idx:-1

3b693c63-91f6-4c27-b4e0-7719c4abbc15 2020-10-20 07:06:55.273268 [DEBUG] switch_core_media.c:3226 [VBR]: Correcting calculated ptime value from [20] to [10] to compensate for [1] lost packet(s)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:56.033269 [INFO] switch_rtp.c:3282 Changing audio DTLS state from HANDSHAKE to SETUP

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:56.053271 [INFO] switch_rtp.c:3189 audio Fingerprint Verified.

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:56.053271 [INFO] switch_rtp.c:4254 Activating audio Secure RTP SEND

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:56.053271 [INFO] switch_rtp.c:4232 Activating audio Secure RTP RECV

2020-10-20 07:06:56.053271 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:56.053271 [INFO] switch_rtp.c:3231 Changing audio DTLS state from SETUP to READY

2020-10-20 07:06:56.053271 [DEBUG] switch_core_sqldb.c:2836 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:56.053271 [NOTICE] mod_dptools.c:1406 Channel [sofia/external/w_9l4y7ptfetez_...@my.hostname.org] has been answered

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:56.053271 [DEBUG] switch_channel.c:3865 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) Callstate Change EARLY -> ACTIVE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:56.053271 [DEBUG] mod_dptools.c:1672 SET sofia/external/w_9l4y7ptfetez_...@my.hostname.org [bbb_from_echo]=[true]

2020-10-20 07:06:56.053271 [INFO] switch_ivr_async.c:219 Digit parser DPTOOLS: Setting realm to 'direct_from_echo'

2020-10-20 07:06:56.053271 [DEBUG] switch_ivr_async.c:344 Digit parser DPTOOLS: binding 1/direct_from_echo/0 callback: 0x7fadaca88c6d data: 0x7fad88057180

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:56.053271 [DEBUG] switch_ivr.c:195 Codec Activated L16@48000hz 1 channels 20ms

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:56.093273 [DEBUG] switch_rtp.c:1921 rtcp_stats_init: audio ssrc[3522998253] base_seq[29663]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.353267 [DEBUG] switch_rtp.c:8004 RTP RECV DTMF 1:4800

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.353267 [DEBUG] mod_dptools.c:188 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Digit match binding [exec:execute_extension][ECHO_TO_CONFERENCE XML default]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.513270 [DEBUG] switch_ivr.c:632 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Command Execute [depth=1] execute_extension(ECHO_TO_CONFERENCE XML default)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.513270 [INFO] mod_dialplan_xml.c:637 Processing w_9l4y7ptfetez_1-bbbID-XXXXXXX <w_9l4y7ptfetez_1-bbbID-XXXXXXX>->ECHO_TO_CONFERENCE in context default

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.513270 [NOTICE] switch_core_session.c:3017 Execute [depth=2] jitterbuffer(60:120)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.513270 [DEBUG] switch_core_media.c:2554 Setting Jitterbuffer to 60ms (3 frames) (6 max frames)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.513270 [NOTICE] switch_core_session.c:3017 Execute [depth=2] answer()

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.513270 [NOTICE] switch_core_session.c:3017 Execute [depth=2] conference(${vbridge}@cdquality)

2020-10-20 07:06:58.513270 [DEBUG] mod_conference.c:3414 using channel sound prefix: /opt/freeswitch/share/freeswitch/sounds/en/us/callie

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.513270 [DEBUG] conference_member.c:1764 Raw Codec Activation Success L16@48000hz 1 channel 20ms

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.513270 [DEBUG] conference_member.c:1811 Raw Codec Activation Success L16@48000hz 1 channel 20ms

2020-10-20 07:06:58.513270 [DEBUG] mod_conference.c:228 Setup timer success interval: 20 samples: 960

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.513270 [DEBUG] switch_core_codec.c:223 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Push codec L16:100

2020-10-20 07:06:58.533267 [DEBUG] conference_member.c:106 sofia/external/w_9l4y7ptfetez_...@my.hostname.org binding '0' to 'mute'

2020-10-20 07:06:58.533267 [INFO] switch_ivr_async.c:219 Digit parser mod_conference: Setting realm to 'conf'

2020-10-20 07:06:58.533267 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 0/conf/0 callback: 0x7fadacf0100a data: 0x7fad88084688

2020-10-20 07:06:58.533267 [DEBUG] conference_member.c:106 sofia/external/w_9l4y7ptfetez_...@my.hostname.org binding '*' to 'deaf mute'

2020-10-20 07:06:58.533267 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding */conf/0 callback: 0x7fadacf0100a data: 0x7fad880846b8

2020-10-20 07:06:58.533267 [DEBUG] conference_member.c:106 sofia/external/w_9l4y7ptfetez_...@my.hostname.org binding '9' to 'energy up'

2020-10-20 07:06:58.533267 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 9/conf/0 callback: 0x7fadacf0100a data: 0x7fad880846e8

2020-10-20 07:06:58.533267 [DEBUG] conference_member.c:106 sofia/external/w_9l4y7ptfetez_...@my.hostname.org binding '8' to 'energy equ'

2020-10-20 07:06:58.533267 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 8/conf/0 callback: 0x7fadacf0100a data: 0x7fad88084718

2020-10-20 07:06:58.533267 [DEBUG] conference_member.c:106 sofia/external/w_9l4y7ptfetez_...@my.hostname.org binding '7' to 'energy dn'

2020-10-20 07:06:58.533267 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 7/conf/0 callback: 0x7fadacf0100a data: 0x7fad88084748

2020-10-20 07:06:58.533267 [DEBUG] conference_member.c:106 sofia/external/w_9l4y7ptfetez_...@my.hostname.org binding '3' to 'vol talk up'

2020-10-20 07:06:58.533267 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 3/conf/0 callback: 0x7fadacf0100a data: 0x7fad88084778

2020-10-20 07:06:58.533267 [DEBUG] conference_member.c:106 sofia/external/w_9l4y7ptfetez_...@my.hostname.org binding '2' to 'vol talk zero'

2020-10-20 07:06:58.533267 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 2/conf/0 callback: 0x7fadacf0100a data: 0x7fad880847a8

2020-10-20 07:06:58.533267 [DEBUG] conference_member.c:106 sofia/external/w_9l4y7ptfetez_...@my.hostname.org binding '1' to 'vol talk dn'

2020-10-20 07:06:58.533267 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 1/conf/0 callback: 0x7fadacf0100a data: 0x7fad880847d8

2020-10-20 07:06:58.533267 [DEBUG] conference_member.c:106 sofia/external/w_9l4y7ptfetez_...@my.hostname.org binding '6' to 'vol listen up'

2020-10-20 07:06:58.533267 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 6/conf/0 callback: 0x7fadacf0100a data: 0x7fad88084808

2020-10-20 07:06:58.533267 [DEBUG] conference_member.c:106 sofia/external/w_9l4y7ptfetez_...@my.hostname.org binding '5' to 'vol listen zero'

2020-10-20 07:06:58.533267 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 5/conf/0 callback: 0x7fadacf0100a data: 0x7fad88084838

2020-10-20 07:06:58.533267 [DEBUG] conference_member.c:106 sofia/external/w_9l4y7ptfetez_...@my.hostname.org binding '4' to 'vol listen dn'

2020-10-20 07:06:58.533267 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 4/conf/0 callback: 0x7fadacf0100a data: 0x7fad88084868

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:06:58.533267 [DEBUG] conference_loop.c:1338 Setup timer soft success interval: 20 samples: 960 from codec opus

2020-10-20 07:06:58.533267 [DEBUG] conference_record.c:304 Setup timer success interval: 20 samples: 960

3b693c63-91f6-4c27-b4e0-7719c4abbc15 2020-10-20 07:07:00.493270 [DEBUG] switch_core_media.c:3226 [VBR]: Correcting calculated ptime value from [20] to [10] to compensate for [1] lost packet(s)

3b693c63-91f6-4c27-b4e0-7719c4abbc15 2020-10-20 07:07:00.773269 [DEBUG] switch_core_media.c:3226 [VBR]: Correcting calculated ptime value from [40] to [20] to compensate for [1] lost packet(s)

238e1435-ba07-4303-9c06-d6dc75ee06eb 2020-10-20 07:07:09.653271 [DEBUG] conference_member.c:1494 Queueing file /opt/freeswitch/share/freeswitch/sounds/en/us/callie/conference/conf-unmuted.wav for play

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.273276 [INFO] conference_loop.c:1665 Channel leaving conference, cause: NONE

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.273276 [DEBUG] switch_core_codec.c:248 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Restore previous codec opus:116.

2020-10-20 07:07:17.273276 [DEBUG] mod_conference.c:835 Write Lock ON

2020-10-20 07:07:17.293270 [INFO] conference_record.c:425 Recording of /var/freeswitch/meetings/9d9cd27026f3a9712fc35e61c65e935b819da501-1603177586016-8107791.opus Stopped

2020-10-20 07:07:17.293270 [DEBUG] mod_conference.c:838 Write Lock OFF

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [NOTICE] sofia.c:1089 Hangup sofia/external/w_9l4y7ptfetez_...@my.hostname.org [CS_EXECUTE] [NORMAL_CLEARING]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_session.c:2905 sofia/external/w_9l4y7ptfetez_...@my.hostname.org skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:651 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State EXECUTE going to sleep

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:585 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) Running State Change CS_HANGUP (Cur 6 Tot 22)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:848 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) Callstate Change ACTIVE -> HANGUP

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:850 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State HANGUP

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] mod_sofia.c:453 Channel sofia/external/w_9l4y7ptfetez_...@my.hostname.org hanging up, cause: NORMAL_CLEARING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:60 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Standard HANGUP, cause: NORMAL_CLEARING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:850 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State HANGUP going to sleep

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:620 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State Change CS_HANGUP -> CS_REPORTING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:936 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State REPORTING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:174 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Standard REPORTING, cause: NORMAL_CLEARING

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:936 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State REPORTING going to sleep

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:611 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State Change CS_REPORTING -> CS_DESTROY

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_session.c:1726 Session 22 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) Locked, Waiting on external entities

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [NOTICE] switch_core_session.c:1744 Session 22 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) Ended

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [NOTICE] switch_core_session.c:1748 Close Channel sofia/external/w_9l4y7ptfetez_...@my.hostname.org [CS_DESTROY]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:739 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) Running State Change CS_DESTROY (Cur 5 Tot 22)

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:749 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State DESTROY

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] mod_sofia.c:364 sofia/external/w_9l4y7ptfetez_...@my.hostname.org SOFIA DESTROY

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[936] PLC[0] FEC[0]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] mod_opus.c:719 Opus decoder stats: Frames[0] PLC[0] FEC[0]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] mod_opus.c:734 Opus encoder stats: Frames[963] Bytes encoded[82663] Encoded length ms[19260] Average encoded bitrate bps[34805]

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:181 sofia/external/w_9l4y7ptfetez_...@my.hostname.org Standard DESTROY

80971e62-6810-41fb-8342-cba433f5def4 2020-10-20 07:07:17.333275 [DEBUG] switch_core_state_machine.c:749 (sofia/external/w_9l4y7ptfetez_...@my.hostname.org) State DESTROY going to sleep

3b693c63-91f6-4c27-b4e0-7719c4abbc15 2020

Mario Gasparoni Junior

unread,

Oct 20, 2020, 1:03:16 PM10/20/20

to bigbluebu...@googlegroups.com

It seems your FreeSWITCH is answering with SIP 488 (Not acceptable here); i guess this is because it is not able to find a suitable ICE candidate in your INVITE request.

Could you send some html5client logs ?

You received this message because you are subscribed to a topic in the Google Groups "BigBlueButton-Setup" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/bigbluebutton-setup/oeVMDvkc_g4/unsubscribe.
To unsubscribe from this group and all its topics, send an email to bigbluebutton-s...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/bigbluebutton-setup/ce3d246a-e7d7-432c-943d-1860e5eb234cn%40googlegroups.com.

Att. Mário Gasparoni.

www.inf.ufrgs.br/~mcgjunior

Mario Gasparoni Junior

unread,

Oct 20, 2020, 1:22:25 PM10/20/20

to bigbluebu...@googlegroups.com

Also , are you using stun.freeswitch.org (bbb's default) as a stun server?

I've heard about audio connection problems when using this server as stun. Changing it to stun.l.google.com:19302 seems to help in this case.

Miguel Pellicer

unread,

Oct 20, 2020, 3:41:55 PM10/20/20

to BigBlueButton-Setup

Sure, where are this logs in the default installation?

Do you mean these lines?

2020-10-20T19:27:47.341Z DEBUG o.b.web.controllers.ApiController - ApiController#create

2020-10-20T19:27:47.341Z DEBUG o.b.web.controllers.ApiController - [name:[XXXX], meetingID:[152a5ff71d0158ed59dae558bf47b5e117cc5cb9], moderatorPW:[8d7f4e657dbb5956fc41fb32dd1e7afbee062fe8], attendeePW:[f237955281e6d16f2a120a68c5aac58f9d90643c], welcome:[Bienvenido\a a la plataforma de videoconferencia. Recomendamos utilizar auriculares con micro para evitar causar ruido de fondo a otros asistentes. Para entender como funciona BigBlueButton consulte estos <a href="event:http://www.bigbluebutton.org/content/videos">videos tutoriales</a>. Para activar el audio haga click en el icono de auricular (equina superior izquierda). Por favor utilice auricular para evitar causar ruido. ], logoutURL:[https://my.ezxternal.domain/i, voiceBridge:[76506], record:[true], duration:[0], meta_origin:[sakai], meta_originVersion:[12-SNAPSHOT], meta_originServerCommonName:[], meta_originServerUrl:[https://my.ezxternal.domain], meta_context:[EDF-TEST], meta_contextId:[433dd8d0-70ab-4afa-bfe5-8cd3962f0535], meta_contextActivity:[Sesiones de nivel fácil], meta_contextActivityDescription:[Sesiones de nivel fácil], checksum:[558d3d329960c3b063676530fb5d1a73cad6b0fa]]

2020-10-20T19:27:47.341Z INFO o.b.api.ParamsProcessorUtil - CHECKSUM=558d3d329960c3b063676530fb5d1a73cad6b0fa length=40

2020-10-20T19:27:47.342Z INFO o.b.api.ParamsProcessorUtil - CHECKSUM=558d3d329960c3b063676530fb5d1a73cad6b0fa length=40

2020-10-20T19:27:47.350Z DEBUG o.b.web.controllers.ApiController - ApiController#uploadDocuments(9d9cd27026f3a9712fc35e61c65e935b819da501-1603222067342)

2020-10-20T19:27:47.350Z DEBUG o.b.web.controllers.ApiController - ApiController#downloadAndProcessDocument(https://my.domain.org/default.pdf, 9d9cd27026f3a9712fc35e61c65e935b819da501-1603222067342, )

2020-10-20T19:27:47.351Z INFO o.bigbluebutton.api.MeetingService - --analytics-- data={"duration":0,"record":true,"logCode":"create_meeting","name":"Sesiones de nivel fácil","description":"Create meeting.","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603222067342","externalMeetingId":"152a5ff71d0158ed59dae558bf47b5e117cc5cb9","isBreakout":false,"webcamsOnlyForModerator":false}

2020-10-20T19:27:47.387Z INFO o.bigbluebutton.api.MeetingService - --analytics-- data={"duration":0,"record":true,"logCode":"meeting_started","name":"Sesiones de nivel fácil","description":"Meeting has started.","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603222067342","externalMeetingId":"152a5ff71d0158ed59dae558bf47b5e117cc5cb9","isBreakout":false}

2020-10-20T19:27:47.439Z DEBUG o.b.web.controllers.ApiController - Rendering as xml

2020-10-20T19:27:47.481Z DEBUG o.b.web.controllers.ApiController - ApiController#join

2020-10-20T19:27:47.481Z INFO o.b.api.ParamsProcessorUtil - CHECKSUM=81bcc975995aeef44ae63071a998e56f32db1f70 length=40

2020-10-20T19:27:47.481Z INFO o.b.web.controllers.ApiController - Retrieving meeting 9d9cd27026f3a9712fc35e61c65e935b819da501

2020-10-20T19:27:47.482Z INFO o.b.web.controllers.ApiController - Session sessionToken for My User [null]

2020-10-20T19:27:47.482Z INFO o.b.web.controllers.ApiController - Session user-token for My User [null]

2020-10-20T19:27:47.482Z INFO o.b.web.controllers.ApiController - --analytics-- data={"extMeetingid":"152a5ff71d0158ed59dae558bf47b5e117cc5cb9","logCode":"join_api","name":"My User","sessionToken":"knjtlvcdoc0ippos","description":"Handle JOIN API.","meetingid":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603222067342","userid":"w_btbkrvd14nv9"}

2020-10-20T19:27:47.482Z INFO o.b.web.controllers.ApiController - Redirecting to https://my.domain.org/html5client/join?sessionToken=knjtlvcdoc0ippos

2020-10-20T19:27:48.353Z INFO o.b.web.controllers.ApiController - Token knjtlvcdoc0ippos is valid

2020-10-20T19:27:48.353Z INFO o.b.web.controllers.ApiController - --analytics-- data={"extMeetingid":"152a5ff71d0158ed59dae558bf47b5e117cc5cb9","logCode":"handle_enter_api","name":"My User","sessionToken":"knjtlvcdoc0ippos","description":"Handling ENTER API.","meetingid":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603222067342","userid":"w_btbkrvd14nv9"}

2020-10-20T19:27:48.396Z INFO o.bigbluebutton.api.MeetingService - --analytics-- data={"role":"MODERATOR","clientType":"HTML5","externalUserId":"admin","logCode":"user_joined_message","name":"Sesiones de nivel fácil","description":"User joined the meeting.","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603222067342","externalMeetingId":"152a5ff71d0158ed59dae558bf47b5e117cc5cb9","guest":false,"guestStatus":"ALLOW","userId":"w_btbkrvd14nv9","username":"My User"}

2020-10-20T19:27:49.948Z INFO o.b.web.controllers.ApiController - Token knjtlvcdoc0ippos is valid

2020-10-20T19:27:49.948Z INFO o.b.w.services.turn.StunTurnService -

StunTurnService::getStunServers

2020-10-20T19:27:49.948Z INFO o.b.w.services.turn.StunTurnService -

StunTurnService::getStunAndTurnServersFor w_btbkrvd14nv9

2020-10-20T19:27:52.439Z INFO o.b.p.DocumentConversionServiceImp - --analytics-- data={"current":true,"filename":"default.pdf","logCode":"presentation_conversion_start","authzToken":"preupload-download-authz-token","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603222067342","message":"Start presentation conversion.","podId":"DEFAULT_PRESENTATION_POD","presId":"d2d9a672040fbde2a47a10bf6c37b6a4b5ae187f-1603222067350"}

2020-10-20T19:27:52.439Z INFO o.b.p.SupportedDocumentFilter - Received supported file /var/bigbluebutton/9d9cd27026f3a9712fc35e61c65e935b819da501-1603222067342/9d9cd27026f3a9712fc35e61c65e935b819da501-1603222067342/d2d9a672040fbde2a47a10bf6c37b6a4b5ae187f-1603222067350/d2d9a672040fbde2a47a10bf6c37b6a4b5ae187f-1603222067350.pdf

2020-10-20T19:27:52.446Z INFO o.b.p.imp.PresentationFileProcessor - --analytics-- data={"filename":"default.pdf","num_pages":1,"logCode":"presentation_conversion_num_pages","authzToken":"preupload-download-authz-token","meetingId":"9d9cd27026f3a9712fc35e61c65e935b819da501-1603222067342","message":"Presentation conversion number of pages.","podId":"DEFAULT_PRESENTATION_POD","presId":"d2d9a672040fbde2a47a10bf6c37b6a4b5ae187f-1603222067350"}

2020-10-20T19:27:52.580Z INFO o.b.p.i.PresentationConversionCompletionService - --analytics-- data={"current":true,"filename":"default.pdf","logCode":"present

Miguel Pellicer

unread,

Oct 20, 2020, 3:42:27 PM10/20/20

to BigBlueButton-Setup

Yeah, I'm using all the default configuration.

Miguel Pellicer

unread,

Oct 21, 2020, 5:19:33 AM10/21/20

to BigBlueButton-Setup

Thank you so much for the help Mário.

I suspect there's something wrong BBB 2.2.28, since the upgrade from 2.2.23 yesterday some moderators reported that the presentation and the controls froze and they couldn't reconnect. Some students report problems connecting the webcam. We're experiencing this in two different instances hosted in different providers.

I've enabled the three Kurento instances feature this morning and I don't think is related to that.

I also experienced 1004 errors during the audio test, this is the log I found on my browser. What kind of FreeSwitch changes have been done?

[11:10:15:0540] INFO: clientLogger: Stripped 1 mDNS candidates p (https://my.domain.org/html5client/d3c57d5494122295d6d06c8426cee650e4e1fd44.js?meteor_js_resource=true:121:1229730)

sip.js?v=1058:9599 Wed Oct 21 2020 11:10:15 GMT+0200 (hora de verano de Europa central) | sip.Inviter | Session iir47qqpfolhjanmpjig6vq7mm6pbm transitioned to state Establishing

d3c57d5494122295d6d06c8426cee650e4e1fd44.js?meteor_js_resource=true:9 [11:10:15:0542] INFO: clientLogger: Audio call session progress update v (https://my.domain.org/html5client/d3c57d5494122295d6d06c8426cee650e4e1fd44.js?meteor_js_resource=true:121:1190940)

sip.js?v=1058:9599 Wed Oct 21 2020 11:10:15 GMT+0200 (hora de verano de Europa central) | sip.Transport | Sending WebSocket message:

INVITE sip:echo...@my.domain.org SIP/2.0

Via: SIP/2.0/WSS a9m6rper574s.invalid;branch=z9hG4bK4686539

To: <sip:echo...@my.domain.org>

From: "w_rcj6yiqvkary_1-bbbID-My User" <sip:w_rcj6yiqvkary_1-bbbID-My%20U...@my.domain.org>;tag=6vq7mm6pbm

CSeq: 1 INVITE

Call-ID: iir47qqpfolhjanmpjig

Max-Forwards: 70

Contact: <sip:8i6s...@a9m6rper574s.invalid;transport=ws;ob>

Allow: ACK,CANCEL,INVITE,MESSAGE,BYE,OPTIONS,INFO,NOTIFY,REFER

Supported: outbound

User-Agent: BigBlueButton

Content-Type: application/sdp

Content-Length: 1655

v=0

o=- 2383748699990737395 2 IN IP4 127.0.0.1

s=-

t=0 0

a=msid-semantic: WMS 5e19a5cf-32ee-426c-8ee1-51b9985f61ae

a=group:BUNDLE 0

m=audio 9 UDP/TLS/RTP/SAVPF 111 103 104 9 0 8 106 105 13 110 112 113 126

c=IN IP4 0.0.0.0

a=rtpmap:111 opus/48000/2

a=rtpmap:103 ISAC/16000

a=rtpmap:104 ISAC/32000

a=rtpmap:9 G722/8000

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:106 CN/32000

a=rtpmap:105 CN/16000

a=rtpmap:13 CN/8000

a=rtpmap:110 telephone-event/48000

a=rtpmap:112 telephone-event/32000

a=rtpmap:113 telephone-event/16000

a=rtpmap:126 telephone-event/8000

a=fmtp:111 minptime=10;useinbandfec=1

a=rtcp:9 IN IP4 0.0.0.0

a=rtcp-fb:111 transport-cc

a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level

a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time

a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01

a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid

a=extmap:5 urn:ietf:params:rtp-hdrext:sdes:rtp-stream-id

a=extmap:6 urn:ietf:params:rtp-hdrext:sdes:repaired-rtp-stream-id

a=setup:actpass

a=mid:0

a=msid:5e19a5cf-32ee-426c-8ee1-51b9985f61ae 90aaa896-bf93-4926-9b75-070da6b8d99c

a=sendrecv

a=ice-ufrag:5h8h

a=ice-pwd:uL4npShrqdRaHxV06sxhu9lk

a=fingerprint:sha-256 0B:4B:CB:E1:3B:48:AF:69:0D:2D:19:66:7F:21:56:A2:D7:99:03:E7:A4:DD:7E:FD:E0:47:6C:A7:07:66:5E:12

a=ice-options:trickle

a=ssrc:2846596914 cname:15oVop0A4+V8aacR

a=ssrc:2846596914 msid:5e19a5cf-32ee-426c-8ee1-51b9985f61ae 90aaa896-bf93-4926-9b75-070da6b8d99c

a=ssrc:2846596914 mslabel:5e19a5cf-32ee-426c-8ee1-51b9985f61ae

a=ssrc:2846596914 label:90aaa896-bf93-4926-9b75-070da6b8d99c

a=rtcp-mux

sip.js?v=1058:9599 Wed Oct 21 2020 11:10:15 GMT+0200 (hora de verano de Europa central) | sip.Transport | Received WebSocket text message:

SIP/2.0 100 Trying

Via: SIP/2.0/WSS a9m6rper574s.invalid;branch=z9hG4bK4686539;received=my.public.ip;rport=48232

From: "w_rcj6yiqvkary_1-bbbID-My User" <sip:w_rcj6yiqvkary_1-bbbID-My%20U...@my.domain.org>;tag=6vq7mm6pbm

To: <sip:echo...@my.domain.org>

Call-ID: iir47qqpfolhjanmpjig

CSeq: 1 INVITE

User-Agent: FreeSWITCH-mod_sofia/1.10.4-release+git~20200805T110119Z~133fc2c870~64bit

Content-Length: 0

sip.js?v=1058:9599 Wed Oct 21 2020 11:10:15 GMT+0200 (hora de verano de Europa central) | sip.Inviter | Inviter.onTrying

sip.js?v=1058:9599 Wed Oct 21 2020 11:10:15 GMT+0200 (hora de verano de Europa central) | sip.Transport | Received WebSocket text message:

SIP/2.0 488 Not Acceptable Here

Via: SIP/2.0/WSS a9m6rper574s.invalid;branch=z9hG4bK4686539;received=my.public.ip;rport=48232

Max-Forwards: 69

From: "w_rcj6yiqvkary_1-bbbID-My User" <sip:w_rcj6yiqvkary_1-bbbID-My%20U...@my.domain.org>;tag=6vq7mm6pbm

To: <sip:echo...@my.domain.org>;tag=NXNSv7e2SSQaF

Call-ID: iir47qqpfolhjanmpjig

CSeq: 1 INVITE

User-Agent: FreeSWITCH-mod_sofia/1.10.4-release+git~20200805T110119Z~133fc2c870~64bit

Accept: application/sdp

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY

Supported: timer, path, replaces

Allow-Events: talk, hold, conference, refer

Reason: Q.850;cause=88;text="INCOMPATIBLE_DESTINATION"

Content-Length: 0

Remote-Party-ID: "echo71162" <sip:echo...@my.domain.org>;party=calling;privacy=off;screen=no

sip.js?v=1058:9599 Wed Oct 21 2020 11:10:15 GMT+0200 (hora de verano de Europa central) | sip.Transport | Sending WebSocket message:

ACK sip:echo...@my.domain.org SIP/2.0

Via: SIP/2.0/WSS a9m6rper574s.invalid;branch=z9hG4bK4686539

To: <sip:echo...@my.domain.org>;tag=NXNSv7e2SSQaF

From: "w_rcj6yiqvkary_1-bbbID-My User" <sip:w_rcj6yiqvkary_1-bbbID-My%20U...@my.domain.org>;tag=6vq7mm6pbm

Call-ID: iir47qqpfolhjanmpjig

CSeq: 1 ACK

Max-Forwards: 70

Content-Length: 0

sip.js?v=1058:9599 Wed Oct 21 2020 11:10:15 GMT+0200 (hora de verano de Europa central) | sip.Inviter | Inviter.onReject

sip.js?v=1058:9599 Wed Oct 21 2020 11:10:15 GMT+0200 (hora de verano de Europa central) | sip.Inviter | Session iir47qqpfolhjanmpjig6vq7mm6pbm transitioned to state Terminated

d3c57d5494122295d6d06c8426cee650e4e1fd44.js?meteor_js_resource=true:9 [11:10:15:0621] ERROR: clientLogger: Audio call terminated. cause=undefined x (https://my.domain.org/html5client/d3c57d5494122295d6d06c8426cee650e4e1fd44.js?meteor_js_resource=true:121:1191744)

d3c57d5494122295d6d06c8426cee650e4e1fd44.js?meteor_js_resource=true:9

Thanks for any advice.

El martes, 20 de octubre de 2020 a las 19:03:16 UTC+2, marioga...@gmail.com escribió:

Mario Gasparoni Junior

unread,

Oct 21, 2020, 9:46:10 AM10/21/20

to bigbluebu...@googlegroups.com

Could you try changing your default stun server ?

You can do that by editing the following value in /usr/share/bbb-web/WEB-INF/classes/spring/turn-stun-servers.xml file:

value="stun:stun.freeswitch.org"

should be replaced by:

value="stun:stun.l.google.com:19302"

Then restart bbb, and see if you still get 1004.

To view this discussion on the web visit https://groups.google.com/d/msgid/bigbluebutton-setup/af00c32f-2177-4bed-b9f0-c1e9f1d57fecn%40googlegroups.com.

Miguel Pellicer

unread,

Oct 21, 2020, 9:51:51 AM10/21/20

to BigBlueButton-Setup

Thank you so much for your help, I can't restart the server right now but I'll try tonight and let you know tomorrow!

Miguel

Miguel Pellicer

unread,

Oct 22, 2020, 10:28:17 AM10/22/20

to BigBlueButton-Setup

Hi Mario, I've applied the change to one of our instances and the test now connects faster, looks like the problem is not happening anymore in that instance (I'm not getting random 1004 without any reason).

I'll keep an eye on the service, thanks for your help.

El miércoles, 21 de octubre de 2020 a las 15:46:10 UTC+2, marioga...@gmail.com escribió:

Mario Gasparoni Junior

unread,

Oct 22, 2020, 10:55:29 AM10/22/20

to bigbluebu...@googlegroups.com

Glad that helps.

To view this discussion on the web visit https://groups.google.com/d/msgid/bigbluebutton-setup/55fe408d-d6c0-4b57-909e-fa092eae3bc0n%40googlegroups.com.

Reply all

Reply to author

Forward

0 new messages