[Freeswitch-users] tls/srtp goes straight to voicemail

Sun Mar 6 08:15:13 MSK 2011

I'm trying to setup a secure phone call across two eyebeam clients running on Apple iPhones.

I am pretty new to Freeswitch.

The problem is that when I make a call using SRTP between the two phones it goes straight to voicemail.  I took some snippets of the debug.  Any help would be greatly appreciated.

2011-03-05 23:21:08.502797 [DEBUG] sofia.c:6451 IP 192.168.60.130 Rejected by acl "domains". Falling back to Digest auth.
2011-03-05 23:21:08.502797 [WARNING] sofia_reg.c:1246 SIP auth challenge (INVITE) on sofia profile 'internal' for [1005 at 172.16.200.60] from ip 192.168.60.130
2011-03-05 23:21:08.527274 [DEBUG] sofia.c:6451 IP 192.168.60.130 Rejected by acl "domains". Falling back to Digest auth.
2011-03-05 23:21:08.527274 [NOTICE] switch_channel.c:812 New Channel sofia/internal/1006 at 172.16.200.60 [d9976fea-1e9e-4d77-8c26-fa3bd32c4979]
2011-03-05 23:21:08.527274 [DEBUG] sofia.c:4683 Channel sofia/internal/1006 at 172.16.200.60 entering state [received][100]
2011-03-05 23:21:08.527274 [DEBUG] sofia.c:4694 Remote SDP:
v=0
o=- 3508374466 3508374466 IN IP4 192.168.60.130
s=cpc_med
c=IN IP4 192.168.60.130
t=0 0
a=X-nat:0
m=audio 4004 RTP/SAVP 0 8 104 3 96
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:104 iLBC/8000
a=fmtp:104 mode=30
a=rtpmap:3 GSM/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:znq1mGYq9Dz+5G2GY3tKNJ0gTMGfvBNeeIYKuIKZ
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:iRs0wouqlzmT6T06/K3CS9HUJmwnwkP+w1rhaDre

2011-03-05 23:21:08.527274 [DEBUG] sofia_glue.c:4415 Set Remote Key [1 AES_CM_128_HMAC_SHA1_80 inline:znq1mGYq9Dz+5G2GY3tKNJ0gTMGfvBNeeIYKuIKZ]
2011-03-05 23:21:08.527274 [DEBUG] sofia_glue.c:2821 Set Local Key [1 AES_CM_128_HMAC_SHA1_80 inline:zXMFICKxSVhKLofieTRxrWH5I35i/Bu6lkit2BbE]

......

2011-03-05 23:21:08.535483 [DEBUG] switch_core_state_machine.c:157 sofia/internal/1006 at 172.16.200.60 Standard EXECUTE
EXECUTE sofia/internal/1006 at 172.16.200.60 set(sip_secure_media=true)
2011-03-05 23:21:08.535483 [DEBUG] mod_dptools.c:1059 sofia/internal/1006 at 172.16.200.60 SET [sip_secure_media]=[true]
EXECUTE sofia/internal/1006 at 172.16.200.60 export(sip_secure_media=true)
2011-03-05 23:21:08.536478 [DEBUG] switch_channel.c:961 EXPORT (export_vars) [sip_secure_media]=[true]
EXECUTE sofia/internal/1006 at 172.16.200.60 hash(insert/172.16.200.60-spymap/1006/d9976fea-1e9e-4d77-8c26-fa3bd32c4979)
EXECUTE sofia/internal/1006 at 172.16.200.60 hash(insert/172.16.200.60-last_dial/1006/1005)
EXECUTE sofia/internal/1006 at 172.16.200.60 hash(insert/172.16.200.60-last_dial/global/d9976fea-1e9e-4d77-8c26-fa3bd32c4979)
EXECUTE sofia/internal/1006 at 172.16.200.60 set(RFC2822_DATE=Sat, 05 Mar 2011 23:21:08 -0500)
2011-03-05 23:21:08.537477 [DEBUG] mod_dptools.c:1059 sofia/internal/1006 at 172.16.200.60 SET [RFC2822_DATE]=[Sat, 05 Mar 2011 23:21:08 -0500]
EXECUTE sofia/internal/1006 at 172.16.200.60 set(dialed_extension=1005)
2011-03-05 23:21:08.538480 [DEBUG] mod_dptools.c:1059 sofia/internal/1006 at 172.16.200.60 SET [dialed_extension]=[1005]
EXECUTE sofia/internal/1006 at 172.16.200.60 export(dialed_extension=1005)
2011-03-05 23:21:08.538480 [DEBUG] switch_channel.c:961 EXPORT (export_vars) [dialed_extension]=[1005]
EXECUTE sofia/internal/1006 at 172.16.200.60 bind_meta_app(1 b s execute_extension::dx XML features)
2011-03-05 23:21:08.539474 [INFO] switch_ivr_async.c:3013 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/1006 at 172.16.200.60 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1006.2011-03-05-23-21-08.wav)

