[2012-04-13 16:09:42] VERBOSE[410] config.c: == Parsing '/etc/asterisk/logger.conf': [2012-04-13 16:09:42] DEBUG[410] config.c: Parsing /etc/asterisk/logger.conf [2012-04-13 16:09:42] VERBOSE[410] config.c: == Found [2012-04-13 16:09:42] VERBOSE[410] logger.c: Asterisk Queue Logger restarted [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 1 [ 85]: From: "1_1103";tag=103198a8-0-13c4-4f884fc8-5d9d3699-4f884fc8 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 2 [ 36]: To: "1_1103" [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 3 [ 51]: Call-ID: 10321aa0-0-13c4-4f884fc8-26933510-4f884fc8 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 4 [ 16]: CSeq: 1 REGISTER [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 5 [ 81]: Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f884fc8-ac77a8af-17af43ae [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 6 [ 56]: Allow: INVITE,CANCEL,BYE,REFER,NOTIFY,SUBSCRIBE,INFO,ACK [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 7 [ 18]: user-Agent: Nateks [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 9 [ 26]: Supported: replaces,100rel [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 10 [ 49]: Contact: ;expires=70 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 12 [ 0]: [2012-04-13 16:09:43] DEBUG[28626] acl.c: For destination '10.42.1.233', our source address is '10.42.0.253'. [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.42.0.253:5060 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Allocating new SIP dialog for 10321aa0-0-13c4-4f884fc8-26933510-4f884fc8 - REGISTER (No RTP) [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 10321aa0-0-13c4-4f884fc8-26933510-4f884fc8 [2012-04-13 16:09:43] DEBUG[28626] netsock2.c: Splitting '10.42.1.233:5060' into... [2012-04-13 16:09:43] DEBUG[28626] netsock2.c: ...host '10.42.1.233' and port '5060'. [2012-04-13 16:09:43] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:09:43] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:09:43] 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:09:43] NOTICE[28626] chan_sip.c: Registration from '"1_1103"' failed for '10.42.1.233:5060' - No matching peer found [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 1 [ 85]: From: "1_1103";tag=103198a8-0-13c4-4f884fc8-5d9d3699-4f884fc8 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 2 [ 36]: To: "1_1103" [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 3 [ 51]: Call-ID: 10321aa0-0-13c4-4f884fc8-26933510-4f884fc8 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 4 [ 16]: CSeq: 2 REGISTER [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 5 [ 81]: Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f884fc8-ac77a8dc-1455944f [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 6 [ 56]: Allow: INVITE,CANCEL,BYE,REFER,NOTIFY,SUBSCRIBE,INFO,ACK [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 7 [ 18]: user-Agent: Nateks [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 9 [ 26]: Supported: replaces,100rel [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 10 [ 49]: Contact: ;expires=70 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 11 [153]: Authorization: Digest username="1_1103",realm="asterisk",nonce="74642ec1",uri="sip:10.42.0.253",response="f465d2b4174c3d698d54333914e322a8",algorithm=MD5 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Header 13 [ 0]: [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:09:43] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 10321aa0-0-13c4-4f884fc8-26933510-4f884fc8 [2012-04-13 16:09:43] DEBUG[28626] netsock2.c: Splitting '10.42.1.233:5060' into... [2012-04-13 16:09:43] DEBUG[28626] netsock2.c: ...host '10.42.1.233' and port '5060'. [2012-04-13 16:09:43] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:09:43] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:09:43] 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:09:43] NOTICE[28626] chan_sip.c: Registration from '"1_1103"' failed for '10.42.1.233:5060' - No matching peer found [2012-04-13 16:09:44] DEBUG[28626] chan_sip.c: Auto destroying SIP dialog '10321aa0-0-13c4-4f884fa9-168c01b7-4f884fa9' [2012-04-13 16:09:44] DEBUG[28626] chan_sip.c: Destroying SIP dialog 10321aa0-0-13c4-4f884fa9-168c01b7-4f884fa9 [2012-04-13 16:09:47] DEBUG[28617] chan_iax2.c: ip callno count incremented to 4 for 1.1.1.4 [2012-04-13 16:09:49] 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-589-1-0 From: "sipp" ;tag=1 To: Call-ID: 1-589@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:09:49] DEBUG[28626] chan_sip.c: Header 0 [ 41]: INVITE sip:11111@10.42.0.253:5060 SIP/2.0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 10.210.12.209:5060;branch=z9hG4bK-589-1-0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 2 [ 48]: From: "sipp" ;tag=1 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 3 [ 32]: To: [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 4 [ 28]: Call-ID: 1-589@10.210.12.209 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 5 [ 14]: CSeq: 1 INVITE [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 8 [ 21]: User-Agent: sipp test [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 9 [ 26]: Supported: replaces, timer [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 10 [ 29]: Content-Type: application/sdp [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 11 [ 21]: Content-Length: 137 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 12 [ 0]: [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 0 [ 3]: v=0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 1 [ 48]: o=user1 53655765 2353687637 IN IP4 10.210.12.209 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 2 [ 3]: s=- [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 3 [ 22]: c=IN IP4 10.210.12.209 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 4 [ 5]: t=0 0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 5 [ 22]: m=audio 6000 RTP/AVP 0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: --- (12 headers 7 lines) --- [2012-04-13 16:09:49] DEBUG[28626] acl.c: For destination '10.210.12.209', our source address is '10.42.0.253'. [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.42.0.253:5060 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Allocating new SIP dialog for 1-589@10.210.12.209 - INVITE (No RTP) [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2012-04-13 16:09:49] DEBUG[28626] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, timer" [2012-04-13 16:09:49] DEBUG[28626] sip/reqresp_parser.c: Found SIP option: -replaces- [2012-04-13 16:09:49] DEBUG[28626] sip/reqresp_parser.c: Matched SIP option: replaces [2012-04-13 16:09:49] DEBUG[28626] sip/reqresp_parser.c: Found SIP option: -timer- [2012-04-13 16:09:49] DEBUG[28626] sip/reqresp_parser.c: Matched SIP option: timer [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port '5060'. [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: Sending to 10.210.12.209:5060 (NAT) [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Initializing initreq for method INVITE - callid 1-589@10.210.12.209 [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: Using INVITE request as basis request - 1-589@10.210.12.209 [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port ''. [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: Found peer 'sipp' for 'sipp' from 10.210.12.209:5060 [2012-04-13 16:09:49] 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-589-1-0;received=10.210.12.209;rport=5060 From: "sipp" ;tag=1 To: ;tag=as4283a98d Call-ID: 1-589@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="49c063dc" Content-Length: 0 <------------> [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #3032 [2012-04-13 16:09:49] 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:09:49] VERBOSE[28626] chan_sip.c: Scheduling destruction of SIP dialog '1-589@10.210.12.209' in 32000 ms (Method: INVITE) [2012-04-13 16:09:49] 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-589@10.210.12.209 CSeq: 2 INVITE Contact: Authorization: Digest username="sipp",realm="asterisk",uri="sip:10.42.0.253:5060",nonce="49c063dc",response="9847440e8c5a6cc7b8363f07ebdcfb0b",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:09:49] DEBUG[28626] chan_sip.c: Header 0 [ 41]: INVITE sip:11111@10.42.0.253:5060 SIP/2.0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 1 [ 35]: Via: SIP/2.0/UDP 10.210.12.209:5060 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 2 [ 48]: From: "sipp" ;tag=1 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 3 [ 32]: To: [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 4 [ 28]: Call-ID: 1-589@10.210.12.209 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 5 [ 14]: CSeq: 2 INVITE [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 7 [156]: Authorization: Digest username="sipp",realm="asterisk",uri="sip:10.42.0.253:5060",nonce="49c063dc",response="9847440e8c5a6cc7b8363f07ebdcfb0b",algorithm=MD5 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 9 [ 21]: User-Agent: sipp test [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 10 [ 26]: Supported: replaces, timer [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 12 [ 21]: Content-Length: 139 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 13 [ 0]: [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 0 [ 0]: [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 1 [ 3]: v=0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 2 [ 48]: o=user1 53655765 2353687637 IN IP4 10.210.12.209 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 3 [ 3]: s=- [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 4 [ 22]: c=IN IP4 10.210.12.209 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 5 [ 5]: t=0 0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 6 [ 22]: m=audio 6000 RTP/AVP 0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: --- (13 headers 8 lines) --- [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3032 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Stopping retransmission on '1-589@10.210.12.209' of Response 1: Match Found [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port '5060'. [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: Sending to 10.210.12.209:5060 (NAT) [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Initializing initreq for method INVITE - callid 1-589@10.210.12.209 [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: Using INVITE request as basis request - 1-589@10.210.12.209 [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port ''. [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: Found peer 'sipp' for 'sipp' from 10.210.12.209:5060 [2012-04-13 16:09:49] DEBUG[28626] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb656aed8' [2012-04-13 16:09:49] DEBUG[28626] res_rtp_asterisk.c: Allocated port 13068 for RTP instance '0xb656aed8' [2012-04-13 16:09:49] DEBUG[28626] rtp_engine.c: RTP instance '0xb656aed8' is setup and ready to go [2012-04-13 16:09:49] DEBUG[28626] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb656aed8' [2012-04-13 16:09:49] VERBOSE[28626] netsock2.c: == Using SIP RTP CoS mark 5 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Setting NAT on RTP to On [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Processing session-level SDP o=user1 53655765 2353687637 IN IP4 10.210.12.209... UNSUPPORTED. [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: Splitting '10.210.12.209' into... [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port ''. [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Processing session-level SDP c=IN IP4 10.210.12.209... OK. [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: Found RTP audio format 0 [2012-04-13 16:09:49] DEBUG[28626] rtp_engine.c: Setting payload 0 based on m type on 0xb6c53344 [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: Found audio description format PCMU for ID 0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2012-04-13 16:09:49] DEBUG[28626] rtp_engine.c: Incorporating payload 0 on 0xb6c53344 [2012-04-13 16:09:49] 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:09:49] VERBOSE[28626] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing) [2012-04-13 16:09:49] DEBUG[28626] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb656aed8' [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: Peer audio RTP is at port 10.210.12.209:6000 [2012-04-13 16:09:49] DEBUG[28626] rtp_engine.c: Copying payload 0 from 0xb6c53344 to 0xb656b084 [2012-04-13 16:09:49] DEBUG[28626] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb656aed8' [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: We're settling with these formats: 0x4 (ulaw) [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Checking SIP call limits for device sipp [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Updating call counter for incoming call [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Call from peer 'sipp' is 1 out of 10 [2012-04-13 16:09:49] DEBUG[28604] devicestate.c: No provider found, checking channel drivers for SIP - sipp [2012-04-13 16:09:49] DEBUG[28604] chan_sip.c: Checking device state for peer sipp [2012-04-13 16:09:49] DEBUG[28604] devicestate.c: Changing state for SIP/sipp - state 5 (Unavailable) [2012-04-13 16:09:49] DEBUG[28604] devicestate.c: device 'SIP/sipp' state '5' [2012-04-13 16:09:49] 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:09:49] DEBUG[28626] netsock2.c: Splitting '10.42.0.253:5060' into... [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:09:49] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port ''. [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: Looking for 11111 in test11 (domain 10.42.0.253) [2012-04-13 16:09:49] DEBUG[28626] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:09:49] DEBUG[28626] pbx.c: returning an exact match-- _X. [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: *** Our native formats are 0x4 (ulaw) [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: *** Joint capabilities are 0x4 (ulaw) [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: This channel will not be able to handle video. [2012-04-13 16:09:49] DEBUG[28626] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:09:49] DEBUG[28626] pbx.c: returning an exact match-- _X. [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: build_route: Contact hop: [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: list_route: hop: [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: SIP/sipp-00000006: New call is still down.... Trying... [2012-04-13 16:09:49] 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-589@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:09:49] 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:09:49] DEBUG[28604] devicestate.c: No provider found, checking channel drivers for SIP - sipp [2012-04-13 16:09:49] DEBUG[28604] chan_sip.c: Checking device state for peer sipp [2012-04-13 16:09:49] DEBUG[28604] devicestate.c: Changing state for SIP/sipp - state 5 (Unavailable) [2012-04-13 16:09:49] DEBUG[28604] devicestate.c: device 'SIP/sipp' state '5' [2012-04-13 16:09:49] 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:09:49] DEBUG[411] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:09:49] DEBUG[411] pbx.c: returning an exact match-- _X. [2012-04-13 16:09:49] DEBUG[411] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:09:49] DEBUG[411] pbx.c: returning an exact match-- _X. [2012-04-13 16:09:49] DEBUG[411] pbx.c: Launching 'NoOp' [2012-04-13 16:09:49] VERBOSE[411] pbx.c: -- Executing [11111@test11:1] NoOp("SIP/sipp-00000006", "") in new stack [2012-04-13 16:09:49] DEBUG[411] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:09:49] DEBUG[411] pbx.c: returning an exact match-- _X. [2012-04-13 16:09:49] DEBUG[411] pbx.c: Launching 'Wait' [2012-04-13 16:09:49] VERBOSE[411] pbx.c: -- Executing [11111@test11:2] Wait("SIP/sipp-00000006", "1") in new stack [2012-04-13 16:09:49] 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=as4283a98d CSeq: 1 ACK Contact: Call-ID: 1-589@10.210.12.209 User-Agent: sipp test Content-Length: 0 <-------------> [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 0 [ 38]: ACK sip:11111@10.42.0.253:5060 SIP/2.0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 1 [ 35]: Via: SIP/2.0/UDP 10.210.12.209:5060 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 3 [ 48]: From: "sipp" ;tag=1 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 4 [ 47]: To: ;tag=as4283a98d [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 5 [ 11]: CSeq: 1 ACK [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 7 [ 28]: Call-ID: 1-589@10.210.12.209 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 8 [ 21]: User-Agent: sipp test [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Header 10 [ 0]: [2012-04-13 16:09:49] VERBOSE[28626] chan_sip.c: --- (10 headers 0 lines) --- [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: Ignoring too old SIP packet packet 1 (expecting >= 2) [2012-04-13 16:09:49] DEBUG[28626] chan_sip.c: SIP message could not be handled, bad request: 1-589@10.210.12.209 [2012-04-13 16:09:50] DEBUG[411] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:09:50] DEBUG[411] pbx.c: returning an exact match-- _X. [2012-04-13 16:09:50] DEBUG[411] pbx.c: Launching 'Progress' [2012-04-13 16:09:50] VERBOSE[411] pbx.c: -- Executing [11111@test11:3] Progress("SIP/sipp-00000006", "") in new stack [2012-04-13 16:09:50] DEBUG[411] chan_sip.c: Setting framing from config on incoming call [2012-04-13 16:09:50] DEBUG[411] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [2012-04-13 16:09:50] DEBUG[411] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [2012-04-13 16:09:50] VERBOSE[411] chan_sip.c: Audio is at 13068 [2012-04-13 16:09:50] VERBOSE[411] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2012-04-13 16:09:50] DEBUG[411] chan_sip.c: -- Done with adding codecs to SDP [2012-04-13 16:09:50] DEBUG[411] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [2012-04-13 16:09:50] VERBOSE[411] 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=as7247e17c Call-ID: 1-589@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 Content-Type: application/sdp Content-Length: 192 v=0 o=root 153348672 153348672 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 13068 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv <------------> [2012-04-13 16:09:50] DEBUG[411] chan_sip.c: Trying to put 'SIP/2.0 183' onto UDP socket destined for 10.210.12.209:5060 [2012-04-13 16:09:50] DEBUG[411] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:09:50] DEBUG[411] pbx.c: returning an exact match-- _X. [2012-04-13 16:09:50] DEBUG[411] pbx.c: Launching 'Wait' [2012-04-13 16:09:50] VERBOSE[411] pbx.c: -- Executing [11111@test11:4] Wait("SIP/sipp-00000006", "2") in new stack [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 0 [ 30]: NOTIFY sip:10.42.0.253 SIP/2.0 [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-8c287273 [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 2 [ 62]: From: "1_1102" ;tag=63e70cb54c3c09fdo1 [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 3 [ 21]: To: [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 4 [ 38]: Call-ID: 187087f5-d62ec7bd@10.42.1.146 [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 5 [ 18]: CSeq: 22654 NOTIFY [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 7 [ 47]: Contact: "1_1102" [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 8 [ 17]: Event: keep-alive [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 9 [ 35]: User-Agent: Linksys/SPA962-6.1.5(a) [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Header 11 [ 0]: [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [2012-04-13 16:09:50] DEBUG[28626] chan_sip.c: Got NOTIFY Event: keep-alive [2012-04-13 16:09:50] 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:09:52] DEBUG[411] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:09:52] DEBUG[411] pbx.c: returning an exact match-- _X. [2012-04-13 16:09:52] DEBUG[411] pbx.c: Launching 'Answer' [2012-04-13 16:09:52] VERBOSE[411] pbx.c: -- Executing [11111@test11:5] Answer("SIP/sipp-00000006", "") in new stack [2012-04-13 16:09:52] DEBUG[411] chan_sip.c: SIP answering channel: SIP/sipp-00000006 [2012-04-13 16:09:52] DEBUG[28604] devicestate.c: No provider found, checking channel drivers for SIP - sipp [2012-04-13 16:09:52] DEBUG[411] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-13 16:09:52] DEBUG[28604] chan_sip.c: Checking device state for peer sipp [2012-04-13 16:09:52] DEBUG[28604] devicestate.c: Changing state for SIP/sipp - state 5 (Unavailable) [2012-04-13 16:09:52] DEBUG[28604] devicestate.c: device 'SIP/sipp' state '5' [2012-04-13 16:09:52] DEBUG[411] chan_sip.c: Setting framing from config on incoming call [2012-04-13 16:09:52] DEBUG[411] chan_sip.c: ** Our capability: 0x4 (ulaw) Video flag: True Text flag: True [2012-04-13 16:09:52] DEBUG[411] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [2012-04-13 16:09:52] VERBOSE[411] chan_sip.c: Audio is at 13068 [2012-04-13 16:09:52] VERBOSE[411] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2012-04-13 16:09:52] DEBUG[411] chan_sip.c: -- Done with adding codecs to SDP [2012-04-13 16:09:52] 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:09:52] DEBUG[411] chan_sip.c: Done building SDP. Settling with this capability: 0x4 (ulaw) [2012-04-13 16:09:52] VERBOSE[411] 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=as7247e17c Call-ID: 1-589@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 Content-Type: application/sdp Content-Length: 192 v=0 o=root 153348672 153348673 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 13068 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:20 a=sendrecv <------------> [2012-04-13 16:09:52] DEBUG[411] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #3037 [2012-04-13 16:09:52] DEBUG[411] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.210.12.209:5060 [2012-04-13 16:09:52] 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-589-1-10 From: "sipp" ;tag=1 To: ;tag=as7247e17c Call-ID: 1-589@10.210.12.209 CSeq: 2 ACK Max-Forwards: 70 Authorization: Digest username="sipp",realm="asterisk",uri="sip:10.42.0.253:5060",nonce="49c063dc",response="9847440e8c5a6cc7b8363f07ebdcfb0b",algorithm=MD5 Contact: User-Agent: sipp test Content-Length: 0 <-------------> [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 0 [ 38]: ACK sip:11111@10.42.0.253:5060 SIP/2.0 [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.210.12.209:5060;branch=z9hG4bK-589-1-10 [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 2 [ 48]: From: "sipp" ;tag=1 [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 3 [ 47]: To: ;tag=as7247e17c [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 4 [ 28]: Call-ID: 1-589@10.210.12.209 [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 5 [ 11]: CSeq: 2 ACK [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 7 [156]: Authorization: Digest username="sipp",realm="asterisk",uri="sip:10.42.0.253:5060",nonce="49c063dc",response="9847440e8c5a6cc7b8363f07ebdcfb0b",algorithm=MD5 [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 8 [ 38]: Contact: [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 9 [ 21]: User-Agent: sipp test [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Header 11 [ 0]: [2012-04-13 16:09:52] VERBOSE[28626] chan_sip.c: --- (11 headers 0 lines) --- [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3037 [2012-04-13 16:09:52] DEBUG[28626] chan_sip.c: Stopping retransmission on '1-589@10.210.12.209' of Response 2: Match Found [2012-04-13 16:09:52] DEBUG[411] channel.c: Didn't receive a media frame from SIP/sipp-00000006 within 500 ms of answering. Continuing anyway [2012-04-13 16:09:52] DEBUG[411] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-13 16:09:52] DEBUG[411] pbx.c: returning an exact match-- _X. [2012-04-13 16:09:52] DEBUG[411] pbx.c: Launching 'Playback' [2012-04-13 16:09:52] VERBOSE[411] pbx.c: -- Executing [11111@test11:6] Playback("SIP/sipp-00000006", "demo-congrats") in new stack [2012-04-13 16:09:52] DEBUG[411] channel.c: Set channel SIP/sipp-00000006 to write format gsm [2012-04-13 16:09:52] DEBUG[411] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [2012-04-13 16:09:52] DEBUG[411] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [2012-04-13 16:09:52] DEBUG[411] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0xb656aed8' [2012-04-13 16:09:52] DEBUG[411] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2012-04-13 16:09:52] VERBOSE[411] file.c: -- Playing 'demo-congrats.gsm' (language 'en') [2012-04-13 16:09:57] 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-589-1-12 From: "sipp" ;tag=1 To: ;tag=as7247e17c Call-ID: 1-589@10.210.12.209 CSeq: 2 BYE Contact: Max-Forwards: 70 User-Agent: sipp test Content-Length: 0 <-------------> [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Header 0 [ 38]: BYE sip:11111@10.42.0.253:5060 SIP/2.0 [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.210.12.209:5060;branch=z9hG4bK-589-1-12 [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Header 2 [ 48]: From: "sipp" ;tag=1 [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Header 3 [ 47]: To: ;tag=as7247e17c [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Header 4 [ 28]: Call-ID: 1-589@10.210.12.209 [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Header 5 [ 11]: CSeq: 2 BYE [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Header 8 [ 21]: User-Agent: sipp test [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Header 10 [ 0]: [2012-04-13 16:09:57] VERBOSE[28626] chan_sip.c: --- (10 headers 0 lines) --- [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Ignoring SIP message because of retransmit (BYE Seqno 2, ours 2) [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Initializing initreq for method BYE - callid 1-589@10.210.12.209 [2012-04-13 16:09:57] DEBUG[28626] netsock2.c: Splitting '10.210.12.209:5060' into... [2012-04-13 16:09:57] DEBUG[28626] netsock2.c: ...host '10.210.12.209' and port '5060'. [2012-04-13 16:09:57] VERBOSE[28626] chan_sip.c: Sending to 10.210.12.209:5060 (NAT) [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Setting SIP_ALREADYGONE on dialog 1-589@10.210.12.209 [2012-04-13 16:09:57] DEBUG[28626] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb656aed8' [2012-04-13 16:09:57] VERBOSE[28626] chan_sip.c: Scheduling destruction of SIP dialog '1-589@10.210.12.209' in 32000 ms (Method: BYE) [2012-04-13 16:09:57] DEBUG[28626] chan_sip.c: Received bye, issuing owner hangup [2012-04-13 16:09:57] 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-589-1-12;received=10.210.12.209;rport=5060 From: "sipp" ;tag=1 To: ;tag=as7247e17c Call-ID: 1-589@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:09:57] 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:09:57] DEBUG[411] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-13 16:09:57] DEBUG[411] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-13 16:09:57] DEBUG[411] channel.c: Set channel SIP/sipp-00000006 to write format ulaw [2012-04-13 16:09:57] DEBUG[411] pbx.c: Spawn extension (test11,11111,6) exited non-zero on 'SIP/sipp-00000006' [2012-04-13 16:09:57] VERBOSE[411] pbx.c: == Spawn extension (test11, 11111, 6) exited non-zero on 'SIP/sipp-00000006' [2012-04-13 16:09:57] DEBUG[411] channel.c: Soft-Hanging up channel 'SIP/sipp-00000006' [2012-04-13 16:09:57] DEBUG[411] pbx.c: return at end of func [2012-04-13 16:09:57] DEBUG[411] channel.c: Hanging up channel 'SIP/sipp-00000006' [2012-04-13 16:09:57] DEBUG[411] chan_sip.c: Hanging up zombie call. Be scared. [2012-04-13 16:09:57] DEBUG[411] chan_sip.c: update_call_counter(sipp) - decrement call limit counter on hangup [2012-04-13 16:09:57] DEBUG[411] chan_sip.c: Updating call counter for incoming call [2012-04-13 16:09:57] DEBUG[411] chan_sip.c: Call from peer 'sipp' removed from call limit 10 [2012-04-13 16:09:57] DEBUG[411] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb656aed8' [2012-04-13 16:09:57] DEBUG[28604] devicestate.c: No provider found, checking channel drivers for SIP - sipp [2012-04-13 16:09:57] DEBUG[28604] chan_sip.c: Checking device state for peer sipp [2012-04-13 16:09:57] DEBUG[28604] devicestate.c: Changing state for SIP/sipp - state 5 (Unavailable) [2012-04-13 16:09:57] DEBUG[28604] devicestate.c: device 'SIP/sipp' state '5' [2012-04-13 16:09:57] 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:09:57] DEBUG[411] cdr_mysql.c: Inserting a CDR record. [2012-04-13 16:09:57] DEBUG[411] 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:09:49','\"sipp\" <1105>','1105','11111','test11','SIP/sipp-00000006','Playback','demo-congrats','8','5','ANSWERED','3','1334318989.6') [2012-04-13 16:09:57] DEBUG[28604] devicestate.c: No provider found, checking channel drivers for SIP - sipp [2012-04-13 16:09:57] DEBUG[28604] chan_sip.c: Checking device state for peer sipp [2012-04-13 16:09:57] DEBUG[28604] devicestate.c: Changing state for SIP/sipp - state 5 (Unavailable) [2012-04-13 16:09:57] DEBUG[28604] devicestate.c: device 'SIP/sipp' state '5' [2012-04-13 16:09:57] 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:09:57] DEBUG[28614] chan_iax2.c: ip callno count decremented to 3 for 1.1.1.4 [2012-04-13 16:09:57] DEBUG[28620] chan_iax2.c: schedule decrement of callno used for 1.1.1.4 in 60 seconds [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 0 [ 0]: [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Body 0 [ 0]: [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 1 [ 58]: Via: SIP/2.0/UDP 10.42.1.242:5064;branch=z9hG4bK2075277422 [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 2 [ 53]: From: "1_1106" ;tag=421474161 [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 3 [ 37]: To: "1_1106" [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 4 [ 31]: Call-ID: 1953910999@10.42.1.242 [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 5 [ 18]: CSeq: 665 REGISTER [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:09: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:09: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:09:58] DEBUG[28626] chan_sip.c: Header 9 [ 16]: Max-Forwards: 70 [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 10 [ 38]: User-Agent: Yealink SIP-T28P 2.43.0.50 [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 11 [ 13]: Expires: 3600 [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Header 13 [ 0]: [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:09:58] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 1953910999@10.42.1.242 [2012-04-13 16:09:58] DEBUG[28626] netsock2.c: Splitting '10.42.1.242:5064' into... [2012-04-13 16:09:58] DEBUG[28626] netsock2.c: ...host '10.42.1.242' and port '5064'. [2012-04-13 16:09:58] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:09:58] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:09: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:09: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:10:00] DEBUG[28626] chan_sip.c: Auto destroying SIP dialog '41932201716063-229152438629996@10.42.1.125' [2012-04-13 16:10:00] DEBUG[28626] chan_sip.c: Destroying SIP dialog 41932201716063-229152438629996@10.42.1.125 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 1 [ 85]: From: "1_1103";tag=1031c1e8-0-13c4-4f884fdb-2740228a-4f884fdb [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 2 [ 36]: To: "1_1103" [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 3 [ 51]: Call-ID: 10321aa0-0-13c4-4f884fdb-36e0000e-4f884fdb [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 4 [ 16]: CSeq: 1 REGISTER [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 5 [ 81]: Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f884fdb-ac77f2e7-22740014 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 6 [ 56]: Allow: INVITE,CANCEL,BYE,REFER,NOTIFY,SUBSCRIBE,INFO,ACK [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 7 [ 18]: user-Agent: Nateks [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 9 [ 26]: Supported: replaces,100rel [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 10 [ 49]: Contact: ;expires=70 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 12 [ 0]: [2012-04-13 16:10:02] DEBUG[28626] acl.c: For destination '10.42.1.233', our source address is '10.42.0.253'. [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.42.0.253:5060 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Allocating new SIP dialog for 10321aa0-0-13c4-4f884fdb-36e0000e-4f884fdb - REGISTER (No RTP) [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 10321aa0-0-13c4-4f884fdb-36e0000e-4f884fdb [2012-04-13 16:10:02] DEBUG[28626] netsock2.c: Splitting '10.42.1.233:5060' into... [2012-04-13 16:10:02] DEBUG[28626] netsock2.c: ...host '10.42.1.233' and port '5060'. [2012-04-13 16:10:02] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:10:02] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:10:02] 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:10:02] NOTICE[28626] chan_sip.c: Registration from '"1_1103"' failed for '10.42.1.233:5060' - No matching peer found [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 1 [ 85]: From: "1_1103";tag=1031c1e8-0-13c4-4f884fdb-2740228a-4f884fdb [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 2 [ 36]: To: "1_1103" [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 3 [ 51]: Call-ID: 10321aa0-0-13c4-4f884fdb-36e0000e-4f884fdb [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 4 [ 16]: CSeq: 2 REGISTER [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 5 [ 81]: Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f884fdb-ac77f314-69d68ec8 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 6 [ 56]: Allow: INVITE,CANCEL,BYE,REFER,NOTIFY,SUBSCRIBE,INFO,ACK [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 7 [ 18]: user-Agent: Nateks [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 9 [ 26]: Supported: replaces,100rel [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 10 [ 49]: Contact: ;expires=70 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 11 [153]: Authorization: Digest username="1_1103",realm="asterisk",nonce="4c31b6d1",uri="sip:10.42.0.253",response="6d8ed1e1f629a7ef9201efdf6a24c7fd",algorithm=MD5 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Header 13 [ 0]: [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:10:02] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 10321aa0-0-13c4-4f884fdb-36e0000e-4f884fdb [2012-04-13 16:10:02] DEBUG[28626] netsock2.c: Splitting '10.42.1.233:5060' into... [2012-04-13 16:10:02] DEBUG[28626] netsock2.c: ...host '10.42.1.233' and port '5060'. [2012-04-13 16:10:02] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:10:02] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:10:02] 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:10:02] NOTICE[28626] chan_sip.c: Registration from '"1_1103"' failed for '10.42.1.233:5060' - No matching peer found [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 1 [ 74]: Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK19232215761391429871;rport [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 2 [ 52]: From: 1_1105 ;tag=1957311506 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 3 [ 35]: To: 1_1105 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 4 [ 51]: Call-ID: 94901742010081-178072694128230@10.42.1.125 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 5 [ 16]: CSeq: 1 REGISTER [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 8 [ 11]: Expires: 60 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 9 [ 15]: Supported: path [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 10 [ 31]: User-Agent: Greenlite ATOM V2.0 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 12 [ 0]: [2012-04-13 16:10:04] DEBUG[28626] acl.c: For destination '10.42.1.125', our source address is '10.42.0.253'. [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.42.0.253:5060 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Allocating new SIP dialog for 94901742010081-178072694128230@10.42.1.125 - REGISTER (No RTP) [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 94901742010081-178072694128230@10.42.1.125 [2012-04-13 16:10:04] DEBUG[28626] netsock2.c: Splitting '10.42.1.125:5060' into... [2012-04-13 16:10:04] DEBUG[28626] netsock2.c: ...host '10.42.1.125' and port '5060'. [2012-04-13 16:10:04] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:10:04] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:10:04] 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:10:04] NOTICE[28626] chan_sip.c: Registration from '1_1105 ' failed for '10.42.1.125:5060' - No matching peer found [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 1 [ 74]: Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK24917167773255528358;rport [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 2 [ 52]: From: 1_1105 ;tag=1957311506 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 3 [ 35]: To: 1_1105 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 4 [ 51]: Call-ID: 94901742010081-178072694128230@10.42.1.125 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 5 [ 16]: CSeq: 2 REGISTER [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 7 [158]: Authorization: Digest username="1_1105", realm="asterisk", nonce="68b51659", uri="sip:10.42.0.253", response="d9002990f39690552636006fef6d134c", algorithm=MD5 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 9 [ 11]: Expires: 60 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 10 [ 15]: Supported: path [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 11 [ 31]: User-Agent: Greenlite ATOM V2.0 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Header 13 [ 0]: [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-13 16:10:04] DEBUG[28626] chan_sip.c: Initializing initreq for method REGISTER - callid 94901742010081-178072694128230@10.42.1.125 [2012-04-13 16:10:04] DEBUG[28626] netsock2.c: Splitting '10.42.1.125:5060' into... [2012-04-13 16:10:04] DEBUG[28626] netsock2.c: ...host '10.42.1.125' and port '5060'. [2012-04-13 16:10:04] DEBUG[28626] netsock2.c: Splitting '10.42.0.253' into... [2012-04-13 16:10:04] DEBUG[28626] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-13 16:10:04] 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:10:04] NOTICE[28626] chan_sip.c: Registration from '1_1105 ' failed for '10.42.1.125:5060' - No matching peer found [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 0 [ 30]: NOTIFY sip:10.42.0.253 SIP/2.0 [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-8f0b60e1 [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 2 [ 62]: From: "1_1102" ;tag=63e70cb54c3c09fdo1 [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 3 [ 21]: To: [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 4 [ 38]: Call-ID: 187087f5-d62ec7bd@10.42.1.146 [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 5 [ 18]: CSeq: 22655 NOTIFY [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 7 [ 47]: Contact: "1_1102" [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 8 [ 17]: Event: keep-alive [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 9 [ 35]: User-Agent: Linksys/SPA962-6.1.5(a) [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Header 11 [ 0]: [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [2012-04-13 16:10:05] DEBUG[28626] chan_sip.c: Got NOTIFY Event: keep-alive [2012-04-13 16:10: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:10:07] DEBUG[28622] chan_iax2.c: ip callno count incremented to 4 for 1.1.1.4 [2012-04-13 16:10:15] DEBUG[28626] chan_sip.c: Auto destroying SIP dialog '10321aa0-0-13c4-4f884fc8-26933510-4f884fc8' [2012-04-13 16:10:15] DEBUG[28626] chan_sip.c: Destroying SIP dialog 10321aa0-0-13c4-4f884fc8-26933510-4f884fc8