[2012-04-11 11:20:31] VERBOSE[29164] config.c: == Parsing '/etc/asterisk/logger.conf': [2012-04-11 11:20:31] DEBUG[29164] config.c: Parsing /etc/asterisk/logger.conf [2012-04-11 11:20:31] VERBOSE[29164] config.c: == Found [2012-04-11 11:20:31] VERBOSE[29164] logger.c: Asterisk Queue Logger restarted [2012-04-11 11:20:32] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.242:5064 ---> <-------------> [2012-04-11 11:20:32] DEBUG[1763] chan_sip.c: Header 0 [ 0]: [2012-04-11 11:20:36] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.146:5061 ---> NOTIFY sip:10.42.0.253 SIP/2.0 Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-aa9d9a84 From: "1_1102" ;tag=63e70cb54c3c09fdo1 To: Call-ID: 187087f5-d62ec7bd@10.42.1.146 CSeq: 9991 NOTIFY Max-Forwards: 70 Contact: "1_1102" Event: keep-alive User-Agent: Linksys/SPA962-6.1.5(a) Content-Length: 0 <-------------> [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Header 0 [ 30]: NOTIFY sip:10.42.0.253 SIP/2.0 [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-aa9d9a84 [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Header 2 [ 62]: From: "1_1102" ;tag=63e70cb54c3c09fdo1 [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Header 3 [ 21]: To: [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Header 4 [ 38]: Call-ID: 187087f5-d62ec7bd@10.42.1.146 [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Header 5 [ 17]: CSeq: 9991 NOTIFY [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Header 7 [ 47]: Contact: "1_1102" [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Header 8 [ 17]: Event: keep-alive [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Header 9 [ 35]: User-Agent: Linksys/SPA962-6.1.5(a) [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [2012-04-11 11:20:36] VERBOSE[1763] chan_sip.c: --- (11 headers 0 lines) --- [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: = Looking for Call ID: 187087f5-d62ec7bd@10.42.1.146 (Checking From) --From tag 63e70cb54c3c09fdo1 --To-tag [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Got NOTIFY Event: keep-alive [2012-04-11 11:20:36] VERBOSE[1763] chan_sip.c: <--- Transmitting (NAT) to 10.42.1.146:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-aa9d9a84;received=10.42.1.146;rport=5061 From: "1_1102" ;tag=63e70cb54c3c09fdo1 To: ;tag=as618cfb40 Call-ID: 187087f5-d62ec7bd@10.42.1.146 CSeq: 9991 NOTIFY Server: Asterisk PBX SVN-branch-1.8-r361040M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [2012-04-11 11:20:36] DEBUG[1763] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.42.1.146:5061 [2012-04-11 11:20:36] VERBOSE[1763] chan_sip.c: Scheduling destruction of SIP dialog '187087f5-d62ec7bd@10.42.1.146' in 32000 ms (Method: NOTIFY) [2012-04-11 11:20:36] DEBUG[1760] chan_iax2.c: ip callno count incremented to 4 for 1.1.1.4 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.233:5060 ---> INVITE sip:1102@10.42.0.253;transport=UDP SIP/2.0 From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a To: "1102" Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 CSeq: 1 INVITE Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f85690a-a122500d-335af3c user-Agent: Nateks Max-Forwards: 70 Supported: replaces,100rel Allow: INVITE,CANCEL,BYE,REFER,NOTIFY,SUBSCRIBE,INFO,ACK,UPDATE Contact: Content-Type: application/sdp Content-Length: 320 v=0 o=Nateks 2890844526 8000 IN IP4 10.42.1.233 s=IpPhone CALL c=IN IP4 10.42.1.233 t=0 0 m=audio 10026 RTP/AVP 8 0 4 18 9 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 0 [ 49]: INVITE sip:1102@10.42.0.253;transport=UDP SIP/2.0 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 1 [ 85]: From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 2 [ 32]: To: "1102" [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 3 [ 63]: Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 4 [ 14]: CSeq: 1 INVITE [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 5 [ 80]: Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f85690a-a122500d-335af3c [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 6 [ 18]: user-Agent: Nateks [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 8 [ 26]: Supported: replaces,100rel [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 9 [ 63]: Allow: INVITE,CANCEL,BYE,REFER,NOTIFY,SUBSCRIBE,INFO,ACK,UPDATE [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 10 [ 52]: Contact: [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 12 [ 19]: Content-Length: 320 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 13 [ 0]: [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 0 [ 3]: v=0 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 1 [ 43]: o=Nateks 2890844526 8000 IN IP4 10.42.1.233 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 2 [ 14]: s=IpPhone CALL [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.42.1.233 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 4 [ 5]: t=0 0 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 5 [ 36]: m=audio 10026 RTP/AVP 8 0 4 18 9 101 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 8 [ 20]: a=rtpmap:4 G723/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 9 [ 21]: a=rtpmap:18 G729/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 10 [ 20]: a=rtpmap:9 G722/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 12 [ 15]: a=fmtp:101 0-15 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 13 [ 10]: a=ptime:20 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 14 [ 10]: a=sendrecv [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: --- (13 headers 15 lines) --- [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: = Looking for Call ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 (Checking From) --From tag 1031ad48-0-13c4-4f85690a-635bf552-4f85690a --To-tag [2012-04-11 11:20:43] DEBUG[1763] acl.c: For destination '10.42.1.233', our source address is '10.42.0.253'. [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.42.0.253:5060 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Allocating new SIP dialog for 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 - INVITE (No RTP) [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2012-04-11 11:20:43] DEBUG[1763] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces,100rel" [2012-04-11 11:20:43] DEBUG[1763] sip/reqresp_parser.c: Found SIP option: -replaces- [2012-04-11 11:20:43] DEBUG[1763] sip/reqresp_parser.c: Matched SIP option: replaces [2012-04-11 11:20:43] DEBUG[1763] sip/reqresp_parser.c: Found SIP option: -100rel- [2012-04-11 11:20:43] DEBUG[1763] sip/reqresp_parser.c: Matched SIP option: 100rel [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: Splitting '10.42.1.233:5060' into... [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: ...host '10.42.1.233' and port '5060'. [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Sending to 10.42.1.233:5060 (NAT) [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Initializing initreq for method INVITE - callid 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Using INVITE request as basis request - 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: Splitting '10.42.0.253' into... [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found peer '1_1103' for '1_1103' from 10.42.1.233:5060 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: <--- Reliably Transmitting (NAT) to 10.42.1.233:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.42.1.233:5060;branch=z9hG4bK-4f85690a-a122500d-335af3c;received=10.42.1.233;rport=5060 From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a To: "1102";tag=as28277a9d Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 CSeq: 1 INVITE Server: Asterisk PBX SVN-branch-1.8-r361040M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5408f0b6" Content-Length: 0 <------------> [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #151315 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.42.1.233:5060 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Scheduling destruction of SIP dialog '10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253' in 32000 ms (Method: INVITE) [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.233:5060 ---> ACK sip:1102@10.42.0.253;transport=UDP SIP/2.0 From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a To: "1102";tag=as28277a9d Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 CSeq: 1 ACK Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f85690a-a122500d-335af3c Max-Forwards: 70 Contact: Content-Length: 0 <-------------> [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 0 [ 46]: ACK sip:1102@10.42.0.253;transport=UDP SIP/2.0 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 1 [ 85]: From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 2 [ 47]: To: "1102";tag=as28277a9d [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 3 [ 63]: Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 4 [ 11]: CSeq: 1 ACK [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 5 [ 80]: Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f85690a-a122500d-335af3c [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 7 [ 52]: Contact: [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: --- (9 headers 0 lines) --- [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: = Looking for Call ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 (Checking From) --From tag 1031ad48-0-13c4-4f85690a-635bf552-4f85690a --To-tag as28277a9d [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #151315 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Stopping retransmission on '10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253' of Response 1: Match Found [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.233:5060 ---> INVITE sip:1102@10.42.0.253;transport=UDP SIP/2.0 From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a To: "1102" Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 CSeq: 2 INVITE Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f85690a-a1225053-15f0c610 user-Agent: Nateks Max-Forwards: 70 Supported: replaces,100rel Contact: Authorization: Digest username="1_1103",realm="asterisk",nonce="5408f0b6",uri="sip:1102@10.42.0.253;transport=UDP",response="7b099c98b5ac8edffe39cc6e43e45be0",algorithm=MD5 Content-Type: application/sdp Content-Length: 320 v=0 o=Nateks 2890844526 8001 IN IP4 10.42.1.233 s=IpPhone CALL c=IN IP4 10.42.1.233 t=0 0 m=audio 10026 RTP/AVP 8 0 4 18 9 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 0 [ 49]: INVITE sip:1102@10.42.0.253;transport=UDP SIP/2.0 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 1 [ 85]: From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 2 [ 32]: To: "1102" [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 3 [ 63]: Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 4 [ 14]: CSeq: 2 INVITE [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 5 [ 81]: Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f85690a-a1225053-15f0c610 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 6 [ 18]: user-Agent: Nateks [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 8 [ 26]: Supported: replaces,100rel [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 9 [ 52]: Contact: [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 10 [172]: Authorization: Digest username="1_1103",realm="asterisk",nonce="5408f0b6",uri="sip:1102@10.42.0.253;transport=UDP",response="7b099c98b5ac8edffe39cc6e43e45be0",algorithm=MD5 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 12 [ 19]: Content-Length: 320 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 13 [ 0]: [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 0 [ 3]: v=0 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 1 [ 43]: o=Nateks 2890844526 8001 IN IP4 10.42.1.233 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 2 [ 14]: s=IpPhone CALL [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.42.1.233 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 4 [ 5]: t=0 0 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 5 [ 36]: m=audio 10026 RTP/AVP 8 0 4 18 9 101 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 8 [ 20]: a=rtpmap:4 G723/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 9 [ 21]: a=rtpmap:18 G729/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 10 [ 20]: a=rtpmap:9 G722/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 11 [ 33]: a=rtpmap:101 telephone-event/8000 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 12 [ 15]: a=fmtp:101 0-15 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 13 [ 10]: a=ptime:20 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Body 14 [ 10]: a=sendrecv [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: --- (13 headers 15 lines) --- [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: = Looking for Call ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 (Checking From) --From tag 1031ad48-0-13c4-4f85690a-635bf552-4f85690a --To-tag [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: Splitting '10.42.0.253' into... [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: Splitting '10.42.0.253' into... [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: Splitting '10.42.1.233:5060' into... [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: ...host '10.42.1.233' and port '5060'. [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Sending to 10.42.1.233:5060 (NAT) [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Initializing initreq for method INVITE - callid 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Using INVITE request as basis request - 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: Splitting '10.42.0.253' into... [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found peer '1_1103' for '1_1103' from 10.42.1.233:5060 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb775fe38' [2012-04-11 11:20:43] DEBUG[1763] res_rtp_asterisk.c: Allocated port 15814 for RTP instance '0xb775fe38' [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: RTP instance '0xb775fe38' is setup and ready to go [2012-04-11 11:20:43] DEBUG[1763] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb775fe38' [2012-04-11 11:20:43] VERBOSE[1763] netsock2.c: == Using SIP RTP CoS mark 5 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Setting NAT on RTP to On [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing session-level SDP o=Nateks 2890844526 8001 IN IP4 10.42.1.233... UNSUPPORTED. [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing session-level SDP s=IpPhone CALL... UNSUPPORTED. [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: Splitting '10.42.1.233' into... [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: ...host '10.42.1.233' and port ''. [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing session-level SDP c=IN IP4 10.42.1.233... OK. [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found RTP audio format 8 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Setting payload 8 based on m type on 0xb6be8344 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found RTP audio format 0 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Setting payload 0 based on m type on 0xb6be8344 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found RTP audio format 4 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Setting payload 4 based on m type on 0xb6be8344 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found RTP audio format 18 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Setting payload 18 based on m type on 0xb6be8344 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found RTP audio format 9 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Setting payload 9 based on m type on 0xb6be8344 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found RTP audio format 101 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Setting payload 101 based on m type on 0xb6be8344 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found audio description format PCMA for ID 8 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found audio description format PCMU for ID 0 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found audio description format G723 for ID 4 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:4 G723/8000... OK. [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found audio description format G729 for ID 18 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found audio description format G722 for ID 9 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Found audio description format telephone-event for ID 101 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Incorporating payload 0 on 0xb6be8344 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Incorporating payload 4 on 0xb6be8344 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Incorporating payload 8 on 0xb6be8344 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Incorporating payload 9 on 0xb6be8344 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Incorporating payload 18 on 0xb6be8344 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Incorporating payload 101 on 0xb6be8344 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x110d (g723|ulaw|alaw|g729|g722)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xc (ulaw|alaw) [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [2012-04-11 11:20:43] DEBUG[1763] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb775fe38' [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Peer audio RTP is at port 10.42.1.233:10026 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Copying payload 0 from 0xb6be8344 to 0xb775ffe4 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Copying payload 4 from 0xb6be8344 to 0xb775ffe4 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Copying payload 8 from 0xb6be8344 to 0xb775ffe4 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Copying payload 9 from 0xb6be8344 to 0xb775ffe4 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Copying payload 18 from 0xb6be8344 to 0xb775ffe4 [2012-04-11 11:20:43] DEBUG[1763] rtp_engine.c: Copying payload 101 from 0xb6be8344 to 0xb775ffe4 [2012-04-11 11:20:43] DEBUG[1763] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb775fe38' [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Checking SIP call limits for device 1103 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Updating call counter for incoming call [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Call from peer '1_1103' is 1 out of 10 [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1103 [2012-04-11 11:20:43] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1103 [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: Changing state for SIP/1_1103 - state 2 (In use) [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: device 'SIP/1_1103' state '2' [2012-04-11 11:20:43] DEBUG[1773] app_queue.c: Device 'SIP/1_1103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: Splitting '10.42.0.253' into... [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: Splitting '10.42.0.253' into... [2012-04-11 11:20:43] DEBUG[1763] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: Looking for 1102 in test10 (domain 10.42.0.253) [2012-04-11 11:20:43] DEBUG[1763] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:43] DEBUG[1763] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: *** Our native formats are 0x8 (alaw) [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw) [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: This channel will not be able to handle video. [2012-04-11 11:20:43] DEBUG[1763] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:43] DEBUG[1763] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: build_route: Contact hop: [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: list_route: hop: [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: SIP/1_1103-00000020: New call is still down.... Trying... [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: <--- Transmitting (NAT) to 10.42.1.233:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.42.1.233:5060;branch=z9hG4bK-4f85690a-a1225053-15f0c610;received=10.42.1.233;rport=5060 From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a To: "1102" Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 CSeq: 2 INVITE Server: Asterisk PBX SVN-branch-1.8-r361040M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Contact: Content-Length: 0 <------------> [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.42.1.233:5060 [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1103 [2012-04-11 11:20:43] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1103 [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: Changing state for SIP/1_1103 - state 2 (In use) [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: device 'SIP/1_1103' state '2' [2012-04-11 11:20:43] DEBUG[1773] app_queue.c: Device 'SIP/1_1103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:43] DEBUG[29279] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:43] DEBUG[29279] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:43] DEBUG[29279] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:43] DEBUG[29279] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:43] DEBUG[29279] pbx.c: Result of 'EXTEN' is '1102' [2012-04-11 11:20:43] DEBUG[29279] pbx.c: Launching 'Dial' [2012-04-11 11:20:43] VERBOSE[29279] pbx.c: -- Executing [1102@test10:1] Dial("SIP/1_1103-00000020", "SIP/1_1102,60,t") in new stack [2012-04-11 11:20:43] DEBUG[29279] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:43] DEBUG[29279] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw) [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Allocating new SIP dialog for 527695b1648a1ac8543bc9fb25fcb43c@127.0.0.1:5060 - INVITE (No RTP) [2012-04-11 11:20:43] DEBUG[29279] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb65b61e0' [2012-04-11 11:20:43] DEBUG[29279] res_rtp_asterisk.c: Allocated port 16120 for RTP instance '0xb65b61e0' [2012-04-11 11:20:43] DEBUG[29279] rtp_engine.c: RTP instance '0xb65b61e0' is setup and ready to go [2012-04-11 11:20:43] DEBUG[29279] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb65b61e0' [2012-04-11 11:20:43] VERBOSE[29279] netsock2.c: == Using SIP RTP CoS mark 5 [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Setting NAT on RTP to On [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: OBPROXY: Not applying OBproxy to this call [2012-04-11 11:20:43] DEBUG[29279] acl.c: For destination '10.42.1.146', our source address is '10.42.0.253'. [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.42.0.253:5060 [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: *** Our native formats are 0x8 (alaw) [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw) [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: This channel will not be able to handle video. [2012-04-11 11:20:43] DEBUG[29279] pbx.c: Nothing strange about this match [2012-04-11 11:20:43] DEBUG[29279] pbx.c: returning an exact match-- first found-- h [2012-04-11 11:20:43] DEBUG[29279] rtp_engine.c: Seeded SDP of 'SIP/1_1102-00000021' with that of 'SIP/1_1103-00000020' [2012-04-11 11:20:43] DEBUG[29279] channel.c: Not copying variable DIALEDTIME. [2012-04-11 11:20:43] DEBUG[29279] channel.c: Not copying variable ANSWEREDTIME. [2012-04-11 11:20:43] DEBUG[29279] channel.c: Not copying variable DIALEDPEERNAME. [2012-04-11 11:20:43] DEBUG[29279] channel.c: Not copying variable DIALEDPEERNUMBER. [2012-04-11 11:20:43] DEBUG[29279] channel.c: Not copying variable DIALSTATUS. [2012-04-11 11:20:43] DEBUG[29279] channel.c: Not copying variable SIPCALLID. [2012-04-11 11:20:43] DEBUG[29279] channel.c: Not copying variable SIPDOMAIN. [2012-04-11 11:20:43] DEBUG[29279] channel.c: Not copying variable SIPURI. [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Outgoing Call for 1102 [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Updating call counter for outgoing call [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Call to peer '1_1102' is 1 out of 10 [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1102 [2012-04-11 11:20:43] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1102 [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: Changing state for SIP/1_1102 - state 6 (Ringing) [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: device 'SIP/1_1102' state '6' [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: False Text flag: False [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [2012-04-11 11:20:43] DEBUG[1773] app_queue.c: Device 'SIP/1_1102' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2012-04-11 11:20:43] VERBOSE[29279] chan_sip.c: Audio is at 16120 [2012-04-11 11:20:43] VERBOSE[29279] chan_sip.c: Adding codec 0x8 (alaw) to SDP [2012-04-11 11:20:43] VERBOSE[29279] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2012-04-11 11:20:43] VERBOSE[29279] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: -- Done with adding codecs to SDP [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Initializing initreq for method INVITE - callid 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 0 [ 42]: INVITE sip:1_1102@10.42.1.146:5061 SIP/2.0 [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK1489e091;rport [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 3 [ 52]: From: "1_1103" ;tag=as268d8acc [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 4 [ 33]: To: [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 5 [ 36]: Contact: [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 6 [ 58]: Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 8 [ 48]: User-Agent: Asterisk PBX SVN-branch-1.8-r361040M [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 9 [ 35]: Date: Wed, 11 Apr 2012 07:20:43 GMT [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 11 [ 19]: Supported: replaces [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [2012-04-11 11:20:43] VERBOSE[29279] chan_sip.c: Reliably Transmitting (NAT) to 10.42.1.146:5061: INVITE sip:1_1102@10.42.1.146:5061 SIP/2.0 Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK1489e091;rport Max-Forwards: 70 From: "1_1103" ;tag=as268d8acc To: Contact: Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-branch-1.8-r361040M Date: Wed, 11 Apr 2012 07:20:43 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Type: application/sdp Content-Length: 272 v=0 o=root 642645217 642645217 IN IP4 10.42.0.253 s=Asterisk PBX SVN-branch-1.8-r361040M c=IN IP4 10.42.0.253 t=0 0 m=audio 16120 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #151318 [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.42.1.146:5061 [2012-04-11 11:20:43] VERBOSE[29279] app_dial.c: -- Called SIP/1_1102 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.146:5061 ---> SIP/2.0 100 Trying To: From: "1_1103" ;tag=as268d8acc Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK1489e091 Server: Linksys/SPA962-6.1.5(a) Content-Length: 0 <-------------> [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 1 [ 33]: To: [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 2 [ 52]: From: "1_1103" ;tag=as268d8acc [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 3 [ 58]: Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 5 [ 56]: Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK1489e091 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 6 [ 31]: Server: Linksys/SPA962-6.1.5(a) [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: --- (8 headers 0 lines) --- [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: = Looking for Call ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 (Checking To) --From tag as268d8acc --To-tag [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: *** SIP TIMER: Cancelling retransmission #151318 - INVITE (got response) [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060' Request 102: Found [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: SIP response 100 to standard invite [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.146:5061 ---> SIP/2.0 180 Ringing To: ;tag=619381ced398c25ei1 From: "1_1103" ;tag=as268d8acc Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK1489e091 Contact: "1_1102" Server: Linksys/SPA962-6.1.5(a) Content-Length: 0 <-------------> [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 1 [ 56]: To: ;tag=619381ced398c25ei1 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 2 [ 52]: From: "1_1103" ;tag=as268d8acc [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 3 [ 58]: Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 5 [ 56]: Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK1489e091 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 6 [ 47]: Contact: "1_1102" [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 7 [ 31]: Server: Linksys/SPA962-6.1.5(a) [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: --- (9 headers 0 lines) --- [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: = Looking for Call ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 (Checking To) --From tag as268d8acc --To-tag 619381ced398c25ei1 [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060' Request 102: Found [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: SIP response 180 to standard invite [2012-04-11 11:20:43] DEBUG[1763] chan_sip.c: build_route: Contact hop: "1_1102" [2012-04-11 11:20:43] VERBOSE[1763] chan_sip.c: list_route: hop: [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1102 [2012-04-11 11:20:43] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1102 [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: Changing state for SIP/1_1102 - state 6 (Ringing) [2012-04-11 11:20:43] DEBUG[1741] devicestate.c: device 'SIP/1_1102' state '6' [2012-04-11 11:20:43] DEBUG[1773] app_queue.c: Device 'SIP/1_1102' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2012-04-11 11:20:43] VERBOSE[29279] app_dial.c: -- SIP/1_1102-00000021 is ringing [2012-04-11 11:20:43] DEBUG[29279] rtp_engine.c: Setting early bridge SDP of 'SIP/1_1103-00000020' with that of 'SIP/1_1102-00000021' [2012-04-11 11:20:43] VERBOSE[29279] chan_sip.c: <--- Transmitting (NAT) to 10.42.1.233:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.42.1.233:5060;branch=z9hG4bK-4f85690a-a1225053-15f0c610;received=10.42.1.233;rport=5060 From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a To: "1102";tag=as23cb731a Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 CSeq: 2 INVITE Server: Asterisk PBX SVN-branch-1.8-r361040M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Contact: Content-Length: 0 <------------> [2012-04-11 11:20:43] DEBUG[29279] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 10.42.1.233:5060 [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.146:5061 ---> SIP/2.0 200 OK To: ;tag=619381ced398c25ei1 From: "1_1103" ;tag=as268d8acc Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 CSeq: 102 INVITE Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK1489e091 Contact: "1_1102" Server: Linksys/SPA962-6.1.5(a) Content-Length: 208 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 14997333 14997333 IN IP4 10.42.1.146 s=- c=IN IP4 10.42.1.146 t=0 0 m=audio 16438 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 1 [ 56]: To: ;tag=619381ced398c25ei1 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 2 [ 52]: From: "1_1103" ;tag=as268d8acc [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 3 [ 58]: Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 4 [ 16]: CSeq: 102 INVITE [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 5 [ 56]: Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK1489e091 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 6 [ 47]: Contact: "1_1102" [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 7 [ 31]: Server: Linksys/SPA962-6.1.5(a) [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 8 [ 19]: Content-Length: 208 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 9 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 10 [ 19]: Supported: replaces [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 12 [ 0]: [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Body 0 [ 3]: v=0 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Body 1 [ 40]: o=- 14997333 14997333 IN IP4 10.42.1.146 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Body 2 [ 3]: s=- [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.42.1.146 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Body 4 [ 5]: t=0 0 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Body 5 [ 27]: m=audio 16438 RTP/AVP 8 101 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-15 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Body 9 [ 10]: a=ptime:30 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Body 10 [ 10]: a=sendrecv [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: --- (12 headers 11 lines) --- [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: = Looking for Call ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 (Checking To) --From tag as268d8acc --To-tag 619381ced398c25ei1 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Acked pending invite 102 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Stopping retransmission on '00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060' of Request 102: Match Found [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: SIP response 200 to standard invite [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Processing session-level SDP o=- 14997333 14997333 IN IP4 10.42.1.146... UNSUPPORTED. [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [2012-04-11 11:20:44] DEBUG[1763] netsock2.c: Splitting '10.42.1.146' into... [2012-04-11 11:20:44] DEBUG[1763] netsock2.c: ...host '10.42.1.146' and port ''. [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Processing session-level SDP c=IN IP4 10.42.1.146... OK. [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: Found RTP audio format 8 [2012-04-11 11:20:44] DEBUG[1763] rtp_engine.c: Setting payload 8 based on m type on 0xb6be8454 [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: Found RTP audio format 101 [2012-04-11 11:20:44] DEBUG[1763] rtp_engine.c: Setting payload 101 based on m type on 0xb6be8454 [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: Found audio description format PCMA for ID 8 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: Found audio description format telephone-event for ID 101 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2012-04-11 11:20:44] DEBUG[1763] rtp_engine.c: Incorporating payload 8 on 0xb6be8454 [2012-04-11 11:20:44] DEBUG[1763] rtp_engine.c: Incorporating payload 101 on 0xb6be8454 [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [2012-04-11 11:20:44] DEBUG[1763] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb65b61e0' [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: Peer audio RTP is at port 10.42.1.146:16438 [2012-04-11 11:20:44] DEBUG[1763] rtp_engine.c: Copying payload 8 from 0xb6be8454 to 0xb65b638c [2012-04-11 11:20:44] DEBUG[1763] rtp_engine.c: Copying payload 101 from 0xb6be8454 to 0xb65b638c [2012-04-11 11:20:44] DEBUG[1763] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb65b61e0' [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: We're settling with these formats: 0x8 (alaw) [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: We have an owner, now see if we need to change this call [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Updating call counter for outgoing call [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: build_route: Contact hop: "1_1102" [2012-04-11 11:20:44] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1102 [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: list_route: hop: [2012-04-11 11:20:44] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1102 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Strict routing enforced for session 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 [2012-04-11 11:20:44] DEBUG[1741] devicestate.c: Changing state for SIP/1_1102 - state 2 (In use) [2012-04-11 11:20:44] DEBUG[1741] devicestate.c: device 'SIP/1_1102' state '2' [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: set_destination: Parsing for address/port to send to [2012-04-11 11:20:44] DEBUG[1773] app_queue.c: Device 'SIP/1_1102' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:44] DEBUG[1763] netsock2.c: Splitting '10.42.1.146:5061' into... [2012-04-11 11:20:44] DEBUG[1763] netsock2.c: ...host '10.42.1.146' and port '5061'. [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: set_destination: set destination to 10.42.1.146:5061 [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: Transmitting (NAT) to 10.42.1.146:5061: ACK sip:1_1102@10.42.1.146:5061 SIP/2.0 Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK1d49ab55;rport Max-Forwards: 70 From: "1_1103" ;tag=as268d8acc To: ;tag=619381ced398c25ei1 Contact: Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-branch-1.8-r361040M Content-Length: 0 --- [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Trying to put 'ACK sip:1_1' onto UDP socket destined for 10.42.1.146:5061 [2012-04-11 11:20:44] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1102 [2012-04-11 11:20:44] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1102 [2012-04-11 11:20:44] DEBUG[1741] devicestate.c: Changing state for SIP/1_1102 - state 2 (In use) [2012-04-11 11:20:44] DEBUG[1741] devicestate.c: device 'SIP/1_1102' state '2' [2012-04-11 11:20:44] DEBUG[1773] app_queue.c: Device 'SIP/1_1102' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:44] VERBOSE[29279] app_dial.c: -- SIP/1_1102-00000021 answered SIP/1_1103-00000020 [2012-04-11 11:20:44] DEBUG[29279] chan_sip.c: SIP answering channel: SIP/1_1103-00000020 [2012-04-11 11:20:44] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1103 [2012-04-11 11:20:44] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:44] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1103 [2012-04-11 11:20:44] DEBUG[1741] devicestate.c: Changing state for SIP/1_1103 - state 2 (In use) [2012-04-11 11:20:44] DEBUG[29279] chan_sip.c: Setting framing from config on incoming call [2012-04-11 11:20:44] DEBUG[1741] devicestate.c: device 'SIP/1_1103' state '2' [2012-04-11 11:20:44] DEBUG[1773] app_queue.c: Device 'SIP/1_1103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:44] DEBUG[29279] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [2012-04-11 11:20:44] DEBUG[29279] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [2012-04-11 11:20:44] VERBOSE[29279] chan_sip.c: Audio is at 15814 [2012-04-11 11:20:44] VERBOSE[29279] chan_sip.c: Adding codec 0x8 (alaw) to SDP [2012-04-11 11:20:44] VERBOSE[29279] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2012-04-11 11:20:44] VERBOSE[29279] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2012-04-11 11:20:44] DEBUG[29279] chan_sip.c: -- Done with adding codecs to SDP [2012-04-11 11:20:44] DEBUG[29279] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [2012-04-11 11:20:44] VERBOSE[29279] chan_sip.c: <--- Reliably Transmitting (NAT) to 10.42.1.233:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.42.1.233:5060;branch=z9hG4bK-4f85690a-a1225053-15f0c610;received=10.42.1.233;rport=5060 From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a To: "1102";tag=as23cb731a Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 CSeq: 2 INVITE Server: Asterisk PBX SVN-branch-1.8-r361040M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Contact: Content-Type: application/sdp Content-Length: 274 v=0 o=root 1069460084 1069460084 IN IP4 10.42.0.253 s=Asterisk PBX SVN-branch-1.8-r361040M c=IN IP4 10.42.0.253 t=0 0 m=audio 15814 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [2012-04-11 11:20:44] DEBUG[29279] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #151321 [2012-04-11 11:20:44] DEBUG[29279] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.42.1.233:5060 [2012-04-11 11:20:44] DEBUG[29279] features.c: bridge answer set, chan answer set [2012-04-11 11:20:44] DEBUG[29279] features.c: Removing dialed interfaces datastore on SIP/1_1102-00000021 since we're bridging [2012-04-11 11:20:44] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:44] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:44] DEBUG[29279] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [2012-04-11 11:20:44] DEBUG[29279] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [2012-04-11 11:20:44] DEBUG[29279] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0xb775fe38' [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.233:5060 ---> ACK sip:1102@10.42.0.253:5060 SIP/2.0 From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a To: "1102";tag=as23cb731a Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 CSeq: 2 ACK Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f85690b-a12256a1-15207422 Max-Forwards: 70 Contact: Authorization: Digest username="1_1103",realm="asterisk",nonce="5408f0b6",uri="sip:1102@10.42.0.253;transport=UDP",response="7b099c98b5ac8edffe39cc6e43e45be0",algorithm=MD5 Content-Length: 0 <-------------> [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 0 [ 37]: ACK sip:1102@10.42.0.253:5060 SIP/2.0 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 1 [ 85]: From: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 2 [ 47]: To: "1102";tag=as23cb731a [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 3 [ 63]: Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 4 [ 11]: CSeq: 2 ACK [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 5 [ 81]: Via: SIP/2.0/UDP 10.42.1.233:5060;rport;branch=z9hG4bK-4f85690b-a12256a1-15207422 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 7 [ 52]: Contact: [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 8 [172]: Authorization: Digest username="1_1103",realm="asterisk",nonce="5408f0b6",uri="sip:1102@10.42.0.253;transport=UDP",response="7b099c98b5ac8edffe39cc6e43e45be0",algorithm=MD5 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [2012-04-11 11:20:44] VERBOSE[1763] chan_sip.c: --- (10 headers 0 lines) --- [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: = Looking for Call ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 (Checking From) --From tag 1031ad48-0-13c4-4f85690a-635bf552-4f85690a --To-tag as23cb731a [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #151321 [2012-04-11 11:20:44] DEBUG[1763] chan_sip.c: Stopping retransmission on '10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253' of Response 2: Match Found [2012-04-11 11:20:44] DEBUG[29279] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [2012-04-11 11:20:44] DEBUG[29279] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 42 (*), at 10.42.1.146:16438 [2012-04-11 11:20:45] DEBUG[29279] channel.c: Got DTMF begin on channel (SIP/1_1102-00000021) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] channel.c: Bridge stops bridging channels SIP/1_1103-00000020 and SIP/1_1102-00000021 [2012-04-11 11:20:45] DEBUG[29279] features.c: Not passing DTMF through, since it may be a feature code [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 42 (*), at 10.42.1.146:16438 [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4) [2012-04-11 11:20:45] DEBUG[29279] channel.c: Got DTMF end on channel (SIP/1_1102-00000021) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] channel.c: Bridge stops bridging channels SIP/1_1103-00000020 and SIP/1_1102-00000021 [2012-04-11 11:20:45] DEBUG[29279] features.c: Feature interpret: chan=SIP/1_1103-00000020, peer=SIP/1_1102-00000021, code=*, sense=2, features=2, dynamic=# [2012-04-11 11:20:45] DEBUG[29279] features.c: Set feature timer to 1500 ms [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 48 (0), at 10.42.1.146:16438 [2012-04-11 11:20:45] DEBUG[29279] channel.c: Got DTMF begin on channel (SIP/1_1102-00000021) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] channel.c: Bridge stops bridging channels SIP/1_1103-00000020 and SIP/1_1102-00000021 [2012-04-11 11:20:45] DEBUG[29279] features.c: Not passing DTMF through, since it may be a feature code [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:45] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:46] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:46] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 48 (0), at 10.42.1.146:16438 [2012-04-11 11:20:46] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:46] DEBUG[29279] channel.c: Got DTMF end on channel (SIP/1_1102-00000021) [2012-04-11 11:20:46] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:46] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:46] DEBUG[29279] channel.c: Bridge stops bridging channels SIP/1_1103-00000020 and SIP/1_1102-00000021 [2012-04-11 11:20:46] DEBUG[29279] features.c: Feature interpret: chan=SIP/1_1103-00000020, peer=SIP/1_1102-00000021, code=*0, sense=2, features=2, dynamic=# [2012-04-11 11:20:46] DEBUG[29279] features.c: Feature detected: fname=Attended Transfer sname=atxfer exten=*0 [2012-04-11 11:20:46] DEBUG[29279] features.c: Executing Attended Transfer SIP/1_1103-00000020, SIP/1_1102-00000021 (sense=2) [2012-04-11 11:20:46] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:46] DEBUG[29279] res_musiconhold.c: Music on Hold class 'default' not found in memory [2012-04-11 11:20:46] DEBUG[29279] res_config_mysql.c: MySQL RealTime: Connection okay. [2012-04-11 11:20:46] DEBUG[29279] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM musiconhold_realtime WHERE name = 'default' [2012-04-11 11:20:46] DEBUG[29279] res_musiconhold.c: Scanning '/var/lib/asterisk/sounds/welltime/moh/3' for files for class 'default' [2012-04-11 11:20:46] VERBOSE[29279] res_musiconhold.c: -- Started music on hold, class 'default', on SIP/1_1103-00000020 [2012-04-11 11:20:46] DEBUG[29279] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2012-04-11 11:20:46] DEBUG[29279] channel.c: Set channel SIP/1_1102-00000021 to write format slin [2012-04-11 11:20:46] DEBUG[29279] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2012-04-11 11:20:46] VERBOSE[29279] file.c: -- Playing 'pbx-transfer.slin' (language 'ru') [2012-04-11 11:20:46] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:46] DEBUG[27754] res_musiconhold.c: SIP/1_1103-00000020 Opened file 0 '/var/lib/asterisk/sounds/welltime/moh/3/2' [2012-04-11 11:20:46] DEBUG[27754] res_rtp_asterisk.c: Difference is 656, ms is 102 [2012-04-11 11:20:46] DEBUG[29279] channel.c: Scheduling timer at (98 requested / 98 actual) timer ticks per second [2012-04-11 11:20:46] DEBUG[29279] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-11 11:20:46] DEBUG[29279] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-11 11:20:46] DEBUG[29279] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-11 11:20:46] DEBUG[29279] channel.c: Set channel SIP/1_1102-00000021 to write format alaw [2012-04-11 11:20:46] DEBUG[29279] channel.c: Set channel SIP/1_1102-00000021 to write format slin [2012-04-11 11:20:46] DEBUG[29279] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2012-04-11 11:20:46] DEBUG[1751] chan_iax2.c: ip callno count decremented to 3 for 1.1.1.4 [2012-04-11 11:20:46] DEBUG[1752] chan_iax2.c: schedule decrement of callno used for 1.1.1.4 in 60 seconds [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 49 (1), at 10.42.1.146:16438 [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 49 (1), at 10.42.1.146:16438 [2012-04-11 11:20:47] DEBUG[29279] channel.c: Set channel SIP/1_1102-00000021 to write format alaw [2012-04-11 11:20:47] DEBUG[29279] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-11 11:20:47] DEBUG[29279] pbx.c: returning a canmatch/matchmore--- str=1 [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 49 (1), at 10.42.1.146:16438 [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 49 (1), at 10.42.1.146:16438 [2012-04-11 11:20:47] DEBUG[29279] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:47] DEBUG[29279] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000001 (len = 4) [2012-04-11 11:20:47] DEBUG[1763] chan_sip.c: Auto destroying SIP dialog '383667564242908804541da72aec6efc@10.42.0.253:5060' [2012-04-11 11:20:47] DEBUG[1763] chan_sip.c: Destroying SIP dialog 383667564242908804541da72aec6efc@10.42.0.253:5060 [2012-04-11 11:20:47] VERBOSE[1763] chan_sip.c: Really destroying SIP dialog '383667564242908804541da72aec6efc@10.42.0.253:5060' Method: BYE [2012-04-11 11:20:47] DEBUG[1763] rtp_engine.c: Destroyed RTP instance '0xb65eb1b0' [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 48 (0), at 10.42.1.146:16438 [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 48 (0), at 10.42.1.146:16438 [2012-04-11 11:20:48] DEBUG[29279] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:48] DEBUG[29279] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000000 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 53 (5), at 10.42.1.146:16438 [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 53 (5), at 10.42.1.146:16438 [2012-04-11 11:20:48] DEBUG[29279] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:48] DEBUG[29279] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [2012-04-11 11:20:48] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 00000005 (len = 4) [2012-04-11 11:20:49] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [2012-04-11 11:20:49] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 35 (#), at 10.42.1.146:16438 [2012-04-11 11:20:49] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [2012-04-11 11:20:49] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [2012-04-11 11:20:49] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [2012-04-11 11:20:49] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [2012-04-11 11:20:49] DEBUG[29279] res_rtp_asterisk.c: Sending dtmf: 35 (#), at 10.42.1.146:16438 [2012-04-11 11:20:49] DEBUG[29279] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:49] DEBUG[29279] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:49] DEBUG[29279] features.c: Checking if 1105@test10 is a parking exten [2012-04-11 11:20:49] DEBUG[29279] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:49] DEBUG[29279] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:49] DEBUG[29279] channel.c: Not copying variable BRIDGEPVTCALLID. [2012-04-11 11:20:49] DEBUG[29279] channel.c: Not copying variable BRIDGEPEER. [2012-04-11 11:20:49] DEBUG[29279] channel.c: Not copying variable DIALEDPEERNUMBER. [2012-04-11 11:20:49] DEBUG[29279] channel.c: Not copying variable SIPCALLID. [2012-04-11 11:20:49] DEBUG[29279] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:49] DEBUG[29279] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:49] DEBUG[29280] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:49] DEBUG[29280] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:49] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [2012-04-11 11:20:49] DEBUG[29279] res_rtp_asterisk.c: - RTP 2833 Event: 0000000b (len = 4) [2012-04-11 11:20:49] DEBUG[29280] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:49] DEBUG[29280] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:49] DEBUG[29280] pbx.c: Result of 'EXTEN' is '1105' [2012-04-11 11:20:49] DEBUG[29280] pbx.c: Launching 'Dial' [2012-04-11 11:20:49] VERBOSE[29280] pbx.c: -- Executing [1105@test10:1] Dial("Local/1105@test10-3545;2", "SIP/1_1105,60,t") in new stack [2012-04-11 11:20:49] DEBUG[29280] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:49] DEBUG[29280] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw) [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Allocating new SIP dialog for 19d98710632dc68e15905e612511faf7@127.0.0.1:5060 - INVITE (No RTP) [2012-04-11 11:20:49] DEBUG[29280] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb65eb1b0' [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: Allocated port 19526 for RTP instance '0xb65eb1b0' [2012-04-11 11:20:49] DEBUG[29280] rtp_engine.c: RTP instance '0xb65eb1b0' is setup and ready to go [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb65eb1b0' [2012-04-11 11:20:49] VERBOSE[29280] netsock2.c: == Using SIP RTP CoS mark 5 [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Setting NAT on RTP to On [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: OBPROXY: Not applying OBproxy to this call [2012-04-11 11:20:49] DEBUG[29280] acl.c: For destination '10.42.1.125', our source address is '10.42.0.253'. [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.42.0.253:5060 [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: *** Our native formats are 0x8 (alaw) [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw) [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: This channel will not be able to handle video. [2012-04-11 11:20:49] DEBUG[29280] pbx.c: Nothing strange about this match [2012-04-11 11:20:49] DEBUG[29280] pbx.c: returning an exact match-- first found-- h [2012-04-11 11:20:49] DEBUG[29280] rtp_engine.c: Can't find native functions for channel 'Local/1105@test10-3545;2' [2012-04-11 11:20:49] DEBUG[29280] rtp_engine.c: Seeded SDP of 'SIP/1_1105-00000022' with that of 'Local/1105@test10-3545;2' [2012-04-11 11:20:49] DEBUG[29280] channel.c: Not copying variable DIALEDTIME. [2012-04-11 11:20:49] DEBUG[29280] channel.c: Not copying variable ANSWEREDTIME. [2012-04-11 11:20:49] DEBUG[29280] channel.c: Not copying variable DIALEDPEERNAME. [2012-04-11 11:20:49] DEBUG[29280] channel.c: Not copying variable DIALEDPEERNUMBER. [2012-04-11 11:20:49] DEBUG[29280] channel.c: Not copying variable DIALSTATUS. [2012-04-11 11:20:49] DEBUG[29280] channel.c: Not copying variable TRANSFERERNAME. [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Outgoing Call for 1105 [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Updating call counter for outgoing call [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Call to peer '1_1105' is 1 out of 10 [2012-04-11 11:20:49] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1105 [2012-04-11 11:20:49] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1105 [2012-04-11 11:20:49] DEBUG[1741] devicestate.c: Changing state for SIP/1_1105 - state 6 (Ringing) [2012-04-11 11:20:49] DEBUG[1741] devicestate.c: device 'SIP/1_1105' state '6' [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: False Text flag: False [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [2012-04-11 11:20:49] VERBOSE[29280] chan_sip.c: Audio is at 19526 [2012-04-11 11:20:49] DEBUG[1773] app_queue.c: Device 'SIP/1_1105' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2012-04-11 11:20:49] VERBOSE[29280] chan_sip.c: Adding codec 0x8 (alaw) to SDP [2012-04-11 11:20:49] VERBOSE[29280] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [2012-04-11 11:20:49] VERBOSE[29280] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: -- Done with adding codecs to SDP [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw) [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Initializing initreq for method INVITE - callid 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 0 [ 42]: INVITE sip:1_1105@10.42.1.125:5060 SIP/2.0 [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK4c814703;rport [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 3 [ 50]: From: "1102" ;tag=as4fa1fb25 [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 4 [ 33]: To: [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 5 [ 36]: Contact: [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 6 [ 58]: Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 8 [ 48]: User-Agent: Asterisk PBX SVN-branch-1.8-r361040M [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 9 [ 35]: Date: Wed, 11 Apr 2012 07:20:49 GMT [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 11 [ 19]: Supported: replaces [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [2012-04-11 11:20:49] VERBOSE[29280] chan_sip.c: Reliably Transmitting (NAT) to 10.42.1.125:5060: INVITE sip:1_1105@10.42.1.125:5060 SIP/2.0 Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK4c814703;rport Max-Forwards: 70 From: "1102" ;tag=as4fa1fb25 To: Contact: Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-branch-1.8-r361040M Date: Wed, 11 Apr 2012 07:20:49 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Type: application/sdp Content-Length: 274 v=0 o=root 1268314558 1268314558 IN IP4 10.42.0.253 s=Asterisk PBX SVN-branch-1.8-r361040M c=IN IP4 10.42.0.253 t=0 0 m=audio 19526 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #151324 [2012-04-11 11:20:49] DEBUG[29280] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.42.1.125:5060 [2012-04-11 11:20:49] VERBOSE[29280] app_dial.c: -- Called SIP/1_1105 [2012-04-11 11:20:49] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.125:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK4c814703;rport From: "1102" ;tag=as4fa1fb25 To: Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 CSeq: 102 INVITE Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE Content-Length: 0 <-------------> [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK4c814703;rport [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 2 [ 50]: From: "1102" ;tag=as4fa1fb25 [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 3 [ 33]: To: [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 4 [ 58]: Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 6 [ 85]: Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [2012-04-11 11:20:49] VERBOSE[1763] chan_sip.c: --- (8 headers 0 lines) --- [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: = Looking for Call ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 (Checking To) --From tag as4fa1fb25 --To-tag [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: *** SIP TIMER: Cancelling retransmission #151324 - INVITE (got response) [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060' Request 102: Found [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: SIP response 100 to standard invite [2012-04-11 11:20:49] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.125:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK4c814703;rport From: "1102" ;tag=as4fa1fb25 To: ;tag=302594275 Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 CSeq: 102 INVITE Contact: Server: Greenlite ATOM V2.0 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE Content-Length: 0 <-------------> [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 0 [ 19]: SIP/2.0 180 Ringing [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK4c814703;rport [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 2 [ 50]: From: "1102" ;tag=as4fa1fb25 [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 3 [ 47]: To: ;tag=302594275 [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 4 [ 58]: Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 7 [ 27]: Server: Greenlite ATOM V2.0 [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 8 [ 85]: Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [2012-04-11 11:20:49] VERBOSE[1763] chan_sip.c: --- (10 headers 0 lines) --- [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: = Looking for Call ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 (Checking To) --From tag as4fa1fb25 --To-tag 302594275 [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060' Request 102: Found [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: SIP response 180 to standard invite [2012-04-11 11:20:49] DEBUG[1763] chan_sip.c: build_route: Contact hop: [2012-04-11 11:20:49] VERBOSE[1763] chan_sip.c: list_route: hop: [2012-04-11 11:20:49] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1105 [2012-04-11 11:20:49] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1105 [2012-04-11 11:20:49] VERBOSE[29280] app_dial.c: -- SIP/1_1105-00000022 is ringing [2012-04-11 11:20:49] DEBUG[1741] devicestate.c: Changing state for SIP/1_1105 - state 6 (Ringing) [2012-04-11 11:20:49] DEBUG[1741] devicestate.c: device 'SIP/1_1105' state '6' [2012-04-11 11:20:49] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for Local - 1105@test10 [2012-04-11 11:20:49] VERBOSE[29279] features.c: -- Local/1105@test10-3545;1 is ringing [2012-04-11 11:20:49] DEBUG[29279] channel.c: Driver for channel 'SIP/1_1102-00000021' does not support indication 3, emulating it [2012-04-11 11:20:49] DEBUG[1741] chan_local.c: Checking if extension 1105@test10 exists (devicestate) [2012-04-11 11:20:49] DEBUG[1773] app_queue.c: Device 'SIP/1_1105' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [2012-04-11 11:20:49] DEBUG[1741] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:49] DEBUG[1741] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[1741] devicestate.c: Changing state for Local/1105@test10 - state 2 (In use) [2012-04-11 11:20:49] DEBUG[1741] devicestate.c: device 'Local/1105@test10' state '2' [2012-04-11 11:20:49] DEBUG[29279] channel.c: Set channel SIP/1_1102-00000021 to write format slin [2012-04-11 11:20:49] DEBUG[29279] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [2012-04-11 11:20:49] DEBUG[1773] app_queue.c: Device 'Local/1105@test10' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29279] res_rtp_asterisk.c: Difference is 16320, ms is 2060 [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:49] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:50] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:51] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:51] DEBUG[29280] res_rtp_asterisk.c: No remote address on RTP instance '0xb65eb1b0' so dropping frame [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.125:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK4c814703;rport From: "1102" ;tag=as4fa1fb25 To: ;tag=302594275 Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 CSeq: 102 INVITE Contact: Supported: 100rel, replaces, timer Server: Greenlite ATOM V2.0 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE Content-Type: application/sdp Content-Length: 238 v=0 o=1_1105 61582331 27080141 IN IP4 10.42.1.125 s=A conversation c=IN IP4 10.42.1.125 t=0 0 m=audio 10134 RTP/AVP 8 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv <-------------> [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 1 [ 62]: Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK4c814703;rport [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 2 [ 50]: From: "1102" ;tag=as4fa1fb25 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 3 [ 47]: To: ;tag=302594275 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 4 [ 58]: Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 7 [ 34]: Supported: 100rel, replaces, timer [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 8 [ 27]: Server: Greenlite ATOM V2.0 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 9 [ 85]: Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, INFO, PRACK, UPDATE, MESSAGE [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 10 [ 29]: Content-Type: application/sdp [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 11 [ 19]: Content-Length: 238 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 12 [ 0]: [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Body 0 [ 3]: v=0 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Body 1 [ 45]: o=1_1105 61582331 27080141 IN IP4 10.42.1.125 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Body 2 [ 16]: s=A conversation [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.42.1.125 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Body 4 [ 5]: t=0 0 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Body 5 [ 29]: m=audio 10134 RTP/AVP 8 0 101 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Body 9 [ 15]: a=fmtp:101 0-15 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Body 10 [ 10]: a=sendrecv [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: --- (12 headers 11 lines) --- [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: = Looking for Call ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 (Checking To) --From tag as4fa1fb25 --To-tag 302594275 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Acked pending invite 102 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Stopping retransmission on '231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060' of Request 102: Match Found [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: SIP response 200 to standard invite [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Processing session-level SDP o=1_1105 61582331 27080141 IN IP4 10.42.1.125... UNSUPPORTED. [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Processing session-level SDP s=A conversation... UNSUPPORTED. [2012-04-11 11:20:51] DEBUG[1763] netsock2.c: Splitting '10.42.1.125' into... [2012-04-11 11:20:51] DEBUG[1763] netsock2.c: ...host '10.42.1.125' and port ''. [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Processing session-level SDP c=IN IP4 10.42.1.125... OK. [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: Found RTP audio format 8 [2012-04-11 11:20:51] DEBUG[1763] rtp_engine.c: Setting payload 8 based on m type on 0xb6be8454 [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: Found RTP audio format 0 [2012-04-11 11:20:51] DEBUG[1763] rtp_engine.c: Setting payload 0 based on m type on 0xb6be8454 [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: Found RTP audio format 101 [2012-04-11 11:20:51] DEBUG[1763] rtp_engine.c: Setting payload 101 based on m type on 0xb6be8454 [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: Found audio description format PCMA for ID 8 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: Found audio description format PCMU for ID 0 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: Found audio description format telephone-event for ID 101 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2012-04-11 11:20:51] DEBUG[1763] rtp_engine.c: Incorporating payload 0 on 0xb6be8454 [2012-04-11 11:20:51] DEBUG[1763] rtp_engine.c: Incorporating payload 8 on 0xb6be8454 [2012-04-11 11:20:51] DEBUG[1763] rtp_engine.c: Incorporating payload 101 on 0xb6be8454 [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0xc (ulaw|alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xc (ulaw|alaw) [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [2012-04-11 11:20:51] DEBUG[1763] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb65eb1b0' [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: Peer audio RTP is at port 10.42.1.125:10134 [2012-04-11 11:20:51] DEBUG[1763] rtp_engine.c: Copying payload 0 from 0xb6be8454 to 0xb65eb35c [2012-04-11 11:20:51] DEBUG[1763] rtp_engine.c: Copying payload 8 from 0xb6be8454 to 0xb65eb35c [2012-04-11 11:20:51] DEBUG[1763] rtp_engine.c: Copying payload 101 from 0xb6be8454 to 0xb65eb35c [2012-04-11 11:20:51] DEBUG[1763] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb65eb1b0' [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: We have an owner, now see if we need to change this call [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Updating call counter for outgoing call [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1105 [2012-04-11 11:20:51] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1105 [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: Changing state for SIP/1_1105 - state 2 (In use) [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: device 'SIP/1_1105' state '2' [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: build_route: Contact hop: [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: list_route: hop: [2012-04-11 11:20:51] DEBUG[1773] app_queue.c: Device 'SIP/1_1105' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Strict routing enforced for session 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: set_destination: Parsing for address/port to send to [2012-04-11 11:20:51] DEBUG[1763] netsock2.c: Splitting '10.42.1.125:5060' into... [2012-04-11 11:20:51] DEBUG[1763] netsock2.c: ...host '10.42.1.125' and port '5060'. [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: set_destination: set destination to 10.42.1.125:5060 [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: Transmitting (NAT) to 10.42.1.125:5060: ACK sip:1_1105@10.42.1.125:5060 SIP/2.0 Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK3dd69e72;rport Max-Forwards: 70 From: "1102" ;tag=as4fa1fb25 To: ;tag=302594275 Contact: Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-branch-1.8-r361040M Content-Length: 0 --- [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Trying to put 'ACK sip:1_1' onto UDP socket destined for 10.42.1.125:5060 [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1105 [2012-04-11 11:20:51] VERBOSE[29280] app_dial.c: -- SIP/1_1105-00000022 answered Local/1105@test10-3545;2 [2012-04-11 11:20:51] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1105 [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: Changing state for SIP/1_1105 - state 2 (In use) [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: device 'SIP/1_1105' state '2' [2012-04-11 11:20:51] DEBUG[1773] app_queue.c: Device 'SIP/1_1105' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for Local - 1105@test10 [2012-04-11 11:20:51] DEBUG[1741] chan_local.c: Checking if extension 1105@test10 exists (devicestate) [2012-04-11 11:20:51] DEBUG[1741] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:51] DEBUG[1741] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:51] DEBUG[29279] channel.c: Set channel SIP/1_1102-00000021 to write format alaw [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: Changing state for Local/1105@test10 - state 2 (In use) [2012-04-11 11:20:51] DEBUG[29279] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: device 'Local/1105@test10' state '2' [2012-04-11 11:20:51] DEBUG[29280] features.c: bridge answer set, chan answer set [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for Local - 1105@test10 [2012-04-11 11:20:51] DEBUG[29279] features.c: Dial party C result: newchan:1, outstate:4 [2012-04-11 11:20:51] DEBUG[1773] app_queue.c: Device 'Local/1105@test10' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:51] DEBUG[1741] chan_local.c: Checking if extension 1105@test10 exists (devicestate) [2012-04-11 11:20:51] DEBUG[29280] features.c: Removing dialed interfaces datastore on SIP/1_1105-00000022 since we're bridging [2012-04-11 11:20:51] DEBUG[29279] features.c: Actually doing an attended transfer. [2012-04-11 11:20:51] DEBUG[1741] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:51] DEBUG[1741] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: Changing state for Local/1105@test10 - state 2 (In use) [2012-04-11 11:20:51] DEBUG[1741] devicestate.c: device 'Local/1105@test10' state '2' [2012-04-11 11:20:51] DEBUG[29280] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:51] DEBUG[1773] app_queue.c: Device 'Local/1105@test10' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:51] DEBUG[29279] features.c: bridge answer set, chan answer set [2012-04-11 11:20:51] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:51] DEBUG[29279] channel.c: Got a FRAME_CONTROL (-1) frame on channel Local/1105@test10-3545;1 [2012-04-11 11:20:51] DEBUG[29280] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw [2012-04-11 11:20:51] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:51] DEBUG[29280] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160 [2012-04-11 11:20:51] DEBUG[29279] channel.c: Bridge stops bridging channels SIP/1_1102-00000021 and Local/1105@test10-3545;1 [2012-04-11 11:20:51] DEBUG[29280] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0xb65eb1b0' [2012-04-11 11:20:51] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:51] DEBUG[29280] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:51] DEBUG[29280] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:51] DEBUG[29280] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:51] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.146:5061 ---> NOTIFY sip:10.42.0.253 SIP/2.0 Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-f49340a1 From: "1_1102" ;tag=63e70cb54c3c09fdo1 To: Call-ID: 187087f5-d62ec7bd@10.42.1.146 CSeq: 9992 NOTIFY Max-Forwards: 70 Contact: "1_1102" Event: keep-alive User-Agent: Linksys/SPA962-6.1.5(a) Content-Length: 0 <-------------> [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 0 [ 30]: NOTIFY sip:10.42.0.253 SIP/2.0 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-f49340a1 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 2 [ 62]: From: "1_1102" ;tag=63e70cb54c3c09fdo1 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 3 [ 21]: To: [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 4 [ 38]: Call-ID: 187087f5-d62ec7bd@10.42.1.146 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 5 [ 17]: CSeq: 9992 NOTIFY [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 7 [ 47]: Contact: "1_1102" [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 8 [ 17]: Event: keep-alive [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 9 [ 35]: User-Agent: Linksys/SPA962-6.1.5(a) [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: --- (11 headers 0 lines) --- [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: = Looking for Call ID: 187087f5-d62ec7bd@10.42.1.146 (Checking From) --From tag 63e70cb54c3c09fdo1 --To-tag [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Got NOTIFY Event: keep-alive [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: <--- Transmitting (NAT) to 10.42.1.146:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-f49340a1;received=10.42.1.146;rport=5061 From: "1_1102" ;tag=63e70cb54c3c09fdo1 To: ;tag=as618cfb40 Call-ID: 187087f5-d62ec7bd@10.42.1.146 CSeq: 9992 NOTIFY Server: Asterisk PBX SVN-branch-1.8-r361040M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [2012-04-11 11:20:51] DEBUG[1763] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.42.1.146:5061 [2012-04-11 11:20:51] VERBOSE[1763] chan_sip.c: Scheduling destruction of SIP dialog '187087f5-d62ec7bd@10.42.1.146' in 32000 ms (Method: NOTIFY) [2012-04-11 11:20:52] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.125:5060 ---> BYE sip:1102@10.42.0.253:5060 SIP/2.0 Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK2262713456528512341;rport From: ;tag=302594275 To: "1102" ;tag=as4fa1fb25 Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 CSeq: 1 BYE Max-Forwards: 70 User-Agent: Greenlite ATOM V2.0 Content-Length: 0 <-------------> [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Header 0 [ 37]: BYE sip:1102@10.42.0.253:5060 SIP/2.0 [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Header 1 [ 73]: Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK2262713456528512341;rport [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Header 2 [ 49]: From: ;tag=302594275 [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Header 3 [ 48]: To: "1102" ;tag=as4fa1fb25 [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Header 4 [ 58]: Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Header 5 [ 11]: CSeq: 1 BYE [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Header 7 [ 31]: User-Agent: Greenlite ATOM V2.0 [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [2012-04-11 11:20:52] VERBOSE[1763] chan_sip.c: --- (9 headers 0 lines) --- [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: = Looking for Call ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 (Checking From) --From tag 302594275 --To-tag as4fa1fb25 [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Initializing initreq for method BYE - callid 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 [2012-04-11 11:20:52] DEBUG[1763] netsock2.c: Splitting '10.42.1.125:5060' into... [2012-04-11 11:20:52] DEBUG[1763] netsock2.c: ...host '10.42.1.125' and port '5060'. [2012-04-11 11:20:52] VERBOSE[1763] chan_sip.c: Sending to 10.42.1.125:5060 (NAT) [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Setting SIP_ALREADYGONE on dialog 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 [2012-04-11 11:20:52] DEBUG[1763] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb65eb1b0' [2012-04-11 11:20:52] VERBOSE[1763] chan_sip.c: Scheduling destruction of SIP dialog '231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060' in 32000 ms (Method: BYE) [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Received bye, issuing owner hangup [2012-04-11 11:20:52] VERBOSE[1763] chan_sip.c: <--- Transmitting (NAT) to 10.42.1.125:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK2262713456528512341;received=10.42.1.125;rport=5060 From: ;tag=302594275 To: "1102" ;tag=as4fa1fb25 Call-ID: 231445cc2686033d1d6a0e72550b13b1@10.42.0.253:5060 CSeq: 1 BYE Server: Asterisk PBX SVN-branch-1.8-r361040M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces Content-Length: 0 <------------> [2012-04-11 11:20:52] DEBUG[1763] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.42.1.125:5060 [2012-04-11 11:20:52] DEBUG[29280] channel.c: Didn't get a frame from channel: SIP/1_1105-00000022 [2012-04-11 11:20:52] DEBUG[29280] channel.c: Bridge stops bridging channels Local/1105@test10-3545;2 and SIP/1_1105-00000022 [2012-04-11 11:20:52] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:52] DEBUG[29280] pbx.c: Nothing strange about this match [2012-04-11 11:20:52] DEBUG[29280] pbx.c: returning an exact match-- first found-- h [2012-04-11 11:20:52] DEBUG[29280] channel.c: Soft-Hanging up channel 'Local/1105@test10-3545;2' [2012-04-11 11:20:52] DEBUG[29280] pbx.c: Nothing strange about this match [2012-04-11 11:20:52] DEBUG[29280] pbx.c: returning an exact match-- first found-- h [2012-04-11 11:20:52] DEBUG[29280] pbx.c: Launching 'NoOp' [2012-04-11 11:20:52] VERBOSE[29280] pbx.c: -- Executing [h@test10:1] NoOp("Local/1105@test10-3545;2", "") in new stack [2012-04-11 11:20:52] DEBUG[29280] pbx.c: Nothing strange about this match [2012-04-11 11:20:52] DEBUG[29280] pbx.c: returning an exact match-- first found-- h [2012-04-11 11:20:52] DEBUG[29280] cdr_mysql.c: Inserting a CDR record. [2012-04-11 11:20:52] DEBUG[29280] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`) VALUES ('2012-04-11 11:20:49','1102','1102','1105','test10','Local/1105@test10-3545;2','SIP/1_1105-00000022','Dial','SIP/1_1105,60,t','3','1','ANSWERED','3','1334128849.47') [2012-04-11 11:20:52] DEBUG[29280] channel.c: Hanging up channel 'SIP/1_1105-00000022' [2012-04-11 11:20:52] DEBUG[29280] chan_sip.c: Hanging up zombie call. Be scared. [2012-04-11 11:20:52] DEBUG[29280] chan_sip.c: update_call_counter(1105) - decrement call limit counter on hangup [2012-04-11 11:20:52] DEBUG[29280] chan_sip.c: Updating call counter for outgoing call [2012-04-11 11:20:52] DEBUG[29280] chan_sip.c: Call to peer '1_1105' removed from call limit 10 [2012-04-11 11:20:52] DEBUG[29280] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb65eb1b0' [2012-04-11 11:20:52] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1105 [2012-04-11 11:20:52] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1105 [2012-04-11 11:20:52] DEBUG[29280] app_dial.c: Exiting with DIALSTATUS=ANSWER. [2012-04-11 11:20:52] DEBUG[1741] devicestate.c: Changing state for SIP/1_1105 - state 1 (Not in use) [2012-04-11 11:20:52] DEBUG[1741] devicestate.c: device 'SIP/1_1105' state '1' [2012-04-11 11:20:52] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1105 [2012-04-11 11:20:52] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1105 [2012-04-11 11:20:52] DEBUG[1741] devicestate.c: Changing state for SIP/1_1105 - state 1 (Not in use) [2012-04-11 11:20:52] DEBUG[1741] devicestate.c: device 'SIP/1_1105' state '1' [2012-04-11 11:20:52] DEBUG[1773] app_queue.c: Device 'SIP/1_1105' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:52] DEBUG[29280] pbx.c: Spawn extension (test10,1105,1) exited non-zero on 'Local/1105@test10-3545;2' [2012-04-11 11:20:52] DEBUG[1773] app_queue.c: Device 'SIP/1_1105' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:52] VERBOSE[29280] pbx.c: == Spawn extension (test10, 1105, 1) exited non-zero on 'Local/1105@test10-3545;2' [2012-04-11 11:20:52] DEBUG[29280] channel.c: Soft-Hanging up channel 'Local/1105@test10-3545;2' [2012-04-11 11:20:52] DEBUG[29280] channel.c: Hanging up channel 'Local/1105@test10-3545;2' [2012-04-11 11:20:52] DEBUG[29279] channel.c: Didn't get a frame from channel: Local/1105@test10-3545;1 [2012-04-11 11:20:52] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for Local - 1105@test10 [2012-04-11 11:20:52] DEBUG[1741] chan_local.c: Checking if extension 1105@test10 exists (devicestate) [2012-04-11 11:20:52] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:52] DEBUG[1741] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:52] DEBUG[29279] channel.c: Bridge stops bridging channels SIP/1_1102-00000021 and Local/1105@test10-3545;1 [2012-04-11 11:20:52] DEBUG[1741] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:52] DEBUG[1741] devicestate.c: Changing state for Local/1105@test10 - state 2 (In use) [2012-04-11 11:20:52] DEBUG[29279] pbx.c: Nothing strange about this match [2012-04-11 11:20:52] DEBUG[1741] devicestate.c: device 'Local/1105@test10' state '2' [2012-04-11 11:20:52] DEBUG[29279] pbx.c: returning an exact match-- first found-- h [2012-04-11 11:20:53] DEBUG[29279] channel.c: Soft-Hanging up channel 'SIP/1_1102-00000021' [2012-04-11 11:20:53] DEBUG[1773] app_queue.c: Device 'Local/1105@test10' changed to state '2' (In use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:53] DEBUG[29279] pbx.c: Nothing strange about this match [2012-04-11 11:20:53] DEBUG[29279] pbx.c: returning an exact match-- first found-- h [2012-04-11 11:20:53] DEBUG[29279] pbx.c: Launching 'NoOp' [2012-04-11 11:20:53] VERBOSE[29279] pbx.c: -- Executing [h@test10:1] NoOp("SIP/1_1102-00000021", "") in new stack [2012-04-11 11:20:53] DEBUG[29279] pbx.c: Nothing strange about this match [2012-04-11 11:20:53] DEBUG[29279] pbx.c: returning an exact match-- first found-- h [2012-04-11 11:20:53] DEBUG[29279] cdr_mysql.c: Inserting a CDR record. [2012-04-11 11:20:53] DEBUG[29279] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dcontext`,`channel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`) VALUES ('2012-04-11 11:20:43','1102','1102','test10','SIP/1_1102-00000021','AppDial','(Outgoing Line)','10','9','ANSWERED','3','1334128843.45') [2012-04-11 11:20:53] DEBUG[29279] channel.c: Hanging up channel 'Local/1105@test10-3545;1' [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for Local - 1105@test10 [2012-04-11 11:20:53] DEBUG[1741] chan_local.c: Checking if extension 1105@test10 exists (devicestate) [2012-04-11 11:20:53] DEBUG[1741] pbx.c: return because scoreboard has a match with '/'--- _X. [2012-04-11 11:20:53] DEBUG[1741] pbx.c: returning an exact match-- _X. [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: Changing state for Local/1105@test10 - state 1 (Not in use) [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: device 'Local/1105@test10' state '1' [2012-04-11 11:20:53] DEBUG[1773] app_queue.c: Device 'Local/1105@test10' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:53] DEBUG[29279] channel.c: Set channel SIP/1_1102-00000021 to write format slin [2012-04-11 11:20:53] WARNING[29279] file.c: Failed to write frame [2012-04-11 11:20:53] DEBUG[29279] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-11 11:20:53] VERBOSE[29279] file.c: -- Playing 'beep.slin' (language 'ru') [2012-04-11 11:20:53] WARNING[29279] features.c: Failed to play transfer sound! [2012-04-11 11:20:53] DEBUG[29279] res_rtp_asterisk.c: Setting the marker bit due to a source update [2012-04-11 11:20:53] VERBOSE[29279] res_musiconhold.c: -- Stopped music on hold on SIP/1_1103-00000020 [2012-04-11 11:20:53] DEBUG[29279] res_musiconhold.c: Destroying MOH class 'default' [2012-04-11 11:20:53] DEBUG[29279] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-11 11:20:53] DEBUG[29279] pbx.c: Nothing strange about this match [2012-04-11 11:20:53] DEBUG[29279] pbx.c: returning an exact match-- first found-- h [2012-04-11 11:20:53] DEBUG[29279] channel.c: Soft-Hanging up channel 'SIP/1_1103-00000020' [2012-04-11 11:20:53] DEBUG[29279] pbx.c: Nothing strange about this match [2012-04-11 11:20:53] DEBUG[29279] pbx.c: returning an exact match-- first found-- h [2012-04-11 11:20:53] DEBUG[29279] pbx.c: Launching 'NoOp' [2012-04-11 11:20:53] VERBOSE[29279] pbx.c: -- Executing [h@test10:1] NoOp("SIP/1_1103-00000020", "") in new stack [2012-04-11 11:20:53] DEBUG[29279] pbx.c: Nothing strange about this match [2012-04-11 11:20:53] DEBUG[29279] pbx.c: returning an exact match-- first found-- h [2012-04-11 11:20:53] DEBUG[29279] cdr_mysql.c: Inserting a CDR record. [2012-04-11 11:20:53] DEBUG[29279] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`) VALUES ('2012-04-11 11:20:43','\"1_1103\" <1103>','1103','1102','test10','SIP/1_1103-00000020','SIP/1_1102-00000021','Dial','SIP/1_1102,60,t','10','9','ANSWERED','3','1334128843.44') [2012-04-11 11:20:53] DEBUG[29279] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-11 11:20:53] DEBUG[29279] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [2012-04-11 11:20:53] DEBUG[29279] channel.c: Hanging up channel 'SIP/1_1102-00000021' [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: Hanging up zombie call. Be scared. [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: update_call_counter(1102) - decrement call limit counter on hangup [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: Updating call counter for outgoing call [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: Call to peer '1_1102' removed from call limit 10 [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1102 [2012-04-11 11:20:53] DEBUG[29279] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb65b61e0' [2012-04-11 11:20:53] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1102 [2012-04-11 11:20:53] VERBOSE[29279] chan_sip.c: Scheduling destruction of SIP dialog '00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060' in 32000 ms (Method: INVITE) [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: Changing state for SIP/1_1102 - state 1 (Not in use) [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: device 'SIP/1_1102' state '1' [2012-04-11 11:20:53] DEBUG[1773] app_queue.c: Device 'SIP/1_1102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: Strict routing enforced for session 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 [2012-04-11 11:20:53] VERBOSE[29279] chan_sip.c: set_destination: Parsing for address/port to send to [2012-04-11 11:20:53] DEBUG[29279] netsock2.c: Splitting '10.42.1.146:5061' into... [2012-04-11 11:20:53] DEBUG[29279] netsock2.c: ...host '10.42.1.146' and port '5061'. [2012-04-11 11:20:53] VERBOSE[29279] chan_sip.c: set_destination: set destination to 10.42.1.146:5061 [2012-04-11 11:20:53] VERBOSE[29279] chan_sip.c: Reliably Transmitting (NAT) to 10.42.1.146:5061: BYE sip:1_1102@10.42.1.146:5061 SIP/2.0 Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK6f6375c1;rport Max-Forwards: 70 From: "1_1103" ;tag=as268d8acc To: ;tag=619381ced398c25ei1 Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 CSeq: 103 BYE User-Agent: Asterisk PBX SVN-branch-1.8-r361040M X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #151330 [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: Trying to put 'BYE sip:1_1' onto UDP socket destined for 10.42.1.146:5061 [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1102 [2012-04-11 11:20:53] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1102 [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: Changing state for SIP/1_1102 - state 1 (Not in use) [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: device 'SIP/1_1102' state '1' [2012-04-11 11:20:53] DEBUG[29279] app_dial.c: Exiting with DIALSTATUS=ANSWER. [2012-04-11 11:20:53] DEBUG[1773] app_queue.c: Device 'SIP/1_1102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:53] DEBUG[29279] pbx.c: Spawn extension (test10,1102,1) exited non-zero on 'SIP/1_1103-00000020' [2012-04-11 11:20:53] VERBOSE[29279] pbx.c: == Spawn extension (test10, 1102, 1) exited non-zero on 'SIP/1_1103-00000020' [2012-04-11 11:20:53] DEBUG[29279] channel.c: Soft-Hanging up channel 'SIP/1_1103-00000020' [2012-04-11 11:20:53] DEBUG[29279] channel.c: Hanging up channel 'SIP/1_1103-00000020' [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: Hanging up zombie call. Be scared. [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: update_call_counter(1103) - decrement call limit counter on hangup [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: Updating call counter for incoming call [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: Call from peer '1_1103' removed from call limit 10 [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1103 [2012-04-11 11:20:53] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1103 [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: Changing state for SIP/1_1103 - state 1 (Not in use) [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: device 'SIP/1_1103' state '1' [2012-04-11 11:20:53] DEBUG[29279] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb775fe38' [2012-04-11 11:20:53] VERBOSE[29279] chan_sip.c: Scheduling destruction of SIP dialog '10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253' in 32000 ms (Method: ACK) [2012-04-11 11:20:53] DEBUG[1773] app_queue.c: Device 'SIP/1_1103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: Strict routing enforced for session 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 [2012-04-11 11:20:53] VERBOSE[29279] chan_sip.c: set_destination: Parsing for address/port to send to [2012-04-11 11:20:53] DEBUG[29279] netsock2.c: Splitting '10.42.1.233:5060' into... [2012-04-11 11:20:53] DEBUG[29279] netsock2.c: ...host '10.42.1.233' and port '5060'. [2012-04-11 11:20:53] VERBOSE[29279] chan_sip.c: set_destination: set destination to 10.42.1.233:5060 [2012-04-11 11:20:53] VERBOSE[29279] chan_sip.c: Reliably Transmitting (NAT) to 10.42.1.233:5060: BYE sip:1_1103@10.42.1.233:5060;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK56bf3e9c;rport Max-Forwards: 70 From: "1102";tag=as23cb731a To: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 CSeq: 102 BYE User-Agent: Asterisk PBX SVN-branch-1.8-r361040M Proxy-Authorization: Digest username="1103", realm="asterisk", algorithm=MD5, uri="sip:10.42.0.253", nonce="", response="889dd76072813cd446409daa37975c72" X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #151332 [2012-04-11 11:20:53] DEBUG[29279] chan_sip.c: Trying to put 'BYE sip:1_1' onto UDP socket destined for 10.42.1.233:5060 [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1103 [2012-04-11 11:20:53] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1103 [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: Changing state for SIP/1_1103 - state 1 (Not in use) [2012-04-11 11:20:53] DEBUG[1741] devicestate.c: device 'SIP/1_1103' state '1' [2012-04-11 11:20:53] DEBUG[1773] app_queue.c: Device 'SIP/1_1103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2012-04-11 11:20:53] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.146:5061 ---> SIP/2.0 200 OK To: ;tag=619381ced398c25ei1 From: "1_1103" ;tag=as268d8acc Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 CSeq: 103 BYE Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK6f6375c1 Server: Linksys/SPA962-6.1.5(a) Content-Length: 0 <-------------> [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 1 [ 56]: To: ;tag=619381ced398c25ei1 [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 2 [ 52]: From: "1_1103" ;tag=as268d8acc [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 3 [ 58]: Call-ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 4 [ 13]: CSeq: 103 BYE [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 5 [ 56]: Via: SIP/2.0/UDP 10.42.0.253:5060;branch=z9hG4bK6f6375c1 [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 6 [ 31]: Server: Linksys/SPA962-6.1.5(a) [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [2012-04-11 11:20:53] VERBOSE[1763] chan_sip.c: --- (8 headers 0 lines) --- [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: = Looking for Call ID: 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 (Checking To) --From tag as268d8acc --To-tag 619381ced398c25ei1 [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #151330 [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Stopping retransmission on '00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060' of Request 103: Match Found [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Destroying SIP dialog 00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060 [2012-04-11 11:20:53] VERBOSE[1763] chan_sip.c: Really destroying SIP dialog '00075a595a4b43c61b24a1a211dc99ce@10.42.0.253:5060' Method: INVITE [2012-04-11 11:20:53] DEBUG[1763] rtp_engine.c: Destroyed RTP instance '0xb65b61e0' [2012-04-11 11:20:53] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.233:5060 ---> SIP/2.0 200 OK From: "1102";tag=as23cb731a To: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 CSeq: 102 BYE Via: SIP/2.0/UDP 10.42.0.253:5060;rport;branch=z9hG4bK56bf3e9c Supported: replaces,100rel Content-Length: 0 <-------------> [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 1 [ 49]: From: "1102";tag=as23cb731a [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 2 [ 83]: To: "1_1103";tag=1031ad48-0-13c4-4f85690a-635bf552-4f85690a [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 3 [ 63]: Call-ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 4 [ 13]: CSeq: 102 BYE [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 5 [ 62]: Via: SIP/2.0/UDP 10.42.0.253:5060;rport;branch=z9hG4bK56bf3e9c [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 6 [ 26]: Supported: replaces,100rel [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [2012-04-11 11:20:53] VERBOSE[1763] chan_sip.c: --- (8 headers 0 lines) --- [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: = Looking for Call ID: 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 (Checking To) --From tag as23cb731a --To-tag 1031ad48-0-13c4-4f85690a-635bf552-4f85690a [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #151332 [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Stopping retransmission on '10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253' of Request 102: Match Found [2012-04-11 11:20:53] VERBOSE[1763] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [2012-04-11 11:20:53] DEBUG[1763] chan_sip.c: Destroying SIP dialog 10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253 [2012-04-11 11:20:53] VERBOSE[1763] chan_sip.c: Really destroying SIP dialog '10320af0-0-13c4-4f85690a-37d18cb6-4f85690a@10.42.0.253' Method: ACK [2012-04-11 11:20:53] DEBUG[1763] rtp_engine.c: Destroyed RTP instance '0xb775fe38' [2012-04-11 11:20:56] DEBUG[1755] chan_iax2.c: ip callno count incremented to 4 for 1.1.1.4 [2012-04-11 11:20:58] DEBUG[1763] chan_sip.c: Auto destroying SIP dialog '10321aa0-0-13c4-4f82c357-6126d57e-4f82c357' [2012-04-11 11:20:58] DEBUG[1763] chan_sip.c: Destroying SIP dialog 10321aa0-0-13c4-4f82c357-6126d57e-4f82c357 [2012-04-11 11:20:58] VERBOSE[1763] chan_sip.c: Really destroying SIP dialog '10321aa0-0-13c4-4f82c357-6126d57e-4f82c357' Method: REGISTER [2012-04-11 11:21:00] DEBUG[1763] chan_sip.c: Auto destroying SIP dialog '2a2f1352-c05fe943@10.42.1.146' [2012-04-11 11:21:00] DEBUG[1763] chan_sip.c: Destroying SIP dialog 2a2f1352-c05fe943@10.42.1.146 [2012-04-11 11:21:00] VERBOSE[1763] chan_sip.c: Really destroying SIP dialog '2a2f1352-c05fe943@10.42.1.146' Method: REGISTER [2012-04-11 11:21:01] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.125:5060 ---> REGISTER sip:10.42.0.253 SIP/2.0 Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK2745325458442319259;rport From: 1_1105 ;tag=1957311506 To: 1_1105 Call-ID: 104791698725513-250523185615821@10.42.1.125 CSeq: 9843 REGISTER Contact: Max-Forwards: 70 Expires: 60 Supported: path User-Agent: Greenlite ATOM V2.0 Content-Length: 0 <-------------> [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 1 [ 73]: Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK2745325458442319259;rport [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 2 [ 52]: From: 1_1105 ;tag=1957311506 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 3 [ 35]: To: 1_1105 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 4 [ 52]: Call-ID: 104791698725513-250523185615821@10.42.1.125 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 5 [ 19]: CSeq: 9843 REGISTER [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 8 [ 11]: Expires: 60 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 9 [ 15]: Supported: path [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 10 [ 31]: User-Agent: Greenlite ATOM V2.0 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 11 [ 17]: Content-Length: 0 [2012-04-11 11:21:01] VERBOSE[1763] chan_sip.c: --- (12 headers 0 lines) --- [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: = Looking for Call ID: 104791698725513-250523185615821@10.42.1.125 (Checking From) --From tag 1957311506 --To-tag [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Initializing initreq for method REGISTER - callid 104791698725513-250523185615821@10.42.1.125 [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: Splitting '10.42.1.125:5060' into... [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: ...host '10.42.1.125' and port '5060'. [2012-04-11 11:21:01] VERBOSE[1763] chan_sip.c: Sending to 10.42.1.125:5060 (NAT) [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: Splitting '10.42.0.253' into... [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-11 11:21:01] VERBOSE[1763] chan_sip.c: <--- Transmitting (NAT) to 10.42.1.125:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK2745325458442319259;received=10.42.1.125;rport=5060 From: 1_1105 ;tag=1957311506 To: 1_1105 ;tag=as17885c11 Call-ID: 104791698725513-250523185615821@10.42.1.125 CSeq: 9843 REGISTER Server: Asterisk PBX SVN-branch-1.8-r361040M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="08f1c48a" Content-Length: 0 <------------> [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.42.1.125:5060 [2012-04-11 11:21:01] VERBOSE[1763] chan_sip.c: Scheduling destruction of SIP dialog '104791698725513-250523185615821@10.42.1.125' in 32000 ms (Method: REGISTER) [2012-04-11 11:21:01] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.125:5060 ---> REGISTER sip:10.42.0.253 SIP/2.0 Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK34232609147018635;rport From: 1_1105 ;tag=1957311506 To: 1_1105 Call-ID: 104791698725513-250523185615821@10.42.1.125 CSeq: 9844 REGISTER Contact: Authorization: Digest username="1_1105", realm="asterisk", nonce="08f1c48a", uri="sip:10.42.0.253", response="062bedd2d78f5897f5f2495ff477bb2e", algorithm=MD5 Max-Forwards: 70 Expires: 60 Supported: path User-Agent: Greenlite ATOM V2.0 Content-Length: 0 <-------------> [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 0 [ 32]: REGISTER sip:10.42.0.253 SIP/2.0 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 1 [ 71]: Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK34232609147018635;rport [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 2 [ 52]: From: 1_1105 ;tag=1957311506 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 3 [ 35]: To: 1_1105 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 4 [ 52]: Call-ID: 104791698725513-250523185615821@10.42.1.125 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 5 [ 19]: CSeq: 9844 REGISTER [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 6 [ 38]: Contact: [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 7 [158]: Authorization: Digest username="1_1105", realm="asterisk", nonce="08f1c48a", uri="sip:10.42.0.253", response="062bedd2d78f5897f5f2495ff477bb2e", algorithm=MD5 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 8 [ 16]: Max-Forwards: 70 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 9 [ 11]: Expires: 60 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 10 [ 15]: Supported: path [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 11 [ 31]: User-Agent: Greenlite ATOM V2.0 [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [2012-04-11 11:21:01] VERBOSE[1763] chan_sip.c: --- (13 headers 0 lines) --- [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: = Looking for Call ID: 104791698725513-250523185615821@10.42.1.125 (Checking From) --From tag 1957311506 --To-tag [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: Splitting '10.42.0.253' into... [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: Splitting '10.42.0.253' into... [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Initializing initreq for method REGISTER - callid 104791698725513-250523185615821@10.42.1.125 [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: Splitting '10.42.1.125:5060' into... [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: ...host '10.42.1.125' and port '5060'. [2012-04-11 11:21:01] VERBOSE[1763] chan_sip.c: Sending to 10.42.1.125:5060 (NAT) [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: Splitting '10.42.0.253' into... [2012-04-11 11:21:01] DEBUG[1763] netsock2.c: ...host '10.42.0.253' and port ''. [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Store REGISTER's src-IP:port for call routing. [2012-04-11 11:21:01] VERBOSE[1763] chan_sip.c: <--- Transmitting (NAT) to 10.42.1.125:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.42.1.125:5060;branch=z9hG4bK34232609147018635;received=10.42.1.125;rport=5060 From: 1_1105 ;tag=1957311506 To: 1_1105 ;tag=as17885c11 Call-ID: 104791698725513-250523185615821@10.42.1.125 CSeq: 9844 REGISTER Server: Asterisk PBX SVN-branch-1.8-r361040M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Expires: 60 Contact: ;expires=60 Date: Wed, 11 Apr 2012 07:21:01 GMT Content-Length: 0 <------------> [2012-04-11 11:21:01] DEBUG[1763] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.42.1.125:5060 [2012-04-11 11:21:01] DEBUG[1741] devicestate.c: No provider found, checking channel drivers for SIP - 1_1105 [2012-04-11 11:21:01] DEBUG[1741] chan_sip.c: Checking device state for peer 1_1105 [2012-04-11 11:21:01] DEBUG[1741] devicestate.c: Changing state for SIP/1_1105 - state 1 (Not in use) [2012-04-11 11:21:01] DEBUG[1741] devicestate.c: device 'SIP/1_1105' state '1' [2012-04-11 11:21:01] DEBUG[1773] app_queue.c: Device 'SIP/1_1105' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2012-04-11 11:21:01] VERBOSE[1763] chan_sip.c: Scheduling destruction of SIP dialog '104791698725513-250523185615821@10.42.1.125' in 32000 ms (Method: REGISTER) [2012-04-11 11:21:02] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.242:5064 ---> <-------------> [2012-04-11 11:21:02] DEBUG[1763] chan_sip.c: Header 0 [ 0]: [2012-04-11 11:21:06] VERBOSE[1763] chan_sip.c: <--- SIP read from UDP:10.42.1.146:5061 ---> NOTIFY sip:10.42.0.253 SIP/2.0 Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-cf844044 From: "1_1102" ;tag=63e70cb54c3c09fdo1 To: Call-ID: 187087f5-d62ec7bd@10.42.1.146 CSeq: 9993 NOTIFY Max-Forwards: 70 Contact: "1_1102" Event: keep-alive User-Agent: Linksys/SPA962-6.1.5(a) Content-Length: 0 <-------------> [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Header 0 [ 30]: NOTIFY sip:10.42.0.253 SIP/2.0 [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Header 1 [ 57]: Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-cf844044 [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Header 2 [ 62]: From: "1_1102" ;tag=63e70cb54c3c09fdo1 [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Header 3 [ 21]: To: [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Header 4 [ 38]: Call-ID: 187087f5-d62ec7bd@10.42.1.146 [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Header 5 [ 17]: CSeq: 9993 NOTIFY [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Header 7 [ 47]: Contact: "1_1102" [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Header 8 [ 17]: Event: keep-alive [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Header 9 [ 35]: User-Agent: Linksys/SPA962-6.1.5(a) [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [2012-04-11 11:21:06] VERBOSE[1763] chan_sip.c: --- (11 headers 0 lines) --- [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: = Looking for Call ID: 187087f5-d62ec7bd@10.42.1.146 (Checking From) --From tag 63e70cb54c3c09fdo1 --To-tag [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: **** Received NOTIFY (4) - Command in SIP NOTIFY [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Got NOTIFY Event: keep-alive [2012-04-11 11:21:06] VERBOSE[1763] chan_sip.c: <--- Transmitting (NAT) to 10.42.1.146:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.42.1.146:5061;branch=z9hG4bK-cf844044;received=10.42.1.146;rport=5061 From: "1_1102" ;tag=63e70cb54c3c09fdo1 To: ;tag=as618cfb40 Call-ID: 187087f5-d62ec7bd@10.42.1.146 CSeq: 9993 NOTIFY Server: Asterisk PBX SVN-branch-1.8-r361040M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [2012-04-11 11:21:06] DEBUG[1763] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.42.1.146:5061 [2012-04-11 11:21:06] VERBOSE[1763] chan_sip.c: Scheduling destruction of SIP dialog '187087f5-d62ec7bd@10.42.1.146' in 32000 ms (Method: NOTIFY) [2012-04-11 11:21:06] DEBUG[1751] chan_iax2.c: ip callno count decremented to 3 for 1.1.1.4 [2012-04-11 11:21:06] DEBUG[1758] chan_iax2.c: schedule decrement of callno used for 1.1.1.4 in 60 seconds