search

plivo / plivoframework

Open Source Telephony Application Prototyping Framework
http://www.plivo.com/open-source/
Other
417 stars 180 forks source link

Plivo Hanging up / Killing Calls After 90 secs #100

Closed ngrichyj4 closed 11 years ago

ngrichyj4 commented 11 years ago

I'm making a call then bridging with another call when answered, the issue is when the bridge happens and after 1:30 secs as elapsed the call is dropped during a conversation I've been trying to figure out why this is happening with no luck, I've also reinstalled from scratch and the same problem surfaces. I also don't have any firewall configured and I can also see Freeswitch complaining about.

No origination URL specified!
Originate Resulted in Error Cause: 27 [DESTINATION_OUT_OF_ORDER]
Call Params from Ruby
call_params = {
        'From'=> "#{from}", # Caller Id
        'To' => "#{to}", # User Number to Call
        'Gateways' => "sofia/gateway/provider/", # Gateway string to try dialing our separated by comma. First in list will be tried first
        'GatewayCodecs' => "'PCMA,PCMU'", # Codec string as needed by FS for each gateway separated by comma
        'GatewayTimeouts' => "60",      # Seconds to timeout in string for each gateway separated by comma
        'GatewayRetries' => "1", # Retry String for Gateways separated by comma, on how many times each gateway should be retried
        'ExtraDialString' => extra_dial_string,
        'TimeLimit' => "1800",               
        'AnswerUrl' => answerUrl,
        'HangupUrl' => hangupUrl,
        'RingUrl' =>   ringUrl,
    }
