ASTERISK-10203: Supervised Transfer gives continious tone in transferred party

[Home]

Summary: ASTERISK-10203: Supervised Transfer gives continious tone in transferred party

Reporter: Boudewyn Ligthart (boudewyn) Labels:

Date Opened: 2007-08-30 09:11:59 Date Closed: 2007-10-08 09:48:24

Priority: Major Regression? No

Status: Closed/Complete Components: Channels/chan_sip/Transfers

Versions: Frequency of
Occurrence

Related
Issues:

Environment: Attachments: ( 0) Debug.txt

Description: 3 SIP Phones , 501,502,503 (All Mitel Phones 5215,5224,5212)
All using ulaw.

501 phones 502, answers, talking,
select trans/conf
502 phones 503, answers, talking,
option to transfer by pressing 0, press 0 --> transfer

502 get continous tone played back

****** ADDITIONAL INFORMATION ******

[Aug 30 13:27:09] DEBUG[27930] pbx.c: Launching 'Dial'
[Aug 30 13:27:09] VERBOSE[27930] logger.c: -- Executing [501@context_502:2] Dial("SIP/502-081c6668", "SIP/501|30") in new stack
[Aug 30 13:27:09] DEBUG[27930] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Aug 30 13:27:09] DEBUG[27930] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Aug 30 13:27:09] DEBUG[27930] chan_sip.c: Setting NAT on RTP to Off
[Aug 30 13:27:09] DEBUG[27930] channel.c: Not copying variable STACK-context_502-501-2.
[Aug 30 13:27:09] DEBUG[27930] channel.c: Not copying variable MACRO_DEPTH.
[Aug 30 13:27:09] DEBUG[27930] channel.c: Not copying variable STACK-macro-jumpcallerid-502-1.
[Aug 30 13:27:09] DEBUG[27930] channel.c: Not copying variable STACK-macro-jumpcallerid-s-1.
[Aug 30 13:27:09] DEBUG[27930] channel.c: Not copying variable STACK-context_502-501-1.
[Aug 30 13:27:09] DEBUG[27930] channel.c: Not copying variable SIPCALLID.
[Aug 30 13:27:09] DEBUG[27930] channel.c: Not copying variable SIPUSERAGENT.
[Aug 30 13:27:09] DEBUG[27930] channel.c: Not copying variable SIPDOMAIN.
[Aug 30 13:27:09] DEBUG[27930] channel.c: Not copying variable SIPURI.
[Aug 30 13:27:09] DEBUG[27930] chan_sip.c: Outgoing Call for 501
[Aug 30 13:27:09] VERBOSE[27930] logger.c: Audio is at 192.168.0.13 port 13644
[Aug 30 13:27:09] VERBOSE[27930] logger.c: Adding codec 0x4 (ulaw) to SDP
[Aug 30 13:27:09] VERBOSE[27930] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
[Aug 30 13:27:09] VERBOSE[27930] logger.c: Reliably Transmitting (no NAT) to 192.168.0.16:5060:
INVITE sip:501@192.168.0.16 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.13:5060;branch=z9hG4bK354f270a;rport
From: "five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
To: <sip:501@192.168.0.16>
Contact: <sip:5555@192.168.0.13>
Call-ID: 25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
CSeq: 102 INVITE
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Thu, 30 Aug 2007 12:27:09 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Type: application/sdp
Content-Length: 240

v=0
o=root 27822 27822 IN IP4 192.168.0.13
s=session
c=IN IP4 192.168.0.13
t=0 0
m=audio 13644 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

---
[Aug 30 13:27:09] VERBOSE[27930] logger.c: -- Called 501
[Aug 30 13:27:09] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
SIP/2.0 100 Trying
Via:SIP/2.0/UDP 192.168.0.13:5060;rport=5060;received=192.168.0.13;branch=z9hG4bK354f270a
From:"five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
To:<sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
CSeq:102 INVITE
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Call-ID:25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
Content-Length:0

<------------->
[Aug 30 13:27:09] VERBOSE[27842] logger.c: --- (8 headers 0 lines) ---
[Aug 30 13:27:09] DEBUG[27842] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13' Request 102: Found
[Aug 30 13:27:09] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
SIP/2.0 180 Ringing
Via:SIP/2.0/UDP 192.168.0.13:5060;rport=5060;received=192.168.0.13;branch=z9hG4bK354f270a
From:"five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
To:<sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
CSeq:102 INVITE
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Call-ID:25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
Allow-Events:talk,hold,conference
Content-Length:0

<------------->
[Aug 30 13:27:09] VERBOSE[27842] logger.c: --- (9 headers 0 lines) ---
[Aug 30 13:27:09] DEBUG[27842] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13' Request 102: Found
[Aug 30 13:27:09] VERBOSE[27930] logger.c: -- SIP/501-b6d00928 is ringing
[Aug 30 13:27:10] DEBUG[27930] chan_sip.c: Setting framing from config on incoming call
[Aug 30 13:27:10] DEBUG[27930] rtp.c: Ooh, format changed from unknown to ulaw
[Aug 30 13:27:10] DEBUG[27930] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Aug 30 13:27:10] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
SIP/2.0 200 OK
Via:SIP/2.0/UDP 192.168.0.13:5060;rport=5060;received=192.168.0.13;branch=z9hG4bK354f270a
From:"five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
To:<sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
CSeq:102 INVITE
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Call-ID:25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
Contact:"501" <sip:501@192.168.0.16>
Allow-Events:talk,hold,conference
Allow:INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,NOTIFY,PRACK,UPDATE
Supported:timer,100rel,replaces
Content-Type:application/sdp
Content-Length:182

