[2012-04-13 16:12:55] VERBOSE[410] config.c: == Parsing '/etc/asterisk/logger.conf': [2012-04-13 16:12:55] DEBUG[410] config.c: Parsing /etc/asterisk/logger.conf [2012-04-13 16:12:55] VERBOSE[410] config.c: == Found [2012-04-13 16:12:55] VERBOSE[410] logger.c: Asterisk Queue Logger restarted [2012-04-13 16:12:57] DEBUG[28614] chan_iax2.c: ip callno count decremented to 3 for 1.1.1.4 [2012-04-13 16:12:57] DEBUG[28615] chan_iax2.c: schedule decrement of callno used for 1.1.1.4 in 60 seconds [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Auto destroying SIP dialog '137481256314487-33213181130681@10.42.1.125' [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Destroying SIP dialog 137481256314487-33213181130681@10.42.1.125 [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 0 [ 0]: [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 10.42.1.242:5064;branch=z9hG4bK1327438473 [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 2 [ 53]: From: "1_1106" ;tag=421474161 [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 3 [ 37]: To: "1_1106" [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 4 [ 31]: Call-ID: 1953910999@10.42.1.242 [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 5 [ 18]: CSeq: 671 REGISTER [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 7 [158]: Authorization: Digest username="1_1106", realm="asterisk", nonce="2111039a", uri="sip:10.42.0.253", response="b8112b88c6e07f50b7866b37cd174aca", algorithm=MD5 [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 8 [115]: Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 9 [ 16]: Max-Forwards: 70 [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 10 [ 38]: User-Agent: Yealink SIP-T28P 2.43.0.50 [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 11 [ 13]: Expires: 3600 [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: = Looking for Call ID: 1953910999@10.42.1.242 (Checking From) --From tag 421474161 --To-tag [2012-04-13 16:12:58] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:12:58] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:12:58] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:12:58] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 1953910999@10.42.1.242 [2012-04-13 16:12:58] DEBUG[28626] netsock2.c: Splitting '10.42.1.242:5064' into... [2012-04-13 16:12:58] DEBUG[28626] netsock2.c: ...host '10.42.1.242' and port '5064'. [2012-04-13 16:12:58] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:12:58] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:12:58] DEBUG[28626] chan_sip.c: Trying to put 'SIP/2.0 403' onto UDP socket destined for 10.42.1.242:5064 [2012-04-13 16:12:58] NOTICE[28626] chan_sip.c: Registration from '"1_1106" ' failed for '10.42.1.242:5064' - No matching peer found [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: <--- SIP read from UDP:10.210.12.209:5060 ---> INVITE sip:11111@10.42.0.253:5060 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.209:5060;branch=z9hG4bK-593-1-0 From: "sipp" ;tag=1 To: Call-ID: 1-593@10.210.12.209 CSeq: 1 INVITE Contact: Max-Forwards: 70 User-Agent: sipp test Supported: replaces, timer Content-Type: application/sdp Content-Length: 137 v=0 o=user1 53655765 2353687637 IN IP4 10.210.12.209 s=- c=IN IP4 10.210.12.209 t=0 0 m=audio 6000 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 0 [ 41]: INVITE sip:11111@10.42.0.253:5060 SIP/2.0 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 10.210.12.209:5060;branch=z9hG4bK-593-1-0 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 2 [ 48]: From: "sipp" ;tag=1 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 3 [ 32]: To: [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 4 [ 28]: Call-ID: 1-593@10.210.12.209 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 5 [ 14]: CSeq: 1 INVITE [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 8 [ 21]: User-Agent: sipp test [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 9 [ 26]: Supported: replaces, timer [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 10 [ 29]: Content-Type: application/sdp [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 11 [ 19]: Content-Length: 137 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 12 [ 0]: [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 0 [ 3]: v=0 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 1 [ 48]: o=user1 53655765 2353687637 IN IP4 10.210.12.209 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 2 [ 3]: s=- [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 3 [ 22]: c=IN IP4 10.210.12.209 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 4 [ 5]: t=0 0 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 5 [ 22]: m=audio 6000 RTP/AVP 0 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: --- (12 headers 7 lines) --- [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: = Looking for Call ID: 1-593@10.210.12.209 (Checking From) --From tag 1 --To-tag [2012-04-13 16:12:59] DEBUG[28626] acl.c: For destination '10.210.12.209', our source address is '10.42.0.253'. [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.42.0.253:5060 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Allocating new SIP dialog for 1-593@10.210.12.209 - INVITE (No RTP) [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2012-04-13 16:12:59] DEBUG[28626] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, timer" [2012-04-13 16:12:59] DEBUG[28626] sip/reqresp_parser.c: Found SIP option: -replaces- [2012-04-13 16:12:59] DEBUG[28626] sip/reqresp_parser.c: Matched SIP option: replaces [2012-04-13 16:12:59] DEBUG[28626] sip/reqresp_parser.c: Found SIP option: -timer- [2012-04-13 16:12:59] DEBUG[28626] sip/reqresp_parser.c: Matched SIP option: timer [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port '5060'. [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Sending to 10.210.12.209:5060 (NAT) [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Initializing initreq for method INVITE - callid 1-593@10.210.12.209 [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Using INVITE request as basis request - 1-593@10.210.12.209 [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port ''. [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Found peer 'sipp' for 'sipp' from 10.210.12.209:5060 [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: <--- Reliably Transmitting (NAT) to 10.210.12.209:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.210.12.209:5060;branch=z9hG4bK-593-1-0;received=10.210.12.209;rport=5060 From: "sipp" ;tag=1 To: ;tag=as14288027 Call-ID: 1-593@10.210.12.209 CSeq: 1 INVITE Server: Asterisk PBX SVN-branch-1.8-r361972M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="783e3974" Content-Length: 0 <------------> [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #3096 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.210.12.209:5060 [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Scheduling destruction of SIP dialog '1-593@10.210.12.209' in 32000 ms (Method: INVITE) [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: <--- SIP read from UDP:10.210.12.209:5060 ---> INVITE sip:11111@10.42.0.253:5060 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.209:5060 From: "sipp" ;tag=1 To: Call-ID: 1-593@10.210.12.209 CSeq: 2 INVITE Contact: Authorization: Digest username="sipp",realm="asterisk",uri="sip:10.42.0.253:5060",nonce="783e3974",response="dfd77f1bc8986d06636cc09aec3cfc39",algorithm=MD5 Max-Forwards: 70 User-Agent: sipp test Supported: replaces, timer Content-Type: application/sdp Content-Length: 139 v=0 o=user1 53655765 2353687637 IN IP4 10.210.12.209 s=- c=IN IP4 10.210.12.209 t=0 0 m=audio 6000 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 0 [ 41]: INVITE sip:11111@10.42.0.253:5060 SIP/2.0 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 1 [ 35]: Via: SIP/2.0/UDP 10.210.12.209:5060 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 2 [ 48]: From: "sipp" ;tag=1 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 3 [ 32]: To: [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 4 [ 28]: Call-ID: 1-593@10.210.12.209 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 5 [ 14]: CSeq: 2 INVITE [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 7 [156]: Authorization: Digest username="sipp",realm="asterisk",uri="sip:10.42.0.253:5060",nonce="783e3974",response="dfd77f1bc8986d06636cc09aec3cfc39",algorithm=MD5 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 9 [ 21]: User-Agent: sipp test [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 10 [ 26]: Supported: replaces, timer [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 12 [ 19]: Content-Length: 139 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 13 [ 0]: [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 0 [ 0]: [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 1 [ 3]: v=0 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 2 [ 48]: o=user1 53655765 2353687637 IN IP4 10.210.12.209 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 3 [ 3]: s=- [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 4 [ 22]: c=IN IP4 10.210.12.209 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 5 [ 5]: t=0 0 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 6 [ 22]: m=audio 6000 RTP/AVP 0 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: --- (13 headers 8 lines) --- [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: = Looking for Call ID: 1-593@10.210.12.209 (Checking From) --From tag 1 --To-tag [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: Splitting '10.42.0.253:5060' into... [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port '5060'. [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: Splitting '10.42.0.253:5060' into... [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port '5060'. [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3096 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Stopping retransmission on '1-593@10.210.12.209' of Response 1: Match Found [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port '5060'. [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Sending to 10.210.12.209:5060 (NAT) [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Initializing initreq for method INVITE - callid 1-593@10.210.12.209 [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Using INVITE request as basis request - 1-593@10.210.12.209 [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port ''. [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Found peer 'sipp' for 'sipp' from 10.210.12.209:5060 [2012-04-13 16:12:59] DEBUG[28626] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb656aed8' [2012-04-13 16:12:59] DEBUG[28626] res_rtp_asterisk.c: Allocated port 15978 for RTP instance '0xb656aed8' [2012-04-13 16:12:59] DEBUG[28626] rtp_engine.c: RTP instance '0xb656aed8' is setup and ready to go [2012-04-13 16:12:59] DEBUG[28626] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb656aed8' [2012-04-13 16:12:59] VERBOSE[28626] netsock2.c: == Using SIP RTP CoS mark 5 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Setting NAT on RTP to On [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Processing session-level SDP o=user1 53655765 2353687637 IN IP4 10.210.12.209... UNSUPPORTED. [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: Splitting '10.210.12.209' into... [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port ''. [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Processing session-level SDP c=IN IP4 10.210.12.209... OK. [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Found RTP audio format 0 [2012-04-13 16:12:59] DEBUG[28626] rtp_engine.c: Setting payload 0 based on m type on 0xb6c53344 [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Found audio description format PCMU for ID 0 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2012-04-13 16:12:59] DEBUG[28626] rtp_engine.c: Incorporating payload 0 on 0xb6c53344 [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing) [2012-04-13 16:12:59] DEBUG[28626] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb656aed8' [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Peer audio RTP is at port 10.210.12.209:6000 [2012-04-13 16:12:59] DEBUG[28626] rtp_engine.c: Copying payload 0 from 0xb6c53344 to 0xb656b084 [2012-04-13 16:12:59] DEBUG[28626] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb656aed8' [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Checking SIP call limits for device sipp [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Updating call counter for incoming call [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Call from peer 'sipp' is 1 out of 10 [2012-04-13 16:12:59] DEBUG[28604] devicestate.c: No provider found, checking channel drivers for SIP - sipp [2012-04-13 16:12:59] DEBUG[28604] chan_sip.c: Checking device state for peer sipp [2012-04-13 16:12:59] DEBUG[28604] devicestate.c: Changing state for SIP/sipp - state 5 (Unavailable) [2012-04-13 16:12:59] DEBUG[28604] devicestate.c: device 'SIP/sipp' state '5' [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: Splitting '10.42.0.253:5060' into... [2012-04-13 16:12:59] DEBUG[28636] app_queue.c: Device 'SIP/sipp' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:12:59] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port ''. [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: Looking for 11111 in test11 (domain 10.42.0.253) [2012-04-13 16:12:59] DEBUG[28626] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:12:59] DEBUG[28626] pbx.c: returning an exact match-- _X. [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: *** Our native formats are 0x4 (ulaw) [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: This channel will not be able to handle video. [2012-04-13 16:12:59] DEBUG[28626] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:12:59] DEBUG[28626] pbx.c: returning an exact match-- _X. [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: build_route: Contact hop: [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: list_route: hop: [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: SIP/sipp-00000007: New call is still down.... Trying... [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: <--- Transmitting (NAT) to 10.210.12.209:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.210.12.209:5060;received=10.210.12.209;rport=5060 From: "sipp" ;tag=1 To: Call-ID: 1-593@10.210.12.209 CSeq: 2 INVITE Server: Asterisk PBX SVN-branch-1.8-r361972M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.210.12.209:5060 [2012-04-13 16:12:59] DEBUG[28604] devicestate.c: No provider found, checking channel drivers for SIP - sipp [2012-04-13 16:12:59] DEBUG[28604] chan_sip.c: Checking device state for peer sipp [2012-04-13 16:12:59] DEBUG[28604] devicestate.c: Changing state for SIP/sipp - state 5 (Unavailable) [2012-04-13 16:12:59] DEBUG[522] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:12:59] DEBUG[28604] devicestate.c: device 'SIP/sipp' state '5' [2012-04-13 16:12:59] DEBUG[28636] app_queue.c: Device 'SIP/sipp' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [2012-04-13 16:12:59] DEBUG[522] pbx.c: returning an exact match-- _X. [2012-04-13 16:12:59] DEBUG[522] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:12:59] DEBUG[522] pbx.c: returning an exact match-- _X. [2012-04-13 16:12:59] DEBUG[522] pbx.c: Launching 'NoOp' [2012-04-13 16:12:59] VERBOSE[522] pbx.c: -- Executing [11111@test11:1] NoOp("SIP/sipp-00000007", "") in new stack [2012-04-13 16:12:59] DEBUG[522] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:12:59] DEBUG[522] pbx.c: returning an exact match-- _X. [2012-04-13 16:12:59] DEBUG[522] pbx.c: Launching 'Wait' [2012-04-13 16:12:59] VERBOSE[522] pbx.c: -- Executing [11111@test11:2] Wait("SIP/sipp-00000007", "1") in new stack [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: <--- SIP read from UDP:10.210.12.209:5060 ---> ACK sip:11111@10.42.0.253:5060 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.209:5060 Max-Forwards: 70 From: "sipp" ;tag=1 To: ;tag=as14288027 CSeq: 1 ACK Contact: Call-ID: 1-593@10.210.12.209 User-Agent: sipp test Content-Length: 0 <-------------> [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 0 [ 38]: ACK sip:11111@10.42.0.253:5060 SIP/2.0 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 1 [ 35]: Via: SIP/2.0/UDP 10.210.12.209:5060 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 3 [ 48]: From: "sipp" ;tag=1 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 4 [ 47]: To: ;tag=as14288027 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 5 [ 11]: CSeq: 1 ACK [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 7 [ 28]: Call-ID: 1-593@10.210.12.209 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 8 [ 21]: User-Agent: sipp test [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [2012-04-13 16:12:59] VERBOSE[28626] chan_sip.c: --- (10 headers 0 lines) --- [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: = Looking for Call ID: 1-593@10.210.12.209 (Checking From) --From tag 1 --To-tag as14288027 [2012-04-13 16:12:59] DEBUG[28626] chan_sip.c: Invalid SIP message - rejected , no callid, len 309 [2012-04-13 16:13:00] DEBUG[522] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:13:00] DEBUG[522] pbx.c: returning an exact match-- _X. [2012-04-13 16:13:00] DEBUG[522] pbx.c: Launching 'Progress' [2012-04-13 16:13:00] VERBOSE[522] pbx.c: -- Executing [11111@test11:3] Progress("SIP/sipp-00000007", "") in new stack [2012-04-13 16:13:00] DEBUG[522] chan_sip.c: Setting framing from config on incoming call [2012-04-13 16:13:00] DEBUG[522] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [2012-04-13 16:13:00] DEBUG[522] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [2012-04-13 16:13:00] VERBOSE[522] chan_sip.c: Audio is at 15978 [2012-04-13 16:13:00] VERBOSE[522] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2012-04-13 16:13:00] DEBUG[522] chan_sip.c: -- Done with adding codecs to SDP [2012-04-13 16:13:00] DEBUG[522] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [2012-04-13 16:13:00] VERBOSE[522] chan_sip.c: <--- Transmitting (NAT) to 10.210.12.209:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.210.12.209:5060;received=10.210.12.209;rport=5060 From: "sipp" ;tag=1 To: ;tag=as5321f3cd Call-ID: 1-593@10.210.12.209 CSeq: 2 INVITE Server: Asterisk PBX SVN-branch-1.8-r361972M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 192 v=0 o=root 408221265 408221265 IN IP4 10.42.0.253 s=Asterisk PBX SVN-branch-1.8-r361972M c=IN IP4 10.42.0.253 t=0 0 m=audio 15978 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv <------------> [2012-04-13 16:13:00] DEBUG[522] chan_sip.c: Trying to put 'SIP/2.0 183' onto UDP socket destined for 10.210.12.209:5060 [2012-04-13 16:13:00] DEBUG[522] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:13:00] DEBUG[522] pbx.c: returning an exact match-- _X. [2012-04-13 16:13:00] DEBUG[522] pbx.c: Launching 'Wait' [2012-04-13 16:13:00] VERBOSE[522] pbx.c: -- Executing [11111@test11:4] Wait("SIP/sipp-00000007", "2") in new stack [2012-04-13 16:13:02] DEBUG[522] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:13:02] DEBUG[522] pbx.c: returning an exact match-- _X. [2012-04-13 16:13:02] DEBUG[522] pbx.c: Launching 'Answer' [2012-04-13 16:13:02] VERBOSE[522] pbx.c: -- Executing [11111@test11:5] Answer("SIP/sipp-00000007", "") in new stack [2012-04-13 16:13:02] DEBUG[522] chan_sip.c: SIP answering channel: SIP/sipp-00000007 [2012-04-13 16:13:02] DEBUG[522] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-13 16:13:02] DEBUG[28604] devicestate.c: No provider found, checking channel drivers for SIP - sipp [2012-04-13 16:13:02] DEBUG[522] chan_sip.c: Setting framing from config on incoming call [2012-04-13 16:13:02] DEBUG[522] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [2012-04-13 16:13:02] DEBUG[522] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [2012-04-13 16:13:02] DEBUG[28604] chan_sip.c: Checking device state for peer sipp [2012-04-13 16:13:02] VERBOSE[522] chan_sip.c: Audio is at 15978 [2012-04-13 16:13:02] DEBUG[28604] devicestate.c: Changing state for SIP/sipp - state 5 (Unavailable) [2012-04-13 16:13:02] DEBUG[28604] devicestate.c: device 'SIP/sipp' state '5' [2012-04-13 16:13:02] VERBOSE[522] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2012-04-13 16:13:02] DEBUG[522] chan_sip.c: -- Done with adding codecs to SDP [2012-04-13 16:13:02] DEBUG[522] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [2012-04-13 16:13:02] VERBOSE[522] chan_sip.c: <--- Reliably Transmitting (NAT) to 10.210.12.209:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.210.12.209:5060;received=10.210.12.209;rport=5060 From: "sipp" ;tag=1 To: ;tag=as5321f3cd Call-ID: 1-593@10.210.12.209 CSeq: 2 INVITE Server: Asterisk PBX SVN-branch-1.8-r361972M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 192 v=0 o=root 408221265 408221266 IN IP4 10.42.0.253 s=Asterisk PBX SVN-branch-1.8-r361972M c=IN IP4 10.42.0.253 t=0 0 m=audio 15978 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv <------------> [2012-04-13 16:13:02] DEBUG[28636] app_queue.c: Device 'SIP/sipp' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [2012-04-13 16:13:02] DEBUG[522] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #3100 [2012-04-13 16:13:02] DEBUG[522] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.210.12.209:5060 [2012-04-13 16:13:02] VERBOSE[28626] chan_sip.c: <--- SIP read from UDP:10.210.12.209:5060 ---> ACK sip:11111@10.42.0.253:5060 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.209:5060;branch=z9hG4bK-593-1-10 From: "sipp" ;tag=1 To: ;tag=as5321f3cd Call-ID: 1-593@10.210.12.209 CSeq: 2 ACK Max-Forwards: 70 Authorization: Digest username="sipp",realm="asterisk",uri="sip:10.42.0.253:5060",nonce="783e3974",response="dfd77f1bc8986d06636cc09aec3cfc39",algorithm=MD5 Contact: User-Agent: sipp test Content-Length: 0 <-------------> [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 0 [ 38]: ACK sip:11111@10.42.0.253:5060 SIP/2.0 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.210.12.209:5060;branch=z9hG4bK-593-1-10 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 2 [ 48]: From: "sipp" ;tag=1 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 3 [ 47]: To: ;tag=as5321f3cd [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 4 [ 28]: Call-ID: 1-593@10.210.12.209 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 5 [ 11]: CSeq: 2 ACK [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 7 [156]: Authorization: Digest username="sipp",realm="asterisk",uri="sip:10.42.0.253:5060",nonce="783e3974",response="dfd77f1bc8986d06636cc09aec3cfc39",algorithm=MD5 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 8 [ 38]: Contact: [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 9 [ 21]: User-Agent: sipp test [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [2012-04-13 16:13:02] VERBOSE[28626] chan_sip.c: --- (11 headers 0 lines) --- [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: = Looking for Call ID: 1-593@10.210.12.209 (Checking From) --From tag 1 --To-tag as5321f3cd [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3100 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Stopping retransmission on '1-593@10.210.12.209' of Response 2: Match Found [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 1 [ 74]: Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK27681174481077925064;rport [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 2 [ 52]: From: 1_1105 ;tag=1957311506 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 3 [ 35]: To: 1_1105 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 4 [ 49]: Call-ID: 27161482026229-2759917572088@10.42.1.125 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 5 [ 16]: CSeq: 1 REGISTER [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 8 [ 11]: Expires: 60 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 9 [ 15]: Supported: path [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 10 [ 31]: User-Agent: Greenlite ATOM V2.0 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: = Looking for Call ID: 27161482026229-2759917572088@10.42.1.125 (Checking From) --From tag 1957311506 --To-tag [2012-04-13 16:13:02] DEBUG[28626] acl.c: For destination '10.42.1.125', our source address is '10.42.0.253'. [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.42.0.253:5060 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Allocating new SIP dialog for 27161482026229-2759917572088@10.42.1.125 - REGISTER (No RTP) [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 27161482026229-2759917572088@10.42.1.125 [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: Splitting '10.42.1.125:5060' into... [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: ...host '10.42.1.125' and port '5060'. [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.42.1.125:5060 [2012-04-13 16:13:02] NOTICE[28626] chan_sip.c: Registration from '1_1105 ' failed for '10.42.1.125:5060' - No matching peer found [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 1 [ 72]: Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK350764051209822215;rport [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 2 [ 52]: From: 1_1105 ;tag=1957311506 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 3 [ 35]: To: 1_1105 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 4 [ 49]: Call-ID: 27161482026229-2759917572088@10.42.1.125 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 5 [ 16]: CSeq: 2 REGISTER [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 7 [158]: Authorization: Digest username="1_1105", realm="asterisk", nonce="3c0f42c5", uri="sip:10.42.0.253", response="5400a8b61becef5c444a3ab42bda2f97", algorithm=MD5 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 9 [ 11]: Expires: 60 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 10 [ 15]: Supported: path [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 11 [ 31]: User-Agent: Greenlite ATOM V2.0 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: = Looking for Call ID: 27161482026229-2759917572088@10.42.1.125 (Checking From) --From tag 1957311506 --To-tag [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 27161482026229-2759917572088@10.42.1.125 [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: Splitting '10.42.1.125:5060' into... [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: ...host '10.42.1.125' and port '5060'. [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:13:02] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:13:02] DEBUG[28626] chan_sip.c: Trying to put 'SIP/2.0 403' onto UDP socket destined for 10.42.1.125:5060 [2012-04-13 16:13:02] NOTICE[28626] chan_sip.c: Registration from '1_1105 ' failed for '10.42.1.125:5060' - No matching peer found [2012-04-13 16:13:02] DEBUG[522] channel.c: Didn't receive a media frame from SIP/sipp-00000007 within 500 ms of answering. Continuing anyway [2012-04-13 16:13:02] DEBUG[522] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:13:02] DEBUG[522] pbx.c: returning an exact match-- _X. [2012-04-13 16:13:02] DEBUG[522] pbx.c: Launching 'Playback' [2012-04-13 16:13:02] VERBOSE[522] pbx.c: -- Executing [11111@test11:6] Playback("SIP/sipp-00000007", "demo-congrats") in new stack [2012-04-13 16:13:02] DEBUG[522] channel.c: Set channel SIP/sipp-00000007 to write format gsm [2012-04-13 16:13:02] DEBUG[522] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [2012-04-13 16:13:02] DEBUG[522] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [2012-04-13 16:13:02] DEBUG[522] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0xb656aed8' [2012-04-13 16:13:02] DEBUG[522] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2012-04-13 16:13:02] VERBOSE[522] file.c: -- Playing 'demo-congrats.gsm' (language 'en') [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 1 [ 84]: From: "1_1103";tag=103191c8-0-13c4-4f885090-a88c3c5-4f885090 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 2 [ 36]: To: "1_1103" [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 3 [ 51]: Call-ID: 10321aa0-0-13c4-4f885090-11fbb50c-4f885090 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 4 [ 16]: CSeq: 1 REGISTER [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 5 [ 81]: Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f885090-ac7ab5f9-5905c76a [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 6 [ 56]: Allow: INVITE,CANCEL,BYE,REFER,NOTIFY,SUBSCRIBE,INFO,ACK [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 7 [ 18]: user-Agent: Nateks [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 9 [ 26]: Supported: replaces,100rel [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 10 [ 49]: Contact: ;expires=70 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: = Looking for Call ID: 10321aa0-0-13c4-4f885090-11fbb50c-4f885090 (Checking From) --From tag 103191c8-0-13c4-4f885090-a88c3c5-4f885090 --To-tag [2012-04-13 16:13:03] DEBUG[28626] acl.c: For destination '10.42.1.233', our source address is '10.42.0.253'. [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.42.0.253:5060 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Allocating new SIP dialog for 10321aa0-0-13c4-4f885090-11fbb50c-4f885090 - REGISTER (No RTP) [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 10321aa0-0-13c4-4f885090-11fbb50c-4f885090 [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: Splitting '10.42.1.233:5060' into... [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: ...host '10.42.1.233' and port '5060'. [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.42.1.233:5060 [2012-04-13 16:13:03] NOTICE[28626] chan_sip.c: Registration from '"1_1103"' failed for '10.42.1.233:5060' - No matching peer found [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 1 [ 84]: From: "1_1103";tag=103191c8-0-13c4-4f885090-a88c3c5-4f885090 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 2 [ 36]: To: "1_1103" [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 3 [ 51]: Call-ID: 10321aa0-0-13c4-4f885090-11fbb50c-4f885090 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 4 [ 16]: CSeq: 2 REGISTER [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 5 [ 81]: Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f885090-ac7ab626-220ac83b [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 6 [ 56]: Allow: INVITE,CANCEL,BYE,REFER,NOTIFY,SUBSCRIBE,INFO,ACK [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 7 [ 18]: user-Agent: Nateks [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 9 [ 26]: Supported: replaces,100rel [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 10 [ 49]: Contact: ;expires=70 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 11 [153]: Authorization: Digest username="1_1103",realm="asterisk",nonce="20a56939",uri="sip:10.42.0.253",response="9bae50a645de8ea35a7bbd0b1f64284c",algorithm=MD5 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: = Looking for Call ID: 10321aa0-0-13c4-4f885090-11fbb50c-4f885090 (Checking From) --From tag 103191c8-0-13c4-4f885090-a88c3c5-4f885090 --To-tag [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 10321aa0-0-13c4-4f885090-11fbb50c-4f885090 [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: Splitting '10.42.1.233:5060' into... [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: ...host '10.42.1.233' and port '5060'. [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:13:03] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:13:03] DEBUG[28626] chan_sip.c: Trying to put 'SIP/2.0 403' onto UDP socket destined for 10.42.1.233:5060 [2012-04-13 16:13:03] NOTICE[28626] chan_sip.c: Registration from '"1_1103"' failed for '10.42.1.233:5060' - No matching peer found [2012-04-13 16:13:04] DEBUG[28626] chan_sip.c: Auto destroying SIP dialog '10321aa0-0-13c4-4f885071-595122a3-4f885071' [2012-04-13 16:13:04] DEBUG[28626] chan_sip.c: Destroying SIP dialog 10321aa0-0-13c4-4f885071-595122a3-4f885071 [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Header 0 [ 30]: NOTIFY sip:10.42.0.253 SIP/2.0 [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-a2f141de [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Header 2 [ 62]: From: "1_1102" ;tag=63e70cb54c3c09fdo1 [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Header 3 [ 21]: To: [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Header 4 [ 38]: Call-ID: 187087f5-d62ec7bd@10.42.1.146 [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Header 5 [ 18]: CSeq: 22667 NOTIFY [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Header 7 [ 47]: Contact: "1_1102" [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Header 8 [ 17]: Event: keep-alive [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Header 9 [ 35]: User-Agent: Linksys/SPA962-6.1.5(a) [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: = Looking for Call ID: 187087f5-d62ec7bd@10.42.1.146 (Checking From) --From tag 63e70cb54c3c09fdo1 --To-tag [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Got NOTIFY Event: keep-alive [2012-04-13 16:13:05] DEBUG[28626] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.42.1.146:5061 [2012-04-13 16:13:07] VERBOSE[28626] chan_sip.c: <--- SIP read from UDP:10.210.12.209:5060 ---> BYE sip:11111@10.42.0.253:5060 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.209:5060;branch=z9hG4bK-593-1-12 From: "sipp" ;tag=1 To: ;tag=as5321f3cd Call-ID: 1-593@10.210.12.209 CSeq: 2 BYE Contact: Max-Forwards: 70 User-Agent: sipp test Content-Length: 0 <-------------> [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Header 0 [ 38]: BYE sip:11111@10.42.0.253:5060 SIP/2.0 [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.210.12.209:5060;branch=z9hG4bK-593-1-12 [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Header 2 [ 48]: From: "sipp" ;tag=1 [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Header 3 [ 47]: To: ;tag=as5321f3cd [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Header 4 [ 28]: Call-ID: 1-593@10.210.12.209 [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Header 5 [ 11]: CSeq: 2 BYE [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Header 8 [ 21]: User-Agent: sipp test [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [2012-04-13 16:13:07] VERBOSE[28626] chan_sip.c: --- (10 headers 0 lines) --- [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: = Looking for Call ID: 1-593@10.210.12.209 (Checking From) --From tag 1 --To-tag as5321f3cd [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Ignoring SIP message because of retransmit (BYE Seqno 2, ours 2) [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Initializing initreq for method BYE - callid 1-593@10.210.12.209 [2012-04-13 16:13:07] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:13:07] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port '5060'. [2012-04-13 16:13:07] VERBOSE[28626] chan_sip.c: Sending to 10.210.12.209:5060 (NAT) [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Setting SIP_ALREADYGONE on dialog 1-593@10.210.12.209 [2012-04-13 16:13:07] DEBUG[28626] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb656aed8' [2012-04-13 16:13:07] VERBOSE[28626] chan_sip.c: Scheduling destruction of SIP dialog '1-593@10.210.12.209' in 32000 ms (Method: BYE) [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Received bye, issuing owner hangup [2012-04-13 16:13:07] VERBOSE[28626] chan_sip.c: <--- Transmitting (NAT) to 10.210.12.209:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.210.12.209:5060;branch=z9hG4bK-593-1-12;received=10.210.12.209;rport=5060 From: "sipp" ;tag=1 To: ;tag=as5321f3cd Call-ID: 1-593@10.210.12.209 CSeq: 2 BYE Server: Asterisk PBX SVN-branch-1.8-r361972M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [2012-04-13 16:13:07] DEBUG[28626] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.210.12.209:5060 [2012-04-13 16:13:07] DEBUG[522] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-13 16:13:07] DEBUG[522] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-13 16:13:07] DEBUG[522] channel.c: Set channel SIP/sipp-00000007 to write format ulaw [2012-04-13 16:13:07] DEBUG[522] pbx.c: Spawn extension (test11,11111,6) exited non-zero on 'SIP/sipp-00000007' [2012-04-13 16:13:07] VERBOSE[522] pbx.c: == Spawn extension (test11, 11111, 6) exited non-zero on 'SIP/sipp-00000007' [2012-04-13 16:13:07] DEBUG[522] channel.c: Soft-Hanging up channel 'SIP/sipp-00000007' [2012-04-13 16:13:07] DEBUG[522] pbx.c: return at end of func [2012-04-13 16:13:07] DEBUG[522] channel.c: Hanging up channel 'SIP/sipp-00000007' [2012-04-13 16:13:07] DEBUG[522] chan_sip.c: Hanging up zombie call. Be scared. [2012-04-13 16:13:07] DEBUG[522] chan_sip.c: update_call_counter(sipp) - decrement call limit counter on hangup [2012-04-13 16:13:07] DEBUG[522] chan_sip.c: Updating call counter for incoming call [2012-04-13 16:13:07] DEBUG[522] chan_sip.c: Call from peer 'sipp' removed from call limit 10 [2012-04-13 16:13:07] DEBUG[28604] devicestate.c: No provider found, checking channel drivers for SIP - sipp [2012-04-13 16:13:07] DEBUG[28604] chan_sip.c: Checking device state for peer sipp [2012-04-13 16:13:07] DEBUG[28604] devicestate.c: Changing state for SIP/sipp - state 5 (Unavailable) [2012-04-13 16:13:07] DEBUG[28604] devicestate.c: device 'SIP/sipp' state '5' [2012-04-13 16:13:07] DEBUG[522] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb656aed8' [2012-04-13 16:13:07] DEBUG[28636] app_queue.c: Device 'SIP/sipp' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [2012-04-13 16:13:07] DEBUG[522] cdr_mysql.c: Inserting a CDR record. [2012-04-13 16:13:07] DEBUG[522] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`) VALUES ('2012-04-13 16:12:59','\"sipp\" <1105>','1105','11111','test11','SIP/sipp-00000007','Playback','demo-congrats','8','5','ANSWERED','3','1334319179.7') [2012-04-13 16:13:07] DEBUG[28604] devicestate.c: No provider found, checking channel drivers for SIP - sipp [2012-04-13 16:13:07] DEBUG[28604] chan_sip.c: Checking device state for peer sipp [2012-04-13 16:13:07] DEBUG[28604] devicestate.c: Changing state for SIP/sipp - state 5 (Unavailable) [2012-04-13 16:13:07] DEBUG[28604] devicestate.c: device 'SIP/sipp' state '5' [2012-04-13 16:13:07] DEBUG[28636] app_queue.c: Device 'SIP/sipp' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [2012-04-13 16:13:07] DEBUG[28617] chan_iax2.c: ip callno count incremented to 4 for 1.1.1.4 [2012-04-13 16:13:17] DEBUG[28614] chan_iax2.c: ip callno count decremented to 3 for 1.1.1.4 [2012-04-13 16:13:17] DEBUG[28620] chan_iax2.c: schedule decrement of callno used for 1.1.1.4 in 60 seconds