Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

REST XML not being rendered properly #13

Closed
mattwilliamson opened this issue Jun 30, 2011 · 5 comments
Closed

REST XML not being rendered properly #13

mattwilliamson opened this issue Jun 30, 2011 · 5 comments

Comments

@mattwilliamson
Copy link
Contributor

When I initiate a call via the REST server, I should hear some TTS but I hear silence instead. Freeswitch shows nothing in regards to the Speak command being sent.

Here's the API call using the plivohelper-python lib:

call_params = {
    'From'              : source_address,
    'To'                : destination_address,
    'Gateways'          : DEFAULT_GATEWAYS,
    'ExtraDialString'   : extra_dial_string,
    'AnswerUrl'         : request.build_absolute_uri(reverse('plivo_api.views.outgoing_answered')),
    'HangupUrl'         : request.build_absolute_uri(reverse('plivo_api.views.outgoing_hung_up')),
    'RingUrl'           : "http://api.telapia.com/_plivo/outgoing/ringing/",
    'TimeLimit'         : str(call.allowed_units)
}

result = plivo.call(call_params)

Plivo Log:

2011-06-30 17:29:20,154 plivo-outbound[26161]: INFO: (9) New request from ('127.0.0.1', 48507)
2011-06-30 17:29:20,155 plivo-outbound[26161]: DEBUG: (9) Execute: connect args=''
2011-06-30 17:29:20,160 plivo-outbound[26161]: DEBUG: (9) Response: <CommandResponse headers={'variable_sip_use_codec_rate': '8000', 'Channel-Channel-Progress-Media-Time': '1309469368081094', 'variable_sip_use_codec_ptime': '20', 'Caller-Screen-Bit': 'true', 'variable_is_outbound': 'true', 'Call-Direction': 'outbound', 'Channel-Read-Codec-Bit-Rate': '64000', 'Event-Calling-Line-Number': '1843', 'variable_sip_req_uri': '+17328381916@sip1.teltechsys.com', 'variable_sip_full_from': '"" <sip:kamailio@sip1.teltechsys.com;transport=udp>;tag=v8Kc5vejeF49p', 'Reply-Text': '+OK\n', 'variable_call_uuid': '25797b6d-f590-428a-92df-98d4d4825af3', 'variable_sip_contact_uri': '7328381916@75.127.90.67:5060', 'variable_sip_from_params': 'transport=udp', 'Channel-Channel-Created-Time': '1309469365996956', 'Event-Date-Timestamp': '1309469369765254', 'Event-Name': 'CHANNEL_DATA', 'FreeSWITCH-Switchname': 'plivo1.teltechsys.com', 'variable_sip_contact_params': 'transport=udp', 'Unique-ID': '78896797-1785-46c2-bb42-24d9391d46ae', 'variable_originate_early_media': 'false', 'Control': 'full', 'variable_plivo_sched_hangup_id': '01d47060-a360-11e0-8e69-12313b0c4557', 'Caller-Caller-ID-Number': '17328381916', 'variable_ignore_early_media': 'true', 'Caller-Privacy-Hide-Number': 'false', 'variable_sip_audio_recv_pt': '0', 'Channel-Write-Codec-Bit-Rate': '64000', 'Content-Type': 'command/reply', 'Channel-Write-Codec-Rate': '8000', 'variable_sip_to_user': '+17328381916', 'Event-Date-Local': '2011-06-30 17:29:29', 'Channel-Channel-Answered-Time': '1309469369745191', 'Event-Calling-Function': 'parse_command', 'variable_socket_host': '127.0.0.1', 'Caller-Destination-Number': '+17328381916', 'variable_sip_local_sdp_str': 'v=0\no=FreeSWITCH 1309439515 1309439516 IN IP4 50.17.206.81\ns=FreeSWITCH\nc=IN IP4 50.17.206.81\nt=0 0\nm=audio 29850 RTP/AVP 0 8 3 101 13\na=rtpmap:101 telephone-event/8000\na=fmtp:101 0-16\na=ptime:20\na=sendrecv\n', 'Caller-Profile-Index': '2', 'Channel-State': 'CS_EXECUTE', 'variable_plivo_app': 'true', 'variable_sip_contact_port': '5060', 'Caller-Caller-ID-Name': '17328381916', 'Core-UUID': '728288a5-efc6-44e0-8d58-f0753dcabdab', 'Caller-Profile-Created-Time': '1309469369765254', 'variable_sip_call_id': 'd9332edc-1e02-122f-6eac-12313b0c4557', 'variable_channel_name': 'sofia/external/+17328381916', 'Caller-Channel-Answered-Time': '1309469369745191', 'variable_switch_r_sdp': 'v=0\r\no=- 6755 11954 IN IP4 208.93.227.13\r\ns=-\r\nc=IN IP4 208.93.227.13\r\nt=0 0\r\nm=audio 16252 RTP/AVP 0 101\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-15\r\na=ptime:20\r\n', 'Answer-State': 'answered', 'Caller-Privacy-Hide-Name': 'false', 'variable_plivo_answer_url': 'http://api.telapia.com/_plivo/outgoing/answered', 'variable_remote_media_ip': '208.93.227.13', 'variable_write_codec': 'PCMU', 'Caller-Context': 'default', 'variable_max_forwards': '70', 'variable_sip_to_uri': '+17328381916@sip1.teltechsys.com', 'variable_sip_reply_port': '5060', 'variable_read_codec': 'PCMU', 'Channel-Channel-Progress-Time': '0', 'Caller-Channel-Created-Time': '1309469365996956', 'variable_endpoint_disposition': 'ANSWER', 'Channel-Context': 'default', 'variable_sip_from_tag': 'v8Kc5vejeF49p', 'Channel-Channel-Transfer-Time': '0', 'variable_sip_from_uri': 'kamailio@sip1.teltechsys.com', 'Channel-Channel-Hangup-Time': '0', 'Event-Date-GMT': 'Thu, 30 Jun 2011 21:29:29 GMT', 'Caller-Channel-Progress-Media-Time': '1309469368081094', 'variable_sip_full_via': 'SIP/2.0/UDP 50.17.206.81:5080;rport=5080;branch=z9hG4bKXNSa9vcQ7XQZg', 'Channel-Read-Codec-Rate': '8000', 'Channel-Profile-Index': '2', 'Channel-Direction': 'outbound', 'Channel-Name': 'sofia/external/+17328381916', 'variable_sip_reply_host': '75.101.162.138', 'variable_sofia_profile_name': 'external', 'Channel-Privacy-Hide-Name': 'false', 'Channel-State-Number': '4', 'variable_sip_destination_url': 'sip:+17328381916@sip1.teltechsys.com', 'Channel-Call-UUID': '25797b6d-f590-428a-92df-98d4d4825af3', 'variable_bridge_early_media': 'true', 'Channel-Caller-ID-Name': '17328381916', 'Caller-Dialplan': 'inline', 'variable_local_media_ip': '50.17.206.81', 'variable_rtp_use_ssrc': '75530', 'Caller-Source': 'src/switch_ivr_originate.c', 'variable_sip_network_ip': '75.101.162.138', 'Caller-Channel-Name': 'sofia/external/+17328381916', 'FreeSWITCH-IPv4': '10.98.70.165', 'FreeSWITCH-IPv6': '::1', 'Channel-Network-Addr': '75.101.162.138', 'variable_sip_full_to': '<sip:+17328381916@sip1.teltechsys.com>;tag=7KctBp3U43X1p', 'Channel-Dialplan': 'inline', 'variable_local_media_port': '29850', 'variable_sip_gateway_name': 'sip1', 'Caller-Channel-Transfer-Time': '0', 'variable_current_application': 'socket', 'variable_sip_profile_name': 'gateway', 'Event-Calling-File': 'mod_event_socket.c', 'Channel-Destination-Number': '+17328381916', 'variable_remote_media_port': '16252', 'Channel-Write-Codec-Name': 'PCMU', 'variable_current_application_data': '127.0.0.1:8084 async full', 'Channel-Source': 'src/switch_ivr_originate.c', 'Channel-Profile-Created-Time': '1309469369765254', 'variable_sip_network_port': '5060', 'Caller-Unique-ID': '78896797-1785-46c2-bb42-24d9391d46ae', 'variable_sip_to_host': 'sip1.teltechsys.com', 'Channel-Screen-Bit': 'true', 'variable_origination_caller_id_number': '555', 'Presence-Call-Direction': 'outbound', 'variable_pre_transfer_caller_id_number': '555', 'Channel-Read-Codec-Name': 'PCMU', 'variable_write_rate': '8000', 'variable_sip_contact_user': '7328381916', 'variable_sip_contact_host': '75.127.90.67', 'variable_sip_local_network_addr': '50.17.206.81', 'variable_plivo_request_uuid': '01d46c32-a360-11e0-8e69-12313b0c4557', 'variable_sip_cseq': '14398614', 'variable_read_rate': '8000', 'variable_sip_from_host': 'sip1.teltechsys.com', 'variable_sip_to_tag': '7KctBp3U43X1p', 'Caller-Channel-Hangup-Time': '0', 'Channel-Caller-ID-Number': '17328381916', 'Channel-Channel-Name': 'sofia/external/+17328381916', 'variable_sip_use_pt': '0', 'Channel-Privacy-Hide-Number': 'false', 'Caller-Direction': 'outbound', 'variable_uuid': '78896797-1785-46c2-bb42-24d9391d46ae', 'variable_direction': 'outbound', 'variable_sip_outgoing_contact_uri': '<sip:gw+sip1@50.17.206.81:5080;transport=udp;gw=sip1>', 'Caller-Network-Addr': '75.101.162.138', 'Channel-Unique-ID': '78896797-1785-46c2-bb42-24d9391d46ae', 'variable_originate_timeout': '60', 'variable_sip_from_user': 'kamailio', 'Socket-Mode': 'async', 'variable_sip_use_codec_name': 'PCMU', 'Caller-Channel-Progress-Time': '0', 'FreeSWITCH-Hostname': 'plivo1.teltechsys.com', 'Channel-Call-State': 'ACTIVE', 'variable_api_on_answer': 'sched_api 01d47060-a360-11e0-8e69-12313b0c4557 +34602 hupall ALLOTTED_TIMEOUT plivo_request_uuid 01d46c32-a360-11e0-8e69-12313b0c4557'}, body=>
2011-06-30 17:29:20,160 plivo-outbound[26161]: DEBUG: (9) Execute: resume args=''
2011-06-30 17:29:20,221 plivo-outbound[26161]: DEBUG: (9) Response: <CommandResponse headers={'Content-Type': 'command/reply', 'Reply-Text': '+OK'}, body=>
2011-06-30 17:29:20,222 plivo-outbound[26161]: DEBUG: (9) Execute: linger args=''
2011-06-30 17:29:20,222 plivo-outbound[26161]: DEBUG: (9) Response: <CommandResponse headers={'Content-Type': 'command/reply', 'Reply-Text': '+OK will linger'}, body=>
2011-06-30 17:29:20,222 plivo-outbound[26161]: DEBUG: (9) Execute: myevents json args=''
2011-06-30 17:29:20,223 plivo-outbound[26161]: DEBUG: (9) Response: <CommandResponse headers={'Content-Type': 'command/reply', 'Reply-Text': '+OK Events Enabled'}, body=>
2011-06-30 17:29:20,223 plivo-outbound[26161]: DEBUG: (9) Execute: event json args='CUSTOM conference::maintenance'
2011-06-30 17:29:20,223 plivo-outbound[26161]: DEBUG: (9) Response: <CommandResponse headers={'Content-Type': 'command/reply', 'Reply-Text': '+OK event listener enabled json'}, body=>
2011-06-30 17:29:20,224 plivo-outbound[26161]: DEBUG: (9) Execute: set args=plivo_app=true, uuid='', lock=True, loops=1
2011-06-30 17:29:20,224 plivo-outbound[26161]: DEBUG: (9) Response: <CommandResponse headers={'Content-Type': 'command/reply', 'Reply-Text': '+OK'}, body=>
2011-06-30 17:29:20,225 plivo-outbound[26161]: DEBUG: (9) Execute: set args=hangup_after_bridge=false, uuid='', lock=True, loops=1
2011-06-30 17:29:20,225 plivo-outbound[26161]: DEBUG: (9) Response: <CommandResponse headers={'Content-Type': 'command/reply', 'Reply-Text': '+OK'}, body=>
2011-06-30 17:29:20,225 plivo-outbound[26161]: INFO: (9) Using AnswerUrl http://api.telapia.com/_plivo/outgoing/answered
2011-06-30 17:29:20,226 plivo-outbound[26161]: DEBUG: (9) Execute: unset args=plivo_sched_hangup_id, uuid='', lock=True, loops=1
2011-06-30 17:29:20,226 plivo-outbound[26161]: DEBUG: (9) Response: <CommandResponse headers={'Content-Type': 'command/reply', 'Reply-Text': '+OK'}, body=>
2011-06-30 17:29:20,226 plivo-outbound[26161]: INFO: (9) Processing Call
2011-06-30 17:29:20,227 plivo-outbound[26161]: INFO: (9) Fetching RESTXML from http://api.telapia.com/_plivo/outgoing/answered with {}
2011-06-30 17:29:20,378 plivo-outbound[26161]: INFO: (9) Sent to POST http://api.telapia.com/_plivo/outgoing/answered with {'Direction': 'outbound', 'From': '17328381916', 'ALegUUID': '78896797-1785-46c2-bb42-24d9391d46ae', 'CallStatus': 'in-progress', 'To': '17328381916', 'ALegRequestUUID': '01d46c32-a360-11e0-8e69-12313b0c4557', 'CallUUID': '78896797-1785-46c2-bb42-24d9391d46ae', 'ScheduledHangupId': '01d47060-a360-11e0-8e69-12313b0c4557'} -- Result: <Response><Speak loop="1" voice="slt">Hello</Speak></Response>
2011-06-30 17:29:20,378 plivo-outbound[26161]: INFO: (9) Requested RESTXML to http://api.telapia.com/_plivo/outgoing/answered with {'Direction': 'outbound', 'From': '17328381916', 'ALegUUID': '78896797-1785-46c2-bb42-24d9391d46ae', 'CallStatus': 'in-progress', 'To': '17328381916', 'ALegRequestUUID': '01d46c32-a360-11e0-8e69-12313b0c4557', 'CallUUID': '78896797-1785-46c2-bb42-24d9391d46ae', 'ScheduledHangupId': '01d47060-a360-11e0-8e69-12313b0c4557'}
2011-06-30 17:29:20,378 plivo-outbound[26161]: INFO: (9) [Speak] Hello {'engine': 'flite', 'language': 'en', 'voice': 'slt', 'type': '', 'method': '', 'loop': '1'}
2011-06-30 17:29:20,378 plivo-outbound[26161]: DEBUG: (9) Execute: speak args=flite|slt|Hello, uuid='', lock=True, loops=1
2011-06-30 17:29:20,386 plivo-outbound[26161]: DEBUG: (9) Response: <CommandResponse headers={'Content-Type': 'command/reply', 'Reply-Text': '+OK'}, body=>
2011-06-30 17:29:20,386 plivo-outbound[26161]: DEBUG: (9) Speaking 1 times ...
2011-06-30 17:29:20,398 plivo-outbound[26161]: INFO: (9) Event: channel 78896797-1785-46c2-bb42-24d9391d46ae has hung up (ALLOTTED_TIMEOUT)
2011-06-30 17:29:20,398 plivo-outbound[26161]: WARNING: (9) Speak Break (empty event)
2011-06-30 17:29:20,398 plivo-outbound[26161]: INFO: (9) [Speak] Done
2011-06-30 17:29:20,398 plivo-outbound[26161]: INFO: (9) End of RESTXML
2011-06-30 17:29:20,398 plivo-outbound[26161]: INFO: (9) Processing Call Ended
2011-06-30 17:29:20,399 plivo-outbound[26161]: DEBUG: (9) Releasing Connection ...
2011-06-30 17:29:20,399 plivo-outbound[26161]: DEBUG: (9) Releasing Connection Done
2011-06-30 17:29:20,399 plivo-outbound[26161]: INFO: (9) End request from ('127.0.0.1', 48507)