Freeswitch log
2013-05-16 08:55:45.864677 [DEBUG] switch_ivr_originate.c:2044 Parsing global variables
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [plivo_request_uuid]=[7199d09c-bdef-11e2-a1e3-bc764e051180]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [plivo_answer_url]=[http://api.cardup.co/v1/answered/?billno=1403&connect_to=14085423354&source=iphone]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [plivo_ring_url]=[http://api.cardup.co/v1/ringing/?billno=1403&connect_to=14085423354&source=iphone]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [plivo_hangup_url]=[http://api.cardup.co/v1/hangup/?billno=1403&connect_to=14085423354&source=iphone]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [origination_caller_id_number]=[14035423333]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [bridge_early_media]=[true]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [hangup_after_bridge]=[true]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [plivo_sched_hangup_id]=[719b4152-bdef-11e2-a1e3-bc764e051180]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [plivo_from]=[14035423333]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [plivo_to]=[14035423333]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [plivo_app]=[true]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [absolute_codec_string]=[PCMA]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [originate_timeout]=[60]
2013-05-16 08:55:45.864677 [DEBUG] switch_event.c:1608 Parsing variable [ignore_early_media]=[true]
2013-05-16 08:55:45.864677 [NOTICE] switch_channel.c:978 New Channel sofia/external/14035423333 [65a2c516-be06-11e2-a7f0-ab304f53eb37]
2013-05-16 08:55:45.864677 [DEBUG] mod_sofia.c:4417 (sofia/external/14035423333) State Change CS_NEW -> CS_INIT
2013-05-16 08:55:45.864677 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:45.864677 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14035423333) Running State Change CS_INIT
2013-05-16 08:55:45.864677 [DEBUG] switch_core_state_machine.c:454 (sofia/external/14035423333) State INIT
2013-05-16 08:55:45.864677 [DEBUG] mod_sofia.c:87 sofia/external/14035423333 SOFIA INIT
2013-05-16 08:55:45.864677 [DEBUG] sofia_glue.c:1219 Local SDP:
v=0
o=FreeSWITCH 1368677427 1368677428 IN IP4 <ip address>
s=FreeSWITCH
c=IN IP4 <ip address>
t=0 0
m=audio 17118 RTP/AVP 8 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-05-16 08:55:45.864677 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:45.864677 [DEBUG] mod_sofia.c:114 (sofia/external/14035423333) State Change CS_INIT -> CS_ROUTING
2013-05-16 08:55:45.864677 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:45.864677 [DEBUG] switch_core_state_machine.c:454 (sofia/external/14035423333) State INIT going to sleep
2013-05-16 08:55:45.864677 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14035423333) Running State Change CS_ROUTING
2013-05-16 08:55:45.864677 [DEBUG] switch_core_state_machine.c:470 (sofia/external/14035423333) State ROUTING
2013-05-16 08:55:45.864677 [DEBUG] mod_sofia.c:137 sofia/external/14035423333 SOFIA ROUTING
2013-05-16 08:55:45.864677 [DEBUG] switch_ivr_originate.c:67 (sofia/external/14035423333) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-05-16 08:55:45.864677 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:45.864677 [DEBUG] switch_core_state_machine.c:470 (sofia/external/14035423333) State ROUTING going to sleep
2013-05-16 08:55:45.864677 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14035423333) Running State Change CS_CONSUME_MEDIA
2013-05-16 08:55:45.864677 [DEBUG] switch_core_state_machine.c:489 (sofia/external/14035423333) State CONSUME_MEDIA
2013-05-16 08:55:45.864677 [DEBUG] switch_core_state_machine.c:489 (sofia/external/14035423333) State CONSUME_MEDIA going to sleep
2013-05-16 08:55:45.864677 [DEBUG] sofia.c:5742 Channel sofia/external/14035423333 entering state [calling][0]
2013-05-16 08:55:46.064684 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:46.064684 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:46.064684 [DEBUG] sofia.c:5742 Channel sofia/external/14035423333 entering state [calling][0]
2013-05-16 08:55:49.044681 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:49.044681 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:49.044681 [DEBUG] sofia.c:5742 Channel sofia/external/14035423333 entering state [proceeding][183]
2013-05-16 08:55:49.044681 [DEBUG] sofia.c:5751 Remote SDP:
v=0
o=root 1062870387 1062870387 IN IP4 178.63.143.236
s=Asterisk PBX 1.6.2.9-2+squeeze5
c=IN IP4 178.63.143.236
t=0 0
m=audio 33972 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2013-05-16 08:55:49.044681 [DEBUG] switch_core_media.c:2673 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-05-16 08:55:49.044681 [DEBUG] switch_core_media.c:1772 Set Codec sofia/external/14035423333 PCMA/8000 20 ms 160 samples 64000 bits
2013-05-16 08:55:49.044681 [DEBUG] switch_core_codec.c:111 sofia/external/14035423333 Original read codec set to PCMA:8
2013-05-16 08:55:49.044681 [DEBUG] switch_core_media.c:2835 Set 2833 dtmf send payload to 101
2013-05-16 08:55:49.044681 [DEBUG] switch_core_media.c:3759 AUDIO RTP [sofia/external/14035423333] <ip address> port 17118 -> 178.63.143.236 port 33972 codec: 8 ms: 20
2013-05-16 08:55:49.044681 [DEBUG] switch_rtp.c:2659 Starting timer [soft] 160 bytes per 20ms
2013-05-16 08:55:49.044681 [DEBUG] switch_core_media.c:4104 Set 2833 dtmf send payload to 101
2013-05-16 08:55:49.044681 [DEBUG] switch_core_media.c:4110 Set 2833 dtmf receive payload to 101
2013-05-16 08:55:49.044681 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/14035423333!
2013-05-16 08:55:49.044681 [DEBUG] switch_channel.c:3277 (sofia/external/14035423333) Callstate Change DOWN -> EARLY
2013-05-16 08:55:53.784638 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:53.784638 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:53.784638 [DEBUG] sofia.c:5742 Channel sofia/external/14035423333 entering state [completing][200]
2013-05-16 08:55:53.784638 [DEBUG] sofia.c:5751 Remote SDP:
v=0
o=root 1062870387 1062870388 IN IP4 178.63.143.236
s=Asterisk PBX 1.6.2.9-2+squeeze5
c=IN IP4 178.63.143.236
t=0 0
m=audio 33972 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2013-05-16 08:55:53.784638 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:53.784638 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:53.784638 [DEBUG] sofia.c:5742 Channel sofia/external/14035423333 entering state [ready][200]
2013-05-16 08:55:53.784638 [NOTICE] sofia.c:6434 Channel [sofia/external/14035423333] has been answered
2013-05-16 08:55:53.784638 [DEBUG] switch_channel.c:3556 (sofia/external/14035423333) Callstate Change EARLY -> ACTIVE
2013-05-16 08:55:53.804637 [DEBUG] switch_ivr_originate.c:3467 Originate Resulted in Success: [sofia/external/14035423333]
2013-05-16 08:55:53.804637 [INFO] switch_channel.c:2939 sofia/external/14035423333 Flipping CID from "" <14035423333> to "Outbound Call" <14035423333>
2013-05-16 08:55:53.804637 [DEBUG] mod_commands.c:4066 (sofia/external/14035423333) State Change CS_CONSUME_MEDIA -> CS_EXECUTE
2013-05-16 08:55:53.804637 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:53.804637 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14035423333) Running State Change CS_EXECUTE
2013-05-16 08:55:53.804637 [DEBUG] switch_core_state_machine.c:477 (sofia/external/14035423333) State EXECUTE
2013-05-16 08:55:53.804637 [DEBUG] mod_sofia.c:230 sofia/external/14035423333 SOFIA EXECUTE
2013-05-16 08:55:53.804637 [DEBUG] switch_core_state_machine.c:209 sofia/external/14035423333 Standard EXECUTE
EXECUTE sofia/external/14035423333 socket(127.0.0.1:8084 async full)
2013-05-16 08:55:53.804637 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:53.804637 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:53.804637 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:53.844680 [DEBUG] switch_rtp.c:4689 Correct ip/port confirmed.
2013-05-16 08:55:53.844680 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute set(plivo_app=true)
EXECUTE sofia/external/14035423333 set(plivo_app=true)
2013-05-16 08:55:53.844680 [DEBUG] mod_dptools.c:1373 sofia/external/14035423333 SET [plivo_app]=[true]
2013-05-16 08:55:53.844680 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute set(hangup_after_bridge=false)
EXECUTE sofia/external/14035423333 set(hangup_after_bridge=false)
2013-05-16 08:55:53.844680 [DEBUG] mod_dptools.c:1373 sofia/external/14035423333 SET [hangup_after_bridge]=[false]
2013-05-16 08:55:53.844680 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute unset(plivo_sched_hangup_id)
EXECUTE sofia/external/14035423333 unset(plivo_sched_hangup_id)
2013-05-16 08:55:53.844680 [DEBUG] mod_dptools.c:1517 UNSET [plivo_sched_hangup_id]
2013-05-16 08:55:54.084645 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:54.104642 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute set(playback_sleep_val=0)
EXECUTE sofia/external/14035423333 set(playback_sleep_val=0)
2013-05-16 08:55:54.104642 [DEBUG] mod_dptools.c:1373 sofia/external/14035423333 SET [playback_sleep_val]=[0]
2013-05-16 08:55:54.104642 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:54.104642 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:54.144717 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute set(playback_terminators=none)
EXECUTE sofia/external/14035423333 set(playback_terminators=none)
2013-05-16 08:55:54.144717 [DEBUG] mod_dptools.c:1373 sofia/external/14035423333 SET [playback_terminators]=[none]
2013-05-16 08:55:54.144717 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute playback(/usr/local/freeswitch/sounds/en/us/callie/ivr/8000/ivr-please_hold_while_party_contacted.wav)
EXECUTE sofia/external/14035423333 playback(/usr/local/freeswitch/sounds/en/us/callie/ivr/8000/ivr-please_hold_while_party_contacted.wav)
2013-05-16 08:55:54.144717 [DEBUG] switch_ivr_play_say.c:1308 Codec Activated L16@8000hz 1 channels 20ms
2013-05-16 08:55:56.404631 [DEBUG] switch_ivr_play_say.c:1694 done playing file /usr/local/freeswitch/sounds/en/us/callie/ivr/8000/ivr-please_hold_while_party_contacted.wav
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.424644 [DEBUG] switch_core_session.c:1140 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute unset(call_timeout)
EXECUTE sofia/external/14035423333 unset(call_timeout)
2013-05-16 08:55:56.444649 [DEBUG] mod_dptools.c:1517 UNSET [call_timeout]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute unset(effective_caller_id_number)
EXECUTE sofia/external/14035423333 unset(effective_caller_id_number)
2013-05-16 08:55:56.444649 [DEBUG] mod_dptools.c:1517 UNSET [effective_caller_id_number]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute unset(effective_caller_id_name)
EXECUTE sofia/external/14035423333 unset(effective_caller_id_name)
2013-05-16 08:55:56.444649 [DEBUG] mod_dptools.c:1517 UNSET [effective_caller_id_name]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute set(continue_on_fail=true)
EXECUTE sofia/external/14035423333 set(continue_on_fail=true)
2013-05-16 08:55:56.444649 [DEBUG] mod_dptools.c:1373 sofia/external/14035423333 SET [continue_on_fail]=[true]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute set(hangup_after_bridge=false)
EXECUTE sofia/external/14035423333 set(hangup_after_bridge=false)
2013-05-16 08:55:56.444649 [DEBUG] mod_dptools.c:1373 sofia/external/14035423333 SET [hangup_after_bridge]=[false]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute set(plivo_dial_rang=false)
EXECUTE sofia/external/14035423333 set(plivo_dial_rang=false)
2013-05-16 08:55:56.444649 [DEBUG] mod_dptools.c:1373 sofia/external/14035423333 SET [plivo_dial_rang]=[false]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute unset(bridge_terminate_key)
EXECUTE sofia/external/14035423333 unset(bridge_terminate_key)
2013-05-16 08:55:56.444649 [DEBUG] mod_dptools.c:1517 UNSET [bridge_terminate_key]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute set(bridge_early_media=false)
EXECUTE sofia/external/14035423333 set(bridge_early_media=false)
2013-05-16 08:55:56.444649 [DEBUG] mod_dptools.c:1373 sofia/external/14035423333 SET [bridge_early_media]=[false]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute set(instant_ringback=true)
EXECUTE sofia/external/14035423333 set(instant_ringback=true)
2013-05-16 08:55:56.444649 [DEBUG] mod_dptools.c:1373 sofia/external/14035423333 SET [instant_ringback]=[true]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute set(ringback=${us-ring})
EXECUTE sofia/external/14035423333 set(ringback=%(2000,4000,440,480))
2013-05-16 08:55:56.444649 [DEBUG] mod_dptools.c:1373 sofia/external/14035423333 SET [ringback]=[%(2000,4000,440,480)]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute ring_ready()
EXECUTE sofia/external/14035423333 ring_ready()
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr.c:612 sofia/external/14035423333 Command Execute bridge(<api_on_ring='uuid_setvar 65a2c516-be06-11e2-a7f0-ab304f53eb37 plivo_dial_rang true',api_on_pre_answer='uuid_setvar 65a2c516-be06-11e2-a7f0-ab304f53eb37 plivo_dial_rang true',api_on_answer_1='sched_api +14400 6bed2b6e-be06-11e2-a1e3-bc764e051180 uuid_transfer 65a2c516-be06-11e2-a7f0-ab304f53eb37 -bleg hangup:ALLOTTED_TIMEOUT inline'>[absolute_codec_string='PCMA,PCMU']sofia/gateway/didlogic/14085423354:_:)
EXECUTE sofia/external/14035423333 bridge(<api_on_ring='uuid_setvar 65a2c516-be06-11e2-a7f0-ab304f53eb37 plivo_dial_rang true',api_on_pre_answer='uuid_setvar 65a2c516-be06-11e2-a7f0-ab304f53eb37 plivo_dial_rang true',api_on_answer_1='sched_api +14400 6bed2b6e-be06-11e2-a1e3-bc764e051180 uuid_transfer 65a2c516-be06-11e2-a7f0-ab304f53eb37 -bleg hangup:ALLOTTED_TIMEOUT inline'>[absolute_codec_string='PCMA,PCMU']sofia/gateway/didlogic/14085423354:_:)
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr_originate.c:1509 Parsing ultra-global variables
2013-05-16 08:55:56.444649 [DEBUG] switch_event.c:1608 Parsing variable [api_on_ring]=[uuid_setvar 65a2c516-be06-11e2-a7f0-ab304f53eb37 plivo_dial_rang true]
2013-05-16 08:55:56.444649 [DEBUG] switch_event.c:1608 Parsing variable [api_on_pre_answer]=[uuid_setvar 65a2c516-be06-11e2-a7f0-ab304f53eb37 plivo_dial_rang true]
2013-05-16 08:55:56.444649 [DEBUG] switch_event.c:1608 Parsing variable [api_on_answer_1]=[sched_api +14400 6bed2b6e-be06-11e2-a1e3-bc764e051180 uuid_transfer 65a2c516-be06-11e2-a7f0-ab304f53eb37 -bleg hangup:ALLOTTED_TIMEOUT inline]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr_originate.c:2044 Parsing global variables
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr_originate.c:2473 Parsing session specific variables
2013-05-16 08:55:56.444649 [DEBUG] switch_event.c:1608 Parsing variable [absolute_codec_string]=[PCMA]
2013-05-16 08:55:56.444649 [NOTICE] switch_channel.c:978 New Channel sofia/external/14085423354 [6bf0698c-be06-11e2-a808-ab304f53eb37]
2013-05-16 08:55:56.444649 [DEBUG] mod_sofia.c:4417 (sofia/external/14085423354) State Change CS_NEW -> CS_INIT
2013-05-16 08:55:56.444649 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr_originate.c:2044 Parsing global variables
2013-05-16 08:55:56.444649 [WARNING] switch_ivr_originate.c:2063 No origination URL specified!
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr_originate.c:3605 Originate Resulted in Error Cause: 27 [DESTINATION_OUT_OF_ORDER]
2013-05-16 08:55:56.444649 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14085423354) Running State Change CS_INIT
2013-05-16 08:55:56.444649 [DEBUG] switch_core_state_machine.c:454 (sofia/external/14085423354) State INIT
2013-05-16 08:55:56.444649 [DEBUG] mod_sofia.c:87 sofia/external/14085423354 SOFIA INIT
2013-05-16 08:55:56.444649 [DEBUG] sofia_glue.c:1219 Local SDP:
v=0
o=FreeSWITCH 1368664552 1368664553 IN IP4 <ip address>
s=FreeSWITCH
c=IN IP4 <ip address>
t=0 0
m=audio 30004 RTP/AVP 8 101 13
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2013-05-16 08:55:56.444649 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:55:56.444649 [DEBUG] mod_sofia.c:114 (sofia/external/14085423354) State Change CS_INIT -> CS_ROUTING
2013-05-16 08:55:56.444649 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:55:56.444649 [DEBUG] switch_core_state_machine.c:454 (sofia/external/14085423354) State INIT going to sleep
2013-05-16 08:55:56.444649 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14085423354) Running State Change CS_ROUTING
2013-05-16 08:55:56.444649 [DEBUG] switch_core_state_machine.c:470 (sofia/external/14085423354) State ROUTING
2013-05-16 08:55:56.444649 [DEBUG] mod_sofia.c:137 sofia/external/14085423354 SOFIA ROUTING
2013-05-16 08:55:56.444649 [DEBUG] switch_ivr_originate.c:67 (sofia/external/14085423354) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2013-05-16 08:55:56.444649 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:55:56.444649 [DEBUG] switch_core_state_machine.c:470 (sofia/external/14085423354) State ROUTING going to sleep
2013-05-16 08:55:56.444649 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14085423354) Running State Change CS_CONSUME_MEDIA
2013-05-16 08:55:56.444649 [DEBUG] switch_core_state_machine.c:489 (sofia/external/14085423354) State CONSUME_MEDIA
2013-05-16 08:55:56.444649 [DEBUG] switch_core_state_machine.c:489 (sofia/external/14085423354) State CONSUME_MEDIA going to sleep
2013-05-16 08:55:56.444649 [DEBUG] sofia.c:5742 Channel sofia/external/14085423354 entering state [calling][0]
2013-05-16 08:55:56.624629 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:55:56.624629 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:55:56.624629 [DEBUG] sofia.c:5742 Channel sofia/external/14085423354 entering state [calling][0]
2013-05-16 08:55:59.984641 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:55:59.984641 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:55:59.984641 [DEBUG] sofia.c:5742 Channel sofia/external/14085423354 entering state [proceeding][183]
2013-05-16 08:55:59.984641 [DEBUG] sofia.c:5751 Remote SDP:
v=0
o=root 589406641 589406641 IN IP4 178.63.143.236
s=Asterisk PBX 1.6.2.9-2+squeeze5
c=IN IP4 178.63.143.236
t=0 0
m=audio 24602 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2013-05-16 08:55:59.984641 [DEBUG] switch_core_media.c:2673 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-05-16 08:55:59.984641 [DEBUG] switch_core_media.c:1772 Set Codec sofia/external/14085423354 PCMA/8000 20 ms 160 samples 64000 bits
2013-05-16 08:55:59.984641 [DEBUG] switch_core_codec.c:111 sofia/external/14085423354 Original read codec set to PCMA:8
2013-05-16 08:55:59.984641 [DEBUG] switch_core_media.c:2835 Set 2833 dtmf send payload to 101
2013-05-16 08:55:59.984641 [DEBUG] switch_core_media.c:3759 AUDIO RTP [sofia/external/14085423354] <ip address> port 30004 -> 178.63.143.236 port 24602 codec: 8 ms: 20
2013-05-16 08:55:59.984641 [DEBUG] switch_rtp.c:2659 Starting timer [soft] 160 bytes per 20ms
2013-05-16 08:55:59.984641 [DEBUG] switch_core_media.c:4104 Set 2833 dtmf send payload to 101
2013-05-16 08:55:59.984641 [DEBUG] switch_core_media.c:4110 Set 2833 dtmf receive payload to 101
2013-05-16 08:55:59.984641 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/14085423354!
2013-05-16 08:55:59.984641 [DEBUG] switch_channel.c:3372 sofia/external/14085423354 process uuid_setvar 65a2c516-be06-11e2-a7f0-ab304f53eb37 plivo_dial_rang true: uuid_setvar(65a2c516-be06-11e2-a7f0-ab304f53eb37 plivo_dial_rang true)

