[Freeswitch-dev] Google Voice incoming calls

Oleg Khovayko khovayko at gmail.com
Sun Sep 5 07:36:07 PDT 2010


Hi,

I very excited with your new feature: support GV in the FreeSWITCH.
This is real and valuable asset, and I definitely plan to use it.

Yesterday, Sep 4, I fetch new FS tree by GIT, build and install.
Outgoing calls through GV works OK.

But, I faced 2 problems with incoming calls.

1. When calls comes in, phone rings.
But, when I pick up handset on recipient's phone, I hear nothing.
In the caller's handset,I continue hear long beeps. And, thereafter,
in ~30s, GVs answering machine activated.
Looks like GV doesn't understand, when I pick up handset on recepient's
phone.
I tried couple times, with 2 phones: X-lite softphone and VM1188T SIP phone.
Result is same. Can you help me to resolve this problem? Log following.



2. When call comes from GV, on the phone, in the CID line, i see message 
"Google Voice".
In the logs, I see Caller's Number in the line:

2010-09-05 09:27:32.554417 [DEBUG] mod_dingaling.c:3066 Creating an 
identity for SIP1182451466 at 10.218.25.84 Google Voice <+12404760839> 1002

This meaning, CID sending correct. Problem in the both my phones, they 
shows CID Name only.
I have fixed it, by adding into dialplan "public" following XML code:

<extension name="Fix CID" continue="true">
<condition field="caller_id_name" expression="^Google Voice">
<action application="set" 
data="effective_caller_id_name=${caller_id_number}"/>
</condition>
</extension>


RESUME:
Please, help me with [1], and add [2] onto WIKI about GV call, if you 
found it interesting.







Following - log of the unsuccessful call through GV->dingaling