v=0
o=501 1188463304 1188463303 IN IP4 192.168.0.16
s=SIP Call
c=IN IP4 192.168.0.16
t=0 0
m=audio 20002 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000

<------------->
[Aug 30 13:27:10] VERBOSE[27842] logger.c: --- (13 headers 8 lines) ---
[Aug 30 13:27:10] DEBUG[27842] chan_sip.c: Acked pending invite 102
[Aug 30 13:27:10] DEBUG[27842] chan_sip.c: Stopping retransmission on '25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13' of Request 102: Match Not Found
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Found RTP audio format 0
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Found RTP audio format 101
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Peer audio RTP is at port 192.168.0.16:20002
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Found description format PCMU for ID 0
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Found description format telephone-event for ID 101
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Peer audio RTP is at port 192.168.0.16:20002
[Aug 30 13:27:10] VERBOSE[27842] logger.c: list_route: hop: <sip:501@192.168.0.16>
[Aug 30 13:27:10] DEBUG[27842] chan_sip.c: Strict routing enforced for session 25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
[Aug 30 13:27:10] VERBOSE[27842] logger.c: set_destination: Parsing <sip:501@192.168.0.16> for address/port to send to
[Aug 30 13:27:10] VERBOSE[27842] logger.c: set_destination: set destination to 192.168.0.16, port 5060
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Transmitting (no NAT) to 192.168.0.16:5060:
ACK sip:501@192.168.0.16 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.13:5060;branch=z9hG4bK2c46c642;rport
From: "five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
To: <sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
Contact: <sip:5555@192.168.0.13>
Call-ID: 25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
CSeq: 102 ACK
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0

---
[Aug 30 13:27:10] VERBOSE[27930] logger.c: -- SIP/501-b6d00928 answered SIP/502-081c6668
[Aug 30 13:27:10] DEBUG[27930] chan_sip.c: SIP answering channel: SIP/502-081c6668
[Aug 30 13:27:10] DEBUG[27930] chan_sip.c: Setting framing from config on incoming call
[Aug 30 13:27:10] VERBOSE[27930] logger.c: -- Packet2Packet bridging SIP/502-081c6668 and SIP/501-b6d00928
[Aug 30 13:27:10] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
SUBSCRIBE sip:192.168.0.13 SIP/2.0
Via:SIP/2.0/UDP 192.168.0.16:5060;rport;branch=z9hG4bK7f7b0005
From:<sip:501@192.168.0.13>;tag=46d67f7b-3a0-7bc8afc4
To:<sip:192.168.0.13>
Contact:<sip:501@192.168.0.16>
Call-ID:7f7b0000-44b97313@192.168.0.16
CSeq:2 SUBSCRIBE
Expires: 7200
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Event: message-summary
Max-Forwards:70
Accept:application/simple-message-summary
Content-Length:0

<------------->
[Aug 30 13:27:10] VERBOSE[27842] logger.c: --- (13 headers 0 lines) ---
[Aug 30 13:27:10] DEBUG[27842] chan_sip.c: Allocating new SIP dialog for 7f7b0000-44b97313@192.168.0.16 - SUBSCRIBE (No RTP)
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Creating new subscription
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Sending to 192.168.0.16 : 5060 (NAT)
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Found peer '501'
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Looking for s in context_501 (domain 192.168.0.13)
[Aug 30 13:27:10] VERBOSE[27842] logger.c:
<--- Transmitting (no NAT) to 192.168.0.16:5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 192.168.0.16:5060;branch=z9hG4bK7f7b0005;received=192.168.0.16;rport=5060
From: <sip:501@192.168.0.13>;tag=46d67f7b-3a0-7bc8afc4
To: <sip:192.168.0.13>;tag=as67a5a5ca
Call-ID: 7f7b0000-44b97313@192.168.0.16
CSeq: 2 SUBSCRIBE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0

<------------>
[Aug 30 13:27:10] VERBOSE[27842] logger.c: Really destroying SIP dialog '7f7b0000-44b97313@192.168.0.16' Method: SUBSCRIBE
[Aug 30 13:27:10] DEBUG[27842] chan_sip.c: Stopping retransmission on 'c5ca0000-7cee94b1@192.168.0.13' of Response 673416698: Match Not Found
[Aug 30 13:27:11] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
INVITE sip:5555@192.168.0.13 SIP/2.0
Via:SIP/2.0/UDP 192.168.0.16:5060;rport;branch=z9hG4bK7f7d0006
From:<sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
To:"five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
Contact:"501" <sip:501@192.168.0.16>
Call-ID:25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
CSeq:103 INVITE
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Allow:INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,NOTIFY,PRACK,UPDATE
Allow-Events:talk,hold,conference
Supported:timer,100rel,replaces
Max-Forwards:70
Content-Type:application/sdp
Content-Length:194

v=0
o=501 1188463305 1188463304 IN IP4 192.168.0.16
s=SIP Call
c=IN IP4 192.168.0.16
t=0 0
a=sendonly
m=audio 20002 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000

<------------->
[Aug 30 13:27:11] VERBOSE[27842] logger.c: --- (14 headers 9 lines) ---
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Sending to 192.168.0.16 : 5060 (NAT)
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Found RTP audio format 0
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Found RTP audio format 101
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Peer audio RTP is at port 192.168.0.16:20002
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Found description format PCMU for ID 0
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Found description format telephone-event for ID 101
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Peer audio RTP is at port 192.168.0.16:20002
[Aug 30 13:27:11] DEBUG[27842] chan_sip.c: Setting framing from config on incoming call
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Audio is at 192.168.0.13 port 13644
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Adding codec 0x4 (ulaw) to SDP
[Aug 30 13:27:11] VERBOSE[27842] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
[Aug 30 13:27:11] VERBOSE[27842] logger.c:
<--- Transmitting (NAT) to 192.168.0.16:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.16:5060;branch=z9hG4bK7f7d0006;received=192.168.0.16;rport=5060
From: <sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
To: "five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
Call-ID: 25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
CSeq: 103 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:5555@192.168.0.13>
Content-Type: application/sdp
Content-Length: 240

