[Freeswitch-users] RTP Audio Stream Initialise

Tue Oct 1 19:31:53 MSD 2013

Hi Michael,

Thanks for the response.

I am sending the application executions in the sequence in my last mail and
have just enabled event lock for the answer and confirmed that this has not
made a difference to my call.

It sounds like your suggestion of nat auto-correction explains the problem
and is not something i had considered although i had realised that a 1
second pause solved the issue. I presume that the record application will
only work if the RTP stream is ready when the application starts, and this
is the reason why my packet capture contains the audio and the recorded
file does not?

I have attached a complete debug trace from fs_cli in case it helps to
further explain my configuration.

Many thanks,

Callum

______________________________

Callum Guy
Developer

X-on
Framlingham Technology Centre
Station Road, Framlingham,
Suffolk, IP13 9EZ

T       0333 332 0116
E       callum.guy at x-on.co.uk

X-on is a trading name of Storacall Technology Ltd a limited company
registered in England and Wales
Registered Office : Avaland House, 110 London Road, Apsley, Hemel
Hempstead, Herts, HP3 9SD
Company Registration No. 2578478

This email has been sent from X-on.The contents and attachments are
confidential to the sender and the intended addressees.If the message
is received by anyone other than the addressee please return the
message to the sender by replying to it and then delete the message
from
your computer without copying or disclosing the contents to
anyone.Opinions, conclusions and statements of intent in this email
are those of
the sender and do not bind X-on unless confirmed by authorised
representatives independently of this message.While best endeavours
have
been taken to avoid transmission of viruses, it is the responsibility
of the recipient to scan for these.Please note emails sent to and from
X-on
are routinely monitored for record keeping and quality control, to
ensure regulatory compliance and prevent unauthorised use of our
systems.
Please consider the environment before printing this email.

On 1 October 2013 16:15, Anthony Minessale <anthony.minessale at gmail.com>wrote:

