[Freeswitch-dev] FreeSWITCH erroneous RTP timestamps in front of sofsip_cli client?
Jean-Paul Iribarren
jeanpaul.iribarren at free.fr
Fri Nov 22 11:26:27 MSK 2013
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 at XXX-xxxxxxxxx> recv 675 bytes from udp/[10.0.0.186]:5060 at
07:54:00.545012:
------------------------------------------------------------------------
INVITE sip:1001 at 10.0.0.57 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK0BaUp7Be94yKS
Max-Forwards: 70
From: <1009 at 10.0.0.57>;tag=08mryQ3v0DXtF
To: <sip:1001 at 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 at 10.0.0.57>;tag=08mryQ3v0DXtF
To: <sip:1001 at 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 at 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 at 10.0.0.57 [BREAK]
2013-11-22 08:54:00.560624 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/1009 at 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 at 10.0.0.57 [BREAK]
2013-11-22 08:54:00.560624 [DEBUG] switch_core_state_machine.c:485
(sofia/internal/1009 at 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 at 10.0.0.57>;tag=08mryQ3v0DXtF
To: <sip:1001 at 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 at 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 at 10.0.0.57 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK0BaUp7Be94yKS
Max-Forwards: 70
From: <1009 at 10.0.0.57>;tag=08mryQ3v0DXtF
To: <sip:1001 at 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 at 10.0.0.57 SIP/2.0
Via: SIP/2.0/UDP 10.0.0.186;rport;branch=z9hG4bK1m3Kr2vH6DN6m
Max-Forwards: 70
From: <1009 at 10.0.0.57>;tag=08mryQ3v0DXtF
To: <sip:1001 at 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 at 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 at 10.0.0.57>;tag=08mryQ3v0DXtF
To: <sip:1001 at 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 at 10.0.0.57 [BREAK]
2013-11-22 08:54:03.370658 [DEBUG] switch_core_session.c:1037 Send
signal sofia/internal/1009 at 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 at 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 at 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 at 10.0.0.57 [BREAK]
2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:467
(sofia/internal/1009 at 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 at 10.0.0.57) State INIT
2013-11-22 08:54:03.417492 [DEBUG] mod_sofia.c:87
sofia/internal/1009 at 10.0.0.57 SOFIA INIT
2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:40
sofia/internal/1009 at 10.0.0.57 Standard INIT
2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:48
(sofia/internal/1009 at 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 at 10.0.0.57 [BREAK]
2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:506
(sofia/internal/1009 at 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 at 10.0.0.57) Running State Change CS_ROUTING
2013-11-22 08:54:03.417492 [DEBUG] switch_channel.c:2178
(sofia/internal/1009 at 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 at 10.0.0.57) State ROUTING
2013-11-22 08:54:03.417492 [DEBUG] mod_sofia.c:123
sofia/internal/1009 at 10.0.0.57 SOFIA ROUTING
2013-11-22 08:54:03.417492 [DEBUG] switch_core_state_machine.c:164
sofia/internal/1009 at 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 at 10.0.0.57 parsing [default->unloop]
continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (PASS) [unloop]
${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [unloop]
${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing [default->tod_example]
continue=true
Dialplan: sofia/internal/1009 at 10.0.0.57 Date/TimeMatch (FAIL)
[tod_example] break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing
[default->holiday_example] continue=true
Dialplan: sofia/internal/1009 at 10.0.0.57 Date/TimeMatch (FAIL)
[holiday_example] break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing
[default->global-intercept] continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [global-intercept]
destination_number(1001) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing
[default->group-intercept] continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [group-intercept]
destination_number(1001) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing [default->intercept-ext]
continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [intercept-ext]
destination_number(1001) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing [default->redial]
continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [redial]
destination_number(1001) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing [default->global]
continue=true
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [global]
${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1009 at 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 at 10.0.0.57 Regex (PASS) [global]
${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/
break=on-false
Dialplan: sofia/internal/1009 at 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 at 10.0.0.57 Absolute Condition [global]
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing [default->snom-demo-2]
continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [snom-demo-2]
destination_number(1001) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing [default->snom-demo-1]
continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [snom-demo-1]
destination_number(1001) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing [default->eavesdrop]
continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [eavesdrop]
destination_number(1001) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing [default->eavesdrop]
continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [eavesdrop]
destination_number(1001) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing [default->call_return]
continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [call_return]
destination_number(1001) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing [default->del-group]
continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [del-group]
destination_number(1001) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing [default->add-group]
continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [add-group]
destination_number(1001) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing
[default->call-group-simo] continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [call-group-simo]
destination_number(1001) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing
[default->call-group-order] continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL) [call-group-order]
destination_number(1001) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing
[default->extension-intercom] continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (FAIL)
[extension-intercom] destination_number(1001) =~ /^8(10[01][0-9])$/
break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 parsing
[default->Local_Extension] continue=false
Dialplan: sofia/internal/1009 at 10.0.0.57 Regex (PASS) [Local_Extension]
destination_number(1001) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1009 at 10.0.0.57 Action export(dialed_extension=1001)
Dialplan: sofia/internal/1009 at 10.0.0.57 Action bind_meta_app(1 b s
execute_extension::dx XML features)
Dialplan: sofia/internal/1009 at 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 at 10.0.0.57 Action bind_meta_app(3 b s
execute_extension::cf XML features)
Dialplan: sofia/internal/1009 at 10.0.0.57 Action bind_meta_app(4 b s
execute_extension::att_xfer XML features)
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
set(disable_rtp_auto_adjust=true)
Dialplan: sofia/internal/1009 at 10.0.0.57 Action set(zrtp_secure_media=false)
Dialplan: sofia/internal/1009 at 10.0.0.57 Action set(ringback=${us-ring})
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1009 at 10.0.0.57 Action set(call_timeout=30)
Dialplan: sofia/internal/1009 at 10.0.0.57 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/1009 at 10.0.0.57 Action set(continue_on_fail=true)
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var
callgroup)})
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1009 at 10.0.0.57 Action
bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/1009 at 10.0.0.57 Action answer()
Dialplan: sofia/internal/1009 at 10.0.0.57 Action sleep(1000)
Dialplan: sofia/internal/1009 at 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 at 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 at 10.0.0.57 [BREAK]
2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:522
(sofia/internal/1009 at 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 at 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 at 10.0.0.57) State EXECUTE
2013-11-22 08:54:03.433103 [DEBUG] mod_sofia.c:178
sofia/internal/1009 at 10.0.0.57 SOFIA EXECUTE
2013-11-22 08:54:03.433103 [DEBUG] switch_core_state_machine.c:256
sofia/internal/1009 at 10.0.0.57 Standard EXECUTE
EXECUTE sofia/internal/1009 at 10.0.0.57
hash(insert/10.0.0.57-spymap/1009/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c)
EXECUTE sofia/internal/1009 at 10.0.0.57
hash(insert/10.0.0.57-last_dial/1009/1001)
EXECUTE sofia/internal/1009 at 10.0.0.57
hash(insert/10.0.0.57-last_dial/global/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c)
EXECUTE sofia/internal/1009 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 10.0.0.57 SET [disable_rtp_auto_adjust]=[true]
EXECUTE sofia/internal/1009 at 10.0.0.57 set(zrtp_secure_media=false)
2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402
sofia/internal/1009 at 10.0.0.57 SET [zrtp_secure_media]=[false]
EXECUTE sofia/internal/1009 at 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 at 10.0.0.57 SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/1009 at 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 at 10.0.0.57 SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1009 at 10.0.0.57 set(call_timeout=30)
2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402
sofia/internal/1009 at 10.0.0.57 SET [call_timeout]=[30]
EXECUTE sofia/internal/1009 at 10.0.0.57 set(hangup_after_bridge=true)
2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402
sofia/internal/1009 at 10.0.0.57 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1009 at 10.0.0.57 set(continue_on_fail=true)
2013-11-22 08:54:03.495548 [DEBUG] mod_dptools.c:1402
sofia/internal/1009 at 10.0.0.57 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1009 at 10.0.0.57
hash(insert/10.0.0.57-call_return/1001/1009)
EXECUTE sofia/internal/1009 at 10.0.0.57
hash(insert/10.0.0.57-last_dial_ext/1001/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c)
EXECUTE sofia/internal/1009 at 10.0.0.57
set(called_party_callgroup=techsupport)
2013-11-22 08:54:03.511159 [DEBUG] mod_dptools.c:1402
sofia/internal/1009 at 10.0.0.57 SET [called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/1009 at 10.0.0.57
hash(insert/10.0.0.57-last_dial_ext/techsupport/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c)
EXECUTE sofia/internal/1009 at 10.0.0.57
hash(insert/10.0.0.57-last_dial_ext/global/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c)
EXECUTE sofia/internal/1009 at 10.0.0.57
hash(insert/10.0.0.57-last_dial/techsupport/f28e1f66-1524-4ce5-9fe0-acf7bb929a1c)
EXECUTE sofia/internal/1009 at 10.0.0.57 bridge(user/1001 at 10.0.0.57)
2013-11-22 08:54:03.511159 [DEBUG] switch_channel.c:1201
sofia/internal/1009 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 10.0.0.57!
2013-11-22 08:54:03.542382 [DEBUG] switch_channel.c:3404
(sofia/internal/1009 at 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 at 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 at 10.0.0.57>;tag=08mryQ3v0DXtF
To: <sip:1001 at 10.0.0.57>;tag=3jQFZFQ68HcSm
Call-ID: 5c7dc01d-c230-1231-6982-0050c2d5dd07
CSeq: 51571882 INVITE
Contact: <sip:1001 at 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 at 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 at 10.0.0.57 [BREAK]
2013-11-22 08:54:03.542382 [DEBUG] switch_core_session.c:1037 Send
signal sofia/internal/1009 at 10.0.0.57 [BREAK]
2013-11-22 08:54:03.542382 [NOTICE] mod_dptools.c:1225 Channel
[sofia/internal/1009 at 10.0.0.57] has been answered
2013-11-22 08:54:03.557993 [DEBUG] switch_channel.c:3685
(sofia/internal/1009 at 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 at 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 at 10.0.0.57>;tag=08mryQ3v0DXtF
To: <sip:1001 at 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 at 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 at 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 at 10.0.0.57 [BREAK]
2013-11-22 08:54:03.557993 [DEBUG] switch_core_session.c:1037 Send
signal sofia/internal/1009 at 10.0.0.57 [BREAK]
2013-11-22 08:54:03.557993 [DEBUG] sofia.c:5863 Channel
sofia/internal/1009 at 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 at 10.0.0.57 [BREAK]
EXECUTE sofia/internal/1009 at 10.0.0.57 sleep(1000)
EXECUTE sofia/internal/1009 at 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 at 10.0.0.57) Callstate Change ACTIVE -> RING_WAIT
2013-11-22 08:54:04.572728 [DEBUG] switch_channel.c:1201
sofia/internal/1009 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 10.0.0.57 [BREAK]
recv 726 bytes from udp/[10.0.0.186]:5060 at 07:54:28.270681:
------------------------------------------------------------------------
BYE sip:1001 at 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 at 10.0.0.57>;tag=08mryQ3v0DXtF
To: <sip:1001 at 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 at 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 at 10.0.0.57 [BREAK]
2013-11-22 08:54:28.270681 [NOTICE] sofia.c:715 Hangup
sofia/internal/1009 at 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 at 10.0.0.57 [KILL]
2013-11-22 08:54:28.270681 [DEBUG] switch_core_session.c:1372 Send
signal sofia/internal/1009 at 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 at 10.0.0.57>;tag=08mryQ3v0DXtF
To: <sip:1001 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 10.0.0.57 [BREAK]
2013-11-22 08:54:28.379960 [DEBUG] switch_core_session.c:1580 Session 1
(sofia/internal/1009 at 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 at 10.0.0.57) Ended
2013-11-22 08:54:28.379960 [NOTICE] switch_core_session.c:1602 Close
Channel sofia/internal/1009 at 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 at 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 at 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 at 10.0.0.57) State DESTROY
2013-11-22 08:54:28.379960 [DEBUG] mod_sofia.c:323
sofia/internal/1009 at 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 at 10.0.0.57 Standard DESTROY
2013-11-22 08:54:28.379960 [DEBUG] switch_core_state_machine.c:630
(sofia/internal/1009 at 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 at hotmail.com
> <mailto:MSN%3Aanthony_minessale at hotmail.com>
> GTALK/JABBER/PAYPAL:anthony.minessale at gmail.com
> <mailto:PAYPAL%3Aanthony.minessale at gmail.com>
> IRC: irc.freenode.net <http://irc.freenode.net> #freeswitch
>
> FreeSWITCH Developer Conference
> sip:888 at conference.freeswitch.org
> <mailto:sip%3A888 at conference.freeswitch.org>
> googletalk:conf+888 at conference.freeswitch.org
> <mailto:googletalk%3Aconf%2B888 at conference.freeswitch.org>
> pstn:+19193869900
>
>
> _________________________________________________________________________
> Professional FreeSWITCH Consulting Services:
> consulting at freeswitch.org
> http://www.freeswitchsolutions.com
>
>
>
>
> Official FreeSWITCH Sites
> http://www.freeswitch.org
> http://wiki.freeswitch.org
> http://www.cluecon.com
>
> FreeSWITCH-dev mailing list
> FreeSWITCH-dev at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-dev
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-dev
> http://www.freeswitch.org
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-dev/attachments/20131122/ca09c966/attachment-0001.html
Join us at ClueCon 2013 Aug 6-8, 2013
More information about the FreeSWITCH-dev
mailing list