2013-05-16 08:55:59.984641 [DEBUG] switch_channel.c:3277 (sofia/external/14085423354) Callstate Change DOWN -> EARLY
2013-05-16 08:56:07.704670 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:56:07.704670 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:56:07.704670 [DEBUG] sofia.c:5742 Channel sofia/external/14085423354 entering state [completing][200]
2013-05-16 08:56:07.704670 [DEBUG] sofia.c:5751 Remote SDP:
v=0
o=root 589406641 589406642 IN IP4 178.63.143.236
s=Asterisk PBX 1.6.2.9-2+squeeze5
c=IN IP4 178.63.143.236
t=0 0
m=audio 24602 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2013-05-16 08:56:07.704670 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:56:07.704670 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:56:07.704670 [DEBUG] sofia.c:5742 Channel sofia/external/14085423354 entering state [ready][200]
2013-05-16 08:56:07.704670 [NOTICE] sofia.c:6434 Channel [sofia/external/14085423354] has been answered
2013-05-16 08:56:07.704670 [DEBUG] switch_channel.c:3372 sofia/external/14085423354 process sched_api +14400 6bed2b6e-be06-11e2-a1e3-bc764e051180 uuid_transfer 65a2c516-be06-11e2-a7f0-ab304f53eb37 -bleg hangup:ALLOTTED_TIMEOUT inline: sched_api(+14400 6bed2b6e-be06-11e2-a1e3-bc764e051180 uuid_transfer 65a2c516-be06-11e2-a7f0-ab304f53eb37 -bleg hangup:ALLOTTED_TIMEOUT inline)