v=0
o=root 27822 27823 IN IP4 192.168.0.13
s=session
c=IN IP4 192.168.0.13
t=0 0
m=audio 13644 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=recvonly

<------------>
[Aug 30 13:27:11] VERBOSE[27930] logger.c: -- Started music on hold, class 'default', on SIP/502-081c6668
[Aug 30 13:27:11] DEBUG[27930] channel.c: Scheduling timer at 160 sample intervals
[Aug 30 13:27:11] DEBUG[27930] channel.c: Scheduling timer at 0 sample intervals
[Aug 30 13:27:11] WARNING[27930] file.c: File /var/lib/asterisk/mohmp3//fpm-world-mix does not exist in any format
[Aug 30 13:27:11] WARNING[27930] res_musiconhold.c: Unable to open file '/var/lib/asterisk/mohmp3//fpm-world-mix': No such file or directory
[Aug 30 13:27:11] VERBOSE[27930] logger.c: -- Stopped music on hold on SIP/502-081c6668
[Aug 30 13:27:11] DEBUG[27930] channel.c: Scheduling timer at 0 sample intervals
[Aug 30 13:27:11] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
ACK sip:5555@192.168.0.13 SIP/2.0
Via:SIP/2.0/UDP 192.168.0.16:5060;rport;branch=z9hG4bK7f7d0007
From:<sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
To:"five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
Contact:"501" <sip:501@192.168.0.16>
Call-ID:25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
CSeq:103 ACK
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Max-Forwards:70
Content-Length:0

<------------->
[Aug 30 13:27:11] VERBOSE[27842] logger.c: --- (10 headers 0 lines) ---
[Aug 30 13:27:11] DEBUG[27842] chan_sip.c: Stopping retransmission on '25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13' of Response 103: Match Found
[Aug 30 13:27:14] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
INVITE sip:503@192.168.0.13 SIP/2.0
Via:SIP/2.0/UDP 192.168.0.16:5060;rport;branch=z9hG4bK7f7f0008
From:"501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To:<sip:503@192.168.0.13>
Contact:"501" <sip:501@192.168.0.16>
Call-ID:7f7f0000-1247106c@192.168.0.13
Subject:sip phone call
CSeq:178822075 INVITE
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Allow:INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,NOTIFY,PRACK,UPDATE
Allow-Events:talk,hold,conference
Supported:timer,100rel,replaces
Session-Expires: 1800
Min-SE: 90
Max-Forwards:70
Content-Type:application/sdp
Content-Length:244

v=0
o=501 1188463131 1188463130 IN IP4 192.168.0.16
s=SIP Call
c=IN IP4 192.168.0.16
t=0 0
a=sendrecv
m=audio 20004 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000

<------------->
[Aug 30 13:27:14] VERBOSE[27842] logger.c: --- (17 headers 11 lines) ---
[Aug 30 13:27:14] DEBUG[27842] chan_sip.c: Setting NAT on RTP to Off
[Aug 30 13:27:14] DEBUG[27842] chan_sip.c: Allocating new SIP dialog for 7f7f0000-1247106c@192.168.0.13 - INVITE (With RTP)
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Sending to 192.168.0.16 : 5060 (NAT)
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Using INVITE request as basis request - 7f7f0000-1247106c@192.168.0.13
[Aug 30 13:27:14] DEBUG[27842] chan_sip.c: Setting NAT on RTP to Off
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Found user '501'
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Found RTP audio format 0
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Found RTP audio format 8
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Found RTP audio format 18
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Found RTP audio format 101
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Peer audio RTP is at port 192.168.0.16:20004
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Found description format PCMU for ID 0
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Found description format PCMA for ID 8
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Found description format G729 for ID 18
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Found description format telephone-event for ID 101
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Peer audio RTP is at port 192.168.0.16:20004
[Aug 30 13:27:14] DEBUG[27842] chan_sip.c: Checking SIP call limits for device 501
[Aug 30 13:27:14] VERBOSE[27842] logger.c: Looking for 503 in context_501 (domain 192.168.0.13)
[Aug 30 13:27:14] VERBOSE[27842] logger.c: list_route: hop: <sip:501@192.168.0.16>
[Aug 30 13:27:14] VERBOSE[27842] logger.c:
<--- Transmitting (no NAT) to 192.168.0.16:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.0.16:5060;branch=z9hG4bK7f7f0008;received=192.168.0.16;rport=5060
From: "501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To: <sip:503@192.168.0.13>
Call-ID: 7f7f0000-1247106c@192.168.0.13
CSeq: 178822075 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:503@192.168.0.13>
Content-Length: 0

