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

May 18 09:57:31 VERBOSE[10710] logger.c: Asterisk Event Logger restarted
May 18 09:57:31 VERBOSE[10710] logger.c: Asterisk Queue Logger restarted
May 18 09:57:35 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.6956.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 
X-Salamat: 123 

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:57:35 DEBUG[2387] chan_sip.c: Header 0: INVITE sip:811@192.168.3.99:5060 SIP/2.0 (40)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.3.197:5060 (35)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 2: From: sipp ;tag=1 (46)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 3: To: sut (35)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 4: Call-ID: 1.6956.192.168.3.197@sipp.call.id (42)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 5: Cseq: 1 INVITE (14)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 6: Contact: sip:sipp@192.168.3.197:5060 (36)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 7: Max-Forwards: 70 (16)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 8: Subject: Performance Test (25)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 9: Content-Type: application/sdp (29)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 10: Content-Length: 136 (19)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 11: X-Salamat: 123 (17)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 12: (0)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Line: v=0 (3)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Line: o=user1 53655765 2353687637 IN IP4 127.0.0.1 (44)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Line: s=- (3)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Line: t=0 0 (5)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Line: c=IN IP4 127.0.0.1 (24)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Line: m=audio 10000 RTP/AVP 0 (23)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
May 18 09:57:35 VERBOSE[2387] logger.c: --- (12 headers 7 lines)May 18 09:57:35 VERBOSE[2387] logger.c: --- (12 headers 7 lines)---
May 18 09:57:35 DEBUG[2387] chan_sip.c: Allocating new SIP dialog for 1.6956.192.168.3.197@sipp.call.id - INVITE (With RTP)
May 18 09:57:35 DEBUG[2387] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
May 18 09:57:35 VERBOSE[2387] logger.c: Using INVITE request as basis request - 1.6956.192.168.3.197@sipp.call.id
May 18 09:57:35 VERBOSE[2387] logger.c: Sending to 192.168.3.197 : 5060 (non-NAT)
May 18 09:57:35 VERBOSE[2387] logger.c: Found no matching peer or user for '192.168.3.197:5060'
May 18 09:57:35 VERBOSE[2387] logger.c: Found RTP audio format 0
May 18 09:57:35 VERBOSE[2387] logger.c: Peer audio RTP is at port 127.0.0.1:10000
May 18 09:57:35 DEBUG[2387] chan_sip.c: Peer audio RTP is at port 127.0.0.1:10000
May 18 09:57:35 VERBOSE[2387] logger.c: Found description format PCMU
May 18 09:57:35 VERBOSE[2387] logger.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw)
May 18 09:57:35 VERBOSE[2387] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Checking SIP call limits for device 
May 18 09:57:35 DEBUG[2387] chan_sip.c: Updating call counter for incoming call
May 18 09:57:35 VERBOSE[2387] logger.c: Looking for 811 in from-internal (domain 192.168.3.99)
May 18 09:57:35 DEBUG[2387] chan_sip.c: build_route: Contact hop: sip:sipp@192.168.3.197:5060
May 18 09:57:35 VERBOSE[2387] logger.c: list_route: hop: 
May 18 09:57:35 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.6956.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:57:35 DEBUG[2380] chan_sip.c: Checking device state for peer 5060
May 18 09:57:35 DEBUG[2380] devicestate.c: Changing state for SIP/5060 - state 4 (Invalid)
May 18 09:57:35 DEBUG[11247] pbx.c: Launching 'Answer'
May 18 09:57:35 VERBOSE[11247] logger.c: -- Executing Answer("SIP/5060-0981d5c0", "") in new stack
May 18 09:57:35 DEBUG[2380] chan_sip.c: Checking device state for peer 5060
May 18 09:57:35 DEBUG[2380] devicestate.c: Changing state for SIP/5060 - state 4 (Invalid)
May 18 09:57:35 DEBUG[11247] chan_sip.c: sip_answer(SIP/5060-0981d5c0)
May 18 09:57:35 VERBOSE[11247] logger.c: We're at 192.168.3.99 port 14364
May 18 09:57:35 VERBOSE[11247] logger.c: Adding codec 0x4 (ulaw) to SDP
May 18 09:57:35 VERBOSE[11247] 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=as38d88c6e 
Call-ID: 1.6956.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 14364 RTP/AVP 0 
a=rtpmap:0 PCMU/8000 
a=silenceSupp:off - - - - 