.....

EXECUTE sofia/internal/1006 at 172.16.200.60 hash(insert/172.16.200.60-last_dial/techsupport/d9976fea-1e9e-4d77-8c26-fa3bd32c4979)
EXECUTE sofia/internal/1006 at 172.16.200.60 bridge(user/1005 at 172.16.200.60)
2011-03-05 23:21:08.556511 [DEBUG] switch_channel.c:918 sofia/internal/1006 at 172.16.200.60 EXPORTING[export_vars] [sip_secure_media]=[true] to event
2011-03-05 23:21:08.556511 [DEBUG] switch_channel.c:918 sofia/internal/1006 at 172.16.200.60 EXPORTING[export_vars] [dialed_extension]=[1005] to event
2011-03-05 23:21:08.558529 [DEBUG] switch_channel.c:918 sofia/internal/1006 at 172.16.200.60 EXPORTING[export_vars] [sip_secure_media]=[true] to event
2011-03-05 23:21:08.558529 [DEBUG] switch_channel.c:918 sofia/internal/1006 at 172.16.200.60 EXPORTING[export_vars] [dialed_extension]=[1005] to event
2011-03-05 23:21:08.558529 [DEBUG] switch_ivr_originate.c:1971 variable string 0 = [sip_secure_media=false]
2011-03-05 23:21:08.558529 [DEBUG] switch_ivr_originate.c:1971 variable string 1 = [presence_id=1005 at 172.16.200.60]
2011-03-05 23:21:08.558529 [NOTICE] switch_channel.c:812 New Channel sofia/internal/sip:1005 at 192.168.60.135:53664 [aed041ea-4355-46aa-ad11-e58389f8e6d9]
2011-03-05 23:21:08.558529 [DEBUG] mod_sofia.c:4151 (sofia/internal/sip:1005 at 192.168.60.135:53664) State Change CS_NEW -> CS_INIT
2011-03-05 23:21:08.558529 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1005 at 192.168.60.135:53664 [BREAK]
2011-03-05 23:21:08.565722 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1005 at 192.168.60.135:53664) Running State Change CS_INIT
2011-03-05 23:21:08.566543 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/sip:1005 at 192.168.60.135:53664) State INIT
2011-03-05 23:21:08.566543 [DEBUG] mod_sofia.c:84 sofia/internal/sip:1005 at 192.168.60.135:53664 SOFIA INIT
2011-03-05 23:21:08.570553 [DEBUG] sofia_glue.c:2327 sip:1005 at 192.168.60.135:53710;transport=TLS Setting proxy route to sofia/internal/sip:1005 at 192.168.60.135:53664
2011-03-05 23:21:08.572076 [DEBUG] mod_sofia.c:124 (sofia/internal/sip:1005 at 192.168.60.135:53664) State Change CS_INIT -> CS_ROUTING
2011-03-05 23:21:08.572076 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1005 at 192.168.60.135:53664 [BREAK]
2011-03-05 23:21:08.572076 [DEBUG] sofia.c:4683 Channel sofia/internal/sip:1005 at 192.168.60.135:53664 entering state [calling][0]
2011-03-05 23:21:08.572076 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/sip:1005 at 192.168.60.135:53664) State INIT going to sleep
2011-03-05 23:21:08.572076 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1005 at 192.168.60.135:53664) Running State Change CS_ROUTING
2011-03-05 23:21:08.572076 [DEBUG] switch_channel.c:1664 (sofia/internal/sip:1005 at 192.168.60.135:53664) Callstate Change DOWN -> RINGING
2011-03-05 23:21:08.573709 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/sip:1005 at 192.168.60.135:53664) State ROUTING
2011-03-05 23:21:08.573709 [DEBUG] mod_sofia.c:147 sofia/internal/sip:1005 at 192.168.60.135:53664 SOFIA ROUTING
2011-03-05 23:21:08.574575 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1005 at 192.168.60.135:53664) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-03-05 23:21:08.574575 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1005 at 192.168.60.135:53664 [BREAK]
2011-03-05 23:21:08.574575 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/sip:1005 at 192.168.60.135:53664) State ROUTING going to sleep
2011-03-05 23:21:08.574575 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1005 at 192.168.60.135:53664) Running State Change CS_CONSUME_MEDIA
2011-03-05 23:21:08.574575 [DEBUG] switch_core_state_machine.c:378 (sofia/internal/sip:1005 at 192.168.60.135:53664) State CONSUME_MEDIA
2011-03-05 23:21:08.574575 [DEBUG] switch_core_state_machine.c:378 (sofia/internal/sip:1005 at 192.168.60.135:53664) State CONSUME_MEDIA going to sleep
2011-03-05 23:21:08.650486 [DEBUG] sofia.c:4683 Channel sofia/internal/sip:1005 at 192.168.60.135:53664 entering state [terminated][406]
2011-03-05 23:21:08.650486 [DEBUG] switch_channel.c:2545 (sofia/internal/sip:1005 at 192.168.60.135:53664) Callstate Change RINGING -> HANGUP
2011-03-05 23:21:08.650486 [NOTICE] sofia.c:5323 Hangup sofia/internal/sip:1005 at 192.168.60.135:53664 [CS_CONSUME_MEDIA] [SERVICE_NOT_IMPLEMENTED]
2011-03-05 23:21:08.650486 [DEBUG] switch_channel.c:2561 Send signal sofia/internal/sip:1005 at 192.168.60.135:53664 [KILL]
2011-03-05 23:21:08.650486 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1005 at 192.168.60.135:53664 [BREAK]
2011-03-05 23:21:08.652479 [DEBUG] switch_ivr_originate.c:3502 Originate Resulted in Error Cause: 79 [SERVICE_NOT_IMPLEMENTED]
2011-03-05 23:21:08.652479 [ERR] switch_ivr_originate.c:2638 Cannot create outgoing channel of type [user] cause: [SERVICE_NOT_IMPLEMENTED]
2011-03-05 23:21:08.652479 [DEBUG] switch_ivr_originate.c:3502 Originate Resulted in Error Cause: 79 [SERVICE_NOT_IMPLEMENTED]
2011-03-05 23:21:08.653662 [INFO] mod_dptools.c:2623 Originate Failed.  Cause: SERVICE_NOT_IMPLEMENTED
EXECUTE sofia/internal/1006 at 172.16.200.60 answer()
2011-03-05 23:21:08.655518 [DEBUG] sofia_glue.c:2990 AUDIO RTP [sofia/internal/1006 at 172.16.200.60] 172.16.200.60 port 22870 -> 192.168.60.130 port 4004 codec: 0 ms: 20
2011-03-05 23:21:08.656829 [DEBUG] switch_rtp.c:1621 Starting timer [soft] 160 bytes per 20ms
2011-03-05 23:21:08.658299 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1005 at 192.168.60.135:53664) Running State Change CS_HANGUP
2011-03-05 23:21:08.658299 [DEBUG] sofia_glue.c:3235 Set 2833 dtmf send payload to 96
2011-03-05 23:21:08.658299 [DEBUG] sofia_glue.c:3240 Set 2833 dtmf receive payload to 96
2011-03-05 23:21:08.658299 [INFO] switch_rtp.c:1450 Activating Secure RTP SEND
2011-03-05 23:21:08.659547 [DEBUG] switch_core_sqldb.c:1422 Secure Type: srtp:AES_CM_128_HMAC_SHA1_80
2011-03-05 23:21:08.659547 [INFO] switch_rtp.c:1430 Activating Secure RTP RECV
2011-03-05 23:21:08.659547 [DEBUG] switch_core_sqldb.c:1422 Secure Type: srtp:AES_CM_128_HMAC_SHA1_80
2011-03-05 23:21:08.659547 [DEBUG] mod_sofia.c:681 Local SDP sofia/internal/1006 at 172.16.200.60:
v=0
o=FreeSWITCH 1299362398 1299362399 IN IP4 172.16.200.60
s=FreeSWITCH
c=IN IP4 172.16.200.60
t=0 0
m=audio 22870 RTP/SAVP 0 96
a=rtpmap:0 PCMU/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:zXMFICKxSVhKLofieTRxrWH5I35i/Bu6lkit2BbE

