[Freeswitch-users] session-api - How to continue with A-leg after bridge-timeout?

Fri Mar 9 20:51:30 MSK 2012

> Hmm, what i don't understand - when i rebuild the same route-logic in
> XML, the initiating channel is not hung up but continues the steps in
> the extension it has been transfered to

Attached is a log of this scenario, i've only added an additional
"info" to the XML-dialplan posted before.

The initial channel bf969cf6-6a0f-11e1-8e5c-299021af10b6 is still
there at the very end of the transfered call - there must be some way
to get the same result in my script-based routing and be able to
reroute this initial channel?

Regards,
Christian
-------------- next part --------------
   ------------------------------------------------------------------------
recv 864 bytes from udp/[10.3.0.22]:5060 at 17:46:06.881969:
   ------------------------------------------------------------------------
   INVITE sip:820 at 10.3.0.4:5060;user=phone SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bKb780533fA6980116
   From: "A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314
   To: <sip:820 at 10.3.0.4;user=phone>
   CSeq: 1 INVITE
   Call-ID: 73ec8749-ef90cb48-95fd5843 at 10.3.0.22
   Contact: <sip:10 at 10.3.0.22>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Supported: 100rel,replaces
   Allow-Events: talk,hold,conference
   Max-Forwards: 70
   Content-Type: application/sdp
   Content-Length: 241

   v=0
   o=- 1167610354 1167610354 IN IP4 10.3.0.22
   s=Polycom IP Phone
   c=IN IP4 10.3.0.22
   t=0 0
   a=sendrecv
   m=audio 2226 RTP/AVP 9 0 8 127
   a=rtpmap:9 G722/8000
   a=rtpmap:0 PCMU/8000
   a=rtpmap:8 PCMA/8000
   a=rtpmap:127 telephone-event/8000
   ------------------------------------------------------------------------
send 335 bytes to udp/[10.3.0.22]:5060 at 17:46:06.883097:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bKb780533fA6980116
   From: "A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314
   To: <sip:820 at 10.3.0.4;user=phone>
   Call-ID: 73ec8749-ef90cb48-95fd5843 at 10.3.0.22
   CSeq: 1 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:06.873921 [DEBUG] sofia.c:7567 IP 10.3.0.22 Rejected by acl "domains". Falling back to Digest auth.
2012-03-09 18:46:06.873921 [WARNING] sofia_reg.c:1422 SIP auth challenge (INVITE) on sofia profile 'internal' for [820 at 10.3.0.4] from ip 10.3.0.22
send 818 bytes to udp/[10.3.0.22]:5060 at 17:46:06.887952:
   ------------------------------------------------------------------------
   SIP/2.0 407 Proxy Authentication Required
   Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bKb780533fA6980116
   From: "A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314
   To: <sip:820 at 10.3.0.4;user=phone>;tag=v24X3rSHa9e9S
   Call-ID: 73ec8749-ef90cb48-95fd5843 at 10.3.0.22
   CSeq: 1 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Accept: application/sdp
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Proxy-Authenticate: Digest realm="10.3.0.4", nonce="bf913b3a-6a0f-11e1-8e5b-299021af10b6", algorithm=MD5, qop="auth"
   Content-Length: 0

   ------------------------------------------------------------------------
recv 538 bytes from udp/[10.3.0.22]:5060 at 17:46:06.903231:
   ------------------------------------------------------------------------
   ACK sip:820 at 10.3.0.4:5060;user=phone SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bKb780533fA6980116
   From: "A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314
   To: <sip:820 at 10.3.0.4;user=phone>;tag=v24X3rSHa9e9S
   CSeq: 1 ACK
   Call-ID: 73ec8749-ef90cb48-95fd5843 at 10.3.0.22
   Contact: <sip:10 at 10.3.0.22>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Max-Forwards: 70
   Content-Length: 0

   ------------------------------------------------------------------------
recv 1120 bytes from udp/[10.3.0.22]:5060 at 17:46:06.910997:
   ------------------------------------------------------------------------
   INVITE sip:820 at 10.3.0.4:5060;user=phone SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bK747f362a84831CAD
   From: "A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314
   To: <sip:820 at 10.3.0.4;user=phone>
   CSeq: 2 INVITE
   Call-ID: 73ec8749-ef90cb48-95fd5843 at 10.3.0.22
   Contact: <sip:10 at 10.3.0.22>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Supported: 100rel,replaces
   Allow-Events: talk,hold,conference
   Proxy-Authorization: Digest username="10", realm="10.3.0.4", nonce="bf913b3a-6a0f-11e1-8e5b-299021af10b6", qop=auth, cnonce="+FNV0YSM4tEnYzr", nc=00000001, uri="sip:820 at 10.3.0.4:5060;user=phone", response="75f359abb81875ac5b6b9a587665ce8d", algorithm=MD5
   Max-Forwards: 70
   Content-Type: application/sdp
   Content-Length: 241

   v=0
   o=- 1167610354 1167610354 IN IP4 10.3.0.22
   s=Polycom IP Phone
   c=IN IP4 10.3.0.22
   t=0 0
   a=sendrecv
   m=audio 2226 RTP/AVP 9 0 8 127
   a=rtpmap:9 G722/8000
   a=rtpmap:0 PCMU/8000
   a=rtpmap:8 PCMA/8000
   a=rtpmap:127 telephone-event/8000
   ------------------------------------------------------------------------
send 335 bytes to udp/[10.3.0.22]:5060 at 17:46:06.912114:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bK747f362a84831CAD
   From: "A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314
   To: <sip:820 at 10.3.0.4;user=phone>
   Call-ID: 73ec8749-ef90cb48-95fd5843 at 10.3.0.22
   CSeq: 2 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:06.913289 [DEBUG] sofia.c:7567 IP 10.3.0.22 Rejected by acl "domains". Falling back to Digest auth.
2012-03-09 18:46:06.913289 [NOTICE] switch_channel.c:926 New Channel sofia/internal/10 at 10.3.0.4 [bf969cf6-6a0f-11e1-8e5c-299021af10b6]
2012-03-09 18:46:06.913289 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10 at 10.3.0.4) Running State Change CS_NEW
2012-03-09 18:46:06.913289 [DEBUG] switch_core_state_machine.c:380 (sofia/internal/10 at 10.3.0.4) State NEW
2012-03-09 18:46:06.913289 [DEBUG] sofia.c:5532 Channel sofia/internal/10 at 10.3.0.4 entering state [received][100]
2012-03-09 18:46:06.913289 [DEBUG] sofia.c:5543 Remote SDP:
v=0
o=- 1167610354 1167610354 IN IP4 10.3.0.22
s=Polycom IP Phone
c=IN IP4 10.3.0.22
t=0 0
a=sendrecv
m=audio 2226 RTP/AVP 9 0 8 127
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:127 telephone-event/8000