---
May 18 09:57:35 DEBUG[11247] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #941
May 18 09:57:35 DEBUG[11247] pbx.c: Launching 'Wait'
May 18 09:57:35 VERBOSE[11247] logger.c: -- Executing Wait("SIP/5060-0981d5c0", "1.5") in new stack
May 18 09:57:35 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=as38d88c6e 
Call-ID: 1.6956.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:57:35 DEBUG[2387] chan_sip.c: Header 0: ACK sip:811@192.168.3.99:5060 SIP/2.0 (37)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.3.197:5060 (35)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 2: From: sipp ;tag=1 (46)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 3: To: sut ;tag=as38d88c6e (50)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 4: Call-ID: 1.6956.192.168.3.197@sipp.call.id (42)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 5: Cseq: 1 ACK (11)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 6: Contact: sip:sipp@192.168.3.197:5060 (36)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 7: Max-Forwards: 70 (16)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 8: Subject: Performance Test (25)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 9: Content-Length: 0 (17)
May 18 09:57:35 DEBUG[2387] chan_sip.c: Header 10: (0)
May 18 09:57:35 VERBOSE[2387] logger.c: --- (10 headers 0 lines)May 18 09:57:35 VERBOSE[2387] logger.c: --- (10 headers 0 lines)---
May 18 09:57:35 DEBUG[2387] chan_sip.c: = Found Their Call ID: 1.6956.192.168.3.197@sipp.call.id Their Tag 1 Our tag: as38d88c6e
May 18 09:57:35 DEBUG[2387] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
May 18 09:57:35 DEBUG[2387] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #941
May 18 09:57:35 DEBUG[2387] chan_sip.c: Stopping retransmission on '1.6956.192.168.3.197@sipp.call.id' of Response 1: Match Found
May 18 09:57:35 DEBUG[11248] app_queue.c: Device 'SIP/5060' changed to state '4' (Invalid)
May 18 09:57:35 DEBUG[11249] app_queue.c: Device 'SIP/5060' changed to state '4' (Invalid)
May 18 09:57:36 DEBUG[11247] pbx.c: Launching 'SetLanguage'
May 18 09:57:36 VERBOSE[11247] logger.c: -- Executing SetLanguage("SIP/5060-0981d5c0", "he") in new stack
May 18 09:57:36 DEBUG[11247] pbx.c: Launching 'Dial'
May 18 09:57:36 VERBOSE[11247] logger.c: -- Executing Dial("SIP/5060-0981d5c0", "Local/11@bhca-test") in new stack
May 18 09:57:36 DEBUG[11247] channel.c: Not copying variable STACK-from-internal-811-4.
May 18 09:57:36 DEBUG[11247] channel.c: Not copying variable STACK-from-internal-811-3.
May 18 09:57:36 DEBUG[11247] channel.c: Not copying variable STACK-from-internal-811-2.
May 18 09:57:36 DEBUG[11247] channel.c: Not copying variable STACK-from-internal-811-1.
May 18 09:57:36 DEBUG[11247] channel.c: Not copying variable SIPCALLID.
May 18 09:57:36 DEBUG[11247] channel.c: Not copying variable SIPDOMAIN.
May 18 09:57:36 DEBUG[11247] channel.c: Not copying variable SIPURI.
May 18 09:57:36 DEBUG[2380] devicestate.c: Changing state for Local/11@bhca-test - state 2 (In use)
May 18 09:57:36 VERBOSE[11247] logger.c: -- Called 11@bhca-test
May 18 09:57:36 DEBUG[11247] channel.c: Set channel Local/11@bhca-test-ed0e,1 to read format ulaw
May 18 09:57:36 DEBUG[11247] channel.c: Set channel SIP/5060-0981d5c0 to write format ulaw
May 18 09:57:36 DEBUG[11247] channel.c: Set channel SIP/5060-0981d5c0 to read format ulaw
May 18 09:57:36 DEBUG[11247] channel.c: Set channel Local/11@bhca-test-ed0e,1 to write format ulaw
May 18 09:57:36 DEBUG[11251] app_queue.c: Device 'Local/11@bhca-test' changed to state '2' (In use)
May 18 09:57:36 DEBUG[11250] pbx.c: Launching 'Playback'
May 18 09:57:36 VERBOSE[11250] logger.c: -- Executing Playback("Local/11@bhca-test-ed0e,2", "custom/no-user") in new stack
May 18 09:57:36 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-ed0e,2'
May 18 09:57:37 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-ed0e,2'
May 18 09:57:37 VERBOSE[11247] logger.c: -- Local/11@bhca-test-ed0e,1 answered SIP/5060-0981d5c0
May 18 09:57:37 DEBUG[11247] channel.c: Set channel SIP/5060-0981d5c0 to read format ulaw
May 18 09:57:37 DEBUG[11247] channel.c: Set channel Local/11@bhca-test-ed0e,1 to write format ulaw
May 18 09:57:37 DEBUG[11247] channel.c: Set channel Local/11@bhca-test-ed0e,1 to read format ulaw
May 18 09:57:37 DEBUG[11247] channel.c: Set channel SIP/5060-0981d5c0 to write format ulaw
May 18 09:57:37 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-ed0e,2'
May 18 09:57:37 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-ed0e,2'
May 18 09:57:37 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-ed0e,2'
May 18 09:57:37 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-ed0e,2'
May 18 09:57:37 DEBUG[11250] channel.c: Set channel Local/11@bhca-test-ed0e,2 to write format gsm
May 18 09:57:37 DEBUG[2380] channel.c: Avoiding initial deadlock for 'Local/11@bhca-test-ed0e,2'
May 18 09:57:37 DEBUG[11247] rtp.c: Ooh, format changed from unknown to ulaw
May 18 09:57:37 DEBUG[11250] channel.c: Scheduling timer at 160 sample intervals
May 18 09:57:37 VERBOSE[11250] logger.c: -- Playing 'custom/no-user' (language 'he')
May 18 09:57:37 DEBUG[2380] devicestate.c: Changing state for Local/11@bhca-test - state 2 (In use)
May 18 09:57:37 DEBUG[2380] devicestate.c: Changing state for Local/11@bhca-test - state 2 (In use)
May 18 09:57:37 DEBUG[11252] app_queue.c: Device 'Local/11@bhca-test' changed to state '2' (In use)
May 18 09:57:37 DEBUG[11253] app_queue.c: Device 'Local/11@bhca-test' changed to state '2' (In use)
May 18 09:57:38 DEBUG[11250] channel.c: Scheduling timer at 0 sample intervals
May 18 09:57:38 DEBUG[11250] channel.c: Scheduling timer at 0 sample intervals
May 18 09:57:38 DEBUG[11250] channel.c: Set channel Local/11@bhca-test-ed0e,2 to write format ulaw
May 18 09:57:38 WARNING[11250] chan_sip.c: This function can only be used on SIP channels.
May 18 09:57:38 DEBUG[11250] pbx.c: Function result is '(null)'
May 18 09:57:38 DEBUG[11250] pbx.c: Launching 'Set'
May 18 09:57:38 VERBOSE[11250] logger.c: -- Executing Set("Local/11@bhca-test-ed0e,2", "foo=") in new stack
May 18 09:57:38 DEBUG[11250] pbx.c: Launching 'NoOp'
May 18 09:57:38 VERBOSE[11250] logger.c: -- Executing NoOp("Local/11@bhca-test-ed0e,2", "") in new stack
May 18 09:57:38 DEBUG[11250] pbx.c: Launching 'Wait'
May 18 09:57:38 VERBOSE[11250] logger.c: -- Executing Wait("Local/11@bhca-test-ed0e,2", "1.5") in new stack
May 18 09:57:39 DEBUG[11250] pbx.c: Launching 'Hangup'
May 18 09:57:39 VERBOSE[11250] logger.c: -- Executing Hangup("Local/11@bhca-test-ed0e,2", "") in new stack
May 18 09:57:39 DEBUG[11250] pbx.c: Spawn extension (bhca-test,11,5) exited non-zero on 'Local/11@bhca-test-ed0e,2'
May 18 09:57:39 DEBUG[11250] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 18 09:57:39 DEBUG[11250] 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:57:36','\"sipp\" ','sipp','11','bhca-test', 'Local/11@bhca-test-ed0e,2','','Hangup','',3,2,'ANSWERED',3,'','1147935456.313')
May 18 09:57:39 DEBUG[11250] channel.c: Hanging up channel 'Local/11@bhca-test-ed0e,2'
May 18 09:57:39 DEBUG[2380] devicestate.c: Changing state for Local/11@bhca-test - state 2 (In use)
May 18 09:57:39 DEBUG[11247] channel.c: Didn't get a frame from channel: Local/11@bhca-test-ed0e,1
May 18 09:57:39 DEBUG[11247] channel.c: Bridge stops bridging channels SIP/5060-0981d5c0 and Local/11@bhca-test-ed0e,1
May 18 09:57:39 DEBUG[11247] channel.c: Hanging up channel 'Local/11@bhca-test-ed0e,1'
May 18 09:57:39 DEBUG[11247] app_dial.c: Exiting with DIALSTATUS=ANSWER.
May 18 09:57:39 DEBUG[11247] pbx.c: Spawn extension (from-internal,811,4) exited non-zero on 'SIP/5060-0981d5c0'
May 18 09:57:39 DEBUG[11247] pbx.c: Launching 'Macro'
May 18 09:57:39 VERBOSE[11247] logger.c: -- Executing Macro("SIP/5060-0981d5c0", "hangupcall") in new stack
May 18 09:57:39 DEBUG[11247] pbx.c: Launching 'ResetCDR'
May 18 09:57:39 VERBOSE[11247] logger.c: -- Executing ResetCDR("SIP/5060-0981d5c0", "w") in new stack
May 18 09:57:39 DEBUG[2380] devicestate.c: Changing state for Local/11@bhca-test - state 0 (Unknown)
May 18 09:57:39 DEBUG[11247] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
May 18 09:57:39 DEBUG[11247] 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:57:35','\"sipp\" ','sipp','811','from-internal', 'SIP/5060-0981d5c0','Local/11@bhca-test-ed0e,1','ResetCDR','w',4,4,'ANSWERED',3,'','1147935455.311')
May 18 09:57:39 DEBUG[11247] pbx.c: Launching 'NoCDR'
May 18 09:57:39 VERBOSE[11247] logger.c: -- Executing NoCDR("SIP/5060-0981d5c0", "") in new stack
May 18 09:57:39 WARNING[11247] cdr.c: CDR on channel 'SIP/5060-0981d5c0' not posted
May 18 09:57:39 WARNING[11247] cdr.c: CDR on channel 'SIP/5060-0981d5c0' lacks end
May 18 09:57:39 DEBUG[11247] pbx.c: Launching 'Wait'
May 18 09:57:39 VERBOSE[11247] logger.c: -- Executing Wait("SIP/5060-0981d5c0", "5") in new stack
May 18 09:57:39 DEBUG[11254] app_queue.c: Device 'Local/11@bhca-test' changed to state '2' (In use)
May 18 09:57:39 DEBUG[11255] app_queue.c: Device 'Local/11@bhca-test' changed to state '0' (Unknown)
May 18 09:57:44 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=as38d88c6e 
Call-ID: 1.6956.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:57:44 DEBUG[2387] chan_sip.c: Header 0: BYE sip:811@192.168.3.99:5060 SIP/2.0 (37)
May 18 09:57:44 DEBUG[2387] chan_sip.c: Header 1: Via: SIP/2.0/UDP 192.168.3.197:5060 (35)
May 18 09:57:44 DEBUG[2387] chan_sip.c: Header 2: From: sipp ;tag=1 (46)
May 18 09:57:44 DEBUG[2387] chan_sip.c: Header 3: To: sut ;tag=as38d88c6e (50)
May 18 09:57:44 DEBUG[2387] chan_sip.c: Header 4: Call-ID: 1.6956.192.168.3.197@sipp.call.id (42)
May 18 09:57:44 DEBUG[2387] chan_sip.c: Header 5: Cseq: 2 BYE (11)
May 18 09:57:44 DEBUG[2387] chan_sip.c: Header 6: Contact: sip:sipp@192.168.3.197:5060 (36)
May 18 09:57:44 DEBUG[2387] chan_sip.c: Header 7: Max-Forwards: 70 (16)
May 18 09:57:44 DEBUG[2387] chan_sip.c: Header 8: Subject: Performance Test (25)
May 18 09:57:44 DEBUG[2387] chan_sip.c: Header 9: Content-Length: 0 (17)
May 18 09:57:44 DEBUG[2387] chan_sip.c: Header 10: (0)
May 18 09:57:44 VERBOSE[2387] logger.c: --- (10 headers 0 lines)May 18 09:57:44 VERBOSE[2387] logger.c: --- (10 headers 0 lines)---
May 18 09:57:44 DEBUG[2387] chan_sip.c: = Found Their Call ID: 1.6956.192.168.3.197@sipp.call.id Their Tag 1 Our tag: as38d88c6e
May 18 09:57:44 DEBUG[2387] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
May 18 09:57:44 VERBOSE[2387] logger.c: Sending to 192.168.3.197 : 5060 (non-NAT)
May 18 09:57:44 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=as38d88c6e 
Call-ID: 1.6956.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:57:44 DEBUG[11247] app_macro.c: Spawn extension (macro-hangupcall,s,3) exited non-zero on 'SIP/5060-0981d5c0' in macro 'hangupcall'
May 18 09:57:44 DEBUG[11247] pbx.c: Spawn extension (macro-hangupcall,s,3) exited non-zero on 'SIP/5060-0981d5c0'
May 18 09:57:44 DEBUG[11247] channel.c: Hanging up channel 'SIP/5060-0981d5c0'
May 18 09:57:44 DEBUG[11247] chan_sip.c: Hangup call SIP/5060-0981d5c0, SIP callid 1.6956.192.168.3.197@sipp.call.id)
May 18 09:57:44 DEBUG[11247] chan_sip.c: update_call_counter() - decrement call limit counter
May 18 09:57:44 DEBUG[11247] chan_sip.c: Updating call counter for incoming call
May 18 09:57:44 DEBUG[2380] chan_sip.c: Checking device state for peer 5060
May 18 09:57:44 DEBUG[2380] devicestate.c: Changing state for SIP/5060 - state 4 (Invalid)
May 18 09:57:44 DEBUG[11256] app_queue.c: Device 'SIP/5060' changed to state '4' (Invalid)
May 18 09:57:45 VERBOSE[2387] logger.c: Destroying call '1.6956.192.168.3.197@sipp.call.id'
May 18 09:57:45 VERBOSE[2387] logger.c: 
<-- SIP read from 192.168.3.11:5060: 
OPTIONS sip:192.168.3.99 SIP/2.0 
Content-Length: 0 
Call-ID: D4750E05-5696-4264-B7CD-1B06900E6834@192.168.3.11 
From: ;tag=60549601519680 
CSeq: 7652 OPTIONS 
Max-Forwards: 70 
To: 
Via: SIP/2.0/UDP 192.168.3.11;rport;branch=z9hG4bKc0a8030b0131c9b1446c289f00003fae0000525a 


