exten => 11,1,SIPAddHeader(X-Announce-Server: No User - Start)
exten => 11,2,Playback(custom/no-user)
exten => 11,3,SIPAddHeader(X-Announce-Server: No User - End)
exten => 11,4,Wait(1.5)
exten => 11,5,Hangup()



asterisk log

/var/log/asterisk/full - last 2000 lines 
--------------------------------------------------------------------------------

May 18 09:22:37 VERBOSE[10710] logger.c: Asterisk Event Logger restarted
May 18 09:22:37 VERBOSE[10710] logger.c: Asterisk Queue Logger restarted
May 18 09:22:43 VERBOSE[2387] logger.c: 
<-- SIP read from 192.168.3.197:5060: 
INVITE sip:811@192.168.3.99:5060 SIP/2.0 
Via: SIP/2.0/UDP 192.168.3.197:5060 
From: sipp ;tag=1 
To: sut 
Call-ID: 1.6948.192.168.3.197@sipp.call.id 
Cseq: 1 INVITE 
Contact: sip:sipp@192.168.3.197:5060 
Max-Forwards: 70 
Subject: Performance Test 
Content-Type: application/sdp 
Content-Length: 136 

v=0 
o=user1 53655765 2353687637 IN IP4 127.0.0.1 
s=- 
t=0 0 
c=IN IP4 127.0.0.1 
m=audio 10000 RTP/AVP 0 
a=rtpmap:0 PCMU/8000 

May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 0: INVITE sip:811@192.168.3.99:5060 SIP/2.0 (40)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.3.197:5060 (35)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 2: From: sipp ;tag=1 (46)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 3: To: sut (35)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 4: Call-ID: 1.6948.192.168.3.197@sipp.call.id (42)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 5: Cseq: 1 INVITE (14)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 6: Contact: sip:sipp@192.168.3.197:5060 (36)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 7: Max-Forwards: 70 (16)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 8: Subject: Performance Test (25)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 9: Content-Type: application/sdp (29)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 10: Content-Length: 136 (19)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 11: (0)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Line: v=0 (3)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Line: o=user1 53655765 2353687637 IN IP4 127.0.0.1 (44)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Line: s=- (3)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Line: t=0 0 (5)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Line: c=IN IP4 127.0.0.1 (24)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Line: m=audio 10000 RTP/AVP 0 (23)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
May 18 09:22:43 VERBOSE[2387] logger.c: --- (11 headers 7 lines)May 18 09:22:43 VERBOSE[2387] logger.c: --- (11 headers 7 lines)---
May 18 09:22:43 DEBUG[2387] chan_sip.c: Allocating new SIP dialog for 1.6948.192.168.3.197@sipp.call.id - INVITE (With RTP)
May 18 09:22:43 DEBUG[2387] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
May 18 09:22:43 VERBOSE[2387] logger.c: Using INVITE request as basis request - 1.6948.192.168.3.197@sipp.call.id
May 18 09:22:43 VERBOSE[2387] logger.c: Sending to 192.168.3.197 : 5060 (non-NAT)
May 18 09:22:43 VERBOSE[2387] logger.c: Found no matching peer or user for '192.168.3.197:5060'
May 18 09:22:43 VERBOSE[2387] logger.c: Found RTP audio format 0
May 18 09:22:43 VERBOSE[2387] logger.c: Peer audio RTP is at port 127.0.0.1:10000
May 18 09:22:43 DEBUG[2387] chan_sip.c: Peer audio RTP is at port 127.0.0.1:10000
May 18 09:22:43 VERBOSE[2387] logger.c: Found description format PCMU
May 18 09:22:43 VERBOSE[2387] logger.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
May 18 09:22:43 VERBOSE[2387] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Checking SIP call limits for device 
May 18 09:22:43 DEBUG[2387] chan_sip.c: Updating call counter for incoming call
May 18 09:22:43 VERBOSE[2387] logger.c: Looking for 811 in from-internal (domain 192.168.3.99)
May 18 09:22:43 DEBUG[2387] chan_sip.c: build_route: Contact hop: sip:sipp@192.168.3.197:5060
May 18 09:22:43 VERBOSE[2387] logger.c: list_route: hop: 
May 18 09:22:43 VERBOSE[2387] logger.c: Transmitting (no NAT) to 192.168.3.197:5060:
SIP/2.0 100 Trying 
Via: SIP/2.0/UDP 192.168.3.197:5060;received=192.168.3.197 
From: sipp ;tag=1 
To: sut 
Call-ID: 1.6948.192.168.3.197@sipp.call.id 
CSeq: 1 INVITE 
User-Agent: Asterisk PBX 
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY 
Contact: 
Content-Length: 0 