<------------>
[Aug 30 13:27:14] DEBUG[27937] pbx.c: Function result is 'five o one (501)'
[Aug 30 13:27:14] DEBUG[27937] pbx.c: Function result is '501'
[Aug 30 13:27:14] DEBUG[27937] pbx.c: Launching 'Set'
[Aug 30 13:27:14] VERBOSE[27937] logger.c: -- Executing [503@context_501:1] Set("SIP/501-081f0d10", "CALLERID(all)=five o one (501)<01>") in new stack
[Aug 30 13:27:14] DEBUG[27937] pbx.c: Launching 'Dial'
[Aug 30 13:27:14] VERBOSE[27937] logger.c: -- Executing [503@context_501:2] Dial("SIP/501-081f0d10", "SIP/503|30|wW") in new stack
[Aug 30 13:27:14] DEBUG[27937] chan_sip.c: Asked to create a SIP channel with formats: 0x4 (ulaw)
[Aug 30 13:27:14] DEBUG[27937] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP)
[Aug 30 13:27:14] DEBUG[27937] chan_sip.c: Setting NAT on RTP to Off
[Aug 30 13:27:14] DEBUG[27937] channel.c: Not copying variable STACK-context_501-503-2.
[Aug 30 13:27:14] DEBUG[27937] channel.c: Not copying variable STACK-context_501-503-1.
[Aug 30 13:27:14] DEBUG[27937] channel.c: Not copying variable SIPCALLID.
[Aug 30 13:27:14] DEBUG[27937] channel.c: Not copying variable SIPUSERAGENT.
[Aug 30 13:27:14] DEBUG[27937] channel.c: Not copying variable SIPDOMAIN.
[Aug 30 13:27:14] DEBUG[27937] channel.c: Not copying variable SIPURI.
[Aug 30 13:27:14] DEBUG[27937] chan_sip.c: Outgoing Call for 503
[Aug 30 13:27:14] VERBOSE[27937] logger.c: -- Called 503
[Aug 30 13:27:14] DEBUG[27842] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '490743753757935372eeef8b5d4e48b9@192.168.0.13' Request 102: Found
[Aug 30 13:27:14] DEBUG[27842] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '490743753757935372eeef8b5d4e48b9@192.168.0.13' Request 102: Found
[Aug 30 13:27:14] VERBOSE[27937] logger.c: -- SIP/503-081f7d88 is ringing
[Aug 30 13:27:14] VERBOSE[27937] logger.c:
<--- Transmitting (no NAT) to 192.168.0.16:5060 --->
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.0.16:5060;branch=z9hG4bK7f7f0008;received=192.168.0.16;rport=5060
From: "501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To: <sip:503@192.168.0.13>;tag=as47aa1963
Call-ID: 7f7f0000-1247106c@192.168.0.13
CSeq: 178822075 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:503@192.168.0.13>
Content-Length: 0

<------------>
[Aug 30 13:27:15] DEBUG[27937] chan_sip.c: Setting framing from config on incoming call
[Aug 30 13:27:15] VERBOSE[27937] logger.c: Audio is at 192.168.0.13 port 11954
[Aug 30 13:27:15] VERBOSE[27937] logger.c: Adding codec 0x4 (ulaw) to SDP
[Aug 30 13:27:15] VERBOSE[27937] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
[Aug 30 13:27:15] VERBOSE[27937] logger.c:
<--- Transmitting (no NAT) to 192.168.0.16:5060 --->
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.0.16:5060;branch=z9hG4bK7f7f0008;received=192.168.0.16;rport=5060
From: "501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To: <sip:503@192.168.0.13>;tag=as47aa1963
Call-ID: 7f7f0000-1247106c@192.168.0.13
CSeq: 178822075 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:503@192.168.0.13>
Content-Type: application/sdp
Content-Length: 240

v=0
o=root 27822 27822 IN IP4 192.168.0.13
s=session
c=IN IP4 192.168.0.13
t=0 0
m=audio 11954 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

<------------>
[Aug 30 13:27:15] DEBUG[27937] rtp.c: Ooh, format changed from unknown to ulaw
[Aug 30 13:27:15] DEBUG[27937] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Aug 30 13:27:15] DEBUG[27842] chan_sip.c: Acked pending invite 102
[Aug 30 13:27:15] DEBUG[27842] chan_sip.c: Stopping retransmission on '490743753757935372eeef8b5d4e48b9@192.168.0.13' of Request 102: Match Not Found
[Aug 30 13:27:15] DEBUG[27842] chan_sip.c: Strict routing enforced for session 490743753757935372eeef8b5d4e48b9@192.168.0.13
[Aug 30 13:27:15] VERBOSE[27937] logger.c: -- SIP/503-081f7d88 answered SIP/501-081f0d10
[Aug 30 13:27:15] DEBUG[27937] chan_sip.c: SIP answering channel: SIP/501-081f0d10
[Aug 30 13:27:15] DEBUG[27937] chan_sip.c: Setting framing from config on incoming call
[Aug 30 13:27:15] VERBOSE[27937] logger.c: Audio is at 192.168.0.13 port 11954
[Aug 30 13:27:15] VERBOSE[27937] logger.c: Adding codec 0x4 (ulaw) to SDP
[Aug 30 13:27:15] VERBOSE[27937] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
[Aug 30 13:27:15] VERBOSE[27937] logger.c:
<--- Reliably Transmitting (no NAT) to 192.168.0.16:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.16:5060;branch=z9hG4bK7f7f0008;received=192.168.0.16;rport=5060
From: "501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To: <sip:503@192.168.0.13>;tag=as47aa1963
Call-ID: 7f7f0000-1247106c@192.168.0.13
CSeq: 178822075 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:503@192.168.0.13>
Content-Type: application/sdp
Content-Length: 240

v=0
o=root 27822 27823 IN IP4 192.168.0.13
s=session
c=IN IP4 192.168.0.13
t=0 0
m=audio 11954 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

<------------>
[Aug 30 13:27:15] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:15] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
ACK sip:503@192.168.0.13 SIP/2.0
Via:SIP/2.0/UDP 192.168.0.16:5060;rport;branch=z9hG4bK7f800009
From:"501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To:<sip:503@192.168.0.13>;tag=as47aa1963
Contact:"501" <sip:501@192.168.0.16>
Call-ID:7f7f0000-1247106c@192.168.0.13
CSeq:178822075 ACK
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Max-Forwards:70
Content-Length:0