2012-03-09 18:46:06.913289 [DEBUG] sofia_glue.c:4874 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000]
2012-03-09 18:46:06.913289 [DEBUG] sofia_glue.c:2991 Set Codec sofia/internal/10 at 10.3.0.4 G722/8000 20 ms 160 samples 64000 bits
2012-03-09 18:46:06.913289 [DEBUG] switch_core_codec.c:111 sofia/internal/10 at 10.3.0.4 Original read codec set to G722:9
2012-03-09 18:46:06.913289 [DEBUG] sofia_glue.c:4995 Set 2833 dtmf send/recv payload to 127
2012-03-09 18:46:06.913289 [DEBUG] sofia.c:5757 (sofia/internal/10 at 10.3.0.4) State Change CS_NEW -> CS_INIT
2012-03-09 18:46:06.913289 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:06.913289 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10 at 10.3.0.4) Running State Change CS_INIT
2012-03-09 18:46:06.913289 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/10 at 10.3.0.4) State INIT
2012-03-09 18:46:06.913289 [DEBUG] mod_sofia.c:85 sofia/internal/10 at 10.3.0.4 SOFIA INIT
2012-03-09 18:46:06.913289 [DEBUG] mod_sofia.c:125 (sofia/internal/10 at 10.3.0.4) State Change CS_INIT -> CS_ROUTING
2012-03-09 18:46:06.913289 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:06.913289 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/10 at 10.3.0.4) State INIT going to sleep
2012-03-09 18:46:06.913289 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10 at 10.3.0.4) Running State Change CS_ROUTING
2012-03-09 18:46:06.913289 [DEBUG] switch_channel.c:1886 (sofia/internal/10 at 10.3.0.4) Callstate Change DOWN -> RINGING
2012-03-09 18:46:06.913289 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/10 at 10.3.0.4) State ROUTING
2012-03-09 18:46:06.913289 [DEBUG] mod_sofia.c:148 sofia/internal/10 at 10.3.0.4 SOFIA ROUTING
2012-03-09 18:46:06.913289 [DEBUG] switch_core_state_machine.c:104 sofia/internal/10 at 10.3.0.4 Standard ROUTING
2012-03-09 18:46:06.913289 [INFO] mod_dialplan_xml.c:485 Processing A <10>->820 in context default
Dialplan: sofia/internal/10 at 10.3.0.4 parsing [default->test1] continue=false
Dialplan: sofia/internal/10 at 10.3.0.4 Regex (FAIL) [test1] destination_number(820) =~ /810/ break=on-false
Dialplan: sofia/internal/10 at 10.3.0.4 parsing [default->test3] continue=false
Dialplan: sofia/internal/10 at 10.3.0.4 Regex (PASS) [test3] destination_number(820) =~ /820/ break=on-false
Dialplan: sofia/internal/10 at 10.3.0.4 Action info() 
Dialplan: sofia/internal/10 at 10.3.0.4 Action log(WARNING TEST1 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action sleep(1000) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action log(WARNING TEST2 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action sleep(1000) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action log(WARNING TEST3 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action sleep(1000) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action bridge([leg_timeout=10][origination_caller_id_number=${caller_id_number}]user/20@${domain_name}) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action info() 
Dialplan: sofia/internal/10 at 10.3.0.4 Action log(WARNING TEST4 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action sleep(1000) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action log(WARNING TEST5 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action sleep(1000) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action log(WARNING TEST6 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/10 at 10.3.0.4 Action sleep(1000) 
2012-03-09 18:46:06.934453 [DEBUG] switch_core_state_machine.c:154 (sofia/internal/10 at 10.3.0.4) State Change CS_ROUTING -> CS_EXECUTE
2012-03-09 18:46:06.934453 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:06.934453 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/10 at 10.3.0.4) State ROUTING going to sleep
2012-03-09 18:46:06.934453 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10 at 10.3.0.4) Running State Change CS_EXECUTE
2012-03-09 18:46:06.934453 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10 at 10.3.0.4) State EXECUTE
2012-03-09 18:46:06.934453 [DEBUG] mod_sofia.c:241 sofia/internal/10 at 10.3.0.4 SOFIA EXECUTE
2012-03-09 18:46:06.934453 [DEBUG] switch_core_state_machine.c:192 sofia/internal/10 at 10.3.0.4 Standard EXECUTE
EXECUTE sofia/internal/10 at 10.3.0.4 info()
2012-03-09 18:46:06.934453 [INFO] mod_dptools.c:1439 CHANNEL_DATA:
Channel-State: [CS_EXECUTE]
Channel-Call-State: [RINGING]
Channel-State-Number: [4]
Channel-Name: [sofia/internal/10 at 10.3.0.4]
Unique-ID: [bf969cf6-6a0f-11e1-8e5c-299021af10b6]
Call-Direction: [inbound]
Presence-Call-Direction: [inbound]
Channel-HIT-Dialplan: [true]
Channel-Presence-ID: [10 at 10.3.0.4]
Channel-Call-UUID: [bf969cf6-6a0f-11e1-8e5c-299021af10b6]
Answer-State: [ringing]
Channel-Read-Codec-Name: [G722]
Channel-Read-Codec-Rate: [16000]
Channel-Read-Codec-Bit-Rate: [64000]
Channel-Write-Codec-Name: [G722]
Channel-Write-Codec-Rate: [16000]
Channel-Write-Codec-Bit-Rate: [64000]
Caller-Direction: [inbound]
Caller-Username: [10]
Caller-Dialplan: [XML]
Caller-Caller-ID-Name: [A]
Caller-Caller-ID-Number: [10]
Caller-Network-Addr: [10.3.0.22]
Caller-ANI: [10]
Caller-Destination-Number: [820]
Caller-Unique-ID: [bf969cf6-6a0f-11e1-8e5c-299021af10b6]
Caller-Source: [mod_sofia]
Caller-Context: [default]
Caller-Channel-Name: [sofia/internal/10 at 10.3.0.4]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1331315166913289]
Caller-Channel-Created-Time: [1331315166913289]
Caller-Channel-Answered-Time: [0]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [inbound]
variable_uuid: [bf969cf6-6a0f-11e1-8e5c-299021af10b6]
variable_session_id: [181]
variable_sip_local_network_addr: [10.3.0.4]
variable_sip_network_ip: [10.3.0.22]
variable_sip_network_port: [5060]
variable_sip_received_ip: [10.3.0.22]
variable_sip_received_port: [5060]
variable_sip_via_protocol: [udp]
variable_sip_authorized: [true]
variable_sip_number_alias: [10]
variable_sip_auth_username: [10]
variable_sip_auth_realm: [10.3.0.4]
variable_number_alias: [10]
variable_user_name: [10]
variable_domain_name: [10.3.0.4]
variable_record_stereo: [true]
variable_default_gateway: [fonira]
variable_default_areacode: [01]
variable_transfer_fallback_extension: [operator]
variable_toll_allow: [local,domestic,international,vas]
variable_accountcode: [10]
variable_user_context: [default]
variable_effective_caller_id_name: [A ]
variable_effective_caller_id_number: [10]
variable_outbound_caller_id_name: [A ]
variable_outbound_caller_id_number: [1997156010]
variable_callgroup: [intercept]
variable_sip_from_user: [10]
variable_sip_from_uri: [10 at 10.3.0.4]
variable_sip_from_host: [10.3.0.4]
variable_sip_from_user_stripped: [10]
variable_sip_from_tag: [A59BE1A5-8A2B1314]
variable_sofia_profile_name: [internal]
variable_sip_full_via: [SIP/2.0/UDP 10.3.0.22;branch=z9hG4bK747f362a84831CAD]
variable_sip_from_display: [A]
variable_sip_full_from: ["A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314]
variable_sip_full_to: [<sip:820 at 10.3.0.4;user=phone>]
variable_sip_req_params: [user=phone]
variable_sip_req_user: [820]
variable_sip_req_port: [5060]
variable_sip_req_uri: [820 at 10.3.0.4:5060]
variable_sip_req_host: [10.3.0.4]
variable_sip_to_params: [user=phone]
variable_sip_to_user: [820]
variable_sip_to_uri: [820 at 10.3.0.4]
variable_sip_to_host: [10.3.0.4]
variable_sip_contact_user: [10]
variable_sip_contact_uri: [10 at 10.3.0.22]
variable_sip_contact_host: [10.3.0.22]
variable_channel_name: [sofia/internal/10 at 10.3.0.4]
variable_sip_call_id: [73ec8749-ef90cb48-95fd5843 at 10.3.0.22]
variable_sip_user_agent: [PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933]
variable_sip_via_host: [10.3.0.22]
variable_max_forwards: [70]
variable_presence_id: [10 at 10.3.0.4]
variable_switch_r_sdp: [v=0
o=- 1167610354 1167610354 IN IP4 10.3.0.22
s=Polycom IP Phone
c=IN IP4 10.3.0.22
t=0 0
a=sendrecv
m=audio 2226 RTP/AVP 9 0 8 127
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:127 telephone-event/8000
]
variable_remote_media_ip: [10.3.0.22]
variable_remote_media_port: [2226]
variable_sip_audio_recv_pt: [9]
variable_sip_use_codec_name: [G722]
variable_sip_use_codec_rate: [8000]
variable_sip_use_codec_ptime: [20]
variable_read_codec: [G722]
variable_read_rate: [16000]
variable_write_codec: [G722]
variable_write_rate: [16000]
variable_endpoint_disposition: [RECEIVED]
variable_call_uuid: [bf969cf6-6a0f-11e1-8e5c-299021af10b6]
variable_current_application: [info]

EXECUTE sofia/internal/10 at 10.3.0.4 log(WARNING TEST1 for UUID bf969cf6-6a0f-11e1-8e5c-299021af10b6, src 10, dest 820)
2012-03-09 18:46:06.934453 [WARNING] mod_dptools.c:1420 TEST1 for UUID bf969cf6-6a0f-11e1-8e5c-299021af10b6, src 10, dest 820
EXECUTE sofia/internal/10 at 10.3.0.4 sleep(1000)
EXECUTE sofia/internal/10 at 10.3.0.4 log(WARNING TEST2 for UUID bf969cf6-6a0f-11e1-8e5c-299021af10b6, src 10, dest 820)
2012-03-09 18:46:07.932932 [WARNING] mod_dptools.c:1420 TEST2 for UUID bf969cf6-6a0f-11e1-8e5c-299021af10b6, src 10, dest 820
EXECUTE sofia/internal/10 at 10.3.0.4 sleep(1000)
EXECUTE sofia/internal/10 at 10.3.0.4 log(WARNING TEST3 for UUID bf969cf6-6a0f-11e1-8e5c-299021af10b6, src 10, dest 820)
2012-03-09 18:46:08.913902 [WARNING] mod_dptools.c:1420 TEST3 for UUID bf969cf6-6a0f-11e1-8e5c-299021af10b6, src 10, dest 820
EXECUTE sofia/internal/10 at 10.3.0.4 sleep(1000)
EXECUTE sofia/internal/10 at 10.3.0.4 bridge([leg_timeout=10][origination_caller_id_number=10]user/20 at 10.3.0.4)
2012-03-09 18:46:09.933915 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-03-09 18:46:09.933915 [DEBUG] switch_ivr_originate.c:2299 Parsing session specific variables
2012-03-09 18:46:09.933915 [DEBUG] switch_event.c:1522 Parsing variable [leg_timeout]=[10]
2012-03-09 18:46:09.933915 [DEBUG] switch_event.c:1522 Parsing variable [origination_caller_id_number]=[10]
2012-03-09 18:46:09.933915 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-03-09 18:46:09.933915 [DEBUG] switch_event.c:1522 Parsing variable [presence_id]=[20 at 10.3.0.4]
2012-03-09 18:46:09.933915 [NOTICE] switch_channel.c:926 New Channel sofia/internal/sip:20 at 10.3.0.25 [c1665710-6a0f-11e1-8e64-299021af10b6]
2012-03-09 18:46:09.933915 [DEBUG] mod_sofia.c:4691 (sofia/internal/sip:20 at 10.3.0.25) State Change CS_NEW -> CS_INIT
2012-03-09 18:46:09.933915 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:09.933915 [DEBUG] switch_ivr_originate.c:2561 sofia/internal/sip:20 at 10.3.0.25 Setting leg timeout to 10
2012-03-09 18:46:09.933915 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:20 at 10.3.0.25) Running State Change CS_INIT
2012-03-09 18:46:09.933915 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:20 at 10.3.0.25) State INIT
2012-03-09 18:46:09.933915 [DEBUG] mod_sofia.c:85 sofia/internal/sip:20 at 10.3.0.25 SOFIA INIT
2012-03-09 18:46:09.933915 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:20 at 10.3.0.25) State Change CS_INIT -> CS_ROUTING
2012-03-09 18:46:09.933915 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:09.933915 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:20 at 10.3.0.25) State INIT going to sleep
2012-03-09 18:46:09.933915 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:20 at 10.3.0.25) Running State Change CS_ROUTING
2012-03-09 18:46:09.933915 [DEBUG] switch_channel.c:1886 (sofia/internal/sip:20 at 10.3.0.25) Callstate Change DOWN -> RINGING
send 1255 bytes to udp/[10.3.0.25]:5060 at 17:46:09.964563:
   ------------------------------------------------------------------------
   INVITE sip:20 at 10.3.0.25 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK6rSXB0ZDat57m
   Max-Forwards: 69
   From: "A " <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   To: <sip:20 at 10.3.0.25>
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   CSeq: 25321520 INVITE
   Contact: <sip:mod_sofia at 10.3.0.4:5060>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 369
   X-FS-Support: update_display,send_info
   Remote-Party-ID: "A " <sip:10 at 10.3.0.4>;party=calling;screen=yes;privacy=off

   v=0
   o=FreeSWITCH 1331298751 1331298752 IN IP4 10.3.0.4
   s=FreeSWITCH
   c=IN IP4 10.3.0.4
   t=0 0
   m=audio 16418 RTP/AVP 9 0 8 3 101 13
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   m=video 16404 RTP/AVP 98 99 100 34 31
   a=rtpmap:98 H264/90000
   a=rtpmap:99 H263-2000/90000
   a=rtpmap:100 H263-1998/90000
   a=rtpmap:34 H263/90000
   a=rtpmap:31 H261/90000
   ------------------------------------------------------------------------
2012-03-09 18:46:09.933915 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:20 at 10.3.0.25) State ROUTING
2012-03-09 18:46:09.933915 [DEBUG] mod_sofia.c:148 sofia/internal/sip:20 at 10.3.0.25 SOFIA ROUTING
2012-03-09 18:46:09.933915 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:20 at 10.3.0.25) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2012-03-09 18:46:09.933915 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:09.933915 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:20 at 10.3.0.25) State ROUTING going to sleep
2012-03-09 18:46:09.933915 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:20 at 10.3.0.25) Running State Change CS_CONSUME_MEDIA
2012-03-09 18:46:09.933915 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:20 at 10.3.0.25) State CONSUME_MEDIA
2012-03-09 18:46:09.933915 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:20 at 10.3.0.25) State CONSUME_MEDIA going to sleep
2012-03-09 18:46:09.933915 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:09.933915 [DEBUG] sofia.c:5532 Channel sofia/internal/sip:20 at 10.3.0.25 entering state [calling][0]
recv 405 bytes from udp/[10.3.0.25]:5060 at 17:46:09.975584:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK6rSXB0ZDat57m
   From: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   To: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   CSeq: 25321520 INVITE
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   Contact: <sip:20 at 10.3.0.25>
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Content-Length: 0

   ------------------------------------------------------------------------
recv 442 bytes from udp/[10.3.0.25]:5060 at 17:46:10.037810:
   ------------------------------------------------------------------------
   SIP/2.0 180 Ringing
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK6rSXB0ZDat57m
   From: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   To: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   CSeq: 25321520 INVITE
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   Contact: <sip:20 at 10.3.0.25>
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Allow-Events: talk,hold,conference
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:10.032935 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:10.032935 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:10.032935 [DEBUG] sofia.c:5532 Channel sofia/internal/sip:20 at 10.3.0.25 entering state [proceeding][180]
2012-03-09 18:46:10.032935 [NOTICE] sofia.c:5624 Ring-Ready sofia/internal/sip:20 at 10.3.0.25!
2012-03-09 18:46:10.032935 [NOTICE] mod_sofia.c:2514 Ring-Ready sofia/internal/10 at 10.3.0.4!
send 801 bytes to udp/[10.3.0.22]:5060 at 17:46:10.049093:
   ------------------------------------------------------------------------
   SIP/2.0 180 Ringing
   Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bK747f362a84831CAD
   From: "A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314
   To: <sip:820 at 10.3.0.4;user=phone>;tag=XByp5KaN7H5UN
   Call-ID: 73ec8749-ef90cb48-95fd5843 at 10.3.0.22
   CSeq: 2 INVITE
   Contact: <sip:820 at 10.3.0.4:5060;transport=udp>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Accept: application/sdp
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Content-Length: 0
   Remote-Party-ID: "Outbound Call" <20>;party=calling;privacy=off;screen=no

   ------------------------------------------------------------------------
2012-03-09 18:46:10.032935 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:10.032935 [DEBUG] sofia.c:5532 Channel sofia/internal/10 at 10.3.0.4 entering state [early][180]
2012-03-09 18:46:10.032935 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:10.032935 [NOTICE] switch_ivr_originate.c:483 Ring Ready sofia/internal/10 at 10.3.0.4!
recv 907 bytes from udp/[10.3.0.25]:5060 at 17:46:11.270917:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK6rSXB0ZDat57m
   From: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   To: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   CSeq: 25321520 INVITE
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   Contact: <sip:20 at 10.3.0.25>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   Supported: 100rel,replaces
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Content-Type: application/sdp
   Content-Length: 347

   v=0
   o=- 1167610359 1167610359 IN IP4 10.3.0.25
   s=Polycom IP Phone
   c=IN IP4 10.3.0.25
   t=0 0
   m=audio 2230 RTP/AVP 9 127
   a=rtpmap:9 G722/8000
   a=rtpmap:127 telephone-event/8000
   m=video 0 RTP/AVP 98 99 100 34 31
   a=rtpmap:98 H264/90000
   a=rtpmap:99 H263-2000/90000
   a=rtpmap:100 H263-1998/90000
   a=rtpmap:34 H263/90000
   a=rtpmap:31 H261/90000
   ------------------------------------------------------------------------
