[Freeswitch-dev] second leg of call isnt hanged up by Freeswitch

Michael Jerris mike at jerris.com
Wed Apr 9 12:39:58 EDT 2008 

This issue is now fixed in svn trunk:

http://fisheye.freeswitch.org/changelog/FreeSWITCH/?cs=8062

fix hung channels when using respond app with 1xx or 2xx responses or  
on re-invite in proxy/bypass media with 1xx and 2xx responses

Mike


On Apr 8, 2008, at 3:23 PM, kokoska rokoska wrote:

>
>
> kokoska rokoska napsal(a):
>> kokoska rokoska napsal(a):
>>>
>>> Anthony Minessale napsal(a):
>>>> That's all fine but the call leg does exist?
>>>>
>>>>
>>>> phoneA -- legA ---> FS <--- legB--- phoneB
>>>>
>>>>
>>>> if phoneB leaves and FS did not get a bye legA will never end so  
>>>> naturally when you hangup
>>>> phoneA you will get a 200ok on it's leg.
>>>>
>>>> That is why I asked you for the traces because it's most likely  
>>>> the case that legA is still up
>>>> because legB is as well and only phoneB thinks the call is over.
>>>>
>>> I sent the dump few minutes before...
>>>
>>> BTW: Phone B sends BYE, recieves 200 OK and Freeswitch announce  
>>> hangup on console. But leaves call leg A alive.
>>> If I don't use "transfer" app, everything works ok.
>>>
>>> Now I'm try to install IRC client and join conference :-)
>>>
>>> Regards,
>>>
>>> kokoska.rokoska
>>>
>> My e-mail with dump (400 kB) was rejected. How can I send the dump?
>> Regards,
>> kokoska.rokoska
>
> Here is console dump.
>
> regards,
>
> kokoska.rokoska
>
>
>
>
>
>
> 2008-04-08 20:19:50 [DEBUG] sofia.c:219 sofia_event_callback() event  
> [nua_i_state] status [407][Proxy Authentication Required] session: n/a
> 2008-04-08 20:19:50 [NOTICE] switch_channel.c:531  
> switch_channel_set_name() New Channel sofia/default/0002*23 at 192.168.1.128 
> :5065 [0821700d-67c1-46dc-8d9e-8e2b77f8d9a0]
> 2008-04-08 20:19:50 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state()  
> Channel sofia/default/0002*23 at 192.168.1.128:5065 entering state  
> [received]
> 2008-04-08 20:19:50 [DEBUG] sofia.c:1599 sofia_handle_sip_i_state()  
> Remote SDP:
> v=0
> o=- 3416667593 3416667593 IN IP4 192.168.1.101
> s=SJphone
> c=IN IP4 192.168.1.101
> t=0 0
> m=audio 49152 RTP/AVP 8 101
> c=IN IP4 192.168.1.101
> a=rtpmap:8 PCMA/8000
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=setup:active
>
> 2008-04-08 20:19:50 [DEBUG] sofia_glue.c:2011  
> sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/ 
> [G722:9:8000]
> 2008-04-08 20:19:50 [DEBUG] sofia_glue.c:2011  
> sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[PCMA: 
> 8:8000]
> 2008-04-08 20:19:50 [DEBUG] sofia_glue.c:1333  
> sofia_glue_tech_set_codec() Set Codec sofia/default/0002*23 at 192.168.1.128 
> :5065 PCMA/8000 20 ms 160 samples
> 2008-04-08 20:19:50 [DEBUG] sofia_glue.c:1975  
> sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101
> 2008-04-08 20:19:50 [DEBUG] sofia.c:1736 sofia_handle_sip_i_state() sofia/default/0002*23 at 192.168.1.128 
> :5065 State Change CS_NEW -> CS_INIT
> 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*23 at 192.168.1.128:5065  
> Running State Change CS_INIT
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:413  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State INIT
> 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:80 sofia_on_init() sofia/default/0002*23 at 192.168.1.128 
> :5065 SOFIA INIT
> 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:107 sofia_on_init() sofia/default/0002*23 at 192.168.1.128 
> :5065 State Change CS_INIT -> CS_RING
> 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:413  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State INIT going to sleep
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*23 at 192.168.1.128:5065  
> Running State Change CS_RING
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:418  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State RING
> 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/0002*23 at 192.168.1.128 
> :5065 SOFIA RING
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:65  
> switch_core_standard_on_ring() Standard RING sofia/default/0002*23 at 192.168.1.128 
> :5065
> 2008-04-08 20:19:50 [INFO] mod_dialplan_xml.c:223 dialplan_hunt()  
> Processing unknown->23 at default
> 2008-04-08 20:19:50 [DEBUG] mod_dialplan_xml.c:107 parse_exten()  
> test conditions destination_number(23) =~ /^.*$/
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:96  
> switch_core_standard_on_ring() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 State Change CS_RING -> CS_EXECUTE
> 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:418  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State RING going to sleep
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*23 at 192.168.1.128:5065  
> Running State Change CS_EXECUTE
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:428  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State EXECUTE
> 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/default/0002*23 at 192.168.1.128 
> :5065 SOFIA EXECUTE
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:128  
> switch_core_standard_on_execute() Standard EXECUTE
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute set(forward_counter=1)
> 2008-04-08 20:19:50 [DEBUG] mod_dptools.c:493 set_function() SET  
> [forward_counter]=[1]
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute export(forward_counter=1)
> 2008-04-08 20:19:50 [DEBUG] mod_dptools.c:626 export_function()  
> EXPORT [forward_counter]=[1]
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute respond(181 Call is being  
> forwarded)
> 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:990 sofia_receive_message()  
> Responding with 181 Call is being forwarded
> 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute export(sip_h_Diversion=<sip:24 at 192.168.1.128 
> >;reason=uncoditional;counter=1)
> 2008-04-08 20:19:50 [DEBUG] mod_dptools.c:626 export_function()  
> EXPORT [sip_h_Diversion]=[<sip: 
> 24 at 192.168.1.128>;reason=uncoditional;counter=1]
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute transfer(24)
> 2008-04-08 20:19:50 [DEBUG] switch_ivr.c:1007  
> switch_ivr_session_transfer() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 State Change CS_EXECUTE -> CS_RING
> 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:50 [NOTICE] switch_ivr.c:1013  
> switch_ivr_session_transfer() Transfer sofia/default/0002*23 at 192.168.1.128 
> :5065 to XML[24 at default]
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:428  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State EXECUTE going to sleep
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*23 at 192.168.1.128:5065  
> Running State Change CS_RING
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:418  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State RING
> 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/0002*23 at 192.168.1.128 
> :5065 SOFIA RING
> 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:65  
> switch_core_standard_on_ring() Standard RING sofia/default/0002*23 at 192.168.1.128 
> :5065
> 2008-04-08 20:19:50 [INFO] mod_dialplan_xml.c:223 dialplan_hunt()  
> Processing unknown->24 at default
> 2008-04-08 20:19:50 [DEBUG] sofia.c:219 sofia_event_callback() event  
> [nua_i_state] status [181][Call is being forwarded] session: sofia/default/0002*23 at 192.168.1.128 
> :5065
> 2008-04-08 20:19:51 [DEBUG] mod_dialplan_xml.c:107 parse_exten()  
> test conditions destination_number(24) =~ /^.*$/
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:96  
> switch_core_standard_on_ring() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 State Change CS_RING -> CS_EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State RING going to sleep
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*23 at 192.168.1.128:5065  
> Running State Change CS_EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:428  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State EXECUTE
> 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/default/0002*23 at 192.168.1.128 
> :5065 SOFIA EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:128  
> switch_core_standard_on_execute() Standard EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute set(forward_counter=2)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET  
> [forward_counter]=[2]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute export(forward_counter=2)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function()  
> EXPORT [forward_counter]=[2]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute respond(181 Call is being  
> forwarded)
> 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:990 sofia_receive_message()  
> Responding with 181 Call is being forwarded
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute export(sip_h_Diversion=<sip:22 at 192.168.1.128 
> >;reason=uncoditional;counter=2)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function()  
> EXPORT [sip_h_Diversion]=[<sip: 
> 22 at 192.168.1.128>;reason=uncoditional;counter=2]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute transfer(22)
> 2008-04-08 20:19:51 [DEBUG] switch_ivr.c:1007  
> switch_ivr_session_transfer() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 State Change CS_EXECUTE -> CS_RING
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:51 [NOTICE] switch_ivr.c:1013  
> switch_ivr_session_transfer() Transfer sofia/default/0002*23 at 192.168.1.128 
> :5065 to XML[22 at default]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:428  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State EXECUTE going to sleep
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*23 at 192.168.1.128:5065  
> Running State Change CS_RING
> 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state()  
> Channel sofia/default/0002*23 at 192.168.1.128:5065 entering state  
> [early]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State RING
> 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/0002*23 at 192.168.1.128 
> :5065 SOFIA RING
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:65  
> switch_core_standard_on_ring() Standard RING sofia/default/0002*23 at 192.168.1.128 
> :5065
> 2008-04-08 20:19:51 [INFO] mod_dialplan_xml.c:223 dialplan_hunt()  
> Processing unknown->22 at default
> 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event  
> [nua_i_state] status [181][Call is being forwarded] session: sofia/default/0002*23 at 192.168.1.128 
> :5065
> 2008-04-08 20:19:51 [DEBUG] mod_dialplan_xml.c:107 parse_exten()  
> test conditions destination_number(22) =~ /^.*$/
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:96  
> switch_core_standard_on_ring() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 State Change CS_RING -> CS_EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State RING going to sleep
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*23 at 192.168.1.128:5065  
> Running State Change CS_EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:428  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State EXECUTE
> 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/default/0002*23 at 192.168.1.128 
> :5065 SOFIA EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:128  
> switch_core_standard_on_execute() Standard EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute set(forward_counter=3)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET  
> [forward_counter]=[3]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute export(forward_counter=3)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function()  
> EXPORT [forward_counter]=[3]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute respond(181 Call is being  
> forwarded)
> 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state()  
> Channel sofia/default/0002*23 at 192.168.1.128:5065 entering state  
> [early]
> 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:990 sofia_receive_message()  
> Responding with 181 Call is being forwarded
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute export(sip_h_Diversion=<sip:21 at 192.168.1.128 
> >;reason=uncoditional;counter=3)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function()  
> EXPORT [sip_h_Diversion]=[<sip: 
> 21 at 192.168.1.128>;reason=uncoditional;counter=3]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute transfer(21)
> 2008-04-08 20:19:51 [DEBUG] switch_ivr.c:1007  
> switch_ivr_session_transfer() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 State Change CS_EXECUTE -> CS_RING
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:51 [NOTICE] switch_ivr.c:1013  
> switch_ivr_session_transfer() Transfer sofia/default/0002*23 at 192.168.1.128 
> :5065 to XML[21 at default]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:428  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State EXECUTE going to sleep
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*23 at 192.168.1.128:5065  
> Running State Change CS_RING
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State RING
> 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/0002*23 at 192.168.1.128 
> :5065 SOFIA RING
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:65  
> switch_core_standard_on_ring() Standard RING sofia/default/0002*23 at 192.168.1.128 
> :5065
> 2008-04-08 20:19:51 [INFO] mod_dialplan_xml.c:223 dialplan_hunt()  
> Processing unknown->21 at default
> 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event  
> [nua_i_state] status [181][Call is being forwarded] session: sofia/default/0002*23 at 192.168.1.128 
> :5065
> 2008-04-08 20:19:51 [DEBUG] mod_dialplan_xml.c:107 parse_exten()  
> test conditions destination_number(21) =~ /^.*$/
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:96  
> switch_core_standard_on_ring() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 State Change CS_RING -> CS_EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State RING going to sleep
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*23 at 192.168.1.128:5065  
> Running State Change CS_EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:428  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State EXECUTE
> 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/default/0002*23 at 192.168.1.128 
> :5065 SOFIA EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:128  
> switch_core_standard_on_execute() Standard EXECUTE
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute set(dialed_ext=21)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET  
> [dialed_ext]=[21]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute export(dialed_ext=21)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function()  
> EXPORT [dialed_ext]=[21]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute export(dst_user=0002*21)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function()  
> EXPORT [dst_user]=[0002*21]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute set(call_timeout=10)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET  
> [call_timeout]=[10]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute set(sip_exclude_contact=$ 
> {network_addr})
> 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state()  
> Channel sofia/default/0002*23 at 192.168.1.128:5065 entering state  
> [early]
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:984  
> switch_core_session_execute_application() sofia/default/0002*23 at 192.168.1.128 
> :5065 Expanded String set(sip_exclude_contact=192.168.1.101)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET  
> [sip_exclude_contact]=[192.168.1.101]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute set(hangup_after_bridge=true)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET  
> [hangup_after_bridge]=[true]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute set(continue_on_fail=true)
> 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET  
> [continue_on_fail]=[true]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139  
> switch_core_standard_on_execute() sofia/default/ 
> 0002*23 at 192.168.1.128:5065 Execute bridge(sofia/default/${dst_user} 
> %192.168.1.128)
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:984  
> switch_core_session_execute_application() sofia/default/0002*23 at 192.168.1.128 
> :5065 Expanded String bridge(sofia/default/0002*21%192.168.1.128)
> 2008-04-08 20:19:51 [NOTICE] switch_channel.c:531  
> switch_channel_set_name() New Channel sofia/default/0002*21  
> [0ded99a5-5044-48d2-96ab-66f43af1a03c]
> 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:1829  
> sofia_outgoing_channel() sofia/default/0002*21 State Change CS_NEW - 
> > CS_INIT
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*21  
> [BREAK]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*21 Running State Change  
> CS_INIT
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:413  
> switch_core_session_run() (sofia/default/0002*21) State INIT
> 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:80 sofia_on_init() sofia/ 
> default/0002*21 SOFIA INIT
> 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event  
> [nua_i_state] status [0][INVITE sent] session: sofia/default/0002*21
> 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:107 sofia_on_init() sofia/ 
> default/0002*21 State Change CS_INIT -> CS_RING
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*21  
> [BREAK]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:413  
> switch_core_session_run() (sofia/default/0002*21) State INIT going  
> to sleep
> 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state()  
> Channel sofia/default/0002*21 entering state [calling]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*21 Running State Change  
> CS_RING
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418  
> switch_core_session_run() (sofia/default/0002*21) State RING
> 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/ 
> default/0002*21 SOFIA RING
> 2008-04-08 20:19:51 [DEBUG] switch_ivr_originate.c:55  
> originate_on_ring() sofia/default/0002*21 State Change CS_RING ->  
> CS_HOLD
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*21  
> [BREAK]
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418  
> switch_core_session_run() (sofia/default/0002*21) State RING going  
> to sleep
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*21 Running State Change  
> CS_HOLD
> 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:440  
> switch_core_session_run() (sofia/default/0002*21) State HOLD
> 2008-04-08 20:19:51 [DEBUG] switch_ivr_originate.c:951  
> switch_ivr_originate() Raw Codec Activation Success L16 at 8000hz 1  
> channel 20ms
> 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event  
> [nua_r_invite] status [180][Ringing] session: sofia/default/0002*21
> 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event  
> [nua_i_state] status [180][Ringing] session: sofia/default/0002*21
> 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state()  
> Channel sofia/default/0002*21 entering state [proceeding]
> 2008-04-08 20:19:51 [NOTICE] sofia.c:1633 sofia_handle_sip_i_state()  
> Ring-Ready sofia/default/0002*21!
> 2008-04-08 20:19:51 [NOTICE] mod_sofia.c:1017  
> sofia_receive_message() Ring-Ready sofia/default/ 
> 0002*23 at 192.168.1.128:5065!
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:51 [NOTICE] switch_ivr_originate.c:1026  
> switch_ivr_originate() Ring Ready sofia/default/ 
> 0002*23 at 192.168.1.128:5065!
> 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event  
> [nua_i_state] status [180][Ringing] session: sofia/default/0002*23 at 192.168.1.128 
> :5065
> 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state()  
> Channel sofia/default/0002*23 at 192.168.1.128:5065 entering state  
> [early]
> 2008-04-08 20:19:53 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state()  
> Channel sofia/default/0002*21 entering state [ready]
> 2008-04-08 20:19:53 [DEBUG] sofia.c:1599 sofia_handle_sip_i_state()  
> Remote SDP:
> v=0
> o=- 18939677 18939677 IN IP4 192.168.1.151
> s=-
> c=IN IP4 192.168.1.151
> t=0 0
> m=audio 16424 RTP/AVP 8 100 101
> a=rtpmap:8 PCMA/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
>
> 2008-04-08 20:19:53 [DEBUG] sofia_glue.c:2011  
> sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[PCMA: 
> 8:8000]
> 2008-04-08 20:19:53 [DEBUG] sofia_glue.c:1333  
> sofia_glue_tech_set_codec() Set Codec sofia/default/0002*21 PCMA/ 
> 8000 20 ms 160 samples
> 2008-04-08 20:19:53 [DEBUG] sofia_glue.c:1975  
> sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101
> 2008-04-08 20:19:53 [DEBUG] sofia_glue.c:1523  
> sofia_glue_activate_rtp() AUDIO RTP [sofia/default/0002*21]  
> 192.168.1.128:26702->192.168.1.151:16424 codec: 8 ms: 20
> 2008-04-08 20:19:53 [DEBUG] switch_rtp.c:716 switch_rtp_create()  
> Starting timer [soft] 160 bytes per 20000ms
> 2008-04-08 20:19:53 [DEBUG] switch_channel.c:1506  
> switch_channel_perform_mark_answered() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:53 [NOTICE] sofia.c:1945 sofia_handle_sip_i_state()  
> Channel [sofia/default/0002*21] has been answered
> 2008-04-08 20:19:53 [DEBUG] sofia_glue.c:1523  
> sofia_glue_activate_rtp() AUDIO RTP [sofia/default/0002*23 at 192.168.1.128 
> :5065] 192.168.1.128:22042->192.168.1.101:49152 codec: 8 ms: 20
> 2008-04-08 20:19:53 [DEBUG] switch_rtp.c:716 switch_rtp_create()  
> Starting timer [soft] 160 bytes per 20000ms
> 2008-04-08 20:19:53 [DEBUG] mod_sofia.c:376 sofia_answer_channel()  
> Local SDP sofia/default/0002*23 at 192.168.1.128:5065:
> v=0
> o=FreeSWITCH 1207656751 1207656752 IN IP4 192.168.1.128
> s=FreeSWITCH
> c=IN IP4 192.168.1.128
> t=0 0
> a=sendrecv
> m=audio 22042 RTP/AVP 8 101 13
> a=rtpmap:8 PCMA/8000
> a=rtpmap:101 telephone-event/8000
> a=fmtp:101 0-16
> a=rtpmap:13 CN/8000
> a=ptime:20
>
> 2008-04-08 20:19:53 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:53 [NOTICE] switch_ivr_originate.c:1171  
> switch_ivr_originate() Channel [sofia/default/ 
> 0002*23 at 192.168.1.128:5065] has been answered
> 2008-04-08 20:19:53 [DEBUG] switch_ivr_originate.c:1205  
> switch_ivr_originate() Originate Resulted in Success: [sofia/default/ 
> 0002*21]
> 2008-04-08 20:19:53 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*21  
> [BREAK]
> 2008-04-08 20:19:53 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:19:53 [DEBUG] switch_ivr_bridge.c:756  
> switch_ivr_multi_threaded_bridge() sofia/default/0002*21 State  
> Change CS_HOLD -> CS_LOOPBACK
> 2008-04-08 20:19:53 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*21  
> [BREAK]
> 2008-04-08 20:19:53 [DEBUG] switch_core_state_machine.c:440  
> switch_core_session_run() (sofia/default/0002*21) State HOLD going  
> to sleep
> 2008-04-08 20:19:53 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*21 Running State Change  
> CS_LOOPBACK
> 2008-04-08 20:19:53 [DEBUG] switch_core_state_machine.c:431  
> switch_core_session_run() (sofia/default/0002*21) State LOOPBACK
> 2008-04-08 20:19:53 [DEBUG] mod_sofia.c:314 sofia_on_loopback()  
> SOFIA LOOPBACK
> 2008-04-08 20:19:53 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state()  
> Channel sofia/default/0002*23 at 192.168.1.128:5065 entering state  
> [completed]
> 2008-04-08 20:19:53 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state()  
> Channel sofia/default/0002*23 at 192.168.1.128:5065 entering state  
> [ready]
> 2008-04-08 20:20:08 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state()  
> Channel sofia/default/0002*21 entering state [terminated]
> 2008-04-08 20:20:08 [NOTICE] sofia.c:1992 sofia_handle_sip_i_state()  
> Hangup sofia/default/0002*21 [CS_LOOPBACK] [NORMAL_CLEARING]
> 2008-04-08 20:20:08 [DEBUG] switch_channel.c:1355  
> switch_channel_perform_hangup() Kill sofia/default/0002*21 [KILL]
> 2008-04-08 20:20:08 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*21  
> [BREAK]
> 2008-04-08 20:20:08 [DEBUG] switch_ivr_bridge.c:275  
> audio_bridge_thread() read: sofia/default/0002*21 Bad Frame.... Bubye!
> 2008-04-08 20:20:08 [DEBUG] switch_ivr_bridge.c:344  
> audio_bridge_thread() Kill sofia/default/0002*23 at 192.168.1.128:5065  
> [BREAK]
> 2008-04-08 20:20:08 [DEBUG] switch_ivr_bridge.c:347  
> audio_bridge_thread() BRIDGE THREAD DONE [sofia/default/0002*21]
> 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:431  
> switch_core_session_run() (sofia/default/0002*21) State LOOPBACK  
> going to sleep
> 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*21 Running State Change  
> CS_HANGUP
> 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:392  
> switch_core_session_run() (sofia/default/0002*21) State HANGUP
> 2008-04-08 20:20:08 [DEBUG] mod_sofia.c:255 sofia_on_hangup()  
> Channel sofia/default/0002*21 hanging up, cause: NORMAL_CLEARING
> 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:46  
> switch_core_standard_on_hangup() Standard HANGUP sofia/default/ 
> 0002*21, cause: NORMAL_CLEARING
> 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:392  
> switch_core_session_run() (sofia/default/0002*21) State HANGUP going  
> to sleep
> 2008-04-08 20:20:08 [DEBUG] switch_core_session.c:730  
> switch_core_session_thread() Session 2 (sofia/default/0002*21)  
> Locked, Waiting on external entities
> 2008-04-08 20:20:08 [DEBUG] switch_core_session.c:383  
> switch_core_session_receive_message() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:20:08 [DEBUG] switch_ivr_bridge.c:344  
> audio_bridge_thread() Kill sofia/default/0002*21 [BREAK]
> 2008-04-08 20:20:08 [DEBUG] switch_ivr_bridge.c:347  
> audio_bridge_thread() BRIDGE THREAD DONE [sofia/default/0002*23 at 192.168.1.128 
> :5065]
> 2008-04-08 20:20:08 [NOTICE] switch_ivr_bridge.c:802  
> switch_ivr_multi_threaded_bridge() Hangup sofia/default/0002*23 at 192.168.1.128 
> :5065 [CS_EXECUTE] [NORMAL_CLEARING]
> 2008-04-08 20:20:08 [DEBUG] switch_channel.c:1355  
> switch_channel_perform_hangup() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [KILL]
> 2008-04-08 20:20:08 [DEBUG] switch_core_session.c:670  
> switch_core_session_signal_state_change() Kill sofia/default/0002*23 at 192.168.1.128 
> :5065 [BREAK]
> 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:428  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State EXECUTE going to sleep
> 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:364  
> switch_core_session_run() sofia/default/0002*23 at 192.168.1.128:5065  
> Running State Change CS_HANGUP
> 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:392  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State HANGUP
> 2008-04-08 20:20:08 [DEBUG] mod_sofia.c:255 sofia_on_hangup()  
> Channel sofia/default/0002*23 at 192.168.1.128:5065 hanging up, cause:  
> NORMAL_CLEARING
> 2008-04-08 20:20:08 [NOTICE] switch_core_session.c:748  
> switch_core_session_thread() Session 2 (sofia/default/0002*21) Ended
> 2008-04-08 20:20:08 [NOTICE] switch_core_session.c:750  
> switch_core_session_thread() Close Channel sofia/default/0002*21  
> [CS_HANGUP]
> 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:46  
> switch_core_standard_on_hangup() Standard HANGUP sofia/default/0002*23 at 192.168.1.128 
> :5065, cause: NORMAL_CLEARING
> 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:392  
> switch_core_session_run() (sofia/default/0002*23 at 192.168.1.128:5065)  
> State HANGUP going to sleep
> 2008-04-08 20:20:08 [DEBUG] switch_core_session.c:730  
> switch_core_session_thread() Session 1 (sofia/default/0002*23 at 192.168.1.128 
> :5065) Locked, Waiting on external entities
> 2008-04-08 20:20:08 [NOTICE] switch_core_session.c:748  
> switch_core_session_thread() Session 1 (sofia/default/0002*23 at 192.168.1.128 
> :5065) Ended
> 2008-04-08 20:20:08 [NOTICE] switch_core_session.c:750  
> switch_core_session_thread() Close Channel sofia/default/0002*23 at 192.168.1.128 
> :5065 [CS_HANGUP]
> _______________________________________________
> Freeswitch-dev mailing list
> Freeswitch-dev at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev
> http://www.freeswitch.org

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-dev/attachments/20080409/a8c40c2d/attachment-0001.html

More information about the Freeswitch-dev mailing list