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@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@172.16.200.60 [d9976fea-1e9e-4d77-8c26-fa3bd32c4979] 2011-03-05 23:21:08.527274 [DEBUG] sofia.c:4683 Channel sofia/internal/1006@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@172.16.200.60 Standard EXECUTE EXECUTE sofia/internal/1006@172.16.200.60 set(sip_secure_media=true) 2011-03-05 23:21:08.535483 [DEBUG] mod_dptools.c:1059 sofia/internal/1006@172.16.200.60 SET [sip_secure_media]=[true] EXECUTE sofia/internal/1006@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@172.16.200.60 hash(insert/172.16.200.60-spymap/1006/d9976fea-1e9e-4d77-8c26-fa3bd32c4979) EXECUTE sofia/internal/1006@172.16.200.60 hash(insert/172.16.200.60-last_dial/1006/1005) EXECUTE sofia/internal/1006@172.16.200.60 hash(insert/172.16.200.60-last_dial/global/d9976fea-1e9e-4d77-8c26-fa3bd32c4979) EXECUTE sofia/internal/1006@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@172.16.200.60 SET [RFC2822_DATE]=[Sat, 05 Mar 2011 23:21:08 -0500] EXECUTE sofia/internal/1006@172.16.200.60 set(dialed_extension=1005) 2011-03-05 23:21:08.538480 [DEBUG] mod_dptools.c:1059 sofia/internal/1006@172.16.200.60 SET [dialed_extension]=[1005] EXECUTE sofia/internal/1006@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@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@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@172.16.200.60 hash(insert/172.16.200.60-last_dial/techsupport/d9976fea-1e9e-4d77-8c26-fa3bd32c4979) EXECUTE sofia/internal/1006@172.16.200.60 bridge(user/1005@172.16.200.60) 2011-03-05 23:21:08.556511 [DEBUG] switch_channel.c:918 sofia/internal/1006@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@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@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@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@172.16.200.60] 2011-03-05 23:21:08.558529 [NOTICE] switch_channel.c:812 New Channel sofia/internal/sip:1005@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@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@192.168.60.135:53664 [BREAK] 2011-03-05 23:21:08.565722 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1005@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@192.168.60.135:53664) State INIT 2011-03-05 23:21:08.566543 [DEBUG] mod_sofia.c:84 sofia/internal/sip:1005@192.168.60.135:53664 SOFIA INIT 2011-03-05 23:21:08.570553 [DEBUG] sofia_glue.c:2327 sip:1005@192.168.60.135:53710;transport=TLS Setting proxy route to sofia/internal/sip:1005@192.168.60.135:53664 2011-03-05 23:21:08.572076 [DEBUG] mod_sofia.c:124 (sofia/internal/sip:1005@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@192.168.60.135:53664 [BREAK] 2011-03-05 23:21:08.572076 [DEBUG] sofia.c:4683 Channel sofia/internal/sip:1005@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@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@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@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@192.168.60.135:53664) State ROUTING 2011-03-05 23:21:08.573709 [DEBUG] mod_sofia.c:147 sofia/internal/sip:1005@192.168.60.135:53664 SOFIA ROUTING 2011-03-05 23:21:08.574575 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/sip:1005@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@192.168.60.135:53664 [BREAK] 2011-03-05 23:21:08.574575 [DEBUG] switch_core_state_machine.c:359 (sofia/internal/sip:1005@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@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@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@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@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@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@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@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@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@172.16.200.60 answer() 2011-03-05 23:21:08.655518 [DEBUG] sofia_glue.c:2990 AUDIO RTP [sofia/internal/1006@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@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@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@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@172.16.200.60 [BREAK] 2011-03-05 23:21:08.661306 [DEBUG] switch_channel.c:2795 (sofia/internal/1006@172.16.200.60) Callstate Change RINGING -> ACTIVE 2011-03-05 23:21:08.662543 [NOTICE] mod_dptools.c:929 Channel [sofia/internal/1006@172.16.200.60] has been answered EXECUTE sofia/internal/1006@172.16.200.60 sleep(1000) 2011-03-05 23:21:08.664527 [DEBUG] switch_core_state_machine.c:560 (sofia/internal/sip:1005@192.168.60.135:53664) State HANGUP 2011-03-05 23:21:08.665590 [DEBUG] mod_sofia.c:451 sofia/internal/sip:1005@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@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@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@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@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@192.168.60.135:53664 [BREAK] 2011-03-05 23:21:08.666556 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/sip:1005@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@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@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@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@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@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@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@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@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@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@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@192.168.60.135:53664) State DESTROY 2011-03-05 23:21:08.671619 [DEBUG] mod_sofia.c:362 sofia/internal/sip:1005@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@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@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@172.16.200.60 entering state [ready][200] EXECUTE sofia/internal/1006@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@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@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@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@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@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@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@8000hz 1 channels 20ms 2011-03-05 23:21:11.370005 [DEBUG] switch_channel.c:2545 (sofia/internal/1006@172.16.200.60) Callstate Change ACTIVE -> HANGUP 2011-03-05 23:21:11.370005 [NOTICE] sofia.c:537 Hangup sofia/internal/1006@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@172.16.200.60 [KILL] 2011-03-05 23:21:11.370005 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1006@172.16.200.60 [BREAK] 2011-03-05 23:21:11.381511 [DEBUG] switch_ivr_bridge.c:500 sofia/internal/1006@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@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@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@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@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@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@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@172.16.200.60) State HANGUP 2011-03-05 23:21:11.384116 [DEBUG] mod_sofia.c:451 sofia/internal/1006@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@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@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@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@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@172.16.200.60 [BREAK] 2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:320 (sofia/internal/1006@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@172.16.200.60) State REPORTING 2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1006@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@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@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@172.16.200.60 [BREAK] 2011-03-05 23:21:11.384116 [DEBUG] switch_core_session.c:1288 Session 161 (sofia/internal/1006@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@172.16.200.60) Ended 2011-03-05 23:21:11.384116 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/1006@172.16.200.60 [CS_DESTROY] 2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:449 (sofia/internal/1006@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@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@172.16.200.60) State DESTROY 2011-03-05 23:21:11.384116 [DEBUG] mod_sofia.c:362 sofia/internal/1006@172.16.200.60 SOFIA DESTROY 2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1006@172.16.200.60 Standard DESTROY 2011-03-05 23:21:11.384116 [DEBUG] switch_core_state_machine.c:462 (sofia/internal/1006@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