2012-03-09 18:46:11.253958 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:11.253958 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:11.253958 [DEBUG] sofia.c:5532 Channel sofia/internal/sip:20 at 10.3.0.25 entering state [completing][200]
2012-03-09 18:46:11.253958 [DEBUG] sofia.c:5543 Remote SDP:
v=0
o=- 1167610359 1167610359 IN IP4 10.3.0.25
s=Polycom IP Phone
c=IN IP4 10.3.0.25
t=0 0
m=audio 2230 RTP/AVP 9 127
a=rtpmap:9 G722/8000
a=rtpmap:127 telephone-event/8000
m=video 0 RTP/AVP 98 99 100 34 31
a=rtpmap:98 H264/90000
a=rtpmap:99 H263-2000/90000
a=rtpmap:100 H263-1998/90000
a=rtpmap:34 H263/90000
a=rtpmap:31 H261/90000

send 336 bytes to udp/[10.3.0.25]:5060 at 17:46:11.282795:
   ------------------------------------------------------------------------
   ACK sip:20 at 10.3.0.25 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK71jpDUgH72Utg
   Max-Forwards: 70
   From: "A " <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   To: <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   CSeq: 25321520 ACK
   Contact: <sip:mod_sofia at 10.3.0.4:5060>
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:11.253958 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:11.253958 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:11.253958 [DEBUG] sofia.c:5532 Channel sofia/internal/sip:20 at 10.3.0.25 entering state [ready][200]
2012-03-09 18:46:11.253958 [DEBUG] sofia_glue.c:4874 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000]
2012-03-09 18:46:11.253958 [DEBUG] sofia_glue.c:2991 Set Codec sofia/internal/sip:20 at 10.3.0.25 G722/8000 20 ms 160 samples 64000 bits
2012-03-09 18:46:11.253958 [DEBUG] switch_core_codec.c:111 sofia/internal/sip:20 at 10.3.0.25 Original read codec set to G722:9
2012-03-09 18:46:11.253958 [DEBUG] sofia_glue.c:4988 Set 2833 dtmf send payload to 127
2012-03-09 18:46:11.253958 [DEBUG] sofia_glue.c:3243 AUDIO RTP [sofia/internal/sip:20 at 10.3.0.25] 10.3.0.4 port 16418 -> 10.3.0.25 port 2230 codec: 9 ms: 20
2012-03-09 18:46:11.253958 [DEBUG] switch_rtp.c:1661 Starting timer [soft] 160 bytes per 20ms
2012-03-09 18:46:11.253958 [DEBUG] sofia_glue.c:3507 Set 2833 dtmf send payload to 127
2012-03-09 18:46:11.253958 [DEBUG] sofia_glue.c:3513 Set 2833 dtmf receive payload to 101
2012-03-09 18:46:11.253958 [DEBUG] switch_channel.c:3190 (sofia/internal/sip:20 at 10.3.0.25) Callstate Change RINGING -> ACTIVE
2012-03-09 18:46:11.253958 [DEBUG] switch_channel.c:3202 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:11.253958 [NOTICE] sofia.c:6246 Channel [sofia/internal/sip:20 at 10.3.0.25] has been answered
2012-03-09 18:46:11.292944 [DEBUG] sofia_glue.c:3243 AUDIO RTP [sofia/internal/10 at 10.3.0.4] 10.3.0.4 port 16424 -> 10.3.0.22 port 2226 codec: 9 ms: 20
2012-03-09 18:46:11.292944 [DEBUG] switch_rtp.c:1661 Starting timer [soft] 160 bytes per 20ms
2012-03-09 18:46:11.292944 [DEBUG] sofia_glue.c:3507 Set 2833 dtmf send payload to 127
2012-03-09 18:46:11.292944 [DEBUG] sofia_glue.c:3513 Set 2833 dtmf receive payload to 127
2012-03-09 18:46:11.292944 [DEBUG] mod_sofia.c:750 Local SDP sofia/internal/10 at 10.3.0.4:
v=0
o=FreeSWITCH 1331298747 1331298748 IN IP4 10.3.0.4
s=FreeSWITCH
c=IN IP4 10.3.0.4
t=0 0
m=audio 16424 RTP/AVP 9 127
a=rtpmap:9 G722/8000
a=rtpmap:127 telephone-event/8000
a=fmtp:127 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2012-03-09 18:46:11.292944 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:11.292944 [DEBUG] switch_channel.c:3190 (sofia/internal/10 at 10.3.0.4) Callstate Change RINGING -> ACTIVE
send 1073 bytes to udp/[10.3.0.22]:5060 at 17:46:11.302824:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bK747f362a84831CAD
   From: "A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314
   To: <sip:820 at 10.3.0.4;user=phone>;tag=XByp5KaN7H5UN
   Call-ID: 73ec8749-ef90cb48-95fd5843 at 10.3.0.22
   CSeq: 2 INVITE
   Contact: <sip:820 at 10.3.0.4:5060;transport=udp>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces2012-03-09 18:46:11.292944 [NOTICE] switch_ivr_originate.c:3209 Channel [sofia/internal/10 at 10.3.0.4] has been answered

   Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 239
   Remote-Party-ID: "Outbound Call" <20>;party=calling;privacy=off;screen=no

   v=0
   o=FreeSWITCH 1331298747 1331298748 IN IP4 10.3.0.4
   s=FreeSWITCH
   c=IN IP4 10.3.0.4
   t=0 0
   m=audio 16424 RTP/AVP 9 127
   a=rtpmap:9 G722/8000
   a=rtpmap:127 telephone-event/8000
   a=fmtp:127 0-16
   a=silenceSupp:off - - - -
   a=ptime:20
   ------------------------------------------------------------------------
2012-03-09 18:46:11.292944 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:11.292944 [DEBUG] sofia.c:5532 Channel sofia/internal/10 at 10.3.0.4 entering state [completed][200]
2012-03-09 18:46:11.292944 [DEBUG] switch_ivr_originate.c:3266 Originate Resulted in Success: [sofia/internal/sip:20 at 10.3.0.25]
2012-03-09 18:46:11.292944 [DEBUG] switch_ivr_originate.c:2561 sofia/internal/sip:20 at 10.3.0.25 Setting leg timeout to 10
2012-03-09 18:46:11.292944 [DEBUG] switch_ivr_originate.c:3266 Originate Resulted in Success: [sofia/internal/sip:20 at 10.3.0.25]
2012-03-09 18:46:11.292944 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:11.292944 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:11.292944 [DEBUG] switch_ivr_bridge.c:1328 (sofia/internal/sip:20 at 10.3.0.25) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2012-03-09 18:46:11.292944 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:11.292944 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:20 at 10.3.0.25) Running State Change CS_EXCHANGE_MEDIA
2012-03-09 18:46:11.292944 [DEBUG] switch_core_state_machine.c:420 (sofia/internal/sip:20 at 10.3.0.25) State EXCHANGE_MEDIA
2012-03-09 18:46:11.292944 [DEBUG] mod_sofia.c:578 SOFIA EXCHANGE_MEDIA
recv 541 bytes from udp/[10.3.0.22]:5060 at 17:46:11.314619:
   ------------------------------------------------------------------------
   ACK sip:820 at 10.3.0.4:5060;transport=udp SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.22;branch=z9hG4bK6e693bfe5C6D05D1
   From: "A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314
   To: <sip:820 at 10.3.0.4;user=phone>;tag=XByp5KaN7H5UN
   CSeq: 2 ACK
   Call-ID: 73ec8749-ef90cb48-95fd5843 at 10.3.0.22
   Contact: <sip:10 at 10.3.0.22>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Max-Forwards: 70
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:11.314245 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:11.314245 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:11.314245 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:11.352934 [DEBUG] sofia.c:5532 Channel sofia/internal/10 at 10.3.0.4 entering state [ready][200]
2012-03-09 18:46:11.352934 [DEBUG] switch_core_session.c:791 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:11.352934 [DEBUG] switch_core_session.c:791 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:11.412951 [DEBUG] switch_rtp.c:3210 Correct ip/port confirmed.
2012-03-09 18:46:11.412951 [DEBUG] switch_rtp.c:3210 Correct ip/port confirmed.
recv 978 bytes from udp/[10.3.0.25]:5060 at 17:46:12.152357:
   ------------------------------------------------------------------------
   INVITE sip:mod_sofia at 10.3.0.4:5060 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bKf57df0b37D8DB26E
   From: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   To: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   CSeq: 1 INVITE
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   Contact: <sip:20 at 10.3.0.25>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Supported: 100rel,replaces
   Allow-Events: talk,hold,conference
   Max-Forwards: 70
   Content-Type: application/sdp
   Content-Length: 345

   v=0
   o=- 1167610359 1167610360 IN IP4 10.3.0.25
   s=Polycom IP Phone
   c=IN IP4 0.0.0.0
   t=0 0
   m=audio 2230 RTP/AVP 9 101
   a=rtpmap:9 G722/8000
   a=rtpmap:101 telephone-event/8000
   m=video 0 RTP/AVP 98 99 100 34 31
   a=rtpmap:98 H264/90000
   a=rtpmap:99 H263-2000/90000
   a=rtpmap:100 H263-1998/90000
   a=rtpmap:34 H263/90000
   a=rtpmap:31 H261/90000
   ------------------------------------------------------------------------
send 350 bytes to udp/[10.3.0.25]:5060 at 17:46:12.153437:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bKf57df0b37D8DB26E
   From: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   To: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   CSeq: 1 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:12.153783 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:12.153783 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:12.155039 [DEBUG] sofia.c:5532 Channel sofia/internal/sip:20 at 10.3.0.25 entering state [received][100]
2012-03-09 18:46:12.155039 [DEBUG] sofia.c:5543 Remote SDP:
v=0
o=- 1167610359 1167610360 IN IP4 10.3.0.25
s=Polycom IP Phone
c=IN IP4 0.0.0.0
t=0 0
m=audio 2230 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=sendonly
m=video 0 RTP/AVP 98 99 100 34 31
a=rtpmap:98 H264/90000
a=rtpmap:99 H263-2000/90000
a=rtpmap:100 H263-1998/90000
a=rtpmap:34 H263/90000
a=rtpmap:31 H261/90000

