FreeSWITCH Pastebin

opus negotiation problem

From babak yakhchali, 5 Years ago, written in FreeSWITCH.
- view diff
URL https://pastebin.freeswitch.org/view/6faf8a02
Embed
Download Paste or View Raw
  1. recv 1031 bytes from udp/[192.168.80.65]:5060 at 10:25:57.644013:
  2.    ------------------------------------------------------------------------
  3.    INVITE sip:800981234@192.168.80.26:5060 SIP/2.0
  4.    Record-Route: <sip:192.168.80.65;lr;nat=yes;did=8fe.d710efb5>
  5.    Via: SIP/2.0/UDP 192.168.80.65:5060;branch=z9hG4bK773e.16ed8dd7.0
  6.    Via: SIP/2.0/UDP 80.191.36.252:51544;received=80.191.36.252;rport=51544;branch=z9hG4bK16215
  7.    From: <sip:16144444444@192.168.80.65>;tag=15724
  8.    To: <sip:800981234@192.168.80.65>
  9.    Call-ID: 11478
  10.    CSeq: 21 INVITE
  11.    Contact: <sip:16144444444@80.191.36.252:51544>
  12.    Content-Type: application/sdp
  13.    Max-Forwards: 69
  14.    User-Agent: navamessenger
  15.    Subject: This is a call for a conversation
  16.    Content-Length: 433
  17.    P-hint: outbound
  18.  
  19.    v=0
  20.    o=navamessenger 0 0 IN IP4 192.168.80.30
  21.    s=navamessenger
  22.    c=IN IP4 192.168.80.30
  23.    t=0 0
  24.    m=audio 21574 RTP/AVP 107 18 0 8 101
  25.    a=rtpmap:107 opus/48000/2
  26.    a=fmtp:107 maxplaybackrate=48000; sprop-maxcapturerate=48000
  27.    a=ptime:20
  28.    a=maxptime:20
  29.    a=rtpmap:18 G729/8000
  30.    a=fmtp:18 annexb=no
  31.    a=ptime:20
  32.    a=sendrecv
  33.    a=rtpmap:0 PCMU/8000/1
  34.    a=rtpmap:8 PCMA/8000/1
  35.    a=rtpmap:101 telephone-event/8000
  36.    a=fmtp:101 0-15
  37.    a=nortpproxy:yes
  38.    ------------------------------------------------------------------------
  39. 2019-04-30 10:25:57.641516 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/16144444444@192.168.80.65 [3aae4d2b-e731-4929-98ae-0fbb7910e1ec]
  40. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/16144444444@192.168.80.65) Running State Change CS_NEW (Cur 1 Tot 6506)
  41. 2019-04-30 10:25:57.641516 [DEBUG] sofia.c:10092 sofia/internal/16144444444@192.168.80.65 receiving invite from 192.168.80.65:5060 version: 1.8.4 git 749a6e1 2018-12-27 01:10:58Z 64bit
  42. 2019-04-30 10:25:57.641516 [DEBUG] sofia.c:7291 Channel sofia/internal/16144444444@192.168.80.65 entering state [received][100]
  43. 2019-04-30 10:25:57.641516 [DEBUG] sofia.c:7301 Remote SDP:
  44. v=0
  45. o=navamessenger 0 0 IN IP4 192.168.80.30
  46. s=navamessenger
  47. c=IN IP4 192.168.80.30
  48. t=0 0
  49. m=audio 21574 RTP/AVP 107 18 0 8 101
  50. a=rtpmap:107 opus/48000/2
  51. a=fmtp:107 maxplaybackrate=48000; sprop-maxcapturerate=48000
  52. a=rtpmap:18 G729/8000
  53. a=fmtp:18 annexb=no
  54. a=rtpmap:0 PCMU/8000/1
  55. a=rtpmap:8 PCMA/8000/1
  56. a=rtpmap:101 telephone-event/8000
  57. a=fmtp:101 0-15
  58. a=ptime:20
  59. a=maxptime:20
  60. a=ptime:20
  61. a=nortpproxy:yes
  62.  
  63. 2019-04-30 10:25:57.641516 [DEBUG] sofia.c:7695 (sofia/internal/16144444444@192.168.80.65) State Change CS_NEW -> CS_INIT
  64. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/16144444444@192.168.80.65) State NEW
  65. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/16144444444@192.168.80.65) Running State Change CS_INIT (Cur 1 Tot 6506)
  66. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/16144444444@192.168.80.65) State INIT
  67. 2019-04-30 10:25:57.641516 [DEBUG] mod_sofia.c:93 sofia/internal/16144444444@192.168.80.65 SOFIA INIT
  68. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:40 sofia/internal/16144444444@192.168.80.65 Standard INIT
  69. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/16144444444@192.168.80.65) State Change CS_INIT -> CS_ROUTING
  70. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/16144444444@192.168.80.65) State INIT going to sleep
  71. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/16144444444@192.168.80.65) Running State Change CS_ROUTING (Cur 1 Tot 6506)
  72. 2019-04-30 10:25:57.641516 [DEBUG] switch_channel.c:2249 (sofia/internal/16144444444@192.168.80.65) Callstate Change DOWN -> RINGING
  73. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/16144444444@192.168.80.65) State ROUTING
  74. 2019-04-30 10:25:57.641516 [DEBUG] mod_sofia.c:154 sofia/internal/16144444444@192.168.80.65 SOFIA ROUTING
  75. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:236 sofia/internal/16144444444@192.168.80.65 Standard ROUTING
  76. 2019-04-30 10:25:57.641516 [INFO] mod_dialplan_xml.c:637 Processing 16144444444 <16144444444>->800981234 in context sgas
  77. send 303 bytes to udp/[192.168.80.65]:5060 at 10:25:57.647334:
  78.    ------------------------------------------------------------------------
  79.    SIP/2.0 100 Trying
  80.    Via: SIP/2.0/UDP 192.168.80.65:5060;branch=z9hG4bK773e.16ed8dd7.0
  81.    From: <sip:16144444444@192.168.80.65>;tag=15724
  82.    To: <sip:800981234@192.168.80.65>
  83.    Call-ID: 11478
  84.    CSeq: 21 INVITE
  85.    User-Agent: FreeSWITCH-mod_sofia/1.8.4+git~20181227T011058Z~749a6e108b~64bit
  86.    Content-Length: 0
  87.  
  88.    ------------------------------------------------------------------------
  89. Dialplan: sofia/internal/16144444444@192.168.80.65 parsing [sgas->park] continue=false
  90. Dialplan: sofia/internal/16144444444@192.168.80.65 Regex (FAIL) [park] destination_number(800981234) =~ /^park$/ break=on-false
  91. Dialplan: sofia/internal/16144444444@192.168.80.65 parsing [sgas->park] continue=false
  92. Dialplan: sofia/internal/16144444444@192.168.80.65 Regex (FAIL) [park] destination_number(800981234) =~ /^hold|999$/ break=on-false
  93. Dialplan: sofia/internal/16144444444@192.168.80.65 parsing [sgas->add-to-conf] continue=false
  94. Dialplan: sofia/internal/16144444444@192.168.80.65 Regex (FAIL) [add-to-conf] destination_number(800981234) =~ /^add_to_conf$/ break=on-false
  95. Dialplan: sofia/internal/16144444444@192.168.80.65 parsing [sgas->conf] continue=false
  96. Dialplan: sofia/internal/16144444444@192.168.80.65 Regex (FAIL) [conf] destination_number(800981234) =~ /^conf-(.*)$/ break=on-false
  97. Dialplan: sofia/internal/16144444444@192.168.80.65 parsing [sgas->nava-rec] continue=false
  98. Dialplan: sofia/internal/16144444444@192.168.80.65 Regex (FAIL) [nava-rec] destination_number(800981234) =~ /^800980000$/ break=on-false
  99. Dialplan: sofia/internal/16144444444@192.168.80.65 parsing [sgas->nava-conf] continue=false
  100. Dialplan: sofia/internal/16144444444@192.168.80.65 Regex (PASS) [nava-conf] destination_number(800981234) =~ /^800981234$/ break=on-false
  101. Dialplan: sofia/internal/16144444444@192.168.80.65 Action conference(test)
  102. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/16144444444@192.168.80.65) State Change CS_ROUTING -> CS_EXECUTE
  103. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/16144444444@192.168.80.65) State ROUTING going to sleep
  104. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/16144444444@192.168.80.65) Running State Change CS_EXECUTE (Cur 1 Tot 6506)
  105. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/16144444444@192.168.80.65) State EXECUTE
  106. 2019-04-30 10:25:57.641516 [DEBUG] mod_sofia.c:209 sofia/internal/16144444444@192.168.80.65 SOFIA EXECUTE
  107. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_state_machine.c:328 sofia/internal/16144444444@192.168.80.65 Standard EXECUTE
  108. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_session.c:2710 Application conference Requires media! pre_answering channel sofia/internal/16144444444@192.168.80.65
  109. 2019-04-30 10:25:57.641516 [INFO] switch_core_session.c:2712 Sending early media
  110. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:107:48000:20:0:1]/[opus:116:48000:20:0:1]
  111. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
  112. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:107:48000:20:0:1]/[G729:18:8000:20:8000:1]
  113. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:107:48000:20:0:1]/[G722:9:8000:20:64000:1]
  114. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:107:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
  115. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [opus:107:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
  116. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[opus:116:48000:20:0:1]
  117. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
  118. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
  119. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[G722:9:8000:20:64000:1]
  120. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
  121. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
  122. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
  123. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1]
  124. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  125. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  126. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  127. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  128. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
  129. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1]
  130. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
  131. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  132. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5478 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  133. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5533 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  134. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5394 Set telephone-event payload to 101@8000
  135. 2019-04-30 10:25:57.641516 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [72000bps]
  136. 2019-04-30 10:25:57.641516 [DEBUG] mod_opus.c:636 Opus encoder: CBR mode enabled
  137. 2019-04-30 10:25:57.641516 [DEBUG] mod_opus.c:617 Opus encoder: set bitrate to local settings [72000bps]
  138. 2019-04-30 10:25:57.641516 [DEBUG] mod_opus.c:636 Opus encoder: CBR mode enabled
  139. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:3781 Set Codec sofia/internal/16144444444@192.168.80.65 opus/48000 20 ms 960 samples 0 bits 1 channels
  140. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_codec.c:111 sofia/internal/16144444444@192.168.80.65 Original read codec set to opus:116
  141. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:5795 sofia/internal/16144444444@192.168.80.65 Set 2833 dtmf send payload to 101 recv payload to 101
  142. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:8511 AUDIO RTP [sofia/internal/16144444444@192.168.80.65] 192.168.80.26 port 20102 -> 192.168.80.30 port 21574 codec: 107 ms: 20
  143. 2019-04-30 10:25:57.641516 [DEBUG] switch_rtp.c:4300 Starting timer [soft] 960 bytes per 20ms
  144. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:8815 sofia/internal/16144444444@192.168.80.65 Set 2833 dtmf send payload to 101
  145. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:8822 sofia/internal/16144444444@192.168.80.65 Set 2833 dtmf receive payload to 101
  146. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:8845 sofia/internal/16144444444@192.168.80.65 Set rtp dtmf delay to 40
  147. 2019-04-30 10:25:57.641516 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/16144444444@192.168.80.65!
  148. 2019-04-30 10:25:57.641516 [DEBUG] switch_channel.c:3482 (sofia/internal/16144444444@192.168.80.65) Callstate Change RINGING -> EARLY
  149. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:8494 Audio params are unchanged for sofia/internal/16144444444@192.168.80.65.
  150. 2019-04-30 10:25:57.641516 [DEBUG] mod_sofia.c:2504 Ring SDP:
  151. v=0
  152. o=FreeSWITCH 1556583655 1556583656 IN IP4 192.168.80.26
  153. s=FreeSWITCH
  154. c=IN IP4 192.168.80.26
  155. t=0 0
  156. m=audio 20102 RTP/AVP 107 101
  157. a=rtpmap:107 opus/48000/2
  158. a=fmtp:107 useinbandfec=1; cbr=1
  159. a=rtpmap:101 telephone-event/8000
  160. a=fmtp:101 0-16
  161. a=ptime:20
  162. a=sendrecv
  163.  
  164. EXECUTE sofia/internal/16144444444@192.168.80.65 conference(test)
  165. send 1308 bytes to udp/[192.168.80.65]:5060 at 10:25:57.652760:
  166.    ------------------------------------------------------------------------
  167.    SIP/2.0 183 Session Progress
  168.    Via: SIP/2.0/UDP 192.168.80.65:5060;branch=z9hG4bK773e.16ed8dd7.0
  169.    Via: SIP/2.0/UDP 80.191.36.252:51544;received=80.191.36.252;rport=51544;branch=z9hG4bK16215
  170.    Record-Route: <sip:192.168.80.65;lr;nat=yes;did=8fe.d710efb5>
  171.    From: <sip:16144444444@192.168.80.65>;tag=15724
  172.    To: <sip:800981234@192.168.80.65>;tag=1KtDvQQgUy9vD
  173.    Call-ID: 11478
  174.    CSeq: 21 INVITE
  175.    Contact: <sip:800981234@192.168.80.26:5060;transport=udp>
  176.    User-Agent: FreeSWITCH-mod_sofia/1.8.4+git~20181227T011058Z~749a6e108b~64bit
  177.    Accept: application/sdp
  178.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  179.    Supported: timer, path, replaces
  180.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
  181.    Content-Type: application/sdp
  182.    Content-Disposition: session
  183.    Content-Length: 263
  184.    Remote-Party-ID: "800981234" <sip:800981234@192.168.80.65>;party=calling;privacy=off;screen=no
  185.  
  186.    v=0
  187.    o=FreeSWITCH 1556583655 1556583656 IN IP4 192.168.80.26
  188.    s=FreeSWITCH
  189.    c=IN IP4 192.168.80.26
  190.    t=0 0
  191.    m=audio 20102 RTP/AVP 107 101
  192.    a=rtpmap:107 opus/48000/2
  193.    a=fmtp:107 useinbandfec=1; cbr=1
  194.    a=rtpmap:101 telephone-event/8000
  195.    a=fmtp:101 0-16
  196.    a=ptime:20
  197.    ------------------------------------------------------------------------
  198. 2019-04-30 10:25:57.641516 [DEBUG] sofia.c:7291 Channel sofia/internal/16144444444@192.168.80.65 entering state [early][183]
  199. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_media.c:8494 Audio params are unchanged for sofia/internal/16144444444@192.168.80.65.
  200. 2019-04-30 10:25:57.641516 [DEBUG] mod_sofia.c:881 Local SDP sofia/internal/16144444444@192.168.80.65:
  201. v=0
  202. o=FreeSWITCH 1556583655 1556583657 IN IP4 192.168.80.26
  203. s=FreeSWITCH
  204. c=IN IP4 192.168.80.26
  205. t=0 0
  206. m=audio 20102 RTP/AVP 107 101
  207. a=rtpmap:107 opus/48000/2
  208. a=fmtp:107 useinbandfec=1; cbr=1
  209. a=rtpmap:101 telephone-event/8000
  210. a=fmtp:101 0-16
  211. a=ptime:20
  212. a=sendrecv
  213.  
  214. send 1277 bytes to udp/[192.168.80.65]:5060 at 10:25:57.653931:
  215.    ------------------------------------------------------------------------
  216.    SIP/2.0 200 OK
  217.    Via: SIP/2.0/UDP 192.168.80.65:5060;branch=z9hG4bK773e.16ed8dd7.0
  218.    Via: SIP/2.0/UDP 80.191.36.252:51544;received=80.191.36.252;rport=51544;branch=z9hG4bK16215
  219.    Record-Route: <sip:192.168.80.65;lr;nat=yes;did=8fe.d710efb5>
  220.    From: <sip:16144444444@192.168.80.65>;tag=15724
  221.    To: <sip:800981234@192.168.80.65>;tag=1KtDvQQgUy9vD
  222.    Call-ID: 11478
  223.    CSeq: 21 INVITE
  224.    Contact: <sip:800981234@192.168.80.26:5060;transport=udp>;isfocus
  225.    User-Agent: FreeSWITCH-mod_sofia/1.8.4+git~20181227T011058Z~749a6e108b~64bit
  226.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  227.    Supported: timer, path, replaces
  228.    Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
  229.    Content-Type: application/sdp
  230.    Content-Disposition: session
  231.    Content-Length: 263
  232.    Remote-Party-ID: "800981234" <sip:800981234@192.168.80.65>;party=calling;privacy=off;screen=no
  233.  
  234.    v=0
  235.    o=FreeSWITCH 1556583655 1556583656 IN IP4 192.168.80.26
  236.    s=FreeSWITCH
  237.    c=IN IP4 192.168.80.26
  238.    t=0 0
  239.    m=audio 20102 RTP/AVP 107 101
  240.    a=rtpmap:107 opus/48000/2
  241. 2019-04-30 10:25:57.641516 [NOTICE] mod_conference.c:1885 Channel [sofia/internal/16144444444@192.168.80.65] has been answered
  242.    a=fmtp:107 useinbandfec=1; cbr=1
  243.    a=rtpmap:101 telephone-event/8000
  244.    a=fmtp:101 0-16
  245.    a=ptime:20
  246.    ------------------------------------------------------------------------
  247. 2019-04-30 10:25:57.641516 [DEBUG] switch_channel.c:3781 (sofia/internal/16144444444@192.168.80.65) Callstate Change EARLY -> ACTIVE
  248. 2019-04-30 10:25:57.641516 [DEBUG] sofia.c:7291 Channel sofia/internal/16144444444@192.168.80.65 entering state [completed][200]
  249. 2019-04-30 10:25:57.641516 [DEBUG] mod_conference.c:3384 using channel sound prefix: /usr/local/freeswitch/sounds/en/us/callie
  250. 2019-04-30 10:25:57.641516 [DEBUG] conference_member.c:1758 Raw Codec Activation Success L16@48000hz 1 channel 20ms
  251. 2019-04-30 10:25:57.641516 [DEBUG] mod_conference.c:233 Setup timer success interval: 20  samples: 160
  252. 2019-04-30 10:25:57.641516 [DEBUG] conference_member.c:1805 Raw Codec Activation Success L16@8000hz 1 channel 20ms
  253. 2019-04-30 10:25:57.641516 [DEBUG] switch_core_codec.c:223 sofia/internal/16144444444@192.168.80.65 Push codec L16:100
  254. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '0' to 'mute'
  255. 2019-04-30 10:25:57.661517 [INFO] switch_ivr_async.c:219 Digit parser mod_conference: Setting realm to 'conf'
  256. 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 0/conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b03e8
  257. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '*' to 'deaf mute'
  258. 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding */conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b0418
  259. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '9' to 'energy up'
  260. 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 9/conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b0448
  261. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '8' to 'energy equ'
  262. 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 8/conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b0478
  263. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '7' to 'energy dn'
  264. 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 7/conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b04a8
  265. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '3' to 'vol talk up'
  266. 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 3/conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b04d8
  267. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '2' to 'vol talk zero'
  268. 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 2/conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b0508
  269. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '1' to 'vol talk dn'
  270. 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 1/conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b0538
  271. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '6' to 'vol listen up'
  272. 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 6/conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b0568
  273. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '5' to 'vol listen zero'
  274. 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 5/conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b0598
  275. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '4' to 'vol listen dn'
  276. 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding 4/conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b05c8
  277. 2019-04-30 10:25:57.661517 [DEBUG] conference_member.c:105 sofia/internal/16144444444@192.168.80.65 binding '#' to 'hangup'
  278. span style="color: goldenrod; font-weight: bold;"> 2019-04-30 10:25:57.661517 [DEBUG] switch_ivr_async.c:344 Digit parser mod_conference: binding #/conf/0 callback: 0x7fa8b50e21c0 data: 0x7fa8402b05f8
  279. span style="color: goldenrod; font-weight: bold;"> 2019-04-30 10:25:57.661517 [DEBUG] conference_loop.c:1334 Setup timer soft success interval: 20  samples: 960 from codec opus
  280. 2019-04-30 10:25:57.661517 [DEBUG] mod_local_stream.c:907 Opening Stream [moh/8000] 8000hz
  281. 2019-04-30 10:25:57.681509 [NOTICE] switch_core_media.c:15578 Activating write resampler
  282. 2019-04-30 10:25:57.881529 [DEBUG] conference_member.c:1758 Raw Codec Activation Success L16@48000hz 1 channel 20ms
  283. 2019-04-30 10:25:57.881529 [DEBUG] conference_member.c:1805 Raw Codec Activation Success L16@8000hz 1 channel 20ms
  284. 2019-04-30 10:25:57.881529 [DEBUG] conference_loop.c:1334 Setup timer soft success interval: 20  samples: 960 from codec opus
  285. recv 740 bytes from udp/[192.168.80.65]:5060 at 10:25:57.962387:
  286.    ------------------------------------------------------------------------
  287.    ACK sip:800981234@192.168.80.26:5060;transport=udp SIP/2.0
  288.    Via: SIP/2.0/UDP 192.168.80.65:5060;branch=z9hG4bK773e.16ed8dd7.2
  289.    Via: SIP/2.0/UDP 80.191.36.252:51544;received=80.191.36.252;rport=51544;branch=z9hG4bK31547
  290.    From: <sip:16144444444@192.168.80.65>;tag=15724
  291.    To: <sip:800981234@192.168.80.65>;tag=1KtDvQQgUy9vD
  292.    Call-ID: 11478
  293.    CSeq: 21 ACK
  294.    Contact: <sip:16144444444@80.191.36.252:51544>
  295.    Proxy-Authorization: Digest username="16144444444", realm="192.168.80.65", nonce="5cc7e38b0000e67c7cdb6a068b832a3d08e2715e0d147afd", uri="sip:800981234@192.168.80.40:5060", response="328513d9102634924edcb49646e32031", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000001
  296.    Max-Forwards: 69
  297.    User-Agent: navamessenger
  298.    Content-Length: 0
  299.  
  300.    ------------------------------------------------------------------------
  301. 2019-04-30 10:25:57.961579 [DEBUG] sofia.c:7291 Channel sofia/internal/16144444444@192.168.80.65 entering state [ready][200]
  302. 2019-04-30 10:25:58.101569 [DEBUG] switch_rtp.c:7550 Correct audio ip/port confirmed.
  303. recv 715 bytes from udp/[192.168.80.65]:5060 at 10:26:03.644411:
  304.    ------------------------------------------------------------------------
  305.    BYE sip:800981234@192.168.80.26:5060;transport=udp SIP/2.0
  306.    Via: SIP/2.0/UDP 192.168.80.65:5060;branch=z9hG4bK473e.b18ae6d1.0
  307.    Via: SIP/2.0/UDP 80.191.36.252:51544;received=80.191.36.252;rport=51544;branch=z9hG4bK26962
  308.    From: <sip:16144444444@192.168.80.65>;tag=15724
  309.    To: <sip:800981234@192.168.80.65>;tag=1KtDvQQgUy9vD
  310.    Call-ID: 11478
  311.    CSeq: 22 BYE
  312.    Proxy-Authorization: Digest username="16144444444", realm="192.168.80.65", nonce="5cc7e38b0000e67c7cdb6a068b832a3d08e2715e0d147afd", uri="sip:800981234@192.168.80.40:49263;transport=udp;nat=yes", response="80bd7bdd075fd33cb0234defe0c2ce01", algorithm=MD5, cnonce="0a4f113b", qop=auth, nc=00000002
  313.    Max-Forwards: 69
  314.    User-Agent: navamessenger
  315.    Content-Length: 0
  316.  
  317.    ------------------------------------------------------------------------
  318. 2019-04-30 10:26:03.641566 [NOTICE] sofia.c:1079 Hangup sofia/internal/16144444444@192.168.80.65 [CS_EXECUTE] [NORMAL_CLEARING]
  319. send 551 bytes to udp/[192.168.80.65]:5060 at 10:26:03.653086:
  320.    ------------------------------------------------------------------------
  321.    SIP/2.0 200 OK
  322.    Via: SIP/2.0/UDP 192.168.80.65:5060;branch=z9hG4bK473e.b18ae6d1.0
  323.    Via: SIP/2.0/UDP 80.191.36.252:51544;received=80.191.36.252;rport=51544;branch=z9hG4bK26962
  324.    From: <sip:16144444444@192.168.80.65>;tag=15724
  325.    To: <sip:800981234@192.168.80.65>;tag=1KtDvQQgUy9vD
  326.    Call-ID: 11478
  327.    CSeq: 22 BYE
  328.    User-Agent: FreeSWITCH-mod_sofia/1.8.4+git~20181227T011058Z~749a6e108b~64bit
  329.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
  330.    Supported: timer, path, replaces
  331.    Content-Length: 0
  332.  
  333.    ------------------------------------------------------------------------
  334. 2019-04-30 10:26:03.661518 [INFO] conference_loop.c:1670 Channel leaving conference, cause: NORMAL_CLEARING
  335. 2019-04-30 10:26:03.661518 [DEBUG] mod_conference.c:2467 sofia/internal/16144444444@192.168.80.65 skip receive message [UNBRIDGE] (channel is hungup already)
  336. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_media.c:12213 sofia/internal/16144444444@192.168.80.65 skip receive message [HARD_MUTE] (channel is hungup already)
  337. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_codec.c:260 Restore original codec.
  338. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_session.c:2887 sofia/internal/16144444444@192.168.80.65 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
  339. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/16144444444@192.168.80.65) State EXECUTE going to sleep
  340. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/16144444444@192.168.80.65) Running State Change CS_HANGUP (Cur 1 Tot 6506)
  341. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/16144444444@192.168.80.65) Callstate Change ACTIVE -> HANGUP
  342. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/16144444444@192.168.80.65) State HANGUP
  343. 2019-04-30 10:26:03.661518 [DEBUG] mod_sofia.c:449 Channel sofia/internal/16144444444@192.168.80.65 hanging up, cause: NORMAL_CLEARING
  344. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:60 sofia/internal/16144444444@192.168.80.65 Standard HANGUP, cause: NORMAL_CLEARING
  345. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/16144444444@192.168.80.65) State HANGUP going to sleep
  346. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/16144444444@192.168.80.65) State Change CS_HANGUP -> CS_REPORTING
  347. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/16144444444@192.168.80.65) Running State Change CS_REPORTING (Cur 1 Tot 6506)
  348. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/16144444444@192.168.80.65) State REPORTING
  349. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:174 sofia/internal/16144444444@192.168.80.65 Standard REPORTING, cause: NORMAL_CLEARING
  350. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/16144444444@192.168.80.65) State REPORTING going to sleep
  351. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/16144444444@192.168.80.65) State Change CS_REPORTING -> CS_DESTROY
  352. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_session.c:1715 Session 6506 (sofia/internal/16144444444@192.168.80.65) Locked, Waiting on external entities
  353. 2019-04-30 10:26:03.661518 [NOTICE] switch_core_session.c:1733 Session 6506 (sofia/internal/16144444444@192.168.80.65) Ended
  354. 2019-04-30 10:26:03.661518 [NOTICE] switch_core_session.c:1737 Close Channel sofia/internal/16144444444@192.168.80.65 [CS_DESTROY]
  355. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/16144444444@192.168.80.65) Running State Change CS_DESTROY (Cur 0 Tot 6506)
  356. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/16144444444@192.168.80.65) State DESTROY
  357. 2019-04-30 10:26:03.661518 [DEBUG] mod_sofia.c:354 sofia/internal/16144444444@192.168.80.65 SOFIA DESTROY
  358. 2019-04-30 10:26:03.661518 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[265] PLC[0] FEC[0]
  359. 2019-04-30 10:26:03.661518 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
  360. 2019-04-30 10:26:03.661518 [DEBUG] mod_opus.c:725 Opus decoder stats: Frames[0] PLC[0] FEC[0]
  361. 2019-04-30 10:26:03.661518 [DEBUG] mod_opus.c:740 Opus encoder stats: Frames[298] Bytes encoded[38144] Encoded length ms[5960] Average encoded bitrate bps[61030]
  362. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:181 sofia/internal/16144444444@192.168.80.65 Standard DESTROY
  363. 2019-04-30 10:26:03.661518 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/16144444444@192.168.80.65) State DESTROY going to sleep
  364. 2019-04-30 10:26:03.661518 [DEBUG] mod_conference.c:833 Write Lock ON
  365. 2019-04-30 10:26:03.661518 [DEBUG] mod_conference.c:836 Write Lock OFF
  366.  

Reply to "opus negotiation problem"