---
May 18 09:22:43 DEBUG[2380] chan_sip.c: Checking device state for peer 5060
May 18 09:22:43 DEBUG[2380] devicestate.c: Changing state for SIP/5060 - state 4 (Invalid)
May 18 09:22:43 DEBUG[10913] pbx.c: Launching 'Answer'
May 18 09:22:43 VERBOSE[10913] logger.c: -- Executing Answer("SIP/5060-0981d5c0", "") in new stack
May 18 09:22:43 DEBUG[2380] chan_sip.c: Checking device state for peer 5060
May 18 09:22:43 DEBUG[2380] devicestate.c: Changing state for SIP/5060 - state 4 (Invalid)
May 18 09:22:43 DEBUG[10913] chan_sip.c: sip_answer(SIP/5060-0981d5c0)
May 18 09:22:43 VERBOSE[10913] logger.c: We're at 192.168.3.99 port 13538
May 18 09:22:43 VERBOSE[10913] logger.c: Adding codec 0x4 (ulaw) to SDP
May 18 09:22:43 VERBOSE[10913] logger.c: Reliably Transmitting (no NAT) to 192.168.3.197:5060:
SIP/2.0 200 OK 
Via: SIP/2.0/UDP 192.168.3.197:5060;received=192.168.3.197 
From: sipp ;tag=1 
To: sut ;tag=as4a266f56 
Call-ID: 1.6948.192.168.3.197@sipp.call.id 
CSeq: 1 INVITE 
User-Agent: Asterisk PBX 
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY 
Contact: 
Content-Type: application/sdp 
Content-Length: 158 

v=0 
o=root 2354 2354 IN IP4 192.168.3.99 
s=session 
c=IN IP4 192.168.3.99 
t=0 0 
m=audio 13538 RTP/AVP 0 
a=rtpmap:0 PCMU/8000 
a=silenceSupp:off - - - - 

---
May 18 09:22:43 DEBUG[10913] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #856
May 18 09:22:43 DEBUG[10913] pbx.c: Launching 'Wait'
May 18 09:22:43 VERBOSE[10913] logger.c: -- Executing Wait("SIP/5060-0981d5c0", "1.5") in new stack
May 18 09:22:43 VERBOSE[2387] logger.c: 
<-- SIP read from 192.168.3.197:5060: 
ACK sip:811@192.168.3.99:5060 SIP/2.0 
Via: SIP/2.0/UDP 192.168.3.197:5060 
From: sipp ;tag=1 
To: sut ;tag=as4a266f56 
Call-ID: 1.6948.192.168.3.197@sipp.call.id 
Cseq: 1 ACK 
Contact: sip:sipp@192.168.3.197:5060 
Max-Forwards: 70 
Subject: Performance Test 
Content-Length: 0 


