[Freeswitch-users] Calls drop immediately when terminator forces G.729 Codec.
Jim Burke
jim at evolutiontel.net
Thu Jun 4 16:15:08 PDT 2009
Hi Anthony,
Traces as requested. Let me know if you want a jira opened or any further data.
Regards,
Jim
On Thu, Jun 4, 2009 at 10:59 PM, Anthony Minessale
<anthony.minessale at gmail.com> wrote:
> you should have also turned in the sip trace
> sofia profile internal siptrace on
>
>
> On Thu, Jun 4, 2009 at 7:43 AM, Jim Burke <jim at evolutiontel.net> wrote:
>>
>> Hi All,
>>
>> Looking for some debugging tips and comments on what might be causing
>> the media port in the 200OK ( Answer message) to be set to 0 by
>> freeswitch. Essentially it looks like data might be getting trampled
>> somehow.
>>
>> Portion of 200OK going into Freeswitch
>> m=audio 16416 RTP/AVP 18 100 101..a=rtpmap:18 G729a/8000..a=rtpmap:100
>> NSE/8000..a=
>> fmtp:100 192-193..a=rtpmap:101 telephone-event/8000..a=fmtp:101
>> 0-15..a=ptime:20..a=sendrecv..
>>
>> Portion of 200OK coming out of Freeswitch
>> m=audio 0 RTP/AVP 96 100 101..a=rtpmap:96 G729a/8000..a=rtpmap:100
>> NSE/8000..a=fmtp:100 192-193..a=rtpmap:101 telephone-event
>> /8000..a=fmtp:101 0-15..
>>
>> Note the media port has been set to 0 and the rtpmap for G729 is also
>> not correct. On receipt of this bad 200Ok the originator sends a BYE.
>>
>> We are using FS as a B2BUA with bypass_media set to true. Thus IMHO
>> Freeswitch should not be touching the SDP portion of the message and
>> just passing it through.
>>
>> This can reproduce this at will, so I can collect whatever data is
>> nessicary. I have added the sofia debug from the console.
>>
>> Thanks,
>> --
>> Jim Burke
>> Director Evolutiontel.
>> http://www.evolutiontel.net
>>
>> _______________________________________________
>> Freeswitch-users mailing list
>> Freeswitch-users at lists.freeswitch.org
>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>> http://www.freeswitch.org
>>
>
>
>
> --
> Anthony Minessale II
>
> FreeSWITCH http://www.freeswitch.org/
> ClueCon http://www.cluecon.com/
>
> AIM: anthm
> MSN:anthony_minessale at hotmail.com
> GTALK/JABBER/PAYPAL:anthony.minessale at gmail.com
> IRC: irc.freenode.net #freeswitch
>
> FreeSWITCH Developer Conference
> sip:888 at conference.freeswitch.org
> iax:guest at conference.freeswitch.org/888
> googletalk:conf+888 at conference.freeswitch.org
> pstn:213-799-1400
>
> _______________________________________________
> Freeswitch-users mailing list
> Freeswitch-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
--
Jim Burke
Director Evolutiontel.
http://www.evolutiontel.net
-------------- next part --------------
login as: root
root at 202.xxx.xx.xx's password:
Last login: Thu Jun 4 21:56:36 2009 from 60-241-91-137.static.tpgi.com.au
[root at sip01 ~]# cd /usr/local/freeswitch/bin
[root at sip01 bin]# ./fs_cli
_____ ____ ____ _ ___
| ___/ ___| / ___| | |_ _|
| |_ \___ \ | | | | | |
| _| ___) | | |___| |___ | |
|_| |____/ \____|_____|___|
*****************************************************
* Anthony Minessale II, Ken Rice, Michael Jerris *
* FreeSWITCH (http://www.freeswitch.org) *
* Brought to you by ClueCon http://www.cluecon.com/ *
*****************************************************
Type /help <enter> to see a list of commands
+OK log level [7]
freeswitch at internal> sofia
USAGE:
--------------------------------------------------------------------------------
sofia help
sofia profile <profile_name> [[start|stop|restart|rescan] [reloadxml]|flush_inbound_reg [<call_id>] [reboot]|[register|unregister] [<gateway name>|all]|killgw <gateway name>|[stun-auto-disable|stun-enabled] [true|false]]|siptrace [on|off]
sofia status profile <name> [ reg <contact str> ] | [ pres <pres str> ]
sofia status gateway <name>
sofia loglevel <all|default|tport|iptsec|nea|nta|nth_client|nth_server|nua|soa|sresolv|stun> [0-9]
--------------------------------------------------------------------------------
freeswitch at internal> sofia loglevel all 9
Sofia log level for component [all] has been set to [9]
freeswitch at internal> sofia profile internal siptrace on
Enabled sip debugging on internal
nua: nua_set_params: entering
freeswitch at internal> nua((nil)): sent signal r_set_params
nua((nil)): recv signal r_set_params
nua: nua_stack_set_params: entering
soa_set_params(static::0x9baf508, ...) called
nua((nil)): event r_set_params 200 OK
nua: nua_application_event: entering
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9bcba58 from (udp/192.168.0.2:5070) has 1299 bytes, veclen = 1
recv 1299 bytes from udp/[192.168.0.2]:5060 at 23:06:35.605391:
------------------------------------------------------------------------
INVITE sip:0631000001 at 192.168.0.2:5060 SIP/2.0
Record-Route: <sip:192.168.0.2;r2=on;lr=on;ftag=50f70f41-co453-INS001;vsf=czFwOldpejRyZCFzMXA6FjA4NC8hYC58N30LNDRkLnx/FkU-;did=1e1.1ee44d26>
Record-Route: <sip:202.xxx.xx.xx;r2=on;lr=on;ftag=50f70f41-co453-INS001;vsf=czFwOldpejRyZCFzMXA6FjA4NC8hYC58N30LNDRkLnx/FkU-;did=1e1.1ee44d26>
Via: SIP/2.0/UDP 192.168.0.2;branch=z9hG4bK92ec.85e18692.0
Via: SIP/2.0/UDP 202.xx.xxx.xx:5060;branch=z9hG4bK1ca53b7214a28536c-b0f5-0
Max-Forwards: 69
Contact: <sip:0445674567 at 202.xx.xxx.xx:5060>
To: <sip:0312341234 at 202.xxx.xx.xx:5060>
From: "0445674567"<sip:0445674567 at sip.evolutiontel.net>;tag=50f70f41-co453-INS001
Call-ID: 2619-475-54200923635-IMG01-0-202.83.183.46
CSeq: 45301 INVITE
Content-Type: application/sdp
Date: Thu, 04 Jun 2009 23:06:20 GMT
Supported: 100rel
User-Agent: ENSR2.5.4
Content-Length: 288
P-Incoming-GW: Yes
P-Incoming-GW: Yes
X-Max-TIMER: 7200
X-Source_IP: 202.xx.xxx.xx
P-Asserted-Identity: <sip:0445674567 at sip.evolutiontel.net>
v=0
o=- 1358368577 1358368577 IN IP4 202.xx.xxx.xx
s=ENSResip
c=IN IP4 202..xxx.xx.xx
t=0 0
m=audio 12580 RTP/AVP 18 8 0 101
a=fmtp:101 0-15
a=rtpmap:18 G729/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=silenceSupp:off - - - -
a=sendrecv
------------------------------------------------------------------------
tport_deliver(0x9bb0e28): msg 0x9bcba58 (1299 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received INVITE sip:0631000001 at 192.168.0.2:5060 SIP/2.0 (CSeq 45301)
nta: INVITE (45301) 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::0x9baf508, 0x9b9a050, 0x9ccc130) called
soa_set_params(static::0x9c1d4e8, ...) called
nta_leg_tcreate(0x9c41a68)
soa_init_offer_answer(static::0x9c1d4e8) called
soa_set_remote_sdp(static::0x9c1d4e8, (nil), 0x9c85df3, 288) called
nua(0x9ccc130): adding session usage
tport_tsend(0x9bb0e28) tpn = UDP/192.168.0.2:5060
tport_resolve addrinfo = 192.168.0.2:5060
tport_by_addrinfo(0x9bb0e28): not found by name UDP/192.168.0.2:5060
tport_vsend(0x9bb0e28): 698 bytes of 698 to udp/192.168.0.2:5060
tport_vsend returned 698
send 698 bytes to udp/[192.168.0.2]:5060 at 23:06:35.624664:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.0.2;branch=z9hG4bK92ec.85e18692.0
Via: SIP/2.0/UDP 202.xx.xxx.xx:5060;branch=z9hG4bK1ca53b7214a28536c-b0f5-0
Record-Route: <sip:192.168.0.2;r2=on;lr=on;ftag=50f70f41-co453-INS001;vsf=czFwOldpejRyZCFzMXA6FjA4NC8hYC58N30LNDRkLnx/FkU-;did=1e1.1ee44d26>
Record-Route: <sip:202.xxx.xx.xx;r2=on;lr=on;ftag=50f70f41-co453-INS001;vsf=czFwOldpejRyZCFzMXA6FjA4NC8hYC58N30LNDRkLnx/FkU-;did=1e1.1ee44d26>
From: "0445674567"<sip:0445674567 at sip.evolutiontel.net>;tag=50f70f41-co453-INS001
To: <sip:0312341234 at 202.xxx.xx.xx:5060>
Call-ID: 2619-475-54200923635-IMG01-0-202.83.183.46
CSeq: 45301 INVITE
User-Agent: Evolutiontel SIP Service
Content-Length: 0
------------------------------------------------------------------------
nta: sent 100 Trying for INVITE (45301)
nua(0x9ccc130): event i_invite 100 Trying
nua(0x9ccc130): call state changed: init -> received, received offer
soa_get_remote_sdp(static::0x9c1d4e8, [0xb77b7bac], [0xb77b7ba8], [(nil)]) called
nua(0x9ccc130): event i_state 100 Trying
nua: nua_application_event: entering
2009-06-05 09:06:35 [NOTICE] switch_channel.c:602 switch_channel_set_name() New Channel sofia/internal/0445674567 at sip.evolutiontel.net [e57f4f54-7b45-48cc-98d3-8b594bdc19e8]
nua: nua_handle_bind: entering
nua: nua_handle_magic: entering
nua: nua_application_event: entering
2009-06-05 09:06:35 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/0445674567 at sip.evolutiontel.net entering state [received][100]
2009-06-05 09:06:35 [DEBUG] sofia.c:3046 sofia_handle_sip_i_state() Remote SDP:
v=0
o=- 1358368577 1358368577 IN IP4 202.xx.xxx.xx
s=ENSResip
c=IN IP4 202..xxx.xx.xx
t=0 0
m=audio 12580 RTP/AVP 18 8 0 101
a=rtpmap:18 G729/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
2009-06-05 09:06:35 [DEBUG] sofia.c:3182 sofia_handle_sip_i_state() (sofia/internal/0445674567 at sip.evolutiontel.net) State Change CS_NEW -> CS_INIT
2009-06-05 09:06:35 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0445674567 at sip.evolutiontel.net [BREAK]
nua: nua_handle_magic: entering
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) Running State Change CS_INIT
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:480 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State INIT
2009-06-05 09:06:35 [DEBUG] mod_sofia.c:83 sofia_on_init() sofia/internal/0445674567 at sip.evolutiontel.net SOFIA INIT
2009-06-05 09:06:35 [DEBUG] mod_sofia.c:111 sofia_on_init() (sofia/internal/0445674567 at sip.evolutiontel.net) State Change CS_INIT -> CS_ROUTING
2009-06-05 09:06:35 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0445674567 at sip.evolutiontel.net [BREAK]
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:480 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State INIT going to sleep
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) Running State Change CS_ROUTING
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State ROUTING
2009-06-05 09:06:35 [DEBUG] mod_sofia.c:130 sofia_on_routing() sofia/internal/0445674567 at sip.evolutiontel.net SOFIA ROUTING
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:78 switch_core_standard_on_routing() sofia/internal/0445674567 at sip.evolutiontel.net Standard ROUTING
2009-06-05 09:06:35 [INFO] mod_dialplan_xml.c:252 dialplan_hunt() Processing 0445674567->0631000001 in context evolutiontel
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->unloop] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->global] continue=true
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [global] ${network_addr}(192.168.0.2) =~ /^$/ break=never
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net ANTI-Action set(use_profile=${cond(${acl(${network_addr} rfc1918)} == true ? nat : default)})
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (PASS) [global] ${numbering_plan}() =~ /^$/ break=never
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action set_user(default@${domain_name})
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [global] ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net ANTI-Action set(bypass_media=true)
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [global] ${sip_h_X-ZRTP-On}() =~ /^Y$/ break=never
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net ANTI-Action set(bypass_media=true)
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [global] ${sip_secure_media}() =~ /^true$/ break=never
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [global] ${sip_user_agent}(ENSR2.5.4) =~ /^PolycomSound(Point|Station)IP-S(S|P)IP_\d{3,4}-UA\/((3).(\d).(\d).(\d{4}))$/ break=never
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Absolute Condition [global]
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->vmain] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [vmain] destination_number(0631000001) =~ /^121/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->vmain1] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [vmain1] destination_number(0631000001) =~ /^123/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->vmain2] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [vmain2] destination_number(0631000001) =~ /^122/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->ivr_demo] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [ivr_demo] destination_number(0631000001) =~ /^5000$/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->park] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [park] destination_number(0631000001) =~ /^5900$/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->unpark] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [unpark] destination_number(0631000001) =~ /^5901$/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->park] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [park] destination_number(0631000001) =~ /park\+(\d+)/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->unpark] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [unpark] destination_number(0631000001) =~ /^parking$/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->park] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [park] destination_number(0631000001) =~ /callpark/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->unpark] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [unpark] destination_number(0631000001) =~ /pickup/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->wait] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [wait] destination_number(0631000001) =~ /^wait$/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->National_calls] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [National_calls] destination_number(0631000001) =~ /^0(2|3|4|5|7|8|9)[0-9]{8}$/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->Special_calls] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [Special_calls] destination_number(0631000001) =~ /^1[3|8][0-9]+$/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->International_calls] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (FAIL) [International_calls] destination_number(0631000001) =~ /^0011[0-9]+$/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net parsing [evolutiontel->On-Net_calls] continue=false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Regex (PASS) [On-Net_calls] destination_number(0631000001) =~ /^063[0-9]{7}$/ break=on-false
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action set(execute_on_answer=sched_hangup +${sip_h_x-max-timer} ALLOTED_TIMEOUT)
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action set(sip_cid_type=pid)
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action set(continue_on_fail=79)
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action bridge({sip_from_uri=sip:${sip_from_uri}}sofia/internal/${sip_req_user}@192.168.0.2^${sip_to_uri})
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action set(bypass_media=false)
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action set(ringback=%(400,200,401,450);%(400,2200,400,450))
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action pre_answer()
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action export(sip_secure_media=true)
Dialplan: sofia/internal/0445674567 at sip.evolutiontel.net Action bridge({sip_from_uri=sip:${sip_from_uri}}sofia/internal/${sip_req_user}@192.168.0.2^${sip_to_uri})
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:114 switch_core_standard_on_routing() (sofia/internal/0445674567 at sip.evolutiontel.net) State Change CS_ROUTING -> CS_EXECUTE
2009-06-05 09:06:35 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0445674567 at sip.evolutiontel.net [BREAK]
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State ROUTING going to sleep
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) Running State Change CS_EXECUTE
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:490 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State EXECUTE
2009-06-05 09:06:35 [DEBUG] mod_sofia.c:173 sofia_on_execute() sofia/internal/0445674567 at sip.evolutiontel.net SOFIA EXECUTE
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:151 switch_core_standard_on_execute() sofia/internal/0445674567 at sip.evolutiontel.net Standard EXECUTE
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net set(use_profile=nat)
2009-06-05 09:06:35 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/0445674567 at sip.evolutiontel.net SET [use_profile]=[nat]
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net set_user(default at 192.168.0.2)
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net set(bypass_media=true)
2009-06-05 09:06:35 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/0445674567 at sip.evolutiontel.net SET [bypass_media]=[true]
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net set(bypass_media=true)
2009-06-05 09:06:35 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/0445674567 at sip.evolutiontel.net SET [bypass_media]=[true]
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net hash(insert/192.168.0.2-spymap/0445674567/e57f4f54-7b45-48cc-98d3-8b594bdc19e8)
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net hash(insert/192.168.0.2-last_dial/0445674567/0631000001)
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net hash(insert/192.168.0.2-last_dial/global/e57f4f54-7b45-48cc-98d3-8b594bdc19e8)
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net set(execute_on_answer=sched_hangup +7200 ALLOTED_TIMEOUT)
2009-06-05 09:06:35 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/0445674567 at sip.evolutiontel.net SET [execute_on_answer]=[sched_hangup +7200 ALLOTED_TIMEOUT]
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net set(sip_cid_type=pid)
2009-06-05 09:06:35 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/0445674567 at sip.evolutiontel.net SET [sip_cid_type]=[pid]
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net set(continue_on_fail=79)
2009-06-05 09:06:35 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/0445674567 at sip.evolutiontel.net SET [continue_on_fail]=[79]
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net bridge({sip_from_uri=sip:0445674567 at sip.evolutiontel.net}sofia/internal/0631000001 at 192.168.0.2^0312341234 at 202.xxx.xx.xx:5060)
2009-06-05 09:06:35 [DEBUG] switch_ivr_originate.c:1017 switch_ivr_originate() variable string 0 = [sip_from_uri=sip:0445674567 at sip.evolutiontel.net]
2009-06-05 09:06:35 [NOTICE] switch_channel.c:602 switch_channel_set_name() New Channel sofia/internal/0631000001 at 192.168.0.2 [d360e71f-64bd-4eb0-b99d-56af3c9e01f0]
2009-06-05 09:06:35 [DEBUG] mod_sofia.c:2719 sofia_outgoing_channel() (sofia/internal/0631000001 at 192.168.0.2) State Change CS_NEW -> CS_INIT
2009-06-05 09:06:35 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0631000001 at 192.168.0.2 [BREAK]
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) Running State Change CS_INIT
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:480 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State INIT
2009-06-05 09:06:35 [DEBUG] mod_sofia.c:83 sofia_on_init() sofia/internal/0631000001 at 192.168.0.2 SOFIA INIT
nua: nh_create_handle: entering
nua: nua_handle_bind: entering
nua: nua_invite: entering
nua(0x9cf7ed0): recv signal r_invite
nua: nua_stack_set_params: entering
soa_clone(static::0x9baf508, 0x9b9a050, 0x9cf7ed0) called
soa_set_params(static::0x9d15ce0, ...) called
soa_set_params(static::0x9d15ce0, ...) called
soa_set_user_sdp(static::0x9d15ce0, (nil), 0x9cd16f7, -1) called
soa_set_capability_sdp(static::0x9d15ce0, (nil), 0x9cd16f7, -1) called
nua(0x9cf7ed0): adding session usage
nta_leg_tcreate(0x9db94b0)
soa_init_offer_answer(static::0x9d15ce0) called
soa_generate_offer(static::0x9d15ce0, 0) called
soa_static_offer_answer_action(0x9d15ce0, soa_generate_offer): called
soa_static(0x9d15ce0, soa_generate_offer): generating local description
soa_static(0x9d15ce0, soa_generate_offer): upgrade with local description
soa_sdp_mode_set(0xb77b7ef4, (nil), ""): called
soa_init_sdp_connection_with_session: selected IN IP4 202.xxx.xx.xx (a local address)
soa_static(0x9d15ce0, soa_generate_offer): storing local description
soa_get_local_sdp(static::0x9d15ce0, [(nil)], [0xb77b7f7c], [0xb77b7f78]) called
nta: selecting scheme sip
tport_tsend(0x9bb0e28) tpn = */192.168.0.2:5060
tport_resolve addrinfo = 192.168.0.2:5060
tport_by_addrinfo(0x9bb0e28): not found by name */192.168.0.2:5060
tport_vsend(0x9bb0e28): 1233 bytes of 1233 to udp/192.168.0.2:5060
tport_vsend returned 1233
send 1233 bytes to udp/[192.168.0.2]:5060 at 23:06:35.639526:
------------------------------------------------------------------------
INVITE sip:0631000001 at 192.168.0.2 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.2:5070;rport;branch=z9hG4bKZa7eS5j4r9a8F
Max-Forwards: 68
From: "0445674567" <sip:0445674567 at sip.evolutiontel.net>;tag=vQ8mytQ2mXNme
To: <sip:0312341234 at 202.xxx.xx.xx:5060>
Call-ID: 315cd1e2-cbff-122c-ee95-00112fcc990a
CSeq: 115960061 INVITE
Contact: <sip:mod_sofia at 192.168.0.2:5070>
User-Agent: Evolutiontel SIP Service
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH
Supported: timer, precondition, path, replaces
Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Privacy: none
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 294
P-Incoming-GW: Yes
P-Incoming-GW-1: Yes
X-Max-TIMER: 7200
X-Source_IP: 202.xx.xxx.xx
P-Asserted-Identity: "0445674567" <sip:0445674567 at 192.168.0.2>
v=0
o=- 7279717662006744601 8597592345307020033 IN IP4 202.xxx.xx.xx
s=ENSResip
c=IN IP4 202..xxx.xx.xx
t=0 0
m=audio 12580 RTP/AVP 18 8 0 101
a=rtpmap:18 G729/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=silenceSupp:off - - - -
------------------------------------------------------------------------
nta: sent INVITE (115960061) to */192.168.0.2:5060
tport_pend(0x9bb0e28): pending 0x9c63a58 for udp/192.168.0.2:5070 (already 0)
nua(0x9cf7ed0): call state changed: init -> calling, sent offer
soa_get_local_sdp(static::0x9d15ce0, [0xb77b7fa4], [0xb77b7fa0], [(nil)]) called
nua(0x9cf7ed0): event i_state INVITE sent
nua: nua_application_event: entering
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9c633c8 from (udp/192.168.0.2:5070) has 303 bytes, veclen = 1
recv 303 bytes from udp/[192.168.0.2]:5060 at 23:06:35.640683:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.0.2:5070;rport=5070;branch=z9hG4bKZa7eS5j4r9a8F
From: "0445674567" <sip:0445674567 at sip.evolutiontel.net>;tag=vQ8mytQ2mXNme
To: <sip:0312341234 at 202.xxx.xx.xx:5060>
Call-ID: 315cd1e2-cbff-122c-ee95-00112fcc990a
CSeq: 115960061 INVITE
Content-Length: 0
------------------------------------------------------------------------
tport_deliver(0x9bb0e28): msg 0x9c633c8 (303 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received 100 Trying for INVITE (115960061)
nta: 100 Trying is going to a transaction
nta_outgoing: RTT is 1.405 ms
tport_release(0x9bb0e28): 0x9c63a58 by 0x9bcc770 with 0x9c633c8 (preliminary)
nua(0x9cf7ed0): sent signal r_invite
2009-06-05 09:06:35 [DEBUG] mod_sofia.c:111 sofia_on_init() (sofia/internal/0631000001 at 192.168.0.2) State Change CS_INIT -> CS_ROUTING
2009-06-05 09:06:35 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0631000001 at 192.168.0.2 [BREAK]
2009-06-05 09:06:35 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/0631000001 at 192.168.0.2 entering state [calling][0]
nua: nua_handle_magic: entering
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:480 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State INIT going to sleep
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) Running State Change CS_ROUTING
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State ROUTING
2009-06-05 09:06:35 [DEBUG] mod_sofia.c:130 sofia_on_routing() sofia/internal/0631000001 at 192.168.0.2 SOFIA ROUTING
2009-06-05 09:06:35 [DEBUG] switch_ivr_originate.c:63 originate_on_routing() (sofia/internal/0631000001 at 192.168.0.2) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2009-06-05 09:06:35 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0631000001 at 192.168.0.2 [BREAK]
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State ROUTING going to sleep
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) Running State Change CS_CONSUME_MEDIA
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:502 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State CONSUME_MEDIA
2009-06-05 09:06:35 [DEBUG] switch_core_state_machine.c:502 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State CONSUME_MEDIA going to sleep
nta: timer not set
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9c633c8 from (udp/192.168.0.2:5070) has 714 bytes, veclen = 1
recv 714 bytes from udp/[192.168.0.2]:5060 at 23:06:35.925933:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
To: <sip:0312341234 at 202.xxx.xx.xx:5060>;tag=f936c99a6bd026a9i0
From: "0445674567" <sip:0445674567 at sip.evolutiontel.net>;tag=vQ8mytQ2mXNme
Call-ID: 315cd1e2-cbff-122c-ee95-00112fcc990a
CSeq: 115960061 INVITE
Via: SIP/2.0/UDP 192.168.0.2:5070;received=192.168.0.2;rport=5070;branch=z9hG4bKZa7eS5j4r9a8F
Record-Route: <sip:202.125.40.17;r2=on;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.0faf3ae2>
Record-Route: <sip:192.168.0.3;r2=on;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.0faf3ae2>
Record-Route: <sip:192.168.0.2;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.733ef665>
Server: Linksys/SPA3000-3.1.20(GW)
Remote-Party-ID: 0631000001 <sip:0631000001 at sip.evolutiontel.net>;screen=yes;party=called
Content-Length: 0
------------------------------------------------------------------------
tport_deliver(0x9bb0e28): msg 0x9c633c8 (714 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received 180 Ringing for INVITE (115960061)
nta: 180 Ringing is going to a transaction
tport_release(0x9bb0e28): 0x9c63a58 by 0x9bcc770 with 0x9c633c8 (preliminary)
nua(0x9cf7ed0): event r_invite 180 Ringing
nua(0x9cf7ed0): call state changed: calling -> proceeding
nua(0x9cf7ed0): event i_state 180 Ringing
nua: nua_application_event: entering
nua: nua_handle_magic: entering
nua: nua_application_event: entering
2009-06-05 09:06:35 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/0631000001 at 192.168.0.2 entering state [proceeding][180]
2009-06-05 09:06:35 [NOTICE] sofia.c:3103 sofia_handle_sip_i_state() Ring-Ready sofia/internal/0631000001 at 192.168.0.2!
2009-06-05 09:06:35 [DEBUG] sofia.c:3111 sofia_handle_sip_i_state() sofia/internal/0445674567 at sip.evolutiontel.net receive message [RINGING]
nua: nua_respond: entering
nua(0x9ccc130): sent signal r_respond
2009-06-05 09:06:35 [NOTICE] mod_sofia.c:1422 sofia_receive_message() Ring-Ready sofia/internal/0445674567 at sip.evolutiontel.net!
2009-06-05 09:06:35 [DEBUG] switch_core_session.c:630 switch_core_session_perform_receive_message() Send signal sofia/internal/0445674567 at sip.evolutiontel.net [BREAK]
nua: nua_handle_magic: entering
nua(0x9ccc130): recv signal r_respond 180 Ringing
nua: nua_stack_set_params: entering
soa_set_params(static::0x9c1d4e8, ...) called
nua: nua_invite_server_respond: entering
tport_tsend(0x9bb0e28) tpn = UDP/192.168.0.2:5060
tport_resolve addrinfo = 192.168.0.2:5060
tport_by_addrinfo(0x9bb0e28): not found by name UDP/192.168.0.2:5060
tport_vsend(0x9bb0e28): 1125 bytes of 1125 to udp/192.168.0.2:5060
tport_vsend returned 1125
send 1125 bytes to udp/[192.168.0.2]:5060 at 23:06:35.927247:
------------------------------------------------------------------------
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.0.2;branch=z9hG4bK92ec.85e18692.0
Via: SIP/2.0/UDP 202.xx.xxx.xx:5060;branch=z9hG4bK1ca53b7214a28536c-b0f5-0
Record-Route: <sip:192.168.0.2;r2=on;lr=on;ftag=50f70f41-co453-INS001;vsf=czFwOldpejRyZCFzMXA6FjA4NC8hYC58N30LNDRkLnx/FkU-;did=1e1.1ee44d26>
Record-Route: <sip:202.xxx.xx.xx;r2=on;lr=on;ftag=50f70f41-co453-INS001;vsf=czFwOldpejRyZCFzMXA6FjA4NC8hYC58N30LNDRkLnx/FkU-;did=1e1.1ee44d26>
From: "0445674567"<sip:0445674567 at sip.evolutiontel.net>;tag=50f70f41-co453-INS001
To: <sip:0312341234 at 202.xxx.xx.xx:5060>;tag=UeFvvZ6yQmZ1j
Call-ID: 2619-475-54200923635-IMG01-0-202.83.183.46
CSeq: 45301 INVITE
Contact: <sip:mod_sofia at 192.168.0.2:5070;transport=udp>
User-Agent: Evolutiontel SIP Service
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH
Supported: timer, precondition, path, replaces
Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Length: 0
P-Asserted-Identity: "" <0631000001>
------------------------------------------------------------------------
nta: sent 180 Ringing for INVITE (45301)
nta: timer set to 60000 ms
nua(0x9ccc130): call state changed: received -> early
nua(0x9ccc130): event i_state 180 Ringing
nua: nua_application_event: entering
2009-06-05 09:06:35 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/0445674567 at sip.evolutiontel.net entering state [early][180]
nua: nua_handle_magic: entering
2009-06-05 09:06:35 [DEBUG] switch_ivr_originate.c:1768 switch_ivr_originate() sofia/internal/0445674567 at sip.evolutiontel.net receive message [RINGING]
2009-06-05 09:06:35 [DEBUG] switch_core_session.c:630 switch_core_session_perform_receive_message() Send signal sofia/internal/0445674567 at sip.evolutiontel.net [BREAK]
2009-06-05 09:06:35 [NOTICE] switch_ivr_originate.c:1768 switch_ivr_originate() Ring Ready sofia/internal/0445674567 at sip.evolutiontel.net!
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9d93fd8 from (udp/192.168.0.2:5070) has 1218 bytes, veclen = 1
recv 1218 bytes from udp/[192.168.0.2]:5060 at 23:06:41.842064:
------------------------------------------------------------------------
SIP/2.0 200 OK
To: <sip:0312341234 at 202.xxx.xx.xx:5060>;tag=f936c99a6bd026a9i0
From: "0445674567" <sip:0445674567 at sip.evolutiontel.net>;tag=vQ8mytQ2mXNme
Call-ID: 315cd1e2-cbff-122c-ee95-00112fcc990a
CSeq: 115960061 INVITE
Via: SIP/2.0/UDP 192.168.0.2:5070;received=192.168.0.2;rport=5070;branch=z9hG4bKZa7eS5j4r9a8F
Record-Route: <sip:202.125.40.17;r2=on;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.0faf3ae2>
Record-Route: <sip:192.168.0.3;r2=on;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.0faf3ae2>
Record-Route: <sip:192.168.0.2;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.733ef665>
Contact: 0631000001 <sip:0631000001 at 60.xxx.xx.xxx:5080>
Server: Linksys/SPA3000-3.1.20(GW)
Remote-Party-ID: 0631000001 <sip:0631000001 at sip.evolutiontel.net>;screen=yes;party=called
Content-Length: 306
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: x-sipura, replaces
Content-Type: application/sdp
P-Behind-NAT: Yes
v=0
o=- 8503548 8503548 IN IP4 192.168.0.10
s=-
c=IN IP4 60.xxx.xx.xxx
t=0 0
m=audio 16582 RTP/AVP 18 100 101
a=rtpmap:18 G729a/8000
a=rtpmap:100 NSE/8000
a=fmtp:100 192-193
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
a=direction:active
a=oldmediaip:192.168.0.10
------------------------------------------------------------------------
tport_deliver(0x9bb0e28): msg 0x9d93fd8 (1218 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received 200 OK for INVITE (115960061)
nta: 200 OK is going to a transaction
tport_release(0x9bb0e28): 0x9c63a58 by 0x9bcc770 with 0x9d93fd8
nta: timer shortened to 32000 ms
soa_set_remote_sdp(static::0x9d15ce0, (nil), 0x9c62d18, 306) called
soa_process_answer(static::0x9d15ce0) called
soa_static_offer_answer_action(0x9d15ce0, soa_process_answer): called
soa_sdp_mode_set(0x9cec6b0, 0x9db77b0, ""): called
soa_static(0x9d15ce0, soa_process_answer): upgrade codecs with remote description
soa_static(0x9d15ce0, soa_process_answer): storing local description
soa_activate(static::0x9d15ce0, (nil)) called
nua(0x9cf7ed0): INVITE: processed SDP answer in 200 OK
nua(0x9cf7ed0): event r_invite 200 OK
soa_activate(static::0x9d15ce0, (nil)) called
nta: selecting scheme sip
tport_tsend(0x9bb0e28) tpn = */192.168.0.2:5060
tport_resolve addrinfo = 192.168.0.2:5060
tport_by_addrinfo(0x9bb0e28): not found by name */192.168.0.2:5060
tport_vsend(0x9bb0e28): 624 bytes of 624 to udp/192.168.0.2:5060
tport_vsend returned 624
send 624 bytes to udp/[192.168.0.2]:5060 at 23:06:41.842923:
------------------------------------------------------------------------
ACK sip:0631000001 at 60.xxx.xx.xxx:5080 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.2:5070;rport;branch=z9hG4bK0K07t037Nj1tB
Route: <sip:192.168.0.2;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.733ef665>
Route: <sip:192.168.0.3;r2=on;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.0faf3ae2>
Route: <sip:202.125.40.17;r2=on;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.0faf3ae2>
Max-Forwards: 70
From: "0445674567" <sip:0445674567 at sip.evolutiontel.net>;tag=vQ8mytQ2mXNme
To: <sip:0312341234 at 202.xxx.xx.xx:5060>;tag=f936c99a6bd026a9i0
Call-ID: 315cd1e2-cbff-122c-ee95-00112fcc990a
CSeq: 115960061 ACK
Contact: <sip:mod_sofia at 192.168.0.2:5070>
Content-Length: 0
------------------------------------------------------------------------
nta: sent ACK (115960061) to */192.168.0.2:5060
nua(0x9cf7ed0): call state changed: proceeding -> ready, received answer
soa_get_remote_sdp(static::0x9d15ce0, [0xb77b7bfc], [0xb77b7bf8], [(nil)]) called
soa_get_params(static::0x9d15ce0, ...) called
nua(0x9cf7ed0): event i_state 200 OK
nua(0x9cf7ed0): event i_active 200 Call active
nua: nua_application_event: entering
nua: nua_handle_magic: entering
nua: nua_application_event: entering
2009-06-05 09:06:41 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/0631000001 at 192.168.0.2 entering state [ready][200]
2009-06-05 09:06:41 [DEBUG] sofia.c:3046 sofia_handle_sip_i_state() Remote SDP:
v=0
o=- 8503548 8503548 IN IP4 192.168.0.10
s=-
c=IN IP4 60.xxx.xx.xxx
t=0 0
m=audio 16582 RTP/AVP 18 100 101
a=rtpmap:18 G729a/8000
a=rtpmap:100 NSE/8000
a=fmtp:100 192-193
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=direction:active
a=oldmediaip:192.168.0.10
2009-06-05 09:06:41 [DEBUG] switch_channel.c:1875 switch_channel_perform_mark_answered() Send signal sofia/internal/0445674567 at sip.evolutiontel.net [BREAK]
2009-06-05 09:06:41 [DEBUG] switch_ivr_originate.c:1978 switch_ivr_originate() sofia/internal/0445674567 at sip.evolutiontel.net receive message [ANSWER]
nua: nua_respond: entering
nua(0x9ccc130): sent signal r_respond
2009-06-05 09:06:41 [DEBUG] switch_core_session.c:630 switch_core_session_perform_receive_message() Send signal sofia/internal/0445674567 at sip.evolutiontel.net [BREAK]
2009-06-05 09:06:41 [NOTICE] switch_ivr_originate.c:1978 switch_ivr_originate() Channel [sofia/internal/0445674567 at sip.evolutiontel.net] has been answered
2009-06-05 09:06:41 [DEBUG] switch_channel.c:1911 switch_channel_perform_mark_answered() sofia/internal/0445674567 at sip.evolutiontel.net execute on answer: sched_hangup(+7200 ALLOTED_TIMEOUT)
EXECUTE sofia/internal/0445674567 at sip.evolutiontel.net sched_hangup(+7200 ALLOTED_TIMEOUT)
2009-06-05 09:06:41 [DEBUG] switch_scheduler.c:214 switch_scheduler_add_task() Added task 7 switch_ivr_schedule_hangup (e57f4f54-7b45-48cc-98d3-8b594bdc19e8) to run at 1244164001
2009-06-05 09:06:41 [DEBUG] switch_ivr_originate.c:2024 switch_ivr_originate() Originate Resulted in Success: [sofia/internal/0631000001 at 192.168.0.2]
nua(0x9ccc130): recv signal r_respond 200 OK
nua: nua_stack_set_params: entering
soa_set_params(static::0x9c1d4e8, ...) called
soa_set_user_sdp(static::0x9c1d4e8, (nil), 0x9dc2c08, -1) called
soa_set_capability_sdp(static::0x9c1d4e8, (nil), 0x9dc2c08, -1) called
nua: nua_invite_server_respond: entering
soa_generate_answer(static::0x9c1d4e8) called
soa_static_offer_answer_action(0x9c1d4e8, soa_generate_answer): called
soa_static(0x9c1d4e8, soa_generate_answer): generating local description
soa_static(0x9c1d4e8, soa_generate_answer): upgrade with remote description
soa_static(0x9c1d4e8, soa_generate_answer): marking rejected media
soa_sdp_mode_set(0xb77b7fb4, 0x9ce6698, ""): called
soa_init_sdp_connection_with_session: selected IN IP4 202.xxx.xx.xx (a local address)
soa_static(0x9c1d4e8, soa_generate_answer): storing local description
soa_activate(static::0x9c1d4e8, (nil)) called
soa_get_local_sdp(static::0x9c1d4e8, [(nil)], [0xb77b803c], [0xb77b8038]) called
tport_tsend(0x9bb0e28) tpn = UDP/192.168.0.2:5060
tport_resolve addrinfo = 192.168.0.2:5060
tport_by_addrinfo(0x9bb0e28): not found by name UDP/192.168.0.2:5060
tport_vsend(0x9bb0e28): 1414 bytes of 1414 to udp/192.168.0.2:5060
tport_vsend returned 1414
send 1414 bytes to udp/[192.168.0.2]:5060 at 23:06:41.847721:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.2;branch=z9hG4bK92ec.85e18692.0
Via: SIP/2.0/UDP 202.xx.xxx.xx:5060;branch=z9hG4bK1ca53b7214a28536c-b0f5-0
Record-Route: <sip:192.168.0.2;r2=on;lr=on;ftag=50f70f41-co453-INS001;vsf=czFwOldpejRyZCFzMXA6FjA4NC8hYC58N30LNDRkLnx/FkU-;did=1e1.1ee44d26>
Record-Route: <sip:202.xxx.xx.xx;r2=on;lr=on;ftag=50f70f41-co453-INS001;vsf=czFwOldpejRyZCFzMXA6FjA4NC8hYC58N30LNDRkLnx/FkU-;did=1e1.1ee44d26>
From: "0445674567"<sip:0445674567 at sip.evolutiontel.net>;tag=50f70f41-co453-INS001
To: <sip:0312341234 at 202.xxx.xx.xx:5060>;tag=UeFvvZ6yQmZ1j
Call-ID: 2619-475-54200923635-IMG01-0-202.83.183.46
CSeq: 45301 INVITE
Contact: <sip:mod_sofia at 192.168.0.2:5070;transport=udp>
User-Agent: Evolutiontel SIP Service
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH
Supported: timer, precondition, path, replaces
Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 256
P-Asserted-Identity: "" <0631000001>
v=0
o=- 2963411278722346302 7975655717233217142 IN IP4 202.xxx.xx.xx
s=-
c=IN IP4 60.xxx.xx.xxx
t=0 0
m=audio 0 RTP/AVP 96 100 101
a=rtpmap:96 G729a/8000
a=rtpmap:100 NSE/8000
a=fmtp:100 192-193
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
------------------------------------------------------------------------
nta: sent 200 OK for INVITE (45301)
nta: timer shortened to 500 ms
nua(0x9ccc130): call state changed: early -> completed, sent answer
soa_get_local_sdp(static::0x9c1d4e8, [0xb77b8124], [0xb77b8120], [(nil)]) called
soa_get_params(static::0x9c1d4e8, ...) called
nua(0x9ccc130): event i_state 200 OK
2009-06-05 09:06:41 [DEBUG] switch_ivr_bridge.c:791 switch_ivr_signal_bridge() (sofia/internal/0445674567 at sip.evolutiontel.net) State Change CS_EXECUTE -> CS_HIBERNATE
2009-06-05 09:06:41 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0445674567 at sip.evolutiontel.net [BREAK]
2009-06-05 09:06:41 [DEBUG] switch_ivr_bridge.c:792 switch_ivr_signal_bridge() (sofia/internal/0631000001 at 192.168.0.2) State Change CS_CONSUME_MEDIA -> CS_HIBERNATE
2009-06-05 09:06:41 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0631000001 at 192.168.0.2 [BREAK]
2009-06-05 09:06:41 [DEBUG] switch_core_state_machine.c:490 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State EXECUTE going to sleep
2009-06-05 09:06:41 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) Running State Change CS_HIBERNATE
2009-06-05 09:06:41 [DEBUG] switch_core_state_machine.c:505 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State HIBERNATE
2009-06-05 09:06:41 [DEBUG] mod_sofia.c:160 sofia_on_hibernate() sofia/internal/0445674567 at sip.evolutiontel.net SOFIA HIBERNATE
2009-06-05 09:06:41 [DEBUG] switch_core_state_machine.c:212 switch_core_standard_on_hibernate() sofia/internal/0445674567 at sip.evolutiontel.net Standard HIBERNATE
2009-06-05 09:06:41 [DEBUG] switch_core_state_machine.c:505 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State HIBERNATE going to sleep
2009-06-05 09:06:41 [NOTICE] sofia.c:3509 sofia_handle_sip_i_state() Channel [sofia/internal/0631000001 at 192.168.0.2] has been answered
nua: nua_handle_magic: entering
nua: nua_application_event: entering
nua: nua_handle_magic: entering
nua: nua_application_event: entering
2009-06-05 09:06:41 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/0445674567 at sip.evolutiontel.net entering state [completed][200]
nua: nua_handle_magic: entering
2009-06-05 09:06:41 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) Running State Change CS_HIBERNATE
2009-06-05 09:06:41 [DEBUG] switch_core_state_machine.c:505 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State HIBERNATE
2009-06-05 09:06:41 [DEBUG] mod_sofia.c:160 sofia_on_hibernate() sofia/internal/0631000001 at 192.168.0.2 SOFIA HIBERNATE
2009-06-05 09:06:41 [DEBUG] switch_core_state_machine.c:212 switch_core_standard_on_hibernate() sofia/internal/0631000001 at 192.168.0.2 Standard HIBERNATE
2009-06-05 09:06:41 [DEBUG] switch_core_state_machine.c:505 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State HIBERNATE going to sleep
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9cbc8b8 from (udp/192.168.0.2:5070) has 475 bytes, veclen = 1
recv 475 bytes from udp/[192.168.0.2]:5060 at 23:06:42.052636:
------------------------------------------------------------------------
ACK sip:mod_sofia at 192.168.0.2:5070 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.2;branch=z9hG4bK92ec.85e18692.2
Via: SIP/2.0/UDP 202.xx.xxx.xx:5060;branch=z9hG4bK1ca53b7214a28536c-b0f5-1
Max-Forwards: 69
To: <sip:0312341234 at 202.xxx.xx.xx:5060>;tag=UeFvvZ6yQmZ1j
From: "0445674567"<sip:0445674567 at sip.evolutiontel.net>;tag=50f70f41-co453-INS001
Call-ID: 2619-475-54200923635-IMG01-0-202.83.183.46
CSeq: 45301 ACK
User-Agent: ENSR2.5.4
Content-Length: 0
P-hint: rr-enforced
------------------------------------------------------------------------
tport_deliver(0x9bb0e28): msg 0x9cbc8b8 (475 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received ACK sip:mod_sofia at 192.168.0.2:5070 SIP/2.0 (CSeq 45301)
nta: ACK (45301) is going to INVITE (45301)
nua: process_ack_or_cancel: entering
soa_clear_remote_sdp(static::0x9c1d4e8) called
nua(0x9ccc130): event i_ack 200 OK
nua(0x9ccc130): call state changed: completed -> ready
nua(0x9ccc130): event i_state 200 OK
nua(0x9ccc130): event i_active 200 Call active
nua: nua_application_event: entering
nua: nua_handle_magic: entering
nua: nua_application_event: entering
2009-06-05 09:06:42 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/0445674567 at sip.evolutiontel.net entering state [ready][200]
nua: nua_handle_magic: entering
nua: nua_application_event: entering
nua: nua_handle_magic: entering
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9cbc8b8 from (udp/192.168.0.2:5070) has 475 bytes, veclen = 1
recv 475 bytes from udp/[192.168.0.2]:5060 at 23:06:42.088227:
------------------------------------------------------------------------
BYE sip:mod_sofia at 192.168.0.2:5070 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.2;branch=z9hG4bK62ec.b694c4f3.0
Via: SIP/2.0/UDP 202.xx.xxx.xx:5060;branch=z9hG4bK1ca53b7214a28536c-b0f6-0
Max-Forwards: 69
To: <sip:0312341234 at 202.xxx.xx.xx:5060>;tag=UeFvvZ6yQmZ1j
From: "0445674567"<sip:0445674567 at sip.evolutiontel.net>;tag=50f70f41-co453-INS001
Call-ID: 2619-475-54200923635-IMG01-0-202.83.183.46
CSeq: 45302 BYE
User-Agent: ENSR2.5.4
Content-Length: 0
P-hint: rr-enforced
------------------------------------------------------------------------
tport_deliver(0x9bb0e28): msg 0x9cbc8b8 (475 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received BYE sip:mod_sofia at 192.168.0.2:5070 SIP/2.0 (CSeq 45302)
nta: canonizing sip:mod_sofia at 192.168.0.2:5070 with contact
nta: BYE (45302) going to existing leg
nua: nua_stack_process_request: entering
tport_tsend(0x9bb0e28) tpn = UDP/192.168.0.2:5060
tport_resolve addrinfo = 192.168.0.2:5060
tport_by_addrinfo(0x9bb0e28): not found by name UDP/192.168.0.2:5060
tport_vsend(0x9bb0e28): 588 bytes of 588 to udp/192.168.0.2:5060
tport_vsend returned 588
send 588 bytes to udp/[192.168.0.2]:5060 at 23:06:42.088632:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.2;branch=z9hG4bK62ec.b694c4f3.0
Via: SIP/2.0/UDP 202.xx.xxx.xx:5060;branch=z9hG4bK1ca53b7214a28536c-b0f6-0
From: "0445674567"<sip:0445674567 at sip.evolutiontel.net>;tag=50f70f41-co453-INS001
To: <sip:0312341234 at 202.xxx.xx.xx:5060>;tag=UeFvvZ6yQmZ1j
Call-ID: 2619-475-54200923635-IMG01-0-202.83.183.46
CSeq: 45302 BYE
User-Agent: Evolutiontel SIP Service
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH
Supported: timer, precondition, path, replaces
Content-Length: 0
------------------------------------------------------------------------
nta: sent 200 OK for BYE (45302)
nua(0x9ccc130): event i_bye 200 Session Terminated
nua(0x9ccc130): removing session usage
nua(0x9ccc130): call state changed: ready -> terminated
nua(0x9ccc130): event i_state 200 Session Terminated
nua(0x9ccc130): event i_terminated 200 Session Terminated
soa_destroy(static::0x9c1d4e8) called
nta_leg_destroy(0x9c41a68)
nua: nua_application_event: entering
nua: nua_handle_magic: entering
nua: nua_application_event: entering
2009-06-05 09:06:42 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/0445674567 at sip.evolutiontel.net entering state [terminated][200]
2009-06-05 09:06:42 [NOTICE] sofia.c:3599 sofia_handle_sip_i_state() Hangup sofia/internal/0445674567 at sip.evolutiontel.net [CS_HIBERNATE] [NORMAL_CLEARING]
2009-06-05 09:06:42 [DEBUG] switch_channel.c:1667 switch_channel_perform_hangup() Send signal sofia/internal/0445674567 at sip.evolutiontel.net [KILL]
2009-06-05 09:06:42 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0445674567 at sip.evolutiontel.net [BREAK]
nua: nua_handle_bind: entering
nua: nua_handle_destroy: entering
nua(0x9ccc130): sent signal r_destroy
nua: nua_handle_magic: entering
nua: nua_handle_bind: entering
nua: nua_handle_destroy: entering
nua: nua_application_event: entering
nua(0x9ccc130): event i_terminated dropped
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) Running State Change CS_HANGUP
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:433 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State HANGUP
2009-06-05 09:06:42 [DEBUG] mod_sofia.c:307 sofia_on_hangup() sofia/internal/0445674567 at sip.evolutiontel.net Overriding SIP cause 480 with 200 from the other leg
2009-06-05 09:06:42 [DEBUG] mod_sofia.c:339 sofia_on_hangup() Channel sofia/internal/0445674567 at sip.evolutiontel.net hanging up, cause: NORMAL_CLEARING
2009-06-05 09:06:42 [NOTICE] switch_ivr_bridge.c:712 signal_bridge_on_hangup() Hangup sofia/internal/0631000001 at 192.168.0.2 [CS_HIBERNATE] [NORMAL_CLEARING]
2009-06-05 09:06:42 [DEBUG] switch_channel.c:1667 switch_channel_perform_hangup() Send signal sofia/internal/0631000001 at 192.168.0.2 [KILL]
2009-06-05 09:06:42 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0631000001 at 192.168.0.2 [BREAK]
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/internal/0445674567 at sip.evolutiontel.net Standard HANGUP, cause: NORMAL_CLEARING
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:433 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State HANGUP going to sleep
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:475 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State Change CS_HANGUP -> CS_REPORTING
2009-06-05 09:06:42 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0445674567 at sip.evolutiontel.net [BREAK]
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) Running State Change CS_REPORTING
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:607 switch_core_session_reporting_state() (sofia/internal/0445674567 at sip.evolutiontel.net) State REPORTING
nua(0x9ccc130): recv signal r_destroy
nta_leg_destroy((nil))
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) Running State Change CS_HANGUP
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:433 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State HANGUP
2009-06-05 09:06:42 [DEBUG] mod_sofia.c:307 sofia_on_hangup() sofia/internal/0631000001 at 192.168.0.2 Overriding SIP cause 480 with 200 from the other leg
2009-06-05 09:06:42 [DEBUG] mod_sofia.c:339 sofia_on_hangup() Channel sofia/internal/0631000001 at 192.168.0.2 hanging up, cause: NORMAL_CLEARING
2009-06-05 09:06:42 [DEBUG] mod_sofia.c:394 sofia_on_hangup() Sending BYE to sofia/internal/0631000001 at 192.168.0.2
nua: nua_bye: entering
nua(0x9cf7ed0): sent signal r_bye
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/internal/0631000001 at 192.168.0.2 Standard HANGUP, cause: NORMAL_CLEARING
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:433 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State HANGUP going to sleep
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:475 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State Change CS_HANGUP -> CS_REPORTING
2009-06-05 09:06:42 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/0631000001 at 192.168.0.2 [BREAK]
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) Running State Change CS_REPORTING
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:607 switch_core_session_reporting_state() (sofia/internal/0631000001 at 192.168.0.2) State REPORTING
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:53 switch_core_standard_on_reporting() sofia/internal/0631000001 at 192.168.0.2 Standard REPORTING, cause: NORMAL_CLEARING
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:607 switch_core_session_reporting_state() (sofia/internal/0631000001 at 192.168.0.2) State REPORTING going to sleep
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:410 switch_core_session_run() (sofia/internal/0631000001 at 192.168.0.2) State Change CS_REPORTING -> CS_DESTROY
2009-06-05 09:06:42 [DEBUG] switch_core_session.c:1067 switch_core_session_thread() Session 10 (sofia/internal/0631000001 at 192.168.0.2) Locked, Waiting on external entities
2009-06-05 09:06:42 [NOTICE] switch_core_session.c:1085 switch_core_session_thread() Session 10 (sofia/internal/0631000001 at 192.168.0.2) Ended
2009-06-05 09:06:42 [NOTICE] switch_core_session.c:1087 switch_core_session_thread() Close Channel sofia/internal/0631000001 at 192.168.0.2 [CS_DESTROY]
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:559 switch_core_session_destroy_state() (sofia/internal/0631000001 at 192.168.0.2) State DESTROY
2009-06-05 09:06:42 [DEBUG] mod_sofia.c:256 sofia_on_destroy() sofia/internal/0631000001 at 192.168.0.2 SOFIA DESTROY
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:60 switch_core_standard_on_destroy() sofia/internal/0631000001 at 192.168.0.2 Standard DESTROY
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:559 switch_core_session_destroy_state() (sofia/internal/0631000001 at 192.168.0.2) State DESTROY going to sleep
nua(0x9cf7ed0): recv signal r_bye
nua: nua_stack_set_params: entering
soa_set_params(static::0x9d15ce0, ...) called
soa_terminate(static::0x9d15ce0) called
soa_init_offer_answer(static::0x9d15ce0) called
nta: selecting scheme sip
tport_tsend(0x9bb0e28) tpn = */192.168.0.2:5060
tport_resolve addrinfo = 192.168.0.2:5060
tport_by_addrinfo(0x9bb0e28): not found by name */192.168.0.2:5060
tport_vsend(0x9bb0e28): 874 bytes of 874 to udp/192.168.0.2:5060
tport_vsend returned 874
send 874 bytes to udp/[192.168.0.2]:5060 at 23:06:42.094504:
------------------------------------------------------------------------
BYE sip:0631000001 at 60.xxx.xx.xxx:5080 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.2:5070;rport;branch=z9hG4bK1vS0vUmBKUQDQ
Route: <sip:192.168.0.2;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.733ef665>
Route: <sip:192.168.0.3;r2=on;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.0faf3ae2>
Route: <sip:202.125.40.17;r2=on;lr=on;ftag=vQ8mytQ2mXNme;did=0e2.0faf3ae2>
Max-Forwards: 70
From: "0445674567" <sip:0445674567 at sip.evolutiontel.net>;tag=vQ8mytQ2mXNme
To: <sip:0312341234 at 202.xxx.xx.xx:5060>;tag=f936c99a6bd026a9i0
Call-ID: 315cd1e2-cbff-122c-ee95-00112fcc990a
CSeq: 115960062 BYE
Contact: <sip:mod_sofia at 192.168.0.2:5070>
User-Agent: Evolutiontel SIP Service
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH
Supported: timer, precondition, path, replaces
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
Content-Length: 0
------------------------------------------------------------------------
nta: sent BYE (115960062) to */192.168.0.2:5060
tport_pend(0x9bb0e28): pending 0x9d15e08 for udp/192.168.0.2:5070 (already 0)
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:53 switch_core_standard_on_reporting() sofia/internal/0445674567 at sip.evolutiontel.net Standard REPORTING, cause: NORMAL_CLEARING
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:607 switch_core_session_reporting_state() (sofia/internal/0445674567 at sip.evolutiontel.net) State REPORTING going to sleep
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:410 switch_core_session_run() (sofia/internal/0445674567 at sip.evolutiontel.net) State Change CS_REPORTING -> CS_DESTROY
2009-06-05 09:06:42 [DEBUG] switch_core_session.c:1067 switch_core_session_thread() Session 9 (sofia/internal/0445674567 at sip.evolutiontel.net) Locked, Waiting on external entities
2009-06-05 09:06:42 [NOTICE] switch_core_session.c:1085 switch_core_session_thread() Session 9 (sofia/internal/0445674567 at sip.evolutiontel.net) Ended
2009-06-05 09:06:42 [NOTICE] switch_core_session.c:1087 switch_core_session_thread() Close Channel sofia/internal/0445674567 at sip.evolutiontel.net [CS_DESTROY]
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:559 switch_core_session_destroy_state() (sofia/internal/0445674567 at sip.evolutiontel.net) State DESTROY
2009-06-05 09:06:42 [DEBUG] mod_sofia.c:256 sofia_on_destroy() sofia/internal/0445674567 at sip.evolutiontel.net SOFIA DESTROY
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:60 switch_core_standard_on_destroy() sofia/internal/0445674567 at sip.evolutiontel.net Standard DESTROY
2009-06-05 09:06:42 [DEBUG] switch_core_state_machine.c:559 switch_core_session_destroy_state() (sofia/internal/0445674567 at sip.evolutiontel.net) State DESTROY going to sleep
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9c41b38 from (udp/192.168.0.2:5070) has 450 bytes, veclen = 1
recv 450 bytes from udp/[192.168.0.2]:5060 at 23:06:42.210621:
------------------------------------------------------------------------
SIP/2.0 200 OK
To: <sip:0312341234 at 202.xxx.xx.xx:5060>;tag=f936c99a6bd026a9i0
From: "0445674567" <sip:0445674567 at sip.evolutiontel.net>;tag=vQ8mytQ2mXNme
Call-ID: 315cd1e2-cbff-122c-ee95-00112fcc990a
CSeq: 115960062 BYE
Via: SIP/2.0/UDP 192.168.0.2:5070;received=192.168.0.2;rport=5070;branch=z9hG4bK1vS0vUmBKUQDQ
Server: Linksys/SPA3000-3.1.20(GW)
P-RTP-Stat: PS=12,OS=240,PR=0,OR=0,PL=0,JI=0,LA=0,DU=0,EN=G729a,DE=G711u
Content-Length: 0
------------------------------------------------------------------------
tport_deliver(0x9bb0e28): msg 0x9c41b38 (450 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received 200 OK for BYE (115960062)
nta: 200 OK is going to a transaction
nta_outgoing: RTT is 116.446 ms
tport_release(0x9bb0e28): 0x9d15e08 by 0x9bcdcb0 with 0x9c41b38
nua(0x9cf7ed0): event r_bye 200 OK
nua(0x9cf7ed0): call state changed: terminating -> terminated
nua(0x9cf7ed0): event i_state 200 to BYE
nua(0x9cf7ed0): event i_terminated 200 to BYE
nua(0x9cf7ed0): removing session usage
soa_destroy(static::0x9d15ce0) called
nta_leg_destroy(0x9db94b0)
nua: terminated session 0x9cf7ed0
nua: nua_application_event: entering
nua: nua_handle_magic: entering
nua: nua_handle_bind: entering
nua: nua_application_event: entering
nua: nua_handle_magic: entering
nua: nua_handle_destroy: entering
nua(0x9cf7ed0): sent signal r_destroy
nua: nua_application_event: entering
nua(0x9cf7ed0): event i_terminated dropped
nua(0x9cf7ed0): recv signal r_destroy
nta_leg_destroy((nil))
nta: timer set next to 4704 ms
2009-06-05 09:06:42 [DEBUG] switch_scheduler.c:138 task_thread_loop() Deleting task 7 switch_ivr_schedule_hangup (e57f4f54-7b45-48cc-98d3-8b594bdc19e8)
nta: timer I fired, terminate 200 response
incoming_reclaim_all((nil), (nil), 0xb77b81cc)
nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free
nta: timer set next to 157 ms
nta: timer K fired, terminate BYE (115960062)
outgoing_reclaim_all((nil), (nil), 0xb77b81c8)
nta_outgoing_timer: 0/0 resent, 0/1 tout, 1/2 term, 1/3 free
nta: timer set next to 26628 ms
/exit
[root at sip01 bin]#
More information about the FreeSWITCH-users
mailing list