2010-09-05 09:26:48.363159 [DEBUG] sofia_reg.c:1583 Changing expire time 
to 60 by request of proxy sip:callcentric.com
2010-09-05 09:26:48.455464 [DEBUG] sofia_reg.c:1583 Changing expire time 
to 60 by request of proxy sip:callcentric.com
2010-09-05 09:27:15.336517 [DEBUG] sofia_reg.c:1583 Changing expire time 
to 61 by request of proxy sip:callcentric.com
2010-09-05 09:27:20.332705 [DEBUG] sofia_reg.c:1583 Changing expire time 
to 61 by request of proxy sip:callcentric.com
2010-09-05 09:27:32.554417 [DEBUG] mod_dingaling.c:1002 Send Candidate 
192.168.1.5:31596 [OfpLNJrFNLpxHUnK]
2010-09-05 09:27:32.554417 [DEBUG] mod_dingaling.c:3066 Creating an 
identity for SIP1182451466 at 10.218.25.84 Google Voice <+12404760839> 1002
2010-09-05 09:27:32.554417 [NOTICE] switch_channel.c:779 New Channel 
dingaling/1002 [dc89b256-f1b8-df11-8091-005004c3cb7e]
2010-09-05 09:27:32.554417 [DEBUG] mod_dingaling.c:3094 Creating a 
session for SIP1182451466 at 10.218.25.84
2010-09-05 09:27:32.554417 [NOTICE] switch_channel.c:777 Rename Channel 
dingaling/1002->DingaLing/new [dc89b256-f1b8-df11-8091-005004c3cb7e]
2010-09-05 09:27:32.554417 [DEBUG] mod_dingaling.c:3098 (DingaLing/new) 
State Change CS_NEW -> CS_INIT
2010-09-05 09:27:32.554417 [DEBUG] switch_core_session.c:1039 Send 
signal DingaLing/new [BREAK]
2010-09-05 09:27:32.554417 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:32.554417 [DEBUG] mod_dingaling.c:3200 2 payloads
2010-09-05 09:27:32.554417 [DEBUG] mod_dingaling.c:3202 Available 
Payload PCMU 0
2010-09-05 09:27:32.554417 [DEBUG] mod_dingaling.c:3210 compare PCMU 
0/8000 to PCMU 0/8000
2010-09-05 09:27:32.554417 [DEBUG] mod_dingaling.c:3221 Choosing Payload 
index 0 PCMU 0
2010-09-05 09:27:32.554417 [DEBUG] mod_dingaling.c:1077 Send Describe 
[PCMU at 8000]
2010-09-05 09:27:32.562847 [DEBUG] switch_core_state_machine.c:314 
(DingaLing/new) Running State Change CS_INIT
2010-09-05 09:27:32.562847 [DEBUG] switch_core_state_machine.c:338 
(DingaLing/new) State INIT
2010-09-05 09:27:32.562847 [NOTICE] mod_dingaling.c:1104 Ring-Ready 
DingaLing/new!
2010-09-05 09:27:32.795806 [DEBUG] mod_dingaling.c:2934 using Existing 
session for SIP1182451466 at 10.218.25.84
2010-09-05 09:27:32.795806 [DEBUG] mod_dingaling.c:3272 3 candidates
2010-09-05 09:27:32.795806 [DEBUG] mod_dingaling.c:3292 candidate 
74.125.93.126:19295 PASS ACL wan.auto
2010-09-05 09:27:32.795806 [DEBUG] mod_dingaling.c:3344 Acceptable 
Candidate 74.125.93.126:19295
2010-09-05 09:27:32.800152 [DEBUG] mod_dingaling.c:859 Set Read Codec to 
PCMU at 8000
2010-09-05 09:27:32.800152 [DEBUG] mod_dingaling.c:874 Set Write Codec 
to PCMU at 8000
2010-09-05 09:27:35.151687 [DEBUG] switch_nat.c:500 mapped public port 
31596 protocol UDP to localport 31596
2010-09-05 09:27:35.151687 [DEBUG] mod_dingaling.c:886 SETUP RTP 
192.168.1.5:31596 -> 74.125.93.126:19295
2010-09-05 09:27:35.151687 [DEBUG] switch_rtp.c:1413 Starting timer 
[soft] 160 bytes per 20ms
2010-09-05 09:27:35.156967 [DEBUG] switch_rtp.c:3545 Activate VAD codec 
PCMU 20ms
2010-09-05 09:27:35.156967 [DEBUG] mod_dingaling.c:1199 (DingaLing/new) 
State Change CS_INIT -> CS_ROUTING
2010-09-05 09:27:35.156967 [DEBUG] switch_core_session.c:1039 Send 
signal DingaLing/new [BREAK]
2010-09-05 09:27:35.156967 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:338 
(DingaLing/new) State INIT going to sleep
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:314 
(DingaLing/new) Running State Change CS_ROUTING
2010-09-05 09:27:35.156967 [DEBUG] switch_channel.c:1512 (DingaLing/new) 
Callstate Change DOWN -> RINGING
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:341 
(DingaLing/new) State ROUTING
2010-09-05 09:27:35.156967 [DEBUG] mod_dingaling.c:1213 DingaLing/new 
CHANNEL ROUTING
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:77 
DingaLing/new Standard ROUTING
2010-09-05 09:27:35.156967 [INFO] mod_dialplan_xml.c:331 Processing 
Google Voice <+12404760839>->1002 in context public
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:119 
(DingaLing/new) State Change CS_ROUTING -> CS_EXECUTE
2010-09-05 09:27:35.156967 [DEBUG] switch_core_session.c:1039 Send 
signal DingaLing/new [BREAK]
2010-09-05 09:27:35.156967 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:341 
(DingaLing/new) State ROUTING going to sleep
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:314 
(DingaLing/new) Running State Change CS_EXECUTE
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:348 
(DingaLing/new) State EXECUTE
2010-09-05 09:27:35.156967 [DEBUG] mod_dingaling.c:1230 DingaLing/new 
CHANNEL EXECUTE
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:157 
DingaLing/new Standard EXECUTE
2010-09-05 09:27:35.156967 [DEBUG] mod_dptools.c:854 DingaLing/new SET 
[outside_call]=[true]
2010-09-05 09:27:35.156967 [DEBUG] mod_dptools.c:854 DingaLing/new SET 
[bypass_media]=[false]
2010-09-05 09:27:35.156967 [DEBUG] switch_ivr.c:1470 (DingaLing/new) 
State Change CS_EXECUTE -> CS_ROUTING
2010-09-05 09:27:35.156967 [DEBUG] switch_core_session.c:1039 Send 
signal DingaLing/new [BREAK]
2010-09-05 09:27:35.156967 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:35.156967 [DEBUG] switch_core_session.c:658 Send signal 
DingaLing/new [BREAK]
2010-09-05 09:27:35.156967 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:35.156967 [NOTICE] switch_ivr.c:1476 Transfer 
DingaLing/new to XML[1002 at default]
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:348 
(DingaLing/new) State EXECUTE going to sleep
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:314 
(DingaLing/new) Running State Change CS_ROUTING
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:341 
(DingaLing/new) State ROUTING
2010-09-05 09:27:35.156967 [DEBUG] mod_dingaling.c:1213 DingaLing/new 
CHANNEL ROUTING
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:77 
DingaLing/new Standard ROUTING
2010-09-05 09:27:35.156967 [INFO] mod_dialplan_xml.c:331 Processing 
Google Voice <+12404760839>->1002 in context default
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:119 
(DingaLing/new) State Change CS_ROUTING -> CS_EXECUTE
2010-09-05 09:27:35.156967 [DEBUG] switch_core_session.c:1039 Send 
signal DingaLing/new [BREAK]
2010-09-05 09:27:35.156967 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:341 
(DingaLing/new) State ROUTING going to sleep
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:314 
(DingaLing/new) Running State Change CS_EXECUTE
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:348 
(DingaLing/new) State EXECUTE
2010-09-05 09:27:35.156967 [DEBUG] mod_dingaling.c:1230 DingaLing/new 
CHANNEL EXECUTE
2010-09-05 09:27:35.156967 [DEBUG] switch_core_state_machine.c:157 
DingaLing/new Standard EXECUTE
2010-09-05 09:27:35.156967 [DEBUG] mod_dptools.c:854 DingaLing/new SET 
[dialed_extension]=[1002]
2010-09-05 09:27:35.156967 [DEBUG] mod_dptools.c:938 EXPORT 
[dialed_extension]=[1002]
2010-09-05 09:27:35.156967 [INFO] switch_ivr_async.c:2464 Bound B-Leg: 
*1 execute_extension::dx XML features
EXECUTE DingaLing/new bind_meta_app(2 b s 
record_session::/usr/local/freeswitch/recordings/+12404760839.2010-09-05-09-27-35.wav)
2010-09-05 09:27:35.156967 [INFO] switch_ivr_async.c:2464 Bound B-Leg: 
*2 
record_session::/usr/local/freeswitch/recordings/+12404760839.2010-09-05-09-27-35.wav
2010-09-05 09:27:35.156967 [INFO] switch_ivr_async.c:2464 Bound B-Leg: 
*3 execute_extension::cf XML features
2010-09-05 09:27:35.156967 [DEBUG] mod_dptools.c:854 DingaLing/new SET 
[ringback]=[%(2000,4000,440.0,480.0)]
2010-09-05 09:27:35.156967 [DEBUG] mod_dptools.c:854 DingaLing/new SET 
[transfer_ringback]=[local_stream://moh]
2010-09-05 09:27:35.156967 [DEBUG] mod_dptools.c:854 DingaLing/new SET 
[call_timeout]=[30]
2010-09-05 09:27:35.156967 [DEBUG] mod_dptools.c:854 DingaLing/new SET 
[hangup_after_bridge]=[true]
2010-09-05 09:27:35.156967 [DEBUG] mod_dptools.c:854 DingaLing/new SET 
[continue_on_fail]=[true]
2010-09-05 09:27:35.156967 [DEBUG] mod_dptools.c:854 DingaLing/new SET 
[called_party_callgroup]=[techsupport]
2010-09-05 09:27:35.266981 [DEBUG] switch_ivr_originate.c:1979 variable 
string 0 = [presence_id=1002 at 192.168.1.5]
2010-09-05 09:27:35.266981 [NOTICE] switch_channel.c:779 New Channel 
sofia/internal/sip:1002 at 173.79.240.220:42889 
[6de15b58-f1b8-df11-8091-005004c3cb7e]
2010-09-05 09:27:35.266981 [DEBUG] mod_sofia.c:3899 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State Change CS_NEW -> 
CS_INIT
2010-09-05 09:27:35.266981 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002 at 173.79.240.220:42889 [BREAK]
2010-09-05 09:27:35.840736 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Running State Change CS_INIT
2010-09-05 09:27:35.840736 [DEBUG] switch_core_state_machine.c:338 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State INIT
2010-09-05 09:27:35.840736 [DEBUG] mod_sofia.c:83 
sofia/internal/sip:1002 at 173.79.240.220:42889 SOFIA INIT
2010-09-05 09:27:38.271136 [DEBUG] switch_nat.c:500 mapped public port 
26562 protocol UDP to localport 26562
2010-09-05 09:27:40.682970 [DEBUG] switch_nat.c:500 mapped public port 
26563 protocol UDP to localport 26563
2010-09-05 09:27:40.682970 [DEBUG] sofia_glue.c:2036 
sip:1002 at 173.79.240.220:42889;rinstance=67bf5b5a98c827e0 Setting proxy 
route to sofia/internal/sip:1002 at 173.79.240.220:42889
2010-09-05 09:27:40.692198 [DEBUG] mod_sofia.c:119 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State Change CS_INIT -> 
CS_ROUTING
2010-09-05 09:27:40.692198 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002 at 173.79.240.220:42889 [BREAK]
2010-09-05 09:27:40.692198 [DEBUG] switch_core_state_machine.c:338 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State INIT going to sleep
2010-09-05 09:27:40.692198 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Running State Change 
CS_ROUTING
2010-09-05 09:27:40.692198 [DEBUG] switch_channel.c:1512 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Callstate Change DOWN -> 
RINGING
2010-09-05 09:27:40.692198 [DEBUG] switch_core_state_machine.c:341 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State ROUTING
2010-09-05 09:27:40.692198 [DEBUG] mod_sofia.c:142 
sofia/internal/sip:1002 at 173.79.240.220:42889 SOFIA ROUTING
2010-09-05 09:27:40.692198 [DEBUG] switch_ivr_originate.c:66 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State Change CS_ROUTING 
-> CS_CONSUME_MEDIA
2010-09-05 09:27:40.692198 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002 at 173.79.240.220:42889 [BREAK]
2010-09-05 09:27:40.692198 [DEBUG] switch_core_state_machine.c:341 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State ROUTING going to sleep
2010-09-05 09:27:40.692198 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Running State Change 
CS_CONSUME_MEDIA
2010-09-05 09:27:40.692198 [DEBUG] switch_core_state_machine.c:360 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State CONSUME_MEDIA
2010-09-05 09:27:40.692198 [DEBUG] switch_core_state_machine.c:360 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State CONSUME_MEDIA going 
to sleep
2010-09-05 09:27:40.702461 [DEBUG] sofia.c:4405 Channel 
sofia/internal/sip:1002 at 173.79.240.220:42889 entering state [calling][0]
2010-09-05 09:27:40.767237 [INFO] sofia.c:709 
sofia/internal/sip:1002 at 173.79.240.220:42889 Update Callee ID to "1002" 
<1002>
2010-09-05 09:27:40.841074 [DEBUG] sofia.c:4405 Channel 
sofia/internal/sip:1002 at 173.79.240.220:42889 entering state 
[proceeding][180]
2010-09-05 09:27:40.841074 [NOTICE] sofia.c:4477 Ring-Ready 
sofia/internal/sip:1002 at 173.79.240.220:42889!
2010-09-05 09:27:40.852851 [DEBUG] switch_core_session.c:658 Send signal 
DingaLing/new [BREAK]
2010-09-05 09:27:40.852851 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:40.852851 [NOTICE] switch_ivr_originate.c:1079 
Pre-Answer DingaLing/new!
2010-09-05 09:27:40.852851 [DEBUG] switch_channel.c:2409 (DingaLing/new) 
Callstate Change RINGING -> EARLY
2010-09-05 09:27:40.852851 [DEBUG] switch_ivr_originate.c:1128 Raw Codec 
Activation Success L16 at 8000hz 1 channel 20ms
2010-09-05 09:27:40.852851 [DEBUG] switch_core_codec.c:116 DingaLing/new 
Push codec L16:10
2010-09-05 09:27:40.852851 [DEBUG] switch_ivr_originate.c:1193 Play 
Ringback Tone [%(2000,4000,440.0,480.0)]
2010-09-05 09:27:40.942585 [DEBUG] switch_rtp.c:2527 Correct ip/port 
confirmed.
2010-09-05 09:27:46.853579 [DEBUG] sofia.c:4405 Channel 
sofia/internal/sip:1002 at 173.79.240.220:42889 entering state 
[completing][200]
2010-09-05 09:27:46.853579 [DEBUG] sofia.c:4416 Remote SDP:
2010-09-05 09:27:46.860768 [DEBUG] sofia.c:4405 Channel 
sofia/internal/sip:1002 at 173.79.240.220:42889 entering state [ready][200]
2010-09-05 09:27:46.860768 [DEBUG] sofia_glue.c:3851 Audio Codec Compare 
[PCMU:0:8000:20]/[PCMU:0:8000:20]
2010-09-05 09:27:46.860768 [DEBUG] sofia_glue.c:2446 Set Codec 
sofia/internal/sip:1002 at 173.79.240.220:42889 PCMU/8000 20 ms 160 samples
2010-09-05 09:27:46.860768 [DEBUG] sofia_glue.c:3941 Set 2833 dtmf send 
payload to 101
2010-09-05 09:27:46.860768 [DEBUG] sofia_glue.c:2686 AUDIO RTP 
[sofia/internal/sip:1002 at 173.79.240.220:42889] 192.168.1.5 port 26562 -> 
192.168.1.8 port 43976 codec: 0 ms: 20
2010-09-05 09:27:46.860768 [DEBUG] switch_rtp.c:1413 Starting timer 
[soft] 160 bytes per 20ms
2010-09-05 09:27:46.879728 [DEBUG] sofia_glue.c:2896 Set 2833 dtmf send 
payload to 101
2010-09-05 09:27:46.879728 [DEBUG] sofia_glue.c:2901 Set 2833 dtmf 
receive payload to 101
2010-09-05 09:27:46.879728 [DEBUG] switch_channel.c:2555 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Callstate Change RINGING 
-> ACTIVE
2010-09-05 09:27:46.879728 [DEBUG] switch_channel.c:2567 Send signal 
DingaLing/new [BREAK]
2010-09-05 09:27:46.879728 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:46.879728 [NOTICE] sofia.c:4963 Channel 
[sofia/internal/sip:1002 at 173.79.240.220:42889] has been answered
2010-09-05 09:27:46.929612 [DEBUG] switch_core_codec.c:140 DingaLing/new 
Restore previous codec PCMU:0.
2010-09-05 09:27:46.929612 [DEBUG] switch_core_session.c:658 Send signal 
DingaLing/new [BREAK]
2010-09-05 09:27:46.929612 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:46.929612 [DEBUG] switch_channel.c:2555 (DingaLing/new) 
Callstate Change EARLY -> ACTIVE
2010-09-05 09:27:46.929612 [NOTICE] switch_ivr_originate.c:3315 Channel 
[DingaLing/new] has been answered
2010-09-05 09:27:46.929612 [DEBUG] switch_ivr_originate.c:3360 Originate 
Resulted in Success: [sofia/internal/sip:1002 at 173.79.240.220:42889]
2010-09-05 09:27:46.929612 [DEBUG] switch_ivr_originate.c:3360 Originate 
Resulted in Success: [sofia/internal/sip:1002 at 173.79.240.220:42889]
2010-09-05 09:27:46.929612 [DEBUG] switch_core_session.c:658 Send signal 
sofia/internal/sip:1002 at 173.79.240.220:42889 [BREAK]
2010-09-05 09:27:46.929612 [DEBUG] switch_core_session.c:658 Send signal 
DingaLing/new [BREAK]
2010-09-05 09:27:46.929612 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:46.929612 [DEBUG] switch_ivr_bridge.c:1186 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State Change 
CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2010-09-05 09:27:46.929612 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002 at 173.79.240.220:42889 [BREAK]
2010-09-05 09:27:46.977702 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Running State Change 
CS_EXCHANGE_MEDIA
2010-09-05 09:27:46.977702 [DEBUG] switch_core_state_machine.c:351 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State EXCHANGE_MEDIA
2010-09-05 09:27:46.977702 [DEBUG] mod_sofia.c:548 SOFIA EXCHANGE_MEDIA
2010-09-05 09:27:46.977702 [DEBUG] switch_core_session.c:720 Send signal 
sofia/internal/sip:1002 at 173.79.240.220:42889 [BREAK]
2010-09-05 09:27:46.977702 [DEBUG] switch_core_session.c:720 Send signal 
DingaLing/new [BREAK]
2010-09-05 09:27:46.977702 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:47.241475 [INFO] switch_rtp.c:2510 Auto Changing port 
from 192.168.1.8:43976 to 173.79.240.220:43976
2010-09-05 09:27:47.261722 [DEBUG] mod_dingaling.c:2934 using Existing 
session for SIP1182451466 at 10.218.25.84
2010-09-05 09:27:47.261722 [DEBUG] mod_dingaling.c:3404 hungup DingaLing/new
2010-09-05 09:27:47.261722 [DEBUG] mod_dingaling.c:704 Terminate called 
from line 3405 state=CS_EXECUTE
2010-09-05 09:27:47.261722 [DEBUG] switch_channel.c:2322 (DingaLing/new) 
Callstate Change ACTIVE -> HANGUP
2010-09-05 09:27:47.261722 [NOTICE] mod_dingaling.c:725 Hangup 
DingaLing/new [CS_EXECUTE] [NORMAL_CLEARING]
2010-09-05 09:27:47.261722 [DEBUG] switch_channel.c:2338 Send signal 
DingaLing/new [KILL]
2010-09-05 09:27:47.261722 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:47.261722 [DEBUG] switch_core_session.c:1039 Send 
signal DingaLing/new [BREAK]
2010-09-05 09:27:47.261722 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:47.261722 [DEBUG] mod_dingaling.c:3406 End Call
2010-09-05 09:27:47.295949 [DEBUG] switch_ivr_bridge.c:473 DingaLing/new 
ending bridge by request from write function
2010-09-05 09:27:47.295949 [DEBUG] switch_ivr_bridge.c:560 BRIDGE THREAD 
DONE [sofia/internal/sip:1002 at 173.79.240.220:42889]
2010-09-05 09:27:47.295949 [DEBUG] switch_ivr_bridge.c:580 Send signal 
DingaLing/new [BREAK]
2010-09-05 09:27:47.295949 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:47.295949 [DEBUG] switch_channel.c:2322 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Callstate Change ACTIVE 
-> HANGUP
2010-09-05 09:27:47.295949 [NOTICE] switch_ivr_bridge.c:632 Hangup 
sofia/internal/sip:1002 at 173.79.240.220:42889 [CS_EXCHANGE_MEDIA] 
[NORMAL_CLEARING]
2010-09-05 09:27:47.295949 [DEBUG] switch_channel.c:2338 Send signal 
sofia/internal/sip:1002 at 173.79.240.220:42889 [KILL]
2010-09-05 09:27:47.295949 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002 at 173.79.240.220:42889 [BREAK]
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:351 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State EXCHANGE_MEDIA 
going to sleep
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Running State Change 
CS_HANGUP
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:535 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State HANGUP
2010-09-05 09:27:47.295949 [DEBUG] mod_sofia.c:453 Channel 
sofia/internal/sip:1002 at 173.79.240.220:42889 hanging up, cause: 
NORMAL_CLEARING
2010-09-05 09:27:47.295949 [DEBUG] switch_ivr_bridge.c:479 DingaLing/new 
ending bridge by request from read function
2010-09-05 09:27:47.295949 [DEBUG] switch_ivr_bridge.c:560 BRIDGE THREAD 
DONE [DingaLing/new]
2010-09-05 09:27:47.295949 [DEBUG] switch_ivr_bridge.c:580 Send signal 
sofia/internal/sip:1002 at 173.79.240.220:42889 [BREAK]
2010-09-05 09:27:47.295949 [DEBUG] switch_ivr_bridge.c:1257 
sofia/internal/sip:1002 at 173.79.240.220:42889 skip receive message 
[UNBRIDGE] (channel is hungup already)
2010-09-05 09:27:47.295949 [DEBUG] switch_ivr_bridge.c:1260 
DingaLing/new skip receive message [UNBRIDGE] (channel is hungup already)
2010-09-05 09:27:47.295949 [DEBUG] switch_core_session.c:1909 
DingaLing/new skip receive message [APPLICATION_EXEC_COMPLETE] (channel 
is hungup already)
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:348 
(DingaLing/new) State EXECUTE going to sleep
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:314 
(DingaLing/new) Running State Change CS_HANGUP
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:535 
(DingaLing/new) State HANGUP
2010-09-05 09:27:47.295949 [DEBUG] mod_dingaling.c:1310 DingaLing/new 
CHANNEL HANGUP
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:46 
DingaLing/new Standard HANGUP, cause: NORMAL_CLEARING
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:535 
(DingaLing/new) State HANGUP going to sleep
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:333 
(DingaLing/new) State Change CS_HANGUP -> CS_REPORTING
2010-09-05 09:27:47.295949 [DEBUG] switch_core_session.c:1039 Send 
signal DingaLing/new [BREAK]
2010-09-05 09:27:47.295949 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:314 
(DingaLing/new) Running State Change CS_REPORTING
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:595 
(DingaLing/new) State REPORTING
2010-09-05 09:27:47.295949 [DEBUG] mod_sofia.c:496 Sending BYE to 
sofia/internal/sip:1002 at 173.79.240.220:42889
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:53 
DingaLing/new Standard REPORTING, cause: NORMAL_CLEARING
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:595 
(DingaLing/new) State REPORTING going to sleep
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:327 
(DingaLing/new) State Change CS_REPORTING -> CS_DESTROY
2010-09-05 09:27:47.295949 [DEBUG] switch_core_session.c:1039 Send 
signal DingaLing/new [BREAK]
2010-09-05 09:27:47.295949 [DEBUG] mod_dingaling.c:1341 DingaLing/new 
CHANNEL KILL
2010-09-05 09:27:47.295949 [DEBUG] switch_core_session.c:1202 Session 1 
(DingaLing/new) Locked, Waiting on external entities
2010-09-05 09:27:47.295949 [NOTICE] switch_core_session.c:1220 Session 1 
(DingaLing/new) Ended
2010-09-05 09:27:47.295949 [NOTICE] switch_core_session.c:1222 Close 
Channel DingaLing/new [CS_DESTROY]
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:427 
(DingaLing/new) Callstate Change HANGUP -> DOWN
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:430 
(DingaLing/new) Running State Change CS_DESTROY
2010-09-05 09:27:47.295949 [DEBUG] switch_core_state_machine.c:440 
(DingaLing/new) State DESTROY
2010-09-05 09:27:47.295949 [DEBUG] mod_dingaling.c:1246 NUKE RTP
2010-09-05 09:27:47.412489 [DEBUG] switch_core_state_machine.c:46 
sofia/internal/sip:1002 at 173.79.240.220:42889 Standard HANGUP, cause: 
NORMAL_CLEARING
2010-09-05 09:27:47.412489 [DEBUG] switch_core_state_machine.c:535 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State HANGUP going to sleep
2010-09-05 09:27:47.412489 [DEBUG] switch_core_state_machine.c:333 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State Change CS_HANGUP -> 
CS_REPORTING
2010-09-05 09:27:47.412489 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002 at 173.79.240.220:42889 [BREAK]
2010-09-05 09:27:47.412489 [DEBUG] switch_core_state_machine.c:314 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Running State Change 
CS_REPORTING
2010-09-05 09:27:47.412489 [DEBUG] switch_core_state_machine.c:595 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State REPORTING
2010-09-05 09:27:47.412489 [DEBUG] switch_core_state_machine.c:53 
sofia/internal/sip:1002 at 173.79.240.220:42889 Standard REPORTING, cause: 
NORMAL_CLEARING
2010-09-05 09:27:47.412489 [DEBUG] switch_core_state_machine.c:595 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State REPORTING going to 
sleep
2010-09-05 09:27:47.412489 [DEBUG] switch_core_state_machine.c:327 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State Change CS_REPORTING 
-> CS_DESTROY
2010-09-05 09:27:47.412489 [DEBUG] switch_core_session.c:1039 Send 
signal sofia/internal/sip:1002 at 173.79.240.220:42889 [BREAK]
2010-09-05 09:27:47.412489 [DEBUG] switch_core_session.c:1202 Session 2 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Locked, Waiting on 
external entities
2010-09-05 09:27:47.412489 [NOTICE] switch_core_session.c:1220 Session 2 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Ended
2010-09-05 09:27:47.412489 [NOTICE] switch_core_session.c:1222 Close 
Channel sofia/internal/sip:1002 at 173.79.240.220:42889 [CS_DESTROY]
2010-09-05 09:27:47.412489 [DEBUG] switch_core_state_machine.c:427 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Callstate Change HANGUP 
-> DOWN
2010-09-05 09:27:47.412489 [DEBUG] switch_core_state_machine.c:430 
(sofia/internal/sip:1002 at 173.79.240.220:42889) Running State Change 
CS_DESTROY
2010-09-05 09:27:47.412489 [DEBUG] switch_core_state_machine.c:440 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State DESTROY
2010-09-05 09:27:47.412489 [DEBUG] mod_sofia.c:358 
sofia/internal/sip:1002 at 173.79.240.220:42889 SOFIA DESTROY
2010-09-05 09:27:47.533113 [DEBUG] switch_nat.c:560 unmapped public port 
31596 protocol UDP to localport 31596
2010-09-05 09:27:47.533113 [DEBUG] switch_core_state_machine.c:60 
DingaLing/new Standard DESTROY
2010-09-05 09:27:47.533113 [DEBUG] switch_core_state_machine.c:440 
(DingaLing/new) State DESTROY going to sleep
2010-09-05 09:27:47.533113 [DEBUG] switch_nat.c:560 unmapped public port 
26562 protocol UDP to localport 26562
2010-09-05 09:27:47.642883 [DEBUG] switch_nat.c:560 unmapped public port 
26563 protocol UDP to localport 26563
2010-09-05 09:27:47.642883 [DEBUG] switch_core_state_machine.c:60 
sofia/internal/sip:1002 at 173.79.240.220:42889 Standard DESTROY
2010-09-05 09:27:47.642883 [DEBUG] switch_core_state_machine.c:440 
(sofia/internal/sip:1002 at 173.79.240.220:42889) State DESTROY going to sleep
2010-09-05 09:27:48.361715 [DEBUG] sofia_reg.c:1583 Changing expire time 
to 62 by request of proxy sip:callcentric.com




More information about the FreeSWITCH-dev mailing list