[Freeswitch-users] Leg-A is automatically disconnected on Leg-B orginate failure
David Ma
mays.david at gmail.com
Fri Jun 24 10:26:44 MSD 2011
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: "" <sip:03996563750914 at 202.73.56.46>;tag=H4ZN43UH9S9Qc
>>> To: <sip:03996590031055 at 203.208.207.212>
>>> Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>> CSeq: 13501633 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, 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: "" <sip:03996563750914 at 202.73.56.46>
>>>
>>> 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: "" <sip:03996563750914 at 10.1.1.46>;tag=H4ZN43UH9S9Qc
>>> To: <sip:03996590031055 at 203.208.207.212>
>>> 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: "" <sip:03996563750914 at 10.1.1.46>;tag=H4ZN43UH9S9Qc
>>> To:
>>> <sip:03996590031055 at 203.208.207.212
>>> >;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: "" <sip:03996563750914 at 10.1.1.46>;tag=H4ZN43UH9S9Qc
>>> To:
>>> <sip:03996590031055 at 203.208.207.212
>>> >;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: "" <sip:03996563750914 at 10.1.1.46>;tag=H4ZN43UH9S9Qc
>>> To:
>>> <sip:03996590031055 at 203.208.207.212
>>> >;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: "" <sip:03996563750914 at 10.1.1.46>;tag=H4ZN43UH9S9Qc
>>> To:
>>> <sip:03996590031055 at 203.208.207.212
>>> >;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: "" <sip:03996563750914 at 202.73.56.46>;tag=H4ZN43UH9S9Qc
>>> To:
>>> <sip:03996590031055 at 203.208.207.212
>>> >;tag=2QGB951HCR30000E1D0001Ll0008FJ21EI9PBW
>>> Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>> CSeq: 13501633 ACK
>>> Contact: <sip:mod_sofia at 202.73.56.46:5080>
>>> 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: "" <sip:03996590031055 at 202.73.56.46>;tag=jDSe6ycN62Zar
>>> To: <sip:03996563750914 at 203.208.207.212>
>>> Call-ID: 082c8244-0db2-122f-c4ab-0015c5fc7ad9
>>> CSeq: 13501649 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, 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: "" <sip:03996590031055 at 202.73.56.46>
>>>
>>> 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: "" <sip:03996590031055 at 10.1.1.46>;tag=jDSe6ycN62Zar
>>> To: <sip:03996563750914 at 203.208.207.212>
>>> 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: "" <sip:03996590031055 at 10.1.1.46>;tag=jDSe6ycN62Zar
>>> To:
>>> <sip:03996563750914 at 203.208.207.212
>>> >;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: "" <sip:03996590031055 at 10.1.1.46>;tag=jDSe6ycN62Zar
>>> To:
>>> <sip:03996563750914 at 203.208.207.212
>>> >;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: "" <sip:03996590031055 at 202.73.56.46>;tag=jDSe6ycN62Zar
>>> To: <sip:03996563750914 at 203.208.207.212>
>>> 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: "" <sip:03996563750914 at 202.73.56.46>;tag=H4ZN43UH9S9Qc
>>> To:
>>> <sip:03996590031055 at 203.208.207.212
>>> >;tag=2QGB951HCR30000E1D0001Ll0008FJ21EI9PBW
>>> Call-ID: f529ae7e-0db1-122f-c4ab-0015c5fc7ad9
>>> CSeq: 13501634 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, 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: "" <sip:03996590031055 at 10.1.1.46>;tag=jDSe6ycN62Zar
>>> To:
>>> <sip:03996563750914 at 203.208.207.212
>>> >;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: "" <sip:03996590031055 at 10.1.1.46>;tag=jDSe6ycN62Zar
>>> To:
>>> <sip:03996563750914 at 203.208.207.212
>>> >;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: "" <sip:03996590031055 at 202.73.56.46>;tag=jDSe6ycN62Zar
>>> To:
>>> <sip:03996563750914 at 203.208.207.212
>>> >;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: "" <sip:03996563750914 at 10.1.1.46>;tag=H4ZN43UH9S9Qc
>>> To:
>>> <sip:03996590031055 at 203.208.207.212
>>> >;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
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20110624/201b6658/attachment-0001.html
More information about the FreeSWITCH-users
mailing list