freeswitch@switchtest.teliax.com> recv 902 bytes from udp/[208.139.193.162]:32406 at 20:46:22.808360: ------------------------------------------------------------------------ INVITE sip:3039811234@207.1.2.3 SIP/2.0 Via: SIP/2.0/UDP 192.168.123.103:32406;branch=z9hG4bK-d87543-3a66513de25fa539-1--d87543-;rport Max-Forwards: 70 Contact: To: "3039811234" From: "12345678";tag=87286515 Call-ID: YzdmNGYxNTRjMTg1MmZmMjVmMGNlZGVmMDBkNjIwZDI. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: X-Lite release 1006e stamp 34025 Content-Length: 334 v=0 o=- 0 2 IN IP4 192.168.123.103 s=CounterPath X-Lite 3.0 c=IN IP4 192.168.123.103 t=0 0 m=audio 42640 RTP/AVP 107 119 0 98 8 3 101 a=alt:1 1 : TcabT742 u0HVoobW 192.168.123.103 42640 a=fmtp:101 0-15 a=rtpmap:107 BV32/16000 a=rtpmap:119 BV32-FEC/16000 a=rtpmap:98 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv ------------------------------------------------------------------------ send 382 bytes to udp/[208.139.193.162]:32406 at 20:46:22.809616: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.123.103:32406;branch=z9hG4bK-d87543-3a66513de25fa539-1--d87543-;rport=32406;received=208.139.193.162 From: "12345678";tag=87286515 To: "3039811234" Call-ID: YzdmNGYxNTRjMTg1MmZmMjVmMGNlZGVmMDBkNjIwZDI. CSeq: 1 INVITE User-Agent: FreeSWITCH(mod_sofia) Content-Length: 0 ------------------------------------------------------------------------ 2006-12-20 13:46:22 [NOTICE] switch_channel.c:347 switch_channel_set_name() New Chan sofia/zteliax.com/vulpyne@207.1.2.3 [380f0527-6b90-db11-9177-00142272da49] 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:2518 sip_i_state() Channel sofia/zteliax.com/vulpyne@207.1.2.3 entering state [received] 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:2523 sip_i_state() Remote SDP: v=0 o=- 0 2 IN IP4 192.168.123.103 s=CounterPath X-Lite 3.0 c=IN IP4 192.168.123.103 t=0 0 m=audio 42640 RTP/AVP 107 119 0 98 8 3 101 a=rtpmap:107 BV32/16000 a=rtpmap:119 BV32-FEC/16000 a=rtpmap:98 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=alt:1 1 : TcabT742 u0HVoobW 192.168.123.103 42640 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:2169 negotiate_sdp() Codec Compare [BV32:107]/[PCMU:0] 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:2169 negotiate_sdp() Codec Compare [BV32-FEC:119]/[PCMU:0] 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:2169 negotiate_sdp() Codec Compare [PCMU:0]/[PCMU:0] 2006-12-20 13:46:22 [INFO] mod_sofia.c:1368 tech_set_codec() Set Codec sofia/zteliax.com/vulpyne@207.1.2.3 PCMU/8000 20 ms 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:2641 sip_i_state() sofia/zteliax.com/vulpyne@207.1.2.3 State Change CS_NEW -> CS_INIT 2006-12-20 13:46:22 [DEBUG] switch_core.c:2945 switch_core_session_run() (sofia/zteliax.com/vulpyne@207.1.2.3) State INIT 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:1119 sofia_on_init() SOFIA INIT 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:1130 sofia_on_init() sofia/zteliax.com/vulpyne@207.1.2.3 State Change CS_INIT -> CS_RING 2006-12-20 13:46:22 [DEBUG] switch_core.c:2981 switch_core_session_run() (sofia/zteliax.com/vulpyne@207.1.2.3) State RING 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:1146 sofia_on_ring() SOFIA RING 2006-12-20 13:46:22 [DEBUG] switch_core.c:2622 switch_core_standard_on_ring() Standard RING sofia/zteliax.com/vulpyne@207.1.2.3 2006-12-20 13:46:22 [INFO] mod_dialplan_xml.c:209 dialplan_hunt() Processing 12345678->3039811234! 2006-12-20 13:46:22 [DEBUG] mod_dialplan_xml.c:120 parse_exten() test conditions source(mod_sofia) =~ /mod_sofia/ send 589 bytes to udp/[208.139.193.162]:32406 at 20:46:22.817081: 2006-12-20 13:46:22 [DEBUG] mod_dialplan_xml.c:120 parse_exten() test conditions destination_number(3039811234) =~ /tones/ 2006-12-20 13:46:22 [DEBUG] mod_dialplan_xml.c:122 parse_exten() Regex mismatch ------------------------------------------------------------------------ 2006-12-20 13:46:22 [DEBUG] mod_dialplan_xml.c:120 parse_exten() test conditions source(mod_sofia) =~ /mod_sofia/ 2006-12-20 13:46:22 [DEBUG] mod_dialplan_xml.c:120 parse_exten() test conditions destination_number(3039811234) =~ /^([^0][0-9]+)$/ SIP/2.0 180 Ringing2006-12-20 13:46:22 [DEBUG] mod_dialplan_xml.c:328 dialplan_hunt() sofia/zteliax.com/vulpyne@207.1.2.3 State Change CS_RING -> CS_EXECUTE 2006-12-20 13:46:22 [DEBUG] switch_core.c:3017 switch_core_session_run() (sofia/zteliax.com/vulpyne@207.1.2.3) State EXECUTE 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:1164 sofia_on_execute() SOFIA EXECUTE 2006-12-20 13:46:22 [DEBUG] switch_core.c:2673 switch_core_standard_on_execute() Standard EXECUTE Via: SIP/2.0/UDP 192.168.123.103:32406;branch=z9hG4bK-d87543-3a66513de25fa539-1--d87543-;rport=32406;received=208.139.193.1622006-12-20 13:46:22 [NOTICE] switch_core.c:2683 switch_core_standard_on_execute() Execute set(effective_caller_id_number=3039811234) 2006-12-20 13:46:22 [DEBUG] mod_dptools.c:134 set_function() SET [effective_caller_id_number]=[3039811234] nua: nua_r_invite with invalid handle 0x0 2006-12-20 13:46:22 [NOTICE] switch_core.c:2683 switch_core_standard_on_execute() Execute set(effective_caller_id_name=Test) 2006-12-20 13:46:22 [DEBUG] mod_dptools.c:134 set_function() SET [effective_caller_id_name]=[Test] 2006-12-20 13:46:22 [NOTICE] switch_core.c:2683 switch_core_standard_on_execute() Execute ringback() From: "12345678";tag=872865152006-12-20 13:46:22 [NOTICE] mod_dptools.c:71 ringback_function() Ringback sofia/zteliax.com/vulpyne@207.1.2.3! 2006-12-20 13:46:22 [NOTICE] switch_core.c:2683 switch_core_standard_on_execute() Execute bridge(sofia/sip/3039811234@pri01.teliax.com) 2006-12-20 13:46:22 [NOTICE] switch_channel.c:347 switch_channel_set_name() New Chan sofia/sip/3039811234@pri01.teliax.com [14a60527-6b90-db11-9177-00142272da49] To: "3039811234" ;tag=6X7v7mFtQFU3F 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:2113 sofia_outgoing_channel() sofia/sip/3039811234@pri01.teliax.com State Change CS_NEW -> CS_INIT 2006-12-20 13:46:22 [DEBUG] switch_core.c:2945 switch_core_session_run() (sofia/sip/3039811234@pri01.teliax.com) State INIT 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:1119 sofia_on_init() SOFIA INIT 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:1130 sofia_on_init() sofia/sip/3039811234@pri01.teliax.com State Change CS_INIT -> CS_RING Call-ID: YzdmNGYxNTRjMTg1MmZmMjVmMGNlZGVmMDBkNjIwZDI.2006-12-20 13:46:22 [DEBUG] switch_ivr.c:2568 switch_ivr_originate() Raw Codec Activation Success L16@8000hz 1 channel 20ms 2006-12-20 13:46:22 [DEBUG] switch_core.c:2981 switch_core_session_run() (sofia/sip/3039811234@pri01.teliax.com) State RING CSeq: 1 INVITE2006-12-20 13:46:22 [DEBUG] mod_sofia.c:1146 sofia_on_ring() SOFIA RING 2006-12-20 13:46:22 [DEBUG] switch_ivr.c:1975 audio_bridge_on_ring() CUSTOM RING Contact: 2006-12-20 13:46:22 [DEBUG] switch_ivr.c:1978 audio_bridge_on_ring() sofia/sip/3039811234@pri01.teliax.com State Change CS_RING -> CS_HOLD 2006-12-20 13:46:22 [DEBUG] switch_core.c:3126 switch_core_session_run() (sofia/sip/3039811234@pri01.teliax.com) State HOLD 2006-12-20 13:46:22 [DEBUG] switch_ivr.c:1989 audio_bridge_on_hold() CUSTOM HOLD User-Agent: FreeSWITCH(mod_sofia) Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO Supported: 100rel, precondition Content-Length: 0 ------------------------------------------------------------------------ 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:4347 event_callback() event [nua_i_state] status [180][Ringing] session: sofia/zteliax.com/vulpyne@207.1.2.3 2006-12-20 13:46:22 [DEBUG] mod_sofia.c:2518 sip_i_state() Channel sofia/zteliax.com/vulpyne@207.1.2.3 entering state [early] nta_agent: received garbage from udp/208.139.193.162:5060/sip ^Z [1]+ Stopped TPORT_LOG=1 bin/freeswitch