2012-03-09 18:46:12.155039 [DEBUG] switch_channel.c:1560 (sofia/internal/sip:20 at 10.3.0.25) Callstate Change ACTIVE -> HELD
2012-03-09 18:46:12.155039 [DEBUG] switch_core_session.c:1012 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:12.192940 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:12.273953 [DEBUG] switch_ivr.c:591 sofia/internal/10 at 10.3.0.4 Command Execute playback(local_stream://moh)
EXECUTE sofia/internal/10 at 10.3.0.4 playback(local_stream://moh)
2012-03-09 18:46:12.273953 [DEBUG] mod_local_stream.c:421 Opening Stream [moh/16000] 16000hz
2012-03-09 18:46:12.273953 [DEBUG] switch_ivr_play_say.c:1306 Codec Activated L16 at 16000hz 1 channels 20ms
2012-03-09 18:46:12.393911 [DEBUG] sofia_glue.c:4874 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000]
2012-03-09 18:46:12.393911 [DEBUG] sofia_glue.c:2925 Already using G722
2012-03-09 18:46:12.393911 [DEBUG] sofia_glue.c:4988 Set 2833 dtmf send payload to 101
2012-03-09 18:46:12.393911 [DEBUG] sofia_glue.c:3232 Audio params changed for sofia/internal/sip:20 at 10.3.0.25 from 10.3.0.25:2230 to 0.0.0.0:2230
2012-03-09 18:46:12.393911 [DEBUG] sofia_glue.c:3243 AUDIO RTP [sofia/internal/sip:20 at 10.3.0.25] 10.3.0.4 port 16418 -> 0.0.0.0 port 2230 codec: 9 ms: 20
2012-03-09 18:46:12.393911 [DEBUG] sofia_glue.c:3284 AUDIO RTP CHANGING DEST TO: [0.0.0.0:2230]
2012-03-09 18:46:12.393911 [DEBUG] sofia.c:6042 Processing updated SDP
send 929 bytes to udp/[10.3.0.25]:5060 at 17:46:12.409614:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bKf57df0b37D8DB26E
   From: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   To: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   CSeq: 1 INVITE
   Contact: <sip:mod_sofia at 10.3.0.4:5060>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Accept: application/sdp
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 297

   v=0
   o=FreeSWITCH 1331298751 1331298753 IN IP4 10.3.0.4
   s=FreeSWITCH
   c=IN IP4 10.3.0.4
   t=0 0
   m=audio 16418 RTP/AVP 9 101
   a=rtpmap:9 G722/8000
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=recvonly
   a=silenceSupp:off - - - -
   a=ptime:20
   m=video 0 RTP/AVP 98
   a=rtpmap:98 H264/90000
   ------------------------------------------------------------------------
2012-03-09 18:46:12.393911 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
recv 529 bytes from udp/[10.3.0.25]:5060 at 17:46:12.428189:
   ------------------------------------------------------------------------
   ACK sip:mod_sofia at 10.3.0.4:5060 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK262feca5B7DADFD
   From: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   To: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   CSeq: 1 ACK
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   Contact: <sip:20 at 10.3.0.25>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Max-Forwards: 70
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:12.393911 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:12.393911 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:12.393911 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:12.432936 [DEBUG] sofia.c:5532 Channel sofia/internal/sip:20 at 10.3.0.25 entering state [completed][200]
2012-03-09 18:46:12.432936 [DEBUG] sofia.c:5532 Channel sofia/internal/sip:20 at 10.3.0.25 entering state [ready][200]
recv 862 bytes from udp/[10.3.0.25]:5060 at 17:46:13.885657:
   ------------------------------------------------------------------------
   INVITE sip:830 at 10.3.0.4:5060;user=phone SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bKdf353688FD5B112B
   From: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   To: <sip:830 at 10.3.0.4;user=phone>
   CSeq: 1 INVITE
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   Contact: <sip:20 at 10.3.0.25>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Supported: 100rel,replaces
   Allow-Events: talk,hold,conference
   Max-Forwards: 70
   Content-Type: application/sdp
   Content-Length: 241

   v=0
   o=- 1167610362 1167610362 IN IP4 10.3.0.25
   s=Polycom IP Phone
   c=IN IP4 10.3.0.25
   t=0 0
   a=sendrecv
   m=audio 2232 RTP/AVP 9 0 8 127
   a=rtpmap:9 G722/8000
   a=rtpmap:0 PCMU/8000
   a=rtpmap:8 PCMA/8000
   a=rtpmap:127 telephone-event/8000
   ------------------------------------------------------------------------
send 333 bytes to udp/[10.3.0.25]:5060 at 17:46:13.886560:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bKdf353688FD5B112B
   From: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   To: <sip:830 at 10.3.0.4;user=phone>
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   CSeq: 1 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:13.872937 [DEBUG] sofia.c:7567 IP 10.3.0.25 Rejected by acl "domains". Falling back to Digest auth.
2012-03-09 18:46:13.872937 [WARNING] sofia_reg.c:1422 SIP auth challenge (INVITE) on sofia profile 'internal' for [830 at 10.3.0.4] from ip 10.3.0.25
send 816 bytes to udp/[10.3.0.25]:5060 at 17:46:13.892050:
   ------------------------------------------------------------------------
   SIP/2.0 407 Proxy Authentication Required
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bKdf353688FD5B112B
   From: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   To: <sip:830 at 10.3.0.4;user=phone>;tag=ZXg889Bv13H1c
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   CSeq: 1 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Accept: application/sdp
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Proxy-Authenticate: Digest realm="10.3.0.4", nonce="c3bdc00c-6a0f-11e1-8e6c-299021af10b6", algorithm=MD5, qop="auth"
   Content-Length: 0

   ------------------------------------------------------------------------
recv 536 bytes from udp/[10.3.0.25]:5060 at 17:46:13.903758:
   ------------------------------------------------------------------------
   ACK sip:830 at 10.3.0.4:5060;user=phone SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bKdf353688FD5B112B
   From: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   To: <sip:830 at 10.3.0.4;user=phone>;tag=ZXg889Bv13H1c
   CSeq: 1 ACK
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   Contact: <sip:20 at 10.3.0.25>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Max-Forwards: 70
   Content-Length: 0

   ------------------------------------------------------------------------
recv 1118 bytes from udp/[10.3.0.25]:5060 at 17:46:13.909222:
   ------------------------------------------------------------------------
   INVITE sip:830 at 10.3.0.4:5060;user=phone SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK924971a7A89CEC02
   From: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   To: <sip:830 at 10.3.0.4;user=phone>
   CSeq: 2 INVITE
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   Contact: <sip:20 at 10.3.0.25>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Supported: 100rel,replaces
   Allow-Events: talk,hold,conference
   Proxy-Authorization: Digest username="20", realm="10.3.0.4", nonce="c3bdc00c-6a0f-11e1-8e6c-299021af10b6", qop=auth, cnonce="xa7J+697IQEBbl7", nc=00000001, uri="sip:830 at 10.3.0.4:5060;user=phone", response="c217f9da396e6a6d2e36f677c1d585b6", algorithm=MD5
   Max-Forwards: 70
   Content-Type: application/sdp
   Content-Length: 241

   v=0
   o=- 1167610362 1167610362 IN IP4 10.3.0.25
   s=Polycom IP Phone
   c=IN IP4 10.3.0.25
   t=0 0
   a=sendrecv
   m=audio 2232 RTP/AVP 9 0 8 127
   a=rtpmap:9 G722/8000
   a=rtpmap:0 PCMU/8000
   a=rtpmap:8 PCMA/8000
   a=rtpmap:127 telephone-event/8000
   ------------------------------------------------------------------------
send 333 bytes to udp/[10.3.0.25]:5060 at 17:46:13.910452:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK924971a7A89CEC02
   From: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   To: <sip:830 at 10.3.0.4;user=phone>
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   CSeq: 2 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:13.894125 [DEBUG] sofia.c:7567 IP 10.3.0.25 Rejected by acl "domains". Falling back to Digest auth.
2012-03-09 18:46:13.894125 [NOTICE] switch_channel.c:926 New Channel sofia/internal/20 at 10.3.0.4 [c3c26f12-6a0f-11e1-8e6d-299021af10b6]
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/20 at 10.3.0.4) Running State Change CS_NEW
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:380 (sofia/internal/20 at 10.3.0.4) State NEW
2012-03-09 18:46:13.894125 [DEBUG] sofia.c:5532 Channel sofia/internal/20 at 10.3.0.4 entering state [received][100]
2012-03-09 18:46:13.894125 [DEBUG] sofia.c:5543 Remote SDP:
v=0
o=- 1167610362 1167610362 IN IP4 10.3.0.25
s=Polycom IP Phone
c=IN IP4 10.3.0.25
t=0 0
a=sendrecv
m=audio 2232 RTP/AVP 9 0 8 127
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:127 telephone-event/8000

