[Freeswitch-users] Leg-A is automatically disconnected on Leg-B orginate failure

David Ma mays.david at gmail.com
Mon Jun 27 10:27:19 MSD 2011


Hi Michael,

Thanks very much for the response. There is no dialplan specified for this
call. In the FS setting, G729 is used as preferred stack for originating
calls. The leg-A and B are bridged immediately after receiving
PROGRESS-MEDIA from leg-B.

Calls are originated with following parameters:
*
-- Leg-A --
            "api originate
{origination_caller_id_number=<caller>,sip_cid_type=pid,privacy=yes,continue_on_fail=true}
<called> &park()"

**-- Leg-B --*
*            "api originate
{origination_caller_id_number=<caller>,originate_timeout=60,sip_cid_type=pid,privacy=yes,continue_on_fail=false}
<called> &park()"
*

The entire debug log for this call follows.

Thanks,
D.Ma

=================================
2011-06-24 13:29:35.887830 [DEBUG] switch_ivr_originate.c:1971 variable
string 0 = [origination_caller_id_number=03996563750911]
2011-06-24 13:29:35.887830 [DEBUG] switch_ivr_originate.c:1971 variable
string 1 = [originate_timeout=60]
2011-06-24 13:29:35.887830 [DEBUG] switch_ivr_originate.c:1971 variable
string 2 = [ccd_session_id=20110624132936888918]
2011-06-24 13:29:35.887830 [DEBUG] switch_ivr_originate.c:1971 variable
string 3 = [sip_cid_type=pid]
2011-06-24 13:29:35.887830 [DEBUG] switch_ivr_originate.c:1971 variable
string 4 = [privacy=yes]
2011-06-24 13:29:35.887830 [DEBUG] switch_ivr_originate.c:1971 variable
string 5 = [continue_on_fail=true]
2011-06-24 13:29:35.887830 [NOTICE] switch_channel.c:808 New Channel
sofia/external/03996597632298 at 203.208.207.212[c0bd700d-913c-42ad-b68f-81001bf658b8]
2011-06-24 13:29:35.887830 [DEBUG] mod_sofia.c:4129 (sofia/external/
03996597632298 at 203.208.207.212) State Change CS_NEW -> CS_INIT
2011-06-24 13:29:35.887830 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:35.889072 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996597632298 at 203.208.207.212) Running State Change CS_INIT
2011-06-24 13:29:35.889829 [DEBUG] switch_core_state_machine.c:356
(sofia/external/03996597632298 at 203.208.207.212) State INIT
2011-06-24 13:29:35.889829 [DEBUG] mod_sofia.c:84 sofia/external/
03996597632298 at 203.208.207.212 SOFIA INIT
send 999 bytes to udp/[203.208.207.212]:5060 at 05:29:36.398490:
   ------------------------------------------------------------------------
   INVITE sip:03996597632298 at 203.208.207.212 SIP/2.0
   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKtpaQ28SQXKvem
   Max-Forwards: 70
   From: "" <sip:03996563750911 at 202.73.56.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212>
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110624 INVITE
   Contact: <sip:mod_sofia at 202.73.56.46:5080>
   User-Agent: FreeSWITCH-mod_sofia/1.0.7-hacked-20110603T012235Z
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO,
REGISTER, REFER, PRACK, NOTIFY
   Supported: 100rel, timer, precondition, path, replaces
   Allow-Events: talk, hold, refer
   Privacy: none
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 204
   X-FS-Support: update_display
   P-Asserted-Identity: "" <sip:03996563750911 at 202.73.56.46>

   v=0
   o=FreeSWITCH 1308862405 1308862406 IN IP4 202.73.56.46
   s=FreeSWITCH
   c=IN IP4 202.73.56.46
   t=0 0
   m=audio 30970 RTP/AVP 18 3 101 13
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   ------------------------------------------------------------------------
2011-06-24 13:29:35.891343 [DEBUG] mod_sofia.c:124 (sofia/external/
03996597632298 at 203.208.207.212) State Change CS_INIT -> CS_ROUTING
2011-06-24 13:29:35.891343 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:35.891343 [DEBUG] sofia.c:4646 Channel sofia/external/
03996597632298 at 203.208.207.212 entering state [calling][0]
2011-06-24 13:29:35.891343 [DEBUG] switch_core_state_machine.c:356
(sofia/external/03996597632298 at 203.208.207.212) State INIT going to sleep
2011-06-24 13:29:35.891343 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996597632298 at 203.208.207.212) Running State Change
CS_ROUTING
2011-06-24 13:29:35.891343 [DEBUG] switch_channel.c:1657 (sofia/external/
03996597632298 at 203.208.207.212) Callstate Change DOWN -> RINGING
2011-06-24 13:29:35.891343 [DEBUG] switch_core_state_machine.c:359
(sofia/external/03996597632298 at 203.208.207.212) State ROUTING
2011-06-24 13:29:35.891343 [DEBUG] mod_sofia.c:147 sofia/external/
03996597632298 at 203.208.207.212 SOFIA ROUTING
2011-06-24 13:29:35.891343 [DEBUG] switch_ivr_originate.c:66
(sofia/external/03996597632298 at 203.208.207.212) State Change CS_ROUTING ->
CS_CONSUME_MEDIA
2011-06-24 13:29:35.891343 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:35.891343 [DEBUG] switch_core_state_machine.c:359
(sofia/external/03996597632298 at 203.208.207.212) State ROUTING going to sleep
2011-06-24 13:29:35.891343 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996597632298 at 203.208.207.212) Running State Change
CS_CONSUME_MEDIA
2011-06-24 13:29:35.891343 [DEBUG] switch_core_state_machine.c:378
(sofia/external/03996597632298 at 203.208.207.212) State CONSUME_MEDIA
2011-06-24 13:29:35.891343 [DEBUG] switch_core_state_machine.c:378
(sofia/external/03996597632298 at 203.208.207.212) State CONSUME_MEDIA going to
sleep
recv 307 bytes from udp/[203.208.207.212]:5060 at 05:29:36.404598:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bKtpaQ28SQXKvem;received=10.1.1.46
   From: "" <sip:03996563750911 at 10.1.1.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212>
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110624 INVITE
   Content-Length:     0

   ------------------------------------------------------------------------
recv 774 bytes from udp/[203.208.207.212]:5060 at 05:29:37.615248:
   ------------------------------------------------------------------------
   SIP/2.0 183 Session Progress
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bKtpaQ28SQXKvem;received=10.1.1.46
   From: "" <sip:03996563750911 at 10.1.1.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RX0S6R1TX
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110624 INVITE
   Contact: <sip:203.208.207.212:5060>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, INFO, REFER, NOTIFY,
SUBSCRIBE, UPDATE
   Content-Type: application/sdp
   Require: 100rel
   RSeq: 1
   Content-Length:   231

   v=0
   o=- 508539113671071081 1 IN IP4 203.208.207.212
   s=session
   c=IN IP4 203.208.207.201
   t=0 0
   m=audio 25120 RTP/AVP 18 101
   a=rtpmap:18 G729/8000
   a=fmtp:18 annexb=no
   a=rtpmap:101 telephone-event/8000
   a=ptime:20
   a=sendrecv
   ------------------------------------------------------------------------
send 651 bytes to udp/[203.208.207.212]:5060 at 05:29:37.615605:
   ------------------------------------------------------------------------
   PRACK sip:203.208.207.212:5060 SIP/2.0
   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKUZ3F43aUtvj1F
   Max-Forwards: 70
   From: "" <sip:03996563750911 at 202.73.56.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RX0S6R1TX
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110625 PRACK
   Contact: <sip:mod_sofia at 202.73.56.46:5080>
   RAck: 1 14110624 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.7-hacked-20110603T012235Z
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO,
REGISTER, REFER, PRACK, NOTIFY
   Supported: 100rel, timer, precondition, path, replaces
   Content-Length: 0

   ------------------------------------------------------------------------
2011-06-24 13:29:37.107576 [INFO] sofia.c:729 sofia/external/
03996597632298 at 203.208.207.212 Update Callee ID to "Outbound Call"
<03996597632298>
2011-06-24 13:29:37.107576 [DEBUG] sofia.c:4646 Channel sofia/external/
03996597632298 at 203.208.207.212 entering state [proceeding][183]
2011-06-24 13:29:37.107576 [DEBUG] sofia.c:4657 Remote SDP:
v=0
o=- 508539113671071081 1 IN IP4 203.208.207.212
s=session
c=IN IP4 203.208.207.201
t=0 0
m=audio 25120 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=ptime:20

2011-06-24 13:29:37.107576 [DEBUG] sofia_glue.c:4467 Audio Codec Compare
[G729:18:8000:20:8000]/[G729:18:8000:20:8000]
2011-06-24 13:29:37.107576 [DEBUG] sofia_glue.c:2757 Set Codec
sofia/external/03996597632298 at 203.208.207.212 G729/8000 20 ms 160 samples
8000 bits
2011-06-24 13:29:37.108995 [DEBUG] sofia_glue.c:4565 Set 2833 dtmf send
payload to 101
2011-06-24 13:29:37.108995 [DEBUG] sofia_glue.c:2987 AUDIO RTP
[sofia/external/03996597632298 at 203.208.207.212] 10.1.1.46 port 30970 ->
203.208.207.201 port 25120 codec: 18 ms: 20
2011-06-24 13:29:37.108995 [DEBUG] switch_rtp.c:1607 Starting timer [soft]
160 bytes per 20ms
2011-06-24 13:29:37.109893 [DEBUG] sofia_glue.c:3228 Set 2833 dtmf send
payload to 101
2011-06-24 13:29:37.109893 [DEBUG] sofia_glue.c:3233 Set 2833 dtmf receive
payload to 101
2011-06-24 13:29:37.109893 [NOTICE] sofia_glue.c:3680 Pre-Answer
sofia/external/03996597632298 at 203.208.207.212!
2011-06-24 13:29:37.109893 [DEBUG] switch_channel.c:2627 (sofia/external/
03996597632298 at 203.208.207.212) Callstate Change RINGING -> EARLY
2011-06-24 13:29:37.109893 [DEBUG] switch_ivr_originate.c:3408 Originate
Resulted in Success: [sofia/external/03996597632298 at 203.208.207.212]
2011-06-24 13:29:37.109893 [DEBUG] mod_commands.c:3205 (sofia/external/
03996597632298 at 203.208.207.212) State Change CS_CONSUME_MEDIA -> CS_EXECUTE
2011-06-24 13:29:37.109893 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:37.111618 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996597632298 at 203.208.207.212) Running State Change
CS_EXECUTE
2011-06-24 13:29:37.111618 [DEBUG] switch_core_state_machine.c:366
(sofia/external/03996597632298 at 203.208.207.212) State EXECUTE
2011-06-24 13:29:37.111618 [DEBUG] mod_sofia.c:240 sofia/external/
03996597632298 at 203.208.207.212 SOFIA EXECUTE
2011-06-24 13:29:37.111618 [DEBUG] switch_core_state_machine.c:157
sofia/external/03996597632298 at 203.208.207.212 Standard EXECUTE
EXECUTE sofia/external/03996597632298 at 203.208.207.212 park()
recv 382 bytes from udp/[203.208.207.212]:5060 at 05:29:37.620736:
   ------------------------------------------------------------------------
   SIP/2.0 200 Ok
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bKUZ3F43aUtvj1F;received=10.1.1.46
   From: "" <sip:03996563750911 at 10.1.1.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RX0S6R1TX
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110625 PRACK
   Contact: <sip:203.208.207.212:5060>
   Content-Length:     0

   ------------------------------------------------------------------------
2011-06-24 13:29:37.160714 [DEBUG] switch_rtp.c:2933 Correct ip/port
confirmed.
recv 512 bytes from udp/[203.208.207.212]:5060 at 05:29:45.146388:
   ------------------------------------------------------------------------
   SIP/2.0 183 Session Progress
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bKtpaQ28SQXKvem;received=10.1.1.46
   From: "" <sip:03996563750911 at 10.1.1.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RX0S6R1TX
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110624 INVITE
   Contact: <sip:203.208.207.212:5060>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, INFO, REFER, NOTIFY,
SUBSCRIBE, UPDATE
   Require: 100rel
   RSeq: 2
   Content-Length:     0

   ------------------------------------------------------------------------
send 651 bytes to udp/[203.208.207.212]:5060 at 05:29:45.146628:
   ------------------------------------------------------------------------
   PRACK sip:203.208.207.212:5060 SIP/2.0
   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKv8v85yUyQ58KB
  Max-Forwards: 70
   From: "" <sip:03996563750911 at 202.73.56.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RX0S6R1TX
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110626 PRACK
   Contact: <sip:mod_sofia at 202.73.56.46:5080>
   RAck: 2 14110624 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.7-hacked-20110603T012235Z
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO,
REGISTER, REFER, PRACK, NOTIFY
   Supported: 100rel, timer, precondition, path, replaces
   Content-Length: 0

   ------------------------------------------------------------------------