May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 0: ACK sip:811@192.168.3.99:5060 SIP/2.0 (37)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.3.197:5060 (35)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 2: From: sipp ;tag=1 (46)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 3: To: sut ;tag=as4a266f56 (50)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 4: Call-ID: 1.6948.192.168.3.197@sipp.call.id (42)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 5: Cseq: 1 ACK (11)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 6: Contact: sip:sipp@192.168.3.197:5060 (36)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 7: Max-Forwards: 70 (16)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 8: Subject: Performance Test (25)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 9: Content-Length: 0 (17)
May 18 09:22:43 DEBUG[2387] chan_sip.c: Header 10: (0)
May 18 09:22:43 VERBOSE[2387] logger.c: --- (10 headers 0 lines)May 18 09:22:43 VERBOSE[2387] logger.c: --- (10 headers 0 lines)---
May 18 09:22:43 DEBUG[2387] chan_sip.c: = Found Their Call ID: 1.6948.192.168.3.197@sipp.call.id Their Tag 1 Our tag: as4a266f56
May 18 09:22:43 DEBUG[2387] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
May 18 09:22:43 DEBUG[2387] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #856
May 18 09:22:43 DEBUG[2387] chan_sip.c: Stopping retransmission on '1.6948.192.168.3.197@sipp.call.id' of Response 1: Match Found
May 18 09:22:43 DEBUG[10914] app_queue.c: Device 'SIP/5060' changed to state '4' (Invalid)
May 18 09:22:43 DEBUG[10915] app_queue.c: Device 'SIP/5060' changed to state '4' (Invalid)
May 18 09:22:45 DEBUG[10913] pbx.c: Launching 'SetLanguage'
May 18 09:22:45 VERBOSE[10913] logger.c: -- Executing SetLanguage("SIP/5060-0981d5c0", "he") in new stack
May 18 09:22:45 DEBUG[10913] pbx.c: Launching 'Dial'
May 18 09:22:45 VERBOSE[10913] logger.c: -- Executing Dial("SIP/5060-0981d5c0", "Local/11@bhca-test") in new stack
May 18 09:22:45 DEBUG[2380] devicestate.c: Changing state for Local/11@bhca-test - state 2 (In use)
May 18 09:22:45 DEBUG[10913] channel.c: Not copying variable STACK-from-internal-811-4.
May 18 09:22:45 DEBUG[10913] channel.c: Not copying variable STACK-from-internal-811-3.
May 18 09:22:45 DEBUG[10913] channel.c: Not copying variable STACK-from-internal-811-2.
May 18 09:22:45 DEBUG[10913] channel.c: Not copying variable STACK-from-internal-811-1.
May 18 09:22:45 DEBUG[10913] channel.c: Not copying variable SIPCALLID.
May 18 09:22:45 DEBUG[10913] channel.c: Not copying variable SIPDOMAIN.
May 18 09:22:45 DEBUG[10913] channel.c: Not copying variable SIPURI.
May 18 09:22:45 VERBOSE[10913] logger.c: -- Called 11@bhca-test
May 18 09:22:45 DEBUG[10913] channel.c: Set channel Local/11@bhca-test-a132,1 to read format ulaw
May 18 09:22:45 DEBUG[10913] channel.c: Set channel SIP/5060-0981d5c0 to write format ulaw
May 18 09:22:45 DEBUG[10913] channel.c: Set channel SIP/5060-0981d5c0 to read format ulaw
May 18 09:22:45 DEBUG[10913] channel.c: Set channel Local/11@bhca-test-a132,1 to write format ulaw
May 18 09:22:45 DEBUG[10916] app_queue.c: Device 'Local/11@bhca-test' changed to state '2' (In use)
May 18 09:22:45 DEBUG[10917] pbx.c: Launching 'SIPAddHeader'
May 18 09:22:45 VERBOSE[10917] logger.c: -- Executing SIPAddHeader("Local/11@bhca-test-a132,2", "X-Announce-Server: No User - Start") in new stack
May 18 09:22:45 DEBUG[10917] chan_sip.c: SIP Header added "X-Announce-Server: No User - Start" as _SIPADDHEADER01
May 18 09:22:45 DEBUG[10917] pbx.c: Launching 'Playback'
May 18 09:22:45 VERBOSE[10917] logger.c: -- Executing Playback("Local/11@bhca-test-a132,2", "custom/no-user") in new stack
May 18 09:22:45 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-a132,2'
May 18 09:22:45 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-a132,2'
May 18 09:22:45 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-a132,2'
May 18 09:22:45 VERBOSE[10913] logger.c: -- Local/11@bhca-test-a132,1 answered SIP/5060-0981d5c0
May 18 09:22:45 DEBUG[10913] channel.c: Set channel SIP/5060-0981d5c0 to read format ulaw
May 18 09:22:45 DEBUG[10913] channel.c: Set channel Local/11@bhca-test-a132,1 to write format ulaw
May 18 09:22:45 DEBUG[10913] channel.c: Set channel Local/11@bhca-test-a132,1 to read format ulaw
May 18 09:22:45 DEBUG[10913] channel.c: Set channel SIP/5060-0981d5c0 to write format ulaw
May 18 09:22:45 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-a132,2'
May 18 09:22:45 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-a132,2'
May 18 09:22:45 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-a132,2'
May 18 09:22:45 DEBUG[10917] channel.c: Set channel Local/11@bhca-test-a132,2 to write format gsm
May 18 09:22:45 DEBUG[10913] rtp.c: Ooh, format changed from unknown to ulaw
May 18 09:22:45 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-a132,2'
May 18 09:22:45 DEBUG[10917] channel.c: Scheduling timer at 160 sample intervals
May 18 09:22:45 VERBOSE[10917] logger.c: -- Playing 'custom/no-user' (language 'he')
May 18 09:22:45 DEBUG[2380] devicestate.c: Changing state for Local/11@bhca-test - state 2 (In use)
May 18 09:22:45 DEBUG[2380] devicestate.c: Changing state for Local/11@bhca-test - state 2 (In use)
May 18 09:22:45 DEBUG[10918] app_queue.c: Device 'Local/11@bhca-test' changed to state '2' (In use)
May 18 09:22:45 DEBUG[10919] app_queue.c: Device 'Local/11@bhca-test' changed to state '2' (In use)
May 18 09:22:46 DEBUG[10917] channel.c: Scheduling timer at 0 sample intervals
May 18 09:22:46 DEBUG[10917] channel.c: Scheduling timer at 0 sample intervals
May 18 09:22:46 DEBUG[10917] channel.c: Set channel Local/11@bhca-test-a132,2 to write format ulaw
May 18 09:22:46 DEBUG[10917] pbx.c: Launching 'SIPAddHeader'
May 18 09:22:46 VERBOSE[10917] logger.c: -- Executing SIPAddHeader("Local/11@bhca-test-a132,2", "X-Announce-Server: No User - End") in new stack
May 18 09:22:46 DEBUG[10917] chan_sip.c: SIP Header added "X-Announce-Server: No User - End" as _SIPADDHEADER02
May 18 09:22:46 DEBUG[10917] pbx.c: Launching 'Wait'
May 18 09:22:46 VERBOSE[10917] logger.c: -- Executing Wait("Local/11@bhca-test-a132,2", "1.5") in new stack
May 18 09:22:47 DEBUG[10917] pbx.c: Launching 'Hangup'
May 18 09:22:47 VERBOSE[10917] logger.c: -- Executing Hangup("Local/11@bhca-test-a132,2", "") in new stack
May 18 09:22:47 DEBUG[10917] pbx.c: Spawn extension (bhca-test,11,5) exited non-zero on 'Local/11@bhca-test-a132,2'
May 18 09:22:47 DEBUG[10917] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 18 09:22:47 DEBUG[10917] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2006-05-18 09:22:45','\"sipp\" ','sipp','11','bhca-test', 'Local/11@bhca-test-a132,2','','Hangup','',2,2,'ANSWERED',3,'','1147933365.301')
May 18 09:22:47 DEBUG[10917] channel.c: Hanging up channel 'Local/11@bhca-test-a132,2'
May 18 09:22:47 DEBUG[2380] devicestate.c: Changing state for Local/11@bhca-test - state 2 (In use)
May 18 09:22:47 DEBUG[10913] channel.c: Didn't get a frame from channel: Local/11@bhca-test-a132,1
May 18 09:22:47 DEBUG[10913] channel.c: Bridge stops bridging channels SIP/5060-0981d5c0 and Local/11@bhca-test-a132,1
May 18 09:22:47 DEBUG[10913] channel.c: Hanging up channel 'Local/11@bhca-test-a132,1'
May 18 09:22:47 DEBUG[10913] app_dial.c: Exiting with DIALSTATUS=ANSWER.
May 18 09:22:47 DEBUG[10913] pbx.c: Spawn extension (from-internal,811,4) exited non-zero on 'SIP/5060-0981d5c0'
May 18 09:22:47 DEBUG[10913] pbx.c: Launching 'Macro'
May 18 09:22:47 DEBUG[2380] devicestate.c: Changing state for Local/11@bhca-test - state 0 (Unknown)
May 18 09:22:47 VERBOSE[10913] logger.c: -- Executing Macro("SIP/5060-0981d5c0", "hangupcall") in new stack
May 18 09:22:47 DEBUG[10913] pbx.c: Launching 'ResetCDR'
May 18 09:22:47 VERBOSE[10913] logger.c: -- Executing ResetCDR("SIP/5060-0981d5c0", "w") in new stack
May 18 09:22:47 DEBUG[10913] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 18 09:22:47 DEBUG[10913] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2006-05-18 09:22:43','\"sipp\" ','sipp','811','from-internal', 'SIP/5060-0981d5c0','Local/11@bhca-test-a132,1','ResetCDR','w',4,4,'ANSWERED',3,'','1147933363.299')
May 18 09:22:47 DEBUG[10913] pbx.c: Launching 'NoCDR'
May 18 09:22:47 VERBOSE[10913] logger.c: -- Executing NoCDR("SIP/5060-0981d5c0", "") in new stack
May 18 09:22:47 WARNING[10913] cdr.c: CDR on channel 'SIP/5060-0981d5c0' not posted
May 18 09:22:47 WARNING[10913] cdr.c: CDR on channel 'SIP/5060-0981d5c0' lacks end
May 18 09:22:47 DEBUG[10913] pbx.c: Launching 'Wait'
May 18 09:22:47 VERBOSE[10913] logger.c: -- Executing Wait("SIP/5060-0981d5c0", "5") in new stack
May 18 09:22:47 DEBUG[10920] app_queue.c: Device 'Local/11@bhca-test' changed to state '2' (In use)
May 18 09:22:47 DEBUG[10921] app_queue.c: Device 'Local/11@bhca-test' changed to state '0' (Unknown)
May 18 09:22:49 VERBOSE[2387] logger.c: 
<-- SIP read from 192.168.3.197:5060: 
BYE sip:811@192.168.3.99:5060 SIP/2.0 
Via: SIP/2.0/UDP 192.168.3.197:5060 
From: sipp ;tag=1 
To: sut ;tag=as4a266f56 
Call-ID: 1.6948.192.168.3.197@sipp.call.id 
Cseq: 2 BYE 
Contact: sip:sipp@192.168.3.197:5060 
Max-Forwards: 70 
Subject: Performance Test 
Content-Length: 0 