2012-03-09 18:46:13.894125 [DEBUG] sofia_glue.c:4874 Audio Codec Compare [G722:9:8000:20:64000]/[G722:9:8000:20:64000]
2012-03-09 18:46:13.894125 [DEBUG] sofia_glue.c:2991 Set Codec sofia/internal/20 at 10.3.0.4 G722/8000 20 ms 160 samples 64000 bits
2012-03-09 18:46:13.894125 [DEBUG] switch_core_codec.c:111 sofia/internal/20 at 10.3.0.4 Original read codec set to G722:9
2012-03-09 18:46:13.894125 [DEBUG] sofia_glue.c:4995 Set 2833 dtmf send/recv payload to 127
2012-03-09 18:46:13.894125 [DEBUG] sofia.c:5757 (sofia/internal/20 at 10.3.0.4) State Change CS_NEW -> CS_INIT
2012-03-09 18:46:13.894125 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/20 at 10.3.0.4 [BREAK]
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/20 at 10.3.0.4) Running State Change CS_INIT
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/20 at 10.3.0.4) State INIT
2012-03-09 18:46:13.894125 [DEBUG] mod_sofia.c:85 sofia/internal/20 at 10.3.0.4 SOFIA INIT
2012-03-09 18:46:13.894125 [DEBUG] mod_sofia.c:125 (sofia/internal/20 at 10.3.0.4) State Change CS_INIT -> CS_ROUTING
2012-03-09 18:46:13.894125 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/20 at 10.3.0.4 [BREAK]
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/20 at 10.3.0.4) State INIT going to sleep
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/20 at 10.3.0.4) Running State Change CS_ROUTING
2012-03-09 18:46:13.894125 [DEBUG] switch_channel.c:1886 (sofia/internal/20 at 10.3.0.4) Callstate Change DOWN -> RINGING
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/20 at 10.3.0.4) State ROUTING
2012-03-09 18:46:13.894125 [DEBUG] mod_sofia.c:148 sofia/internal/20 at 10.3.0.4 SOFIA ROUTING
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:104 sofia/internal/20 at 10.3.0.4 Standard ROUTING
2012-03-09 18:46:13.894125 [INFO] mod_dialplan_xml.c:485 Processing B <20>->830 in context default
Dialplan: sofia/internal/20 at 10.3.0.4 parsing [default->test1] continue=false
Dialplan: sofia/internal/20 at 10.3.0.4 Regex (FAIL) [test1] destination_number(830) =~ /810/ break=on-false
Dialplan: sofia/internal/20 at 10.3.0.4 parsing [default->test3] continue=false
Dialplan: sofia/internal/20 at 10.3.0.4 Regex (FAIL) [test3] destination_number(830) =~ /820/ break=on-false
Dialplan: sofia/internal/20 at 10.3.0.4 parsing [default->test2] continue=false
Dialplan: sofia/internal/20 at 10.3.0.4 Regex (PASS) [test2] destination_number(830) =~ /830/ break=on-false
Dialplan: sofia/internal/20 at 10.3.0.4 Action info() 
Dialplan: sofia/internal/20 at 10.3.0.4 Action log(WARNING TEST1 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action sleep(1000) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action log(WARNING TEST2 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action sleep(1000) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action log(WARNING TEST3 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action sleep(1000) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action bridge([leg_timeout=10][origination_caller_id_number=${caller_id_number}]user/30@${domain_name}) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action info() 
Dialplan: sofia/internal/20 at 10.3.0.4 Action log(WARNING TEST4 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action sleep(1000) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action log(WARNING TEST5 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action sleep(1000) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action log(WARNING TEST6 for UUID ${uuid}, src ${caller_id_number}, dest ${destination_number}) 
Dialplan: sofia/internal/20 at 10.3.0.4 Action sleep(1000) 
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:154 (sofia/internal/20 at 10.3.0.4) State Change CS_ROUTING -> CS_EXECUTE
2012-03-09 18:46:13.894125 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/20 at 10.3.0.4 [BREAK]
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/20 at 10.3.0.4) State ROUTING going to sleep
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/20 at 10.3.0.4) Running State Change CS_EXECUTE
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/20 at 10.3.0.4) State EXECUTE
2012-03-09 18:46:13.894125 [DEBUG] mod_sofia.c:241 sofia/internal/20 at 10.3.0.4 SOFIA EXECUTE
2012-03-09 18:46:13.894125 [DEBUG] switch_core_state_machine.c:192 sofia/internal/20 at 10.3.0.4 Standard EXECUTE
EXECUTE sofia/internal/20 at 10.3.0.4 info()
2012-03-09 18:46:13.933936 [INFO] mod_dptools.c:1439 CHANNEL_DATA:
Channel-State: [CS_EXECUTE]
Channel-Call-State: [RINGING]
Channel-State-Number: [4]
Channel-Name: [sofia/internal/20 at 10.3.0.4]
Unique-ID: [c3c26f12-6a0f-11e1-8e6d-299021af10b6]
Call-Direction: [inbound]
Presence-Call-Direction: [inbound]
Channel-HIT-Dialplan: [true]
Channel-Presence-ID: [20 at 10.3.0.4]
Channel-Call-UUID: [c3c26f12-6a0f-11e1-8e6d-299021af10b6]
Answer-State: [ringing]
Channel-Read-Codec-Name: [G722]
Channel-Read-Codec-Rate: [16000]
Channel-Read-Codec-Bit-Rate: [64000]
Channel-Write-Codec-Name: [G722]
Channel-Write-Codec-Rate: [16000]
Channel-Write-Codec-Bit-Rate: [64000]
Caller-Direction: [inbound]
Caller-Username: [20]
Caller-Dialplan: [XML]
Caller-Caller-ID-Name: [B]
Caller-Caller-ID-Number: [20]
Caller-Network-Addr: [10.3.0.25]
Caller-ANI: [20]
Caller-Destination-Number: [830]
Caller-Unique-ID: [c3c26f12-6a0f-11e1-8e6d-299021af10b6]
Caller-Source: [mod_sofia]
Caller-Context: [default]
Caller-Channel-Name: [sofia/internal/20 at 10.3.0.4]
Caller-Profile-Index: [1]
Caller-Profile-Created-Time: [1331315173894125]
Caller-Channel-Created-Time: [1331315173894125]
Caller-Channel-Answered-Time: [0]
Caller-Channel-Progress-Time: [0]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_direction: [inbound]
variable_uuid: [c3c26f12-6a0f-11e1-8e6d-299021af10b6]
variable_session_id: [183]
variable_sip_local_network_addr: [10.3.0.4]
variable_sip_network_ip: [10.3.0.25]
variable_sip_network_port: [5060]
variable_sip_received_ip: [10.3.0.25]
variable_sip_received_port: [5060]
variable_sip_via_protocol: [udp]
variable_sip_authorized: [true]
variable_sip_number_alias: [20]
variable_sip_auth_username: [20]
variable_sip_auth_realm: [10.3.0.4]
variable_number_alias: [20]
variable_user_name: [20]
variable_domain_name: [10.3.0.4]
variable_record_stereo: [true]
variable_default_gateway: [fonira]
variable_default_areacode: [01]
variable_transfer_fallback_extension: [operator]
variable_toll_allow: [local,domestic,international,vas]
variable_accountcode: [20]
variable_user_context: [default]
variable_effective_caller_id_name: [B ]
variable_effective_caller_id_number: [20]
variable_outbound_caller_id_name: [B ]
variable_outbound_caller_id_number: [1997156020]
variable_callgroup: [intercept]
variable_sip_from_user: [20]
variable_sip_from_uri: [20 at 10.3.0.4]
variable_sip_from_host: [10.3.0.4]
variable_sip_from_user_stripped: [20]
variable_sip_from_tag: [FAB3376C-15AEB62F]
variable_sofia_profile_name: [internal]
variable_sip_full_via: [SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK924971a7A89CEC02]
variable_sip_from_display: [B]
variable_sip_full_from: ["B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F]
variable_sip_full_to: [<sip:830 at 10.3.0.4;user=phone>]
variable_sip_req_params: [user=phone]
variable_sip_req_user: [830]
variable_sip_req_port: [5060]
variable_sip_req_uri: [830 at 10.3.0.4:5060]
variable_sip_req_host: [10.3.0.4]
variable_sip_to_params: [user=phone]
variable_sip_to_user: [830]
variable_sip_to_uri: [830 at 10.3.0.4]
variable_sip_to_host: [10.3.0.4]
variable_sip_contact_user: [20]
variable_sip_contact_uri: [20 at 10.3.0.25]
variable_sip_contact_host: [10.3.0.25]
variable_channel_name: [sofia/internal/20 at 10.3.0.4]
variable_sip_call_id: [12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25]
variable_sip_user_agent: [PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933]
variable_sip_via_host: [10.3.0.25]
variable_max_forwards: [70]
variable_presence_id: [20 at 10.3.0.4]
variable_switch_r_sdp: [v=0
o=- 1167610362 1167610362 IN IP4 10.3.0.25
s=Polycom IP Phone
c=IN IP4 10.3.0.25
t=0 0
a=sendrecv
m=audio 2232 RTP/AVP 9 0 8 127
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:127 telephone-event/8000
]
variable_remote_media_ip: [10.3.0.25]
variable_remote_media_port: [2232]
variable_sip_audio_recv_pt: [9]
variable_sip_use_codec_name: [G722]
variable_sip_use_codec_rate: [8000]
variable_sip_use_codec_ptime: [20]
variable_read_codec: [G722]
variable_read_rate: [16000]
variable_write_codec: [G722]
variable_write_rate: [16000]
variable_endpoint_disposition: [RECEIVED]
variable_call_uuid: [c3c26f12-6a0f-11e1-8e6d-299021af10b6]
variable_current_application: [info]

EXECUTE sofia/internal/20 at 10.3.0.4 log(WARNING TEST1 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 20, dest 830)
2012-03-09 18:46:13.933936 [WARNING] mod_dptools.c:1420 TEST1 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 20, dest 830
EXECUTE sofia/internal/20 at 10.3.0.4 sleep(1000)
EXECUTE sofia/internal/20 at 10.3.0.4 log(WARNING TEST2 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 20, dest 830)
2012-03-09 18:46:14.913910 [WARNING] mod_dptools.c:1420 TEST2 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 20, dest 830
EXECUTE sofia/internal/20 at 10.3.0.4 sleep(1000)
EXECUTE sofia/internal/20 at 10.3.0.4 log(WARNING TEST3 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 20, dest 830)
2012-03-09 18:46:15.933910 [WARNING] mod_dptools.c:1420 TEST3 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 20, dest 830
EXECUTE sofia/internal/20 at 10.3.0.4 sleep(1000)
EXECUTE sofia/internal/20 at 10.3.0.4 bridge([leg_timeout=10][origination_caller_id_number=20]user/30 at 10.3.0.4)
2012-03-09 18:46:16.932926 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-03-09 18:46:16.932926 [DEBUG] switch_ivr_originate.c:2299 Parsing session specific variables
2012-03-09 18:46:16.932926 [DEBUG] switch_event.c:1522 Parsing variable [leg_timeout]=[10]
2012-03-09 18:46:16.932926 [DEBUG] switch_event.c:1522 Parsing variable [origination_caller_id_number]=[20]
2012-03-09 18:46:16.954363 [DEBUG] switch_ivr_originate.c:1884 Parsing global variables
2012-03-09 18:46:16.954363 [DEBUG] switch_event.c:1522 Parsing variable [presence_id]=[30 at 10.3.0.4]
2012-03-09 18:46:16.954363 [NOTICE] switch_channel.c:926 New Channel sofia/internal/sip:30 at 10.3.0.26 [c5926360-6a0f-11e1-8e75-299021af10b6]
2012-03-09 18:46:16.954363 [DEBUG] mod_sofia.c:4691 (sofia/internal/sip:30 at 10.3.0.26) State Change CS_NEW -> CS_INIT
2012-03-09 18:46:16.954363 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30 at 10.3.0.26 [BREAK]
2012-03-09 18:46:16.954363 [DEBUG] switch_ivr_originate.c:2561 sofia/internal/sip:30 at 10.3.0.26 Setting leg timeout to 10
2012-03-09 18:46:16.954363 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:30 at 10.3.0.26) Running State Change CS_INIT
2012-03-09 18:46:16.954363 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:30 at 10.3.0.26) State INIT
2012-03-09 18:46:16.954363 [DEBUG] mod_sofia.c:85 sofia/internal/sip:30 at 10.3.0.26 SOFIA INIT
2012-03-09 18:46:16.954363 [DEBUG] mod_sofia.c:125 (sofia/internal/sip:30 at 10.3.0.26) State Change CS_INIT -> CS_ROUTING
2012-03-09 18:46:16.954363 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30 at 10.3.0.26 [BREAK]
2012-03-09 18:46:16.954363 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/sip:30 at 10.3.0.26) State INIT going to sleep
2012-03-09 18:46:16.954363 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:30 at 10.3.0.26) Running State Change CS_ROUTING
2012-03-09 18:46:16.954363 [DEBUG] switch_channel.c:1886 (sofia/internal/sip:30 at 10.3.0.26) Callstate Change DOWN -> RINGING
send 1253 bytes to udp/[10.3.0.26]:5060 at 17:46:16.964763:
   ------------------------------------------------------------------------
   INVITE sip:30 at 10.3.0.26 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8acFFp1m4BjDc
   Max-Forwards: 69
   From: "B " <sip:20 at 10.3.0.4>;tag=1F3Sc0D3UNy6K
   To: <sip:30 at 10.3.0.26>
   Call-ID: 9cf1865a-e4b2-122f-cd91-00900b1be504
   CSeq: 25321524 INVITE
   Contact: <sip:mod_sofia at 10.3.0.4:5060>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 369
   X-FS-Support: update_display,send_info
   Remote-Party-ID: "B " <sip:20 at 10.3.0.4>;party=calling;screen=yes;privacy=off

   v=0
   o=FreeSWITCH 1331298730 1331298731 IN IP4 10.3.0.4
   s=FreeSWITCH
   c=IN IP4 10.3.0.4
   t=0 0
   m=audio 16446 RTP/AVP 9 0 8 3 101 13
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   m=video 16438 RTP/AVP 98 99 100 34 31
   a=rtpmap:98 H264/90000
   a=rtpmap:99 H263-2000/90000
   a=rtpmap:100 H263-1998/90000
   a=rtpmap:34 H263/90000
   a=rtpmap:31 H261/90000
   ------------------------------------------------------------------------
2012-03-09 18:46:16.954363 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:30 at 10.3.0.26) State ROUTING
2012-03-09 18:46:16.954363 [DEBUG] mod_sofia.c:148 sofia/internal/sip:30 at 10.3.0.26 SOFIA ROUTING
2012-03-09 18:46:16.954363 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:30 at 10.3.0.26) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2012-03-09 18:46:16.954363 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30 at 10.3.0.26 [BREAK]
2012-03-09 18:46:16.954363 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/sip:30 at 10.3.0.26) State ROUTING going to sleep
2012-03-09 18:46:16.954363 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:30 at 10.3.0.26) Running State Change CS_CONSUME_MEDIA
2012-03-09 18:46:16.954363 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:30 at 10.3.0.26) State CONSUME_MEDIA
2012-03-09 18:46:16.954363 [DEBUG] switch_core_state_machine.c:429 (sofia/internal/sip:30 at 10.3.0.26) State CONSUME_MEDIA going to sleep
2012-03-09 18:46:16.954363 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30 at 10.3.0.26 [BREAK]
2012-03-09 18:46:16.954363 [DEBUG] sofia.c:5532 Channel sofia/internal/sip:30 at 10.3.0.26 entering state [calling][0]
recv 411 bytes from udp/[10.3.0.26]:5060 at 17:46:16.976025:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8acFFp1m4BjDc
   From: "B" <sip:20 at 10.3.0.4>;tag=1F3Sc0D3UNy6K
   To: "C" <sip:30 at 10.3.0.26>;tag=93CE8DA-22B4DC39
   CSeq: 25321524 INVITE
   Call-ID: 9cf1865a-e4b2-122f-cd91-00900b1be504
   Contact: <sip:30 at 10.3.0.26>
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Content-Length: 0

   ------------------------------------------------------------------------
recv 448 bytes from udp/[10.3.0.26]:5060 at 17:46:17.023373:
   ------------------------------------------------------------------------
   SIP/2.0 180 Ringing
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8acFFp1m4BjDc
   From: "B" <sip:20 at 10.3.0.4>;tag=1F3Sc0D3UNy6K
   To: "C" <sip:30 at 10.3.0.26>;tag=93CE8DA-22B4DC39
   CSeq: 25321524 INVITE
   Call-ID: 9cf1865a-e4b2-122f-cd91-00900b1be504
   Contact: <sip:30 at 10.3.0.26>
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Allow-Events: talk,hold,conference
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:17.014010 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30 at 10.3.0.26 [BREAK]
2012-03-09 18:46:17.014010 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:30 at 10.3.0.26 [BREAK]
2012-03-09 18:46:17.014010 [DEBUG] sofia.c:5532 Channel sofia/internal/sip:30 at 10.3.0.26 entering state [proceeding][180]
2012-03-09 18:46:17.014010 [NOTICE] sofia.c:5624 Ring-Ready sofia/internal/sip:30 at 10.3.0.26!
2012-03-09 18:46:17.014010 [NOTICE] mod_sofia.c:2514 Ring-Ready sofia/internal/20 at 10.3.0.4!
send 799 bytes to udp/[10.3.0.25]:5060 at 17:46:17.034554:
   ------------------------------------------------------------------------
   SIP/2.0 180 Ringing
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK924971a7A89CEC02
   From: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   To: <sip:830 at 10.3.0.4;user=phone>;tag=0690a5vZyc8Kr
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   CSeq: 2 INVITE
   Contact: <sip:830 at 10.3.0.4:5060;transport=udp>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Accept: application/sdp
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Content-Length: 0
   Remote-Party-ID: "Outbound Call" <30>;party=calling;privacy=off;screen=no

   ------------------------------------------------------------------------