<------------->
[Aug 30 13:27:15] VERBOSE[27842] logger.c: --- (10 headers 0 lines) ---
[Aug 30 13:27:15] DEBUG[27842] chan_sip.c: Stopping retransmission on '7f7f0000-1247106c@192.168.0.13' of Response 178822075: Match Not Found
[Aug 30 13:27:17] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
INVITE sip:503@192.168.0.13 SIP/2.0
Via:SIP/2.0/UDP 192.168.0.16:5060;rport;branch=z9hG4bK7f82000a
From:"501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To:<sip:503@192.168.0.13>;tag=as47aa1963
Contact:"501" <sip:501@192.168.0.16>
Call-ID:7f7f0000-1247106c@192.168.0.13
Subject:sip phone call
CSeq:178822076 INVITE
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Allow:INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,NOTIFY,PRACK,UPDATE
Allow-Events:talk,hold,conference
Supported:timer,100rel,replaces
Session-Expires: 1800
Min-SE: 90
Max-Forwards:70
Content-Type:application/sdp
Content-Length:244

v=0
o=501 1188463132 1188463131 IN IP4 192.168.0.16
s=SIP Call
c=IN IP4 192.168.0.16
t=0 0
a=sendonly
m=audio 20004 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000

<------------->
[Aug 30 13:27:17] VERBOSE[27842] logger.c: --- (17 headers 11 lines) ---
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Sending to 192.168.0.16 : 5060 (NAT)
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Found RTP audio format 0
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Found RTP audio format 8
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Found RTP audio format 18
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Found RTP audio format 101
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Peer audio RTP is at port 192.168.0.16:20004
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Found description format PCMU for ID 0
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Found description format PCMA for ID 8
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Found description format G729 for ID 18
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Found description format telephone-event for ID 101
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Peer audio RTP is at port 192.168.0.16:20004
[Aug 30 13:27:17] DEBUG[27842] chan_sip.c: Setting framing from config on incoming call
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Audio is at 192.168.0.13 port 11954
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Adding codec 0x4 (ulaw) to SDP
[Aug 30 13:27:17] VERBOSE[27842] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
[Aug 30 13:27:17] VERBOSE[27842] logger.c:
<--- Transmitting (NAT) to 192.168.0.16:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.16:5060;branch=z9hG4bK7f82000a;received=192.168.0.16;rport=5060
From: "501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To: <sip:503@192.168.0.13>;tag=as47aa1963
Call-ID: 7f7f0000-1247106c@192.168.0.13
CSeq: 178822076 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:503@192.168.0.13>
Content-Type: application/sdp
Content-Length: 240

v=0
o=root 27822 27824 IN IP4 192.168.0.13
s=session
c=IN IP4 192.168.0.13
t=0 0
m=audio 11954 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=recvonly

<------------>
[Aug 30 13:27:17] VERBOSE[27937] logger.c: -- Started music on hold, class 'default', on SIP/503-081f7d88
[Aug 30 13:27:17] DEBUG[27937] channel.c: Scheduling timer at 160 sample intervals
[Aug 30 13:27:17] DEBUG[27937] channel.c: Scheduling timer at 0 sample intervals
[Aug 30 13:27:17] WARNING[27937] file.c: File /var/lib/asterisk/mohmp3//fpm-world-mix does not exist in any format
[Aug 30 13:27:17] WARNING[27937] res_musiconhold.c: Unable to open file '/var/lib/asterisk/mohmp3//fpm-world-mix': No such file or directory
[Aug 30 13:27:17] VERBOSE[27937] logger.c: -- Stopped music on hold on SIP/503-081f7d88
[Aug 30 13:27:17] DEBUG[27937] channel.c: Scheduling timer at 0 sample intervals
[Aug 30 13:27:17] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
ACK sip:503@192.168.0.13 SIP/2.0
Via:SIP/2.0/UDP 192.168.0.16:5060;rport;branch=z9hG4bK7f82000b
From:"501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To:<sip:503@192.168.0.13>;tag=as47aa1963
Contact:"501" <sip:501@192.168.0.16>
Call-ID:7f7f0000-1247106c@192.168.0.13
CSeq:178822076 ACK
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Max-Forwards:70
Content-Length:0

<------------->
[Aug 30 13:27:17] VERBOSE[27842] logger.c: --- (10 headers 0 lines) ---
[Aug 30 13:27:17] DEBUG[27842] chan_sip.c: Stopping retransmission on '7f7f0000-1247106c@192.168.0.13' of Response 178822076: Match Found
[Aug 30 13:27:18] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
INVITE sip:5555@192.168.0.13 SIP/2.0
Via:SIP/2.0/UDP 192.168.0.16:5060;rport;branch=z9hG4bK7f83000c
From:<sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
To:"five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
Contact:"501" <sip:501@192.168.0.16>
Call-ID:25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
CSeq:104 INVITE
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Allow:INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,NOTIFY,PRACK,UPDATE
Allow-Events:talk,hold,conference
Supported:timer,100rel,replaces
Max-Forwards:70
Content-Type:application/sdp
Content-Length:244

v=0
o=501 1188463307 1188463306 IN IP4 192.168.0.16
s=SIP Call
c=IN IP4 192.168.0.16
t=0 0
a=sendrecv
m=audio 20002 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000

