freeswitch@svidev06b> tport_wakeup_pri(0x8091130): events IN tport_recv_event(0x8091130) tport_recv_iovec(0x8091130) msg 0x80c31a8 from (udp/10.133.92.53:5060) has 908 bytes, veclen = 1 recv 908 bytes from udp/[10.60.2.20]:21778 at 15:04:13.241975: ------------------------------------------------------------------------ INVITE sip:5399@svidev06b.tst33.cvf SIP/2.0 Via: SIP/2.0/UDP 10.60.2.20:21778;branch=z9hG4bK-d87543-0c39062a9d626d65-1--d87543- Max-Forwards: 70 Contact: To: "5399" From: "key2";tag=c1788339 Call-ID: ZmZjNTAxOWEwMWY2YThmMDhhYmYxMDllMzllZmRhNGE. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: X-Lite release 1011s stamp 41150 Content-Length: 369 v=0 o=- 8 2 IN IP4 10.60.2.20 s=CounterPath X-Lite 3.0 c=IN IP4 10.60.2.20 t=0 0 m=audio 45136 RTP/AVP 100 106 0 105 8 101 a=fmtp:101 0-15 a=rtpmap:100 SPEEX/16000 a=rtpmap:106 SPEEX-FEC/16000 a=rtpmap:105 SPEEX-FEC/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv m=video 26324 RTP/AVP 34 a=fmtp:34 QCIF=1 MaxBR=1960 a=rtpmap:34 H263/90000 a=sendrecv ------------------------------------------------------------------------ tport_deliver(0x8091130): msg 0x80c31a8 (908 bytes) from udp/10.60.2.20:5060/sip next=(nil) nta: received INVITE sip:5399@svidev06b.tst33.cvf SIP/2.0 (CSeq 1) nta: INVITE (1) going to a default leg nta: timer set to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x808e7b8, 0x808e4e0, 0x80c7cc0) called soa_set_params(static::0x80ca310, ...) called soa_set_params(static::0x80ca310, ...) called nta_leg_create(0x80c7c18) soa_init_offer_answer(static::0x80ca310) called soa_set_remote_sdp(static::0x80ca310, (nil), 0x80959eb, 369) called nua(0x80c7cc0): adding session usage tport_tsend(0x8091130) tpn = UDP/10.60.2.20:21778 tport_resolve addrinfo = 10.60.2.20:21778 tport_by_addrinfo(0x8091130): not found by name UDP/10.60.2.20:21778 tport_vsend(0x8091130): 331 bytes of 331 to UDP/10.60.2.20:21778 tport_vsend returned 331 send 331 bytes to udp/[10.60.2.20]:21778 at 15:04:13.243270: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.60.2.20:21778;branch=z9hG4bK-d87543-0c39062a9d626d65-1--d87543- From: "key2";tag=c1788339 To: "5399" Call-ID: ZmZjNTAxOWEwMWY2YThmMDhhYmYxMDllMzllZmRhNGE. CSeq: 1 INVITE User-Agent: FreeSWITCH(mod_sofia) Content-Length: 0 ------------------------------------------------------------------------ nta: sent 100 Trying for INVITE (1) nua(0x80c7cc0): event i_invite 100 Trying nua(0x80c7cc0): call state changed: init -> received, received offer soa_get_remote_sdp(static::0x80ca310, [0x437c8de8], [0x437c8de4], [(nil)]) called nua(0x80c7cc0): event i_state 100 Trying nua: nua_event: entering nua: nua_handle_bind: entering nua: nua_event: entering 2007-07-24 17:04:13 [NOTICE] switch_channel.c:381 switch_channel_set_name() New Chan sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 [23abc980-39f7-11dc-b76a-7f299aba097e] 2007-07-24 17:04:13 [DEBUG] sofia.c:1028 sofia_handle_sip_i_state() Channel sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 entering state [received] 2007-07-24 17:04:13 [DEBUG] sofia.c:1032 sofia_handle_sip_i_state() Remote SDP: v=0 o=- 8 2 IN IP4 10.60.2.20 s=CounterPath X-Lite 3.0 c=IN IP4 10.60.2.20 t=0 0 m=audio 45136 RTP/AVP 100 106 0 105 8 101 a=rtpmap:100 SPEEX/16000 a=rtpmap:106 SPEEX-FEC/16000 a=rtpmap:105 SPEEX-FEC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 m=video 26324 RTP/AVP 34 a=rtpmap:34 H263/90000 a=fmtp:34 QCIF=1 MaxBR=1960 2007-07-24 17:04:13 [DEBUG] sofia_glue.c:1202 sofia_glue_negotiate_sdp() Audio Codec Compare [SPEEX:100:16000]/[PCMU:0:8000] 2007-07-24 17:04:13 [DEBUG] sofia_glue.c:1202 sofia_glue_negotiate_sdp() Audio Codec Compare [SPEEX-FEC:106:16000]/[PCMU:0:8000] 2007-07-24 17:04:13 [DEBUG] sofia_glue.c:1202 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[PCMU:0:8000] 2007-07-24 17:04:13 [DEBUG] sofia_glue.c:812 sofia_glue_tech_set_codec() Set Codec sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 PCMU/8000 20 ms 160 samples 2007-07-24 17:04:13 [DEBUG] sofia_glue.c:1166 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101 2007-07-24 17:04:13 [DEBUG] sofia.c:1132 sofia_handle_sip_i_state() sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 State Change CS_NEW -> CS_INIT 2007-07-24 17:04:13 [DEBUG] switch_core_session.c:647 switch_core_session_signal_state_change() Kill sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 [BREAK] 2007-07-24 17:04:13 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() (sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060) State INIT 2007-07-24 17:04:13 [DEBUG] mod_sofia.c:92 sofia_on_init() SOFIA INIT 2007-07-24 17:04:13 [DEBUG] mod_sofia.c:105 sofia_on_init() sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 State Change CS_INIT -> CS_RING 2007-07-24 17:04:13 [DEBUG] switch_core_session.c:647 switch_core_session_signal_state_change() Kill sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 [BREAK] 2007-07-24 17:04:13 [DEBUG] switch_core_state_machine.c:402 switch_core_session_run() (sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060) State RING 2007-07-24 17:04:13 [DEBUG] mod_sofia.c:120 sofia_on_ring() SOFIA RING 2007-07-24 17:04:13 [DEBUG] switch_core_state_machine.c:56 switch_core_standard_on_ring() Standard RING sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 2007-07-24 17:04:13 [INFO] mod_dialplan_xml.c:316 dialplan_hunt() Processing key2->5399! 2007-07-24 17:04:13 [DEBUG] mod_dialplan_xml.c:116 parse_exten() test conditions destination_number(5399) =~ /^5391$/ 2007-07-24 17:04:13 [DEBUG] mod_dialplan_xml.c:118 parse_exten() Regex mismatch 2007-07-24 17:04:13 [DEBUG] mod_dialplan_xml.c:116 parse_exten() test conditions destination_number(5399) =~ /^5390$/ 2007-07-24 17:04:13 [DEBUG] mod_dialplan_xml.c:118 parse_exten() Regex mismatch 2007-07-24 17:04:13 [DEBUG] mod_dialplan_xml.c:116 parse_exten() test conditions destination_number(5399) =~ /^5399$/ 2007-07-24 17:04:13 [DEBUG] mod_dialplan_xml.c:372 dialplan_hunt() sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 State Change CS_RING -> CS_EXECUTE 2007-07-24 17:04:13 [DEBUG] switch_core_session.c:647 switch_core_session_signal_state_change() Kill sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 [BREAK] 2007-07-24 17:04:13 [DEBUG] switch_core_state_machine.c:437 switch_core_session_run() (sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060) State EXECUTE 2007-07-24 17:04:13 [DEBUG] mod_sofia.c:137 sofia_on_execute() SOFIA EXECUTE 2007-07-24 17:04:13 [DEBUG] switch_core_state_machine.c:113 switch_core_standard_on_execute() Standard EXECUTE 2007-07-24 17:04:13 [NOTICE] switch_core_state_machine.c:123 switch_core_standard_on_execute() Execute answer() 2007-07-24 17:04:13 [DEBUG] sofia_glue.c:876 sofia_glue_activate_rtp() AUDIO RTP [sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060] 10.133.92.53:16386->10.60.2.20:45136 codec: 0 ms: 20 2007-07-24 17:04:13 [DEBUG] switch_rtp.c:538 switch_rtp_create() Starting timer [soft] 160 bytes per 20000ms 2007-07-24 17:04:13 [DEBUG] mod_sofia.c:317 sofia_answer_channel() Local SDP sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060: v=0 o=FreeSWITCH 1185273067 1185273068 IN IP4 10.133.92.53 s=FreeSWITCH c=IN IP4 10.133.92.53 t=0 0 a=sendrecv m=audio 16386 RTP/AVP 0 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 nua: nua_respond: entering nua(0x80c7cc0): signal r_respond nua(0x80c7cc0): recv r_respond nua(0x80c7cc0): signal r_respond 200 OK nua: nua_stack_set_params: entering soa_set_params(static::0x80ca310, ...) called soa_set_user_sdp(static::0x80ca310, (nil), 0x80b9a6c, -1) called soa_set_capability_sdp(static::0x80ca310, (nil), 0x80b9a6c, -1) called nua: nua_invite_server_respond: entering soa_generate_answer(static::0x80ca310) called soa_static_offer_answer_action(0x80ca310, soa_generate_answer): called soa_static(0x80ca310, soa_generate_answer): generating local description soa_static(0x80ca310, soa_generate_answer): upgrade with remote description soa_static(0x80ca310, soa_generate_answer): marking rejected media soa_sdp_mode_set_is_needed(0x437c9104, 0x80c0190, ""): called soa_static(0x80ca310, soa_generate_answer): storing local description soa_activate(static::0x80ca310, (nil)) called soa_get_local_sdp(static::0x80ca310, [(nil)], [0x437c9218], [0x437c9214]) called tport_tsend(0x8091130) tpn = UDP/10.60.2.20:21778 tport_resolve addrinfo = 10.60.2.20:21778 tport_by_addrinfo(0x8091130): not found by name UDP/10.60.2.20:21778 tport_vsend(0x8091130): 914 bytes of 914 to UDP/10.60.2.20:21778 tport_vsend returned 914 send 914 bytes to udp/[10.60.2.20]:21778 at 15:04:13.252074: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.60.2.20:21778;branch=z9hG4bK-d87543-0c39062a9d626d65-1--d87543- From: "key2";tag=c1788339 To: "5399" ;tag=UgUc3e5c45BBp Call-ID: ZmZjNTAxOWEwMWY2YThmMDhhYmYxMDllMzllZmRhNGE. CSeq: 1 INVITE Contact: User-Agent: FreeSWITCH(mod_sofia) Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition Content-Type: application/sdp Content-Disposition: session Content-Length: 295 v=0 o=FreeSWITCH 1151807409329099377 5176940148824763350 IN IP4 10.133.92.53 s=FreeSWITCH c=IN IP4 10.133.92.53 t=0 0 a=sendrecv m=audio 16386 RTP/AVP 0 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 m=video 0 RTP/AVP 9 ------------------------------------------------------------------------ nta: sent 200 OK for INVITE (1) nua(0x80c7cc0): call state changed: received -> completed, sent answer soa_get_local_sdp(static::0x80ca310, [0x437c9290], [0x437c928c], [(nil)]) called soa_get_params(static::0x80ca310, ...) called nua(0x80c7cc0): event i_state 200 OK nua: nua_event: entering 2007-07-24 17:04:13 [DEBUG] sofia.c:1028 sofia_handle_sip_i_state() Channel sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 entering state [completed] 2007-07-24 17:04:13 [DEBUG] switch_core_session.c:349 switch_core_session_receive_message() Kill sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 [BREAK] 2007-07-24 17:04:13 [NOTICE] mod_dptools.c:286 answer_function() Channel [sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060] has been answered 2007-07-24 17:04:13 [NOTICE] switch_core_state_machine.c:123 switch_core_standard_on_execute() Execute sleep(1000) nta: timer set next to 311 ms tport_wakeup_pri(0x8091130): events IN tport_recv_event(0x8091130) tport_recv_iovec(0x8091130) msg 0x80c42d8 from (udp/10.133.92.53:5060) has 438 bytes, veclen = 1 recv 438 bytes from udp/[10.60.2.20]:21778 at 15:04:13.455802: ------------------------------------------------------------------------ ACK sip:mod_sofia@10.133.92.53:5060 SIP/2.0 Via: SIP/2.0/UDP 10.60.2.20:21778;branch=z9hG4bK-d87543-7a6d3459233fa445-1--d87543- Max-Forwards: 70 Contact: To: "5399";tag=UgUc3e5c45BBp From: "key2";tag=c1788339 Call-ID: ZmZjNTAxOWEwMWY2YThmMDhhYmYxMDllMzllZmRhNGE. CSeq: 1 ACK User-Agent: X-Lite release 1011s stamp 41150 Content-Length: 0 ------------------------------------------------------------------------ tport_deliver(0x8091130): msg 0x80c42d8 (438 bytes) from udp/10.60.2.20:5060/sip next=(nil) nta: received ACK sip:mod_sofia@10.133.92.53:5060 SIP/2.0 (CSeq 1) nta: ACK (1) is going to INVITE (1) nua: process_ack_or_cancel: entering soa_clear_remote_sdp(static::0x80ca310) called nua(0x80c7cc0): event i_ack 200 OK nua(0x80c7cc0): call state changed: completed -> ready nua(0x80c7cc0): event i_state 200 OK nua(0x80c7cc0): event i_active 200 Call active nua: nua_event: entering nua: nua_event: entering nua: nua_event: entering 2007-07-24 17:04:13 [DEBUG] sofia.c:1028 sofia_handle_sip_i_state() Channel sofia/mydomain.com/key2@svidev06b.tst33.cvf:5060 entering state [ready] nta: timer set next to 4703 ms 2007-07-24 17:04:14 [NOTICE] switch_core_state_machine.c:123 switch_core_standard_on_execute() Execute bridge(openzap/1/0/0614062706) nta: timer I fired, terminate 200 response incoming_reclaim_all((nil), (nil), 0x437c9208) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer not set