> Are you running the answer application before you call the record app?
> It appears as you are not as the codec negotiation seems to take place
> after you call record.
> Also you are behind nat and you need to wait for the nat auto-correction
> to trigger before the media stream is correct so the 10ms is not enough.
> You need to exchange audio for about 1 seconds for it to fix the problem
> for you.  If you fixed the other end to not need server side nat it would
> also help your issue.
>
>
> On Tue, Oct 1, 2013 at 10:05 AM, Callum Guy <callum.guy at x-on.co.uk> wrote:
>
>> I have just checked and although my test configuration recorded an empty
>> file the packets captured with tcpdump can be successfully played back in
>> Wireshark. The audio in the capture is exactly as I would have expected the
>> recording to be.
>>
>> Are we suggesting that there is a bug of some description here? Is there
>> anything else I can test to confirm?
>>
>> To provide some clarity on my setup here is a list of what i have:
>>
>>    1. Registered Linksys SPA941 on OpenSIPS
>>    2. Direct call from OpenSIPS to FreeSWITCH
>>    3. XML dialplan with ESL outbound connection to socket server
>>    4. Socket server issues SendMsg answer
>>    5. Socket server issues SendMsg park
>>    6. Socket client intercepts CHANNEL_PARK
>>    7. Socket client issues SendMsg record (filepath/test.wav 15 200)
>>
>>
>>
>> ______________________________
>>
>> Callum Guy
>> Developer
>>
>> X-on
>> Framlingham Technology Centre
>> Station Road, Framlingham,
>> Suffolk, IP13 9EZ
>>
>> T       0333 332 0116
>> E       callum.guy at x-on.co.uk
>>
>>
>> X-on is a trading name of Storacall Technology Ltd a limited company registered in England and Wales
>> Registered Office : Avaland House, 110 London Road, Apsley, Hemel Hempstead, Herts, HP3 9SD
>> Company Registration No. 2578478
>>
>> This email has been sent from X-on.The contents and attachments are confidential to the sender and the intended addressees.If the message
>> is received by anyone other than the addressee please return the message to the sender by replying to it and then delete the message from
>> your computer without copying or disclosing the contents to anyone.Opinions, conclusions and statements of intent in this email are those of
>> the sender and do not bind X-on unless confirmed by authorised representatives independently of this message.While best endeavours have
>> been taken to avoid transmission of viruses, it is the responsibility of the recipient to scan for these.Please note emails sent to and from X-on
>> are routinely monitored for record keeping and quality control, to ensure regulatory compliance and prevent unauthorised use of our systems.
>> Please consider the environment before printing this email.
>>
>>
>>
>> On 1 October 2013 15:33, Michael Jerris <mike at jerris.com> wrote:
>>
>>> Your saying you see media flowing in both directions even when the
>>> record doesn't work, and when you play the stream in wireshark, there is
>>> media in that stream, and its not silent?
>>>
>>> On Oct 1, 2013, at 10:23 AM, Callum Guy <callum.guy at x-on.co.uk> wrote:
>>>
>>> I'm calling in from a Linksys SPA941 and I will be the only user on the
>>> FreeSWITCH server. I have been using tcpdump to capture my RTP traffic
>>> using the following command:
>>>
>>> tcpdump -i any -n dst portrange 10000-50000
>>>
>>> I configured two test scripts as below:
>>>
>>> *Script 1: Answer call, generate 1000ms silence (as above) and then
>>> record. *
>>> This showed a steady stream of UDP data throughout the call and resulted
>>> in a recording.
>>>
>>> *Script 2: Answer call, sleep for 1 second and then record. *
>>> This showed a steady stream of UDP data throughout the call but resulted
>>> in a blank recording.
>>>
>>> This is interesting and indicates to me that there is probably something
>>> that the FreeSWITCH file play operation is doing (even when its a silence
>>> stream) that is not carried out by the record application. I would expect
>>> that its unusual for a telephony application to want to answer and record
>>> without any play operations first.
>>>
>>> Thanks again,
>>>
>>> Callum
>>>
>>>
>>>
>>> _________________________________________________________________________
>>> Professional FreeSWITCH Consulting Services:
>>> consulting at freeswitch.org
>>> http://www.freeswitchsolutions.com
>>>
>>> 
>>> 
>>>
>>> Official FreeSWITCH Sites
>>> http://www.freeswitch.org
>>> http://wiki.freeswitch.org
>>> http://www.cluecon.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
>>>
>>>
>>
>> _________________________________________________________________________
>> Professional FreeSWITCH Consulting Services:
>> consulting at freeswitch.org
>> http://www.freeswitchsolutions.com
>>
>> 
>> 
>>
>> Official FreeSWITCH Sites
>> http://www.freeswitch.org
>> http://wiki.freeswitch.org
>> http://www.cluecon.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
>>
>>
>
>
> --
> Anthony Minessale II
>
> FreeSWITCH http://www.freeswitch.org/
> ClueCon http://www.cluecon.com/
> Twitter: http://twitter.com/FreeSWITCH_wire
>
> AIM: anthm
> MSN:anthony_minessale at hotmail.com
> GTALK/JABBER/PAYPAL:anthony.minessale at gmail.com
> IRC: irc.freenode.net #freeswitch
>
> FreeSWITCH Developer Conference
> sip:888 at conference.freeswitch.org
> googletalk:conf+888 at conference.freeswitch.org
> pstn:+19193869900
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
> 
> 
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.freeswitch.org
> http://www.cluecon.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
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20131001/97b11a4c/attachment-0001.html 
-------------- next part --------------
2013-10-01 17:50:45.290072 [NOTICE] switch_channel.c:978 New Channel sofia/internal/3333320116 at sipserver.net [674ea0b0-2aad-11e3-ac3d-434c845291ea]
2013-10-01 17:50:45.290072 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:45.290072 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:45.290072 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116 at sipserver.net) Running State Change CS_NEW
2013-10-01 17:50:45.290072 [DEBUG] switch_core_state_machine.c:433 (sofia/internal/3333320116 at sipserver.net) State NEW
2013-10-01 17:50:45.310083 [DEBUG] sofia.c:7793 IP 193.104.89.45 Approved by acl "localnet.auto[]". Access Granted.
2013-10-01 17:50:45.310083 [DEBUG] sofia.c:5685 Channel sofia/internal/3333320116 at sipserver.net entering state [received][100]
2013-10-01 17:50:45.310083 [DEBUG] sofia.c:5696 Remote SDP:
v=0
o=- 243381907 243381907 IN IP4 193.104.89.10
s=-
c=IN IP4 193.104.89.46
t=0 0
m=audio 60794 RTP/AVP 8 0 2 4 18 96 97 98 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:4 G723/8000
a=rtpmap:18 G729a/8000
a=rtpmap:96 G726-40/8000
a=rtpmap:97 G726-24/8000
a=rtpmap:98 G726-16/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

