Hi,
I started sip debug. And you can see the output:
INVITE sip:05305235244@XX.XX.XX.XX SIP/2.0
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK1507ea1f;rport
From: “02122134114” sip:02122134114@XX.XX.XX.XX;tag=as5d4ca7b8
To: sip:05305235244@XX.XX.XX.XX
Contact: sip:02122134114@YYY.YYY.YYY.YYY
Call-ID: 297044a51f2b84ad4930f74330184e61@XX.XX.XX.XX
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Mon, 18 Jan 2010 11:57:51 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 315
v=0
o=root 3419 3419 IN IP4 YYY.YYY.YYY.YYY
s=session
c=IN IP4 YYY.YYY.YYY.YYY
t=0 0
m=audio 19636 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
[Jan 18 13:57:51] VERBOSE[4444] logger.c:
<— SIP read from XX.XX.XX.XX:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;rport=5060;received=YYY.YYY.YYY.YYY;branch=z9hG4bK1507ea1f
From: “02122134114” sip:02122134114@XX.XX.XX.XX;tag=as5d4ca7b8
To: sip:05305235244@XX.XX.XX.XX
Call-ID: 297044a51f2b84ad4930f74330184e61@XX.XX.XX.XX
CSeq: 102 INVITE
Content-Length: 0
<------------->
[Jan 18 13:57:51] VERBOSE[4444] logger.c: — (7 headers 0 lines) —
[Jan 18 13:57:53] VERBOSE[4444] logger.c:
<— SIP read from XX.XX.XX.XX:5060 —>
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;rport=5060;received=YYY.YYY.YYY.YYY;branch=z9hG4bK1507ea1f
To: sip:05305235244@XX.XX.XX.XX;tag=3472804677-628605
From: “02122134114” sip:02122134114@XX.XX.XX.XX;tag=as5d4ca7b8
Call-ID: 297044a51f2b84ad4930f74330184e61@XX.XX.XX.XX
CSeq: 102 INVITE
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH
Contact: sip:05305235244@XX.XX.XX.XX:5060
Call-Info: sip:XX.XX.XX.XX;method="NOTIFY;Event=telephone-event;Duration=1000"
Content-Type: application/sdp
Content-Length: 208
v=0
o=btnxtmsc1 14207 14207 IN IP4 XX.XX.XX.XX
s=sip call
c=IN IP4 62.244.254.150
t=0 0
m=audio 39944 RTP/AVP 18 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=fmtp:18 annexb=no
a=ptime:20
<------------->
[Jan 18 13:57:53] VERBOSE[4444] logger.c: — (11 headers 10 lines) —
[Jan 18 13:57:53] VERBOSE[4444] logger.c: Found RTP audio format 18
[Jan 18 13:57:53] VERBOSE[4444] logger.c: Found RTP audio format 101
[Jan 18 13:57:53] VERBOSE[4444] logger.c: Peer audio RTP is at port 62.244.254.150:39944
[Jan 18 13:57:53] VERBOSE[4444] logger.c: Found audio description format telephone-event for ID 101
[Jan 18 13:57:53] VERBOSE[4444] logger.c: Capabilities: us - 0x10c (ulaw|alaw|g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729)
[Jan 18 13:57:53] VERBOSE[4444] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Jan 18 13:57:53] VERBOSE[4444] logger.c: Peer audio RTP is at port 62.244.254.150:39944
[Jan 18 13:57:53] DEBUG[4444] chan_sip.c: Oooh, we need to change our audio formats since our peer supports only 0x100 (g729) and not 0x4 (ulaw)
[Jan 18 13:57:54] VERBOSE[4444] logger.c:
<— SIP read from XX.XX.XX.XX:5060 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;rport=5060;received=YYY.YYY.YYY.YYY;branch=z9hG4bK1507ea1f
To: sip:05305235244@XX.XX.XX.XX;tag=3472804677-628605
From: “02122134114” sip:02122134114@XX.XX.XX.XX;tag=as5d4ca7b8
Call-ID: 297044a51f2b84ad4930f74330184e61@XX.XX.XX.XX
CSeq: 102 INVITE
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH
Contact: sip:05305235244@XX.XX.XX.XX:5060
Call-Info: sip:XX.XX.XX.XX;method="NOTIFY;Event=telephone-event;Duration=1000"
Content-Type: application/sdp
Content-Length: 208
v=0
o=btnxtmsc1 14207 14207 IN IP4 XX.XX.XX.XX
s=sip call
c=IN IP4 62.244.254.150
t=0 0
m=audio 39944 RTP/AVP 18 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=fmtp:18 annexb=no
a=ptime:20
<------------->
[Jan 18 13:57:54] VERBOSE[4444] logger.c: — (11 headers 10 lines) —
[Jan 18 13:57:54] VERBOSE[4444] logger.c: Found RTP audio format 18
[Jan 18 13:57:54] VERBOSE[4444] logger.c: Found RTP audio format 101
[Jan 18 13:57:54] VERBOSE[4444] logger.c: Peer audio RTP is at port 62.244.254.150:39944
[Jan 18 13:57:54] VERBOSE[4444] logger.c: Found audio description format telephone-event for ID 101
[Jan 18 13:57:54] VERBOSE[4444] logger.c: Capabilities: us - 0x10c (ulaw|alaw|g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729)
[Jan 18 13:57:54] VERBOSE[4444] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Jan 18 13:57:54] VERBOSE[4444] logger.c: Peer audio RTP is at port 62.244.254.150:39944
[Jan 18 13:57:56] VERBOSE[4444] logger.c:
<— SIP read from XX.XX.XX.XX:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;rport=5060;received=YYY.YYY.YYY.YYY;branch=z9hG4bK1507ea1f
To: sip:05305235244@XX.XX.XX.XX;tag=3472804677-628605
From: “02122134114” sip:02122134114@XX.XX.XX.XX;tag=as5d4ca7b8
Call-ID: 297044a51f2b84ad4930f74330184e61@XX.XX.XX.XX
CSeq: 102 INVITE
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH
Contact: sip:05305235244@XX.XX.XX.XX:5060
Call-Info: sip:XX.XX.XX.XX;method="NOTIFY;Event=telephone-event;Duration=1000"
Content-Type: application/sdp
Content-Length: 208
v=0
o=btnxtmsc1 14207 14207 IN IP4 XX.XX.XX.XX
s=sip call
c=IN IP4 62.244.254.150
t=0 0
m=audio 39944 RTP/AVP 18 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=fmtp:18 annexb=no
a=ptime:20
<------------->
[Jan 18 13:57:56] VERBOSE[4444] logger.c: — (11 headers 10 lines) —
[Jan 18 13:57:56] VERBOSE[4444] logger.c: Found RTP audio format 18
[Jan 18 13:57:56] VERBOSE[4444] logger.c: Found RTP audio format 101
[Jan 18 13:57:56] VERBOSE[4444] logger.c: Peer audio RTP is at port 62.244.254.150:39944
[Jan 18 13:57:56] VERBOSE[4444] logger.c: Found audio description format telephone-event for ID 101
[Jan 18 13:57:56] VERBOSE[4444] logger.c: Capabilities: us - 0x10c (ulaw|alaw|g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729)
[Jan 18 13:57:56] VERBOSE[4444] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Jan 18 13:57:56] VERBOSE[4444] logger.c: Peer audio RTP is at port 62.244.254.150:39944
[Jan 18 13:57:56] VERBOSE[4444] logger.c: list_route: hop: sip:05305235244@XX.XX.XX.XX:5060
[Jan 18 13:57:56] DEBUG[4444] chan_sip.c: Strict routing enforced for session 297044a51f2b84ad4930f74330184e61@XX.XX.XX.XX
[Jan 18 13:57:56] VERBOSE[4444] logger.c: set_destination: Parsing sip:05305235244@XX.XX.XX.XX:5060 for address/port to send to
[Jan 18 13:57:56] VERBOSE[4444] logger.c: set_destination: set destination to XX.XX.XX.XX, port 5060
[Jan 18 13:57:56] VERBOSE[4444] logger.c: Transmitting (NAT) to XX.XX.XX.XX:5060:
ACK sip:05305235244@XX.XX.XX.XX:5060 SIP/2.0
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK0113a5cb;rport
From: “02122134114” sip:02122134114@XX.XX.XX.XX;tag=as5d4ca7b8
To: sip:05305235244@XX.XX.XX.XX;tag=3472804677-628605
Contact: sip:02122134114@YYY.YYY.YYY.YYY
Call-ID: 297044a51f2b84ad4930f74330184e61@XX.XX.XX.XX
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0
[Jan 18 13:57:56] VERBOSE[4516] logger.c: > Channel SIP/MySIP-09587a30 was answered.
[Jan 18 13:57:56] VERBOSE[4518] logger.c: – Executing [05305235244@MySIP:1] Set(“SIP/MySIP-09587a30”, “CALLERID(all)=Telegami <02124448546>”) in new stack
[Jan 18 13:57:56] WARNING[4518] pbx.c: Can’t find trailing parenthesis?
[Jan 18 13:57:56] VERBOSE[4518] logger.c: – Executing [05305235244@MySIP:2] Set(“SIP/MySIP-09587a30”, “CALLFILENAME=5305235244-Mon Jan 18 13:57:56 2010||%Y%m%d-%H%M%S)}-”) in new stack
[Jan 18 13:57:56] WARNING[4518] pbx.c: Setting multiple variables at once within Set is deprecated. Please separate each name/value pair into its own line.
[Jan 18 13:57:56] WARNING[4518] pbx.c: Ignoring entry ‘’ with no = (and not last ‘options’ entry)
[Jan 18 13:57:56] VERBOSE[4518] logger.c: – Executing [05305235244@MySIP:3] Monitor(“SIP/MySIP-09587a30”, “wav|5305235244-Mon Jan 18 13:57:56 2010|m”) in new stack
[Jan 18 13:57:56] VERBOSE[4518] logger.c: – Executing [05305235244@MySIP:4] Dial(“SIP/MySIP-09587a30”, “SIP/05305235244@MySIP”) in new stack
[Jan 18 13:57:56] VERBOSE[4518] logger.c: Audio is at YYY.YYY.YYY.YYY port 17596
[Jan 18 13:57:56] VERBOSE[4518] logger.c: Adding codec 0x100 (g729) to SDP
[Jan 18 13:57:56] VERBOSE[4518] logger.c: Adding codec 0x4 (ulaw) to SDP
[Jan 18 13:57:56] VERBOSE[4518] logger.c: Adding codec 0x8 (alaw) to SDP
[Jan 18 13:57:56] VERBOSE[4518] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
[Jan 18 13:57:56] VERBOSE[4518] logger.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:5060:
INVITE sip:05305235244@XX.XX.XX.XX SIP/2.0
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK78955bf6;rport
From: “Telegami” sip:02124448546@XX.XX.XX.XX;tag=as05dd652c
To: sip:05305235244@XX.XX.XX.XX
Contact: sip:02124448546@YYY.YYY.YYY.YYY
Call-ID: 5004eaab24eebe5e7fc7177d1c4ee299@XX.XX.XX.XX
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Mon, 18 Jan 2010 11:57:56 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 315
v=0
o=root 3419 3419 IN IP4 YYY.YYY.YYY.YYY
s=session
c=IN IP4 YYY.YYY.YYY.YYY
t=0 0
m=audio 17596 RTP/AVP 18 0 8 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
[Jan 18 13:57:56] VERBOSE[4518] logger.c: – Called 05305235244@MySIP
[Jan 18 13:57:56] VERBOSE[4444] logger.c:
<— SIP read from XX.XX.XX.XX:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;rport=5060;received=YYY.YYY.YYY.YYY;branch=z9hG4bK78955bf6
From: “Telegami” sip:02124448546@XX.XX.XX.XX;tag=as05dd652c
To: sip:05305235244@XX.XX.XX.XX
Call-ID: 5004eaab24eebe5e7fc7177d1c4ee299@XX.XX.XX.XX
CSeq: 102 INVITE
Content-Length: 0
<------------->
[Jan 18 13:57:56] VERBOSE[4444] logger.c: — (7 headers 0 lines) —
[Jan 18 13:57:56] VERBOSE[4444] logger.c:
<— SIP read from XX.XX.XX.XX:5060 —>
SIP/2.0 486 Busy here
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;rport=5060;received=YYY.YYY.YYY.YYY;branch=z9hG4bK78955bf6
To: sip:05305235244@XX.XX.XX.XX;tag=3472804680-801306
From: “Telegami” sip:02124448546@XX.XX.XX.XX;tag=as05dd652c
Call-ID: 5004eaab24eebe5e7fc7177d1c4ee299@XX.XX.XX.XX
CSeq: 102 INVITE
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH
Contact: sip:05305235244@XX.XX.XX.XX:5060
Call-Info: sip:XX.XX.XX.XX;method="NOTIFY;Event=telephone-event;Duration=1000"
Content-Length: 0
<------------->
[Jan 18 13:57:56] VERBOSE[4444] logger.c: — (10 headers 0 lines) —
[Jan 18 13:57:56] VERBOSE[4444] logger.c: – Got SIP response 486 “Busy here” back from XX.XX.XX.XX
[Jan 18 13:57:56] VERBOSE[4444] logger.c: Transmitting (NAT) to XX.XX.XX.XX:5060:
ACK sip:05305235244@XX.XX.XX.XX SIP/2.0
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK78955bf6;rport
From: “Telegami” sip:02124448546@XX.XX.XX.XX;tag=as05dd652c
To: sip:05305235244@XX.XX.XX.XX;tag=3472804680-801306
Contact: sip:02124448546@YYY.YYY.YYY.YYY
Call-ID: 5004eaab24eebe5e7fc7177d1c4ee299@XX.XX.XX.XX
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0
[Jan 18 13:57:56] VERBOSE[4518] logger.c: – SIP/MySIP-095a81d0 is busy
[Jan 18 13:57:56] VERBOSE[4518] logger.c: == Everyone is busy/congested at this time (1:1/0/0)
[Jan 18 13:57:56] VERBOSE[4518] logger.c: == Auto fallthrough, channel ‘SIP/MySIP-09587a30’ status is ‘BUSY’
[Jan 18 13:57:56] VERBOSE[4444] logger.c: Really destroying SIP dialog '5004eaab24eebe5e7fc7177d1c4ee299@XX.XX.XX.XX’ Method: INVITE
[Jan 18 13:58:07] VERBOSE[4518] logger.c: Scheduling destruction of SIP dialog '297044a51f2b84ad4930f74330184e61@XX.XX.XX.XX’ in 10752 ms (Method: INVITE)
[Jan 18 13:58:07] DEBUG[4518] chan_sip.c: Strict routing enforced for session 297044a51f2b84ad4930f74330184e61@XX.XX.XX.XX
[Jan 18 13:58:07] VERBOSE[4518] logger.c: set_destination: Parsing sip:05305235244@XX.XX.XX.XX:5060 for address/port to send to
[Jan 18 13:58:07] VERBOSE[4518] logger.c: set_destination: set destination to XX.XX.XX.XX, port 5060
[Jan 18 13:58:07] VERBOSE[4518] logger.c: Reliably Transmitting (NAT) to XX.XX.XX.XX:5060:
BYE sip:05305235244@XX.XX.XX.XX:5060 SIP/2.0
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;branch=z9hG4bK00ee8f73;rport
From: “02122134114” sip:02122134114@XX.XX.XX.XX;tag=as5d4ca7b8
To: sip:05305235244@XX.XX.XX.XX;tag=3472804677-628605
Call-ID: 297044a51f2b84ad4930f74330184e61@XX.XX.XX.XX
CSeq: 103 BYE
User-Agent: Asterisk PBX
Max-Forwards: 70
X-Asterisk-HangupCause: User busy
X-Asterisk-HangupCauseCode: 17
Content-Length: 0
[Jan 18 13:58:07] DEBUG[4518] res_monitor.c: monitor executing ( nice -n 19 sox -m “/var/spool/asterisk/monitor/5305235244-Mon Jan 18 13:57:56 2010-in.wav” “/var/spool/asterisk/monitor/5305235244-Mon Jan 18 13:57:56 2010-out.wav” “/var/spool/asterisk/monitor/5305235244-Mon Jan 18 13:57:56 2010.wav” && rm -f “/var/spool/asterisk/monitor/5305235244-Mon Jan 18 13:57:56 2010-”* ) &
[Jan 18 13:58:07] VERBOSE[4444] logger.c:
<— SIP read from XX.XX.XX.XX:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP YYY.YYY.YYY.YYY:5060;rport=5060;received=YYY.YYY.YYY.YYY;branch=z9hG4bK00ee8f73
To: sip:05305235244@XX.XX.XX.XX;tag=3472804677-628605
From: “02122134114” sip:02122134114@XX.XX.XX.XX;tag=as5d4ca7b8
Call-ID: 297044a51f2b84ad4930f74330184e61@XX.XX.XX.XX
CSeq: 103 BYE
Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH
Contact: sip:05305235244@XX.XX.XX.XX:5060
Content-Length: 0
Thanks.