2011-03-05 23:21:08.661306 [DEBUG] sofia.c:4683 Channel sofia/internal/1006 at 172.16.200.60 entering state [completed][200]
2011-03-05 23:21:08.661306 [DEBUG] switch_core_session.c:709 Send signal sofia/internal/1006 at 172.16.200.60 [BREAK]
2011-03-05 23:21:08.661306 [DEBUG] switch_channel.c:2795 (sofia/internal/1006 at 172.16.200.60) Callstate Change RINGING -> ACTIVE
2011-03-05 23:21:08.662543 [NOTICE] mod_dptools.c:929 Channel [sofia/internal/1006 at 172.16.200.60] has been answered
EXECUTE sofia/internal/1006 at 172.16.200.60 sleep(1000)
2011-03-05 23:21:08.664527 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/sip:1005 at 192.168.60.135:53664) State HANGUP
2011-03-05 23:21:08.665590 [DEBUG] mod_sofia.c:451 sofia/internal/sip:1005 at 192.168.60.135:53664 Overriding SIP cause 501 with 406 from the other leg
2011-03-05 23:21:08.665590 [DEBUG] mod_sofia.c:457 Channel sofia/internal/sip:1005 at 192.168.60.135:53664 hanging up, cause: SERVICE_NOT_IMPLEMENTED
2011-03-05 23:21:08.666556 [DEBUG] switch_core_state_machine.c:46 sofia/internal/sip:1005 at 192.168.60.135:53664 Standard HANGUP, cause: SERVICE_NOT_IMPLEMENTED
2011-03-05 23:21:08.666556 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/sip:1005 at 192.168.60.135:53664) State HANGUP going to sleep
2011-03-05 23:21:08.666556 [DEBUG] switch_core_state_machine.c:351 (sofia/internal/sip:1005 at 192.168.60.135:53664) State Change CS_HANGUP -> CS_REPORTING
2011-03-05 23:21:08.666556 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1005 at 192.168.60.135:53664 [BREAK]
2011-03-05 23:21:08.666556 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1005 at 192.168.60.135:53664) Running State Change CS_REPORTING
2011-03-05 23:21:08.667827 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/sip:1005 at 192.168.60.135:53664) State REPORTING
2011-03-05 23:21:08.667827 [DEBUG] switch_core_state_machine.c:53 sofia/internal/sip:1005 at 192.168.60.135:53664 Standard REPORTING, cause: SERVICE_NOT_IMPLEMENTED
2011-03-05 23:21:08.667827 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/sip:1005 at 192.168.60.135:53664) State REPORTING going to sleep
2011-03-05 23:21:08.669333 [DEBUG] switch_core_state_machine.c:345 (sofia/internal/sip:1005 at 192.168.60.135:53664) State Change CS_REPORTING -> CS_DESTROY
2011-03-05 23:21:08.669333 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/sip:1005 at 192.168.60.135:53664 [BREAK]
2011-03-05 23:21:08.669333 [DEBUG] switch_core_session.c:1288 Session 162 (sofia/internal/sip:1005 at 192.168.60.135:53664) Locked, Waiting on external entities
2011-03-05 23:21:08.669333 [NOTICE] switch_core_session.c:1306 Session 162 (sofia/internal/sip:1005 at 192.168.60.135:53664) Ended
2011-03-05 23:21:08.669333 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/sip:1005 at 192.168.60.135:53664 [CS_DESTROY]
2011-03-05 23:21:08.670544 [DEBUG] switch_core_state_machine.c:449 (sofia/internal/sip:1005 at 192.168.60.135:53664) Callstate Change HANGUP -> DOWN
2011-03-05 23:21:08.670544 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/sip:1005 at 192.168.60.135:53664) Running State Change CS_DESTROY
2011-03-05 23:21:08.671619 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/sip:1005 at 192.168.60.135:53664) State DESTROY
2011-03-05 23:21:08.671619 [DEBUG] mod_sofia.c:362 sofia/internal/sip:1005 at 192.168.60.135:53664 SOFIA DESTROY
2011-03-05 23:21:08.671619 [DEBUG] switch_core_state_machine.c:60 sofia/internal/sip:1005 at 192.168.60.135:53664 Standard DESTROY
2011-03-05 23:21:08.671619 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/sip:1005 at 192.168.60.135:53664) State DESTROY going to sleep
2011-03-05 23:21:08.742675 [DEBUG] switch_rtp.c:2989 Correct ip/port confirmed.
2011-03-05 23:21:08.742675 [DEBUG] sofia.c:4683 Channel sofia/internal/1006 at 172.16.200.60 entering state [ready][200]
EXECUTE sofia/internal/1006 at 172.16.200.60 bridge(loopback/app=voicemail:default 172.16.200.60 1005)
2011-03-05 23:21:09.682417 [DEBUG] switch_channel.c:918 sofia/internal/1006 at 172.16.200.60 EXPORTING[export_vars] [sip_secure_media]=[true] to event
2011-03-05 23:21:09.682417 [DEBUG] switch_channel.c:918 sofia/internal/1006 at 172.16.200.60 EXPORTING[export_vars] [dialed_extension]=[1005] to event
2011-03-05 23:21:09.682417 [NOTICE] switch_channel.c:812 New Channel loopback/app=voicemail:default 172.16.200.60 1005-a [f2016cad-3669-4b54-95c2-7f3a958ddca0]
2011-03-05 23:21:09.682417 [DEBUG] mod_loopback.c:131 loopback/app=voicemail:default 172.16.200.60 1005-a setup codec PCMU/8000/20
2011-03-05 23:21:09.682417 [NOTICE] switch_channel.c:810 Rename Channel loopback/app=voicemail:default 172.16.200.60 1005-a->loopback/voicemail-a [f2016cad-3669-4b54-95c2-7f3a958ddca0]
2011-03-05 23:21:09.682417 [DEBUG] mod_loopback.c:939 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT
2011-03-05 23:21:09.682417 [DEBUG] switch_core_session.c:1116 Send signal loopback/voicemail-a [BREAK]
2011-03-05 23:21:09.682417 [DEBUG] mod_loopback.c:469 loopback/voicemail-a CHANNEL KILL
2011-03-05 23:21:09.687524 [DEBUG] switch_core_state_machine.c:320 (loopback/voicemail-a) Running State Change CS_INIT
2011-03-05 23:21:09.687524 [DEBUG] switch_core_state_machine.c:356 (loopback/voicemail-a) State INIT
2011-03-05 23:21:09.687524 [NOTICE] switch_channel.c:812 New Channel loopback/voicemail-b [23eaf856-1bf2-4a84-94cc-e71178199468]
2011-03-05 23:21:09.688656 [DEBUG] mod_loopback.c:131 loopback/voicemail-b setup codec PCMU/8000/20
2011-03-05 23:21:09.689557 [DEBUG] mod_loopback.c:244 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT
2011-03-05 23:21:09.689557 [DEBUG] switch_core_session.c:1116 Send signal loopback/voicemail-b [BREAK]
2011-03-05 23:21:09.689557 [DEBUG] mod_loopback.c:469 loopback/voicemail-b CHANNEL KILL
2011-03-05 23:21:09.690598 [DEBUG] mod_loopback.c:290 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING
2011-03-05 23:21:09.690598 [DEBUG] switch_core_session.c:1116 Send signal loopback/voicemail-a [BREAK]
2011-03-05 23:21:09.690598 [DEBUG] mod_loopback.c:469 loopback/voicemail-a CHANNEL KILL
2011-03-05 23:21:09.690598 [DEBUG] switch_core_state_machine.c:356 (loopback/voicemail-a) State INIT going to sleep
2011-03-05 23:21:09.690598 [DEBUG] switch_core_state_machine.c:320 (loopback/voicemail-a) Running State Change CS_ROUTING
2011-03-05 23:21:09.690598 [DEBUG] switch_channel.c:1664 (loopback/voicemail-a) Callstate Change DOWN -> RINGING
2011-03-05 23:21:09.691794 [DEBUG] switch_core_state_machine.c:359 (loopback/voicemail-a) State ROUTING
2011-03-05 23:21:09.691794 [DEBUG] mod_loopback.c:324 loopback/voicemail-a CHANNEL ROUTING
2011-03-05 23:21:09.691794 [DEBUG] switch_ivr_originate.c:66 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-03-05 23:21:09.691794 [DEBUG] switch_core_session.c:1116 Send signal loopback/voicemail-a [BREAK]
2011-03-05 23:21:09.691794 [DEBUG] mod_loopback.c:469 loopback/voicemail-a CHANNEL KILL
2011-03-05 23:21:09.691794 [DEBUG] switch_core_state_machine.c:359 (loopback/voicemail-a) State ROUTING going to sleep
2011-03-05 23:21:09.691794 [DEBUG] switch_core_state_machine.c:320 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA
2011-03-05 23:21:09.691794 [DEBUG] switch_core_state_machine.c:378 (loopback/voicemail-a) State CONSUME_MEDIA
2011-03-05 23:21:09.691794 [DEBUG] mod_loopback.c:529 CHANNEL CONSUME_MEDIA
2011-03-05 23:21:09.693484 [DEBUG] switch_core_state_machine.c:378 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep
2011-03-05 23:21:09.693484 [DEBUG] switch_core_state_machine.c:320 (loopback/voicemail-b) Running State Change CS_INIT
2011-03-05 23:21:09.693484 [DEBUG] switch_core_state_machine.c:356 (loopback/voicemail-b) State INIT
2011-03-05 23:21:09.693484 [DEBUG] mod_loopback.c:290 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING
2011-03-05 23:21:09.693484 [DEBUG] switch_core_session.c:1116 Send signal loopback/voicemail-b [BREAK]
2011-03-05 23:21:09.693484 [DEBUG] mod_loopback.c:469 loopback/voicemail-b CHANNEL KILL
2011-03-05 23:21:09.693484 [DEBUG] switch_core_state_machine.c:356 (loopback/voicemail-b) State INIT going to sleep
2011-03-05 23:21:09.693484 [DEBUG] switch_core_state_machine.c:320 (loopback/voicemail-b) Running State Change CS_ROUTING
2011-03-05 23:21:09.693484 [DEBUG] switch_channel.c:1664 (loopback/voicemail-b) Callstate Change DOWN -> RINGING
2011-03-05 23:21:09.695557 [DEBUG] switch_core_state_machine.c:359 (loopback/voicemail-b) State ROUTING
2011-03-05 23:21:09.695557 [DEBUG] mod_loopback.c:324 loopback/voicemail-b CHANNEL ROUTING
2011-03-05 23:21:09.695557 [DEBUG] mod_loopback.c:343 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE
2011-03-05 23:21:09.695557 [DEBUG] switch_core_session.c:1116 Send signal loopback/voicemail-b [BREAK]
2011-03-05 23:21:09.695557 [DEBUG] mod_loopback.c:469 loopback/voicemail-b CHANNEL KILL
2011-03-05 23:21:09.695557 [DEBUG] switch_core_state_machine.c:359 (loopback/voicemail-b) State ROUTING going to sleep
2011-03-05 23:21:09.695557 [DEBUG] switch_core_state_machine.c:320 (loopback/voicemail-b) Running State Change CS_EXECUTE
2011-03-05 23:21:09.695557 [DEBUG] switch_core_state_machine.c:366 (loopback/voicemail-b) State EXECUTE
2011-03-05 23:21:09.695557 [DEBUG] mod_loopback.c:363 loopback/voicemail-b CHANNEL EXECUTE
2011-03-05 23:21:09.696643 [DEBUG] switch_core_state_machine.c:157 loopback/voicemail-b Standard EXECUTE
EXECUTE loopback/voicemail-b pre_answer()
2011-03-05 23:21:09.696643 [NOTICE] mod_loopback.c:722 Pre-Answer loopback/voicemail-a!
2011-03-05 23:21:09.696643 [DEBUG] switch_channel.c:2638 (loopback/voicemail-a) Callstate Change RINGING -> EARLY
2011-03-05 23:21:09.697671 [DEBUG] switch_channel.c:2689 Send signal sofia/internal/1006 at 172.16.200.60 [BREAK]
2011-03-05 23:21:09.698642 [DEBUG] switch_core_session.c:709 Send signal loopback/voicemail-b [BREAK]
2011-03-05 23:21:09.698642 [DEBUG] mod_loopback.c:469 loopback/voicemail-b CHANNEL KILL
2011-03-05 23:21:09.698642 [NOTICE] mod_dptools.c:955 Pre-Answer loopback/voicemail-b!
2011-03-05 23:21:09.698642 [DEBUG] switch_channel.c:2638 (loopback/voicemail-b) Callstate Change RINGING -> EARLY
2011-03-05 23:21:09.700393 [DEBUG] switch_channel.c:2689 Send signal sofia/internal/1006 at 172.16.200.60 [BREAK]
EXECUTE loopback/voicemail-b voicemail(default 172.16.200.60 1005)
2011-03-05 23:21:09.701645 [DEBUG] switch_ivr_originate.c:3408 Originate Resulted in Success: [loopback/voicemail-a]
2011-03-05 23:21:09.701645 [DEBUG] switch_core_session.c:709 Send signal loopback/voicemail-a [BREAK]
2011-03-05 23:21:09.701645 [DEBUG] mod_loopback.c:469 loopback/voicemail-a CHANNEL KILL
2011-03-05 23:21:09.701645 [DEBUG] switch_core_session.c:709 Send signal sofia/internal/1006 at 172.16.200.60 [BREAK]
2011-03-05 23:21:09.701645 [DEBUG] switch_ivr_bridge.c:1234 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2011-03-05 23:21:09.701645 [DEBUG] switch_core_session.c:1116 Send signal loopback/voicemail-a [BREAK]
2011-03-05 23:21:09.701645 [DEBUG] mod_loopback.c:469 loopback/voicemail-a CHANNEL KILL
2011-03-05 23:21:09.703337 [DEBUG] switch_core_state_machine.c:320 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA
2011-03-05 23:21:09.703337 [DEBUG] switch_core_state_machine.c:369 (loopback/voicemail-a) State EXCHANGE_MEDIA
2011-03-05 23:21:09.703337 [DEBUG] mod_loopback.c:491 CHANNEL LOOPBACK
2011-03-05 23:21:09.862580 [DEBUG] switch_ivr_play_say.c:63 No language specified - Using [en]
2011-03-05 23:21:09.874639 [DEBUG] switch_ivr_play_say.c:244 Handle play-file:[voicemail/vm-person.wav] (en:en)
2011-03-05 23:21:09.875636 [DEBUG] switch_ivr_play_say.c:1291 Codec Activated L16 at 8000hz 1 channels 20ms
2011-03-05 23:21:11.262410 [DEBUG] switch_ivr_play_say.c:1635 done playing file
2011-03-05 23:21:11.362431 [DEBUG] switch_ivr_play_say.c:244 Handle say:[1005] (en:en)
2011-03-05 23:21:11.362431 [DEBUG] switch_ivr_play_say.c:1291 Codec Activated L16 at 8000hz 1 channels 20ms
2011-03-05 23:21:11.370005 [DEBUG] switch_channel.c:2545 (sofia/internal/1006 at 172.16.200.60) Callstate Change ACTIVE -> HANGUP
2011-03-05 23:21:11.370005 [NOTICE] sofia.c:537 Hangup sofia/internal/1006 at 172.16.200.60 [CS_EXECUTE] [NORMAL_CLEARING]
2011-03-05 23:21:11.370005 [DEBUG] switch_channel.c:2561 Send signal sofia/internal/1006 at 172.16.200.60 [KILL]
2011-03-05 23:21:11.370005 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1006 at 172.16.200.60 [BREAK]
2011-03-05 23:21:11.381511 [DEBUG] switch_ivr_bridge.c:500 sofia/internal/1006 at 172.16.200.60 ending bridge by request from read function
2011-03-05 23:21:11.381511 [DEBUG] switch_ivr_bridge.c:581 BRIDGE THREAD DONE [sofia/internal/1006 at 172.16.200.60]
2011-03-05 23:21:11.381511 [DEBUG] switch_ivr_bridge.c:601 Send signal loopback/voicemail-a [BREAK]
2011-03-05 23:21:11.381511 [DEBUG] mod_loopback.c:469 loopback/voicemail-a CHANNEL KILL
2011-03-05 23:21:11.381511 [DEBUG] switch_ivr_bridge.c:581 BRIDGE THREAD DONE [loopback/voicemail-a]
2011-03-05 23:21:11.381511 [DEBUG] switch_ivr_bridge.c:601 Send signal sofia/internal/1006 at 172.16.200.60 [BREAK]
2011-03-05 23:21:11.381511 [DEBUG] switch_channel.c:2545 (loopback/voicemail-a) Callstate Change EARLY -> HANGUP
2011-03-05 23:21:11.381511 [NOTICE] switch_ivr_bridge.c:653 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2011-03-05 23:21:11.381511 [DEBUG] switch_channel.c:2561 Send signal loopback/voicemail-a [KILL]
2011-03-05 23:21:11.381511 [DEBUG] mod_loopback.c:469 loopback/voicemail-a CHANNEL KILL
2011-03-05 23:21:11.381511 [DEBUG] switch_core_session.c:1116 Send signal loopback/voicemail-a [BREAK]
2011-03-05 23:21:11.381511 [DEBUG] mod_loopback.c:469 loopback/voicemail-a CHANNEL KILL
2011-03-05 23:21:11.381511 [DEBUG] switch_core_state_machine.c:369 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep
2011-03-05 23:21:11.381511 [DEBUG] switch_core_state_machine.c:320 (loopback/voicemail-a) Running State Change CS_HANGUP
2011-03-05 23:21:11.381511 [DEBUG] switch_core_state_machine.c:560 (loopback/voicemail-a) State HANGUP
2011-03-05 23:21:11.381511 [DEBUG] mod_loopback.c:415 loopback/voicemail-a CHANNEL HANGUP
2011-03-05 23:21:11.381511 [DEBUG] switch_channel.c:2545 (loopback/voicemail-b) Callstate Change EARLY -> HANGUP
2011-03-05 23:21:11.381511 [NOTICE] mod_loopback.c:426 Hangup loopback/voicemail-b [CS_EXECUTE] [NORMAL_CLEARING]
2011-03-05 23:21:11.381511 [DEBUG] switch_channel.c:2561 Send signal loopback/voicemail-b [KILL]
2011-03-05 23:21:11.381511 [DEBUG] mod_loopback.c:469 loopback/voicemail-b CHANNEL KILL
2011-03-05 23:21:11.381511 [DEBUG] switch_core_session.c:1116 Send signal loopback/voicemail-b [BREAK]
2011-03-05 23:21:11.381511 [DEBUG] mod_loopback.c:469 loopback/voicemail-b CHANNEL KILL
2011-03-05 23:21:11.381511 [DEBUG] switch_core_state_machine.c:46 loopback/voicemail-a Standard HANGUP, cause: NORMAL_CLEARING
2011-03-05 23:21:11.381511 [DEBUG] switch_core_state_machine.c:560 (loopback/voicemail-a) State HANGUP going to sleep
2011-03-05 23:21:11.381511 [DEBUG] switch_core_state_machine.c:351 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING
2011-03-05 23:21:11.381511 [DEBUG] switch_core_session.c:1116 Send signal loopback/voicemail-a [BREAK]
2011-03-05 23:21:11.381511 [DEBUG] mod_loopback.c:469 loopback/voicemail-a CHANNEL KILL
2011-03-05 23:21:11.381511 [DEBUG] switch_core_state_machine.c:320 (loopback/voicemail-a) Running State Change CS_REPORTING
2011-03-05 23:21:11.381511 [DEBUG] switch_core_state_machine.c:620 (loopback/voicemail-a) State REPORTING
2011-03-05 23:21:11.381511 [DEBUG] switch_core_state_machine.c:53 loopback/voicemail-a Standard REPORTING, cause: NORMAL_CLEARING
2011-03-05 23:21:11.381511 [DEBUG] switch_core_state_machine.c:620 (loopback/voicemail-a) State REPORTING going to sleep
2011-03-05 23:21:11.381511 [DEBUG] switch_core_state_machine.c:345 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY
2011-03-05 23:21:11.381511 [DEBUG] switch_core_session.c:1116 Send signal loopback/voicemail-a [BREAK]
2011-03-05 23:21:11.381511 [DEBUG] mod_loopback.c:469 loopback/voicemail-a CHANNEL KILL
2011-03-05 23:21:11.381511 [DEBUG] switch_core_session.c:1288 Session 163 (loopback/voicemail-a) Locked, Waiting on external entities
2011-03-05 23:21:11.384116 [DEBUG] switch_ivr_bridge.c:1308 sofia/internal/1006 at 172.16.200.60 skip receive message [UNBRIDGE] (channel is hungup already)
2011-03-05 23:21:11.384116 [DEBUG] switch_core_session.c:2060 sofia/internal/1006 at 172.16.200.60 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:366 (sofia/internal/1006 at 172.16.200.60) State EXECUTE going to sleep
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1006 at 172.16.200.60) Running State Change CS_HANGUP
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/1006 at 172.16.200.60) State HANGUP
2011-03-05 23:21:11.384116 [DEBUG] mod_sofia.c:451 sofia/internal/1006 at 172.16.200.60 Overriding SIP cause 480 with 200 from the other leg
2011-03-05 23:21:11.384116 [DEBUG] mod_sofia.c:457 Channel sofia/internal/1006 at 172.16.200.60 hanging up, cause: NORMAL_CLEARING
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1006 at 172.16.200.60 Standard HANGUP, cause: NORMAL_CLEARING
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/1006 at 172.16.200.60) State HANGUP going to sleep
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:351 (sofia/internal/1006 at 172.16.200.60) State Change CS_HANGUP -> CS_REPORTING
2011-03-05 23:21:11.384116 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1006 at 172.16.200.60 [BREAK]
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1006 at 172.16.200.60) Running State Change CS_REPORTING
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/1006 at 172.16.200.60) State REPORTING
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1006 at 172.16.200.60 Standard REPORTING, cause: NORMAL_CLEARING
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/1006 at 172.16.200.60) State REPORTING going to sleep
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:345 (sofia/internal/1006 at 172.16.200.60) State Change CS_REPORTING -> CS_DESTROY
2011-03-05 23:21:11.384116 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1006 at 172.16.200.60 [BREAK]
2011-03-05 23:21:11.384116 [DEBUG] switch_core_session.c:1288 Session 161 (sofia/internal/1006 at 172.16.200.60) Locked, Waiting on external entities
2011-03-05 23:21:11.384116 [NOTICE] switch_core_session.c:1306 Session 161 (sofia/internal/1006 at 172.16.200.60) Ended
2011-03-05 23:21:11.384116 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/1006 at 172.16.200.60 [CS_DESTROY]
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:449 (sofia/internal/1006 at 172.16.200.60) Callstate Change HANGUP -> DOWN
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:452 (sofia/internal/1006 at 172.16.200.60) Running State Change CS_DESTROY
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/1006 at 172.16.200.60) State DESTROY
2011-03-05 23:21:11.384116 [DEBUG] mod_sofia.c:362 sofia/internal/1006 at 172.16.200.60 SOFIA DESTROY
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1006 at 172.16.200.60 Standard DESTROY
2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/1006 at 172.16.200.60) State DESTROY going to sleep 

I'm not sure how to avoid so much output, but I hope it's enough information to sort this out.

Thanks,

Mitch	