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
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.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