Freeswitch log:

2011-06-30 17:29:25.996956 [DEBUG] switch_ivr_originate.c:1869 Parsing global variables
2011-06-30 17:29:25.996956 [DEBUG] switch_event.c:1423 Parsing variable [plivo_request_uuid]=[01d46c32-a360-11e0-8e69-12313b0c4557]
2011-06-30 17:29:25.996956 [DEBUG] switch_event.c:1423 Parsing variable [plivo_answer_url]=[http://api.telapia.com/_plivo/outgoing/answered]
2011-06-30 17:29:25.996956 [DEBUG] switch_event.c:1423 Parsing variable [origination_caller_id_number]=[555]
2011-06-30 17:29:25.996956 [DEBUG] switch_event.c:1423 Parsing variable [bridge_early_media]=[true]
2011-06-30 17:29:25.996956 [DEBUG] switch_event.c:1423 Parsing variable [api_on_answer]=[sched_api 01d47060-a360-11e0-8e69-12313b0c4557 +34602 hupall ALLOTTED_TIMEOUT plivo_request_uuid 01d46c32-a360-11e0-8e69-12313b0c4557]
2011-06-30 17:29:25.996956 [DEBUG] switch_event.c:1423 Parsing variable [plivo_sched_hangup_id]=[01d47060-a360-11e0-8e69-12313b0c4557]
2011-06-30 17:29:25.996956 [DEBUG] switch_event.c:1423 Parsing variable [plivo_app]=[true]
2011-06-30 17:29:25.996956 [DEBUG] switch_event.c:1423 Parsing variable [originate_timeout]=[60]
2011-06-30 17:29:25.996956 [DEBUG] switch_event.c:1423 Parsing variable [ignore_early_media]=[true]
2011-06-30 17:29:25.996956 [NOTICE] switch_channel.c:890 New Channel sofia/external/+17328381916 [78896797-1785-46c2-bb42-24d9391d46ae]
2011-06-30 17:29:25.996956 [DEBUG] mod_sofia.c:4412 (sofia/external/+17328381916) State Change CS_NEW -> CS_INIT
2011-06-30 17:29:25.996956 [DEBUG] switch_core_session.c:1118 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:25.996956 [DEBUG] switch_core_state_machine.c:325 (sofia/external/+17328381916) Running State Change CS_INIT
2011-06-30 17:29:25.996956 [DEBUG] switch_core_state_machine.c:364 (sofia/external/+17328381916) State INIT
2011-06-30 17:29:25.996956 [DEBUG] mod_sofia.c:85 sofia/external/+17328381916 SOFIA INIT
2011-06-30 17:29:25.996956 [DEBUG] mod_sofia.c:125 (sofia/external/+17328381916) State Change CS_INIT -> CS_ROUTING
2011-06-30 17:29:25.996956 [DEBUG] switch_core_session.c:773 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:25.996956 [DEBUG] switch_core_session.c:1118 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:25.996956 [DEBUG] switch_core_state_machine.c:364 (sofia/external/+17328381916) State INIT going to sleep
2011-06-30 17:29:25.996956 [DEBUG] switch_core_state_machine.c:325 (sofia/external/+17328381916) Running State Change CS_ROUTING
2011-06-30 17:29:25.996956 [DEBUG] switch_channel.c:1805 (sofia/external/+17328381916) Callstate Change DOWN -> RINGING
2011-06-30 17:29:25.996956 [DEBUG] switch_core_state_machine.c:373 (sofia/external/+17328381916) State ROUTING
2011-06-30 17:29:25.996956 [DEBUG] mod_sofia.c:148 sofia/external/+17328381916 SOFIA ROUTING
2011-06-30 17:29:25.996956 [DEBUG] switch_ivr_originate.c:66 (sofia/external/+17328381916) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-06-30 17:29:25.996956 [DEBUG] switch_core_session.c:1118 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:25.996956 [DEBUG] switch_core_state_machine.c:373 (sofia/external/+17328381916) State ROUTING going to sleep
2011-06-30 17:29:25.996956 [DEBUG] switch_core_state_machine.c:325 (sofia/external/+17328381916) Running State Change CS_CONSUME_MEDIA
2011-06-30 17:29:25.996956 [DEBUG] switch_core_state_machine.c:392 (sofia/external/+17328381916) State CONSUME_MEDIA
2011-06-30 17:29:25.996956 [DEBUG] switch_core_state_machine.c:392 (sofia/external/+17328381916) State CONSUME_MEDIA going to sleep
2011-06-30 17:29:25.996956 [DEBUG] sofia.c:5074 Channel sofia/external/+17328381916 entering state [calling][0]
2011-06-30 17:29:28.081094 [DEBUG] switch_core_session.c:773 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:28.081094 [DEBUG] switch_core_session.c:773 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:28.081094 [INFO] sofia.c:761 sofia/external/+17328381916 Update Callee ID to "17328381916" <17328381916>
2011-06-30 17:29:28.081094 [DEBUG] sofia.c:5074 Channel sofia/external/+17328381916 entering state [proceeding][183]
2011-06-30 17:29:28.081094 [DEBUG] sofia.c:5085 Remote SDP:
v=0
o=- 6755 11954 IN IP4 208.93.227.13
s=-
c=IN IP4 208.93.227.13
t=0 0
m=audio 16252 RTP/AVP 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2011-06-30 17:29:28.081094 [DEBUG] sofia_glue.c:4711 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2011-06-30 17:29:28.081094 [DEBUG] sofia_glue.c:2819 Set Codec sofia/external/+17328381916 PCMU/8000 20 ms 160 samples 64000 bits
2011-06-30 17:29:28.081094 [DEBUG] sofia_glue.c:4819 Set 2833 dtmf send payload to 101
2011-06-30 17:29:28.081094 [DEBUG] sofia_glue.c:3072 AUDIO RTP [sofia/external/+17328381916] 10.98.70.165 port 29850 -> 208.93.227.13 port 16252 codec: 0 ms: 20
2011-06-30 17:29:28.081094 [DEBUG] switch_rtp.c:1636 Starting timer [soft] 160 bytes per 20ms
2011-06-30 17:29:28.081094 [DEBUG] sofia_glue.c:3334 Set 2833 dtmf send payload to 101
2011-06-30 17:29:28.081094 [DEBUG] sofia_glue.c:3339 Set 2833 dtmf receive payload to 101
2011-06-30 17:29:28.081094 [NOTICE] sofia_glue.c:3843 Pre-Answer sofia/external/+17328381916!
2011-06-30 17:29:28.081094 [DEBUG] switch_channel.c:2799 (sofia/external/+17328381916) Callstate Change RINGING -> EARLY
2011-06-30 17:29:29.745191 [DEBUG] switch_core_session.c:773 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:29.745191 [DEBUG] switch_core_session.c:773 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:29.745191 [DEBUG] switch_core_session.c:773 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:29.745191 [DEBUG] sofia.c:5074 Channel sofia/external/+17328381916 entering state [ready][200]
2011-06-30 17:29:29.745191 [DEBUG] sofia.c:5082 Duplicate SDP
v=0
o=- 6755 11954 IN IP4 208.93.227.13
s=-
c=IN IP4 208.93.227.13
t=0 0
m=audio 16252 RTP/AVP 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2011-06-30 17:29:29.745191 [DEBUG] switch_channel.c:2990 (sofia/external/+17328381916) Callstate Change EARLY -> ACTIVE
2011-06-30 17:29:29.745191 [NOTICE] sofia.c:5679 Channel [sofia/external/+17328381916] has been answered
2011-06-30 17:29:29.745191 [DEBUG] switch_scheduler.c:214 Added task 20 sched_api_function (+34602) to run at 1
2011-06-30 17:29:29.745191 [DEBUG] switch_channel.c:3051 sofia/external/+17328381916 api on answer: sched_api(01d47060-a360-11e0-8e69-12313b0c4557 +34602 hupall ALLOTTED_TIMEOUT plivo_request_uuid 01d46c32-a360-11e0-8e69-12313b0c4557)
+OK Added: 20

2011-06-30 17:29:29.765254 [DEBUG] switch_ivr_originate.c:3214 Originate Resulted in Success: [sofia/external/+17328381916]
2011-06-30 17:29:29.765254 [DEBUG] switch_ivr.c:1622 (sofia/external/+17328381916) State Change CS_CONSUME_MEDIA -> CS_ROUTING
2011-06-30 17:29:29.765254 [DEBUG] switch_core_session.c:1118 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:29.765254 [DEBUG] switch_core_session.c:711 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:29.765254 [NOTICE] switch_ivr.c:1628 Transfer sofia/external/+17328381916 to inline[socket:127.0.0.1:8084 async full@default]
2011-06-30 17:29:29.765254 [DEBUG] switch_core_state_machine.c:325 (sofia/external/+17328381916) Running State Change CS_ROUTING
2011-06-30 17:29:29.765254 [DEBUG] switch_channel.c:1805 (sofia/external/+17328381916) Callstate Change ACTIVE -> RINGING
2011-06-30 17:29:29.765254 [DEBUG] switch_core_state_machine.c:373 (sofia/external/+17328381916) State ROUTING
2011-06-30 17:29:29.765254 [DEBUG] mod_sofia.c:148 sofia/external/+17328381916 SOFIA ROUTING
2011-06-30 17:29:29.765254 [DEBUG] switch_core_state_machine.c:77 sofia/external/+17328381916 Standard ROUTING
2011-06-30 17:29:29.765254 [INFO] switch_channel.c:2607 sofia/external/+17328381916 Flipping CID from "" <555> to "17328381916" <17328381916>
2011-06-30 17:29:29.765254 [DEBUG] switch_core_state_machine.c:119 (sofia/external/+17328381916) State Change CS_ROUTING -> CS_EXECUTE
2011-06-30 17:29:29.765254 [DEBUG] switch_core_session.c:1118 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:29.765254 [DEBUG] switch_core_state_machine.c:373 (sofia/external/+17328381916) State ROUTING going to sleep
2011-06-30 17:29:29.765254 [DEBUG] switch_core_state_machine.c:325 (sofia/external/+17328381916) Running State Change CS_EXECUTE
2011-06-30 17:29:29.765254 [DEBUG] switch_channel.c:1807 (sofia/external/+17328381916) Callstate Change RINGING -> ACTIVE
2011-06-30 17:29:29.765254 [DEBUG] switch_core_state_machine.c:380 (sofia/external/+17328381916) State EXECUTE
2011-06-30 17:29:29.765254 [DEBUG] mod_sofia.c:241 sofia/external/+17328381916 SOFIA EXECUTE
2011-06-30 17:29:29.765254 [DEBUG] switch_core_state_machine.c:157 sofia/external/+17328381916 Standard EXECUTE
EXECUTE sofia/external/+17328381916 socket(127.0.0.1:8084 async full)
2011-06-30 17:29:29.765254 [DEBUG] switch_core_session.c:956 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:29.765254 [DEBUG] switch_core_session.c:956 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:29.765254 [DEBUG] switch_core_session.c:956 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:29.893827 [DEBUG] switch_ivr.c:576 sofia/external/+17328381916 Command Execute set(plivo_app=true)
EXECUTE sofia/external/+17328381916 set(plivo_app=true)
2011-06-30 17:29:29.893827 [DEBUG] mod_dptools.c:1063 sofia/external/+17328381916 SET [plivo_app]=[true]
2011-06-30 17:29:29.893827 [DEBUG] switch_ivr.c:576 sofia/external/+17328381916 Command Execute set(hangup_after_bridge=false)
EXECUTE sofia/external/+17328381916 set(hangup_after_bridge=false)
2011-06-30 17:29:29.893827 [DEBUG] mod_dptools.c:1063 sofia/external/+17328381916 SET [hangup_after_bridge]=[false]
2011-06-30 17:29:29.893827 [DEBUG] switch_ivr.c:576 sofia/external/+17328381916 Command Execute unset(plivo_sched_hangup_id)
EXECUTE sofia/external/+17328381916 unset(plivo_sched_hangup_id)
2011-06-30 17:29:29.893827 [DEBUG] mod_dptools.c:1180 UNSET [plivo_sched_hangup_id]
2011-06-30 17:29:29.933264 [DEBUG] switch_rtp.c:3104 Correct ip/port confirmed.
2011-06-30 17:29:29.993280 [DEBUG] switch_core_session.c:956 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:29.993280 [DEBUG] switch_ivr.c:576 sofia/external/+17328381916 Command Execute speak(flite|slt|Hello)
EXECUTE sofia/external/+17328381916 speak(flite|slt|Hello)
2011-06-30 17:29:29.993280 [DEBUG] switch_ivr_play_say.c:2392 OPEN TTS flite
2011-06-30 17:29:29.993280 [DEBUG] switch_ivr_play_say.c:2401 Raw Codec Activated
2011-06-30 17:29:29.993280 [WARNING] switch_scheduler.c:114 Task was executed late by 1309469368 seconds 20 sched_api_function (+34602)
2011-06-30 17:29:29.993280 [DEBUG] switch_channel.c:2723 (sofia/external/+17328381916) Callstate Change ACTIVE -> HANGUP
2011-06-30 17:29:29.993280 [NOTICE] switch_core_session.c:223 Hangup sofia/external/+17328381916 [CS_EXECUTE] [ALLOTTED_TIMEOUT]
2011-06-30 17:29:29.993280 [DEBUG] switch_channel.c:2739 Send signal sofia/external/+17328381916 [KILL]
2011-06-30 17:29:29.993280 [DEBUG] switch_core_session.c:1118 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:29.993280 [DEBUG] mod_commands.c:3584 Command hupall(ALLOTTED_TIMEOUT plivo_request_uuid 01d46c32-a360-11e0-8e69-12313b0c4557):
+OK hangup all channels matching [plivo_request_uuid]=[01d46c32-a360-11e0-8e69-12313b0c4557] with cause: ALLOTTED_TIMEOUT

2011-06-30 17:29:29.993280 [DEBUG] switch_scheduler.c:138 Deleting task 20 sched_api_function (+34602)
2011-06-30 17:29:30.013272 [DEBUG] switch_ivr_play_say.c:2092 Speaking text: Hello
2011-06-30 17:29:30.033269 [DEBUG] switch_ivr_play_say.c:2284 done speaking text
2011-06-30 17:29:30.033269 [DEBUG] switch_core_session.c:2090 sofia/external/+17328381916 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2011-06-30 17:29:30.033269 [DEBUG] switch_core_session.c:2090 sofia/external/+17328381916 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:380 (sofia/external/+17328381916) State EXECUTE going to sleep
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:325 (sofia/external/+17328381916) Running State Change CS_HANGUP
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:575 (sofia/external/+17328381916) State HANGUP
2011-06-30 17:29:30.033269 [DEBUG] mod_sofia.c:458 Channel sofia/external/+17328381916 hanging up, cause: ALLOTTED_TIMEOUT
2011-06-30 17:29:30.033269 [DEBUG] mod_sofia.c:501 Sending BYE to sofia/external/+17328381916
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:46 sofia/external/+17328381916 Standard HANGUP, cause: ALLOTTED_TIMEOUT
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:575 (sofia/external/+17328381916) State HANGUP going to sleep
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:356 (sofia/external/+17328381916) State Change CS_HANGUP -> CS_REPORTING
2011-06-30 17:29:30.033269 [DEBUG] switch_core_session.c:1118 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:325 (sofia/external/+17328381916) Running State Change CS_REPORTING
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:635 (sofia/external/+17328381916) State REPORTING
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:53 sofia/external/+17328381916 Standard REPORTING, cause: ALLOTTED_TIMEOUT
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:635 (sofia/external/+17328381916) State REPORTING going to sleep
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:350 (sofia/external/+17328381916) State Change CS_REPORTING -> CS_DESTROY
2011-06-30 17:29:30.033269 [DEBUG] switch_core_session.c:1118 Send signal sofia/external/+17328381916 [BREAK]
2011-06-30 17:29:30.033269 [DEBUG] switch_core_session.c:1290 Session 199 (sofia/external/+17328381916) Locked, Waiting on external entities
2011-06-30 17:29:30.033269 [NOTICE] switch_core_session.c:1308 Session 199 (sofia/external/+17328381916) Ended
2011-06-30 17:29:30.033269 [NOTICE] switch_core_session.c:1310 Close Channel sofia/external/+17328381916 [CS_DESTROY]
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:464 (sofia/external/+17328381916) Callstate Change HANGUP -> DOWN
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:467 (sofia/external/+17328381916) Running State Change CS_DESTROY
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:477 (sofia/external/+17328381916) State DESTROY
2011-06-30 17:29:30.033269 [DEBUG] mod_sofia.c:363 sofia/external/+17328381916 SOFIA DESTROY
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:60 sofia/external/+17328381916 Standard DESTROY
2011-06-30 17:29:30.033269 [DEBUG] switch_core_state_machine.c:477 (sofia/external/+17328381916) State DESTROY going to sleep
@mike-plivo
Copy link
Member

In call_params, can you give us the TimeLimit set ?

@mike-plivo
Copy link
Member

ok seems a bug in TimeLimit, can you update plivo to last commit and test again ?

@mattwilliamson
Copy link
Contributor Author

call_params:

{
    'To': u'+17328381916',
     'HangupUrl': 'http://api.telapia.com/_plivo/outgoing/hung_up',
     'From': u'555',
     'Gateways': 'sofia/gateway/sip1,user',
     'RingUrl': 'http://api.telapia.com/_plivo/outgoing/ringing/',
     'TimeLimit': '34482',
     'AnswerUrl': 'http://api.telapia.com/_plivo/outgoing/answered',
     'ExtraDialString': 'bridge_early_media=true'
}

@mattwilliamson
Copy link
Contributor Author

I will try it again.

@mattwilliamson
Copy link
Contributor Author

That did it! Thanks for the prompt fix.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@mattwilliamson @mike-plivo