<------------->
[Aug 30 13:27:18] VERBOSE[27842] logger.c: --- (14 headers 11 lines) ---
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Sending to 192.168.0.16 : 5060 (NAT)
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Found RTP audio format 0
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Found RTP audio format 8
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Found RTP audio format 18
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Found RTP audio format 101
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Peer audio RTP is at port 192.168.0.16:20002
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Found description format PCMU for ID 0
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Found description format PCMA for ID 8
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Found description format G729 for ID 18
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Found description format telephone-event for ID 101
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Capabilities: us - 0x4 (ulaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw)
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Peer audio RTP is at port 192.168.0.16:20002
[Aug 30 13:27:18] DEBUG[27842] chan_sip.c: Setting framing from config on incoming call
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Audio is at 192.168.0.13 port 13644
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Adding codec 0x4 (ulaw) to SDP
[Aug 30 13:27:18] VERBOSE[27842] logger.c: Adding non-codec 0x1 (telephone-event) to SDP
[Aug 30 13:27:18] VERBOSE[27842] logger.c:
<--- Transmitting (NAT) to 192.168.0.16:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.16:5060;branch=z9hG4bK7f83000c;received=192.168.0.16;rport=5060
From: <sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
To: "five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
Call-ID: 25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
CSeq: 104 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:5555@192.168.0.13>
Content-Type: application/sdp
Content-Length: 240

v=0
o=root 27822 27824 IN IP4 192.168.0.13
s=session
c=IN IP4 192.168.0.13
t=0 0
m=audio 13644 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

<------------>
[Aug 30 13:27:18] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
ACK sip:5555@192.168.0.13 SIP/2.0
Via:SIP/2.0/UDP 192.168.0.16:5060;rport;branch=z9hG4bK7f83000d
From:<sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
To:"five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
Contact:"501" <sip:501@192.168.0.16>
Call-ID:25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
CSeq:104 ACK
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Max-Forwards:70
Content-Length:0

<------------->
[Aug 30 13:27:18] VERBOSE[27842] logger.c: --- (10 headers 0 lines) ---
[Aug 30 13:27:18] DEBUG[27842] chan_sip.c: Stopping retransmission on '25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13' of Response 104: Match Found
[Aug 30 13:27:21] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
REFER sip:503@192.168.0.13 SIP/2.0
Via:SIP/2.0/UDP 192.168.0.16:5060;rport;branch=z9hG4bK7f86000e
From:"501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To:<sip:503@192.168.0.13>;tag=as47aa1963
Contact:"501" <sip:501@192.168.0.16>
Call-ID:7f7f0000-1247106c@192.168.0.13
CSeq:178822077 REFER
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Referred-By:"501" <sip:501@192.168.0.13>
Refer-To:<sip:5555@192.168.0.13?Replaces=25a3d2fb5f16c9ab76fb550c6cfd53ee%40192.168.0.13%3bto-tag%3das1e70c9c4%3bfrom-tag%3d46d67f7a-22a-5ddf4f7f>
Accept-Contact:<sip:5555@192.168.0.13>
Supported:timer,100rel,replaces
Max-Forwards:70
Content-Length:0

<------------->
[Aug 30 13:27:21] VERBOSE[27842] logger.c: --- (14 headers 0 lines) ---
[Aug 30 13:27:21] VERBOSE[27842] logger.c: Call 7f7f0000-1247106c@192.168.0.13 got a SIP call transfer from caller: (REFER)!
[Aug 30 13:27:21] VERBOSE[27842] logger.c: SIP transfer to extension 5555@context_501 by 501@192.168.0.13
[Aug 30 13:27:21] VERBOSE[27842] logger.c:
<--- Transmitting (NAT) to 192.168.0.16:5060 --->
SIP/2.0 202 Accepted
Via: SIP/2.0/UDP 192.168.0.16:5060;branch=z9hG4bK7f86000e;received=192.168.0.16;rport=5060
From: "501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To: <sip:503@192.168.0.13>;tag=as47aa1963
Call-ID: 7f7f0000-1247106c@192.168.0.13
CSeq: 178822077 REFER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:503@192.168.0.13>
Content-Length: 0

<------------>
[Aug 30 13:27:21] DEBUG[27842] channel.c: Planning to masquerade channel SIP/503-081f7d88 into the structure of SIP/501-b6d00928
[Aug 30 13:27:21] DEBUG[27842] channel.c: Done planning to masquerade channel SIP/503-081f7d88 into the structure of SIP/501-b6d00928
[Aug 30 13:27:21] DEBUG[27842] chan_sip.c: SIP transfer: Succeeded to masquerade channels.
[Aug 30 13:27:21] DEBUG[27842] chan_sip.c: Strict routing enforced for session 7f7f0000-1247106c@192.168.0.13
[Aug 30 13:27:21] VERBOSE[27842] logger.c: set_destination: Parsing <sip:501@192.168.0.16> for address/port to send to
[Aug 30 13:27:21] VERBOSE[27842] logger.c: set_destination: set destination to 192.168.0.16, port 5060
[Aug 30 13:27:21] VERBOSE[27842] logger.c: Reliably Transmitting (NAT) to 192.168.0.16:5060:
NOTIFY sip:501@192.168.0.16 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.13:5060;branch=z9hG4bK184b955f;rport
From: <sip:503@192.168.0.13>;tag=as47aa1963
To: "501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
Contact: <sip:503@192.168.0.13>
Call-ID: 7f7f0000-1247106c@192.168.0.13
CSeq: 102 NOTIFY
User-Agent: Asterisk PBX
Max-Forwards: 70
Event: refer;id=178822077
Subscription-state: terminated;reason=noresource
Content-Type: message/sipfrag;version=2.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 16

SIP/2.0 200 OK