2013-10-01 17:50:45.310083 [DEBUG] sofia.c:5909 (sofia/internal/3333320116 at sipserver.net) State Change CS_NEW -> CS_INIT
2013-10-01 17:50:45.310083 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116 at sipserver.net) Running State Change CS_INIT
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/3333320116 at sipserver.net) State INIT
2013-10-01 17:50:45.310083 [DEBUG] mod_sofia.c:87 sofia/internal/3333320116 at sipserver.net SOFIA INIT
2013-10-01 17:50:45.310083 [DEBUG] mod_sofia.c:127 (sofia/internal/3333320116 at sipserver.net) State Change CS_INIT -> CS_ROUTING
2013-10-01 17:50:45.310083 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/3333320116 at sipserver.net) State INIT going to sleep
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116 at sipserver.net) Running State Change CS_ROUTING
2013-10-01 17:50:45.310083 [DEBUG] switch_channel.c:2034 (sofia/internal/3333320116 at sipserver.net) Callstate Change DOWN -> RINGING
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/3333320116 at sipserver.net) State ROUTING
2013-10-01 17:50:45.310083 [DEBUG] mod_sofia.c:150 sofia/internal/3333320116 at sipserver.net SOFIA ROUTING
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:117 sofia/internal/3333320116 at sipserver.net Standard ROUTING
2013-10-01 17:50:45.310083 [INFO] mod_dialplan_xml.c:557 Processing Callum Guy <3333320116>->7502 in context public
Dialplan: sofia/internal/3333320116 at sipserver.net parsing [public->unloop] continue=false
Dialplan: sofia/internal/3333320116 at sipserver.net Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/3333320116 at sipserver.net Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/3333320116 at sipserver.net parsing [public->outside_call] continue=true
Dialplan: sofia/internal/3333320116 at sipserver.net Absolute Condition [outside_call]
Dialplan: sofia/internal/3333320116 at sipserver.net Action set(outside_call=true)
Dialplan: sofia/internal/3333320116 at sipserver.net Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/3333320116 at sipserver.net parsing [public->call_debug] continue=true
Dialplan: sofia/internal/3333320116 at sipserver.net Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/3333320116 at sipserver.net parsing [public->public_extensions] continue=false
Dialplan: sofia/internal/3333320116 at sipserver.net Regex (FAIL) [public_extensions] destination_number(7502) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/3333320116 at sipserver.net parsing [public->public_did] continue=false
Dialplan: sofia/internal/3333320116 at sipserver.net Regex (FAIL) [public_did] destination_number(7502) =~ /^(5551212)$/ break=on-false
Dialplan: sofia/internal/3333320116 at sipserver.net parsing [public->sendtosocket] continue=false
Dialplan: sofia/internal/3333320116 at sipserver.net Regex (PASS) [sendtosocket] destination_number(7502) =~ /^[0-9]{1,15}$/ break=on-false
Dialplan: sofia/internal/3333320116 at sipserver.net Action socket(192.168.5.83:8084)
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:167 (sofia/internal/3333320116 at sipserver.net) State Change CS_ROUTING -> CS_EXECUTE
2013-10-01 17:50:45.310083 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:470 (sofia/internal/3333320116 at sipserver.net) State ROUTING going to sleep
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116 at sipserver.net) Running State Change CS_EXECUTE
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/3333320116 at sipserver.net) State EXECUTE
2013-10-01 17:50:45.310083 [DEBUG] mod_sofia.c:243 sofia/internal/3333320116 at sipserver.net SOFIA EXECUTE
2013-10-01 17:50:45.310083 [DEBUG] switch_core_state_machine.c:209 sofia/internal/3333320116 at sipserver.net Standard EXECUTE
EXECUTE sofia/internal/3333320116 at sipserver.net set(outside_call=true)
2013-10-01 17:50:45.310083 [DEBUG] mod_dptools.c:1373 sofia/internal/3333320116 at sipserver.net SET [outside_call]=[true]
EXECUTE sofia/internal/3333320116 at sipserver.net export(RFC2822_DATE=Tue, 01 Oct 2013 17:50:45 +0100)
2013-10-01 17:50:45.310083 [DEBUG] switch_channel.c:1145 EXPORT (export_vars) [RFC2822_DATE]=[Tue, 01 Oct 2013 17:50:45 +0100]
EXECUTE sofia/internal/3333320116 at sipserver.net socket(192.168.5.83:8084)
2013-10-01 17:50:45.340072 [DEBUG] switch_ivr.c:612 sofia/internal/3333320116 at sipserver.net Command Execute answer()
EXECUTE sofia/internal/3333320116 at sipserver.net answer()
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[G722:9:8000:20:64000]
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMU:0:8000:20:64000]
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:5176 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:3119 Set Codec sofia/internal/3333320116 at sipserver.net PCMA/8000 20 ms 160 samples 64000 bits
2013-10-01 17:50:45.340072 [DEBUG] switch_core_codec.c:111 sofia/internal/3333320116 at sipserver.net Original read codec set to PCMA:8
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:5305 Set 2833 dtmf send/recv payload to 101
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:3378 AUDIO RTP [sofia/internal/3333320116 at sipserver.net] 193.104.89.37 port 17122 -> 193.104.89.46 port 60794 codec: 8 ms: 20
2013-10-01 17:50:45.340072 [DEBUG] switch_rtp.c:1985 Starting timer [soft] 160 bytes per 20ms
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:3642 Set 2833 dtmf send payload to 101
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:3648 Set 2833 dtmf receive payload to 101
2013-10-01 17:50:45.340072 [DEBUG] sofia_glue.c:3675 sofia/internal/3333320116 at sipserver.net Set rtp dtmf delay to 40
2013-10-01 17:50:45.340072 [NOTICE] sofia_glue.c:4286 Pre-Answer sofia/internal/3333320116 at sipserver.net!
2013-10-01 17:50:45.340072 [DEBUG] switch_channel.c:3265 (sofia/internal/3333320116 at sipserver.net) Callstate Change RINGING -> EARLY
2013-10-01 17:50:45.340072 [DEBUG] mod_sofia.c:864 Local SDP sofia/internal/3333320116 at sipserver.net:
v=0
o=FreeSWITCH 1380629123 1380629124 IN IP4 193.104.89.37
s=FreeSWITCH
c=IN IP4 193.104.89.37
t=0 0
m=audio 17122 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2013-10-01 17:50:45.340072 [DEBUG] switch_core_session.c:853 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:45.340072 [NOTICE] mod_dptools.c:1205 Channel [sofia/internal/3333320116 at sipserver.net] has been answered
2013-10-01 17:50:45.340072 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:45.340072 [DEBUG] switch_channel.c:3542 (sofia/internal/3333320116 at sipserver.net) Callstate Change EARLY -> ACTIVE
2013-10-01 17:50:45.340072 [DEBUG] sofia.c:5685 Channel sofia/internal/3333320116 at sipserver.net entering state [completed][200]
2013-10-01 17:50:45.340072 [DEBUG] switch_ivr.c:612 sofia/internal/3333320116 at sipserver.net Command Execute park()
EXECUTE sofia/internal/3333320116 at sipserver.net park()
2013-10-01 17:50:45.370072 [DEBUG] switch_core_session.c:1133 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:45.380023 [DEBUG] switch_ivr.c:612 sofia/internal/3333320116 at sipserver.net Command Execute record(/usr/share/sounds/recordings/test.wav 15 200)
EXECUTE sofia/internal/3333320116 at sipserver.net record(/usr/share/sounds/recordings/test.wav 15 200)
2013-10-01 17:50:45.380023 [DEBUG] switch_ivr_play_say.c:599 Raw Codec Activated
2013-10-01 17:50:45.380023 [DEBUG] switch_core_codec.c:219 sofia/internal/3333320116 at sipserver.net Push codec L16:70
2013-10-01 17:50:45.390071 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:45.390071 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:45.390071 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:45.400072 [DEBUG] sofia.c:5685 Channel sofia/internal/3333320116 at sipserver.net entering state [ready][200]
2013-10-01 17:50:48.380081 [DEBUG] switch_core_codec.c:244 sofia/internal/3333320116 at sipserver.net Restore previous codec PCMA:8.
2013-10-01 17:50:53.910084 [DEBUG] switch_core_session.c:998 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:53.920072 [NOTICE] sofia.c:716 Hangup sofia/internal/3333320116 at sipserver.net [CS_EXECUTE] [NORMAL_CLEARING]
2013-10-01 17:50:53.920072 [DEBUG] switch_channel.c:3096 Send signal sofia/internal/3333320116 at sipserver.net [KILL]
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:2731 sofia/internal/3333320116 at sipserver.net skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-10-01 17:50:53.920072 [DEBUG] switch_ivr.c:650 sofia/internal/3333320116 at sipserver.net skip receive message [AUDIO_SYNC] (channel is hungup already)
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:2731 sofia/internal/3333320116 at sipserver.net skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:477 (sofia/internal/3333320116 at sipserver.net) State EXECUTE going to sleep
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116 at sipserver.net) Running State Change CS_HANGUP
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:676 (sofia/internal/3333320116 at sipserver.net) State HANGUP
2013-10-01 17:50:53.920072 [DEBUG] mod_sofia.c:504 Channel sofia/internal/3333320116 at sipserver.net hanging up, cause: NORMAL_CLEARING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:48 sofia/internal/3333320116 at sipserver.net Standard HANGUP, cause: NORMAL_CLEARING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:676 (sofia/internal/3333320116 at sipserver.net) State HANGUP going to sleep
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:687 (sofia/internal/3333320116 at sipserver.net) Callstate Change ACTIVE -> HANGUP
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:446 (sofia/internal/3333320116 at sipserver.net) State Change CS_HANGUP -> CS_REPORTING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:415 (sofia/internal/3333320116 at sipserver.net) Running State Change CS_REPORTING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:759 (sofia/internal/3333320116 at sipserver.net) State REPORTING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:92 sofia/internal/3333320116 at sipserver.net Standard REPORTING, cause: NORMAL_CLEARING
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:759 (sofia/internal/3333320116 at sipserver.net) State REPORTING going to sleep
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:440 (sofia/internal/3333320116 at sipserver.net) State Change CS_REPORTING -> CS_DESTROY
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:1333 Send signal sofia/internal/3333320116 at sipserver.net [BREAK]
2013-10-01 17:50:53.920072 [DEBUG] switch_core_session.c:1541 Session 301 (sofia/internal/3333320116 at sipserver.net) Locked, Waiting on external entities
2013-10-01 17:50:53.920072 [NOTICE] switch_core_session.c:1559 Session 301 (sofia/internal/3333320116 at sipserver.net) Ended
2013-10-01 17:50:53.920072 [NOTICE] switch_core_session.c:1563 Close Channel sofia/internal/3333320116 at sipserver.net [CS_DESTROY]
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/3333320116 at sipserver.net) Callstate Change HANGUP -> DOWN
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:568 (sofia/internal/3333320116 at sipserver.net) Running State Change CS_DESTROY
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/3333320116 at sipserver.net) State DESTROY
2013-10-01 17:50:53.920072 [DEBUG] mod_sofia.c:397 sofia/internal/3333320116 at sipserver.net SOFIA DESTROY
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:99 sofia/internal/3333320116 at sipserver.net Standard DESTROY
2013-10-01 17:50:53.920072 [DEBUG] switch_core_state_machine.c:578 (sofia/internal/3333320116 at sipserver.net) State DESTROY going to sleep