2011-06-24 13:29:44.639310 [INFO] sofia.c:729 sofia/external/
03996597632298 at 203.208.207.212 Update Callee ID to "03996597632298"
<03996597632298>
2011-06-24 13:29:44.639310 [DEBUG] sofia.c:4641 Channel sofia/external/
03996597632298 at 203.208.207.212 skipping state [proceeding][183]
recv 382 bytes from udp/[203.208.207.212]:5060 at 05:29:45.151718:
   ------------------------------------------------------------------------
   SIP/2.0 200 Ok
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bKv8v85yUyQ58KB;received=10.1.1.46
   From: "" <sip:03996563750911 at 10.1.1.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RX0S6R1TX
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110626 PRACK
   Contact: <sip:203.208.207.212:5060>
   Content-Length:     0

   ------------------------------------------------------------------------
recv 529 bytes from udp/[203.208.207.212]:5060 at 05:29:47.446072:
   ------------------------------------------------------------------------
   SIP/2.0 200 Ok
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bKtpaQ28SQXKvem;received=10.1.1.46
   From: "" <sip:03996563750911 at 10.1.1.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RX0S6R1TX
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110624 INVITE
   Contact: <sip:203.208.207.212:5060>
   Allow-Events: refer
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, INFO, REFER, NOTIFY,
SUBSCRIBE, UPDATE
   Supported: 100rel, timer, replaces
   Content-Length:     0

   ------------------------------------------------------------------------
2011-06-24 13:29:46.938477 [DEBUG] sofia.c:4646 Channel sofia/external/
03996597632298 at 203.208.207.212 entering state [completing][200]
send 405 bytes to udp/[203.208.207.212]:5060 at 05:29:47.446869:
   ------------------------------------------------------------------------
   ACK sip:203.208.207.212:5060 SIP/2.0
   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKXHp17Sc2meZ6p
   Max-Forwards: 70
   From: "" <sip:03996563750911 at 202.73.56.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RX0S6R1TX
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110624 ACK
   Contact: <sip:mod_sofia at 202.73.56.46:5080>
   Content-Length: 0

   ------------------------------------------------------------------------
2011-06-24 13:29:46.939738 [DEBUG] sofia.c:4646 Channel sofia/external/
03996597632298 at 203.208.207.212 entering state [ready][200]
2011-06-24 13:29:46.939738 [DEBUG] switch_channel.c:2782 (sofia/external/
03996597632298 at 203.208.207.212) Callstate Change EARLY -> ACTIVE
2011-06-24 13:29:46.939738 [NOTICE] sofia.c:5175 Channel [sofia/external/
03996597632298 at 203.208.207.212] has been answered
2011-06-24 13:29:46.942763 [DEBUG] switch_scheduler.c:214 Added task 27
switch_ivr_schedule_hangup (c0bd700d-913c-42ad-b68f-81001bf658b8) to run at
1308896986
2011-06-24 13:29:46.944563 [DEBUG] switch_core_session.c:954 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:46.945633 [DEBUG] switch_ivr_originate.c:1971 variable
string 0 = [origination_caller_id_number=03996597632298]
2011-06-24 13:29:46.945633 [DEBUG] switch_ivr_originate.c:1971 variable
string 1 = [ccd_session_id=20110624132936888918]
2011-06-24 13:29:46.945633 [DEBUG] switch_ivr_originate.c:1971 variable
string 2 = [sip_cid_type=pid]
2011-06-24 13:29:46.945633 [DEBUG] switch_ivr_originate.c:1971 variable
string 3 = [privacy=yes]
2011-06-24 13:29:46.945633 [DEBUG] switch_ivr_originate.c:1971 variable
string 4 = [continue_on_fail=false]
2011-06-24 13:29:46.945633 [NOTICE] switch_channel.c:808 New Channel
sofia/external/03996563750911 at 203.208.207.212[817124e6-26fe-46cc-af55-89715abdfced]
2011-06-24 13:29:46.945633 [DEBUG] mod_sofia.c:4129 (sofia/external/
03996563750911 at 203.208.207.212) State Change CS_NEW -> CS_INIT
2011-06-24 13:29:46.945633 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:46.945633 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996563750911 at 203.208.207.212) Running State Change CS_INIT
2011-06-24 13:29:46.945633 [DEBUG] switch_core_state_machine.c:356
(sofia/external/03996563750911 at 203.208.207.212) State INIT
2011-06-24 13:29:46.945633 [DEBUG] mod_sofia.c:84 sofia/external/
03996563750911 at 203.208.207.212 SOFIA INIT
2011-06-24 13:29:46.945633 [DEBUG] mod_sofia.c:124 (sofia/external/
03996563750911 at 203.208.207.212) State Change CS_INIT -> CS_ROUTING
2011-06-24 13:29:46.945633 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:46.945633 [DEBUG] switch_core_state_machine.c:356
(sofia/external/03996563750911 at 203.208.207.212) State INIT going to sleep
2011-06-24 13:29:46.945633 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996563750911 at 203.208.207.212) Running State Change
CS_ROUTING
2011-06-24 13:29:46.945633 [DEBUG] switch_channel.c:1657 (sofia/external/
03996563750911 at 203.208.207.212) Callstate Change DOWN -> RINGING
2011-06-24 13:29:46.945633 [DEBUG] switch_core_state_machine.c:359
(sofia/external/03996563750911 at 203.208.207.212) State ROUTING
2011-06-24 13:29:46.945633 [DEBUG] mod_sofia.c:147 sofia/external/
03996563750911 at 203.208.207.212 SOFIA ROUTING
2011-06-24 13:29:46.945633 [DEBUG] switch_ivr_originate.c:66
(sofia/external/03996563750911 at 203.208.207.212) State Change CS_ROUTING ->
CS_CONSUME_MEDIA
2011-06-24 13:29:46.945633 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:46.945633 [DEBUG] switch_core_state_machine.c:359
(sofia/external/03996563750911 at 203.208.207.212) State ROUTING going to sleep
2011-06-24 13:29:46.945633 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996563750911 at 203.208.207.212) Running State Change
CS_CONSUME_MEDIA
send 999 bytes to udp/[203.208.207.212]:5060 at 05:29:47.454251:
   ------------------------------------------------------------------------
   INVITE sip:03996563750911 at 203.208.207.212 SIP/2.0
   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKytFt9mX5HQNSj
   Max-Forwards: 70
   From: "" <sip:03996597632298 at 202.73.56.46>;tag=62eBXSt93tr7F
   To: <sip:03996563750911 at 203.208.207.212>
   Call-ID: d0f42376-18c5-122f-3387-0015c5fc7ad92011-06-24 13:29:46.945633
[DEBUG] switch_core_state_machine.c:378 (sofia/external/
03996563750911 at 203.208.207.212) State CONSUME_MEDIA

   CSeq: 14110629 INVITE
   Contact: <sip:mod_sofia at 202.73.56.46:5080>
2011-06-24 13:29:46.945633 [DEBUG] switch_core_state_machine.c:378
(sofia/external/03996563750911 at 203.208.207.212) State CONSUME_MEDIA going to
sleep
   User-Agent: FreeSWITCH-mod_sofia/1.0.7-hacked-20110603T012235Z
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO,
REGISTER, REFER, PRACK, NOTIFY
   Supported: 100rel, timer, precondition, path, replaces
   Allow-Events: talk, hold, refer
   Privacy: none
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 204
   X-FS-Support: update_display
   P-Asserted-Identity: "" <sip:03996597632298 at 202.73.56.46>

   v=0
   o=FreeSWITCH 1308872756 1308872757 IN IP4 202.73.56.46
   s=FreeSWITCH
   c=IN IP4 202.73.56.46
   t=0 0
   m=audio 20630 RTP/AVP 18 3 101 13
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=ptime:20
   ------------------------------------------------------------------------
2011-06-24 13:29:46.946974 [DEBUG] sofia.c:4646 Channel sofia/external/
03996563750911 at 203.208.207.212 entering state [calling][0]
recv 307 bytes from udp/[203.208.207.212]:5060 at 05:29:47.460017:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bKytFt9mX5HQNSj;received=10.1.1.46
   From: "" <sip:03996597632298 at 10.1.1.46>;tag=62eBXSt93tr7F
   To: <sip:03996563750911 at 203.208.207.212>
   Call-ID: d0f42376-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110629 INVITE
   Content-Length:     0

   ------------------------------------------------------------------------
2011-06-24 13:29:46.960900 [DEBUG] switch_ivr.c:563 sofia/external/
03996597632298 at 203.208.207.212 Command Execute
playback(/usr/local/freeswitch/sounds/clearhub/MusicForCalls_v1.wav)
EXECUTE sofia/external/03996597632298 at 203.208.207.212playback(/usr/local/freeswitch/sounds/clearhub/MusicForCalls_v1.wav)
2011-06-24 13:29:46.960900 [DEBUG] switch_core_file.c:176 File
/usr/local/freeswitch/sounds/clearhub/MusicForCalls_v1.wav sample rate 11025
doesn't match requested rate 8000
2011-06-24 13:29:46.960900 [WARNING] switch_core_file.c:189 File has 2
channels, muxing to mono will occur.
2011-06-24 13:29:46.960900 [DEBUG] switch_ivr_play_say.c:1244 Codec
Activated L16 at 8000hz 2 channels 20ms
2011-06-24 13:29:46.981203 [INFO] mod_com_g729.c:119 ENCODER CREATE -
0x2aaab80894b8 0x5112110
recv 774 bytes from udp/[203.208.207.212]:5060 at 05:29:48.623941:
   ------------------------------------------------------------------------
   SIP/2.0 183 Session Progress
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bKytFt9mX5HQNSj;received=10.1.1.46
   From: "" <sip:03996597632298 at 10.1.1.46>;tag=62eBXSt93tr7F
   To: <sip:03996563750911 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RV0KORLQK
   Call-ID: d0f42376-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110629 INVITE
   Contact: <sip:203.208.207.212:5060>
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, INFO, REFER, NOTIFY,
SUBSCRIBE, UPDATE
   Content-Type: application/sdp
   Require: 100rel
   RSeq: 1
   Content-Length:   231

   v=0
   o=- 508550174225779858 1 IN IP4 203.208.207.212
   s=session
   c=IN IP4 203.208.207.202
   t=0 0
   m=audio 25150 RTP/AVP 18 101
   a=rtpmap:18 G729/8000
   a=fmtp:18 annexb=no
   a=rtpmap:101 telephone-event/8000
   a=ptime:20
   a=sendrecv
   ------------------------------------------------------------------------
send 651 bytes to udp/[203.208.207.212]:5060 at 05:29:48.624297:
   ------------------------------------------------------------------------
   PRACK sip:203.208.207.212:5060 SIP/2.0
   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKZ38jBge9e0Bce
   Max-Forwards: 70
   From: "" <sip:03996597632298 at 202.73.56.46>;tag=62eBXSt93tr7F
   To: <sip:03996563750911 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RV0KORLQK
   Call-ID: d0f42376-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110630 PRACK
   Contact: <sip:mod_sofia at 202.73.56.46:5080>
   RAck: 1 14110629 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.0.7-hacked-20110603T012235Z
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO,
REGISTER, REFER, PRACK, NOTIFY
   Supported: 100rel, timer, precondition, path, replaces
   Content-Length: 0

   ------------------------------------------------------------------------
2011-06-24 13:29:48.115941 [INFO] sofia.c:729 sofia/external/
03996563750911 at 203.208.207.212 Update Callee ID to "Outbound Call"
<03996563750911>
2011-06-24 13:29:48.115941 [DEBUG] sofia.c:4646 Channel sofia/external/
03996563750911 at 203.208.207.212 entering state [proceeding][183]
2011-06-24 13:29:48.115941 [DEBUG] sofia.c:4657 Remote SDP:
v=0
o=- 508550174225779858 1 IN IP4 203.208.207.212
s=session
c=IN IP4 203.208.207.202
t=0 0
m=audio 25150 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=ptime:20

2011-06-24 13:29:48.115941 [DEBUG] sofia_glue.c:4467 Audio Codec Compare
[G729:18:8000:20:8000]/[G729:18:8000:20:8000]
2011-06-24 13:29:48.115941 [DEBUG] sofia_glue.c:2757 Set Codec
sofia/external/03996563750911 at 203.208.207.212 G729/8000 20 ms 160 samples
8000 bits
2011-06-24 13:29:48.115941 [DEBUG] sofia_glue.c:4565 Set 2833 dtmf send
payload to 101
2011-06-24 13:29:48.115941 [DEBUG] sofia_glue.c:2987 AUDIO RTP
[sofia/external/03996563750911 at 203.208.207.212] 10.1.1.46 port 20630 ->
203.208.207.202 port 25150 codec: 18 ms: 20
2011-06-24 13:29:48.115941 [DEBUG] switch_rtp.c:1607 Starting timer [soft]
160 bytes per 20ms
2011-06-24 13:29:48.119065 [DEBUG] sofia_glue.c:3228 Set 2833 dtmf send
payload to 101
2011-06-24 13:29:48.119065 [DEBUG] sofia_glue.c:3233 Set 2833 dtmf receive
payload to 101
2011-06-24 13:29:48.119065 [NOTICE] sofia_glue.c:3680 Pre-Answer
sofia/external/03996563750911 at 203.208.207.212!
2011-06-24 13:29:48.119065 [DEBUG] switch_channel.c:2627 (sofia/external/
03996563750911 at 203.208.207.212) Callstate Change RINGING -> EARLY
2011-06-24 13:29:48.120495 [DEBUG] switch_ivr_originate.c:3408 Originate
Resulted in Success: [sofia/external/03996563750911 at 203.208.207.212]
2011-06-24 13:29:48.120495 [DEBUG] mod_commands.c:3205 (sofia/external/
03996563750911 at 203.208.207.212) State Change CS_CONSUME_MEDIA -> CS_EXECUTE
2011-06-24 13:29:48.120495 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.120495 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996563750911 at 203.208.207.212) Running State Change
CS_EXECUTE
2011-06-24 13:29:48.120495 [DEBUG] switch_core_state_machine.c:366
(sofia/external/03996563750911 at 203.208.207.212) State EXECUTE
2011-06-24 13:29:48.120495 [DEBUG] mod_sofia.c:240 sofia/external/
03996563750911 at 203.208.207.212 SOFIA EXECUTE
2011-06-24 13:29:48.120495 [DEBUG] switch_core_state_machine.c:157
sofia/external/03996563750911 at 203.208.207.212 Standard EXECUTE
EXECUTE sofia/external/03996563750911 at 203.208.207.212 park()
2011-06-24 13:29:48.122782 [DEBUG] switch_core_session.c:954 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
recv 382 bytes from udp/[203.208.207.212]:5060 at 05:29:48.630447:
   ------------------------------------------------------------------------
   SIP/2.0 200 Ok
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bKZ38jBge9e0Bce;received=10.1.1.46
   From: "" <sip:03996597632298 at 10.1.1.46>;tag=62eBXSt93tr7F
   To: <sip:03996563750911 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RV0KORLQK
   Call-ID: d0f42376-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110630 PRACK
   Contact: <sip:203.208.207.212:5060>
   Content-Length:     0

   ------------------------------------------------------------------------
