[Freeswitch-users] Calls drop immediately when terminator forces G.729 Codec.

Thu Jun 4 05:43:24 PDT 2009

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
-------------- next part --------------
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9bcba58 from (udp/192.168.0.2:5070) has 1303 bytes, veclen = 1
tport_deliver(0x9bb0e28): msg 0x9bcba58 (1303 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received INVITE sip:1234567891 at 192.168.0.2:5060 SIP/2.0 (CSeq 811801)
nta: INVITE (811801) 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, 0x9bfa748) called
soa_set_params(static::0x9bcca70, ...) called
nta_leg_tcreate(0x9c19f60)
soa_init_offer_answer(static::0x9bcca70) called
soa_set_remote_sdp(static::0x9bcca70, (nil), 0x9ce1541, 286) called
nua(0x9bfa748): 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): 705 bytes of 705 to udp/192.168.0.2:5060
tport_vsend returned 705
nta: sent 100 Trying for INVITE (811801)
nua(0x9bfa748): event i_invite 100 Trying
nua(0x9bfa748): call state changed: init -> received, received offer
soa_get_remote_sdp(static::0x9bcca70, [0xb77b7bac], [0xb77b7ba8], [(nil)]) called
nua(0x9bfa748): event i_state 100 Trying
nua: nua_application_event: entering
2009-06-04 21:58:34 [NOTICE] switch_channel.c:602 switch_channel_set_name() New Channel sofia/internal/987654321 at sip.evolutiontel.net [6dd5c26f-8cfc-4876-a538-ed5f5e03cc1b]
nua: nua_handle_bind: entering
nua: nua_handle_magic: entering
nua: nua_application_event: entering
2009-06-04 21:58:34 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/987654321 at sip.evolutiontel.net entering state [received][100]
2009-06-04 21:58:34 [DEBUG] sofia.c:3046 sofia_handle_sip_i_state() Remote SDP:
v=0
o=- 570753038 570753038 IN IP4 202.xx.xxx.xx
s=ENSResip
c=IN IP4 202.xx.xxx.xx
t=0 0
m=audio 13298 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-04 21:58:34 [DEBUG] sofia.c:3182 sofia_handle_sip_i_state() (sofia/internal/987654321 at sip.evolutiontel.net) State Change CS_NEW -> CS_INIT
2009-06-04 21:58:34 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/987654321 at sip.evolutiontel.net [BREAK]
nua: nua_handle_magic: entering
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) Running State Change CS_INIT
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:480 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State INIT
2009-06-04 21:58:34 [DEBUG] mod_sofia.c:83 sofia_on_init() sofia/internal/987654321 at sip.evolutiontel.net SOFIA INIT
2009-06-04 21:58:34 [DEBUG] mod_sofia.c:111 sofia_on_init() (sofia/internal/987654321 at sip.evolutiontel.net) State Change CS_INIT -> CS_ROUTING
2009-06-04 21:58:34 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/987654321 at sip.evolutiontel.net [BREAK]
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:480 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State INIT going to sleep
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) Running State Change CS_ROUTING
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State ROUTING
2009-06-04 21:58:34 [DEBUG] mod_sofia.c:130 sofia_on_routing() sofia/internal/987654321 at sip.evolutiontel.net SOFIA ROUTING
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:78 switch_core_standard_on_routing() sofia/internal/987654321 at sip.evolutiontel.net Standard ROUTING
2009-06-04 21:58:34 [INFO] mod_dialplan_xml.c:252 dialplan_hunt() Processing 987654321->1234567891 in context evolutiontel
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->unloop] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->global] continue=true
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [global] ${network_addr}(192.168.0.2) =~ /^$/ break=never
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net ANTI-Action set(use_profile=${cond(${acl(${network_addr} rfc1918)} == true ? nat : default)})
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (PASS) [global] ${numbering_plan}() =~ /^$/ break=never
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Action set_user(default@${domain_name})
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/987654321 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/987654321 at sip.evolutiontel.net ANTI-Action set(bypass_media=true)
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [global] ${sip_h_X-ZRTP-On}() =~ /^Y$/ break=never
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net ANTI-Action set(bypass_media=true)
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [global] ${sip_secure_media}() =~ /^true$/ break=never
Dialplan: sofia/internal/987654321 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/987654321 at sip.evolutiontel.net Absolute Condition [global]
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->vmain] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [vmain] destination_number(1234567891) =~ /^121/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->vmain1] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [vmain1] destination_number(1234567891) =~ /^123/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->vmain2] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [vmain2] destination_number(1234567891) =~ /^122/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->ivr_demo] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [ivr_demo] destination_number(1234567891) =~ /^5000$/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->park] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [park] destination_number(1234567891) =~ /^5900$/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->unpark] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [unpark] destination_number(1234567891) =~ /^5901$/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->park] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [park] destination_number(1234567891) =~ /park\+(\d+)/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->unpark] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [unpark] destination_number(1234567891) =~ /^parking$/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->park] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (PASS) [park] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [park] destination_number(1234567891) =~ /callpark/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->unpark] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (PASS) [unpark] source(mod_sofia) =~ /mod_sofia/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [unpark] destination_number(1234567891) =~ /pickup/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->wait] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [wait] destination_number(1234567891) =~ /^wait$/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->National_calls] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [National_calls] destination_number(1234567891) =~ /^0(2|3|4|5|7|8|9)[0-9]{8}$/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->Special_calls] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [Special_calls] destination_number(1234567891) =~ /^1[3|8][0-9]+$/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->International_calls] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (FAIL) [International_calls] destination_number(1234567891) =~ /^0011[0-9]+$/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net parsing [evolutiontel->On-Net_calls] continue=false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Regex (PASS) [On-Net_calls] destination_number(1234567891) =~ /^063[0-9]{7}$/ break=on-false
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Action set(execute_on_answer=sched_hangup +${sip_h_x-max-timer} ALLOTED_TIMEOUT)
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Action set(sip_cid_type=pid)
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Action set(continue_on_fail=79)
Dialplan: sofia/internal/987654321 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/987654321 at sip.evolutiontel.net Action set(bypass_media=false)
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Action set(ringback=%(400,200,401,450);%(400,2200,400,450))
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Action pre_answer()
Dialplan: sofia/internal/987654321 at sip.evolutiontel.net Action export(sip_secure_media=true)
Dialplan: sofia/internal/987654321 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-04 21:58:34 [DEBUG] switch_core_state_machine.c:114 switch_core_standard_on_routing() (sofia/internal/987654321 at sip.evolutiontel.net) State Change CS_ROUTING -> CS_EXECUTE
2009-06-04 21:58:34 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/987654321 at sip.evolutiontel.net [BREAK]
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State ROUTING going to sleep
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) Running State Change CS_EXECUTE
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:490 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State EXECUTE
2009-06-04 21:58:34 [DEBUG] mod_sofia.c:173 sofia_on_execute() sofia/internal/987654321 at sip.evolutiontel.net SOFIA EXECUTE
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:151 switch_core_standard_on_execute() sofia/internal/987654321 at sip.evolutiontel.net Standard EXECUTE
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net set(use_profile=nat)
2009-06-04 21:58:34 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/987654321 at sip.evolutiontel.net SET [use_profile]=[nat]
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net set_user(default at 192.168.0.2)
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net set(bypass_media=true)
2009-06-04 21:58:34 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/987654321 at sip.evolutiontel.net SET [bypass_media]=[true]
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net set(bypass_media=true)
2009-06-04 21:58:34 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/987654321 at sip.evolutiontel.net SET [bypass_media]=[true]
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net hash(insert/192.168.0.2-spymap/987654321/6dd5c26f-8cfc-4876-a538-ed5f5e03cc1b)
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net hash(insert/192.168.0.2-last_dial/987654321/1234567891)
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net hash(insert/192.168.0.2-last_dial/global/6dd5c26f-8cfc-4876-a538-ed5f5e03cc1b)
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net set(execute_on_answer=sched_hangup +7200 ALLOTED_TIMEOUT)
2009-06-04 21:58:34 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/987654321 at sip.evolutiontel.net SET [execute_on_answer]=[sched_hangup +7200 ALLOTED_TIMEOUT]
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net set(sip_cid_type=pid)
2009-06-04 21:58:34 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/987654321 at sip.evolutiontel.net SET [sip_cid_type]=[pid]
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net set(continue_on_fail=79)
2009-06-04 21:58:34 [DEBUG] mod_dptools.c:748 set_function() sofia/internal/987654321 at sip.evolutiontel.net SET [continue_on_fail]=[79]
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net bridge({sip_from_uri=sip:987654321 at sip.evolutiontel.net}sofia/internal/1234567891 at 192.168.0.2^0312341234 at 202.xxx.xx.xx:5060)
2009-06-04 21:58:34 [DEBUG] switch_ivr_originate.c:1017 switch_ivr_originate() variable string 0 = [sip_from_uri=sip:987654321 at sip.evolutiontel.net]
2009-06-04 21:58:34 [NOTICE] switch_channel.c:602 switch_channel_set_name() New Channel sofia/internal/1234567891 at 192.168.0.2 [64f91098-4f97-4c17-b95b-0d1693c64f8a]
2009-06-04 21:58:34 [DEBUG] mod_sofia.c:2719 sofia_outgoing_channel() (sofia/internal/1234567891 at 192.168.0.2) State Change CS_NEW -> CS_INIT
2009-06-04 21:58:34 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/1234567891 at 192.168.0.2 [BREAK]
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) Running State Change CS_INIT
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:480 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State INIT
2009-06-04 21:58:34 [DEBUG] mod_sofia.c:83 sofia_on_init() sofia/internal/1234567891 at 192.168.0.2 SOFIA INIT
nua: nh_create_handle: entering
nua: nua_handle_bind: entering
nua: nua_invite: entering
nua(0x9d17500): recv signal r_invite
nua: nua_stack_set_params: entering
soa_clone(static::0x9baf508, 0x9b9a050, 0x9d17500) called
soa_set_params(static::0x9bf1e20, ...) called
soa_set_params(static::0x9bf1e20, ...) called
soa_set_user_sdp(static::0x9bf1e20, (nil), 0x9c1d48f, -1) called
soa_set_capability_sdp(static::0x9bf1e20, (nil), 0x9c1d48f, -1) called
nua(0x9d17500): adding session usage
nta_leg_tcreate(0x9bce5c8)
soa_init_offer_answer(static::0x9bf1e20) called
soa_generate_offer(static::0x9bf1e20, 0) called
soa_static_offer_answer_action(0x9bf1e20, soa_generate_offer): called
soa_static(0x9bf1e20, soa_generate_offer): generating local description
soa_static(0x9bf1e20, soa_generate_offer): upgrade with local description
soa_sdp_mode_set(0xb77b7ef4, (nil), ""): called
soa_init_sdp_connection_with_session: selected IN IP4 202.125.42.98 (a local address)
soa_static(0x9bf1e20, soa_generate_offer): storing local description
soa_get_local_sdp(static::0x9bf1e20, [(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
nta: sent INVITE (115940021) to */192.168.0.2:5060
tport_pend(0x9bb0e28): pending 0x9cd15d8 for udp/192.168.0.2:5070 (already 0)
nua(0x9d17500): call state changed: init -> calling, sent offer
soa_get_local_sdp(static::0x9bf1e20, [0xb77b7fa4], [0xb77b7fa0], [(nil)]) called
nua(0x9d17500): 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 0x9d5c900 from (udp/192.168.0.2:5070) has 303 bytes, veclen = 1
tport_deliver(0x9bb0e28): msg 0x9d5c900 (303 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received 100 Trying for INVITE (115940021)
nta: 100 Trying is going to a transaction
nta_outgoing: RTT is 1.918 ms
tport_release(0x9bb0e28): 0x9cd15d8 by 0x9d5c840 with 0x9d5c900 (preliminary)
nua(0x9d17500): sent signal r_invite
2009-06-04 21:58:34 [DEBUG] mod_sofia.c:111 sofia_on_init() (sofia/internal/1234567891 at 192.168.0.2) State Change CS_INIT -> CS_ROUTING
2009-06-04 21:58:34 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/1234567891 at 192.168.0.2 [BREAK]
2009-06-04 21:58:34 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/1234567891 at 192.168.0.2 entering state [calling][0]
nua: nua_handle_magic: entering
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:480 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State INIT going to sleep
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) Running State Change CS_ROUTING
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State ROUTING
2009-06-04 21:58:34 [DEBUG] mod_sofia.c:130 sofia_on_routing() sofia/internal/1234567891 at 192.168.0.2 SOFIA ROUTING
2009-06-04 21:58:34 [DEBUG] switch_ivr_originate.c:63 originate_on_routing() (sofia/internal/1234567891 at 192.168.0.2) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2009-06-04 21:58:34 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/1234567891 at 192.168.0.2 [BREAK]
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:483 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State ROUTING going to sleep
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) Running State Change CS_CONSUME_MEDIA
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:502 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State CONSUME_MEDIA
2009-06-04 21:58:34 [DEBUG] switch_core_state_machine.c:502 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State CONSUME_MEDIA going to sleep
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9c84f30 from (udp/192.168.0.2:5070) has 711 bytes, veclen = 1
tport_deliver(0x9bb0e28): msg 0x9c84f30 (711 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received 180 Ringing for INVITE (115940021)
nta: 180 Ringing is going to a transaction
tport_release(0x9bb0e28): 0x9cd15d8 by 0x9d5c840 with 0x9c84f30 (preliminary)
nua(0x9d17500): event r_invite 180 Ringing
nua(0x9d17500): call state changed: calling -> proceeding
nua(0x9d17500): event i_state 180 Ringing
nua: nua_application_event: entering
nua: nua_handle_magic: entering
nua: nua_application_event: entering
2009-06-04 21:58:34 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/1234567891 at 192.168.0.2 entering state [proceeding][180]
2009-06-04 21:58:34 [NOTICE] sofia.c:3103 sofia_handle_sip_i_state() Ring-Ready sofia/internal/1234567891 at 192.168.0.2!
2009-06-04 21:58:34 [DEBUG] sofia.c:3111 sofia_handle_sip_i_state() sofia/internal/987654321 at sip.evolutiontel.net receive message [RINGING]
nua: nua_respond: entering
nua(0x9bfa748): sent signal r_respond
2009-06-04 21:58:34 [NOTICE] mod_sofia.c:1422 sofia_receive_message() Ring-Ready sofia/internal/987654321 at sip.evolutiontel.net!
2009-06-04 21:58:34 [DEBUG] switch_core_session.c:630 switch_core_session_perform_receive_message() Send signal sofia/internal/987654321 at sip.evolutiontel.net [BREAK]
nua: nua_handle_magic: entering
nua(0x9bfa748): recv signal r_respond 180 Ringing
nua: nua_stack_set_params: entering
soa_set_params(static::0x9bcca70, ...) 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): 1132 bytes of 1132 to udp/192.168.0.2:5060
tport_vsend returned 1132
nta: sent 180 Ringing for INVITE (811801)
nua(0x9bfa748): call state changed: received -> early
nua(0x9bfa748): event i_state 180 Ringing
nua: nua_application_event: entering
2009-06-04 21:58:34 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/987654321 at sip.evolutiontel.net entering state [early][180]
nua: nua_handle_magic: entering
2009-06-04 21:58:34 [DEBUG] switch_ivr_originate.c:1768 switch_ivr_originate() sofia/internal/987654321 at sip.evolutiontel.net receive message [RINGING]
2009-06-04 21:58:34 [DEBUG] switch_core_session.c:630 switch_core_session_perform_receive_message() Send signal sofia/internal/987654321 at sip.evolutiontel.net [BREAK]
2009-06-04 21:58:34 [NOTICE] switch_ivr_originate.c:1768 switch_ivr_originate() Ring Ready sofia/internal/987654321 at sip.evolutiontel.net!
nta: timer set next to 59934 ms
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9c855e8 from (udp/192.168.0.2:5070) has 1215 bytes, veclen = 1
tport_deliver(0x9bb0e28): msg 0x9c855e8 (1215 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received 200 OK for INVITE (115940021)
nta: 200 OK is going to a transaction
tport_release(0x9bb0e28): 0x9cd15d8 by 0x9d5c840 with 0x9c855e8
nta: timer shortened to 32000 ms
soa_set_remote_sdp(static::0x9bf1e20, (nil), 0x9d149c5, 306) called
soa_process_answer(static::0x9bf1e20) called
soa_static_offer_answer_action(0x9bf1e20, soa_process_answer): called
soa_sdp_mode_set(0x9d197c0, 0x9cec6b0, ""): called
soa_static(0x9bf1e20, soa_process_answer): upgrade codecs with remote description
soa_static(0x9bf1e20, soa_process_answer): storing local description
soa_activate(static::0x9bf1e20, (nil)) called
nua(0x9d17500): INVITE: processed SDP answer in 200 OK
nua(0x9d17500): event r_invite 200 OK
nua: nua_application_event: entering
nua: nua_handle_magic: entering
soa_activate(static::0x9bf1e20, (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): 621 bytes of 621 to udp/192.168.0.2:5060
tport_vsend returned 621
nta: sent ACK (115940021) to */192.168.0.2:5060
nua(0x9d17500): call state changed: proceeding -> ready, received answer
soa_get_remote_sdp(static::0x9bf1e20, [0xb77b7bfc], [0xb77b7bf8], [(nil)]) called
soa_get_params(static::0x9bf1e20, ...) called
nua(0x9d17500): event i_state 200 OK
nua: nua_application_event: entering
2009-06-04 21:58:36 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/1234567891 at 192.168.0.2 entering state [ready][200]
2009-06-04 21:58:36 [DEBUG] sofia.c:3046 sofia_handle_sip_i_state() Remote SDP:
v=0
o=- 4495350 4495350 IN IP4 192.168.0.10
s=-
c=IN IP4 60.241.91.137
t=0 0
m=audio 16580 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-04 21:58:36 [DEBUG] switch_channel.c:1875 switch_channel_perform_mark_answered() Send signal sofia/internal/987654321 at sip.evolutiontel.net [BREAK]
2009-06-04 21:58:36 [NOTICE] sofia.c:3509 sofia_handle_sip_i_state() Channel [sofia/internal/1234567891 at 192.168.0.2] has been answered
2009-06-04 21:58:36 [DEBUG] sofia.c:3522 sofia_handle_sip_i_state() sofia/internal/987654321 at sip.evolutiontel.net receive message [ANSWER]
nua: nua_respond: entering
nua(0x9bfa748): sent signal r_respond
2009-06-04 21:58:36 [DEBUG] switch_core_session.c:630 switch_core_session_perform_receive_message() Send signal sofia/internal/987654321 at sip.evolutiontel.net [BREAK]
2009-06-04 21:58:36 [NOTICE] sofia.c:3522 sofia_handle_sip_i_state() Channel [sofia/internal/987654321 at sip.evolutiontel.net] has been answered
2009-06-04 21:58:36 [DEBUG] switch_channel.c:1911 switch_channel_perform_mark_answered() sofia/internal/987654321 at sip.evolutiontel.net execute on answer: sched_hangup(+7200 ALLOTED_TIMEOUT)
EXECUTE sofia/internal/987654321 at sip.evolutiontel.net sched_hangup(+7200 ALLOTED_TIMEOUT)
2009-06-04 21:58:36 [DEBUG] switch_scheduler.c:214 switch_scheduler_add_task() Added task 6 switch_ivr_schedule_hangup (6dd5c26f-8cfc-4876-a538-ed5f5e03cc1b) to run at 1244123916
nua: nua_handle_magic: entering
2009-06-04 21:58:36 [DEBUG] switch_ivr_originate.c:2024 switch_ivr_originate() Originate Resulted in Success: [sofia/internal/1234567891 at 192.168.0.2]
2009-06-04 21:58:36 [DEBUG] switch_ivr_bridge.c:791 switch_ivr_signal_bridge() (sofia/internal/987654321 at sip.evolutiontel.net) State Change CS_EXECUTE -> CS_HIBERNATE
2009-06-04 21:58:36 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/987654321 at sip.evolutiontel.net [BREAK]
2009-06-04 21:58:36 [DEBUG] switch_ivr_bridge.c:792 switch_ivr_signal_bridge() (sofia/internal/1234567891 at 192.168.0.2) State Change CS_CONSUME_MEDIA -> CS_HIBERNATE
2009-06-04 21:58:36 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/1234567891 at 192.168.0.2 [BREAK]
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:490 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State EXECUTE going to sleep
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) Running State Change CS_HIBERNATE
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:505 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State HIBERNATE
2009-06-04 21:58:36 [DEBUG] mod_sofia.c:160 sofia_on_hibernate() sofia/internal/987654321 at sip.evolutiontel.net SOFIA HIBERNATE
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:212 switch_core_standard_on_hibernate() sofia/internal/987654321 at sip.evolutiontel.net Standard HIBERNATE
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:505 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State HIBERNATE going to sleep
nua(0x9d17500): event i_active 200 Call active
nua(0x9bfa748): recv signal r_respond 200 OK
nua: nua_stack_set_params: entering
soa_set_params(static::0x9bcca70, ...) called
soa_set_user_sdp(static::0x9bcca70, (nil), 0x9d739a8, -1) called
soa_set_capability_sdp(static::0x9bcca70, (nil), 0x9d739a8, -1) called
nua: nua_invite_server_respond: entering
soa_generate_answer(static::0x9bcca70) called
soa_static_offer_answer_action(0x9bcca70, soa_generate_answer): called
soa_static(0x9bcca70, soa_generate_answer): generating local description
soa_static(0x9bcca70, soa_generate_answer): upgrade with remote description
soa_static(0x9bcca70, soa_generate_answer): marking rejected media
soa_sdp_mode_set(0xb77b7fb4, 0x9c2c578, ""): called
soa_init_sdp_connection_with_session: selected IN IP4 202.125.42.98 (a local address)
soa_static(0x9bcca70, soa_generate_answer): storing local description
soa_activate(static::0x9bcca70, (nil)) called
soa_get_local_sdp(static::0x9bcca70, [(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): 1421 bytes of 1421 to udp/192.168.0.2:5060
tport_vsend returned 1421
nta: sent 200 OK for INVITE (811801)
nta: timer shortened to 500 ms
nua(0x9bfa748): call state changed: early -> completed, sent answer
soa_get_local_sdp(static::0x9bcca70, [0xb77b8124], [0xb77b8120], [(nil)]) called
soa_get_params(static::0x9bcca70, ...) called
nua(0x9bfa748): event i_state 200 OK
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) Running State Change CS_HIBERNATE
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:505 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State HIBERNATE
2009-06-04 21:58:36 [DEBUG] mod_sofia.c:160 sofia_on_hibernate() sofia/internal/1234567891 at 192.168.0.2 SOFIA HIBERNATE
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:212 switch_core_standard_on_hibernate() sofia/internal/1234567891 at 192.168.0.2 Standard HIBERNATE
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:505 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State HIBERNATE going to sleep
nua: nua_application_event: entering
nua: nua_handle_magic: entering
nua: nua_application_event: entering
2009-06-04 21:58:36 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/987654321 at sip.evolutiontel.net entering state [completed][200]
nua: nua_handle_magic: entering
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9ce6898 from (udp/192.168.0.2:5070) has 479 bytes, veclen = 1
tport_deliver(0x9bb0e28): msg 0x9ce6898 (479 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 811801)
nta: ACK (811801) is going to INVITE (811801)
nua: process_ack_or_cancel: entering
soa_clear_remote_sdp(static::0x9bcca70) called
nua(0x9bfa748): event i_ack 200 OK
nua(0x9bfa748): call state changed: completed -> ready
nua(0x9bfa748): event i_state 200 OK
nua(0x9bfa748): event i_active 200 Call active
nua: nua_application_event: entering
nua: nua_handle_magic: entering
nua: nua_application_event: entering
2009-06-04 21:58:36 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/987654321 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 0x9ce6898 from (udp/192.168.0.2:5070) has 479 bytes, veclen = 1
tport_deliver(0x9bb0e28): msg 0x9ce6898 (479 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 811802)
nta: canonizing sip:mod_sofia at 192.168.0.2:5070 with contact
nta: BYE (811802) 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): 593 bytes of 593 to udp/192.168.0.2:5060
tport_vsend returned 593
nta: sent 200 OK for BYE (811802)
nua(0x9bfa748): event i_bye 200 Session Terminated
nua(0x9bfa748): removing session usage
nua(0x9bfa748): call state changed: ready -> terminated
nua(0x9bfa748): event i_state 200 Session Terminated
nua(0x9bfa748): event i_terminated 200 Session Terminated
soa_destroy(static::0x9bcca70) called
nta_leg_destroy(0x9c19f60)
nua: nua_application_event: entering
nua: nua_handle_magic: entering
nua: nua_application_event: entering
2009-06-04 21:58:36 [DEBUG] sofia.c:3039 sofia_handle_sip_i_state() Channel sofia/internal/987654321 at sip.evolutiontel.net entering state [terminated][200]
2009-06-04 21:58:36 [NOTICE] sofia.c:3599 sofia_handle_sip_i_state() Hangup sofia/internal/987654321 at sip.evolutiontel.net [CS_HIBERNATE] [NORMAL_CLEARING]
2009-06-04 21:58:36 [DEBUG] switch_channel.c:1667 switch_channel_perform_hangup() Send signal sofia/internal/987654321 at sip.evolutiontel.net [KILL]
2009-06-04 21:58:36 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/987654321 at sip.evolutiontel.net [BREAK]
nua: nua_handle_bind: entering
nua: nua_handle_destroy: entering
nua(0x9bfa748): 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(0x9bfa748): event i_terminated dropped
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) Running State Change CS_HANGUP
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:433 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State HANGUP
2009-06-04 21:58:36 [DEBUG] mod_sofia.c:307 sofia_on_hangup() sofia/internal/987654321 at sip.evolutiontel.net Overriding SIP cause 480 with 200 from the other leg
2009-06-04 21:58:36 [DEBUG] mod_sofia.c:339 sofia_on_hangup() Channel sofia/internal/987654321 at sip.evolutiontel.net hanging up, cause: NORMAL_CLEARING
2009-06-04 21:58:36 [NOTICE] switch_ivr_bridge.c:712 signal_bridge_on_hangup() Hangup sofia/internal/1234567891 at 192.168.0.2 [CS_HIBERNATE] [NORMAL_CLEARING]
2009-06-04 21:58:36 [DEBUG] switch_channel.c:1667 switch_channel_perform_hangup() Send signal sofia/internal/1234567891 at 192.168.0.2 [KILL]
2009-06-04 21:58:36 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/1234567891 at 192.168.0.2 [BREAK]
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/internal/987654321 at sip.evolutiontel.net Standard HANGUP, cause: NORMAL_CLEARING
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:433 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State HANGUP going to sleep
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:475 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State Change CS_HANGUP -> CS_REPORTING
2009-06-04 21:58:36 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/987654321 at sip.evolutiontel.net [BREAK]
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) Running State Change CS_REPORTING
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:607 switch_core_session_reporting_state() (sofia/internal/987654321 at sip.evolutiontel.net) State REPORTING
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:53 switch_core_standard_on_reporting() sofia/internal/987654321 at sip.evolutiontel.net Standard REPORTING, cause: NORMAL_CLEARING
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:607 switch_core_session_reporting_state() (sofia/internal/987654321 at sip.evolutiontel.net) State REPORTING going to sleep
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:410 switch_core_session_run() (sofia/internal/987654321 at sip.evolutiontel.net) State Change CS_REPORTING -> CS_DESTROY
2009-06-04 21:58:36 [DEBUG] switch_core_session.c:1067 switch_core_session_thread() Session 7 (sofia/internal/987654321 at sip.evolutiontel.net) Locked, Waiting on external entities
2009-06-04 21:58:36 [NOTICE] switch_core_session.c:1085 switch_core_session_thread() Session 7 (sofia/internal/987654321 at sip.evolutiontel.net) Ended
2009-06-04 21:58:36 [NOTICE] switch_core_session.c:1087 switch_core_session_thread() Close Channel sofia/internal/987654321 at sip.evolutiontel.net [CS_DESTROY]
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:559 switch_core_session_destroy_state() (sofia/internal/987654321 at sip.evolutiontel.net) State DESTROY
2009-06-04 21:58:36 [DEBUG] mod_sofia.c:256 sofia_on_destroy() sofia/internal/987654321 at sip.evolutiontel.net SOFIA DESTROY
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:60 switch_core_standard_on_destroy() sofia/internal/987654321 at sip.evolutiontel.net Standard DESTROY
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:559 switch_core_session_destroy_state() (sofia/internal/987654321 at sip.evolutiontel.net) State DESTROY going to sleep
nua(0x9bfa748): recv signal r_destroy
nta_leg_destroy((nil))
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) Running State Change CS_HANGUP
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:433 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State HANGUP
2009-06-04 21:58:36 [DEBUG] mod_sofia.c:307 sofia_on_hangup() sofia/internal/1234567891 at 192.168.0.2 Overriding SIP cause 480 with 200 from the other leg
2009-06-04 21:58:36 [DEBUG] mod_sofia.c:339 sofia_on_hangup() Channel sofia/internal/1234567891 at 192.168.0.2 hanging up, cause: NORMAL_CLEARING
2009-06-04 21:58:36 [DEBUG] mod_sofia.c:394 sofia_on_hangup() Sending BYE to sofia/internal/1234567891 at 192.168.0.2
nua: nua_bye: entering
nua(0x9d17500): sent signal r_bye
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/internal/1234567891 at 192.168.0.2 Standard HANGUP, cause: NORMAL_CLEARING
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:433 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State HANGUP going to sleep
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:475 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State Change CS_HANGUP -> CS_REPORTING
2009-06-04 21:58:36 [DEBUG] switch_core_session.c:933 switch_core_session_signal_state_change() Send signal sofia/internal/1234567891 at 192.168.0.2 [BREAK]
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:397 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) Running State Change CS_REPORTING
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:607 switch_core_session_reporting_state() (sofia/internal/1234567891 at 192.168.0.2) State REPORTING
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:53 switch_core_standard_on_reporting() sofia/internal/1234567891 at 192.168.0.2 Standard REPORTING, cause: NORMAL_CLEARING
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:607 switch_core_session_reporting_state() (sofia/internal/1234567891 at 192.168.0.2) State REPORTING going to sleep
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:410 switch_core_session_run() (sofia/internal/1234567891 at 192.168.0.2) State Change CS_REPORTING -> CS_DESTROY
2009-06-04 21:58:36 [DEBUG] switch_core_session.c:1067 switch_core_session_thread() Session 8 (sofia/internal/1234567891 at 192.168.0.2) Locked, Waiting on external entities
2009-06-04 21:58:36 [NOTICE] switch_core_session.c:1085 switch_core_session_thread() Session 8 (sofia/internal/1234567891 at 192.168.0.2) Ended
2009-06-04 21:58:36 [NOTICE] switch_core_session.c:1087 switch_core_session_thread() Close Channel sofia/internal/1234567891 at 192.168.0.2 [CS_DESTROY]
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:559 switch_core_session_destroy_state() (sofia/internal/1234567891 at 192.168.0.2) State DESTROY
2009-06-04 21:58:36 [DEBUG] mod_sofia.c:256 sofia_on_destroy() sofia/internal/1234567891 at 192.168.0.2 SOFIA DESTROY
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:60 switch_core_standard_on_destroy() sofia/internal/1234567891 at 192.168.0.2 Standard DESTROY
2009-06-04 21:58:36 [DEBUG] switch_core_state_machine.c:559 switch_core_session_destroy_state() (sofia/internal/1234567891 at 192.168.0.2) State DESTROY going to sleep
nua(0x9d17500): recv signal r_bye
nua: nua_stack_set_params: entering
soa_set_params(static::0x9bf1e20, ...) called
soa_terminate(static::0x9bf1e20) called
soa_init_offer_answer(static::0x9bf1e20) 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): 871 bytes of 871 to udp/192.168.0.2:5060
tport_vsend returned 871
nta: sent BYE (115940022) to */192.168.0.2:5060
tport_pend(0x9bb0e28): pending 0x9d19bc8 for udp/192.168.0.2:5070 (already 0)
2009-06-04 21:58:36 [DEBUG] switch_scheduler.c:138 task_thread_loop() Deleting task 6 switch_ivr_schedule_hangup (6dd5c26f-8cfc-4876-a538-ed5f5e03cc1b)
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9c84f30 from (udp/192.168.0.2:5070) has 449 bytes, veclen = 1
tport_deliver(0x9bb0e28): msg 0x9c84f30 (449 bytes) from udp/192.168.0.2:5070/sip next=(nil)
nta: received 200 OK for BYE (115940022)
nta: 200 OK is going to a transaction
nta_outgoing: RTT is 97.734 ms
tport_release(0x9bb0e28): 0x9d19bc8 by 0x9bb6ef8 with 0x9c84f30
nua(0x9d17500): event r_bye 200 OK
nua(0x9d17500): call state changed: terminating -> terminated
nua(0x9d17500): event i_state 200 to BYE
nua(0x9d17500): event i_terminated 200 to BYE
nua(0x9d17500): removing session usage
soa_destroy(static::0x9bf1e20) called
nta_leg_destroy(0x9bce5c8)
nua: terminated session 0x9d17500
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(0x9d17500): sent signal r_destroy
nua: nua_application_event: entering
nua(0x9d17500): event i_terminated dropped
nua(0x9d17500): recv signal r_destroy
nta_leg_destroy((nil))
nta: timer set next to 4634 ms
tport_wakeup_pri(0x9bb0e28): events IN
tport_recv_event(0x9bb0e28)
tport_recv_iovec(0x9bb0e28) msg 0x9ce6aa0 from (udp/192.168.0.2:5070) has 479 bytes, veclen = 1
tport_deliver(0x9bb0e28): msg 0x9ce6aa0 (479 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 811802)
nta: BYE (811802) going to existing BYE transaction
nta: re-received BYE request, retransmitting 200 reply
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): 593 bytes of 593 to udp/192.168.0.2:5060
tport_vsend returned 593
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 107 ms
nta: timer K fired, terminate BYE (115940022)
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 26750 ms
/exit
[root at sip01 bin]#