FreeSWITCH erroneous RTP timestamps in front of sofsip_cli client?
Hi FS wizards, first message on this list... Apologies if this post belongs to another section (please tell me if this is the case). First, a big thank you to all members of the team for this amazing piece of software. Great job here. Now, on for my issue: I am currently testing a Linux sofsip_cli SIP client on an embedded device, connected to a Win32 FreeSWITCH version, and I can't get correct RX audio on my platform. I ran the same test with a linphonec client on the same embedded device for comparison purposes, and the rx audio is good. Both clients end up using the same RTP configuration (PCMU/8000). Preliminary conclusion: my sofsip_cli client is buggy. But there is more... I ended up checking data exchanged between endpoints using Wireshark, and I was surprised to see that in front of sofsip_cli, FreeSWITCH seems to timestamp TX RTP packets incorrectly: it sends 160 samples/RTP packet, but the timestamps of consecutive TX packets are increased in 320 units steps, and FS sends 25 RTP packets per second on average. Consecutive RTP packets actually contain consecutive PCMU data (from the audio point of view), resulting in a sloooow, chopped rx audio coming out of the loudspeaker of my device. Using Wireshark embedded player to play the VoIP audio results in the same slow / chopped audio, which seems to prove that FS actually sent bad RTP. On the other hand, when I use linphonec in the very same conditions, I can see that FreeSWITCH sends 50 RTP packets per second on average. Each RTP packet contains 160 samples, and timestamps of consecutive are increased in 160 units steps, resulting in correct RX audio coming out of the loudspeaker of my device. FS logs in console window are the same for both cases, below is what I get for the sofsip_cli case: 2013-11-21 09:35:00.549253 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/1009@10.0.0.57 [527f855e-3856-4805-b72c-da59b3a6d292] 2013-11-21 09:35:04.502530 [INFO] mod_dialplan_xml.c:558 Processing 1009 <1009>->1001 in context default 2013-11-21 09:35:04.533781 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *1 execute_extension::dx XML features 2013-11-21 09:35:04.549407 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *2 record_session::C:/Program Files/FreeSWITCH/recordings/1009.2013-11-21-09-35-04.wav 2013-11-21 09:35:04.549407 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *3 execute_extension::cf XML features 2013-11-21 09:35:04.549407 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *4 execute_extension::att_xfer XML features 2013-11-21 09:35:04.565032 [NOTICE] switch_ivr_originate.c:2699 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2013-11-21 09:35:04.565032 [NOTICE] switch_ivr_originate.c:2699 Cannot create outgoing channel of type [user] cause: [USER_NOT_REGISTERED] 2013-11-21 09:35:04.580658 [INFO] mod_dptools.c:3201 Originate Failed. Cause: USER_NOT_REGISTERED 2013-11-21 09:35:04.580658 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1009@10.0.0.57! 2013-11-21 09:35:04.580658 [NOTICE] mod_dptools.c:1225 Channel [sofia/internal/1009@10.0.0.57] has been answered 2013-11-21 09:35:05.580696 [NOTICE] switch_channel.c:1055 New Channel loopback/app=voicemail:default 10.0.0.57 1001-a [f2aa95f1-0631-4590-9fa4-c4dc1c96c88e] 2013-11-21 09:35:05.580696 [NOTICE] switch_channel.c:1053 Rename Channel loopback/app=voicemail:default 10.0.0.57 1001-a->loopback/voicemail-a [f2aa95f1-0631-4590-9fa4-c4dc1c96c88e] 2013-11-21 09:35:05.580696 [NOTICE] switch_channel.c:1055 New Channel loopback/voicemail-b [fc478cfd-e932-450a-9f50-2a5a76acc907] 2013-11-21 09:35:05.611948 [NOTICE] mod_loopback.c:947 Pre-Answer loopback/voicemail-a! 2013-11-21 09:35:05.611948 [NOTICE] mod_dptools.c:1260 Pre-Answer loopback/voicemail-b! 2013-11-21 09:35:11.549676 [NOTICE] sofia.c:715 Hangup sofia/internal/1009@10.0.0.57 [CS_EXECUTE] [NORMAL_CLEARING] 2013-11-21 09:35:11.565301 [NOTICE] switch_ivr_bridge.c:733 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL] 2013-11-21 09:35:11.565301 [NOTICE] mod_loopback.c:553 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL] 2013-11-21 09:35:11.580927 [NOTICE] switch_core_session.c:1598 Session 5 (loopback/voicemail-a) Ended 2013-11-21 09:35:11.580927 [NOTICE] switch_core_session.c:1602 Close Channel loopback/voicemail-a [CS_DESTROY] 2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1598 Session 4 (sofia/internal/1009@10.0.0.57) Ended 2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1602 Close Channel sofia/internal/1009@10.0.0.57 [CS_DESTROY] 2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1598 Session 6 (loopback/voicemail-b) Ended 2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1602 Close Channel loopback/voicemail-b [CS_DESTROY] I ran my tests by calling an unregistered extension (1001), therefore resulting in FS sending voice messaging audio, and hanging up on client after a few seconds. I have compared the SIP handshakes for both clients, and I can't see any significant difference (except that linphonec supports several codecs, while sofsip_cli only supports G.711/PCMU). Regarding FS config (this may or may not be relevant), I had to tweak it a bit to support sofsip_cli. I added the two following lines in the dialplan for the relevant extensions (file default.xml): <action application="set" data="disable_rtp_auto_adjust=true"/> <action application="set" data="zrtp_secure_media=false"/> I also changed the two following lines to add video codecs in file vars.xml: <X-PRE-PROCESS cmd="set" data="global_codec_prefs=G722,PCMU,PCMA,GSM,H263,H263-1998,H264"/> <X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=PCMU,PCMA,GSM,H263,H263-1998,H264"/> The rest of the config is plain vanilla. The (small) Wireshark traces of both tests can be downloaded from Box: - linphonec trace (FS TX RTP ok): file linphone.dac.pcap is available at https://app.box.com/s/63p8ayrr3dc6w1d9wm33 - sofsip_cli trace (FS TX RTP ko): file ssc.pcap is available at https://app.box.com/s/z1cde37xg5teh9d690oy My device has IP address 10.0.0.186, and FS is installed on my PC (running Win XP Pro) at 10.0.0.57. My FreeSWITCH version is "1.5.6b+git~20131101T202135Z~2589bf7750~32bit (git 2589bf7 2013-11-01 20:21:35Z 32bit)" Sorry for the long post (I tried to give all relevant info), and thank you in advance for your comments and help on this weird issue. -- JPI
Do you get different results when you call it with some other phone in place of sofia_cli ? Can you get a full capture of the debug logs sofia global siptrace on console loglevel debug sofia tracelevel alert On Thu, Nov 21, 2013 at 12:13 PM, Jean-Paul Iribarren < jeanpaul.iribarren@free.fr> wrote:
Hi FS wizards, first message on this list... Apologies if this post belongs to another section (please tell me if this is the case).
First, a big thank you to all members of the team for this amazing piece of software. Great job here. Now, on for my issue: I am currently testing a Linux sofsip_cli SIP client on an embedded device, connected to a Win32 FreeSWITCH version, and I can't get correct RX audio on my platform. I ran the same test with a linphonec client on the same embedded device for comparison purposes, and the rx audio is good. Both clients end up using the same RTP configuration (PCMU/8000). Preliminary conclusion: my sofsip_cli client is buggy. But there is more...
I ended up checking data exchanged between endpoints using Wireshark, and I was surprised to see that in front of sofsip_cli, FreeSWITCH seems to timestamp TX RTP packets incorrectly: it sends 160 samples/RTP packet, but the timestamps of consecutive TX packets are increased in 320 units steps, and FS sends 25 RTP packets per second on average. Consecutive RTP packets actually contain consecutive PCMU data (from the audio point of view), resulting in a sloooow, chopped rx audio coming out of the loudspeaker of my device. Using Wireshark embedded player to play the VoIP audio results in the same slow / chopped audio, which seems to prove that FS actually sent bad RTP.
On the other hand, when I use linphonec in the very same conditions, I can see that FreeSWITCH sends 50 RTP packets per second on average. Each RTP packet contains 160 samples, and timestamps of consecutive are increased in 160 units steps, resulting in correct RX audio coming out of the loudspeaker of my device. FS logs in console window are the same for both cases, below is what I get for the sofsip_cli case:
2013-11-21 09:35:00.549253 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/1009@10.0.0.57 [527f855e-3856-4805-b72c-da59b3a6d292] 2013-11-21 09:35:04.502530 [INFO] mod_dialplan_xml.c:558 Processing 1009 <1009>->1001 in context default 2013-11-21 09:35:04.533781 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *1 execute_extension::dx XML features 2013-11-21 09:35:04.549407 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *2 record_session::C:/Program Files/FreeSWITCH/recordings/1009.2013-11-21-09-35-04.wav 2013-11-21 09:35:04.549407 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *3 execute_extension::cf XML features 2013-11-21 09:35:04.549407 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *4 execute_extension::att_xfer XML features 2013-11-21 09:35:04.565032 [NOTICE] switch_ivr_originate.c:2699 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2013-11-21 09:35:04.565032 [NOTICE] switch_ivr_originate.c:2699 Cannot create outgoing channel of type [user] cause: [USER_NOT_REGISTERED] 2013-11-21 09:35:04.580658 [INFO] mod_dptools.c:3201 Originate Failed. Cause: USER_NOT_REGISTERED 2013-11-21 09:35:04.580658 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1009@10.0.0.57! 2013-11-21 09:35:04.580658 [NOTICE] mod_dptools.c:1225 Channel [sofia/internal/1009@10.0.0.57] has been answered 2013-11-21 09:35:05.580696 [NOTICE] switch_channel.c:1055 New Channel loopback/app=voicemail:default 10.0.0.57 1001-a [f2aa95f1-0631-4590-9fa4-c4dc1c96c88e] 2013-11-21 09:35:05.580696 [NOTICE] switch_channel.c:1053 Rename Channel loopback/app=voicemail:default 10.0.0.57 1001-a->loopback/voicemail-a [f2aa95f1-0631-4590-9fa4-c4dc1c96c88e] 2013-11-21 09:35:05.580696 [NOTICE] switch_channel.c:1055 New Channel loopback/voicemail-b [fc478cfd-e932-450a-9f50-2a5a76acc907] 2013-11-21 09:35:05.611948 [NOTICE] mod_loopback.c:947 Pre-Answer loopback/voicemail-a! 2013-11-21 09:35:05.611948 [NOTICE] mod_dptools.c:1260 Pre-Answer loopback/voicemail-b! 2013-11-21 09:35:11.549676 [NOTICE] sofia.c:715 Hangup sofia/internal/1009@10.0.0.57 [CS_EXECUTE] [NORMAL_CLEARING] 2013-11-21 09:35:11.565301 [NOTICE] switch_ivr_bridge.c:733 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL] 2013-11-21 09:35:11.565301 [NOTICE] mod_loopback.c:553 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL] 2013-11-21 09:35:11.580927 [NOTICE] switch_core_session.c:1598 Session 5 (loopback/voicemail-a) Ended 2013-11-21 09:35:11.580927 [NOTICE] switch_core_session.c:1602 Close Channel loopback/voicemail-a [CS_DESTROY] 2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1598 Session 4 (sofia/internal/1009@10.0.0.57) Ended 2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1602 Close Channel sofia/internal/1009@10.0.0.57 [CS_DESTROY] 2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1598 Session 6 (loopback/voicemail-b) Ended 2013-11-21 09:35:11.612178 [NOTICE] switch_core_session.c:1602 Close Channel loopback/voicemail-b [CS_DESTROY]
I ran my tests by calling an unregistered extension (1001), therefore resulting in FS sending voice messaging audio, and hanging up on client after a few seconds. I have compared the SIP handshakes for both clients, and I can't see any significant difference (except that linphonec supports several codecs, while sofsip_cli only supports G.711/PCMU).
Regarding FS config (this may or may not be relevant), I had to tweak it a bit to support sofsip_cli. I added the two following lines in the dialplan for the relevant extensions (file default.xml):
<action application="set" data="disable_rtp_auto_adjust=true"/> <action application="set" data="zrtp_secure_media=false"/>
I also changed the two following lines to add video codecs in file vars.xml:
<X-PRE-PROCESS cmd="set" data="global_codec_prefs=G722,PCMU,PCMA,GSM,H263,H263-1998,H264"/> <X-PRE-PROCESS cmd="set" data="outbound_codec_prefs=PCMU,PCMA,GSM,H263,H263-1998,H264"/>
The rest of the config is plain vanilla.
The (small) Wireshark traces of both tests can be downloaded from Box:
- linphonec trace (FS TX RTP ok): file linphone.dac.pcap is available at https://app.box.com/s/63p8ayrr3dc6w1d9wm33
- sofsip_cli trace (FS TX RTP ko): file ssc.pcap is available at https://app.box.com/s/z1cde37xg5teh9d690oy
My device has IP address 10.0.0.186, and FS is installed on my PC (running Win XP Pro) at 10.0.0.57.
My FreeSWITCH version is "1.5.6b+git~20131101T202135Z~2589bf7750~32bit (git 2589bf7 2013-11-01 20:21:35Z 32bit)"
Sorry for the long post (I tried to give all relevant info), and thank you in advance for your comments and help on this weird issue. -- JPI
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev 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@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
Hi Anthony, thank you for your message. Yes, I did try another client on my device; in my first message, I said: [quote] On the other hand, when I use linphonec in the very same conditions, I can see that FreeSWITCH sends 50 RTP packets per second on average. Each RTP packet contains 160 samples, and timestamps of consecutive packets are increased in 160 units steps, resulting in correct RX audio coming out of the loudspeaker of my device. [/quote] I performed yet another test yesterday evening: using sofsip_cli on caller side, I called a registered client (X-Lite registered as extension 1000), but after a few seconds I hit "Decline" button on X-Lite to refuse the incoming call. On sofsip_cli (caller side), the rx audio was good during the ringback phase (160 samples/pkt, timestamps growing by 160 units, 50 pkts/s average), but turned loose as soon as the call was transfered by FS to the voicemail unit, as a consequence of the callee refusal (160 samples/pkt, timestamps growing by 320 units, 25 pkts/s average -> slow / chopped rx audio). Looks like something is wrong regarding voicemail. But once again, why only in front of sofsip_cli??? Regarding the capture, here it is (call initiated from sofsip_cli to an unregistered extension, triggering voicemail immediately, wait for end of (slow / chopped) voicemail message, hangup from caller side): [capture] freeswitch@XXX-xxxxxxxxx> recv 675 bytes from udp/[10.0.0.186]:5060 at 07:54:00.545012: ------------------------------------------------------------------------ INVITE sip:1001@10.0.0.57 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK0BaUp7Be94yKS Max-Forwards: 70 From: <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57> Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571881 INVITE Contact: <sip:10.0.0.186> User-Agent: sofia-sip/1.12.10 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE Supported: timer, 100rel Min-SE: 120 Content-Type: application/sdp Content-Disposition: session Content-Length: 148 v=0 o=- 4844407640550486747 5665314394658789476 IN IP4 10.0.0.186 s=- c=IN IP4 10.0.0.186 t=0 0 m=audio 16384 RTP/AVP 0 a=rtpmap:0 PCMU/8000 ------------------------------------------------------------------------ send 326 bytes to udp/[10.0.0.186]:5060 at 07:54:00.545012: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.186;rport=5060;branch=z9hG4bK0BaUp7Be94yKS From: <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57> Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571881 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.6b+git~20131101T202135Z~2589bf7750~32bit Content-Length: 0 ------------------------------------------------------------------------ 2013-11-22 08:54:00.560624 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/1009@10.0.0.57 [f28e1f66-1524-4ce5-9fe0-acf7bb929a1c] 2013-11-22 08:54:00.560624 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:00.560624 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1009@10.0.0.57) Running State Change CS_NEW 2013-11-22 08:54:00.560624 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:00.560624 [DEBUG] switch_core_state_machine.c:485 (sofia/internal/1009@10.0.0.57) State NEW 2013-11-22 08:54:00.591846 [DEBUG] sofia.c:8066 IP 10.0.0.186 Rejected by acl "domains". Falling back to Digest auth. send 840 bytes to udp/[10.0.0.186]:5060 at 07:54:00.591846: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.0.0.186;rport=5060;branch=z9hG4bK0BaUp7Be94yKS From: <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=29XpXm62B9N6r Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571881 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.6b+git~20131101T202135Z~2589bf7750~32bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-su mmary, refer Proxy-Authenticate: Digest realm="10.0.0.57", nonce="598a20fb-5ab3-4ecf-af64-71388a03b2e6", algorithm=MD5, qop="auth" Content-Length: 0 ------------------------------------------------------------------------ 2013-11-22 08:54:00.591846 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:00.591846 [DEBUG] sofia.c:1816 detaching session f28e1f66-1524-4ce5-9fe0-acf7bb929a1c recv 287 bytes from udp/[10.0.0.186]:5060 at 07:54:00.607458: ------------------------------------------------------------------------ ACK sip:1001@10.0.0.57 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK0BaUp7Be94yKS Max-Forwards: 70 From: <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=29XpXm62B9N6r Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571881 ACK Content-Length: 0 ------------------------------------------------------------------------ recv 927 bytes from udp/[10.0.0.186]:5060 at 07:54:03.386269: ------------------------------------------------------------------------ INVITE sip:1001@10.0.0.57 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK1m3Kr2vH6DN6m Max-Forwards: 70 From: <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57> Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571882 INVITE Contact: <sip:10.0.0.186> User-Agent: sofia-sip/1.12.10 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE Supported: timer, 100rel Proxy-Authorization: Digest username="1009", realm="10.0.0.57", nonce="598a20fb-5ab3-4ecf-af64-71388a03b2e6", cnonce="XIhwKMIwEjGCaQBQwtXdBw", algorithm=MD5, uri="sip:1001@10.0.0.57", response="df2df2940b0dd6f470f030d80fae7b08", qop=auth, nc=00000001 Min-SE: 120 Content-Type: application/sdp Content-Disposition: session Content-Length: 148 v=0 o=- 4844407640550486747 5665314394658789476 IN IP4 10.0.0.186 s=- c=IN IP4 10.0.0.186 t=0 0 m=audio 16384 RTP/AVP 0 a=rtpmap:0 PCMU/8000 ------------------------------------------------------------------------ send 326 bytes to udp/[10.0.0.186]:5060 at 07:54:03.386269: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.186;rport=5060;branch=z9hG4bK1m3Kr2vH6DN6m From: <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57> Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571882 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.6b+git~20131101T202135Z~2589bf7750~32bit Content-Length: 0 ------------------------------------------------------------------------ 2013-11-22 08:54:03.370658 [DEBUG] sofia.c:1908 Re-attaching to session f28e1f66-1524-4ce5-9fe0-acf7bb929a1c 2013-11-22 08:54:03.370658 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.370658 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.401880 [DEBUG] sofia.c:8066 IP 10.0.0.186 Rejected by acl "domains". Falling back to Digest auth. 2013-11-22 08:54:03.417492 [DEBUG] sofia.c:5863 Channel sofia/internal/1009@10.0.0.57 entering state [received][100] 2013-11-22 08:54:03.417492 [DEBUG] sofia.c:5873 Remote SDP: v=0 o=- 4844407640550486747 5665314394658789476 IN IP4 10.0.0.186 s=- c=IN IP4 10.0.0.186 t=0 0 m=audio 16384 RTP/AVP 0 a=rtpmap:0 PCMU/8000 2013-11-22 08:54:03.417492 [DEBUG] sofia.c:6118 (sofia/internal/1009@10.0.0.57) State Change CS_NEW -> CS_INIT 2013-11-22 08:54:03.417492 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1009@10.0.0.57) Running State Change CS_INIT 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:506 (sofia/internal/1009@10.0.0.57) State INIT 2013-11-22 08:54:03.417492 [DEBUG] mod_sofia.c:87 sofia/internal/1009@10.0.0.57 SOFIA INIT 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1009@10.0.0.57 Standard INIT 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1009@10.0.0.57) State Change CS_INIT -> CS_ROUTING 2013-11-22 08:54:03.417492 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:506 (sofia/internal/1009@10.0.0.57) State INIT going to sleep 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1009@10.0.0.57) Running State Change CS_ROUTING 2013-11-22 08:54:03.417492 [DEBUG] switch_channel.c:2178 (sofia/internal/1009@10.0.0.57) Callstate Change DOWN -> RINGING 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:522 (sofia/internal/1009@10.0.0.57) State ROUTING 2013-11-22 08:54:03.417492 [DEBUG] mod_sofia.c:123 sofia/internal/1009@10.0.0.57 SOFIA ROUTING 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:164 sofia/internal/1009@10.0.0.57 Standard ROUTING 2013-11-22 08:54:03.417492 [INFO] mod_dialplan_xml.c:558 Processing 1009 <1009>->1001 in context default Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->unloop] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->tod_example] continue=true Dialplan: sofia/internal/1009@10.0.0.57 Date/TimeMatch (FAIL) [tod_example] break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/1009@10.0.0.57 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^886$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->redial] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->global] continue=true Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never Dialplan: sofia/internal/1009@10.0.0.57 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [global] ${switch_r_sdp}(v=0 o=- 4844407640550486747 5665314394658789476 IN IP4 10.0.0.186 s=- c=IN IP4 10.0.0.186 t=0 0 m=audio 16384 RTP/AVP 0 a=rtpmap:0 PCMU/8000 ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never Dialplan: sofia/internal/1009@10.0.0.57 Absolute Condition [global] Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^779$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->call_return] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->del-group] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [del-group] destination_number(1001) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->add-group] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [add-group] destination_number(1001) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 Action export(dialed_extension=1001) Dialplan: sofia/internal/1009@10.0.0.57 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1009@10.0.0.57 Action bind_meta_app(2 b s record_session::C:/Program Files/FreeSWITCH/recordings/${caller_id_number}.${strftime(%Y-%m-% d-%H-%M-%S)}.wav) Dialplan: sofia/internal/1009@10.0.0.57 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1009@10.0.0.57 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/internal/1009@10.0.0.57 Action set(disable_rtp_auto_adjust=true) Dialplan: sofia/internal/1009@10.0.0.57 Action set(zrtp_secure_media=false) Dialplan: sofia/internal/1009@10.0.0.57 Action set(ringback=${us-ring}) Dialplan: sofia/internal/1009@10.0.0.57 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1009@10.0.0.57 Action set(call_timeout=30) Dialplan: sofia/internal/1009@10.0.0.57 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1009@10.0.0.57 Action set(continue_on_fail=true) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1009@10.0.0.57 Action answer() Dialplan: sofia/internal/1009@10.0.0.57 Action sleep(1000) Dialplan: sofia/internal/1009@10.0.0.57 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:214 (sofia/internal/1009@10.0.0.57) State Change CS_ROUTING -> CS_EXECUTE 2013-11-22 08:54:03.433103 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:522 (sofia/internal/1009@10.0.0.57) State ROUTING going to sleep 2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1009@10.0.0.57) Running State Change CS_EXECUTE 2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:529 (sofia/internal/1009@10.0.0.57) State EXECUTE 2013-11-22 08:54:03.433103 [DEBUG] mod_sofia.c:178 sofia/internal/1009@10.0.0.57 SOFIA EXECUTE 2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:256 sofia/internal/1009@10.0.0.57 Standard EXECUTE EXECUTE sofia/internal/1009@10.0.0.57 hash(insert/10.0.0.57-spymap/1009/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57 hash(insert/10.0.0.57-last_dial/1009/1001) EXECUTE sofia/internal/1009@10.0.0.57 hash(insert/10.0.0.57-last_dial/global/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57 export(RFC2822_DATE=Fri, 22 Nov 2013 08:54:03 Paris, Madrid) 2013-11-22 08:54:03.433103 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 22 Nov 2013 08:54:03 Paris, Madrid] EXECUTE sofia/internal/1009@10.0.0.57 export(dialed_extension=1001) 2013-11-22 08:54:03.433103 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [dialed_extension]=[1001] EXECUTE sofia/internal/1009@10.0.0.57 bind_meta_app(1 b s execute_extension::dx XML features) 2013-11-22 08:54:03.479937 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE sofia/internal/1009@10.0.0.57 bind_meta_app(2 b s record_session::C:/Program Files/FreeSWITCH/recordings/1009.2013-11-22-08-54-03.wav) 2013-11-22 08:54:03.479937 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *2 record_session::C:/Program Files/FreeSWITCH/recordings/1009.2013-11-22-08-54-03.wav EXECUTE sofia/internal/1009@10.0.0.57 bind_meta_app(3 b s execute_extension::cf XML features) 2013-11-22 08:54:03.479937 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE sofia/internal/1009@10.0.0.57 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2013-11-22 08:54:03.479937 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE sofia/internal/1009@10.0.0.57 set(disable_rtp_auto_adjust=true) 2013-11-22 08:54:03.479937 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [disable_rtp_auto_adjust]=[true] EXECUTE sofia/internal/1009@10.0.0.57 set(zrtp_secure_media=false) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [zrtp_secure_media]=[false] EXECUTE sofia/internal/1009@10.0.0.57 set(ringback=%(2000,4000,440,480)) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/internal/1009@10.0.0.57 set(transfer_ringback=local_stream://moh) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1009@10.0.0.57 set(call_timeout=30) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [call_timeout]=[30] EXECUTE sofia/internal/1009@10.0.0.57 set(hangup_after_bridge=true) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1009@10.0.0.57 set(continue_on_fail=true) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [continue_on_fail]=[true] EXECUTE sofia/internal/1009@10.0.0.57 hash(insert/10.0.0.57-call_return/1001/1009) EXECUTE sofia/internal/1009@10.0.0.57 hash(insert/10.0.0.57-last_dial_ext/1001/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57 set(called_party_callgroup=techsupport) 2013-11-22 08:54:03.511159 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [called_party_callgroup]=[techsupport] EXECUTE sofia/internal/1009@10.0.0.57 hash(insert/10.0.0.57-last_dial_ext/techsupport/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57 hash(insert/10.0.0.57-last_dial_ext/global/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57 hash(insert/10.0.0.57-last_dial/techsupport/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57 bridge(user/1001@10.0.0.57) 2013-11-22 08:54:03.511159 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 22 Nov 2013 08:54:03 Paris, M adrid] to event 2013-11-22 08:54:03.511159 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2013-11-22 08:54:03.511159 [DEBUG] switch_ivr_originate.c:2070 Parsing global variables 2013-11-22 08:54:03.511159 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 22 Nov 2013 08:54:03 Paris, M adrid] to event 2013-11-22 08:54:03.511159 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2013-11-22 08:54:03.511159 [DEBUG] switch_ivr_originate.c:2070 Parsing global variables 2013-11-22 08:54:03.511159 [DEBUG] switch_event.c:1680 Parsing variable [sip_invite_domain]=[10.0.0.57] 2013-11-22 08:54:03.511159 [DEBUG] switch_event.c:1680 Parsing variable [presence_id]=[1001@10.0.0.57] 2013-11-22 08:54:03.511159 [NOTICE] switch_ivr_originate.c:2699 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2013-11-22 08:54:03.511159 [DEBUG] switch_ivr_originate.c:3670 Originate Resulted in Error Cause: 606 [USER_NOT_REGISTERED] 2013-11-22 08:54:03.511159 [NOTICE] switch_ivr_originate.c:2699 Cannot create outgoing channel of type [user] cause: [USER_NOT_REGISTERED] 2013-11-22 08:54:03.511159 [DEBUG] switch_ivr_originate.c:3670 Originate Resulted in Error Cause: 606 [USER_NOT_REGISTERED] 2013-11-22 08:54:03.511159 [INFO] mod_dptools.c:3201 Originate Failed. Cause: USER_NOT_REGISTERED EXECUTE sofia/internal/1009@10.0.0.57 answer() 2013-11-22 08:54:03.542382 [DEBUG] switch_core_media.c:2994 Audio Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000] 2013-11-22 08:54:03.542382 [DEBUG] switch_core_media.c:2994 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2013-11-22 08:54:03.542382 [DEBUG] switch_core_media.c:1956 Set Codec sofia/internal/1009@10.0.0.57 PCMU/8000 20 ms 160 samples 64000 bits 2013-11-22 08:54:03.542382 [DEBUG] switch_core_codec.c:111 sofia/internal/1009@10.0.0.57 Original read codec set to PCMU:0 2013-11-22 08:54:03.542382 [DEBUG] switch_core_media.c:3197 No 2833 in SDP. Disable 2833 dtmf and switch to INFO 2013-11-22 08:54:03.542382 [DEBUG] switch_core_media.c:4321 AUDIO RTP [sofia/internal/1009@10.0.0.57] 10.0.0.57 port 22990 -> 10.0.0.186 port 16384 codec: 0 ms: 20 2013-11-22 08:54:03.542382 [DEBUG] switch_rtp.c:2995 Starting timer [soft] 160 bytes per 20ms 2013-11-22 08:54:03.542382 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1009@10.0.0.57! 2013-11-22 08:54:03.542382 [DEBUG] switch_channel.c:3404 (sofia/internal/1009@10.0.0.57) Callstate Change RINGING -> EARLY 2013-11-22 08:54:03.542382 [DEBUG] mod_sofia.c:772 Local SDP sofia/internal/1009@10.0.0.57: v=0 o=FreeSWITCH 1385083853 1385083854 IN IP4 10.0.0.57 s=FreeSWITCH c=IN IP4 10.0.0.57 t=0 0 m=audio 22990 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv send 1060 bytes to udp/[10.0.0.186]:5060 at 07:54:03.542382: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.0.186;rport=5060;branch=z9hG4bK1m3Kr2vH6DN6m From: <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=3jQFZFQ68HcSm Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571882 INVITE Contact: <sip:1001@10.0.0.57:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.5.6b+git~20131101T202135Z~2589bf7750~32bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-su mmary, refer Min-SE: 120 Content-Type: application/sdp Content-Disposition: session Content-Length: 158 Remote-Party-ID: "1001" <sip:1001@10.0.0.57>;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1385083853 1385083854 IN IP4 10.0.0.57 s=FreeSWITCH c=IN IP4 10.0.0.57 t=0 0 m=audio 22990 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 ------------------------------------------------------------------------ 2013-11-22 08:54:03.542382 [DEBUG] switch_core_session.c:892 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.542382 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.542382 [NOTICE] mod_dptools.c:1225 Channel [sofia/internal/1009@10.0.0.57] has been answered 2013-11-22 08:54:03.557993 [DEBUG] switch_channel.c:3685 (sofia/internal/1009@10.0.0.57) Callstate Change EARLY -> ACTIVE recv 558 bytes from udp/[10.0.0.186]:5060 at 07:54:03.557993: ------------------------------------------------------------------------ ACK sip:1001@10.0.0.57:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK2XvctXDN3pBSg Max-Forwards: 70 From: <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=3jQFZFQ68HcSm Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571882 ACK Proxy-Authorization: Digest username="1009", realm="10.0.0.57", nonce="598a20fb-5ab3-4ecf-af64-71388a03b2e6", cnonce="XIhwKMIwEjGCaQBQwtXdBw", algorithm=MD5, uri="sip:1001@10.0.0.57", response="df2df2940b0dd6f470f030d80fae7b08", qop=auth, nc=00000001 Content-Length: 0 ------------------------------------------------------------------------ 2013-11-22 08:54:03.557993 [DEBUG] sofia.c:5863 Channel sofia/internal/1009@10.0.0.57 entering state [completed][200] 2013-11-22 08:54:03.557993 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.557993 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.557993 [DEBUG] sofia.c:5863 Channel sofia/internal/1009@10.0.0.57 entering state [ready][200] 2013-11-22 08:54:03.557993 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] EXECUTE sofia/internal/1009@10.0.0.57 sleep(1000) EXECUTE sofia/internal/1009@10.0.0.57 bridge(loopback/app=voicemail:default 10.0.0.57 1001) 2013-11-22 08:54:04.572728 [DEBUG] switch_channel.c:1768 (sofia/internal/1009@10.0.0.57) Callstate Change ACTIVE -> RING_WAIT 2013-11-22 08:54:04.572728 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 22 Nov 2013 08:54:03 Paris, M adrid] to event 2013-11-22 08:54:04.572728 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2013-11-22 08:54:04.572728 [DEBUG] switch_ivr_originate.c:2070 Parsing global variables 2013-11-22 08:54:04.572728 [NOTICE] switch_channel.c:1055 New Channel loopback/app=voicemail:default 10.0.0.57 1001-a [ba43ba18-52aa-47b4-8311-daef490b5e73] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:157 loopback/app=voicemail:default 10.0.0.57 1001-a setup codec PCMU/8000/20 2013-11-22 08:54:04.572728 [NOTICE] switch_channel.c:1053 Rename Channel loopback/app=voicemail:default 10.0.0.57 1001-a->loopback/voicemail-a [ba43ba18-52aa-47 b4-8311-daef490b5e73] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:1160 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_INIT 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:506 (loopback/voicemail-a) State INIT 2013-11-22 08:54:04.572728 [NOTICE] switch_channel.c:1055 New Channel loopback/voicemail-b [d1b207bf-b400-40e9-985e-edffbe379887] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:157 loopback/voicemail-b setup codec PCMU/8000/20 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:273 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:359 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-b) Running State Change CS_INIT 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:506 (loopback/voicemail-b) State INIT 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:506 (loopback/voicemail-a) State INIT going to sleep 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:359 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_ROUTING 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:506 (loopback/voicemail-b) State INIT going to sleep 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:522 (loopback/voicemail-a) State ROUTING 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:391 loopback/voicemail-a CHANNEL ROUTING 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-b) Running State Change CS_ROUTING 2013-11-22 08:54:04.572728 [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2013-11-22 08:54:04.572728 [DEBUG] switch_channel.c:2178 (loopback/voicemail-b) Callstate Change DOWN -> RINGING 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:522 (loopback/voicemail-a) State ROUTING going to sleep 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:522 (loopback/voicemail-b) State ROUTING 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:391 loopback/voicemail-b CHANNEL ROUTING 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:410 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:541 (loopback/voicemail-a) State CONSUME_MEDIA 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:650 CHANNEL CONSUME_MEDIA 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:541 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:522 (loopback/voicemail-b) State ROUTING going to sleep 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-b) Running State Change CS_EXECUTE 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:529 (loopback/voicemail-b) State EXECUTE 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:433 loopback/voicemail-b CHANNEL EXECUTE 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:256 loopback/voicemail-b Standard EXECUTE EXECUTE loopback/voicemail-b pre_answer() 2013-11-22 08:54:04.603950 [NOTICE] mod_loopback.c:947 Pre-Answer loopback/voicemail-a! 2013-11-22 08:54:04.603950 [DEBUG] switch_channel.c:3400 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:04.603950 [DEBUG] switch_channel.c:3404 (loopback/voicemail-a) Callstate Change DOWN -> EARLY 2013-11-22 08:54:04.603950 [DEBUG] switch_core_session.c:892 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:04.603950 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:04.603950 [NOTICE] mod_dptools.c:1260 Pre-Answer loopback/voicemail-b! 2013-11-22 08:54:04.603950 [DEBUG] switch_channel.c:3404 (loopback/voicemail-b) Callstate Change RINGING -> EARLY EXECUTE loopback/voicemail-b voicemail(default 10.0.0.57 1001) 2013-11-22 08:54:04.603950 [DEBUG] switch_ivr_originate.c:3532 Originate Resulted in Success: [loopback/voicemail-a] 2013-11-22 08:54:04.603950 [DEBUG] switch_channel.c:1977 (sofia/internal/1009@10.0.0.57) Callstate Change RING_WAIT -> ACTIVE 2013-11-22 08:54:04.603950 [DEBUG] switch_core_session.c:892 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:04.603950 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:04.619562 [DEBUG] switch_core_session.c:892 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:04.619562 [DEBUG] switch_ivr_bridge.c:1440 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2013-11-22 08:54:04.619562 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA 2013-11-22 08:54:04.619562 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:04.619562 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:04.619562 [DEBUG] switch_core_state_machine.c:532 (loopback/voicemail-a) State EXCHANGE_MEDIA 2013-11-22 08:54:04.619562 [DEBUG] mod_loopback.c:612 CHANNEL LOOPBACK 2013-11-22 08:54:04.744452 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2013-11-22 08:54:04.760063 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-person.wav] (en:en) 2013-11-22 08:54:04.822509 [DEBUG] switch_ivr_play_say.c:1319 Codec Activated L16@8000hz 1 channels 20ms 2013-11-22 08:54:07.601320 [DEBUG] switch_ivr_play_say.c:1723 done playing file C:/Program Files/FreeSWITCH/sounds/en/us/callie/voicemail/vm-person.wav 2013-11-22 08:54:07.741822 [DEBUG] switch_ivr_play_say.c:251 Handle say:[1001] (en:en) 2013-11-22 08:54:07.773044 [DEBUG] switch_ivr_play_say.c:1319 Codec Activated L16@8000hz 1 channels 20ms 2013-11-22 08:54:12.440823 [DEBUG] switch_ivr_play_say.c:1723 done playing file file_string://digits/1.wav!digits/0.wav!digits/0.wav!digits/1.wav 2013-11-22 08:54:12.550102 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-not_available.wav] (en:en) 2013-11-22 08:54:12.596936 [DEBUG] switch_ivr_play_say.c:1319 Codec Activated L16@8000hz 1 channels 20ms 2013-11-22 08:54:14.532737 [DEBUG] switch_ivr_play_say.c:1723 done playing file C:/Program Files/FreeSWITCH/sounds/en/us/callie/voicemail/vm-not_available.wav 2013-11-22 08:54:14.657628 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2013-11-22 08:54:14.657628 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-record_message.wav] (en:en) 2013-11-22 08:54:14.673239 [DEBUG] switch_ivr_play_say.c:1319 Codec Activated L16@8000hz 1 channels 20ms 2013-11-22 08:54:23.852683 [DEBUG] switch_ivr_play_say.c:1723 done playing file C:/Program Files/FreeSWITCH/sounds/en/us/callie/voicemail/vm-record_message.wav 2013-11-22 08:54:26.459770 [DEBUG] switch_channel.c:3639 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:26.459770 [NOTICE] mod_loopback.c:942 Channel [loopback/voicemail-a] has been answered 2013-11-22 08:54:26.459770 [DEBUG] switch_channel.c:3685 (loopback/voicemail-a) Callstate Change EARLY -> ACTIVE 2013-11-22 08:54:26.459770 [DEBUG] switch_core_session.c:892 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:26.459770 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:26.459770 [NOTICE] switch_ivr_play_say.c:409 Channel [loopback/voicemail-b] has been answered 2013-11-22 08:54:26.459770 [DEBUG] switch_channel.c:3685 (loopback/voicemail-b) Callstate Change EARLY -> ACTIVE 2013-11-22 08:54:26.459770 [DEBUG] switch_ivr_play_say.c:599 Raw Codec Activated 2013-11-22 08:54:26.459770 [DEBUG] switch_core_codec.c:221 loopback/voicemail-b Push codec L16:70 2013-11-22 08:54:26.475382 [DEBUG] switch_core_session.c:954 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:26.475382 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:26.475382 [DEBUG] switch_core_session.c:954 Send signal sofia/internal/1009@10.0.0.57 [BREAK] recv 726 bytes from udp/[10.0.0.186]:5060 at 07:54:28.270681: ------------------------------------------------------------------------ BYE sip:1001@10.0.0.57:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK36N5Uryr0Z1Bc Max-Forwards: 70 From: <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=3jQFZFQ68HcSm Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571883 BYE User-Agent: sofia-sip/1.12.10 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE Supported: timer, 100rel Proxy-Authorization: Digest username="1009", realm="10.0.0.57", nonce="598a20fb-5ab3-4ecf-af64-71388a03b2e6", cnonce="XIhwKMIwEjGCaQBQwtXdBw", algorithm=MD5, uri="sip:1001@10.0.0.57:5060;transport=udp", response="f3fac72314ac0ff146b8561734438dc5", qop=auth, nc=00000002 Content-Length: 0 ------------------------------------------------------------------------ 2013-11-22 08:54:28.255070 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:28.270681 [NOTICE] sofia.c:715 Hangup sofia/internal/1009@10.0.0.57 [CS_EXECUTE] [NORMAL_CLEARING] 2013-11-22 08:54:28.270681 [DEBUG] switch_channel.c:3211 Send signal sofia/internal/1009@10.0.0.57 [KILL] 2013-11-22 08:54:28.270681 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] send 495 bytes to udp/[10.0.0.186]:5060 at 07:54:28.270681: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.0.186;rport=5060;branch=z9hG4bK36N5Uryr0Z1Bc From: <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=3jQFZFQ68HcSm Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571883 BYE User-Agent: FreeSWITCH-mod_sofia/1.5.6b+git~20131101T202135Z~2589bf7750~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2013-11-22 08:54:28.270681 [DEBUG] switch_ivr_bridge.c:647 BRIDGE THREAD DONE [sofia/internal/1009@10.0.0.57] 2013-11-22 08:54:28.270681 [DEBUG] switch_ivr_bridge.c:672 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:28.270681 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:28.301904 [DEBUG] switch_ivr_bridge.c:647 BRIDGE THREAD DONE [loopback/voicemail-a] 2013-11-22 08:54:28.301904 [DEBUG] switch_ivr_bridge.c:672 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:28.301904 [NOTICE] switch_ivr_bridge.c:735 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2013-11-22 08:54:28.301904 [DEBUG] switch_channel.c:3211 Send signal loopback/voicemail-a [KILL] 2013-11-22 08:54:28.301904 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:28.301904 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:28.301904 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:28.301904 [DEBUG] switch_ivr_bridge.c:1538 loopback/voicemail-a skip receive message [UNBRIDGE] (channel is hungup already) 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:532 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_HANGUP 2013-11-22 08:54:28.301904 [DEBUG] switch_ivr_bridge.c:1541 sofia/internal/1009@10.0.0.57 skip receive message [UNBRIDGE] (channel is hungup already) 2013-11-22 08:54:28.301904 [DEBUG] switch_core_session.c:2841 sofia/internal/1009@10.0.0.57 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:529 (sofia/internal/1009@10.0.0.57) State EXECUTE going to sleep 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1009@10.0.0.57) Running State Change CS_HANGUP 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:730 (loopback/voicemail-a) State HANGUP 2013-11-22 08:54:28.301904 [DEBUG] mod_loopback.c:537 loopback/voicemail-a CHANNEL HANGUP 2013-11-22 08:54:28.301904 [NOTICE] mod_loopback.c:553 Hangup loopback/voicemail-b [CS_EXECUTE] [NORMAL_CLEARING] 2013-11-22 08:54:28.301904 [DEBUG] switch_channel.c:3211 Send signal loopback/voicemail-b [KILL] 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:730 (sofia/internal/1009@10.0.0.57) State HANGUP 2013-11-22 08:54:28.301904 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:28.317515 [DEBUG] mod_sofia.c:413 Channel sofia/internal/1009@10.0.0.57 hanging up, cause: NORMAL_CLEARING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:28.317515 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:58 loopback/voicemail-a Standard HANGUP, cause: NORMAL_CLEARING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:730 (loopback/voicemail-a) State HANGUP going to sleep 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:743 (loopback/voicemail-a) Callstate Change ACTIVE -> HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:498 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:28.317515 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_codec.c:246 loopback/voicemail-b Restore previous codec PCMU:0. 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:815 (loopback/voicemail-a) State REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:102 loopback/voicemail-a Standard REPORTING, cause: NORMAL_CLEARING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:815 (loopback/voicemail-a) State REPORTING going to sleep 2013-11-22 08:54:28.317515 [DEBUG] mod_voicemail.c:1237 Message is less than minimum record length: 3, discarding it. 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:492 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:2841 loopback/voicemail-b skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2013-11-22 08:54:28.317515 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:529 (loopback/voicemail-b) State EXECUTE going to sleep 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:1580 Session 2 (loopback/voicemail-a) Locked, Waiting on external entities 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-b) Running State Change CS_HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:58 sofia/internal/1009@10.0.0.57 Standard HANGUP, cause: NORMAL_CLEARING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:730 (sofia/internal/1009@10.0.0.57) State HANGUP going to sleep 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:743 (sofia/internal/1009@10.0.0.57) Callstate Change ACTIVE -> HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:498 (sofia/internal/1009@10.0.0.57) State Change CS_HANGUP -> CS_REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:730 (loopback/voicemail-b) State HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:28.317515 [DEBUG] mod_loopback.c:537 loopback/voicemail-b CHANNEL HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:58 loopback/voicemail-b Standard HANGUP, cause: NORMAL_CLEARING 2013-11-22 08:54:28.317515 [NOTICE] switch_core_session.c:1598 Session 2 (loopback/voicemail-a) Ended 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1009@10.0.0.57) Running State Change CS_REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:730 (loopback/voicemail-b) State HANGUP going to sleep 2013-11-22 08:54:28.317515 [NOTICE] switch_core_session.c:1602 Close Channel loopback/voicemail-a [CS_DESTROY] 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:743 (loopback/voicemail-b) Callstate Change ACTIVE -> HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:815 (sofia/internal/1009@10.0.0.57) State REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:617 (loopback/voicemail-a) Callstate Change HANGUP -> DOWN 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:498 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:620 (loopback/voicemail-a) Running State Change CS_DESTROY 2013-11-22 08:54:28.333126 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:28.333126 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:630 (loopback/voicemail-a) State DESTROY 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-b) Running State Change CS_REPORTING 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:109 loopback/voicemail-a Standard DESTROY 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:630 (loopback/voicemail-a) State DESTROY going to sleep 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:815 (loopback/voicemail-b) State REPORTING 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:102 loopback/voicemail-b Standard REPORTING, cause: NORMAL_CLEARING 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:102 sofia/internal/1009@10.0.0.57 Standard REPORTING, cause: NORMAL_CLEARING 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:815 (sofia/internal/1009@10.0.0.57) State REPORTING going to sleep 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:815 (loopback/voicemail-b) State REPORTING going to sleep 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:492 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:492 (sofia/internal/1009@10.0.0.57) State Change CS_REPORTING -> CS_DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:28.379960 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:28.379960 [DEBUG] switch_core_session.c:1580 Session 1 (sofia/internal/1009@10.0.0.57) Locked, Waiting on external entities 2013-11-22 08:54:28.379960 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:28.379960 [DEBUG] switch_core_session.c:1580 Session 3 (loopback/voicemail-b) Locked, Waiting on external entities 2013-11-22 08:54:28.379960 [NOTICE] switch_core_session.c:1598 Session 1 (sofia/internal/1009@10.0.0.57) Ended 2013-11-22 08:54:28.379960 [NOTICE] switch_core_session.c:1602 Close Channel sofia/internal/1009@10.0.0.57 [CS_DESTROY] 2013-11-22 08:54:28.379960 [NOTICE] switch_core_session.c:1598 Session 3 (loopback/voicemail-b) Ended 2013-11-22 08:54:28.379960 [NOTICE] switch_core_session.c:1602 Close Channel loopback/voicemail-b [CS_DESTROY] 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:617 (sofia/internal/1009@10.0.0.57) Callstate Change HANGUP -> DOWN 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:617 (loopback/voicemail-b) Callstate Change HANGUP -> DOWN 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:620 (sofia/internal/1009@10.0.0.57) Running State Change CS_DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:620 (loopback/voicemail-b) Running State Change CS_DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:630 (sofia/internal/1009@10.0.0.57) State DESTROY 2013-11-22 08:54:28.379960 [DEBUG] mod_sofia.c:323 sofia/internal/1009@10.0.0.57 SOFIA DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:630 (loopback/voicemail-b) State DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:109 loopback/voicemail-b Standard DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:109 sofia/internal/1009@10.0.0.57 Standard DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:630 (sofia/internal/1009@10.0.0.57) State DESTROY going to sleep 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:630 (loopback/voicemail-b) State DESTROY going to sleep [/capture] Can you see anything unusual in the trace above? -- JPI Le 21/11/2013 22:06, Anthony Minessale a écrit :
Do you get different results when you call it with some other phone in place of sofia_cli ?
Can you get a full capture of the debug logs
sofia global siptrace on console loglevel debug sofia tracelevel alert
[... snip ...]
-- Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire
AIM: anthm MSN:anthony_minessale@hotmail.com <mailto:MSN%3Aanthony_minessale@hotmail.com> GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com <mailto:PAYPAL%3Aanthony.minessale@gmail.com> IRC: irc.freenode.net <http://irc.freenode.net> #freeswitch
FreeSWITCH Developer Conference sip:888@conference.freeswitch.org <mailto:sip%3A888@conference.freeswitch.org> googletalk:conf+888@conference.freeswitch.org <mailto:googletalk%3Aconf%2B888@conference.freeswitch.org> pstn:+19193869900
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev http://www.freeswitch.org
You should transfer this info to jira, http://jira.freeswitch.org it will easily get lost in this mailing list. My inbox fills hundreds of emails..... Its the nest way to track issues. On Fri, Nov 22, 2013 at 2:26 AM, Jean-Paul Iribarren < jeanpaul.iribarren@free.fr> wrote:
Hi Anthony, thank you for your message.
Yes, I did try another client on my device; in my first message, I said:
[quote] On the other hand, when I use linphonec in the very same conditions, I can see that FreeSWITCH sends 50 RTP packets per second on average. Each RTP packet contains 160 samples, and timestamps of consecutive packets are increased in 160 units steps, resulting in correct RX audio coming out of the loudspeaker of my device. [/quote]
I performed yet another test yesterday evening: using sofsip_cli on caller side, I called a registered client (X-Lite registered as extension 1000), but after a few seconds I hit "Decline" button on X-Lite to refuse the incoming call. On sofsip_cli (caller side), the rx audio was good during the ringback phase (160 samples/pkt, timestamps growing by 160 units, 50 pkts/s average), but turned loose as soon as the call was transfered by FS to the voicemail unit, as a consequence of the callee refusal (160 samples/pkt, timestamps growing by 320 units, 25 pkts/s average -> slow / chopped rx audio). Looks like something is wrong regarding voicemail. But once again, why only in front of sofsip_cli???
Regarding the capture, here it is (call initiated from sofsip_cli to an unregistered extension, triggering voicemail immediately, wait for end of (slow / chopped) voicemail message, hangup from caller side):
[capture] freeswitch@XXX-xxxxxxxxx> recv 675 bytes from udp/[10.0.0.186]:5060 at 07:54:00.545012: ------------------------------------------------------------------------ INVITE sip:1001@10.0.0.57 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK0BaUp7Be94yKS Max-Forwards: 70 From: <1009@10.0.0.57> <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57> Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571881 INVITE Contact: <sip:10.0.0.186> User-Agent: sofia-sip/1.12.10 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE Supported: timer, 100rel Min-SE: 120 Content-Type: application/sdp Content-Disposition: session Content-Length: 148
v=0 o=- 4844407640550486747 5665314394658789476 IN IP4 10.0.0.186 s=- c=IN IP4 10.0.0.186 t=0 0 m=audio 16384 RTP/AVP 0 a=rtpmap:0 PCMU/8000 ------------------------------------------------------------------------ send 326 bytes to udp/[10.0.0.186]:5060 at 07:54:00.545012: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.186;rport=5060;branch=z9hG4bK0BaUp7Be94yKS From: <1009@10.0.0.57> <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57> Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571881 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.6b+git~20131101T202135Z~2589bf7750~32bit Content-Length: 0
------------------------------------------------------------------------ 2013-11-22 08:54:00.560624 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/1009@10.0.0.57 [f28e1f66-1524-4ce5-9fe0-acf7bb929a1c] 2013-11-22 08:54:00.560624 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:00.560624 [DEBUG] switch_core_state_machine.c:467 ( sofia/internal/1009@10.0.0.57) Running State Change CS_NEW 2013-11-22 08:54:00.560624 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:00.560624 [DEBUG] switch_core_state_machine.c:485 ( sofia/internal/1009@10.0.0.57) State NEW 2013-11-22 08:54:00.591846 [DEBUG] sofia.c:8066 IP 10.0.0.186 Rejected by acl "domains". Falling back to Digest auth. send 840 bytes to udp/[10.0.0.186]:5060 at 07:54:00.591846: ------------------------------------------------------------------------ SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.0.0.186;rport=5060;branch=z9hG4bK0BaUp7Be94yKS From: <1009@10.0.0.57> <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=29XpXm62B9N6r Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571881 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.6b+git~20131101T202135Z~2589bf7750~32bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-su mmary, refer Proxy-Authenticate: Digest realm="10.0.0.57", nonce="598a20fb-5ab3-4ecf-af64-71388a03b2e6", algorithm=MD5, qop="auth" Content-Length: 0
------------------------------------------------------------------------ 2013-11-22 08:54:00.591846 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:00.591846 [DEBUG] sofia.c:1816 detaching session f28e1f66-1524-4ce5-9fe0-acf7bb929a1c recv 287 bytes from udp/[10.0.0.186]:5060 at 07:54:00.607458: ------------------------------------------------------------------------ ACK sip:1001@10.0.0.57 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK0BaUp7Be94yKS Max-Forwards: 70 From: <1009@10.0.0.57> <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=29XpXm62B9N6r Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571881 ACK Content-Length: 0
------------------------------------------------------------------------ recv 927 bytes from udp/[10.0.0.186]:5060 at 07:54:03.386269: ------------------------------------------------------------------------ INVITE sip:1001@10.0.0.57 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK1m3Kr2vH6DN6m Max-Forwards: 70 From: <1009@10.0.0.57> <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57> Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571882 INVITE Contact: <sip:10.0.0.186> User-Agent: sofia-sip/1.12.10 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE Supported: timer, 100rel Proxy-Authorization: Digest username="1009", realm="10.0.0.57", nonce="598a20fb-5ab3-4ecf-af64-71388a03b2e6", cnonce="XIhwKMIwEjGCaQBQwtXdBw", algorithm=MD5, uri="sip:1001@10.0.0.57", response="df2df2940b0dd6f470f030d80fae7b08", qop=auth, nc=00000001 Min-SE: 120 Content-Type: application/sdp Content-Disposition: session Content-Length: 148
v=0 o=- 4844407640550486747 5665314394658789476 IN IP4 10.0.0.186 s=- c=IN IP4 10.0.0.186 t=0 0 m=audio 16384 RTP/AVP 0 a=rtpmap:0 PCMU/8000 ------------------------------------------------------------------------ send 326 bytes to udp/[10.0.0.186]:5060 at 07:54:03.386269: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.186;rport=5060;branch=z9hG4bK1m3Kr2vH6DN6m From: <1009@10.0.0.57> <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57> Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571882 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.6b+git~20131101T202135Z~2589bf7750~32bit Content-Length: 0
------------------------------------------------------------------------ 2013-11-22 08:54:03.370658 [DEBUG] sofia.c:1908 Re-attaching to session f28e1f66-1524-4ce5-9fe0-acf7bb929a1c 2013-11-22 08:54:03.370658 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.370658 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.401880 [DEBUG] sofia.c:8066 IP 10.0.0.186 Rejected by acl "domains". Falling back to Digest auth. 2013-11-22 08:54:03.417492 [DEBUG] sofia.c:5863 Channel sofia/internal/1009@10.0.0.57 entering state [received][100] 2013-11-22 08:54:03.417492 [DEBUG] sofia.c:5873 Remote SDP: v=0 o=- 4844407640550486747 5665314394658789476 IN IP4 10.0.0.186 s=- c=IN IP4 10.0.0.186 t=0 0 m=audio 16384 RTP/AVP 0 a=rtpmap:0 PCMU/8000
2013-11-22 08:54:03.417492 [DEBUG] sofia.c:6118 ( sofia/internal/1009@10.0.0.57) State Change CS_NEW -> CS_INIT 2013-11-22 08:54:03.417492 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:467 ( sofia/internal/1009@10.0.0.57) Running State Change CS_INIT 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:506 ( sofia/internal/1009@10.0.0.57) State INIT 2013-11-22 08:54:03.417492 [DEBUG] mod_sofia.c:87 sofia/internal/1009@10.0.0.57 SOFIA INIT 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1009@10.0.0.57 Standard INIT 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:48 ( sofia/internal/1009@10.0.0.57) State Change CS_INIT -> CS_ROUTING 2013-11-22 08:54:03.417492 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:506 ( sofia/internal/1009@10.0.0.57) State INIT going to sleep 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:467 ( sofia/internal/1009@10.0.0.57) Running State Change CS_ROUTING 2013-11-22 08:54:03.417492 [DEBUG] switch_channel.c:2178 ( sofia/internal/1009@10.0.0.57) Callstate Change DOWN -> RINGING 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:522 ( sofia/internal/1009@10.0.0.57) State ROUTING 2013-11-22 08:54:03.417492 [DEBUG] mod_sofia.c:123 sofia/internal/1009@10.0.0.57 SOFIA ROUTING 2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:164 sofia/internal/1009@10.0.0.57 Standard ROUTING 2013-11-22 08:54:03.417492 [INFO] mod_dialplan_xml.c:558 Processing 1009 <1009>->1001 in context default Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->unloop] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->tod_example] continue=true Dialplan: sofia/internal/1009@10.0.0.57 Date/TimeMatch (FAIL) [tod_example] break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->holiday_example] continue=true Dialplan: sofia/internal/1009@10.0.0.57 Date/TimeMatch (FAIL) [holiday_example] break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->global-intercept] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [global-intercept] destination_number(1001) =~ /^886$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->group-intercept] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [group-intercept] destination_number(1001) =~ /^\*8$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->intercept-ext] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [intercept-ext] destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->redial] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [redial] destination_number(1001) =~ /^(redial|870)$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->global] continue=true Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/ break=never Dialplan: sofia/internal/1009@10.0.0.57 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [global] ${switch_r_sdp}(v=0 o=- 4844407640550486747 5665314394658789476 IN IP4 10.0.0.186 s=- c=IN IP4 10.0.0.186 t=0 0 m=audio 16384 RTP/AVP 0 a=rtpmap:0 PCMU/8000 ) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never Dialplan: sofia/internal/1009@10.0.0.57 Absolute Condition [global] Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial/global/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->snom-demo-2] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [snom-demo-2] destination_number(1001) =~ /^9001$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->snom-demo-1] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [snom-demo-1] destination_number(1001) =~ /^9000$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->eavesdrop] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [eavesdrop] destination_number(1001) =~ /^779$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->call_return] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [call_return] destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->del-group] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [del-group] destination_number(1001) =~ /^80(\d{2})$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->add-group] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [add-group] destination_number(1001) =~ /^81(\d{2})$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->call-group-simo] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [call-group-simo] destination_number(1001) =~ /^82(\d{2})$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->call-group-order] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [call-group-order] destination_number(1001) =~ /^83(\d{2})$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->extension-intercom] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (FAIL) [extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 parsing [default->Local_Extension] continue=false Dialplan: sofia/internal/1009@10.0.0.57 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false Dialplan: sofia/internal/1009@10.0.0.57 Action export(dialed_extension=1001) Dialplan: sofia/internal/1009@10.0.0.57 Action bind_meta_app(1 b s execute_extension::dx XML features) Dialplan: sofia/internal/1009@10.0.0.57 Action bind_meta_app(2 b s record_session::C:/Program Files/FreeSWITCH/recordings/${caller_id_number}.${strftime(%Y-%m-% d-%H-%M-%S)}.wav) Dialplan: sofia/internal/1009@10.0.0.57 Action bind_meta_app(3 b s execute_extension::cf XML features) Dialplan: sofia/internal/1009@10.0.0.57 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) Dialplan: sofia/internal/1009@10.0.0.57 Action set(disable_rtp_auto_adjust=true) Dialplan: sofia/internal/1009@10.0.0.57 Action set(zrtp_secure_media=false) Dialplan: sofia/internal/1009@10.0.0.57 Action set(ringback=${us-ring}) Dialplan: sofia/internal/1009@10.0.0.57 Action set(transfer_ringback=local_stream://moh) Dialplan: sofia/internal/1009@10.0.0.57 Action set(call_timeout=30) Dialplan: sofia/internal/1009@10.0.0.57 Action set(hangup_after_bridge=true) Dialplan: sofia/internal/1009@10.0.0.57 Action set(continue_on_fail=true) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) Dialplan: sofia/internal/1009@10.0.0.57 Action bridge(user/${dialed_extension}@${domain_name}) Dialplan: sofia/internal/1009@10.0.0.57 Action answer() Dialplan: sofia/internal/1009@10.0.0.57 Action sleep(1000) Dialplan: sofia/internal/1009@10.0.0.57 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:214 ( sofia/internal/1009@10.0.0.57) State Change CS_ROUTING -> CS_EXECUTE 2013-11-22 08:54:03.433103 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:522 ( sofia/internal/1009@10.0.0.57) State ROUTING going to sleep 2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:467 ( sofia/internal/1009@10.0.0.57) Running State Change CS_EXECUTE 2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:529 ( sofia/internal/1009@10.0.0.57) State EXECUTE 2013-11-22 08:54:03.433103 [DEBUG] mod_sofia.c:178 sofia/internal/1009@10.0.0.57 SOFIA EXECUTE 2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:256 sofia/internal/1009@10.0.0.57 Standard EXECUTE EXECUTE sofia/internal/1009@10.0.0.57hash(insert/10.0.0.57-spymap/1009/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57hash(insert/10.0.0.57-last_dial/1009/1001) EXECUTE sofia/internal/1009@10.0.0.57hash(insert/10.0.0.57-last_dial/global/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57 export(RFC2822_DATE=Fri, 22 Nov 2013 08:54:03 Paris, Madrid) 2013-11-22 08:54:03.433103 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [RFC2822_DATE]=[Fri, 22 Nov 2013 08:54:03 Paris, Madrid] EXECUTE sofia/internal/1009@10.0.0.57 export(dialed_extension=1001) 2013-11-22 08:54:03.433103 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [dialed_extension]=[1001] EXECUTE sofia/internal/1009@10.0.0.57 bind_meta_app(1 b s execute_extension::dx XML features) 2013-11-22 08:54:03.479937 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *1 execute_extension::dx XML features EXECUTE sofia/internal/1009@10.0.0.57 bind_meta_app(2 b s record_session::C:/Program Files/FreeSWITCH/recordings/1009.2013-11-22-08-54-03.wav) 2013-11-22 08:54:03.479937 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *2 record_session::C:/Program Files/FreeSWITCH/recordings/1009.2013-11-22-08-54-03.wav EXECUTE sofia/internal/1009@10.0.0.57 bind_meta_app(3 b s execute_extension::cf XML features) 2013-11-22 08:54:03.479937 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *3 execute_extension::cf XML features EXECUTE sofia/internal/1009@10.0.0.57 bind_meta_app(4 b s execute_extension::att_xfer XML features) 2013-11-22 08:54:03.479937 [INFO] switch_ivr_async.c:3631 Bound B-Leg: *4 execute_extension::att_xfer XML features EXECUTE sofia/internal/1009@10.0.0.57 set(disable_rtp_auto_adjust=true) 2013-11-22 08:54:03.479937 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [disable_rtp_auto_adjust]=[true] EXECUTE sofia/internal/1009@10.0.0.57 set(zrtp_secure_media=false) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [zrtp_secure_media]=[false] EXECUTE sofia/internal/1009@10.0.0.57 set(ringback=%(2000,4000,440,480)) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [ringback]=[%(2000,4000,440,480)] EXECUTE sofia/internal/1009@10.0.0.57set(transfer_ringback=local_stream://moh) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [transfer_ringback]=[local_stream://moh] EXECUTE sofia/internal/1009@10.0.0.57 set(call_timeout=30) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [call_timeout]=[30] EXECUTE sofia/internal/1009@10.0.0.57 set(hangup_after_bridge=true) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [hangup_after_bridge]=[true] EXECUTE sofia/internal/1009@10.0.0.57 set(continue_on_fail=true) 2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [continue_on_fail]=[true] EXECUTE sofia/internal/1009@10.0.0.57hash(insert/10.0.0.57-call_return/1001/1009) EXECUTE sofia/internal/1009@10.0.0.57hash(insert/10.0.0.57-last_dial_ext/1001/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57set(called_party_callgroup=techsupport) 2013-11-22 08:54:03.511159 [DEBUG] mod_dptools.c:1402 sofia/internal/1009@10.0.0.57 SET [called_party_callgroup]=[techsupport] EXECUTE sofia/internal/1009@10.0.0.57hash(insert/10.0.0.57-last_dial_ext/techsupport/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57hash(insert/10.0.0.57-last_dial_ext/global/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57hash(insert/10.0.0.57-last_dial/techsupport/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c) EXECUTE sofia/internal/1009@10.0.0.57 bridge(user/1001@10.0.0.57) 2013-11-22 08:54:03.511159 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 22 Nov 2013 08:54:03 Paris, M adrid] to event 2013-11-22 08:54:03.511159 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2013-11-22 08:54:03.511159 [DEBUG] switch_ivr_originate.c:2070 Parsing global variables 2013-11-22 08:54:03.511159 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 22 Nov 2013 08:54:03 Paris, M adrid] to event 2013-11-22 08:54:03.511159 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2013-11-22 08:54:03.511159 [DEBUG] switch_ivr_originate.c:2070 Parsing global variables 2013-11-22 08:54:03.511159 [DEBUG] switch_event.c:1680 Parsing variable [sip_invite_domain]=[10.0.0.57] 2013-11-22 08:54:03.511159 [DEBUG] switch_event.c:1680 Parsing variable [presence_id]=[1001@10.0.0.57] 2013-11-22 08:54:03.511159 [NOTICE] switch_ivr_originate.c:2699 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2013-11-22 08:54:03.511159 [DEBUG] switch_ivr_originate.c:3670 Originate Resulted in Error Cause: 606 [USER_NOT_REGISTERED] 2013-11-22 08:54:03.511159 [NOTICE] switch_ivr_originate.c:2699 Cannot create outgoing channel of type [user] cause: [USER_NOT_REGISTERED]
2013-11-22 08:54:03.511159 [DEBUG] switch_ivr_originate.c:3670 Originate Resulted in Error Cause: 606 [USER_NOT_REGISTERED] 2013-11-22 08:54:03.511159 [INFO] mod_dptools.c:3201 Originate Failed. Cause: USER_NOT_REGISTERED
EXECUTE sofia/internal/1009@10.0.0.57 answer() 2013-11-22 08:54:03.542382 [DEBUG] switch_core_media.c:2994 Audio Codec Compare [PCMU:0:8000:20:64000]/[G722:9:8000:20:64000] 2013-11-22 08:54:03.542382 [DEBUG] switch_core_media.c:2994 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2013-11-22 08:54:03.542382 [DEBUG] switch_core_media.c:1956 Set Codec sofia/internal/1009@10.0.0.57 PCMU/8000 20 ms 160 samples 64000 bits 2013-11-22 08:54:03.542382 [DEBUG] switch_core_codec.c:111 sofia/internal/1009@10.0.0.57 Original read codec set to PCMU:0 2013-11-22 08:54:03.542382 [DEBUG] switch_core_media.c:3197 No 2833 in SDP. Disable 2833 dtmf and switch to INFO 2013-11-22 08:54:03.542382 [DEBUG] switch_core_media.c:4321 AUDIO RTP [ sofia/internal/1009@10.0.0.57] 10.0.0.57 port 22990 -> 10.0.0.186 port 16384 codec: 0 ms: 20 2013-11-22 08:54:03.542382 [DEBUG] switch_rtp.c:2995 Starting timer [soft] 160 bytes per 20ms 2013-11-22 08:54:03.542382 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1009@10.0.0.57! 2013-11-22 08:54:03.542382 [DEBUG] switch_channel.c:3404 ( sofia/internal/1009@10.0.0.57) Callstate Change RINGING -> EARLY 2013-11-22 08:54:03.542382 [DEBUG] mod_sofia.c:772 Local SDP sofia/internal/1009@10.0.0.57: v=0 o=FreeSWITCH 1385083853 1385083854 IN IP4 10.0.0.57 s=FreeSWITCH c=IN IP4 10.0.0.57 t=0 0 m=audio 22990 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv
send 1060 bytes to udp/[10.0.0.186]:5060 at 07:54:03.542382: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.0.186;rport=5060;branch=z9hG4bK1m3Kr2vH6DN6m From: <1009@10.0.0.57> <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=3jQFZFQ68HcSm Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571882 INVITE Contact: <sip:1001@10.0.0.57:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.5.6b+git~20131101T202135Z~2589bf7750~32bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-su mmary, refer Min-SE: 120 Content-Type: application/sdp Content-Disposition: session Content-Length: 158 Remote-Party-ID: "1001" <sip:1001@10.0.0.57> ;party=calling;privacy=off;screen=no
v=0 o=FreeSWITCH 1385083853 1385083854 IN IP4 10.0.0.57 s=FreeSWITCH c=IN IP4 10.0.0.57 t=0 0 m=audio 22990 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 ------------------------------------------------------------------------ 2013-11-22 08:54:03.542382 [DEBUG] switch_core_session.c:892 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.542382 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.542382 [NOTICE] mod_dptools.c:1225 Channel [ sofia/internal/1009@10.0.0.57] has been answered 2013-11-22 08:54:03.557993 [DEBUG] switch_channel.c:3685 ( sofia/internal/1009@10.0.0.57) Callstate Change EARLY -> ACTIVE recv 558 bytes from udp/[10.0.0.186]:5060 at 07:54:03.557993: ------------------------------------------------------------------------ ACK sip:1001@10.0.0.57:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK2XvctXDN3pBSg Max-Forwards: 70 From: <1009@10.0.0.57> <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=3jQFZFQ68HcSm Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571882 ACK Proxy-Authorization: Digest username="1009", realm="10.0.0.57", nonce="598a20fb-5ab3-4ecf-af64-71388a03b2e6", cnonce="XIhwKMIwEjGCaQBQwtXdBw", algorithm=MD5, uri="sip:1001@10.0.0.57", response="df2df2940b0dd6f470f030d80fae7b08", qop=auth, nc=00000001 Content-Length: 0
------------------------------------------------------------------------ 2013-11-22 08:54:03.557993 [DEBUG] sofia.c:5863 Channel sofia/internal/1009@10.0.0.57 entering state [completed][200] 2013-11-22 08:54:03.557993 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.557993 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:03.557993 [DEBUG] sofia.c:5863 Channel sofia/internal/1009@10.0.0.57 entering state [ready][200] 2013-11-22 08:54:03.557993 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] EXECUTE sofia/internal/1009@10.0.0.57 sleep(1000) EXECUTE sofia/internal/1009@10.0.0.57bridge(loopback/app=voicemail:default 10.0.0.57 1001) 2013-11-22 08:54:04.572728 [DEBUG] switch_channel.c:1768 ( sofia/internal/1009@10.0.0.57) Callstate Change ACTIVE -> RING_WAIT 2013-11-22 08:54:04.572728 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [RFC2822_DATE]=[Fri, 22 Nov 2013 08:54:03 Paris, M adrid] to event 2013-11-22 08:54:04.572728 [DEBUG] switch_channel.c:1201 sofia/internal/1009@10.0.0.57 EXPORTING[export_vars] [dialed_extension]=[1001] to event 2013-11-22 08:54:04.572728 [DEBUG] switch_ivr_originate.c:2070 Parsing global variables 2013-11-22 08:54:04.572728 [NOTICE] switch_channel.c:1055 New Channel loopback/app=voicemail:default 10.0.0.57 1001-a [ba43ba18-52aa-47b4-8311-daef490b5e73] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:157 loopback/app=voicemail:default 10.0.0.57 1001-a setup codec PCMU/8000/20 2013-11-22 08:54:04.572728 [NOTICE] switch_channel.c:1053 Rename Channel loopback/app=voicemail:default 10.0.0.57 1001-a->loopback/voicemail-a [ba43ba18-52aa-47 b4-8311-daef490b5e73] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:1160 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_INIT 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:506 (loopback/voicemail-a) State INIT 2013-11-22 08:54:04.572728 [NOTICE] switch_channel.c:1055 New Channel loopback/voicemail-b [d1b207bf-b400-40e9-985e-edffbe379887] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:157 loopback/voicemail-b setup codec PCMU/8000/20 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:273 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:359 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-b) Running State Change CS_INIT 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:506 (loopback/voicemail-b) State INIT 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:506 (loopback/voicemail-a) State INIT going to sleep 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:359 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_ROUTING 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:506 (loopback/voicemail-b) State INIT going to sleep 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:522 (loopback/voicemail-a) State ROUTING 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:391 loopback/voicemail-a CHANNEL ROUTING 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-b) Running State Change CS_ROUTING 2013-11-22 08:54:04.572728 [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2013-11-22 08:54:04.572728 [DEBUG] switch_channel.c:2178 (loopback/voicemail-b) Callstate Change DOWN -> RINGING 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:522 (loopback/voicemail-a) State ROUTING going to sleep 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:522 (loopback/voicemail-b) State ROUTING 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:391 loopback/voicemail-b CHANNEL ROUTING 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:410 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:541 (loopback/voicemail-a) State CONSUME_MEDIA 2013-11-22 08:54:04.572728 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:650 CHANNEL CONSUME_MEDIA 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:541 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:522 (loopback/voicemail-b) State ROUTING going to sleep 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-b) Running State Change CS_EXECUTE 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:529 (loopback/voicemail-b) State EXECUTE 2013-11-22 08:54:04.572728 [DEBUG] mod_loopback.c:433 loopback/voicemail-b CHANNEL EXECUTE 2013-11-22 08:54:04.572728 [DEBUG] switch_core_state_machine.c:256 loopback/voicemail-b Standard EXECUTE EXECUTE loopback/voicemail-b pre_answer() 2013-11-22 08:54:04.603950 [NOTICE] mod_loopback.c:947 Pre-Answer loopback/voicemail-a! 2013-11-22 08:54:04.603950 [DEBUG] switch_channel.c:3400 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:04.603950 [DEBUG] switch_channel.c:3404 (loopback/voicemail-a) Callstate Change DOWN -> EARLY 2013-11-22 08:54:04.603950 [DEBUG] switch_core_session.c:892 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:04.603950 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:04.603950 [NOTICE] mod_dptools.c:1260 Pre-Answer loopback/voicemail-b! 2013-11-22 08:54:04.603950 [DEBUG] switch_channel.c:3404 (loopback/voicemail-b) Callstate Change RINGING -> EARLY EXECUTE loopback/voicemail-b voicemail(default 10.0.0.57 1001) 2013-11-22 08:54:04.603950 [DEBUG] switch_ivr_originate.c:3532 Originate Resulted in Success: [loopback/voicemail-a] 2013-11-22 08:54:04.603950 [DEBUG] switch_channel.c:1977 ( sofia/internal/1009@10.0.0.57) Callstate Change RING_WAIT -> ACTIVE 2013-11-22 08:54:04.603950 [DEBUG] switch_core_session.c:892 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:04.603950 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:04.619562 [DEBUG] switch_core_session.c:892 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:04.619562 [DEBUG] switch_ivr_bridge.c:1440 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2013-11-22 08:54:04.619562 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA 2013-11-22 08:54:04.619562 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:04.619562 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:04.619562 [DEBUG] switch_core_state_machine.c:532 (loopback/voicemail-a) State EXCHANGE_MEDIA 2013-11-22 08:54:04.619562 [DEBUG] mod_loopback.c:612 CHANNEL LOOPBACK 2013-11-22 08:54:04.744452 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2013-11-22 08:54:04.760063 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-person.wav] (en:en) 2013-11-22 08:54:04.822509 [DEBUG] switch_ivr_play_say.c:1319 Codec Activated L16@8000hz 1 channels 20ms 2013-11-22 08:54:07.601320 [DEBUG] switch_ivr_play_say.c:1723 done playing file C:/Program Files/FreeSWITCH/sounds/en/us/callie/voicemail/vm-person.wav 2013-11-22 08:54:07.741822 [DEBUG] switch_ivr_play_say.c:251 Handle say:[1001] (en:en) 2013-11-22 08:54:07.773044 [DEBUG] switch_ivr_play_say.c:1319 Codec Activated L16@8000hz 1 channels 20ms 2013-11-22 08:54:12.440823 [DEBUG] switch_ivr_play_say.c:1723 done playing file file_string://digits/1.wav!digits/0.wav!digits/0.wav!digits/1.wav 2013-11-22 08:54:12.550102 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-not_available.wav] (en:en) 2013-11-22 08:54:12.596936 [DEBUG] switch_ivr_play_say.c:1319 Codec Activated L16@8000hz 1 channels 20ms 2013-11-22 08:54:14.532737 [DEBUG] switch_ivr_play_say.c:1723 done playing file C:/Program Files/FreeSWITCH/sounds/en/us/callie/voicemail/vm-not_available.wav 2013-11-22 08:54:14.657628 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2013-11-22 08:54:14.657628 [DEBUG] switch_ivr_play_say.c:251 Handle play-file:[voicemail/vm-record_message.wav] (en:en) 2013-11-22 08:54:14.673239 [DEBUG] switch_ivr_play_say.c:1319 Codec Activated L16@8000hz 1 channels 20ms 2013-11-22 08:54:23.852683 [DEBUG] switch_ivr_play_say.c:1723 done playing file C:/Program Files/FreeSWITCH/sounds/en/us/callie/voicemail/vm-record_message.wav 2013-11-22 08:54:26.459770 [DEBUG] switch_channel.c:3639 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:26.459770 [NOTICE] mod_loopback.c:942 Channel [loopback/voicemail-a] has been answered 2013-11-22 08:54:26.459770 [DEBUG] switch_channel.c:3685 (loopback/voicemail-a) Callstate Change EARLY -> ACTIVE 2013-11-22 08:54:26.459770 [DEBUG] switch_core_session.c:892 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:26.459770 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:26.459770 [NOTICE] switch_ivr_play_say.c:409 Channel [loopback/voicemail-b] has been answered 2013-11-22 08:54:26.459770 [DEBUG] switch_channel.c:3685 (loopback/voicemail-b) Callstate Change EARLY -> ACTIVE 2013-11-22 08:54:26.459770 [DEBUG] switch_ivr_play_say.c:599 Raw Codec Activated 2013-11-22 08:54:26.459770 [DEBUG] switch_core_codec.c:221 loopback/voicemail-b Push codec L16:70 2013-11-22 08:54:26.475382 [DEBUG] switch_core_session.c:954 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:26.475382 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:26.475382 [DEBUG] switch_core_session.c:954 Send signal sofia/internal/1009@10.0.0.57 [BREAK] recv 726 bytes from udp/[10.0.0.186]:5060 at 07:54:28.270681: ------------------------------------------------------------------------ BYE sip:1001@10.0.0.57:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK36N5Uryr0Z1Bc Max-Forwards: 70 From: <1009@10.0.0.57> <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=3jQFZFQ68HcSm Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571883 BYE User-Agent: sofia-sip/1.12.10 Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE Supported: timer, 100rel Proxy-Authorization: Digest username="1009", realm="10.0.0.57", nonce="598a20fb-5ab3-4ecf-af64-71388a03b2e6", cnonce="XIhwKMIwEjGCaQBQwtXdBw", algorithm=MD5, uri="sip:1001@10.0.0.57:5060;transport=udp", response="f3fac72314ac0ff146b8561734438dc5", qop=auth, nc=00000002 Content-Length: 0
------------------------------------------------------------------------ 2013-11-22 08:54:28.255070 [DEBUG] switch_core_session.c:1037 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:28.270681 [NOTICE] sofia.c:715 Hangup sofia/internal/1009@10.0.0.57 [CS_EXECUTE] [NORMAL_CLEARING] 2013-11-22 08:54:28.270681 [DEBUG] switch_channel.c:3211 Send signal sofia/internal/1009@10.0.0.57 [KILL] 2013-11-22 08:54:28.270681 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] send 495 bytes to udp/[10.0.0.186]:5060 at 07:54:28.270681: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.0.186;rport=5060;branch=z9hG4bK36N5Uryr0Z1Bc From: <1009@10.0.0.57> <1009@10.0.0.57>;tag=08mryQ3v0DXtF To: <sip:1001@10.0.0.57>;tag=3jQFZFQ68HcSm Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07 CSeq: 51571883 BYE User-Agent: FreeSWITCH-mod_sofia/1.5.6b+git~20131101T202135Z~2589bf7750~32bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, precondition, path, replaces Content-Length: 0
------------------------------------------------------------------------ 2013-11-22 08:54:28.270681 [DEBUG] switch_ivr_bridge.c:647 BRIDGE THREAD DONE [sofia/internal/1009@10.0.0.57] 2013-11-22 08:54:28.270681 [DEBUG] switch_ivr_bridge.c:672 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:28.270681 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:28.301904 [DEBUG] switch_ivr_bridge.c:647 BRIDGE THREAD DONE [loopback/voicemail-a] 2013-11-22 08:54:28.301904 [DEBUG] switch_ivr_bridge.c:672 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:28.301904 [NOTICE] switch_ivr_bridge.c:735 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2013-11-22 08:54:28.301904 [DEBUG] switch_channel.c:3211 Send signal loopback/voicemail-a [KILL] 2013-11-22 08:54:28.301904 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:28.301904 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:28.301904 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:28.301904 [DEBUG] switch_ivr_bridge.c:1538 loopback/voicemail-a skip receive message [UNBRIDGE] (channel is hungup already) 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:532 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_HANGUP 2013-11-22 08:54:28.301904 [DEBUG] switch_ivr_bridge.c:1541 sofia/internal/1009@10.0.0.57 skip receive message [UNBRIDGE] (channel is hungup already) 2013-11-22 08:54:28.301904 [DEBUG] switch_core_session.c:2841 sofia/internal/1009@10.0.0.57 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:529 ( sofia/internal/1009@10.0.0.57) State EXECUTE going to sleep 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:467 ( sofia/internal/1009@10.0.0.57) Running State Change CS_HANGUP 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:730 (loopback/voicemail-a) State HANGUP 2013-11-22 08:54:28.301904 [DEBUG] mod_loopback.c:537 loopback/voicemail-a CHANNEL HANGUP 2013-11-22 08:54:28.301904 [NOTICE] mod_loopback.c:553 Hangup loopback/voicemail-b [CS_EXECUTE] [NORMAL_CLEARING] 2013-11-22 08:54:28.301904 [DEBUG] switch_channel.c:3211 Send signal loopback/voicemail-b [KILL] 2013-11-22 08:54:28.301904 [DEBUG] switch_core_state_machine.c:730 ( sofia/internal/1009@10.0.0.57) State HANGUP 2013-11-22 08:54:28.301904 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:28.317515 [DEBUG] mod_sofia.c:413 Channel sofia/internal/1009@10.0.0.57 hanging up, cause: NORMAL_CLEARING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:28.317515 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:58 loopback/voicemail-a Standard HANGUP, cause: NORMAL_CLEARING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:730 (loopback/voicemail-a) State HANGUP going to sleep 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:743 (loopback/voicemail-a) Callstate Change ACTIVE -> HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:498 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:28.317515 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-a) Running State Change CS_REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_codec.c:246 loopback/voicemail-b Restore previous codec PCMU:0. 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:815 (loopback/voicemail-a) State REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:102 loopback/voicemail-a Standard REPORTING, cause: NORMAL_CLEARING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:815 (loopback/voicemail-a) State REPORTING going to sleep 2013-11-22 08:54:28.317515 [DEBUG] mod_voicemail.c:1237 Message is less than minimum record length: 3, discarding it. 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:492 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-a [BREAK] 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:2841 loopback/voicemail-b skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2013-11-22 08:54:28.317515 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:529 (loopback/voicemail-b) State EXECUTE going to sleep 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:1580 Session 2 (loopback/voicemail-a) Locked, Waiting on external entities 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-b) Running State Change CS_HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:58 sofia/internal/1009@10.0.0.57 Standard HANGUP, cause: NORMAL_CLEARING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:730 ( sofia/internal/1009@10.0.0.57) State HANGUP going to sleep 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:743 ( sofia/internal/1009@10.0.0.57) Callstate Change ACTIVE -> HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:498 ( sofia/internal/1009@10.0.0.57) State Change CS_HANGUP -> CS_REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:730 (loopback/voicemail-b) State HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:28.317515 [DEBUG] mod_loopback.c:537 loopback/voicemail-b CHANNEL HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:58 loopback/voicemail-b Standard HANGUP, cause: NORMAL_CLEARING 2013-11-22 08:54:28.317515 [NOTICE] switch_core_session.c:1598 Session 2 (loopback/voicemail-a) Ended 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:467 ( sofia/internal/1009@10.0.0.57) Running State Change CS_REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:730 (loopback/voicemail-b) State HANGUP going to sleep 2013-11-22 08:54:28.317515 [NOTICE] switch_core_session.c:1602 Close Channel loopback/voicemail-a [CS_DESTROY] 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:743 (loopback/voicemail-b) Callstate Change ACTIVE -> HANGUP 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:815 ( sofia/internal/1009@10.0.0.57) State REPORTING 2013-11-22 08:54:28.317515 [DEBUG] switch_core_state_machine.c:617 (loopback/voicemail-a) Callstate Change HANGUP -> DOWN 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:498 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:620 (loopback/voicemail-a) Running State Change CS_DESTROY 2013-11-22 08:54:28.333126 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:28.333126 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:630 (loopback/voicemail-a) State DESTROY 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:467 (loopback/voicemail-b) Running State Change CS_REPORTING 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:109 loopback/voicemail-a Standard DESTROY 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:630 (loopback/voicemail-a) State DESTROY going to sleep 2013-11-22 08:54:28.333126 [DEBUG] switch_core_state_machine.c:815 (loopback/voicemail-b) State REPORTING 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:102 loopback/voicemail-b Standard REPORTING, cause: NORMAL_CLEARING 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:102 sofia/internal/1009@10.0.0.57 Standard REPORTING, cause: NORMAL_CLEARING 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:815 ( sofia/internal/1009@10.0.0.57) State REPORTING going to sleep 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:815 (loopback/voicemail-b) State REPORTING going to sleep 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:492 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:492 ( sofia/internal/1009@10.0.0.57) State Change CS_REPORTING -> CS_DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_session.c:1372 Send signal loopback/voicemail-b [BREAK] 2013-11-22 08:54:28.379960 [DEBUG] switch_core_session.c:1372 Send signal sofia/internal/1009@10.0.0.57 [BREAK] 2013-11-22 08:54:28.379960 [DEBUG] switch_core_session.c:1580 Session 1 ( sofia/internal/1009@10.0.0.57) Locked, Waiting on external entities 2013-11-22 08:54:28.379960 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL 2013-11-22 08:54:28.379960 [DEBUG] switch_core_session.c:1580 Session 3 (loopback/voicemail-b) Locked, Waiting on external entities 2013-11-22 08:54:28.379960 [NOTICE] switch_core_session.c:1598 Session 1 ( sofia/internal/1009@10.0.0.57) Ended 2013-11-22 08:54:28.379960 [NOTICE] switch_core_session.c:1602 Close Channel sofia/internal/1009@10.0.0.57 [CS_DESTROY] 2013-11-22 08:54:28.379960 [NOTICE] switch_core_session.c:1598 Session 3 (loopback/voicemail-b) Ended 2013-11-22 08:54:28.379960 [NOTICE] switch_core_session.c:1602 Close Channel loopback/voicemail-b [CS_DESTROY] 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:617 ( sofia/internal/1009@10.0.0.57) Callstate Change HANGUP -> DOWN 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:617 (loopback/voicemail-b) Callstate Change HANGUP -> DOWN 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:620 ( sofia/internal/1009@10.0.0.57) Running State Change CS_DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:620 (loopback/voicemail-b) Running State Change CS_DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:630 ( sofia/internal/1009@10.0.0.57) State DESTROY 2013-11-22 08:54:28.379960 [DEBUG] mod_sofia.c:323 sofia/internal/1009@10.0.0.57 SOFIA DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:630 (loopback/voicemail-b) State DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:109 loopback/voicemail-b Standard DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:109 sofia/internal/1009@10.0.0.57 Standard DESTROY 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:630 ( sofia/internal/1009@10.0.0.57) State DESTROY going to sleep 2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:630 (loopback/voicemail-b) State DESTROY going to sleep [/capture]
Can you see anything unusual in the trace above? -- JPI
Le 21/11/2013 22:06, Anthony Minessale a écrit :
Do you get different results when you call it with some other phone in place of sofia_cli ?
Can you get a full capture of the debug logs
sofia global siptrace on console loglevel debug sofia tracelevel alert
[... snip ...]
-- Anthony Minessale II
FreeSWITCH http://www.freeswitch.org/ ClueCon http://www.cluecon.com/ Twitter: http://twitter.com/FreeSWITCH_wire
AIM: anthm MSN:anthony_minessale@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch
FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
_________________________________________________________________________ Professional FreeSWITCH Consulting Services:consulting@freeswitch.orghttp://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Serverhttp://www.cudatel.com
Official FreeSWITCH Siteshttp://www.freeswitch.orghttp://wiki.freeswitch.orghttp://www.cluecon.com
FreeSWITCH-dev mailing listFreeSWITCH-dev@lists.freeswitch.orghttp://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-devhttp://www.freeswi...
_________________________________________________________________________ Professional FreeSWITCH Consulting Services: consulting@freeswitch.org http://www.freeswitchsolutions.com
FreeSWITCH-powered IP PBX: The CudaTel Communication Server http://www.cudatel.com
Official FreeSWITCH Sites http://www.freeswitch.org http://wiki.freeswitch.org http://www.cluecon.com
FreeSWITCH-dev mailing list FreeSWITCH-dev@lists.freeswitch.org http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev 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@hotmail.com GTALK/JABBER/PAYPAL:anthony.minessale@gmail.com IRC: irc.freenode.net #freeswitch FreeSWITCH Developer Conference sip:888@conference.freeswitch.org googletalk:conf+888@conference.freeswitch.org pstn:+19193869900
Bugnote created today on Jira under reference FreeSWITCH FS-6021. Thanks a lot for the useful pieces of advice. -- JPI Le 24/11/2013 02:31, Anthony Minessale a écrit :
You should transfer this info to jira, http://jira.freeswitch.org <http://jira.freeswitch.org/> it will easily get lost in this mailing list. My inbox fills hundreds of emails.....
Its the nest way to track issues.
participants (2)
-
Anthony Minessale
-
Jean-Paul Iribarren