2011-06-24 13:29:48.122782 [DEBUG] switch_ivr.c:563 sofia/external/
03996597632298 at 203.208.207.212 Command Execute
playback(tone_stream://%(2000,4000,440,480);loops=10)
EXECUTE sofia/external/03996597632298 at 203.208.207.212playback(tone_stream://%(2000,4000,440,480);loops=10)
2011-06-24 13:29:48.124434 [DEBUG] switch_ivr_bridge.c:1480 (sofia/external/
03996597632298 at 203.208.207.212) State Change CS_EXECUTE -> CS_HIBERNATE
2011-06-24 13:29:48.124434 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.124434 [DEBUG] switch_ivr_bridge.c:1482 (sofia/external/
03996563750911 at 203.208.207.212) State Change CS_EXECUTE -> CS_HIBERNATE
2011-06-24 13:29:48.124434 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.124434 [DEBUG] switch_core_session.c:771 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.124434 [DEBUG] switch_core_session.c:771 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.124434 [DEBUG] switch_ivr_play_say.c:1244 Codec
Activated L16 at 8000hz 1 channels 20ms
2011-06-24 13:29:48.124434 [DEBUG] switch_ivr_play_say.c:1581 done playing
file
2011-06-24 13:29:48.124434 [DEBUG] switch_core_state_machine.c:366
(sofia/external/03996563750911 at 203.208.207.212) State EXECUTE going to sleep
2011-06-24 13:29:48.124434 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996563750911 at 203.208.207.212) Running State Change
CS_HIBERNATE
2011-06-24 13:29:48.124434 [DEBUG] switch_core_state_machine.c:381
(sofia/external/03996563750911 at 203.208.207.212) State HIBERNATE
2011-06-24 13:29:48.124434 [DEBUG] mod_sofia.c:221 sofia/external/
03996563750911 at 203.208.207.212 SOFIA HIBERNATE
2011-06-24 13:29:48.124434 [DEBUG] switch_ivr_bridge.c:731 (sofia/external/
03996563750911 at 203.208.207.212) State Change CS_HIBERNATE -> CS_RESET
2011-06-24 13:29:48.124434 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.124434 [DEBUG] switch_core_state_machine.c:381
(sofia/external/03996563750911 at 203.208.207.212) State HIBERNATE going to
sleep
2011-06-24 13:29:48.124434 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996563750911 at 203.208.207.212) Running State Change
CS_RESET
2011-06-24 13:29:48.124434 [DEBUG] switch_core_state_machine.c:362
(sofia/external/03996563750911 at 203.208.207.212) State RESET
2011-06-24 13:29:48.124434 [DEBUG] mod_sofia.c:165 sofia/external/
03996563750911 at 203.208.207.212 SOFIA RESET
2011-06-24 13:29:48.124434 [DEBUG] switch_ivr_bridge.c:716 sofia/external/
03996563750911 at 203.208.207.212 CUSTOM RESET
2011-06-24 13:29:48.124434 [DEBUG] switch_core_state_machine.c:66
sofia/external/03996563750911 at 203.208.207.212 Standard RESET
2011-06-24 13:29:48.124434 [DEBUG] switch_core_state_machine.c:362
(sofia/external/03996563750911 at 203.208.207.212) State RESET going to sleep
2011-06-24 13:29:48.126015 [DEBUG] switch_core_session.c:709 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.142264 [DEBUG] switch_ivr_play_say.c:1581 done playing
file
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:366
(sofia/external/03996597632298 at 203.208.207.212) State EXECUTE going to sleep
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996597632298 at 203.208.207.212) Running State Change
CS_HIBERNATE
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:381
(sofia/external/03996597632298 at 203.208.207.212) State HIBERNATE
2011-06-24 13:29:48.142264 [DEBUG] mod_sofia.c:221 sofia/external/
03996597632298 at 203.208.207.212 SOFIA HIBERNATE
2011-06-24 13:29:48.142264 [DEBUG] switch_ivr_bridge.c:731 (sofia/external/
03996597632298 at 203.208.207.212) State Change CS_HIBERNATE -> CS_RESET
2011-06-24 13:29:48.142264 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:381
(sofia/external/03996597632298 at 203.208.207.212) State HIBERNATE going to
sleep
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996597632298 at 203.208.207.212) Running State Change
CS_RESET
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:362
(sofia/external/03996597632298 at 203.208.207.212) State RESET
2011-06-24 13:29:48.142264 [DEBUG] mod_sofia.c:165 sofia/external/
03996597632298 at 203.208.207.212 SOFIA RESET
2011-06-24 13:29:48.142264 [DEBUG] switch_ivr_bridge.c:716 sofia/external/
03996597632298 at 203.208.207.212 CUSTOM RESET
2011-06-24 13:29:48.142264 [DEBUG] switch_ivr_bridge.c:723 (sofia/external/
03996597632298 at 203.208.207.212) State Change CS_RESET -> CS_SOFT_EXECUTE
2011-06-24 13:29:48.142264 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:362
(sofia/external/03996597632298 at 203.208.207.212) State RESET going to sleep
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996597632298 at 203.208.207.212) Running State Change
CS_SOFT_EXECUTE
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:372
(sofia/external/03996597632298 at 203.208.207.212) State SOFT_EXECUTE
2011-06-24 13:29:48.142264 [DEBUG] mod_sofia.c:558 SOFIA SOFT_EXECUTE
2011-06-24 13:29:48.142264 [DEBUG] switch_ivr_bridge.c:741 sofia/external/
03996597632298 at 203.208.207.212 CUSTOM SOFT_EXECUTE
2011-06-24 13:29:48.142264 [DEBUG] switch_ivr_bridge.c:761 (sofia/external/
03996563750911 at 203.208.207.212) State Change CS_RESET -> CS_SOFT_EXECUTE
2011-06-24 13:29:48.142264 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996563750911 at 203.208.207.212) Running State Change
CS_SOFT_EXECUTE
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:372
(sofia/external/03996563750911 at 203.208.207.212) State SOFT_EXECUTE
2011-06-24 13:29:48.142264 [DEBUG] mod_sofia.c:558 SOFIA SOFT_EXECUTE
2011-06-24 13:29:48.142264 [DEBUG] switch_ivr_bridge.c:741 sofia/external/
03996563750911 at 203.208.207.212 CUSTOM SOFT_EXECUTE
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:204
sofia/external/03996563750911 at 203.208.207.212 Standard SOFT_EXECUTE
2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:372
(sofia/external/03996563750911 at 203.208.207.212) State SOFT_EXECUTE going to
sleep
2011-06-24 13:29:48.161779 [DEBUG] switch_channel.c:2535 (sofia/external/
03996563750911 at 203.208.207.212) Callstate Change EARLY -> HANGUP
2011-06-24 13:29:48.161779 [NOTICE] switch_ivr_originate.c:1045 Hangup
sofia/external/03996563750911 at 203.208.207.212 [CS_SOFT_EXECUTE]
[DESTINATION_OUT_OF_ORDER]
2011-06-24 13:29:48.161779 [DEBUG] switch_channel.c:2551 Send signal
sofia/external/03996563750911 at 203.208.207.212 [KILL]
2011-06-24 13:29:48.161779 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996563750911 at 203.208.207.212) Running State Change
CS_HANGUP
2011-06-24 13:29:48.161779 [DEBUG] switch_channel.c:2535 (sofia/external/
03996597632298 at 203.208.207.212) Callstate Change ACTIVE -> HANGUP
2011-06-24 13:29:48.161779 [NOTICE] switch_ivr_bridge.c:772 Hangup
sofia/external/03996597632298 at 203.208.207.212 [CS_SOFT_EXECUTE]
[ORIGINATOR_CANCEL]
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:557
(sofia/external/03996563750911 at 203.208.207.212) State HANGUP
2011-06-24 13:29:48.161779 [DEBUG] mod_sofia.c:457 Channel sofia/external/
03996563750911 at 203.208.207.212 hanging up, cause: DESTINATION_OUT_OF_ORDER
2011-06-24 13:29:48.161779 [DEBUG] mod_sofia.c:510 Sending CANCEL to
sofia/external/03996563750911 at 203.208.207.212
2011-06-24 13:29:48.161779 [DEBUG] switch_channel.c:2551 Send signal
sofia/external/03996597632298 at 203.208.207.212 [KILL]
2011-06-24 13:29:48.161779 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:372
(sofia/external/03996597632298 at 203.208.207.212) State SOFT_EXECUTE going to
sleep
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996597632298 at 203.208.207.212) Running State Change
CS_HANGUP
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:46
sofia/external/03996563750911 at 203.208.207.212 Standard HANGUP, cause:
DESTINATION_OUT_OF_ORDER
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:557
(sofia/external/03996563750911 at 203.208.207.212) State HANGUP going to sleep
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:351
(sofia/external/03996563750911 at 203.208.207.212) State Change CS_HANGUP ->
CS_REPORTING
2011-06-24 13:29:48.161779 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996563750911 at 203.208.207.212) Running State Change
CS_REPORTING
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:617
(sofia/external/03996563750911 at 203.208.207.212) State REPORTING
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:53
sofia/external/03996563750911 at 203.208.207.212 Standard REPORTING, cause:
DESTINATION_OUT_OF_ORDER
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:617
(sofia/external/03996563750911 at 203.208.207.212) State REPORTING going to
sleep
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:557
(sofia/external/03996597632298 at 203.208.207.212) State HANGUP
2011-06-24 13:29:48.161779 [DEBUG] mod_sofia.c:457 Channel sofia/external/
03996597632298 at 203.208.207.212 hanging up, cause: ORIGINATOR_CANCEL
2011-06-24 13:29:48.161779 [DEBUG] mod_sofia.c:500 Sending BYE to
sofia/external/03996597632298 at 203.208.207.212
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:345
(sofia/external/03996563750911 at 203.208.207.212) State Change CS_REPORTING ->
CS_DESTROY
2011-06-24 13:29:48.161779 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996563750911 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.161779 [DEBUG] switch_core_session.c:1288 Session 52
(sofia/external/03996563750911 at 203.208.207.212) Locked, Waiting on external
entities
2011-06-24 13:29:48.161779 [NOTICE] switch_core_session.c:1306 Session 52
(sofia/external/03996563750911 at 203.208.207.212) Ended
2011-06-24 13:29:48.161779 [NOTICE] switch_core_session.c:1308 Close Channel
sofia/external/03996563750911 at 203.208.207.212 [CS_DESTROY]
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:449
(sofia/external/03996563750911 at 203.208.207.212) Callstate Change HANGUP ->
DOWN
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:452
(sofia/external/03996563750911 at 203.208.207.212) Running State Change
CS_DESTROY
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:462
(sofia/external/03996563750911 at 203.208.207.212) State DESTROY
2011-06-24 13:29:48.161779 [DEBUG] mod_sofia.c:362 sofia/external/
03996563750911 at 203.208.207.212 SOFIA DESTROY
2011-06-24 13:29:48.161779 [INFO] mod_com_g729.c:78 ENCODER DESTROYX -
0x2aaaac03fff8 (nil)
2011-06-24 13:29:48.161779 [INFO] mod_com_g729.c:79 DECODER DESTROYX -
0x2aaaac03fff8 (nil)
2011-06-24 13:29:48.161779 [INFO] mod_com_g729.c:78 ENCODER DESTROYX -
0x2aaaac068fc8 (nil)
2011-06-24 13:29:48.161779 [INFO] mod_com_g729.c:79 DECODER DESTROYX -
0x2aaaac068fc8 (nil)
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:46
sofia/external/03996597632298 at 203.208.207.212 Standard HANGUP, cause:
ORIGINATOR_CANCEL
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:60
sofia/external/03996563750911 at 203.208.207.212 Standard DESTROY
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:557
(sofia/external/03996597632298 at 203.208.207.212) State HANGUP going to sleep
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:462
(sofia/external/03996563750911 at 203.208.207.212) State DESTROY going to sleep
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:351
(sofia/external/03996597632298 at 203.208.207.212) State Change CS_HANGUP ->
CS_REPORTING
2011-06-24 13:29:48.161779 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:320
(sofia/external/03996597632298 at 203.208.207.212) Running State Change
CS_REPORTING
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:617
(sofia/external/03996597632298 at 203.208.207.212) State REPORTING
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:53
sofia/external/03996597632298 at 203.208.207.212 Standard REPORTING, cause:
ORIGINATOR_CANCEL
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:617
(sofia/external/03996597632298 at 203.208.207.212) State REPORTING going to
sleep
send 390 bytes to udp/[203.208.207.212]:5060 at 05:29:48.671783:
   ------------------------------------------------------------------------
   CANCEL sip:03996563750911 at 203.208.207.212 SIP/2.0
   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKytFt9mX5HQNSj
   Max-Forwards: 70
   From: "" <sip:03996597632298 at 202.73.56.46>;tag=62eBXSt93tr7F
   To: <sip:03996563750911 at 203.208.207.212>
   Call-ID: d0f42376-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110629 CANCEL
   Reason: Q.850;cause=27;text="DESTINATION_OUT_OF_ORDER"
   Content-Length: 0

   ------------------------------------------------------------------------
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:345
(sofia/external/03996597632298 at 203.208.207.212) State Change CS_REPORTING ->
CS_DESTROY
2011-06-24 13:29:48.161779 [DEBUG] switch_core_session.c:1116 Send signal
sofia/external/03996597632298 at 203.208.207.212 [BREAK]
2011-06-24 13:29:48.161779 [DEBUG] switch_core_session.c:1288 Session 51
(sofia/external/03996597632298 at 203.208.207.212) Locked, Waiting on external
entities
2011-06-24 13:29:48.161779 [NOTICE] switch_core_session.c:1306 Session 51
(sofia/external/03996597632298 at 203.208.207.212) Ended
2011-06-24 13:29:48.161779 [NOTICE] switch_core_session.c:1308 Close Channel
sofia/external/03996597632298 at 203.208.207.212 [CS_DESTROY]
send 677 bytes to udp/[203.208.207.212]:5060 at 05:29:48.671936:
   ------------------------------------------------------------------------
   BYE sip:203.208.207.212:5060 SIP/2.0
   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bK0c2BDBZcc91yS
   Max-Forwards: 70
   From: "" <sip:03996563750911 at 202.73.56.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RX0S6R1TX
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110627 BYE
   Contact: <sip:mod_sofia at 202.73.56.46:5080>
   User-Agent: FreeSWITCH-mod_sofia/1.0.7-hacked-20110603T012235Z
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO,
REGISTER, REFER, PRACK, NOTIFY
   Supported: 100rel, timer, precondition, path, replaces
   Reason: FreeSWITCH;cause=487;text="ORIGINATOR_CANCEL"
   Content-Length: 0

   ------------------------------------------------------------------------
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:449
(sofia/external/03996597632298 at 203.208.207.212) Callstate Change HANGUP ->
DOWN
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:452
(sofia/external/03996597632298 at 203.208.207.212) Running State Change
CS_DESTROY
2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:462
(sofia/external/03996597632298 at 203.208.207.212) State DESTROY
2011-06-24 13:29:48.161779 [DEBUG] mod_sofia.c:362 sofia/external/
03996597632298 at 203.208.207.212 SOFIA DESTROY
2011-06-24 13:29:48.161779 [INFO] mod_com_g729.c:78 ENCODER DESTROYX -
0x2aaab8030878 (nil)
2011-06-24 13:29:48.161779 [INFO] mod_com_g729.c:79 DECODER DESTROYX -
0x2aaab8030878 (nil)
2011-06-24 13:29:48.161779 [INFO] mod_com_g729.c:78 ENCODER DESTROYX -
0x2aaab80894b8 0x5112110
2011-06-24 13:29:48.161779 [INFO] mod_com_g729.c:79 DECODER DESTROYX -
0x2aaab80894b8 (nil)
2011-06-24 13:29:48.166430 [INFO] mod_com_g729.c:83 ENCODER DESTROY -
0x2aaab80894b8 0x5112110
2011-06-24 13:29:48.166430 [DEBUG] switch_core_state_machine.c:60
sofia/external/03996597632298 at 203.208.207.212 Standard DESTROY
2011-06-24 13:29:48.166430 [DEBUG] switch_core_state_machine.c:462
(sofia/external/03996597632298 at 203.208.207.212) State DESTROY going to sleep
recv 383 bytes from udp/[203.208.207.212]:5060 at 05:29:48.679561:
   ------------------------------------------------------------------------
   SIP/2.0 200 Ok
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bKytFt9mX5HQNSj;received=10.1.1.46
   From: "" <sip:03996597632298 at 10.1.1.46>;tag=62eBXSt93tr7F
   To: <sip:03996563750911 at 203.208.207.212