2012-03-09 18:46:17.014010 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/20 at 10.3.0.4 [BREAK]
2012-03-09 18:46:17.014010 [DEBUG] sofia.c:5532 Channel sofia/internal/20 at 10.3.0.4 entering state [early][180]
2012-03-09 18:46:17.014010 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/20 at 10.3.0.4 [BREAK]
2012-03-09 18:46:17.014010 [NOTICE] switch_ivr_originate.c:483 Ring Ready sofia/internal/20 at 10.3.0.4!
recv 617 bytes from udp/[10.3.0.25]:5060 at 17:46:17.752817:
   ------------------------------------------------------------------------
   REFER sip:mod_sofia at 10.3.0.4:5060 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK91e647a3A2636CDE
   From: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   To: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   CSeq: 2 REFER
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   Contact: <sip:20 at 10.3.0.25>
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Refer-To: <sip:830 at 10.3.0.4:5060;user=phone?Replaces=12bb6ca6-d165db9-ac5e8f24%4010.3.0.25%3Bto-tag%3D0690a5vZyc8Kr%3Bfrom-tag%3DFAB3376C-15AEB62F>
   Referred-By: <sip:20 at 10.3.0.4>
   Max-Forwards: 70
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:17.733940 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:17.772935 [DEBUG] sofia.c:6522 Process REFER to [830 at 10.3.0.4]
2012-03-09 18:46:17.772935 [DEBUG] sofia.c:6540 Replaces: [12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25]
send 703 bytes to udp/[10.3.0.25]:5060 at 17:46:17.773525:
   ------------------------------------------------------------------------
   SIP/2.0 202 Accepted
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK91e647a3A2636CDE
   From: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   To: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   CSeq: 2 REFER
   Contact: <sip:mod_sofia at 10.3.0.4:5060>
   Expires: 60
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:17.772935 [NOTICE] sofia.c:6623 Attended Transfer on originating session c3c26f12-6a0f-11e1-8e6d-299021af10b6
2012-03-09 18:46:17.772935 [DEBUG] switch_ivr.c:1711 (sofia/internal/10 at 10.3.0.4) State Change CS_EXECUTE -> CS_ROUTING
2012-03-09 18:46:17.772935 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:17.772935 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:17.772935 [NOTICE] switch_ivr.c:1717 Transfer sofia/internal/10 at 10.3.0.4 to inline[endless_playback:local_stream://moh,park@default]
send 851 bytes to udp/[10.3.0.25]:5060 at 17:46:17.775981:
   ------------------------------------------------------------------------
   NOTIFY sip:20 at 10.3.0.25 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK9K57gHjr1m8ZQ
   Max-Forwards: 70
   From: "A " <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   To: <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   CSeq: 25321521 NOTIFY
   Contact: <sip:mod_sofia at 10.3.0.4:5060>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Event: refer;id=2
   Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Subscription-State: terminated;reason=noresource
   Content-Type: message/sipfrag;version=2.0
   Content-Length: 16

   SIP/2.0 200 OK
   ------------------------------------------------------------------------
send 638 bytes to udp/[10.3.0.25]:5060 at 17:46:17.776716:
   ------------------------------------------------------------------------
   BYE sip:20 at 10.3.0.25 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKaXy0jc3UyXyjK
   Max-Forwards: 70
   From: <sip:830 at 10.3.0.4;user=phone>;tag=0690a5vZyc8Kr
   To: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   CSeq: 25321524 BYE
   Contact: <sip:830 at 10.3.0.4:5060;transport=udp>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Reason: Q.850;cause=16;text="normal_clearing"
   Content-Length: 0

   ------------------------------------------------------------------------
send 653 bytes to udp/[10.3.0.25]:5060 at 17:46:17.777176:
   ------------------------------------------------------------------------
   SIP/2.0 486 Busy Here
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK924971a7A89CEC02
   From: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   To: <sip:830 at 10.3.0.4;user=phone>;tag=0690a5vZyc8Kr
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   CSeq: 2 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Allow-Events: talk, hold, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
   Content-Length: 0

   ------------------------------------------------------------------------
recv 420 bytes from udp/[10.3.0.25]:5060 at 17:46:17.788488:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK9K57gHjr1m8ZQ
   From: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   To: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   CSeq: 25321521 NOTIFY
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   Contact: <sip:20 at 10.3.0.25>
   Event: refer;id=2
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:17.772935 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
recv 432 bytes from udp/[10.3.0.25]:5060 at 17:46:17.793916:
   ------------------------------------------------------------------------
   BYE sip:mod_sofia at 10.3.0.4:5060 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK6975a5b1C0C10CDC
   From: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   To: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   CSeq: 3 BYE
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   Contact: <sip:20 at 10.3.0.25>
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Max-Forwards: 70
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_ivr_play_say.c:1678 done playing file local_stream://moh
2012-03-09 18:46:17.794057 [DEBUG] switch_ivr_bridge.c:586 BRIDGE THREAD DONE [sofia/internal/sip:20 at 10.3.0.25]
2012-03-09 18:46:17.794057 [DEBUG] switch_ivr_bridge.c:611 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_channel.c:2848 (sofia/internal/sip:20 at 10.3.0.25) Callstate Change HELD -> HANGUP
2012-03-09 18:46:17.794057 [NOTICE] switch_ivr_bridge.c:669 Hangup sofia/internal/sip:20 at 10.3.0.25 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2012-03-09 18:46:17.794057 [DEBUG] switch_channel.c:2871 Send signal sofia/internal/sip:20 at 10.3.0.25 [KILL]
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:420 (sofia/internal/sip:20 at 10.3.0.25) State EXCHANGE_MEDIA going to sleep
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:20 at 10.3.0.25) Running State Change CS_HANGUP
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_ivr_bridge.c:329 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_ivr_bridge.c:499 sofia/internal/sip:20 at 10.3.0.25 ending bridge by request from write function
2012-03-09 18:46:17.794057 [DEBUG] switch_ivr_bridge.c:586 BRIDGE THREAD DONE [sofia/internal/10 at 10.3.0.4]
2012-03-09 18:46:17.794057 [DEBUG] switch_ivr_bridge.c:611 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:20 at 10.3.0.25) State HANGUP
2012-03-09 18:46:17.794057 [DEBUG] mod_sofia.c:469 Channel sofia/internal/sip:20 at 10.3.0.25 hanging up, cause: NORMAL_CLEARING
2012-03-09 18:46:17.794057 [DEBUG] switch_ivr_bridge.c:1403 sofia/internal/sip:20 at 10.3.0.25 skip receive message [UNBRIDGE] (channel is hungup already)
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:729 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10 at 10.3.0.4) State EXECUTE going to sleep
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10 at 10.3.0.4) Running State Change CS_ROUTING
recv 738 bytes from udp/[10.3.0.25]:5060 at 17:46:17.800685:
   ------------------------------------------------------------------------
   CANCEL sip:830 at 10.3.0.4:5060;user=phone SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK924971a7A89CEC02
   From: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   To: <sip:830 at 10.3.0.4;user=phone>
   CSeq: 2 CANCEL
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   Contact: <sip:20 at 10.3.0.25>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Proxy-Authorization: Digest username="20", realm="10.3.0.4", nonce="c3bdc00c-6a0f-11e1-8e6c-299021af10b6", qop=auth, cnonce="xa7J+697IQEBbl7", nc=00000002, uri="sip:830 at 10.3.0.4:5060;user=phone", response="6c89aa15f8428bb6f6daa6df020c448f", algorithm=MD5
   Max-Forwards: 70
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:17.794057 [DEBUG] switch_channel.c:1886 (sofia/internal/10 at 10.3.0.4) Callstate Change ACTIVE -> RINGING
send 266 bytes to udp/[10.3.0.25]:5060 at 17:46:17.801231:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK924971a7A89CEC02
   From: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   To: <sip:830 at 10.3.0.4;user=phone>;tag=0690a5vZyc8Kr
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   CSeq: 2 CANCEL
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/10 at 10.3.0.4) State ROUTING
2012-03-09 18:46:17.794057 [DEBUG] mod_sofia.c:148 sofia/internal/10 at 10.3.0.4 SOFIA ROUTING
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:104 sofia/internal/10 at 10.3.0.4 Standard ROUTING
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:154 (sofia/internal/10 at 10.3.0.4) State Change CS_ROUTING -> CS_EXECUTE
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/10 at 10.3.0.4) State ROUTING going to sleep
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10 at 10.3.0.4) Running State Change CS_EXECUTE
2012-03-09 18:46:17.794057 [DEBUG] switch_channel.c:1888 (sofia/internal/10 at 10.3.0.4) Callstate Change RINGING -> ACTIVE
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10 at 10.3.0.4) State EXECUTE
2012-03-09 18:46:17.794057 [DEBUG] mod_sofia.c:241 sofia/internal/10 at 10.3.0.4 SOFIA EXECUTE
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:192 sofia/internal/10 at 10.3.0.4 Standard EXECUTE
EXECUTE sofia/internal/10 at 10.3.0.4 endless_playback(local_stream://moh)
2012-03-09 18:46:17.794057 [DEBUG] mod_local_stream.c:421 Opening Stream [moh/16000] 16000hz
2012-03-09 18:46:17.794057 [DEBUG] switch_ivr_play_say.c:1306 Codec Activated L16 at 16000hz 1 channels 20ms
2012-03-09 18:46:17.794057 [DEBUG] mod_sofia.c:513 Sending BYE to sofia/internal/sip:20 at 10.3.0.25
send 622 bytes to udp/[10.3.0.25]:5060 at 17:46:17.808816:
   ------------------------------------------------------------------------
   BYE sip:20 at 10.3.0.25 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKB6QSm7KZU6m5e
   Max-Forwards: 70
   From: "A " <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   To: <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   CSeq: 25321522 BYE
   Contact: <sip:mod_sofia at 10.3.0.4:5060>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Reason: Q.850;cause=16;text="NORMAL_CLEARING"
   Content-Length: 0

2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:47 sofia/internal/sip:20 at 10.3.0.25 Standard HANGUP, cause: NORMAL_CLEARING
   ------------------------------------------------------------------------
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:20 at 10.3.0.25) State HANGUP going to sleep
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:393 (sofia/internal/sip:20 at 10.3.0.25) State Change CS_HANGUP -> CS_REPORTING
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:20 at 10.3.0.25) Running State Change CS_REPORTING
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:20 at 10.3.0.25) State REPORTING
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:79 sofia/internal/sip:20 at 10.3.0.25 Standard REPORTING, cause: NORMAL_CLEARING
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:20 at 10.3.0.25) State REPORTING going to sleep
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:387 (sofia/internal/sip:20 at 10.3.0.25) State Change CS_REPORTING -> CS_DESTROY
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:20 at 10.3.0.25 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:1380 Session 182 (sofia/internal/sip:20 at 10.3.0.25) Locked, Waiting on external entities
2012-03-09 18:46:17.794057 [NOTICE] switch_core_session.c:1398 Session 182 (sofia/internal/sip:20 at 10.3.0.25) Ended
2012-03-09 18:46:17.794057 [NOTICE] switch_core_session.c:1400 Close Channel sofia/internal/sip:20 at 10.3.0.25 [CS_DESTROY]
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/sip:20 at 10.3.0.25) Callstate Change HANGUP -> DOWN
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:494 (sofia/internal/sip:20 at 10.3.0.25) Running State Change CS_DESTROY
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:20 at 10.3.0.25) State DESTROY
2012-03-09 18:46:17.794057 [DEBUG] mod_sofia.c:374 sofia/internal/sip:20 at 10.3.0.25 SOFIA DESTROY
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:86 sofia/internal/sip:20 at 10.3.0.25 Standard DESTROY
2012-03-09 18:46:17.794057 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:20 at 10.3.0.25) State DESTROY going to sleep
recv 403 bytes from udp/[10.3.0.25]:5060 at 17:46:17.828484:
   ------------------------------------------------------------------------
   SIP/2.0 481 Call Leg/Transaction Does Not Exist
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKaXy0jc3UyXyjK
   From: <sip:830 at 10.3.0.4;user=phone>;tag=0690a5vZyc8Kr
   To: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   CSeq: 25321524 BYE
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/20 at 10.3.0.4 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/20 at 10.3.0.4 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:875 Send signal sofia/internal/20 at 10.3.0.4 [BREAK]
2012-03-09 18:46:17.794057 [DEBUG] sofia.c:5532 Channel sofia/internal/20 at 10.3.0.4 entering state [terminated][481]
2012-03-09 18:46:17.794057 [DEBUG] switch_channel.c:2848 (sofia/internal/20 at 10.3.0.4) Callstate Change RINGING -> HANGUP
2012-03-09 18:46:17.794057 [NOTICE] sofia.c:6301 Hangup sofia/internal/20 at 10.3.0.4 [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
2012-03-09 18:46:17.794057 [DEBUG] switch_channel.c:2871 Send signal sofia/internal/20 at 10.3.0.4 [KILL]
2012-03-09 18:46:17.794057 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/20 at 10.3.0.4 [BREAK]
recv 536 bytes from udp/[10.3.0.25]:5060 at 17:46:17.833953:
   ------------------------------------------------------------------------
   ACK sip:830 at 10.3.0.4:5060;user=phone SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK924971a7A89CEC02
   From: "B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F
   To: <sip:830 at 10.3.0.4;user=phone>;tag=0690a5vZyc8Kr
   CSeq: 2 ACK
   Call-ID: 12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25
   Contact: <sip:20 at 10.3.0.25>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Max-Forwards: 70
   Content-Length: 0

   ------------------------------------------------------------------------
recv 394 bytes from udp/[10.3.0.25]:5060 at 17:46:17.850039:
   ------------------------------------------------------------------------
   SIP/2.0 481 Call Leg/Transaction Does Not Exist
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKB6QSm7KZU6m5e
   From: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   To: <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   CSeq: 25321522 BYE
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Content-Length: 0

   ------------------------------------------------------------------------
send 262 bytes to udp/[10.3.0.25]:5060 at 17:46:17.852789:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   Via: SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK6975a5b1C0C10CDC
   From: "B" <sip:20 at 10.3.0.25>;tag=C3930705-7AD5A1D0
   To: "A" <sip:10 at 10.3.0.4>;tag=ymQF7eUr4tUeH
   Call-ID: 98c5604c-e4b2-122f-cd91-00900b1be504
   CSeq: 3 BYE
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:26.014188 [DEBUG] switch_channel.c:2598 (sofia/internal/10 at 10.3.0.4) State Change CS_EXECUTE -> CS_RESET
2012-03-09 18:46:26.014188 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:26.052925 [DEBUG] switch_ivr_play_say.c:1678 done playing file local_stream://moh
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10 at 10.3.0.4) State EXECUTE going to sleep
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10 at 10.3.0.4) Running State Change CS_RESET
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:413 (sofia/internal/10 at 10.3.0.4) State RESET
2012-03-09 18:46:26.052925 [DEBUG] mod_sofia.c:166 sofia/internal/10 at 10.3.0.4 SOFIA RESET
2012-03-09 18:46:26.052925 [DEBUG] switch_channel.c:2600 (sofia/internal/10 at 10.3.0.4) State Change CS_RESET -> CS_EXECUTE
2012-03-09 18:46:26.052925 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:26.052925 [DEBUG] switch_channel.c:2848 (sofia/internal/sip:30 at 10.3.0.26) Callstate Change RINGING -> HANGUP
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:413 (sofia/internal/10 at 10.3.0.4) State RESET going to sleep
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10 at 10.3.0.4) Running State Change CS_EXECUTE
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10 at 10.3.0.4) State EXECUTE
2012-03-09 18:46:26.052925 [DEBUG] mod_sofia.c:241 sofia/internal/10 at 10.3.0.4 SOFIA EXECUTE
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:192 sofia/internal/10 at 10.3.0.4 Standard EXECUTE
EXECUTE sofia/internal/10 at 10.3.0.4 info()
2012-03-09 18:46:26.052925 [NOTICE] switch_ivr_originate.c:3075 Hangup sofia/internal/sip:30 at 10.3.0.26 [CS_CONSUME_MEDIA] [ATTENDED_TRANSFER]
2012-03-09 18:46:26.052925 [DEBUG] switch_channel.c:2871 Send signal sofia/internal/sip:30 at 10.3.0.26 [KILL]
2012-03-09 18:46:26.052925 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30 at 10.3.0.26 [BREAK]
2012-03-09 18:46:26.052925 [NOTICE] switch_ivr_originate.c:2459 Cannot create outgoing channel of type [user] cause: [ATTENDED_TRANSFER]
2012-03-09 18:46:26.052925 [DEBUG] switch_ivr_originate.c:3364 Originate Resulted in Error Cause: 601 [ATTENDED_TRANSFER]
2012-03-09 18:46:26.052925 [INFO] mod_dptools.c:2922 Originate Failed.  Cause: ATTENDED_TRANSFER
2012-03-09 18:46:26.052925 [DEBUG] switch_core_session.c:2285 sofia/internal/20 at 10.3.0.4 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/20 at 10.3.0.4) State EXECUTE going to sleep
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/20 at 10.3.0.4) Running State Change CS_HANGUP
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/20 at 10.3.0.4) State HANGUP
2012-03-09 18:46:26.052925 [DEBUG] mod_sofia.c:469 Channel sofia/internal/20 at 10.3.0.4 hanging up, cause: NORMAL_TEMPORARY_FAILURE
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:30 at 10.3.0.26) Running State Change CS_HANGUP
2012-03-09 18:46:26.052925 [INFO] mod_dptools.c:1439 CHANNEL_DATA:
Channel-State: [CS_EXECUTE]
Channel-Call-State: [ACTIVE]
Channel-State-Number: [4]
Channel-Name: [sofia/internal/10 at 10.3.0.4]
Unique-ID: [bf969cf6-6a0f-11e1-8e5c-299021af10b6]
Call-Direction: [inbound]
Presence-Call-Direction: [inbound]
Channel-HIT-Dialplan: [true]
Channel-Presence-ID: [20 at 10.3.0.4]
Channel-Call-UUID: [bf969cf6-6a0f-11e1-8e5c-299021af10b6]
Answer-State: [answered]
Channel-Read-Codec-Name: [G722]
Channel-Read-Codec-Rate: [16000]
Channel-Read-Codec-Bit-Rate: [64000]
Channel-Write-Codec-Name: [G722]
Channel-Write-Codec-Rate: [16000]
Channel-Write-Codec-Bit-Rate: [64000]
Caller-Direction: [inbound]
Caller-Username: [10]
Caller-Dialplan: [inline]
Caller-Caller-ID-Name: [A]
Caller-Caller-ID-Number: [10]
Caller-Callee-ID-Name: [Outbound Call]
Caller-Callee-ID-Number: [20]
Caller-Network-Addr: [10.3.0.22]
Caller-ANI: [10]
Caller-Destination-Number: [830]
Caller-Unique-ID: [bf969cf6-6a0f-11e1-8e5c-299021af10b6]
Caller-Source: [mod_sofia]
Caller-Context: [default]
Caller-Channel-Name: [sofia/internal/10 at 10.3.0.4]
Caller-Profile-Index: [3]
Caller-Profile-Created-Time: [1331315186012931]
Caller-Channel-Created-Time: [1331315166913289]
Caller-Channel-Answered-Time: [1331315171292944]
Caller-Channel-Progress-Time: [1331315170032935]
Caller-Channel-Progress-Media-Time: [0]
Caller-Channel-Hangup-Time: [0]
Caller-Channel-Transfer-Time: [0]
Caller-Screen-Bit: [true]
Caller-Privacy-Hide-Name: [false]
Caller-Privacy-Hide-Number: [false]
variable_sip_local_sdp_str: [v=0
o=FreeSWITCH 1331298747 1331298748 IN IP4 10.3.0.4
s=FreeSWITCH
c=IN IP4 10.3.0.4
t=0 0
m=audio 16424 RTP/AVP 9 127
a=rtpmap:9 G722/8000
a=rtpmap:127 telephone-event/8000
a=fmtp:127 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
]
variable_local_media_ip: [10.3.0.4]
variable_local_media_port: [16424]
variable_advertised_media_ip: [10.3.0.4]
variable_sip_use_pt: [9]
variable_rtp_use_ssrc: [1271749377]
variable_sip_2833_send_payload: [127]
variable_sip_2833_recv_payload: [127]
variable_last_bridge_to: [c1665710-6a0f-11e1-8e64-299021af10b6]
variable_bridge_channel: [sofia/internal/sip:20 at 10.3.0.25]
variable_bridge_uuid: [c1665710-6a0f-11e1-8e64-299021af10b6]
variable_sip_to_tag: [XByp5KaN7H5UN]
variable_sip_cseq: [2]
variable_switch_m_sdp: [v=0
o=- 1167610359 1167610360 IN IP4 10.3.0.25
s=Polycom IP Phone
c=IN IP4 0.0.0.0
t=0 0
m=audio 2230 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=sendonly
m=video 0 RTP/AVP 98 99 100 34 31
a=rtpmap:98 H264/90000
a=rtpmap:99 H263-2000/90000
a=rtpmap:100 H263-1998/90000
a=rtpmap:34 H263/90000
a=rtpmap:31 H261/90000
]
variable_att_xfer_kill_uuid: [c3c26f12-6a0f-11e1-8e6d-299021af10b6]
variable_transfer_history: [ARRAY::1331315177:c60f0154-6a0f-11e1-8e79-299021af10b6:bl_xfer:endless_playback:local_stream://moh,park/default/inline]
variable_transfer_source: [1331315177:c60f0154-6a0f-11e1-8e79-299021af10b6:bl_xfer:endless_playback:local_stream://moh,park/default/inline]
variable_bridge_hangup_cause: [NORMAL_CLEARING]
variable_direction: [inbound]
variable_uuid: [c3c26f12-6a0f-11e1-8e6d-299021af10b6]
variable_session_id: [183]
variable_sip_local_network_addr: [10.3.0.4]
variable_sip_network_ip: [10.3.0.25]
variable_sip_network_port: [5060]
variable_sip_received_ip: [10.3.0.25]
variable_sip_received_port: [5060]
variable_sip_via_protocol: [udp]
variable_sip_authorized: [true]
variable_sip_number_alias: [20]
variable_sip_auth_username: [20]
variable_sip_auth_realm: [10.3.0.4]
variable_number_alias: [20]
variable_user_name: [20]
variable_domain_name: [10.3.0.4]
variable_record_stereo: [true]
variable_default_gateway: [fonira]
variable_default_areacode: [01]
variable_transfer_fallback_extension: [operator]
variable_toll_allow: [local,domestic,international,vas]
variable_accountcode: [20]
variable_user_context: [default]
variable_effective_caller_id_name: [B ]
variable_effective_caller_id_number: [20]
variable_outbound_caller_id_name: [B ]
variable_outbound_caller_id_number: [1997156020]
variable_callgroup: [intercept]
variable_sip_from_user: [20]
variable_sip_from_uri: [20 at 10.3.0.4]
variable_sip_from_host: [10.3.0.4]
variable_sip_from_user_stripped: [20]
variable_sip_from_tag: [FAB3376C-15AEB62F]
variable_sofia_profile_name: [internal]
variable_sip_full_via: [SIP/2.0/UDP 10.3.0.25;branch=z9hG4bK924971a7A89CEC02]
variable_sip_from_display: [B]
variable_sip_full_from: ["B" <sip:20 at 10.3.0.4>;tag=FAB3376C-15AEB62F]
variable_sip_full_to: [<sip:830 at 10.3.0.4;user=phone>]
variable_sip_req_params: [user=phone]
variable_sip_req_user: [830]
variable_sip_req_port: [5060]
variable_sip_req_uri: [830 at 10.3.0.4:5060]
variable_sip_req_host: [10.3.0.4]
variable_sip_to_params: [user=phone]
variable_sip_to_user: [830]
variable_sip_to_uri: [830 at 10.3.0.4]
variable_sip_to_host: [10.3.0.4]
variable_sip_contact_user: [20]
variable_sip_contact_uri: [20 at 10.3.0.25]
variable_sip_contact_host: [10.3.0.25]
variable_channel_name: [sofia/internal/20 at 10.3.0.4]
variable_sip_call_id: [12bb6ca6-d165db9-ac5e8f24 at 10.3.0.25]
variable_sip_user_agent: [PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933]
variable_sip_via_host: [10.3.0.25]
variable_max_forwards: [70]
variable_presence_id: [20 at 10.3.0.4]
variable_switch_r_sdp: [v=0
o=- 1167610362 1167610362 IN IP4 10.3.0.25
s=Polycom IP Phone
c=IN IP4 10.3.0.25
t=0 0
a=sendrecv
m=audio 2232 RTP/AVP 9 0 8 127
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:127 telephone-event/8000
]
variable_remote_media_ip: [10.3.0.25]
variable_remote_media_port: [2232]
variable_sip_audio_recv_pt: [9]
variable_sip_use_codec_name: [G722]
variable_sip_use_codec_rate: [8000]
variable_sip_use_codec_ptime: [20]
variable_read_codec: [G722]
variable_read_rate: [16000]
variable_write_codec: [G722]
variable_write_rate: [16000]
variable_dialed_user: [30]
variable_dialed_domain: [10.3.0.4]
variable_originate_disposition: [failure]
variable_DIALSTATUS: [INVALIDARGS]
variable_endpoint_disposition: [ATTENDED_TRANSFER]
variable_sip_term_status: [481]
variable_proto_specific_hangup_cause: [sip:481]
variable_sip_term_cause: [41]
variable_playback_seconds: [16]
variable_playback_ms: [16600]
variable_playback_samples: [132800]
variable_call_uuid: [bf969cf6-6a0f-11e1-8e5c-299021af10b6]
variable_current_application: [info]

2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:30 at 10.3.0.26) State HANGUP
2012-03-09 18:46:26.052925 [DEBUG] mod_sofia.c:469 Channel sofia/internal/sip:30 at 10.3.0.26 hanging up, cause: ATTENDED_TRANSFER
EXECUTE sofia/internal/10 at 10.3.0.4 log(WARNING TEST4 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 10, dest 830)
2012-03-09 18:46:26.052925 [WARNING] mod_dptools.c:1420 TEST4 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 10, dest 830
EXECUTE sofia/internal/10 at 10.3.0.4 sleep(1000)
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:47 sofia/internal/20 at 10.3.0.4 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/20 at 10.3.0.4) State HANGUP going to sleep
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:393 (sofia/internal/20 at 10.3.0.4) State Change CS_HANGUP -> CS_REPORTING
2012-03-09 18:46:26.052925 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/20 at 10.3.0.4 [BREAK]
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/20 at 10.3.0.4) Running State Change CS_REPORTING
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/20 at 10.3.0.4) State REPORTING
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:79 sofia/internal/20 at 10.3.0.4 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/20 at 10.3.0.4) State REPORTING going to sleep
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:387 (sofia/internal/20 at 10.3.0.4) State Change CS_REPORTING -> CS_DESTROY
2012-03-09 18:46:26.052925 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/20 at 10.3.0.4 [BREAK]
2012-03-09 18:46:26.052925 [DEBUG] switch_core_session.c:1380 Session 183 (sofia/internal/20 at 10.3.0.4) Locked, Waiting on external entities
2012-03-09 18:46:26.052925 [NOTICE] switch_core_session.c:1398 Session 183 (sofia/internal/20 at 10.3.0.4) Ended
2012-03-09 18:46:26.052925 [NOTICE] switch_core_session.c:1400 Close Channel sofia/internal/20 at 10.3.0.4 [CS_DESTROY]
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/20 at 10.3.0.4) Callstate Change HANGUP -> DOWN
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:494 (sofia/internal/20 at 10.3.0.4) Running State Change CS_DESTROY
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/20 at 10.3.0.4) State DESTROY
2012-03-09 18:46:26.052925 [DEBUG] mod_sofia.c:374 sofia/internal/20 at 10.3.0.4 SOFIA DESTROY
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:86 sofia/internal/20 at 10.3.0.4 Standard DESTROY
2012-03-09 18:46:26.052925 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/20 at 10.3.0.4) State DESTROY going to sleep
2012-03-09 18:46:26.074508 [DEBUG] mod_sofia.c:523 Sending CANCEL to sofia/internal/sip:30 at 10.3.0.26
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:47 sofia/internal/sip:30 at 10.3.0.26 Standard HANGUP, cause: ATTENDED_TRANSFER
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/sip:30 at 10.3.0.26) State HANGUP going to sleep
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:393 (sofia/internal/sip:30 at 10.3.0.26) State Change CS_HANGUP -> CS_REPORTING
2012-03-09 18:46:26.074508 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30 at 10.3.0.26 [BREAK]
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/sip:30 at 10.3.0.26) Running State Change CS_REPORTING
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:30 at 10.3.0.26) State REPORTING
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:79 sofia/internal/sip:30 at 10.3.0.26 Standard REPORTING, cause: ATTENDED_TRANSFER
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/sip:30 at 10.3.0.26) State REPORTING going to sleep
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:387 (sofia/internal/sip:30 at 10.3.0.26) State Change CS_REPORTING -> CS_DESTROY
send 334 bytes to udp/[10.3.0.26]:5060 at 17:46:26.077886:
   ------------------------------------------------------------------------
   CANCEL sip:30 at 10.3.0.26 SIP/2.02012-03-09 18:46:26.074508 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/sip:30 at 10.3.0.26 [BREAK]

   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8acFFp1m4BjDc
   Max-Forwards: 69