---
[Aug 30 13:27:21] DEBUG[27842] chan_sip.c: SIP attended transfer: Unlocking channel SIP/501-b6d00928
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] VERBOSE[27937] logger.c: -- Packet2Packet bridging SIP/501-081f0d10 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] DEBUG[27930] chan_sip.c: Hangup call SIP/503-081f7d88<MASQ>, SIP callid 25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13)
[Aug 30 13:27:21] VERBOSE[27930] logger.c: Scheduling destruction of SIP dialog '25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13' in 32000 ms (Method: ACK)
[Aug 30 13:27:21] DEBUG[27930] chan_sip.c: Strict routing enforced for session 25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
[Aug 30 13:27:21] VERBOSE[27930] logger.c: set_destination: Parsing <sip:501@192.168.0.16> for address/port to send to
[Aug 30 13:27:21] VERBOSE[27930] logger.c: set_destination: set destination to 192.168.0.16, port 5060
[Aug 30 13:27:21] VERBOSE[27930] logger.c: Reliably Transmitting (NAT) to 192.168.0.16:5060:
BYE sip:501@192.168.0.16 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.13:5060;branch=z9hG4bK65182121;rport
From: "five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
To: <sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
Call-ID: 25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
CSeq: 103 BYE
User-Agent: Asterisk PBX
Max-Forwards: 70
Content-Length: 0

---
[Aug 30 13:27:21] DEBUG[27930] channel.c: Putting channel SIP/503-081f7d88 in 4/4 formats
[Aug 30 13:27:21] DEBUG[27930] channel.c: Released clone lock on 'SIP/501-b6d00928<ZOMBIE>'
[Aug 30 13:27:21] DEBUG[27937] channel.c: Bridge stops because we're zombie or need a soft hangup: c0=SIP/501-081f0d10, c1=SIP/501-b6d00928<ZOMBIE>, flags: No,No,Yes,Yes
[Aug 30 13:27:21] DEBUG[27930] channel.c: Done Masquerading SIP/503-081f7d88 (6)
[Aug 30 13:27:21] DEBUG[27937] channel.c: Bridge stops bridging channels SIP/501-081f0d10 and SIP/501-b6d00928<ZOMBIE>
[Aug 30 13:27:21] DEBUG[27930] rtp.c: Oooh, something is weird, backing out
[Aug 30 13:27:21] DEBUG[27937] channel.c: Hanging up zombie 'SIP/501-b6d00928<ZOMBIE>'
[Aug 30 13:27:21] VERBOSE[27930] logger.c: -- Packet2Packet bridging SIP/502-081c6668 and SIP/503-081f7d88
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '502'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '502'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 's'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'context_503'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'SIP/501-b6d00928<ZOMBIE>'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'SIP/501-081f0d10'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is ''
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is ''
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '2007-08-30 13:27:09'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '2007-08-30 13:27:10'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '2007-08-30 13:27:21'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '12'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '11'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'ANSWERED'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'DOCUMENTATION'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is ''
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '1188476834.3'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is ''
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'SIP/501-b6d00928<ZOMBIE>'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '"five o one (501)" <01>'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '01'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '503'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'context_501'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'SIP/501-081f0d10'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'SIP/501-081f0d10'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'Dial'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'SIP/503|30|wW'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '2007-08-30 13:27:14'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '2007-08-30 13:27:15'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '2007-08-30 13:27:21'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '7'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '6'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'ANSWERED'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'DOCUMENTATION'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is ''
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '1188476834.2'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is ''
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'SIP/501-081f0d10'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '01'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '01'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 's'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'context_503'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'SIP/503-081f7d88'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'SIP/501-081f0d10'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is ''
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is ''
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '2007-08-30 13:27:14'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '2007-08-30 13:27:15'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '2007-08-30 13:27:21'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '7'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '6'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'ANSWERED'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'DOCUMENTATION'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is ''
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is '1188476834.3'
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is ''
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Function result is 'SIP/503-081f7d88'
[Aug 30 13:27:21] DEBUG[27937] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Aug 30 13:27:21] DEBUG[27937] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Aug 30 13:27:21] DEBUG[27937] pbx.c: Spawn extension (context_501,503,2) exited non-zero on 'SIP/501-081f0d10'
[Aug 30 13:27:21] VERBOSE[27937] logger.c: == Spawn extension (context_501, 503, 2) exited non-zero on 'SIP/501-081f0d10'
[Aug 30 13:27:21] DEBUG[27937] channel.c: Hanging up channel 'SIP/501-081f0d10'
[Aug 30 13:27:21] VERBOSE[27937] logger.c: Scheduling destruction of SIP dialog '7f7f0000-1247106c@192.168.0.13' in 32000 ms (Method: REFER)
[Aug 30 13:27:21] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
SIP/2.0 200 OK
Via:SIP/2.0/UDP 192.168.0.13:5060;rport=5060;received=192.168.0.13;branch=z9hG4bK184b955f
From:<sip:503@192.168.0.13>;tag=as47aa1963
To:"501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
CSeq:102 NOTIFY
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Call-ID:7f7f0000-1247106c@192.168.0.13
Contact:"501" <sip:501@192.168.0.16>
Allow:INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,NOTIFY,PRACK,UPDATE
Supported:timer,100rel,replaces
Content-Length:0

<------------->
[Aug 30 13:27:21] VERBOSE[27842] logger.c: --- (11 headers 0 lines) ---
[Aug 30 13:27:21] DEBUG[27842] chan_sip.c: Stopping retransmission on '7f7f0000-1247106c@192.168.0.13' of Request 102: Match Not Found
[Aug 30 13:27:21] VERBOSE[27842] logger.c: SIP Response message for INCOMING dialog NOTIFY arrived
[Aug 30 13:27:21] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
SIP/2.0 200 OK
Via:SIP/2.0/UDP 192.168.0.13:5060;rport=5060;received=192.168.0.13;branch=z9hG4bK65182121
From:"five o two (502)" <sip:5555@192.168.0.13>;tag=as1e70c9c4
To:<sip:501@192.168.0.16>;tag=46d67f7a-22a-5ddf4f7f
CSeq:103 BYE
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Call-ID:25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13
Contact:"501" <sip:501@192.168.0.16>
Allow:INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,NOTIFY,PRACK,UPDATE
Supported:timer,100rel,replaces
Content-Length:0