>;tag=2QGB951HCR30000E1D00000u000000013MCNME
   Call-ID: d0f42376-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110629 CANCEL
   Contact: <sip:203.208.207.212:5060>
   Content-Length:     0

   ------------------------------------------------------------------------
recv 731 bytes from udp/[203.208.207.212]:5060 at 05:29:48.681395:
   ------------------------------------------------------------------------
   UPDATE sip:mod_sofia at 10.1.1.46:5080 SIP/2.0
   Via: SIP/2.0/UDP 203.208.207.212:5060
;branch=z9hG4bK00151746C47A8307FCE25ED9D752
   From: <sip:03996563750911 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RV0KORLQK
   To: "" <sip:03996597632298 at 10.1.1.46>;tag=62eBXSt93tr7F
   Call-ID: d0f42376-18c5-122f-3387-0015c5fc7ad9
   CSeq: 46496 UPDATE
   Contact: <sip:03996563750911 at 203.208.207.212:5060>
   Content-Type: application/sdp
   Max-Forwards: 70
   Supported: 100rel, timer, replaces
   Content-Length:   231

   v=0
   o=- 508550174225779858 2 IN IP4 203.208.207.212
   s=session
   c=IN IP4 203.208.207.202
   t=0 0
   m=audio 25150 RTP/AVP 18 101
   a=rtpmap:18 G729/8000
   a=fmtp:18 annexb=no
   a=rtpmap:101 telephone-event/8000
   a=ptime:20
   a=inactive
   ------------------------------------------------------------------------
send 895 bytes to udp/[203.208.207.212]:5060 at 05:29:48.681661:
   ------------------------------------------------------------------------
   SIP/2.0 200 OK
   Via: SIP/2.0/UDP 203.208.207.212:5060
;branch=z9hG4bK00151746C47A8307FCE25ED9D752
   From: <sip:03996563750911 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RV0KORLQK
   To: "" <sip:03996597632298 at 10.1.1.46>;tag=62eBXSt93tr7F
   Call-ID: d0f42376-18c5-122f-3387-0015c5fc7ad9
   CSeq: 46496 UPDATE
   Contact: <sip:mod_sofia at 202.73.56.46:5080>
   User-Agent: FreeSWITCH-mod_sofia/1.0.7-hacked-20110603T012235Z
   Accept: application/sdp
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO,
REGISTER, REFER, PRACK, NOTIFY
   Supported: 100rel, timer, precondition, path, replaces
   Content-Type: application/sdp
   Content-Disposition: session
   Content-Length: 216

   v=0
   o=FreeSWITCH 1308872756 1308872758 IN IP4 202.73.56.46
   s=FreeSWITCH
   c=IN IP4 202.73.56.46
   t=0 0
   m=audio 20630 RTP/AVP 18 101 3 13
   a=rtpmap:101 telephone-event/8000
   a=fmtp:101 0-16
   a=inactive
   a=ptime:20
   ------------------------------------------------------------------------
recv 411 bytes from udp/[203.208.207.212]:5060 at 05:29:48.681824:
   ------------------------------------------------------------------------
   SIP/2.0 487 Request Terminated
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bKytFt9mX5HQNSj;received=10.1.1.46
   From: "" <sip:03996597632298 at 10.1.1.46>;tag=62eBXSt93tr7F
   To: <sip:03996563750911 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RV0KORLQK
   Call-ID: d0f42376-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110629 INVITE
   Reason: SIP;cause=487;text="Request Terminated"
   Content-Length:     0

   ------------------------------------------------------------------------
send 371 bytes to udp/[203.208.207.212]:5060 at 05:29:48.681913:
   ------------------------------------------------------------------------
   ACK sip:03996563750911 at 203.208.207.212 SIP/2.0
   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKytFt9mX5HQNSj
   Max-Forwards: 70
   From: "" <sip:03996597632298 at 202.73.56.46>;tag=62eBXSt93tr7F
   To: <sip:03996563750911 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RV0KORLQK
   Call-ID: d0f42376-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110629 ACK
   Content-Length: 0

   ------------------------------------------------------------------------
recv 380 bytes from udp/[203.208.207.212]:5060 at 05:29:48.683041:
   ------------------------------------------------------------------------
   SIP/2.0 200 Ok
   Via: SIP/2.0/UDP 10.1.1.46:5080
;rport=5080;branch=z9hG4bK0c2BDBZcc91yS;received=10.1.1.46
   From: "" <sip:03996563750911 at 10.1.1.46>;tag=5SNjUy956H2mm
   To: <sip:03996597632298 at 203.208.207.212
>;tag=2QGB951HCR30000E1D0001Ll000B8RX0S6R1TX
   Call-ID: ca5d29b7-18c5-122f-3387-0015c5fc7ad9
   CSeq: 14110627 BYE
   Contact: <sip:203.208.207.212:5060>
   Content-Length:     0

   ------------------------------------------------------------------------
2011-06-24 13:29:48.524051 [DEBUG] switch_scheduler.c:138 Deleting task 27
switch_ivr_schedule_hangup (c0bd700d-913c-42ad-b68f-81001bf658b8)






On Fri, Jun 24, 2011 at 2:41 PM, Michael Collins <msc at freeswitch.org> wrote:

> Pastebin the entire debug log, including the siptrace. Also include the
> originate line and any other dialplan config that might be used.
> -MC
>
>
> On Thu, Jun 23, 2011 at 11:26 PM, David Ma <mays.david at gmail.com> wrote:
>
>> Hi Michael,
>>
>> Unfortunately this problem still happens.
>>
>> I enabled "continue_on_fail" for leg-A when I originated the call. Leg-A
>> call went well. Then I originated leg-B call ("continue_on_fail" is NOT set
>> for leg-B), which failed for [DESTINATION_OUT_OF_ORDER]. As the consequence,
>> leg-A was hung up by FS automatically for [ORIGINATOR_CANCEL].
>>
>> The log excerpt follows.
>>
>> Do you think "continue_on_fail" should be also enabled for leg-B call?
>>
>> Thanks,
>> D.Ma
>>
>> 2011-06-24 13:29:35.887830 [DEBUG] switch_ivr_originate.c:1971 variable
>> string 5 = [continue_on_fail=true]
>>
>> 2011-06-24 13:29:35.887830 [NOTICE] switch_channel.c:808 New Channel
>> sofia/external/03996597632298 at 203.208.207.212[c0bd700d-913c-42ad-b68f-81001bf658b8]
>> [...]
>> 2011-06-24 13:29:48.142264 [DEBUG] switch_core_state_machine.c:372
>> (sofia/external/03996563750911 at 203.208.207.212) State SOFT_EXECUTE going
>> to sleep
>> 2011-06-24 13:29:48.161779 [DEBUG] switch_channel.c:2535 (sofia/external/
>> 03996563750911 at 203.208.207.212) Callstate Change EARLY -> HANGUP
>> 2011-06-24 13:29:48.161779 [NOTICE] switch_ivr_originate.c:1045 Hangup
>> sofia/external/03996563750911 at 203.208.207.212 [CS_SOFT_EXECUTE]
>> [DESTINATION_OUT_OF_ORDER]
>> 2011-06-24 13:29:48.161779 [DEBUG] switch_channel.c:2551 Send signal
>> sofia/external/03996563750911 at 203.208.207.212 [KILL]
>> 2011-06-24 13:29:48.161779 [DEBUG] switch_core_session.c:1116 Send signal
>> sofia/external/03996563750911 at 203.208.207.212 [BREAK]
>> 2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:320
>> (sofia/external/03996563750911 at 203.208.207.212) Running State Change
>> CS_HANGUP
>> 2011-06-24 13:29:48.161779 [DEBUG] switch_channel.c:2535 (sofia/external/
>> 03996597632298 at 203.208.207.212) Callstate Change ACTIVE -> HANGUP
>> 2011-06-24 13:29:48.161779 [NOTICE] switch_ivr_bridge.c:772 Hangup
>> sofia/external/03996597632298 at 203.208.207.212 [CS_SOFT_EXECUTE]
>> [ORIGINATOR_CANCEL]
>> 2011-06-24 13:29:48.161779 [DEBUG] switch_core_state_machine.c:557
>> (sofia/external/03996563750911 at 203.208.207.212) State HANGUP
>> 2011-06-24 13:29:48.161779 [DEBUG] mod_sofia.c:457 Channel sofia/external/
>> 03996563750911 at 203.208.207.212 hanging up, cause:
>> DESTINATION_OUT_OF_ORDER
>> 2011-06-24 13:29:48.161779 [DEBUG] mod_sofia.c:510 Sending CANCEL to
>> sofia/external/03996563750911 at 203.208.207.212
>> 2011-06-24 13:29:48.161779 [DEBUG] switch_channel.c:2551 Send signal
>> sofia/external/03996597632298 at 203.208.207.212 [KILL]
>> 2011-06-24 13:29:48.161779 [DEBUG] switch_core_session.c:1116 Send signal
>> sofia/external/03996597632298 at 203.208.207.212 [BREAK]
>>
>> On Fri, Jun 17, 2011 at 10:52 AM, David Ma <mays.david at gmail.com> wrote:
>>
>>> Hi Michael,
>>>
>>> Thanks very much for your prompt response! I appreciate the information
>>> provided.
>>>
>>> I was actually searching the the existence of such a variable. I was not
>>> so luck to find it out and thereby resort to the support forum.
>>>
>>> I've modified my code to build this parameter into my application. Will
>>> feedback to you after verification.
>>>
>>> Thanks again,
>>> D.Ma
>>>
>>> On Fri, Jun 17, 2011 at 4:51 AM, Michael Collins <msc at freeswitch.org>wrote:
>>>
>>>> How about setting this?
>>>> http://wiki.freeswitch.org/wiki/Channel_Variables#continue_on_fail
>>>>
>>>> -MC
>>>>
>>>>
>>>> On Thu, Jun 16, 2011 at 1:32 AM, dma <mays.david at gmail.com> wrote:
>>>>
>>>>> I am creating a call-back solution. After leg-A answers, I originate
>>>>> leg-B
>>>>> call. After receiving SIP 183 from Leg-B, I bridge the 2 legs. However,
>>>>> in
>>>>> some cases, leg-A is automatically disconnected by FreeSwitch on leg-B
>>>>> failure, for example, DESTINATION_OUT_OF_ORDER. The application is not
>>>>> given
>>>>> a chance to handle leg-B failure event. This should not be a correct
>>>>> scenario because I never set "hangup-after-bridge", which is false by
>>>>> default.
>>>>>
>>>>> The right way should be, FreeSwitch doesn't hang up leg-A
>>>>> automatically, but
>>>>> give a chance for the application to decide what to do.
>>>>>
>>>>> Please see the logs below:
>>>>>
>>>>> =================================================
>>>>>
>>>>> 2011-06-10 11:09:55.370506 [DEBUG] switch_ivr_originate.c:1971 variable
>>>>> string 0 = [origination_caller_id_number=03996563750914]
>>>>> 2011-06-10 11:09:55.370506 [DEBUG] switch_ivr_originate.c:1971 variable
>>>>> string 1 = [originate_timeout=30]
>>>>> 2011-06-10 11:09:55.370506 [DEBUG] switch_ivr_originate.c:1971 variable
>>>>> string 2 = [ccd_session_id=20110610105829676824]
>>>>> 2011-06-10 11:09:55.370506 [DEBUG] switch_ivr_originate.c:1971 variable
>>>>> string 3 = [sip_cid_type=pid]
>>>>> 2011-06-10 11:09:55.370506 [DEBUG] switch_ivr_originate.c:1971 variable
>>>>> string 4 = [privacy=yes]
>>>>> 2011-06-10 11:09:55.370506 [NOTICE] switch_channel.c:808 New Channel
>>>>> sofia/external/03996590031055 at 203.208.207.212
>>>>> [ea57b74b-a8c2-4fea-9683-98054dc03a79]
>>>>> 2011-06-10 11:09:55.370506 [DEBUG] mod_sofia.c:4129
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State Change CS_NEW ->
>>>>> CS_INIT
>>>>> 2011-06-10 11:09:55.370506 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:09:55.370506 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Running State Change
>>>>> CS_INIT
>>>>> 2011-06-10 11:09:55.370506 [DEBUG] switch_core_state_machine.c:356
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State INIT
>>>>> 2011-06-10 11:09:55.370506 [DEBUG] mod_sofia.c:84
>>>>> sofia/external/03996590031055 at 203.208.207.212 SOFIA INIT
>>>>> send 984 bytes to udp/[203.208.207.212]:5060 at 03:09:55.477997:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   INVITE sip:03996590031055 at 203.208.207.212 SIP/2.0
>>>>>   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKXjQ7eFpKypy5D
>>>>>   Max-Forwards: 70
>>>>>   From: "" &lt;sip:03996563750914 at 202.73.56.46&gt;;tag=H4ZN43UH9S9Qc
>>>>>   To: &lt;sip:03996590031055 at 203.208.207.212&gt;
>>>>>   Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501633 INVITE
>>>>>   Contact: &lt;sip:mod_sofia at 202.73.56.46:5080&gt;
>>>>>   User-Agent: FreeSWITCH-mod_sofia/1.0.7-hacked-20110603T012235Z
>>>>>   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO,
>>>>> REGISTER, REFER, NOTIFY
>>>>>   Supported: timer, precondition, path, replaces
>>>>>   Allow-Events: talk, hold, refer
>>>>>   Privacy: none
>>>>>   Content-Type: application/sdp
>>>>>   Content-Disposition: session
>>>>>   Content-Length: 204
>>>>>   X-FS-Support: update_display
>>>>>   P-Asserted-Identity: "" &lt;sip:03996563750914 at 202.73.56.46&gt;
>>>>>
>>>>>   v=0
>>>>>   o=FreeSWITCH 1307645395 1307645396 IN IP4 202.73.56.46
>>>>>   s=FreeSWITCH
>>>>>   c=IN IP4 202.73.56.46
>>>>>   t=0 0
>>>>>   m=audio 30000 RTP/AVP 18 3 101 13
>>>>>   a=rtpmap:101 telephone-event/8000
>>>>>   a=fmtp:101 0-16
>>>>>   a=ptime:20
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:09:55.371674 [DEBUG] mod_sofia.c:124
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State Change CS_INIT
>>>>> ->
>>>>> CS_ROUTING
>>>>> 2011-06-10 11:09:55.371674 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:09:55.371674 [DEBUG] sofia.c:4646 Channel
>>>>> sofia/external/03996590031055 at 203.208.207.212 entering state
>>>>> [calling][0]
>>>>> 2011-06-10 11:09:55.373478 [DEBUG] switch_core_state_machine.c:356
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State INIT going to
>>>>> sleep
>>>>> 2011-06-10 11:09:55.373478 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Running State Change
>>>>> CS_ROUTING
>>>>> 2011-06-10 11:09:55.373478 [DEBUG] switch_channel.c:1657
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Callstate Change DOWN
>>>>> ->
>>>>> RINGING
>>>>> 2011-06-10 11:09:55.373478 [DEBUG] switch_core_state_machine.c:359
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State ROUTING
>>>>> 2011-06-10 11:09:55.373478 [DEBUG] mod_sofia.c:147
>>>>> sofia/external/03996590031055 at 203.208.207.212 SOFIA ROUTING
>>>>> 2011-06-10 11:09:55.373478 [DEBUG] switch_ivr_originate.c:66
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State Change
>>>>> CS_ROUTING ->
>>>>> CS_CONSUME_MEDIA
>>>>> 2011-06-10 11:09:55.373478 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:09:55.373478 [DEBUG] switch_core_state_machine.c:359
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State ROUTING going to
>>>>> sleep
>>>>> 2011-06-10 11:09:55.373478 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Running State Change
>>>>> CS_CONSUME_MEDIA
>>>>> 2011-06-10 11:09:55.374485 [DEBUG] switch_core_state_machine.c:378
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State CONSUME_MEDIA
>>>>> 2011-06-10 11:09:55.374485 [DEBUG] switch_core_state_machine.c:378
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State CONSUME_MEDIA
>>>>> going to
>>>>> sleep
>>>>> recv 307 bytes from udp/[203.208.207.212]:5060 at 03:09:55.485130:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   SIP/2.0 100 Trying
>>>>>   Via: SIP/2.0/UDP
>>>>> 10.1.1.46:5080
>>>>> ;rport=5080;branch=z9hG4bKXjQ7eFpKypy5D;received=10.1.1.46
>>>>>   From: "" &lt;sip:03996563750914 at 10.1.1.46&gt;;tag=H4ZN43UH9S9Qc
>>>>>   To: &lt;sip:03996590031055 at 203.208.207.212&gt;
>>>>>   Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501633 INVITE
>>>>>   Content-Length:     0
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> recv 669 bytes from udp/[203.208.207.212]:5060 at 03:09:56.677788:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   SIP/2.0 183 Session Progress
>>>>>   Via: SIP/2.0/UDP
>>>>> 10.1.1.46:5080
>>>>> ;rport=5080;branch=z9hG4bKXjQ7eFpKypy5D;received=10.1.1.46
>>>>>   From: "" &lt;sip:03996563750914 at 10.1.1.46&gt;;tag=H4ZN43UH9S9Qc
>>>>>   To:
>>>>> &lt;sip:03996590031055 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D0001Ll0008FJ21EI9PBW
>>>>>   Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501633 INVITE
>>>>>   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, INFO, REFER, NOTIFY,
>>>>> SUBSCRIBE, UPDATE
>>>>>   Content-Type: application/sdp
>>>>>   Content-Length:   189
>>>>>
>>>>>   v=0
>>>>>   o=- 421265648 1 IN IP4 203.208.207.219
>>>>>   s=session
>>>>>   c=IN IP4 203.208.207.196
>>>>>   t=0 0
>>>>>   m=audio 30792 RTP/AVP 18 101
>>>>>   a=rtpmap:18 G729/8000
>>>>>   a=rtpmap:101 telephone-event/8000
>>>>>   a=sendrecv
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:09:56.571839 [INFO] sofia.c:729
>>>>> sofia/external/03996590031055 at 203.208.207.212 Update Callee ID to
>>>>> "Outbound
>>>>> Call" <03996590031055>
>>>>> 2011-06-10 11:09:56.571839 [DEBUG] sofia.c:4646 Channel
>>>>> sofia/external/03996590031055 at 203.208.207.212 entering state
>>>>> [proceeding][183]
>>>>> 2011-06-10 11:09:56.571839 [DEBUG] sofia.c:4657 Remote SDP:
>>>>> v=0
>>>>> o=- 421265648 1 IN IP4 203.208.207.219
>>>>> s=session
>>>>> c=IN IP4 203.208.207.196
>>>>> t=0 0
>>>>> m=audio 30792 RTP/AVP 18 101
>>>>> a=rtpmap:18 G729/8000
>>>>> a=rtpmap:101 telephone-event/8000
>>>>>
>>>>> 2011-06-10 11:09:56.571839 [DEBUG] sofia_glue.c:4467 Audio Codec
>>>>> Compare
>>>>> [G729:18:8000:20:8000]/[G729:18:8000:20:8000]
>>>>> 2011-06-10 11:09:56.571839 [DEBUG] sofia_glue.c:2757 Set Codec
>>>>> sofia/external/03996590031055 at 203.208.207.212 G729/8000 20 ms 160
>>>>> samples
>>>>> 8000 bits
>>>>> 2011-06-10 11:09:56.571839 [DEBUG] sofia_glue.c:4565 Set 2833 dtmf send
>>>>> payload to 101
>>>>> 2011-06-10 11:09:56.571839 [DEBUG] sofia_glue.c:2987 AUDIO RTP
>>>>> [sofia/external/03996590031055 at 203.208.207.212] 10.1.1.46 port 30000
>>>>> ->
>>>>> 203.208.207.196 port 30792 codec: 18 ms: 20
>>>>> 2011-06-10 11:09:56.571839 [DEBUG] switch_rtp.c:1607 Starting timer
>>>>> [soft]
>>>>> 160 bytes per 20ms
>>>>> 2011-06-10 11:09:56.573731 [DEBUG] sofia_glue.c:3228 Set 2833 dtmf send
>>>>> payload to 101
>>>>> 2011-06-10 11:09:56.573731 [DEBUG] sofia_glue.c:3233 Set 2833 dtmf
>>>>> receive
>>>>> payload to 101
>>>>> 2011-06-10 11:09:56.573731 [NOTICE] sofia_glue.c:3680 Pre-Answer
>>>>> sofia/external/03996590031055 at 203.208.207.212!
>>>>> 2011-06-10 11:09:56.573731 [DEBUG] switch_channel.c:2627
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Callstate Change
>>>>> RINGING ->
>>>>> EARLY
>>>>> 2011-06-10 11:09:56.573731 [DEBUG] switch_ivr_originate.c:3408
>>>>> Originate
>>>>> Resulted in Success: [sofia/external/03996590031055 at 203.208.207.212]
>>>>> 2011-06-10 11:09:56.573731 [DEBUG] mod_commands.c:3205
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State Change
>>>>> CS_CONSUME_MEDIA -> CS_EXECUTE
>>>>> 2011-06-10 11:09:56.573731 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:09:56.575262 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Running State Change
>>>>> CS_EXECUTE
>>>>> 2011-06-10 11:09:56.575262 [DEBUG] switch_core_state_machine.c:366
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State EXECUTE
>>>>> 2011-06-10 11:09:56.575262 [DEBUG] mod_sofia.c:240
>>>>> sofia/external/03996590031055 at 203.208.207.212 SOFIA EXECUTE
>>>>> 2011-06-10 11:09:56.575262 [DEBUG] switch_core_state_machine.c:157
>>>>> sofia/external/03996590031055 at 203.208.207.212 Standard EXECUTE
>>>>> EXECUTE sofia/external/03996590031055 at 203.208.207.212 park()
>>>>> 2011-06-10 11:09:56.618770 [DEBUG] switch_rtp.c:2933 Correct ip/port
>>>>> confirmed.
>>>>> recv 669 bytes from udp/[203.208.207.212]:5060 at 03:10:01.562021:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   SIP/2.0 183 Session Progress
>>>>>   Via: SIP/2.0/UDP
>>>>> 10.1.1.46:5080
>>>>> ;rport=5080;branch=z9hG4bKXjQ7eFpKypy5D;received=10.1.1.46
>>>>>   From: "" &lt;sip:03996563750914 at 10.1.1.46&gt;;tag=H4ZN43UH9S9Qc
>>>>>   To:
>>>>> &lt;sip:03996590031055 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D0001Ll0008FJ21EI9PBW
>>>>>   Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501633 INVITE
>>>>>   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, INFO, REFER, NOTIFY,
>>>>> SUBSCRIBE, UPDATE
>>>>>   Content-Type: application/sdp
>>>>>   Content-Length:   189
>>>>>
>>>>>   v=0
>>>>>   o=- 421265648 2 IN IP4 203.208.207.219
>>>>>   s=session
>>>>>   c=IN IP4 203.208.207.196
>>>>>   t=0 0
>>>>>   m=audio 30792 RTP/AVP 18 101
>>>>>   a=rtpmap:18 G729/8000
>>>>>   a=rtpmap:101 telephone-event/8000
>>>>>   a=sendrecv
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:10:01.455944 [INFO] sofia.c:729
>>>>> sofia/external/03996590031055 at 203.208.207.212 Update Callee ID to
>>>>> "03996590031055" <03996590031055>
>>>>> 2011-06-10 11:10:01.455944 [DEBUG] sofia.c:4641 Channel
>>>>> sofia/external/03996590031055 at 203.208.207.212 skipping state
>>>>> [proceeding][183]
>>>>> recv 669 bytes from udp/[203.208.207.212]:5060 at 03:10:01.563178:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   SIP/2.0 183 Session Progress
>>>>>   Via: SIP/2.0/UDP
>>>>> 10.1.1.46:5080
>>>>> ;rport=5080;branch=z9hG4bKXjQ7eFpKypy5D;received=10.1.1.46
>>>>>   From: "" &lt;sip:03996563750914 at 10.1.1.46&gt;;tag=H4ZN43UH9S9Qc
>>>>>   To:
>>>>> &lt;sip:03996590031055 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D0001Ll0008FJ21EI9PBW
>>>>>   Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501633 INVITE
>>>>>   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, INFO, REFER, NOTIFY,
>>>>> SUBSCRIBE, UPDATE
>>>>>   Content-Type: application/sdp
>>>>>   Content-Length:   189
>>>>>
>>>>>   v=0
>>>>>   o=- 421265648 3 IN IP4 203.208.207.219
>>>>>   s=session
>>>>>   c=IN IP4 203.208.207.196
>>>>>   t=0 0
>>>>>   m=audio 30792 RTP/AVP 18 101
>>>>>   a=rtpmap:18 G729/8000
>>>>>   a=rtpmap:101 telephone-event/8000
>>>>>   a=sendrecv
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:10:01.457169 [DEBUG] sofia.c:4641 Channel
>>>>> sofia/external/03996590031055 at 203.208.207.212 skipping state
>>>>> [proceeding][183]
>>>>> recv 749 bytes from udp/[203.208.207.212]:5060 at 03:10:27.365284:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   SIP/2.0 200 Ok
>>>>>   Via: SIP/2.0/UDP
>>>>> 10.1.1.46:5080
>>>>> ;rport=5080;branch=z9hG4bKXjQ7eFpKypy5D;received=10.1.1.46
>>>>>   From: "" &lt;sip:03996563750914 at 10.1.1.46&gt;;tag=H4ZN43UH9S9Qc
>>>>>   To:
>>>>> &lt;sip:03996590031055 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D0001Ll0008FJ21EI9PBW
>>>>>   Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501633 INVITE
>>>>>   Contact: <sip:203.208.207.212:5060>
>>>>>   Allow-Events: refer
>>>>>   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, INFO, REFER, NOTIFY,
>>>>> SUBSCRIBE, UPDATE
>>>>>   Content-Type: application/sdp
>>>>>   Supported: 100rel, timer, replaces
>>>>>   Content-Length:   189
>>>>>
>>>>>   v=0
>>>>>   o=- 421265648 4 IN IP4 203.208.207.219
>>>>>   s=session
>>>>>   c=IN IP4 203.208.207.196
>>>>>   t=0 0
>>>>>   m=audio 30792 RTP/AVP 18 101
>>>>>   a=rtpmap:18 G729/8000
>>>>>   a=rtpmap:101 telephone-event/8000
>>>>>   a=sendrecv
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:10:27.258092 [DEBUG] sofia.c:4646 Channel
>>>>> sofia/external/03996590031055 at 203.208.207.212 entering state
>>>>> [completing][200]
>>>>> 2011-06-10 11:10:27.258092 [DEBUG] sofia.c:4657 Remote SDP:
>>>>> v=0
>>>>> o=- 421265648 4 IN IP4 203.208.207.219
>>>>> s=session
>>>>> c=IN IP4 203.208.207.196
>>>>> t=0 0
>>>>> m=audio 30792 RTP/AVP 18 101
>>>>> a=rtpmap:18 G729/8000
>>>>> a=rtpmap:101 telephone-event/8000
>>>>>
>>>>> send 405 bytes to udp/[203.208.207.212]:5060 at 03:10:27.366562:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   ACK sip:203.208.207.212:5060 SIP/2.0
>>>>>   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKyUg0ga7pUZmrS
>>>>>   Max-Forwards: 70
>>>>>   From: "" &lt;sip:03996563750914 at 202.73.56.46&gt;;tag=H4ZN43UH9S9Qc
>>>>>   To:
>>>>> &lt;sip:03996590031055 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D0001Ll0008FJ21EI9PBW
>>>>>   Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501633 ACK
>>>>>   Contact: &lt;sip:mod_sofia at 202.73.56.46:5080&gt;
>>>>>   Content-Length: 0
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:10:27.260267 [DEBUG] sofia.c:4646 Channel
>>>>> sofia/external/03996590031055 at 203.208.207.212 entering state
>>>>> [ready][200]
>>>>> 2011-06-10 11:10:27.260267 [DEBUG] switch_channel.c:2782
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Callstate Change EARLY
>>>>> ->
>>>>> ACTIVE
>>>>> 2011-06-10 11:10:27.260267 [NOTICE] sofia.c:5175 Channel
>>>>> [sofia/external/03996590031055 at 203.208.207.212] has been answered
>>>>> 2011-06-10 11:10:27.264178 [DEBUG] switch_scheduler.c:214 Added task 23
>>>>> switch_ivr_schedule_hangup (ea57b74b-a8c2-4fea-9683-98054dc03a79) to
>>>>> run at
>>>>> 1307676927
>>>>> 2011-06-10 11:10:27.265202 [DEBUG] switch_core_session.c:954 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_ivr_originate.c:1971 variable
>>>>> string 0 = [origination_caller_id_number=03996590031055]
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_ivr_originate.c:1971 variable
>>>>> string 1 = [ccd_session_id=20110610105829676824]
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_ivr_originate.c:1971 variable
>>>>> string 2 = [sip_cid_type=pid]
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_ivr_originate.c:1971 variable
>>>>> string 3 = [privacy=yes]
>>>>> 2011-06-10 11:10:27.266218 [NOTICE] switch_channel.c:808 New Channel
>>>>> sofia/external/03996563750914 at 203.208.207.212
>>>>> [30228d2b-756a-4a98-871d-db63a2955b52]
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] mod_sofia.c:4129
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State Change CS_NEW ->
>>>>> CS_INIT
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Running State Change
>>>>> CS_INIT
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_core_state_machine.c:356
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State INIT
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] mod_sofia.c:84
>>>>> sofia/external/03996563750914 at 203.208.207.212 SOFIA INIT
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] mod_sofia.c:124
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State Change CS_INIT
>>>>> ->
>>>>> CS_ROUTING
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_core_state_machine.c:356
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State INIT going to
>>>>> sleep
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Running State Change
>>>>> CS_ROUTING
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_channel.c:1657
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Callstate Change DOWN
>>>>> ->
>>>>> RINGING
>>>>> 2011-06-10 11:10:27.266218 [DEBUG] switch_core_state_machine.c:359
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State ROUTING
>>>>> send 984 bytes to udp/[203.208.207.212]:5060 at 03:10:27.373220:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   INVITE sip:03996563750914 at 203.208.207.212 SIP/2.0
>>>>>   Via: SIP/2.0/UDP
>>>>> 202.73.56.46:5080;rport;branch=z9hG4bKZ49rj5Qtr8aBN2011-06-10
>>>>> 11:10:27.266218 [DEBUG] mod_sofia.c:147
>>>>> sofia/external/03996563750914 at 203.208.207.212 SOFIA ROUTING
>>>>>
>>>>>   Max-Forwards: 70
>>>>>   From: "" &lt;sip:03996590031055 at 202.73.56.46&gt;;tag=jDSe6ycN62Zar
>>>>>   To: &lt;sip:03996563750914 at 203.208.207.212&gt;
>>>>>   Call-ID: 082c8244-0db2-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501649 INVITE
>>>>>   Contact: &lt;sip:mod_sofia at 202.73.56.46:5080&gt;
>>>>>   User-Agent: FreeSWITCH-mod_sofia/1.0.7-hacked-20110603T012235Z
>>>>>   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO,
>>>>> REGISTER, REFER, NOTIFY
>>>>>   Supported: timer, precondition, path, replaces
>>>>>   Allow-Events: talk, hold, refer
>>>>>   Privacy: none
>>>>>   Content-Type: application/sdp
>>>>>   Content-Disposition: session
>>>>>   Content-Length: 204
>>>>>   X-FS-Support: update_display
>>>>>   P-Asserted-Identity: "" &lt;sip:03996590031055 at 202.73.56.46&gt;
>>>>>
>>>>>   v=0
>>>>>   o=FreeSWITCH 1307646863 1307646864 IN IP4 202.73.56.46
>>>>>   s=FreeSWITCH
>>>>>   c=IN IP4 202.73.56.46
>>>>>   t=0 0
>>>>>   m=audio 28564 RTP/AVP 18 3 101 13
>>>>>   a=rtpmap:101 telephone-event/8000
>>>>>   a=fmtp:101 0-16
>>>>>   a=ptime:20
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:10:27.267630 [DEBUG] sofia.c:4646 Channel
>>>>> sofia/external/03996563750914 at 203.208.207.212 entering state
>>>>> [calling][0]
>>>>> 2011-06-10 11:10:27.267630 [DEBUG] switch_ivr_originate.c:66
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State Change
>>>>> CS_ROUTING ->
>>>>> CS_CONSUME_MEDIA
>>>>> 2011-06-10 11:10:27.267630 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:27.267630 [DEBUG] switch_core_state_machine.c:359
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State ROUTING going to
>>>>> sleep
>>>>> 2011-06-10 11:10:27.267630 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Running State Change
>>>>> CS_CONSUME_MEDIA
>>>>> 2011-06-10 11:10:27.267630 [DEBUG] switch_core_state_machine.c:378
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State CONSUME_MEDIA
>>>>> 2011-06-10 11:10:27.267630 [DEBUG] switch_core_state_machine.c:378
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State CONSUME_MEDIA
>>>>> going to
>>>>> sleep
>>>>> recv 307 bytes from udp/[203.208.207.212]:5060 at 03:10:27.378710:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   SIP/2.0 100 Trying
>>>>>   Via: SIP/2.0/UDP
>>>>> 10.1.1.46:5080
>>>>> ;rport=5080;branch=z9hG4bKZ49rj5Qtr8aBN;received=10.1.1.46
>>>>>   From: "" &lt;sip:03996590031055 at 10.1.1.46&gt;;tag=jDSe6ycN62Zar
>>>>>   To: &lt;sip:03996563750914 at 203.208.207.212&gt;
>>>>>   Call-ID: 082c8244-0db2-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501649 INVITE
>>>>>   Content-Length:     0
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:10:27.278484 [DEBUG] switch_ivr.c:563
>>>>> sofia/external/03996590031055 at 203.208.207.212 Command Execute
>>>>> playback(/usr/local/freeswitch/sounds/clearhub/MusicForCalls_v1.wav)
>>>>> EXECUTE sofia/external/03996590031055 at 203.208.207.212
>>>>> playback(/usr/local/freeswitch/sounds/clearhub/MusicForCalls_v1.wav)
>>>>> 2011-06-10 11:10:27.278484 [DEBUG] switch_core_file.c:176 File
>>>>> /usr/local/freeswitch/sounds/clearhub/MusicForCalls_v1.wav sample rate
>>>>> 11025
>>>>> doesn't match requested rate 8000
>>>>> 2011-06-10 11:10:27.278484 [WARNING] switch_core_file.c:189 File has 2
>>>>> channels, muxing to mono will occur.
>>>>> 2011-06-10 11:10:27.278484 [DEBUG] switch_ivr_play_say.c:1244 Codec
>>>>> Activated L16 at 8000hz 2 channels 20ms
>>>>> 2011-06-10 11:10:27.298764 [INFO] mod_com_g729.c:119 ENCODER CREATE -
>>>>> 0x2aaab00310c0 0x2aaab00b20c0
>>>>> recv 666 bytes from udp/[203.208.207.212]:5060 at 03:10:28.618472:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   SIP/2.0 183 Session Progress
>>>>>   Via: SIP/2.0/UDP
>>>>> 10.1.1.46:5080
>>>>> ;rport=5080;branch=z9hG4bKZ49rj5Qtr8aBN;received=10.1.1.46
>>>>>   From: "" &lt;sip:03996590031055 at 10.1.1.46&gt;;tag=jDSe6ycN62Zar
>>>>>   To:
>>>>> &lt;sip:03996563750914 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D0001Ll0008FJ410OWC5F
>>>>>   Call-ID: 082c8244-0db2-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501649 INVITE
>>>>>   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, INFO, REFER, NOTIFY,
>>>>> SUBSCRIBE, UPDATE
>>>>>   Content-Type: application/sdp
>>>>>   Content-Length:   186
>>>>>
>>>>>   v=0
>>>>>   o=- 131082 1 IN IP4 203.208.207.218
>>>>>   s=session
>>>>>   c=IN IP4 203.208.207.195
>>>>>   t=0 0
>>>>>   m=audio 45002 RTP/AVP 18 101
>>>>>   a=rtpmap:18 G729/8000
>>>>>   a=rtpmap:101 telephone-event/8000
>>>>>   a=sendrecv
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:10:28.513195 [INFO] sofia.c:729
>>>>> sofia/external/03996563750914 at 203.208.207.212 Update Callee ID to
>>>>> "Outbound
>>>>> Call" <03996563750914>
>>>>> 2011-06-10 11:10:28.513195 [DEBUG] sofia.c:4646 Channel
>>>>> sofia/external/03996563750914 at 203.208.207.212 entering state
>>>>> [proceeding][183]
>>>>> 2011-06-10 11:10:28.513195 [DEBUG] sofia.c:4657 Remote SDP:
>>>>> v=0
>>>>> o=- 131082 1 IN IP4 203.208.207.218
>>>>> s=session
>>>>> c=IN IP4 203.208.207.195
>>>>> t=0 0
>>>>> m=audio 45002 RTP/AVP 18 101
>>>>> a=rtpmap:18 G729/8000
>>>>> a=rtpmap:101 telephone-event/8000
>>>>>
>>>>> 2011-06-10 11:10:28.513195 [DEBUG] sofia_glue.c:4467 Audio Codec
>>>>> Compare
>>>>> [G729:18:8000:20:8000]/[G729:18:8000:20:8000]
>>>>> 2011-06-10 11:10:28.513195 [DEBUG] sofia_glue.c:2757 Set Codec
>>>>> sofia/external/03996563750914 at 203.208.207.212 G729/8000 20 ms 160
>>>>> samples
>>>>> 8000 bits
>>>>> 2011-06-10 11:10:28.513195 [DEBUG] sofia_glue.c:4565 Set 2833 dtmf send
>>>>> payload to 101
>>>>> 2011-06-10 11:10:28.513195 [DEBUG] sofia_glue.c:2987 AUDIO RTP
>>>>> [sofia/external/03996563750914 at 203.208.207.212] 10.1.1.46 port 28564
>>>>> ->
>>>>> 203.208.207.195 port 45002 codec: 18 ms: 20
>>>>> 2011-06-10 11:10:28.513195 [DEBUG] switch_rtp.c:1607 Starting timer
>>>>> [soft]
>>>>> 160 bytes per 20ms
>>>>> 2011-06-10 11:10:28.514938 [DEBUG] sofia_glue.c:3228 Set 2833 dtmf send
>>>>> payload to 101
>>>>> 2011-06-10 11:10:28.514938 [DEBUG] sofia_glue.c:3233 Set 2833 dtmf
>>>>> receive
>>>>> payload to 101
>>>>> 2011-06-10 11:10:28.514938 [NOTICE] sofia_glue.c:3680 Pre-Answer
>>>>> sofia/external/03996563750914 at 203.208.207.212!
>>>>> 2011-06-10 11:10:28.514938 [DEBUG] switch_channel.c:2627
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Callstate Change
>>>>> RINGING ->
>>>>> EARLY
>>>>> 2011-06-10 11:10:28.514938 [DEBUG] switch_ivr_originate.c:3408
>>>>> Originate
>>>>> Resulted in Success: [sofia/external/03996563750914 at 203.208.207.212]
>>>>> 2011-06-10 11:10:28.514938 [DEBUG] mod_commands.c:3205
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State Change
>>>>> CS_CONSUME_MEDIA -> CS_EXECUTE
>>>>> 2011-06-10 11:10:28.514938 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:28.515884 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Running State Change
>>>>> CS_EXECUTE
>>>>> 2011-06-10 11:10:28.515884 [DEBUG] switch_core_state_machine.c:366
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State EXECUTE
>>>>> 2011-06-10 11:10:28.515884 [DEBUG] mod_sofia.c:240
>>>>> sofia/external/03996563750914 at 203.208.207.212 SOFIA EXECUTE
>>>>> 2011-06-10 11:10:28.515884 [DEBUG] switch_core_state_machine.c:157
>>>>> sofia/external/03996563750914 at 203.208.207.212 Standard EXECUTE
>>>>> EXECUTE sofia/external/03996563750914 at 203.208.207.212 park()
>>>>> 2011-06-10 11:10:28.516887 [DEBUG] switch_core_session.c:954 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:28.517896 [DEBUG] switch_ivr_bridge.c:1480
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State Change
>>>>> CS_EXECUTE ->
>>>>> CS_HIBERNATE
>>>>> 2011-06-10 11:10:28.517896 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:28.517896 [DEBUG] switch_ivr_bridge.c:1482
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State Change
>>>>> CS_EXECUTE ->
>>>>> CS_HIBERNATE
>>>>> 2011-06-10 11:10:28.517896 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:28.517896 [DEBUG] switch_core_session.c:771 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:28.517896 [DEBUG] switch_core_session.c:771 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_ivr_play_say.c:1581 done
>>>>> playing
>>>>> file
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_ivr.c:563
>>>>> sofia/external/03996590031055 at 203.208.207.212 Command Execute
>>>>> playback(tone_stream://%(2000,4000,440,480);loops=10)
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_core_state_machine.c:366
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State EXECUTE going to
>>>>> sleep
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Running State Change
>>>>> CS_HIBERNATE
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_core_state_machine.c:381
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State HIBERNATE
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] mod_sofia.c:221
>>>>> sofia/external/03996563750914 at 203.208.207.212 SOFIA HIBERNATE
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_ivr_bridge.c:731
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State Change
>>>>> CS_HIBERNATE ->
>>>>> CS_RESET
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_core_state_machine.c:381
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State HIBERNATE going
>>>>> to
>>>>> sleep
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Running State Change
>>>>> CS_RESET
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_core_state_machine.c:362
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State RESET
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] mod_sofia.c:165
>>>>> sofia/external/03996563750914 at 203.208.207.212 SOFIA RESET
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_ivr_bridge.c:716
>>>>> sofia/external/03996563750914 at 203.208.207.212 CUSTOM RESET
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_core_state_machine.c:66
>>>>> sofia/external/03996563750914 at 203.208.207.212 Standard RESET
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_core_state_machine.c:362
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State RESET going to
>>>>> sleep
>>>>> 2011-06-10 11:10:28.519223 [DEBUG] switch_core_session.c:709 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> recv 666 bytes from udp/[203.208.207.212]:5060 at 03:10:30.540814:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   SIP/2.0 183 Session Progress
>>>>>   Via: SIP/2.0/UDP
>>>>> 10.1.1.46:5080
>>>>> ;rport=5080;branch=z9hG4bKZ49rj5Qtr8aBN;received=10.1.1.46
>>>>>   From: "" &lt;sip:03996590031055 at 10.1.1.46&gt;;tag=jDSe6ycN62Zar
>>>>>   To:
>>>>> &lt;sip:03996563750914 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D0001Ll0008FJ410OWC5F
>>>>>   Call-ID: 082c8244-0db2-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501649 INVITE
>>>>>   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, INFO, REFER, NOTIFY,
>>>>> SUBSCRIBE, UPDATE
>>>>>   Content-Type: application/sdp
>>>>>   Content-Length:   186
>>>>>
>>>>>   v=0
>>>>>   o=- 131082 2 IN IP4 203.208.207.218
>>>>>   s=session
>>>>>   c=IN IP4 203.208.207.195
>>>>>   t=0 0
>>>>>   m=audio 45002 RTP/AVP 18 101
>>>>>   a=rtpmap:18 G729/8000
>>>>>   a=rtpmap:101 telephone-event/8000
>>>>>   a=sendrecv
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:10:30.435309 [INFO] sofia.c:729
>>>>> sofia/external/03996563750914 at 203.208.207.212 Update Callee ID to
>>>>> "03996563750914" <03996563750914>
>>>>> 2011-06-10 11:10:30.435309 [DEBUG] sofia.c:4641 Channel
>>>>> sofia/external/03996563750914 at 203.208.207.212 skipping state
>>>>> [proceeding][183]
>>>>> 2011-06-10 11:10:30.691404 [WARNING] switch_core_session.c:1940 Cannot
>>>>> execute app 'playback' media required on an outbound channel that does
>>>>> not
>>>>> have media established
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:366
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State EXECUTE going to
>>>>> sleep
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Running State Change
>>>>> CS_HIBERNATE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:381
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State HIBERNATE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] mod_sofia.c:221
>>>>> sofia/external/03996590031055 at 203.208.207.212 SOFIA HIBERNATE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_ivr_bridge.c:731
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State Change
>>>>> CS_HIBERNATE ->
>>>>> CS_RESET
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:381
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State HIBERNATE going
>>>>> to
>>>>> sleep
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Running State Change
>>>>> CS_RESET
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:362
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State RESET
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] mod_sofia.c:165
>>>>> sofia/external/03996590031055 at 203.208.207.212 SOFIA RESET
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_ivr_bridge.c:716
>>>>> sofia/external/03996590031055 at 203.208.207.212 CUSTOM RESET
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_ivr_bridge.c:723
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State Change CS_RESET
>>>>> ->
>>>>> CS_SOFT_EXECUTE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:362
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State RESET going to
>>>>> sleep
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Running State Change
>>>>> CS_SOFT_EXECUTE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:372
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State SOFT_EXECUTE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] mod_sofia.c:558 SOFIA SOFT_EXECUTE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_ivr_bridge.c:741
>>>>> sofia/external/03996590031055 at 203.208.207.212 CUSTOM SOFT_EXECUTE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_ivr_bridge.c:761
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State Change CS_RESET
>>>>> ->
>>>>> CS_SOFT_EXECUTE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Running State Change
>>>>> CS_SOFT_EXECUTE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:372
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State SOFT_EXECUTE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] mod_sofia.c:558 SOFIA SOFT_EXECUTE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_ivr_bridge.c:741
>>>>> sofia/external/03996563750914 at 203.208.207.212 CUSTOM SOFT_EXECUTE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:204
>>>>> sofia/external/03996563750914 at 203.208.207.212 Standard SOFT_EXECUTE
>>>>> 2011-06-10 11:10:30.691404 [DEBUG] switch_core_state_machine.c:372
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State SOFT_EXECUTE
>>>>> going to
>>>>> sleep
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_channel.c:2535
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Callstate Change EARLY
>>>>> ->
>>>>> HANGUP
>>>>> 2011-06-10 11:10:30.711798 [NOTICE] switch_ivr_originate.c:1045 Hangup
>>>>> sofia/external/03996563750914 at 203.208.207.212 [CS_SOFT_EXECUTE]
>>>>> [DESTINATION_OUT_OF_ORDER]
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_channel.c:2551 Send signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [KILL]
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Running State Change
>>>>> CS_HANGUP
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_channel.c:2535
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Callstate Change
>>>>> ACTIVE ->
>>>>> HANGUP
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:557
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State HANGUP
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] mod_sofia.c:457 Channel
>>>>> sofia/external/03996563750914 at 203.208.207.212 hanging up, cause:
>>>>> DESTINATION_OUT_OF_ORDER
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] mod_sofia.c:510 Sending CANCEL to
>>>>> sofia/external/03996563750914 at 203.208.207.212
>>>>> send 390 bytes to udp/[203.208.207.212]:5060 at 03:10:30.818391:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   CANCEL sip:03996563750914 at 203.208.207.212 SIP/2.0
>>>>>   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKZ49rj5Qtr8aBN
>>>>>   Max-Forwards: 70
>>>>>   From: "" &lt;sip:03996590031055 at 202.73.56.46&gt;;tag=jDSe6ycN62Zar
>>>>>   To: &lt;sip:03996563750914 at 203.208.207.212&gt;
>>>>>   Call-ID: 082c8244-0db2-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501649 CANCEL
>>>>>   Reason: Q.850;cause=27;text="DESTINATION_OUT_OF_ORDER"
>>>>>   Content-Length: 0
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:10:30.711798 [NOTICE] switch_ivr_bridge.c:772 Hangup
>>>>> sofia/external/03996590031055 at 203.208.207.212 [CS_SOFT_EXECUTE]
>>>>> [ORIGINATOR_CANCEL]
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:46
>>>>> sofia/external/03996563750914 at 203.208.207.212 Standard HANGUP, cause:
>>>>> DESTINATION_OUT_OF_ORDER
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:557
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State HANGUP going to
>>>>> sleep
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:351
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State Change CS_HANGUP
>>>>> ->
>>>>> CS_REPORTING
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Running State Change
>>>>> CS_REPORTING
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:617
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State REPORTING
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:53
>>>>> sofia/external/03996563750914 at 203.208.207.212 Standard REPORTING,
>>>>> cause:
>>>>> DESTINATION_OUT_OF_ORDER
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:617
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State REPORTING going
>>>>> to
>>>>> sleep
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_channel.c:2551 Send signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [KILL]
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:372
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State SOFT_EXECUTE
>>>>> going to
>>>>> sleep
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Running State Change
>>>>> CS_HANGUP
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:345
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State Change
>>>>> CS_REPORTING ->
>>>>> CS_DESTROY
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996563750914 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_session.c:1288 Session
>>>>> 40
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Locked, Waiting on
>>>>> external
>>>>> entities
>>>>> 2011-06-10 11:10:30.711798 [NOTICE] switch_core_session.c:1306 Session
>>>>> 40
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Ended
>>>>> 2011-06-10 11:10:30.711798 [NOTICE] switch_core_session.c:1308 Close
>>>>> Channel
>>>>> sofia/external/03996563750914 at 203.208.207.212 [CS_DESTROY]
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:449
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Callstate Change
>>>>> HANGUP ->
>>>>> DOWN
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:452
>>>>> (sofia/external/03996563750914 at 203.208.207.212) Running State Change
>>>>> CS_DESTROY
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:462
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State DESTROY
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] mod_sofia.c:362
>>>>> sofia/external/03996563750914 at 203.208.207.212 SOFIA DESTROY
>>>>> 2011-06-10 11:10:30.711798 [INFO] mod_com_g729.c:78 ENCODER DESTROYX -
>>>>> 0x2aaaac013028 (nil)
>>>>> 2011-06-10 11:10:30.711798 [INFO] mod_com_g729.c:79 DECODER DESTROYX -
>>>>> 0x2aaaac013028 (nil)
>>>>> 2011-06-10 11:10:30.711798 [INFO] mod_com_g729.c:78 ENCODER DESTROYX -
>>>>> 0x2aaaac013088 (nil)
>>>>> 2011-06-10 11:10:30.711798 [INFO] mod_com_g729.c:79 DECODER DESTROYX -
>>>>> 0x2aaaac013088 (nil)
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:60
>>>>> sofia/external/03996563750914 at 203.208.207.212 Standard DESTROY
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:462
>>>>> (sofia/external/03996563750914 at 203.208.207.212) State DESTROY going to
>>>>> sleep
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:557
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State HANGUP
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] mod_sofia.c:457 Channel
>>>>> sofia/external/03996590031055 at 203.208.207.212 hanging up, cause:
>>>>> ORIGINATOR_CANCEL
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] mod_sofia.c:500 Sending BYE to
>>>>> sofia/external/03996590031055 at 203.208.207.212
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:46
>>>>> sofia/external/03996590031055 at 203.208.207.212 Standard HANGUP, cause:
>>>>> ORIGINATOR_CANCEL
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:557
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State HANGUP going to
>>>>> sleep
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:351
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State Change CS_HANGUP
>>>>> ->
>>>>> CS_REPORTING
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:320
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Running State Change
>>>>> CS_REPORTING
>>>>> 2011-06-10 11:10:30.711798 [DEBUG] switch_core_state_machine.c:617
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State REPORTING
>>>>> 2011-06-10 11:10:30.714001 [DEBUG] switch_core_state_machine.c:53
>>>>> sofia/external/03996590031055 at 203.208.207.212 Standard REPORTING,
>>>>> cause:
>>>>> ORIGINATOR_CANCEL
>>>>> 2011-06-10 11:10:30.714001 [DEBUG] switch_core_state_machine.c:617
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State REPORTING going
>>>>> to
>>>>> sleep
>>>>> 2011-06-10 11:10:30.714001 [DEBUG] switch_core_state_machine.c:345
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State Change
>>>>> CS_REPORTING ->
>>>>> CS_DESTROY
>>>>> 2011-06-10 11:10:30.714001 [DEBUG] switch_core_session.c:1116 Send
>>>>> signal
>>>>> sofia/external/03996590031055 at 203.208.207.212 [BREAK]
>>>>> 2011-06-10 11:10:30.714001 [DEBUG] switch_core_session.c:1288 Session
>>>>> 39
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Locked, Waiting on
>>>>> external
>>>>> entities
>>>>> 2011-06-10 11:10:30.714001 [NOTICE] switch_core_session.c:1306 Session
>>>>> 39
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Ended
>>>>> 2011-06-10 11:10:30.714001 [NOTICE] switch_core_session.c:1308 Close
>>>>> Channel
>>>>> sofia/external/03996590031055 at 203.208.207.212 [CS_DESTROY]
>>>>> 2011-06-10 11:10:30.714001 [DEBUG] switch_core_state_machine.c:449
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Callstate Change
>>>>> HANGUP ->
>>>>> DOWN
>>>>> 2011-06-10 11:10:30.714001 [DEBUG] switch_core_state_machine.c:452
>>>>> (sofia/external/03996590031055 at 203.208.207.212) Running State Change
>>>>> CS_DESTROY
>>>>> 2011-06-10 11:10:30.714001 [DEBUG] switch_core_state_machine.c:462
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State DESTROY
>>>>> 2011-06-10 11:10:30.714001 [DEBUG] mod_sofia.c:362
>>>>> sofia/external/03996590031055 at 203.208.207.212 SOFIA DESTROY
>>>>> 2011-06-10 11:10:30.714001 [INFO] mod_com_g729.c:78 ENCODER DESTROYX -
>>>>> 0x2aaab0031060 (nil)
>>>>> 2011-06-10 11:10:30.714001 [INFO] mod_com_g729.c:79 DECODER DESTROYX -
>>>>> 0x2aaab0031060 (nil)
>>>>> 2011-06-10 11:10:30.714001 [INFO] mod_com_g729.c:78 ENCODER DESTROYX -
>>>>> 0x2aaab00310c0 0x2aaab00b20c0
>>>>> 2011-06-10 11:10:30.714001 [INFO] mod_com_g729.c:79 DECODER DESTROYX -
>>>>> 0x2aaab00310c0 (nil)
>>>>> send 662 bytes to udp/[203.208.207.212]:5060 at 03:10:30.820530:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   BYE sip:203.208.207.212:5060 SIP/2.0
>>>>>   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bK0D3Hm08XNH1Xg
>>>>>   Max-Forwards: 70
>>>>>   From: "" &lt;sip:03996563750914 at 202.73.56.46&gt;;tag=H4ZN43UH9S9Qc
>>>>>   To:
>>>>> &lt;sip:03996590031055 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D0001Ll0008FJ21EI9PBW
>>>>>   Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501634 BYE
>>>>>   Contact: &lt;sip:mod_sofia at 202.73.56.46:5080&gt;
>>>>>   User-Agent: FreeSWITCH-mod_sofia/1.0.7-hacked-20110603T012235Z
>>>>>   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, UPDATE, INFO,
>>>>> REGISTER, REFER, NOTIFY
>>>>>   Supported: timer, precondition, path, replaces
>>>>>   Reason: FreeSWITCH;cause=487;text="ORIGINATOR_CANCEL"
>>>>>   Content-Length: 0
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> 2011-06-10 11:10:30.715878 [INFO] mod_com_g729.c:83 ENCODER DESTROY -
>>>>> 0x2aaab00310c0 0x2aaab00b20c0
>>>>> 2011-06-10 11:10:30.715878 [DEBUG] switch_core_state_machine.c:60
>>>>> sofia/external/03996590031055 at 203.208.207.212 Standard DESTROY
>>>>> 2011-06-10 11:10:30.715878 [DEBUG] switch_core_state_machine.c:462
>>>>> (sofia/external/03996590031055 at 203.208.207.212) State DESTROY going to
>>>>> sleep
>>>>> recv 383 bytes from udp/[203.208.207.212]:5060 at 03:10:30.823302:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   SIP/2.0 200 Ok
>>>>>   Via: SIP/2.0/UDP
>>>>> 10.1.1.46:5080
>>>>> ;rport=5080;branch=z9hG4bKZ49rj5Qtr8aBN;received=10.1.1.46
>>>>>   From: "" &lt;sip:03996590031055 at 10.1.1.46&gt;;tag=jDSe6ycN62Zar
>>>>>   To:
>>>>> &lt;sip:03996563750914 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D00000u00000001QXU3LU
>>>>>   Call-ID: 082c8244-0db2-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501649 CANCEL
>>>>>   Contact: <sip:203.208.207.212:5060>
>>>>>   Content-Length:     0
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> recv 411 bytes from udp/[203.208.207.212]:5060 at 03:10:30.824765:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   SIP/2.0 487 Request Terminated
>>>>>   Via: SIP/2.0/UDP
>>>>> 10.1.1.46:5080
>>>>> ;rport=5080;branch=z9hG4bKZ49rj5Qtr8aBN;received=10.1.1.46
>>>>>   From: "" &lt;sip:03996590031055 at 10.1.1.46&gt;;tag=jDSe6ycN62Zar
>>>>>   To:
>>>>> &lt;sip:03996563750914 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D0001Ll0008FJ410OWC5F
>>>>>   Call-ID: 082c8244-0db2-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501649 INVITE
>>>>>   Reason: SIP;cause=487;text="Request Terminated"
>>>>>   Content-Length:     0
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> send 371 bytes to udp/[203.208.207.212]:5060 at 03:10:30.824891:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   ACK sip:03996563750914 at 203.208.207.212 SIP/2.0
>>>>>   Via: SIP/2.0/UDP 202.73.56.46:5080;rport;branch=z9hG4bKZ49rj5Qtr8aBN
>>>>>   Max-Forwards: 70
>>>>>   From: "" &lt;sip:03996590031055 at 202.73.56.46&gt;;tag=jDSe6ycN62Zar
>>>>>   To:
>>>>> &lt;sip:03996563750914 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D0001Ll0008FJ410OWC5F
>>>>>   Call-ID: 082c8244-0db2-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501649 ACK
>>>>>   Content-Length: 0
>>>>>
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>> recv 380 bytes from udp/[203.208.207.212]:5060 at 03:10:30.826375:
>>>>>
>>>>> ------------------------------------------------------------------------
>>>>>   SIP/2.0 200 Ok
>>>>>   Via: SIP/2.0/UDP
>>>>> 10.1.1.46:5080
>>>>> ;rport=5080;branch=z9hG4bK0D3Hm08XNH1Xg;received=10.1.1.46
>>>>>   From: "" &lt;sip:03996563750914 at 10.1.1.46&gt;;tag=H4ZN43UH9S9Qc
>>>>>   To:
>>>>> &lt;sip:03996590031055 at 203.208.207.212
>>>>> &gt;;tag=2QGB951HCR30000E1D0001Ll0008FJ21EI9PBW
>>>>>   Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>>>>   CSeq: 13501634 BYE
>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> View this message in context:
>>>>> http://freeswitch-users.2379917.n2.nabble.com/Leg-A-is-automatically-disconnected-on-Leg-B-orginate-failure-tp6482192p6482192.html
>>>>> Sent from the freeswitch-users mailing list archive at Nabble.com.
>>>>>
>>>>> _______________________________________________
>>>>> FreeSWITCH-users mailing list
>>>>> FreeSWITCH-users at lists.freeswitch.org
>>>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>>>> UNSUBSCRIBE:
>>>>> http://lists.freeswitch.org/mailman/options/freeswitch-users
>>>>> http://www.freeswitch.org
>>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> Join us at ClueCon 2011, Aug 9-11, Chicago
>>>> http://www.cluecon.com 877-7-4ACLUE
>>>>
>>>>
>>>> FreeSWITCH-users mailing list
>>>> FreeSWITCH-users at lists.freeswitch.org
>>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>>> UNSUBSCRIBE:
>>>> http://lists.freeswitch.org/mailman/options/freeswitch-users
>>>> http://www.freeswitch.org
>>>>
>>>>
>>>
>>
>> _______________________________________________
>> Join us at ClueCon 2011, Aug 9-11, Chicago
>> http://www.cluecon.com 877-7-4ACLUE
>>
>> FreeSWITCH-users mailing list
>> FreeSWITCH-users at lists.freeswitch.org
>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>> http://www.freeswitch.org
>>
>>
>
> _______________________________________________
> Join us at ClueCon 2011, Aug 9-11, Chicago
> http://www.cluecon.com 877-7-4ACLUE
>
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20110627/234554ee/attachment-0001.html 


More information about the FreeSWITCH-users mailing list