FreeSWITCH Pastebin

verto2pstn via CUCM call - no media

From River Hume, 4 Years ago, written in Plain Text.
- go back
URL https://pastebin.freeswitch.org/view/55db211d
Embed
Viewing differences between and verto2pstn via CUCM call - no media
  1. note: outbound route is through a Cisco PBX (CUCM) but same errors appear in verto-to-verto call (https://pastebin.freeswitch.org/view/e54c7f90)
  2.  
  3. 2020-02-10 19:56:34.418742 [NOTICE] switch_channel.c:1118 New Channel sofia/Localnet/917072057979 [52bba2c4-d387-4770-8e86-4588443efaf3]
  4. 2020-02-10 19:56:34.418742 [DEBUG] mod_sofia.c:5096 (sofia/Localnet/917072057979) State Change CS_NEW -> CS_INIT
  5. 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:585 (sofia/Localnet/917072057979) Running State Change CS_INIT (Cur 2 Tot 12)
  6. 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:628 (sofia/Localnet/917072057979) State INIT
  7. 2020-02-10 19:56:34.418742 [DEBUG] mod_sofia.c:93 sofia/Localnet/917072057979 SOFIA INIT
  8. 2020-02-10 19:56:34.418742 [DEBUG] sofia_glue.c:1618 sofia/Localnet/917072057979 sending invite version: 1.10.1 -release-12-f9990221e6 64bit
  9. Local SDP:
  10. v=0
  11. o=FreeSWITCH 1581347046 1581347047 IN IP4 172.20.253.46
  12. s=FreeSWITCH
  13. c=IN IP4 172.20.253.46
  14. t=0 0
  15. m=audio 17548 RTP/AVP 0 101 13
  16. a=rtpmap:0 PCMU/8000
  17. a=rtpmap:101 telephone-event/8000
  18. a=fmtp:101 0-16
  19. a=rtpmap:13 CN/8000
  20. a=ptime:20
  21. a=sendrecv
  22.  
  23. 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:40 sofia/Localnet/917072057979 Standard INIT
  24. 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:48 (sofia/Localnet/917072057979) State Change CS_INIT -> CS_ROUTING
  25. 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:628 (sofia/Localnet/917072057979) State INIT going to sleep
  26. 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:585 (sofia/Localnet/917072057979) Running State Change CS_ROUTING (Cur 2 Tot 12)
  27. 2020-02-10 19:56:34.418742 [DEBUG] sofia.c:7290 Channel sofia/Localnet/917072057979 entering state [calling][0]
  28. 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:644 (sofia/Localnet/917072057979) State ROUTING
  29. 2020-02-10 19:56:34.418742 [DEBUG] mod_sofia.c:154 sofia/Localnet/917072057979 SOFIA ROUTING
  30. 2020-02-10 19:56:34.418742 [DEBUG] switch_ivr_originate.c:67 (sofia/Localnet/917072057979) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  31. 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:644 (sofia/Localnet/917072057979) State ROUTING going to sleep
  32. 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:585 (sofia/Localnet/917072057979) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 12)
  33. 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:663 (sofia/Localnet/917072057979) State CONSUME_MEDIA
  34. 2020-02-10 19:56:34.418742 [DEBUG] switch_core_state_machine.c:663 (sofia/Localnet/917072057979) State CONSUME_MEDIA going to sleep
  35. 2020-02-10 19:56:34.478740 [INFO] sofia.c:1364 sofia/Localnet/917072057979 Update Callee ID to "7072057979" <17072057979>
  36. 2020-02-10 19:56:34.478740 [DEBUG] sofia.c:7290 Channel sofia/Localnet/917072057979 entering state [proceeding][183]
  37. 2020-02-10 19:56:34.478740 [DEBUG] sofia.c:7300 Remote SDP:
  38. v=0
  39. o=CiscoSystemsCCM-SIP 12412155 1 IN IP4 10.0.20.27
  40. s=SIP Call
  41. c=IN IP4 10.0.20.27
  42. b=TIAS:64000
  43. b=CT:64
  44. b=AS:64
  45. t=0 0
  46. m=audio 30076 RTP/AVP 0 101
  47. a=rtpmap:0 PCMU/8000
  48. a=rtpmap:101 telephone-event/8000
  49. a=fmtp:101 0-15
  50. a=ptime:20
  51.  
  52. 2020-02-10 19:56:34.478740 [NOTICE] sofia.c:7303 Pre-Answer sofia/Localnet/917072057979!
  53. 2020-02-10 19:56:34.478740 [DEBUG] switch_channel.c:3565 (sofia/Localnet/917072057979) Callstate Change DOWN -> EARLY
  54. 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  55. 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  56. 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:5506 Set telephone-event payload to 101@8000
  57. 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:3834 Set Codec sofia/Localnet/917072057979 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
  58. 2020-02-10 19:56:34.478740 [DEBUG] switch_core_codec.c:111 sofia/Localnet/917072057979 Original read codec set to PCMU:0
  59. 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:5849 Set telephone-event payload to 101@8000
  60. 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:5907 sofia/Localnet/917072057979 Set 2833 dtmf send payload to 101 recv payload to 101
  61. 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:8658 AUDIO RTP [sofia/Localnet/917072057979] 172.20.253.46 port 17548 -> 10.0.20.27 port 30076 codec: 0 ms: 20
  62. 2020-02-10 19:56:34.478740 [DEBUG] switch_rtp.c:4408 Starting timer [soft] 160 bytes per 20ms
  63. 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:8972 sofia/Localnet/917072057979 Set 2833 dtmf send payload to 101
  64. 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:8979 sofia/Localnet/917072057979 Set 2833 dtmf receive payload to 101
  65. 2020-02-10 19:56:34.478740 [DEBUG] switch_core_media.c:9002 sofia/Localnet/917072057979 Set rtp dtmf delay to 40
  66. 2020-02-10 19:56:34.498742 [DEBUG] switch_ivr_originate.c:436 Setting codec string on verto.rtc/7072057979 to PCMU@8000h@20i
  67. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [opus:111:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
  68. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1]
  69. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1]
  70. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  71. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  72. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5645 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  73. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  74. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [CN:106:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
  75. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [CN:105:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
  76. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5590 Audio Codec Compare [CN:13:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
  77. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5506 Set telephone-event payload to 110@48000
  78. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:3834 Set Codec verto.rtc/7072057979 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
  79. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_codec.c:111 verto.rtc/7072057979 Original read codec set to PCMU:0
  80. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4279 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.203.1:52162
  81. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4279 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.11.4:52163
  82. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4279 Save audio Candidate cid: 1 proto: udp type: srflx addr: 47.208.143.73:52163
  83. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4324 Searching for rtp candidate.
  84. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4333 Choose rtp candidate, index 2, 47.208.143.73:52163
  85. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4099 verto.rtc/7072057979 choosing family v4
  86. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4344 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 47.208.143.73:52163
  87. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4396 setting remote audio ice addr to index 2 47.208.143.73:52163 based on candidate
  88. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:4431 Setting remote rtcp audio addr to 47.208.143.73:52163 based on candidate
  89. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5849 Set telephone-event payload to 126@8000
  90. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:5907 verto.rtc/7072057979 Set 2833 dtmf send payload to 126 recv payload to 126
  91.  
  92.  
  93.  
  94. 2020-02-10 19:56:34.498742 [CRIT] switch_channel.c:1484 Invalid data (${advertised_media_ip} contains a variable)
  95. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:8658 AUDIO RTP [verto.rtc/7072057979] 172.20.253.46 port 31858 -> 47.208.143.73 port 52163 codec: 0 ms: 20
  96. 2020-02-10 19:56:34.498742 [CRIT] switch_channel.c:1484 Invalid data (${advertised_media_ip} contains a variable)
  97.  
  98.  
  99. 2020-02-10 19:56:34.498742 [DEBUG] switch_rtp.c:4408 Starting timer [soft] 160 bytes per 20ms
  100. 2020-02-10 19:56:34.498742 [INFO] switch_core_media.c:8840 Activating Audio ICE
  101. 2020-02-10 19:56:34.498742 [NOTICE] switch_rtp.c:4910 Activating RTP audio ICE: MEso:E49jHpieyRDYDTvy 47.208.143.73:52163
  102. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:8880 Activating RTCP PORT 52163
  103. 2020-02-10 19:56:34.498742 [DEBUG] switch_rtp.c:4806 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 52163
  104. 2020-02-10 19:56:34.498742 [INFO] switch_core_media.c:8891 Skipping RTCP ICE (Same as RTP)
  105. 2020-02-10 19:56:34.498742 [INFO] switch_rtp.c:3736 Activate RTP/RTCP audio DTLS client
  106. 2020-02-10 19:56:34.498742 [INFO] switch_rtp.c:3903 Changing audio DTLS state from OFF to HANDSHAKE
  107. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:2549 Setting Jitterbuffer to 20ms (1 frames) (50 max frames)
  108. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:8972 verto.rtc/7072057979 Set 2833 dtmf send payload to 126
  109. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:8979 verto.rtc/7072057979 Set 2833 dtmf receive payload to 126
  110.  
  111. 2020-02-10 19:56:34.498742 [CRIT] switch_channel.c:1484 Invalid data (${rtp_local_sdp_str} contains a variable)
  112.  
  113.  
  114. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:8640 Audio params are unchanged for verto.rtc/7072057979.
  115. 2020-02-10 19:56:34.498742 [DEBUG] mod_verto.c:2519 Local SDP verto.rtc/7072057979:
  116. v=0
  117. o=FreeSWITCH 1581332736 1581332737 IN IP4 ${external_rtp_ip}
  118. s=FreeSWITCH
  119. c=IN IP4 ${external_rtp_ip}
  120. t=0 0
  121. a=msid-semantic: WMS ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH
  122. m=audio 31858 UDP/TLS/RTP/SAVPF 0 126
  123. a=rtpmap:0 PCMU/8000
  124. a=rtpmap:126 telephone-event/8000
  125. a=silenceSupp:off - - - -
  126. a=ptime:20
  127. a=sendrecv
  128. a=fingerprint:sha-256 96:E9:38:23:96:4C:07:4E:61:4F:80:B7:05:E6:BE:BA:04:CA:F3:69:B6:90:E0:43:59:AD:F1:A9:4B:D1:57:C3
  129. a=setup:active
  130. a=rtcp-mux
  131. a=rtcp:31858 IN IP4 ${external_rtp_ip}
  132. a=ice-ufrag:E49jHpieyRDYDTvy
  133. a=ice-pwd:seWjQmYFvVt02UlxPlHnAPrZ
  134. a=candidate:9727255544 1 udp 659136 ${external_rtp_ip} 31858 typ host generation 0
  135. a=end-of-candidates
  136. a=ssrc:3447296298 cname:5JSy0MzPYj6YEhAu
  137. a=ssrc:3447296298 msid:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH a0
  138. a=ssrc:3447296298 mslabel:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH
  139. a=ssrc:3447296298 label:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqHa0
  140.  
  141. 2020-02-10 19:56:34.498742 [NOTICE] switch_ivr_originate.c:3755 Pre-Answer verto.rtc/7072057979!
  142. 2020-02-10 19:56:34.498742 [DEBUG] switch_channel.c:3565 (verto.rtc/7072057979) Callstate Change RINGING -> EARLY
  143. 2020-02-10 19:56:34.498742 [DEBUG] switch_ivr_originate.c:3806 Originate Resulted in Success: [sofia/Localnet/917072057979]
  144. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_media.c:12806 verto.rtc/7072057979 PAUSE Jitterbuffer
  145. 2020-02-10 19:56:34.498742 [DEBUG] switch_ivr_bridge.c:1794 (sofia/Localnet/917072057979) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
  146. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_state_machine.c:585 (sofia/Localnet/917072057979) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 12)
  147. 2020-02-10 19:56:34.498742 [DEBUG] switch_core_state_machine.c:654 (sofia/Localnet/917072057979) State EXCHANGE_MEDIA
  148. 2020-02-10 19:56:34.498742 [DEBUG] mod_sofia.c:663 SOFIA EXCHANGE_MEDIA
  149. 2020-02-10 19:56:34.538739 [DEBUG] mod_verto.c:607 WRITE 47.208.143.73:53106 [{
  150.         "jsonrpc":      "2.0",
  151.         "id":   12,
  152.         "method":       "verto.media",
  153.         "params":       {
  154.                 "callID":       "7088e146-6b2f-2f4b-e970-f12e7a80d7bb",
  155.                 "sdp":  "v=0\r\no=FreeSWITCH 1581332736 1581332737 IN IP4 ${external_rtp_ip}\r\ns=FreeSWITCH\r\nc=IN IP4 ${external_rtp_ip}\r\nt=0 0\r\na=msid-semantic: WMS ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH\r\nm=audio 31858 UDP/TLS/RTP/SAVPF 0 126\r\na=rtpmap:0 PCMU/8000\r\na=rtpmap:126 telephone-event/8000\r\na=silenceSupp:off - - - -\r\na=ptime:20\r\na=sendrecv\r\na=fingerprint:sha-256 96:E9:38:23:96:4C:07:4E:61:4F:80:B7:05:E6:BE:BA:04:CA:F3:69:B6:90:E0:43:59:AD:F1:A9:4B:D1:57:C3\r\na=setup:active\r\na=rtcp-mux\r\na=rtcp:31858 IN IP4 ${external_rtp_ip}\r\na=ice-ufrag:E49jHpieyRDYDTvy\r\na=ice-pwd:seWjQmYFvVt02UlxPlHnAPrZ\r\na=candidate:9727255544 1 udp 659136 ${external_rtp_ip} 31858 typ host generation 0\r\na=end-of-candidates\r\na=ssrc:3447296298 cname:5JSy0MzPYj6YEhAu\r\na=ssrc:3447296298 msid:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH a0\r\na=ssrc:3447296298 mslabel:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqH\r\na=ssrc:3447296298 label:ijtlDq4aZmUq9vlM0wEOONp9GjJyzVqHa0\r\n"
  156.         }
  157. }]
  158. 2020-02-10 19:56:34.538739 [DEBUG] switch_rtp.c:7720 Correct audio ip/port confirmed.
  159. 2020-02-10 19:56:34.618739 [DEBUG] mod_verto.c:1415 READ 47.208.143.73:53106 [{
  160.         "jsonrpc":      "2.0",
  161.         "id":   12,
  162.         "result":       {
  163.                 "method":       "verto.media"
  164.         }
  165. }]
  166. 2020-02-10 19:56:38.438738 [DEBUG] sofia.c:7290 Channel sofia/Localnet/917072057979 entering state [completing][200]
  167. 2020-02-10 19:56:38.438738 [DEBUG] sofia.c:7297 Duplicate SDP
  168. v=0
  169. o=CiscoSystemsCCM-SIP 12412155 1 IN IP4 10.0.20.27
  170. s=SIP Call
  171. c=IN IP4 10.0.20.27
  172. b=TIAS:64000
  173. b=CT:64
  174. b=AS:64
  175. t=0 0
  176. m=audio 30076 RTP/AVP 0 101
  177. a=rtpmap:0 PCMU/8000
  178. a=rtpmap:101 telephone-event/8000
  179. a=fmtp:101 0-15
  180. a=ptime:20
  181.  
  182. 2020-02-10 19:56:38.458740 [DEBUG] sofia.c:7290 Channel sofia/Localnet/917072057979 entering state [ready][200]
  183. 2020-02-10 19:56:38.458740 [NOTICE] sofia.c:8409 Channel [sofia/Localnet/917072057979] has been answered

Reply to "verto2pstn via CUCM call - no media"