May 18 09:22:49 DEBUG[2387] chan_sip.c: Header 0: BYE sip:811@192.168.3.99:5060 SIP/2.0 (37)
May 18 09:22:49 DEBUG[2387] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.3.197:5060 (35)
May 18 09:22:49 DEBUG[2387] chan_sip.c: Header 2: From: sipp ;tag=1 (46)
May 18 09:22:49 DEBUG[2387] chan_sip.c: Header 3: To: sut ;tag=as4a266f56 (50)
May 18 09:22:49 DEBUG[2387] chan_sip.c: Header 4: Call-ID: 1.6948.192.168.3.197@sipp.call.id (42)
May 18 09:22:49 DEBUG[2387] chan_sip.c: Header 5: Cseq: 2 BYE (11)
May 18 09:22:49 DEBUG[2387] chan_sip.c: Header 6: Contact: sip:sipp@192.168.3.197:5060 (36)
May 18 09:22:49 DEBUG[2387] chan_sip.c: Header 7: Max-Forwards: 70 (16)
May 18 09:22:49 DEBUG[2387] chan_sip.c: Header 8: Subject: Performance Test (25)
May 18 09:22:49 DEBUG[2387] chan_sip.c: Header 9: Content-Length: 0 (17)
May 18 09:22:49 DEBUG[2387] chan_sip.c: Header 10: (0)
May 18 09:22:49 VERBOSE[2387] logger.c: --- (10 headers 0 lines)May 18 09:22:49 VERBOSE[2387] logger.c: --- (10 headers 0 lines)---
May 18 09:22:49 DEBUG[2387] chan_sip.c: = Found Their Call ID: 1.6948.192.168.3.197@sipp.call.id Their Tag 1 Our tag: as4a266f56
May 18 09:22:49 DEBUG[2387] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
May 18 09:22:49 VERBOSE[2387] logger.c: Sending to 192.168.3.197 : 5060 (non-NAT)
May 18 09:22:49 VERBOSE[2387] logger.c: Transmitting (no NAT) to 192.168.3.197:5060:
SIP/2.0 200 OK 
Via: SIP/2.0/UDP 192.168.3.197:5060;received=192.168.3.197 
From: sipp ;tag=1 
To: sut ;tag=as4a266f56 
Call-ID: 1.6948.192.168.3.197@sipp.call.id 
CSeq: 2 BYE 
User-Agent: Asterisk PBX 
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY 
Contact: 
Content-Length: 0 
X-Asterisk-HangupCause: Normal Clearing 