2012-03-09 18:46:26.074508 [DEBUG] switch_core_session.c:1380 Session 184 (sofia/internal/sip:30 at 10.3.0.26) Locked, Waiting on external entities
   From: "B " <sip:20 at 10.3.0.4>;tag=1F3Sc0D3UNy6K
   To: <sip:30 at 10.3.0.26>
   Call-ID: 9cf1865a-e4b2-122f-cd91-00900b1be504
   CSeq: 25321524 CANCEL2012-03-09 18:46:26.074508 [NOTICE] switch_core_session.c:1398 Session 184 (sofia/internal/sip:30 at 10.3.0.26) Ended

   Reason: FreeSWITCH;cause=601;text="ATTENDED_TRANSFER"
   Content-Length: 02012-03-09 18:46:26.074508 [NOTICE] switch_core_session.c:1400 Close Channel sofia/internal/sip:30 at 10.3.0.26 [CS_DESTROY]

   ------------------------------------------------------------------------
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/sip:30 at 10.3.0.26) Callstate Change HANGUP -> DOWN
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:494 (sofia/internal/sip:30 at 10.3.0.26) Running State Change CS_DESTROY
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:30 at 10.3.0.26) State DESTROY
2012-03-09 18:46:26.074508 [DEBUG] mod_sofia.c:374 sofia/internal/sip:30 at 10.3.0.26 SOFIA DESTROY
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:86 sofia/internal/sip:30 at 10.3.0.26 Standard DESTROY
2012-03-09 18:46:26.074508 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:30 at 10.3.0.26) State DESTROY going to sleep
recv 386 bytes from udp/[10.3.0.26]:5060 at 17:46:26.085229:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8acFFp1m4BjDc
   From: "B" <sip:20 at 10.3.0.4>;tag=1F3Sc0D3UNy6K
   To: "C" <sip:30 at 10.3.0.26>
   CSeq: 25321524 CANCEL
   Call-ID: 9cf1865a-e4b2-122f-cd91-00900b1be504
   Contact: <sip:30 at 10.3.0.26>
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Content-Length: 0

   ------------------------------------------------------------------------