May 18 09:57:45 DEBUG[2387] chan_sip.c: Header 0: OPTIONS sip:192.168.3.99 SIP/2.0 (32)
May 18 09:57:45 DEBUG[2387] chan_sip.c: Header 1: Content-Length: 0 (17)
May 18 09:57:45 DEBUG[2387] chan_sip.c: Header 2: Call-ID: D4750E05-5696-4264-B7CD-1B06900E6834@192.168.3.11 (58)
May 18 09:57:45 DEBUG[2387] chan_sip.c: Header 3: From: ;tag=60549601519680 (47)
May 18 09:57:45 DEBUG[2387] chan_sip.c: Header 4: CSeq: 7652 OPTIONS (18)
May 18 09:57:45 DEBUG[2387] chan_sip.c: Header 5: Max-Forwards: 70 (16)
May 18 09:57:45 DEBUG[2387] chan_sip.c: Header 6: To: (22)
May 18 09:57:45 DEBUG[2387] chan_sip.c: Header 7: Via: SIP/2.0/UDP 192.168.3.11;rport;branch=z9hG4bKc0a8030b0131c9b1446c289f00003fae0000525a (90)
May 18 09:57:45 DEBUG[2387] chan_sip.c: Header 8: (0)
May 18 09:57:45 VERBOSE[2387] logger.c: --- (8 headers 0 lines)May 18 09:57:45 VERBOSE[2387] logger.c: --- (8 headers 0 lines)---
May 18 09:57:45 DEBUG[2387] chan_sip.c: Allocating new SIP dialog for D4750E05-5696-4264-B7CD-1B06900E6834@192.168.3.11 - OPTIONS (No RTP)
May 18 09:57:45 DEBUG[2387] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS
May 18 09:57:45 VERBOSE[2387] logger.c: Looking for s in from-internal (domain 192.168.3.99)
May 18 09:57:45 VERBOSE[2387] logger.c: Transmitting (no NAT) to 192.168.3.11:5060:
SIP/2.0 200 OK 
Via: SIP/2.0/UDP 192.168.3.11;rport;branch=z9hG4bKc0a8030b0131c9b1446c289f00003fae0000525a;received=192.168.3.11 
From: ;tag=60549601519680 
To: ;tag=as33225d5d 
Call-ID: D4750E05-5696-4264-B7CD-1B06900E6834@192.168.3.11 
CSeq: 7652 OPTIONS 
User-Agent: Asterisk PBX 
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY 
Contact: 
Accept: application/sdp 
Content-Length: 0 


---
May 18 09:57:45 VERBOSE[2387] logger.c: Destroying call 'D4750E05-5696-4264-B7CD-1B06900E6834@192.168.3.11'
May 18 09:57:45 VERBOSE[2387] logger.c: Destroying call 'D4750E05-5696-4264-B7CD-1B06900E6834@192.168.3.11'