2013-05-16 08:56:07.704670 [DEBUG] switch_scheduler.c:219 Added task 5 sched_api_function (6bed2b6e-be06-11e2-a1e3-bc764e051180) to run at 1368708967
2013-05-16 08:56:07.704670 [DEBUG] switch_channel.c:3556 (sofia/external/14085423354) Callstate Change EARLY -> ACTIVE
2013-05-16 08:56:07.704670 [DEBUG] switch_ivr_originate.c:3467 Originate Resulted in Success: [sofia/external/14085423354]
2013-05-16 08:56:07.744680 [DEBUG] switch_core_session.c:860 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:56:07.744680 [DEBUG] switch_core_session.c:860 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:56:07.744680 [DEBUG] switch_ivr_bridge.c:1391 (sofia/external/14085423354) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2013-05-16 08:56:07.744680 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:56:07.744680 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14085423354) Running State Change CS_EXCHANGE_MEDIA
2013-05-16 08:56:07.744680 [DEBUG] switch_core_state_machine.c:480 (sofia/external/14085423354) State EXCHANGE_MEDIA
2013-05-16 08:56:07.744680 [DEBUG] mod_sofia.c:642 SOFIA EXCHANGE_MEDIA
2013-05-16 08:56:07.744680 [DEBUG] switch_core_session.c:922 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:56:07.744680 [DEBUG] switch_core_session.c:922 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:56:07.784685 [DEBUG] switch_rtp.c:4689 Correct ip/port confirmed.
2013-05-16 08:57:04.564637 [DEBUG] switch_core_session.c:1005 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:57:04.584636 [NOTICE] sofia.c:715 Hangup sofia/external/14035423333 [CS_EXECUTE] [NORMAL_CLEARING]
2013-05-16 08:57:04.584636 [DEBUG] switch_channel.c:3096 Send signal sofia/external/14035423333 [KILL]
2013-05-16 08:57:04.584636 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:57:04.584636 [DEBUG] switch_ivr_bridge.c:603 BRIDGE THREAD DONE [sofia/external/14035423333]
2013-05-16 08:57:04.584636 [DEBUG] switch_ivr_bridge.c:628 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:57:04.584636 [DEBUG] switch_ivr_bridge.c:527 sofia/external/14035423333 ending bridge by request from write function
2013-05-16 08:57:04.584636 [DEBUG] switch_ivr_bridge.c:603 BRIDGE THREAD DONE [sofia/external/14085423354]
2013-05-16 08:57:04.584636 [DEBUG] switch_ivr_bridge.c:628 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:57:04.584636 [NOTICE] switch_ivr_bridge.c:691 Hangup sofia/external/14085423354 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2013-05-16 08:57:04.584636 [DEBUG] switch_channel.c:3096 Send signal sofia/external/14085423354 [KILL]
2013-05-16 08:57:04.584636 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:480 (sofia/external/14085423354) State EXCHANGE_MEDIA going to sleep
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14085423354) Running State Change CS_HANGUP
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:676 (sofia/external/14085423354) State HANGUP
2013-05-16 08:57:04.584636 [DEBUG] mod_sofia.c:457 sofia/external/14085423354 Overriding SIP cause 480 with 200 from the other leg
2013-05-16 08:57:04.584636 [DEBUG] mod_sofia.c:463 Channel sofia/external/14085423354 hanging up, cause: NORMAL_CLEARING
2013-05-16 08:57:04.584636 [DEBUG] mod_sofia.c:515 Sending BYE to sofia/external/14085423354
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:48 sofia/external/14085423354 Standard HANGUP, cause: NORMAL_CLEARING
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:676 (sofia/external/14085423354) State HANGUP going to sleep
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:689 (sofia/external/14085423354) Callstate Change ACTIVE -> HANGUP
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:446 (sofia/external/14085423354) State Change CS_HANGUP -> CS_REPORTING
2013-05-16 08:57:04.584636 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14085423354) Running State Change CS_REPORTING
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:761 (sofia/external/14085423354) State REPORTING
2013-05-16 08:57:04.584636 [DEBUG] switch_ivr_bridge.c:1489 sofia/external/14085423354 skip receive message [UNBRIDGE] (channel is hungup already)
2013-05-16 08:57:04.584636 [DEBUG] switch_ivr_bridge.c:1492 sofia/external/14035423333 skip receive message [UNBRIDGE] (channel is hungup already)
2013-05-16 08:57:04.584636 [DEBUG] switch_core_session.c:2739 sofia/external/14035423333 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-05-16 08:57:04.584636 [DEBUG] switch_ivr.c:650 sofia/external/14035423333 skip receive message [AUDIO_SYNC] (channel is hungup already)
2013-05-16 08:57:04.584636 [DEBUG] switch_core_session.c:2739 sofia/external/14035423333 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:477 (sofia/external/14035423333) State EXECUTE going to sleep
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14035423333) Running State Change CS_HANGUP
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:676 (sofia/external/14035423333) State HANGUP
2013-05-16 08:57:04.584636 [DEBUG] mod_sofia.c:463 Channel sofia/external/14035423333 hanging up, cause: NORMAL_CLEARING
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:48 sofia/external/14035423333 Standard HANGUP, cause: NORMAL_CLEARING
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:676 (sofia/external/14035423333) State HANGUP going to sleep
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:689 (sofia/external/14035423333) Callstate Change ACTIVE -> HANGUP
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:446 (sofia/external/14035423333) State Change CS_HANGUP -> CS_REPORTING
2013-05-16 08:57:04.584636 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:415 (sofia/external/14035423333) Running State Change CS_REPORTING
2013-05-16 08:57:04.584636 [DEBUG] switch_core_state_machine.c:761 (sofia/external/14035423333) State REPORTING
2013-05-16 08:57:04.584636 [DEBUG] mod_event_socket.c:1355 sofia/external/14035423333 Socket Linger 0
2013-05-16 08:57:05.004656 [DEBUG] mod_event_socket.c:1345 linger timeout, closing socket
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:92 sofia/external/14085423354 Standard REPORTING, cause: NORMAL_CLEARING
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:761 (sofia/external/14085423354) State REPORTING going to sleep
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:440 (sofia/external/14085423354) State Change CS_REPORTING -> CS_DESTROY
2013-05-16 08:57:05.364653 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14085423354 [BREAK]
2013-05-16 08:57:05.364653 [DEBUG] switch_core_session.c:1548 Session 4 (sofia/external/14085423354) Locked, Waiting on external entities
2013-05-16 08:57:05.364653 [NOTICE] switch_core_session.c:1566 Session 4 (sofia/external/14085423354) Ended
2013-05-16 08:57:05.364653 [NOTICE] switch_core_session.c:1570 Close Channel sofia/external/14085423354 [CS_DESTROY]
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:565 (sofia/external/14085423354) Callstate Change HANGUP -> DOWN
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:568 (sofia/external/14085423354) Running State Change CS_DESTROY
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:578 (sofia/external/14085423354) State DESTROY
2013-05-16 08:57:05.364653 [DEBUG] mod_sofia.c:373 sofia/external/14085423354 SOFIA DESTROY
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:99 sofia/external/14085423354 Standard DESTROY
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:578 (sofia/external/14085423354) State DESTROY going to sleep
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:92 sofia/external/14035423333 Standard REPORTING, cause: NORMAL_CLEARING
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:761 (sofia/external/14035423333) State REPORTING going to sleep
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:440 (sofia/external/14035423333) State Change CS_REPORTING -> CS_DESTROY
2013-05-16 08:57:05.364653 [DEBUG] switch_core_session.c:1340 Send signal sofia/external/14035423333 [BREAK]
2013-05-16 08:57:05.364653 [DEBUG] switch_core_session.c:1548 Session 3 (sofia/external/14035423333) Locked, Waiting on external entities
2013-05-16 08:57:05.364653 [NOTICE] switch_core_session.c:1566 Session 3 (sofia/external/14035423333) Ended
2013-05-16 08:57:05.364653 [NOTICE] switch_core_session.c:1570 Close Channel sofia/external/14035423333 [CS_DESTROY]
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:565 (sofia/external/14035423333) Callstate Change HANGUP -> DOWN
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:568 (sofia/external/14035423333) Running State Change CS_DESTROY
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:578 (sofia/external/14035423333) State DESTROY
2013-05-16 08:57:05.364653 [DEBUG] mod_sofia.c:373 sofia/external/14035423333 SOFIA DESTROY
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:99 sofia/external/14035423333 Standard DESTROY
2013-05-16 08:57:05.364653 [DEBUG] switch_core_state_machine.c:578 (sofia/external/14035423333) State DESTROY going to sleep
floristlinks commented 11 years ago

did you find an answer to this problem? i am encountering the same issue

ngrichyj4 commented 11 years ago

Actually, after doing a tcpdump of the sip connection; I found out it was the upstream server throwing BYE signals. After switching to a different carrier, everything went back to normal.

floristlinks commented 11 years ago

I just found out my problem... I took out 'GatewayCodecs' => "'PCMA,PCMU'" and basically passed nothing for that and it works!