<------------->
[Aug 30 13:27:21] VERBOSE[27842] logger.c: --- (11 headers 0 lines) ---
[Aug 30 13:27:21] DEBUG[27842] chan_sip.c: Stopping retransmission on '25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13' of Request 103: Match Not Found
[Aug 30 13:27:21] VERBOSE[27842] logger.c: SIP Response message for INCOMING dialog BYE arrived
[Aug 30 13:27:21] VERBOSE[27842] logger.c: Really destroying SIP dialog '25a3d2fb5f16c9ab76fb550c6cfd53ee@192.168.0.13' Method: ACK
[Aug 30 13:27:21] VERBOSE[27842] logger.c:
<--- SIP read from 192.168.0.16:5060 --->
BYE sip:503@192.168.0.13 SIP/2.0
Via:SIP/2.0/UDP 192.168.0.16:5060;rport;branch=z9hG4bK7f86000f
From:"501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To:<sip:503@192.168.0.13>;tag=as47aa1963
Contact:"501" <sip:501@192.168.0.16>
Call-ID:7f7f0000-1247106c@192.168.0.13
CSeq:178822078 BYE
User-Agent:Mitel-5215-SIP-Phone 07.00.00.08 08000F1610EB
Supported:timer,100rel,replaces
Max-Forwards:70
Content-Length:0

<------------->
[Aug 30 13:27:21] VERBOSE[27842] logger.c: --- (11 headers 0 lines) ---
[Aug 30 13:27:21] VERBOSE[27842] logger.c: Sending to 192.168.0.16 : 5060 (NAT)
[Aug 30 13:27:21] VERBOSE[27842] logger.c: Scheduling destruction of SIP dialog '7f7f0000-1247106c@192.168.0.13' in 32000 ms (Method: BYE)
[Aug 30 13:27:21] VERBOSE[27842] logger.c:
<--- Transmitting (NAT) to 192.168.0.16:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.16:5060;branch=z9hG4bK7f86000f;received=192.168.0.16;rport=5060
From: "501" <sip:501@192.168.0.13>;tag=46d67f7f-297-7033472b
To: <sip:503@192.168.0.13>;tag=as47aa1963
Call-ID: 7f7f0000-1247106c@192.168.0.13
CSeq: 178822078 BYE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:503@192.168.0.13>
Content-Length: 0

<------------>
[Aug 30 13:27:37] DEBUG[27930] rtp.c: Oooh, got a hangup
[Aug 30 13:27:37] DEBUG[27930] channel.c: Returning from native bridge, channels: SIP/502-081c6668, SIP/503-081f7d88
[Aug 30 13:27:37] DEBUG[27930] channel.c: Hanging up channel 'SIP/503-081f7d88'
[Aug 30 13:27:37] DEBUG[27930] chan_sip.c: Hangup call SIP/503-081f7d88, SIP callid 490743753757935372eeef8b5d4e48b9@192.168.0.13)
[Aug 30 13:27:37] DEBUG[27930] chan_sip.c: Strict routing enforced for session 490743753757935372eeef8b5d4e48b9@192.168.0.13
[Aug 30 13:27:37] DEBUG[27930] rtp.c: Channel '<unspecified>' has no RTP, not doing anything
[Aug 30 13:27:37] DEBUG[27930] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Spawn extension (context_502,501,2) exited non-zero on 'SIP/502-081c6668'
[Aug 30 13:27:37] VERBOSE[27930] logger.c: == Spawn extension (context_502, 501, 2) exited non-zero on 'SIP/502-081c6668'
[Aug 30 13:27:37] DEBUG[27930] channel.c: Hanging up channel 'SIP/502-081c6668'
[Aug 30 13:27:37] DEBUG[27930] chan_sip.c: Hangup call SIP/502-081c6668, SIP callid c5ca0000-7cee94b1@192.168.0.13)
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is '"five o two (502)" <502>'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is '502'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is '501'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is 'context_502'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is 'SIP/502-081c6668'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is 'SIP/501-b6d00928'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is 'Dial'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is 'SIP/501|30'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is '2007-08-30 13:27:09'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is '2007-08-30 13:27:10'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is '2007-08-30 13:27:37'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is '28'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is '27'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is 'ANSWERED'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is 'DOCUMENTATION'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is ''
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is '1188476829.0'
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is ''
[Aug 30 13:27:37] DEBUG[27930] pbx.c: Function result is 'SIP/502-081c6668'
[Aug 30 13:27:37] DEBUG[27842] chan_sip.c: Stopping retransmission on '490743753757935372eeef8b5d4e48b9@192.168.0.13' of Request 103: Match Not Found
[Aug 30 13:27:46] VERBOSE[27822] logger.c: Beginning asterisk shutdown....
[Aug 30 13:27:46] VERBOSE[27822] logger.c: Executing last minute cleanups
[Aug 30 13:27:46] VERBOSE[27822] logger.c: == Destroying musiconhold processes
[Aug 30 13:27:46] VERBOSE[27822] logger.c: Asterisk cleanly ending (0).
[Aug 30 13:27:46] DEBUG[27822] asterisk.c: Asterisk ending (0).

Comments: By: Joshua C. Colp (jcolp) 2007-10-08 09:48:22

Fixed in 1.4 as of revision 84990 and trunk as of revision 84991.