---
May 18 09:22:49 DEBUG[10913] app_macro.c: Spawn extension (macro-hangupcall,s,3) exited non-zero on 'SIP/5060-0981d5c0' in macro 'hangupcall'
May 18 09:22:49 DEBUG[10913] pbx.c: Spawn extension (macro-hangupcall,s,3) exited non-zero on 'SIP/5060-0981d5c0'
May 18 09:22:49 DEBUG[10913] channel.c: Hanging up channel 'SIP/5060-0981d5c0'
May 18 09:22:49 DEBUG[10913] chan_sip.c: Hangup call SIP/5060-0981d5c0, SIP callid 1.6948.192.168.3.197@sipp.call.id)
May 18 09:22:49 DEBUG[10913] chan_sip.c: update_call_counter() - decrement call limit counter
May 18 09:22:49 DEBUG[10913] chan_sip.c: Updating call counter for incoming call
May 18 09:22:49 DEBUG[2380] chan_sip.c: Checking device state for peer 5060
May 18 09:22:49 DEBUG[2380] devicestate.c: Changing state for SIP/5060 - state 4 (Invalid)
May 18 09:22:49 DEBUG[10922] app_queue.c: Device 'SIP/5060' changed to state '4' (Invalid)
May 18 09:22:50 VERBOSE[2387] logger.c: Destroying call '1.6948.192.168.3.197@sipp.call.id'
May 18 09:22:50 VERBOSE[2387] logger.c: Destroying call '1.6948.192.168.3.197@sipp.call.id'