recv 422 bytes from udp/[10.3.0.26]:5060 at 17:46:26.091905:
   ------------------------------------------------------------------------
   SIP/2.0 487 Request Cancelled
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8acFFp1m4BjDc
   From: "B" <sip:20 at 10.3.0.4>;tag=1F3Sc0D3UNy6K
   To: "C" <sip:30 at 10.3.0.26>;tag=93CE8DA-22B4DC39
   CSeq: 25321524 INVITE
   Call-ID: 9cf1865a-e4b2-122f-cd91-00900b1be504
   Contact: <sip:30 at 10.3.0.26>
   User-Agent: PolycomSoundPointIP-SPIP_650-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Content-Length: 0

   ------------------------------------------------------------------------
send 310 bytes to udp/[10.3.0.26]:5060 at 17:46:26.092411:
   ------------------------------------------------------------------------
   ACK sip:30 at 10.3.0.26 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bK8acFFp1m4BjDc
   Max-Forwards: 69
   From: "B " <sip:20 at 10.3.0.4>;tag=1F3Sc0D3UNy6K
   To: "C" <sip:30 at 10.3.0.26>;tag=93CE8DA-22B4DC39
   Call-ID: 9cf1865a-e4b2-122f-cd91-00900b1be504
   CSeq: 25321524 ACK
   Content-Length: 0

   ------------------------------------------------------------------------
EXECUTE sofia/internal/10 at 10.3.0.4 log(WARNING TEST5 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 10, dest 830)
2012-03-09 18:46:27.072929 [WARNING] mod_dptools.c:1420 TEST5 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 10, dest 830
EXECUTE sofia/internal/10 at 10.3.0.4 sleep(1000)
EXECUTE sofia/internal/10 at 10.3.0.4 log(WARNING TEST6 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 10, dest 830)
2012-03-09 18:46:28.092926 [WARNING] mod_dptools.c:1420 TEST6 for UUID c3c26f12-6a0f-11e1-8e6d-299021af10b6, src 10, dest 830
EXECUTE sofia/internal/10 at 10.3.0.4 sleep(1000)
2012-03-09 18:46:29.112925 [NOTICE] switch_core_state_machine.c:226 sofia/internal/10 at 10.3.0.4 has executed the last dialplan instruction, hanging up.
2012-03-09 18:46:29.112925 [DEBUG] switch_channel.c:2848 (sofia/internal/10 at 10.3.0.4) Callstate Change ACTIVE -> HANGUP
2012-03-09 18:46:29.112925 [NOTICE] switch_core_state_machine.c:228 Hangup sofia/internal/10 at 10.3.0.4 [CS_EXECUTE] [NORMAL_CLEARING]
2012-03-09 18:46:29.112925 [DEBUG] switch_channel.c:2871 Send signal sofia/internal/10 at 10.3.0.4 [KILL]
2012-03-09 18:46:29.112925 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/10 at 10.3.0.4) State EXECUTE going to sleep
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10 at 10.3.0.4) Running State Change CS_HANGUP
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/10 at 10.3.0.4) State HANGUP
2012-03-09 18:46:29.112925 [DEBUG] mod_sofia.c:469 Channel sofia/internal/10 at 10.3.0.4 hanging up, cause: NORMAL_CLEARING
2012-03-09 18:46:29.112925 [DEBUG] mod_sofia.c:513 Sending BYE to sofia/internal/10 at 10.3.0.4
send 640 bytes to udp/[10.3.0.22]:5060 at 17:46:29.121085:
   ------------------------------------------------------------------------
   BYE sip:10 at 10.3.0.22 SIP/2.0
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKcFHjp242rFBra
   Max-Forwards: 70
   From: <sip:820 at 10.3.0.4;user=phone>;tag=XByp5KaN7H5UN
   To: "A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314
   Call-ID: 73ec8749-ef90cb48-95fd5843 at 10.3.0.22
   CSeq: 25321530 BYE
   Contact: <sip:820 at 10.3.0.4:5060;transport=udp>
   User-Agent: FreeSWITCH-mod_sofia/1.0.head-git-b128198 2012-03-08 15-27-51 -0600
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
   Supported: timer, precondition, path, replaces
   Reason: Q.850;cause=16;text="NORMAL_CLEARING"
   Content-Length: 0

   ------------------------------------------------------------------------
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:47 sofia/internal/10 at 10.3.0.4 Standard HANGUP, cause: NORMAL_CLEARING
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/10 at 10.3.0.4) State HANGUP going to sleep
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:393 (sofia/internal/10 at 10.3.0.4) State Change CS_HANGUP -> CS_REPORTING
2012-03-09 18:46:29.112925 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/10 at 10.3.0.4) Running State Change CS_REPORTING
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10 at 10.3.0.4) State REPORTING
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:79 sofia/internal/10 at 10.3.0.4 Standard REPORTING, cause: NORMAL_CLEARING
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/10 at 10.3.0.4) State REPORTING going to sleep
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:387 (sofia/internal/10 at 10.3.0.4) State Change CS_REPORTING -> CS_DESTROY
2012-03-09 18:46:29.112925 [DEBUG] switch_core_session.c:1180 Send signal sofia/internal/10 at 10.3.0.4 [BREAK]
2012-03-09 18:46:29.112925 [DEBUG] switch_core_session.c:1380 Session 181 (sofia/internal/10 at 10.3.0.4) Locked, Waiting on external entities
2012-03-09 18:46:29.112925 [NOTICE] switch_core_session.c:1398 Session 181 (sofia/internal/10 at 10.3.0.4) Ended
2012-03-09 18:46:29.112925 [NOTICE] switch_core_session.c:1400 Close Channel sofia/internal/10 at 10.3.0.4 [CS_DESTROY]
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/10 at 10.3.0.4) Callstate Change HANGUP -> DOWN
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:494 (sofia/internal/10 at 10.3.0.4) Running State Change CS_DESTROY
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/10 at 10.3.0.4) State DESTROY
2012-03-09 18:46:29.112925 [DEBUG] mod_sofia.c:374 sofia/internal/10 at 10.3.0.4 SOFIA DESTROY
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:86 sofia/internal/10 at 10.3.0.4 Standard DESTROY
2012-03-09 18:46:29.112925 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/10 at 10.3.0.4) State DESTROY going to sleep
recv 401 bytes from udp/[10.3.0.22]:5060 at 17:46:29.128903:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   Via: SIP/2.0/UDP 10.3.0.4;rport;branch=z9hG4bKcFHjp242rFBra
   From: <sip:820 at 10.3.0.4;user=phone>;tag=XByp5KaN7H5UN
   To: "A" <sip:10 at 10.3.0.4>;tag=A59BE1A5-8A2B1314
   CSeq: 25321530 BYE
   Call-ID: 73ec8749-ef90cb48-95fd5843 at 10.3.0.22
   Contact: <sip:10 at 10.3.0.22>
   User-Agent: PolycomSoundPointIP-SPIP_670-UA/3.3.1.0933
   Accept-Language: de-de,de;q=0.9,en;q=0.8
   Content-Length: 0

   ------------------------------------------------------------------------