[Nov 25 19:01:48] VERBOSE[9722] logger.c: == Parsing '/etc/asterisk/logger.conf': [Nov 25 19:01:48] DEBUG[9722] config.c: Parsing /etc/asterisk/logger.conf [Nov 25 19:01:48] VERBOSE[9722] logger.c: == Found [Nov 25 19:01:48] VERBOSE[9722] logger.c: Asterisk Event Logger restarted [Nov 25 19:01:48] DEBUG[9722] res_config_mysql.c: MySQL RealTime: Connection okay. [Nov 25 19:01:48] DEBUG[9722] res_config_mysql.c: MySQL RealTime: Insert SQL: INSERT into queue_log_raw (time, callid, queuename, agent, event, data) values ('1259164908', 'NONE', 'NONE', 'NONE', 'CONFIGRELOAD', '') [Nov 25 19:01:48] DEBUG[9722] res_config_mysql.c: MySQL RealTime: row inserted on table: queue_log_raw, id: 1027 [Nov 25 19:01:48] VERBOSE[9722] logger.c: Asterisk Queue Logger restarted [Nov 25 19:01:51] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.210.12.104:5060 ---> INVITE sip:0011@10.210.12.253 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-44e1df8f From: "1102" ;tag=f4e74d0070142167o1 To: Call-ID: 78e873b4-613c0a43@10.210.12.104 CSeq: 101 INVITE Max-Forwards: 70 Contact: "1102" Expires: 240 User-Agent: Linksys/SPA962-6.1.3(a) Content-Length: 403 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 127260648 127260648 IN IP4 10.210.12.104 s=- c=IN IP4 10.210.12.104 t=0 0 m=audio 16408 RTP/AVP 8 0 2 4 18 96 97 98 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 0 [ 37]: INVITE sip:0011@10.210.12.253 SIP/2.0 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-44e1df8f [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 2 [ 60]: From: "1102" ;tag=f4e74d0070142167o1 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 3 [ 28]: To: [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 4 [ 40]: Call-ID: 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 5 [ 16]: CSeq: 101 INVITE [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 7 [ 45]: Contact: "1102" [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 8 [ 12]: Expires: 240 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 9 [ 35]: User-Agent: Linksys/SPA962-6.1.3(a) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 10 [ 19]: Content-Length: 403 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 11 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 12 [ 19]: Supported: replaces [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 13 [ 29]: Content-Type: application/sdp [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 14 [ 0]: [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 0 [ 3]: v=0 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 1 [ 44]: o=- 127260648 127260648 IN IP4 10.210.12.104 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 2 [ 3]: s=- [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 3 [ 22]: c=IN IP4 10.210.12.104 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 5 [ 45]: m=audio 16408 RTP/AVP 8 0 2 4 18 96 97 98 101 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 9 [ 20]: a=rtpmap:4 G723/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 15 [ 15]: a=fmtp:101 0-15 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 16 [ 10]: a=ptime:30 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 17 [ 10]: a=sendrecv [Nov 25 19:01:51] VERBOSE[9366] logger.c: --- (14 headers 18 lines) --- [Nov 25 19:01:51] DEBUG[9366] acl.c: Found IP address for this socket [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.210.12.253:5060 [Nov 25 19:01:51] VERBOSE[9366] logger.c: == Using SIP RTP CoS mark 5 [Nov 25 19:01:51] VERBOSE[9366] logger.c: == Using UDPTL CoS mark 5 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Setting NAT on RTP to Off [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Setting NAT on UDPTL to Off [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Allocating new SIP dialog for 78e873b4-613c0a43@10.210.12.104 - INVITE (With RTP) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Begin: parsing SIP "Supported: replaces" [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Found SIP option: -replaces- [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Matched SIP option: replaces [Nov 25 19:01:51] VERBOSE[9366] logger.c: Sending to 10.210.12.104 : 5060 (no NAT) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Initializing initreq for method INVITE - callid 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Using INVITE request as basis request - 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found user '1102' for '1102' [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Setting NAT on RTP to On [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Setting NAT on UDPTL to On [Nov 25 19:01:51] VERBOSE[9366] logger.c: <--- Reliably Transmitting (NAT) to 10.210.12.104:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-44e1df8f;received=10.210.12.104 From: "1102" ;tag=f4e74d0070142167o1 To: ;tag=as54f894fa Call-ID: 78e873b4-613c0a43@10.210.12.104 CSeq: 101 INVITE User-Agent: Asterisk PBX 1.6.0.18 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7f38d04b" Content-Length: 0 <------------> [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #69 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.210.12.104:5060 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Scheduling destruction of SIP dialog '78e873b4-613c0a43@10.210.12.104' in 32000 ms (Method: INVITE) [Nov 25 19:01:51] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.210.12.104:5060 ---> ACK sip:0011@10.210.12.253 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-44e1df8f From: "1102" ;tag=f4e74d0070142167o1 To: ;tag=as54f894fa Call-ID: 78e873b4-613c0a43@10.210.12.104 CSeq: 101 ACK Max-Forwards: 70 Contact: "1102" User-Agent: Linksys/SPA962-6.1.3(a) Content-Length: 0 <-------------> [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 0 [ 34]: ACK sip:0011@10.210.12.253 SIP/2.0 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-44e1df8f [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 2 [ 60]: From: "1102" ;tag=f4e74d0070142167o1 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 3 [ 43]: To: ;tag=as54f894fa [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 4 [ 40]: Call-ID: 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 5 [ 13]: CSeq: 101 ACK [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 7 [ 45]: Contact: "1102" [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 8 [ 35]: User-Agent: Linksys/SPA962-6.1.3(a) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 10 [ 0]: [Nov 25 19:01:51] VERBOSE[9366] logger.c: --- (10 headers 0 lines) --- [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: = Found Their Call ID: 78e873b4-613c0a43@10.210.12.104 Their Tag f4e74d0070142167o1 Our tag: as54f894fa [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #69 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Stopping retransmission on '78e873b4-613c0a43@10.210.12.104' of Response 101: Match Found [Nov 25 19:01:51] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.210.12.104:5060 ---> INVITE sip:0011@10.210.12.253 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-f837e07b From: "1102" ;tag=f4e74d0070142167o1 To: Call-ID: 78e873b4-613c0a43@10.210.12.104 CSeq: 102 INVITE Max-Forwards: 70 Authorization: Digest username="1102",realm="asterisk",nonce="7f38d04b",uri="sip:0011@10.210.12.253",algorithm=MD5,response="e5d99db19fa9e38448c23f966abd8d97" Contact: "1102" Expires: 240 User-Agent: Linksys/SPA962-6.1.3(a) Content-Length: 403 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: replaces Content-Type: application/sdp v=0 o=- 127260648 127260648 IN IP4 10.210.12.104 s=- c=IN IP4 10.210.12.104 t=0 0 m=audio 16408 RTP/AVP 8 0 2 4 18 96 97 98 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 0 [ 37]: INVITE sip:0011@10.210.12.253 SIP/2.0 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-f837e07b [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 2 [ 60]: From: "1102" ;tag=f4e74d0070142167o1 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 3 [ 28]: To: [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 4 [ 40]: Call-ID: 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 5 [ 16]: CSeq: 102 INVITE [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 7 [158]: Authorization: Digest username="1102",realm="asterisk",nonce="7f38d04b",uri="sip:0011@10.210.12.253",algorithm=MD5,response="e5d99db19fa9e38448c23f966abd8d97" [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 8 [ 45]: Contact: "1102" [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 9 [ 12]: Expires: 240 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 10 [ 35]: User-Agent: Linksys/SPA962-6.1.3(a) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 11 [ 19]: Content-Length: 403 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 12 [ 61]: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 13 [ 19]: Supported: replaces [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 14 [ 29]: Content-Type: application/sdp [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 15 [ 0]: [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 0 [ 3]: v=0 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 1 [ 44]: o=- 127260648 127260648 IN IP4 10.210.12.104 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 2 [ 3]: s=- [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 3 [ 22]: c=IN IP4 10.210.12.104 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 5 [ 45]: m=audio 16408 RTP/AVP 8 0 2 4 18 96 97 98 101 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 8 [ 23]: a=rtpmap:2 G726-32/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 9 [ 20]: a=rtpmap:4 G723/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 10 [ 22]: a=rtpmap:18 G729a/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 11 [ 24]: a=rtpmap:96 G726-40/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 12 [ 24]: a=rtpmap:97 G726-24/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 13 [ 24]: a=rtpmap:98 G726-16/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 14 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 15 [ 15]: a=fmtp:101 0-15 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 16 [ 10]: a=ptime:30 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Body 17 [ 10]: a=sendrecv [Nov 25 19:01:51] VERBOSE[9366] logger.c: --- (15 headers 18 lines) --- [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: = Found Their Call ID: 78e873b4-613c0a43@10.210.12.104 Their Tag f4e74d0070142167o1 Our tag: as54f894fa [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Nov 25 19:01:51] VERBOSE[9366] logger.c: Sending to 10.210.12.104 : 5060 (NAT) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Initializing initreq for method INVITE - callid 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Using INVITE request as basis request - 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found user '1102' for '1102' [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Setting NAT on RTP to On [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Setting NAT on UDPTL to On [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing session-level SDP o=- 127260648 127260648 IN IP4 10.210.12.104... UNSUPPORTED. [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing session-level SDP s=-... UNSUPPORTED. [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing session-level SDP c=IN IP4 10.210.12.104... OK. [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found RTP audio format 8 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found RTP audio format 0 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found RTP audio format 2 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found RTP audio format 4 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found RTP audio format 18 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found RTP audio format 96 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found RTP audio format 97 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found RTP audio format 98 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found RTP audio format 101 [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found audio description format PCMA for ID 8 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found audio description format PCMU for ID 0 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found audio description format G726-32 for ID 2 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:2 G726-32/8000... OK. [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found audio description format G723 for ID 4 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:4 G723/8000... OK. [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found audio description format G729a for ID 18 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729a/8000... OK. [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found unknown media description format G726-40 for ID 96 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 G726-40/8000... UNSUPPORTED. [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found unknown media description format G726-24 for ID 97 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:97 G726-24/8000... UNSUPPORTED. [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found unknown media description format G726-16 for ID 98 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:98 G726-16/8000... UNSUPPORTED. [Nov 25 19:01:51] VERBOSE[9366] logger.c: Found audio description format telephone-event for ID 101 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED. [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=ptime:30... OK. [Nov 25 19:01:51] VERBOSE[9366] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x90d (g723|ulaw|alaw|g726|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) [Nov 25 19:01:51] VERBOSE[9366] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Nov 25 19:01:51] VERBOSE[9366] logger.c: Peer audio RTP is at port 10.210.12.104:16408 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Peer doesn't provide T.38 UDPTL [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Checking SIP call limits for device 1102 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Updating call counter for incoming call [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Call from peer '1102' is 1 out of 10 [Nov 25 19:01:51] DEBUG[9366] devicestate.c: Notification of state change to be queued on device/channel SIP/1102 [Nov 25 19:01:51] DEBUG[9361] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [Nov 25 19:01:51] DEBUG[9361] chan_sip.c: Checking device state for peer 1102 [Nov 25 19:01:51] DEBUG[9361] devicestate.c: Changing state for SIP/1102 - state 2 (In use) [Nov 25 19:01:51] DEBUG[9389] app_queue.c: Device 'SIP/1102' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 25 19:01:51] VERBOSE[9366] logger.c: Looking for 0011 in internal (domain 10.210.12.253) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: *** Our native formats are 0x8 (alaw) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: *** Our capabilities are 0x8 (alaw) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Nov 25 19:01:51] DEBUG[9362] devicestate.c: No provider found, checking channel drivers for sip - 1102 [Nov 25 19:01:51] DEBUG[9362] chan_sip.c: Checking device state for peer 1102 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: This channel will not be able to handle video. [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: build_route: Contact hop: "1102" [Nov 25 19:01:51] VERBOSE[9366] logger.c: list_route: hop: [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: SIP/1102-00000007: New call is still down.... Trying... [Nov 25 19:01:51] VERBOSE[9366] logger.c: <--- Transmitting (NAT) to 10.210.12.104:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-f837e07b;received=10.210.12.104 From: "1102" ;tag=f4e74d0070142167o1 To: Call-ID: 78e873b4-613c0a43@10.210.12.104 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.6.0.18 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.210.12.104:5060 [Nov 25 19:01:51] DEBUG[9366] devicestate.c: Notification of state change to be queued on device/channel SIP/1102 [Nov 25 19:01:51] DEBUG[9361] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [Nov 25 19:01:51] DEBUG[9361] chan_sip.c: Checking device state for peer 1102 [Nov 25 19:01:51] DEBUG[9361] devicestate.c: Changing state for SIP/1102 - state 2 (In use) [Nov 25 19:01:51] DEBUG[9362] devicestate.c: No provider found, checking channel drivers for sip - 1102 [Nov 25 19:01:51] DEBUG[9362] chan_sip.c: Checking device state for peer 1102 [Nov 25 19:01:51] DEBUG[9389] app_queue.c: Device 'SIP/1102' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 25 19:01:51] DEBUG[9723] pbx.c: Launching 'Set' [Nov 25 19:01:51] VERBOSE[9723] logger.c: -- Executing [0011@internal:1] Set("SIP/1102-00000007", "CALLERID(num)=74956385115") in new stack [Nov 25 19:01:51] DEBUG[9723] pbx.c: Launching 'Dial' [Nov 25 19:01:51] VERBOSE[9723] logger.c: -- Executing [0011@internal:2] Dial("SIP/1102-00000007", "SIP/cisco/00171234567890,100,t") in new stack [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw) [Nov 25 19:01:51] VERBOSE[9723] logger.c: == Using SIP RTP CoS mark 5 [Nov 25 19:01:51] VERBOSE[9723] logger.c: == Using UDPTL CoS mark 5 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Setting NAT on RTP to Off [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Setting NAT on UDPTL to Off [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Nov 25 19:01:51] DEBUG[9723] acl.c: Found IP address for this socket [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.210.12.253:5060 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: *** Our native formats are 0x8 (alaw) [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: *** Joint capabilities are 0x8 (alaw) [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: *** Our capabilities are 0x8 (alaw) [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: This channel will not be able to handle video. [Nov 25 19:01:51] DEBUG[9723] channel.c: Not copying variable DIALEDTIME. [Nov 25 19:01:51] DEBUG[9723] channel.c: Not copying variable ANSWEREDTIME. [Nov 25 19:01:51] DEBUG[9723] channel.c: Not copying variable DIALEDPEERNAME. [Nov 25 19:01:51] DEBUG[9723] channel.c: Not copying variable DIALEDPEERNUMBER. [Nov 25 19:01:51] DEBUG[9723] channel.c: Not copying variable DIALSTATUS. [Nov 25 19:01:51] DEBUG[9723] channel.c: Not copying variable SIPCALLID. [Nov 25 19:01:51] DEBUG[9723] channel.c: Not copying variable SIPDOMAIN. [Nov 25 19:01:51] DEBUG[9723] channel.c: Not copying variable SIPURI. [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Outgoing Call for 00171234567890 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Updating call counter for outgoing call [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: False Text flag: False [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: ** Our prefcodec: 0x8 (alaw) [Nov 25 19:01:51] VERBOSE[9723] logger.c: Audio is at 10.210.12.253 port 19132 [Nov 25 19:01:51] VERBOSE[9723] logger.c: Adding codec 0x8 (alaw) to SDP [Nov 25 19:01:51] VERBOSE[9723] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: -- Done with adding codecs to SDP [Nov 25 19:01:51] DEBUG[9723] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=61) [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Initializing initreq for method INVITE - callid 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 0 [ 46]: INVITE sip:00171234567890@10.250.10.40 SIP/2.0 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 1 [ 64]: Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK5bbeaf15;rport [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 3 [ 59]: From: "1102" ;tag=as12a9653e [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 4 [ 37]: To: [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 5 [ 40]: Contact: [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 6 [ 55]: Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 8 [ 33]: User-Agent: Asterisk PBX 1.6.0.18 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 9 [ 35]: Date: Wed, 25 Nov 2009 16:01:51 GMT [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 13 [ 19]: Content-Length: 239 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Header 14 [ 0]: [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Body 0 [ 3]: v=0 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Body 1 [ 49]: o=root 1612217910 1612217910 IN IP4 10.210.12.253 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Body 2 [ 23]: s=Asterisk PBX 1.6.0.18 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Body 3 [ 22]: c=IN IP4 10.210.12.253 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Body 5 [ 27]: m=audio 19132 RTP/AVP 8 101 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Body 6 [ 20]: a=rtpmap:8 PCMA/8000 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Body 9 [ 10]: a=ptime:20 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Body 10 [ 10]: a=sendrecv [Nov 25 19:01:51] VERBOSE[9723] logger.c: Reliably Transmitting (no NAT) to 10.250.10.40:5060: INVITE sip:00171234567890@10.250.10.40 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK5bbeaf15;rport Max-Forwards: 70 From: "1102" ;tag=as12a9653e To: Contact: Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.6.0.18 Date: Wed, 25 Nov 2009 16:01:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Type: application/sdp Content-Length: 239 v=0 o=root 1612217910 1612217910 IN IP4 10.210.12.253 s=Asterisk PBX 1.6.0.18 c=IN IP4 10.210.12.253 t=0 0 m=audio 19132 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #72 [Nov 25 19:01:51] DEBUG[9723] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.250.10.40:5060 [Nov 25 19:01:51] VERBOSE[9723] logger.c: -- Called cisco/00171234567890 [Nov 25 19:01:51] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.250.10.40:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK5bbeaf15;rport;received=10.250.10.98 From: "1102" ;tag=as12a9653e To: Date: Wed, 25 Nov 2009 16:01:51 GMT Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow-Events: telephone-event Content-Length: 0 <-------------> [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 1 [ 85]: Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK5bbeaf15;rport;received=10.250.10.98 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 2 [ 59]: From: "1102" ;tag=as12a9653e [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 3 [ 37]: To: [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 4 [ 35]: Date: Wed, 25 Nov 2009 16:01:51 GMT [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 5 [ 55]: Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 8 [ 29]: Allow-Events: telephone-event [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: Header 10 [ 0]: [Nov 25 19:01:51] VERBOSE[9366] logger.c: --- (10 headers 0 lines) --- [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: = Found Their Call ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Their Tag Our tag: as12a9653e [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: *** SIP TIMER: Cancelling retransmission #72 - INVITE (got response) [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '00366da60e319fe44eb30544293fedb3@10.210.12.253' Request 102: Found [Nov 25 19:01:51] DEBUG[9366] chan_sip.c: SIP response 100 to standard invite [Nov 25 19:01:53] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.210.12.104:5062 ---> NOTIFY sip:10.210.12.253 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.104:5062;branch=z9hG4bK-2cef8e33 From: "1103" ;tag=862c59ccf7d9c8a4o2 To: Call-ID: 73f07ccc-baac01a4@10.210.12.104 CSeq: 90411 NOTIFY Max-Forwards: 70 Contact: "1103" Event: keep-alive User-Agent: Linksys/SPA962-6.1.3(a) Content-Length: 0 <-------------> [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 0 [ 32]: NOTIFY sip:10.210.12.253 SIP/2.0 [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.210.12.104:5062;branch=z9hG4bK-2cef8e33 [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 2 [ 60]: From: "1103" ;tag=862c59ccf7d9c8a4o2 [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 3 [ 23]: To: [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 4 [ 40]: Call-ID: 73f07ccc-baac01a4@10.210.12.104 [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 5 [ 18]: CSeq: 90411 NOTIFY [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 7 [ 45]: Contact: "1103" [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 8 [ 17]: Event: keep-alive [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 9 [ 35]: User-Agent: Linksys/SPA962-6.1.3(a) [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Header 11 [ 0]: [Nov 25 19:01:53] VERBOSE[9366] logger.c: --- (11 headers 0 lines) --- [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: = No match Their Call ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Their Tag Our tag: as12a9653e [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: = No match Their Call ID: 78e873b4-613c0a43@10.210.12.104 Their Tag f4e74d0070142167o1 Our tag: as422c6c20 [Nov 25 19:01:53] DEBUG[9366] acl.c: Found IP address for this socket [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.210.12.253:5060 [Nov 25 19:01:53] VERBOSE[9366] logger.c: <--- Transmitting (no NAT) to 10.210.12.104:5062 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 10.210.12.104:5062;branch=z9hG4bK-2cef8e33;received=10.210.12.104 From: "1103" ;tag=862c59ccf7d9c8a4o2 To: ;tag=as0aa8faf7 Call-ID: 73f07ccc-baac01a4@10.210.12.104 CSeq: 90411 NOTIFY User-Agent: Asterisk PBX 1.6.0.18 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Trying to put 'SIP/2.0 489' onto UDP socket destined for 10.210.12.104:5062 [Nov 25 19:01:53] DEBUG[9366] chan_sip.c: Invalid SIP message - rejected , no callid, len 386 [Nov 25 19:01:54] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.250.10.40:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK5bbeaf15;rport;received=10.250.10.98 From: "1102" ;tag=as12a9653e To: ;tag=B9DEFF34-1267 Date: Wed, 25 Nov 2009 16:01:51 GMT Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Contact: Content-Type: application/sdp Content-Disposition: session;handling=required Content-Length: 268 v=0 o=CiscoSystemsSIP-GW-UserAgent 5882 8779 IN IP4 10.250.10.40 s=SIP Call c=IN IP4 10.250.10.40 t=0 0 m=audio 19590 RTP/AVP 8 101 c=IN IP4 10.250.10.40 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=direction:passive <-------------> [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 0 [ 28]: SIP/2.0 183 Session Progress [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 1 [ 85]: Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK5bbeaf15;rport;received=10.250.10.98 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 2 [ 59]: From: "1102" ;tag=as12a9653e [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 3 [ 55]: To: ;tag=B9DEFF34-1267 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 4 [ 35]: Date: Wed, 25 Nov 2009 16:01:51 GMT [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 5 [ 55]: Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 8 [ 97]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 9 [ 29]: Allow-Events: telephone-event [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 10 [ 44]: Contact: [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 12 [ 46]: Content-Disposition: session;handling=required [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 13 [ 19]: Content-Length: 268 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Header 14 [ 0]: [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 0 [ 3]: v=0 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 1 [ 60]: o=CiscoSystemsSIP-GW-UserAgent 5882 8779 IN IP4 10.250.10.40 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 2 [ 10]: s=SIP Call [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 3 [ 21]: c=IN IP4 10.250.10.40 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 5 [ 27]: m=audio 19590 RTP/AVP 8 101 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 6 [ 21]: c=IN IP4 10.250.10.40 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 9 [ 15]: a=fmtp:101 0-16 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Body 11 [ 19]: a=direction:passive [Nov 25 19:01:54] VERBOSE[9366] logger.c: --- (14 headers 12 lines) --- [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: = Found Their Call ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Their Tag Our tag: as12a9653e [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '00366da60e319fe44eb30544293fedb3@10.210.12.253' Request 102: Found [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: SIP response 183 to standard invite [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Processing session-level SDP o=CiscoSystemsSIP-GW-UserAgent 5882 8779 IN IP4 10.250.10.40... UNSUPPORTED. [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED. [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Processing session-level SDP c=IN IP4 10.250.10.40... OK. [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED. [Nov 25 19:01:54] VERBOSE[9366] logger.c: Found RTP audio format 8 [Nov 25 19:01:54] VERBOSE[9366] logger.c: Found RTP audio format 101 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 10.250.10.40... OK. [Nov 25 19:01:54] VERBOSE[9366] logger.c: Found audio description format PCMA for ID 8 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Nov 25 19:01:54] VERBOSE[9366] logger.c: Found audio description format telephone-event for ID 101 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED. [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Nov 25 19:01:54] VERBOSE[9366] logger.c: Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) [Nov 25 19:01:54] VERBOSE[9366] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Nov 25 19:01:54] VERBOSE[9366] logger.c: Peer audio RTP is at port 10.250.10.40:19590 [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: Peer doesn't provide T.38 UDPTL [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: We're settling with these formats: 0x8 (alaw) [Nov 25 19:01:54] DEBUG[9366] chan_sip.c: We have an owner, now see if we need to change this call [Nov 25 19:01:54] VERBOSE[9723] logger.c: -- SIP/cisco-00000008 is making progress passing it to SIP/1102-00000007 [Nov 25 19:01:54] DEBUG[9723] chan_sip.c: Setting framing from config on incoming call [Nov 25 19:01:54] DEBUG[9723] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True [Nov 25 19:01:54] DEBUG[9723] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Nov 25 19:01:54] VERBOSE[9723] logger.c: Audio is at 10.210.12.253 port 13392 [Nov 25 19:01:54] VERBOSE[9723] logger.c: Adding codec 0x8 (alaw) to SDP [Nov 25 19:01:54] VERBOSE[9723] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Nov 25 19:01:54] DEBUG[9723] chan_sip.c: -- Done with adding codecs to SDP [Nov 25 19:01:54] DEBUG[9723] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26) [Nov 25 19:01:54] DEBUG[9723] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Nov 25 19:01:54] VERBOSE[9723] logger.c: <--- Transmitting (NAT) to 10.210.12.104:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-f837e07b;received=10.210.12.104 From: "1102" ;tag=f4e74d0070142167o1 To: ;tag=as422c6c20 Call-ID: 78e873b4-613c0a43@10.210.12.104 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.6.0.18 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 237 v=0 o=root 135072796 135072796 IN IP4 10.210.12.253 s=Asterisk PBX 1.6.0.18 c=IN IP4 10.210.12.253 t=0 0 m=audio 13392 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Nov 25 19:01:54] DEBUG[9723] chan_sip.c: Trying to put 'SIP/2.0 183' onto UDP socket destined for 10.210.12.104:5060 [Nov 25 19:01:55] DEBUG[9723] rtp.c: Ooh, format changed from unknown to alaw [Nov 25 19:01:55] DEBUG[9723] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [Nov 25 19:01:55] DEBUG[9723] rtp.c: Ooh, format changed from unknown to alaw [Nov 25 19:01:55] DEBUG[9723] rtp.c: Created smoother: format: 8 ms: 20 len: 160 [Nov 25 19:01:56] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.250.10.40:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK5bbeaf15;rport;received=10.250.10.98 From: "1102" ;tag=as12a9653e To: ;tag=B9DEFF34-1267 Date: Wed, 25 Nov 2009 16:01:51 GMT Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Contact: Supported: replaces Content-Type: application/sdp Content-Disposition: session;handling=required Content-Length: 268 v=0 o=CiscoSystemsSIP-GW-UserAgent 5882 8779 IN IP4 10.250.10.40 s=SIP Call c=IN IP4 10.250.10.40 t=0 0 m=audio 19590 RTP/AVP 8 101 c=IN IP4 10.250.10.40 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=direction:passive <-------------> [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 1 [ 85]: Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK5bbeaf15;rport;received=10.250.10.98 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 2 [ 59]: From: "1102" ;tag=as12a9653e [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 3 [ 55]: To: ;tag=B9DEFF34-1267 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 4 [ 35]: Date: Wed, 25 Nov 2009 16:01:51 GMT [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 5 [ 55]: Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 8 [ 97]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 9 [ 29]: Allow-Events: telephone-event [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 10 [ 44]: Contact: [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 11 [ 19]: Supported: replaces [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 13 [ 46]: Content-Disposition: session;handling=required [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 14 [ 19]: Content-Length: 268 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 15 [ 0]: [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 0 [ 3]: v=0 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 1 [ 60]: o=CiscoSystemsSIP-GW-UserAgent 5882 8779 IN IP4 10.250.10.40 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 2 [ 10]: s=SIP Call [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 3 [ 21]: c=IN IP4 10.250.10.40 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 5 [ 27]: m=audio 19590 RTP/AVP 8 101 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 6 [ 21]: c=IN IP4 10.250.10.40 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 9 [ 15]: a=fmtp:101 0-16 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 10 [ 10]: a=ptime:20 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Body 11 [ 19]: a=direction:passive [Nov 25 19:01:56] VERBOSE[9366] logger.c: --- (15 headers 12 lines) --- [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: = Found Their Call ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Their Tag B9DEFF34-1267 Our tag: as12a9653e [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Acked pending invite 102 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Stopping retransmission on '00366da60e319fe44eb30544293fedb3@10.210.12.253' of Request 102: Match Found [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: SIP response 200 to standard invite [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED. [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Call 00366da60e319fe44eb30544293fedb3@10.210.12.253 responded to our reinvite without changing SDP version; ignoring SDP. [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Updating call counter for outgoing call [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: build_route: Contact hop: [Nov 25 19:01:56] VERBOSE[9366] logger.c: list_route: hop: [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Strict routing enforced for session 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:01:56] VERBOSE[9366] logger.c: set_destination: Parsing for address/port to send to [Nov 25 19:01:56] VERBOSE[9366] logger.c: set_destination: set destination to 10.250.10.40, port 5060 [Nov 25 19:01:56] VERBOSE[9366] logger.c: Transmitting (no NAT) to 10.250.10.40:5060: ACK sip:71234567890@10.250.10.40:5060 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK006dc7d1;rport Max-Forwards: 70 From: "1102" ;tag=as12a9653e To: ;tag=B9DEFF34-1267 Contact: Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 CSeq: 102 ACK User-Agent: Asterisk PBX 1.6.0.18 Content-Length: 0 --- [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Trying to put 'ACK sip:792' onto UDP socket destined for 10.250.10.40:5060 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Strict routing enforced for session 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:01:56] VERBOSE[9366] logger.c: set_destination: Parsing for address/port to send to [Nov 25 19:01:56] VERBOSE[9366] logger.c: set_destination: set destination to 10.250.10.40, port 5060 [Nov 25 19:01:56] VERBOSE[9366] logger.c: Reliably Transmitting (no NAT) to 10.250.10.40:5060: BYE sip:71234567890@10.250.10.40:5060 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK126d58ae;rport Max-Forwards: 70 From: "1102" ;tag=as12a9653e To: ;tag=B9DEFF34-1267 Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 CSeq: 103 BYE User-Agent: Asterisk PBX 1.6.0.18 X-Asterisk-HangupCause: Unknown X-Asterisk-HangupCauseCode: 0 Content-Length: 0 --- [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #77 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Trying to put 'BYE sip:792' onto UDP socket destined for 10.250.10.40:5060 [Nov 25 19:01:56] VERBOSE[9366] logger.c: Scheduling destruction of SIP dialog '00366da60e319fe44eb30544293fedb3@10.210.12.253' in 32000 ms (Method: INVITE) [Nov 25 19:01:56] DEBUG[9723] devicestate.c: Notification of state change to be queued on device/channel SIP/cisco [Nov 25 19:01:56] VERBOSE[9723] logger.c: -- SIP/cisco-00000008 answered SIP/1102-00000007 [Nov 25 19:01:56] DEBUG[9361] devicestate.c: No provider found, checking channel drivers for SIP - cisco [Nov 25 19:01:56] DEBUG[9361] chan_sip.c: Checking device state for peer cisco [Nov 25 19:01:56] DEBUG[9723] devicestate.c: Notification of state change to be queued on device/channel SIP/1102 [Nov 25 19:01:56] DEBUG[9723] chan_sip.c: SIP answering channel: SIP/1102-00000007 [Nov 25 19:01:56] DEBUG[9361] devicestate.c: Changing state for SIP/cisco - state 1 (Not in use) [Nov 25 19:01:56] DEBUG[9361] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [Nov 25 19:01:56] DEBUG[9723] chan_sip.c: Setting framing from config on incoming call [Nov 25 19:01:56] DEBUG[9361] chan_sip.c: Checking device state for peer 1102 [Nov 25 19:01:56] DEBUG[9723] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True [Nov 25 19:01:56] DEBUG[9361] devicestate.c: Changing state for SIP/1102 - state 2 (In use) [Nov 25 19:01:56] DEBUG[9389] app_queue.c: Device 'SIP/cisco' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 25 19:01:56] DEBUG[9723] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Nov 25 19:01:56] VERBOSE[9723] logger.c: Audio is at 10.210.12.253 port 13392 [Nov 25 19:01:56] VERBOSE[9723] logger.c: Adding codec 0x8 (alaw) to SDP [Nov 25 19:01:56] VERBOSE[9723] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Nov 25 19:01:56] DEBUG[9723] chan_sip.c: -- Done with adding codecs to SDP [Nov 25 19:01:56] DEBUG[9723] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=26) [Nov 25 19:01:56] DEBUG[9723] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw) [Nov 25 19:01:56] VERBOSE[9723] logger.c: <--- Reliably Transmitting (NAT) to 10.210.12.104:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-f837e07b;received=10.210.12.104 From: "1102" ;tag=f4e74d0070142167o1 To: ;tag=as422c6c20 Call-ID: 78e873b4-613c0a43@10.210.12.104 CSeq: 102 INVITE User-Agent: Asterisk PBX 1.6.0.18 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 237 v=0 o=root 135072796 135072797 IN IP4 10.210.12.253 s=Asterisk PBX 1.6.0.18 c=IN IP4 10.210.12.253 t=0 0 m=audio 13392 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> [Nov 25 19:01:56] DEBUG[9723] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #79 [Nov 25 19:01:56] DEBUG[9723] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.210.12.104:5060 [Nov 25 19:01:56] DEBUG[9723] features.c: bridge answer set, chan answer set [Nov 25 19:01:56] DEBUG[9389] app_queue.c: Device 'SIP/1102' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 25 19:01:56] DEBUG[9362] devicestate.c: No provider found, checking channel drivers for sip - 1102 [Nov 25 19:01:56] DEBUG[9362] chan_sip.c: Checking device state for peer 1102 [Nov 25 19:01:56] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.250.10.40:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK126d58ae;rport;received=10.250.10.98 From: "1102" ;tag=as12a9653e To: ;tag=B9DEFF34-1267 Date: Wed, 25 Nov 2009 16:01:56 GMT Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Server: Cisco-SIPGateway/IOS-12.x CSeq: 103 BYE Reason: Q.850;cause=16 Content-Length: 0 <-------------> [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 1 [ 85]: Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK126d58ae;rport;received=10.250.10.98 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 2 [ 59]: From: "1102" ;tag=as12a9653e [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 3 [ 55]: To: ;tag=B9DEFF34-1267 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 4 [ 35]: Date: Wed, 25 Nov 2009 16:01:56 GMT [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 5 [ 55]: Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 7 [ 13]: CSeq: 103 BYE [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 8 [ 22]: Reason: Q.850;cause=16 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 10 [ 0]: [Nov 25 19:01:56] VERBOSE[9366] logger.c: --- (10 headers 0 lines) --- [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: = Found Their Call ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Their Tag B9DEFF34-1267 Our tag: as12a9653e [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #77 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Stopping retransmission on '00366da60e319fe44eb30544293fedb3@10.210.12.253' of Request 103: Match Found [Nov 25 19:01:56] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.210.12.104:5060 ---> ACK sip:0011@10.210.12.253 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-73cffba3 From: "1102" ;tag=f4e74d0070142167o1 To: ;tag=as422c6c20 Call-ID: 78e873b4-613c0a43@10.210.12.104 CSeq: 102 ACK Max-Forwards: 70 Authorization: Digest username="1102",realm="asterisk",nonce="7f38d04b",uri="sip:0011@10.210.12.253",algorithm=MD5,response="e5d99db19fa9e38448c23f966abd8d97" Contact: "1102" User-Agent: Linksys/SPA962-6.1.3(a) Content-Length: 0 <-------------> [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 0 [ 34]: ACK sip:0011@10.210.12.253 SIP/2.0 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-73cffba3 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 2 [ 60]: From: "1102" ;tag=f4e74d0070142167o1 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 3 [ 43]: To: ;tag=as422c6c20 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 4 [ 40]: Call-ID: 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 5 [ 13]: CSeq: 102 ACK [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 7 [158]: Authorization: Digest username="1102",realm="asterisk",nonce="7f38d04b",uri="sip:0011@10.210.12.253",algorithm=MD5,response="e5d99db19fa9e38448c23f966abd8d97" [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 8 [ 45]: Contact: "1102" [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 9 [ 35]: User-Agent: Linksys/SPA962-6.1.3(a) [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Header 11 [ 0]: [Nov 25 19:01:56] VERBOSE[9366] logger.c: --- (11 headers 0 lines) --- [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: = No match Their Call ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Their Tag B9DEFF34-1267 Our tag: as12a9653e [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: = Found Their Call ID: 78e873b4-613c0a43@10.210.12.104 Their Tag f4e74d0070142167o1 Our tag: as422c6c20 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #79 [Nov 25 19:01:56] DEBUG[9366] chan_sip.c: Stopping retransmission on '78e873b4-613c0a43@10.210.12.104' of Response 102: Match Found [Nov 25 19:02:08] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.210.12.104:5062 ---> NOTIFY sip:10.210.12.253 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.104:5062;branch=z9hG4bK-26c821b0 From: "1103" ;tag=862c59ccf7d9c8a4o2 To: Call-ID: 73f07ccc-baac01a4@10.210.12.104 CSeq: 90412 NOTIFY Max-Forwards: 70 Contact: "1103" Event: keep-alive User-Agent: Linksys/SPA962-6.1.3(a) Content-Length: 0 <-------------> [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 0 [ 32]: NOTIFY sip:10.210.12.253 SIP/2.0 [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.210.12.104:5062;branch=z9hG4bK-26c821b0 [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 2 [ 60]: From: "1103" ;tag=862c59ccf7d9c8a4o2 [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 3 [ 23]: To: [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 4 [ 40]: Call-ID: 73f07ccc-baac01a4@10.210.12.104 [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 5 [ 18]: CSeq: 90412 NOTIFY [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 7 [ 45]: Contact: "1103" [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 8 [ 17]: Event: keep-alive [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 9 [ 35]: User-Agent: Linksys/SPA962-6.1.3(a) [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 10 [ 17]: Content-Length: 0 [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Header 11 [ 0]: [Nov 25 19:02:08] VERBOSE[9366] logger.c: --- (11 headers 0 lines) --- [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: = No match Their Call ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Their Tag B9DEFF34-1267 Our tag: as12a9653e [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: = No match Their Call ID: 78e873b4-613c0a43@10.210.12.104 Their Tag f4e74d0070142167o1 Our tag: as422c6c20 [Nov 25 19:02:08] DEBUG[9366] acl.c: Found IP address for this socket [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.210.12.253:5060 [Nov 25 19:02:08] VERBOSE[9366] logger.c: <--- Transmitting (no NAT) to 10.210.12.104:5062 ---> SIP/2.0 489 Bad event Via: SIP/2.0/UDP 10.210.12.104:5062;branch=z9hG4bK-26c821b0;received=10.210.12.104 From: "1103" ;tag=862c59ccf7d9c8a4o2 To: ;tag=as7e5dc6af Call-ID: 73f07ccc-baac01a4@10.210.12.104 CSeq: 90412 NOTIFY User-Agent: Asterisk PBX 1.6.0.18 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Trying to put 'SIP/2.0 489' onto UDP socket destined for 10.210.12.104:5062 [Nov 25 19:02:08] DEBUG[9366] chan_sip.c: Invalid SIP message - rejected , no callid, len 386 [Nov 25 19:02:09] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.210.12.104:5060 ---> BYE sip:0011@10.210.12.253 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-5335584f From: "1102" ;tag=f4e74d0070142167o1 To: ;tag=as422c6c20 Call-ID: 78e873b4-613c0a43@10.210.12.104 CSeq: 103 BYE Max-Forwards: 70 Authorization: Digest username="1102",realm="asterisk",nonce="7f38d04b",uri="sip:0011@10.210.12.253",algorithm=MD5,response="08d086696dbc9b95a1182ef2c0996a64" User-Agent: Linksys/SPA962-6.1.3(a) Content-Length: 0 <-------------> [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 0 [ 34]: BYE sip:0011@10.210.12.253 SIP/2.0 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 1 [ 59]: Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-5335584f [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 2 [ 60]: From: "1102" ;tag=f4e74d0070142167o1 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 3 [ 43]: To: ;tag=as422c6c20 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 4 [ 40]: Call-ID: 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 5 [ 13]: CSeq: 103 BYE [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 7 [158]: Authorization: Digest username="1102",realm="asterisk",nonce="7f38d04b",uri="sip:0011@10.210.12.253",algorithm=MD5,response="08d086696dbc9b95a1182ef2c0996a64" [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 8 [ 35]: User-Agent: Linksys/SPA962-6.1.3(a) [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 10 [ 0]: [Nov 25 19:02:09] VERBOSE[9366] logger.c: --- (10 headers 0 lines) --- [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: = No match Their Call ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Their Tag B9DEFF34-1267 Our tag: as12a9653e [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: = Found Their Call ID: 78e873b4-613c0a43@10.210.12.104 Their Tag f4e74d0070142167o1 Our tag: as422c6c20 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Initializing initreq for method BYE - callid 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:02:09] VERBOSE[9366] logger.c: Sending to 10.210.12.104 : 5060 (NAT) [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Setting SIP_ALREADYGONE on dialog 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Received bye, issuing owner hangup [Nov 25 19:02:09] VERBOSE[9366] logger.c: <--- Transmitting (NAT) to 10.210.12.104:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.210.12.104:5060;branch=z9hG4bK-5335584f;received=10.210.12.104 From: "1102" ;tag=f4e74d0070142167o1 To: ;tag=as422c6c20 Call-ID: 78e873b4-613c0a43@10.210.12.104 CSeq: 103 BYE User-Agent: Asterisk PBX 1.6.0.18 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.210.12.104:5060 [Nov 25 19:02:09] DEBUG[9723] channel.c: Didn't get a frame from channel: SIP/1102-00000007 [Nov 25 19:02:09] DEBUG[9723] channel.c: Bridge stops bridging channels SIP/1102-00000007 and SIP/cisco-00000008 [Nov 25 19:02:09] DEBUG[9723] pbx.c: Launching 'NoOp' [Nov 25 19:02:09] VERBOSE[9723] logger.c: -- Executing [h@internal:1] NoOp("SIP/1102-00000007", "Hangup in internal") in new stack [Nov 25 19:02:09] DEBUG[9723] cdr_addon_mysql.c: Inserting a CDR record. [Nov 25 19:02:09] DEBUG[9723] cdr_addon_mysql.c: SQL command as follows: INSERT INTO cdr (calldate,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,uniqueid) VALUES ('2009-11-25 19:01:51','1102','0011','internal','SIP/1102-00000007','SIP/cisco-00000008','Dial','SIP/cisco/00171234567890,100,t','18','13','ANSWERED','3','1259164911.7') [Nov 25 19:02:09] DEBUG[9723] channel.c: Hanging up channel 'SIP/cisco-00000008' [Nov 25 19:02:09] DEBUG[9723] chan_sip.c: Hangup call SIP/cisco-00000008, SIP callid 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:02:09] VERBOSE[9723] logger.c: Scheduling destruction of SIP dialog '00366da60e319fe44eb30544293fedb3@10.210.12.253' in 32000 ms (Method: INVITE) [Nov 25 19:02:09] DEBUG[9723] chan_sip.c: Strict routing enforced for session 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:02:09] VERBOSE[9723] logger.c: set_destination: Parsing for address/port to send to [Nov 25 19:02:09] VERBOSE[9723] logger.c: set_destination: set destination to 10.250.10.40, port 5060 [Nov 25 19:02:09] VERBOSE[9723] logger.c: Reliably Transmitting (no NAT) to 10.250.10.40:5060: BYE sip:71234567890@10.250.10.40:5060 SIP/2.0 Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK7c0fa500;rport Max-Forwards: 70 From: "1102" ;tag=as12a9653e To: ;tag=B9DEFF34-1267 Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 CSeq: 104 BYE User-Agent: Asterisk PBX 1.6.0.18 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Nov 25 19:02:09] DEBUG[9723] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #81 [Nov 25 19:02:09] DEBUG[9723] chan_sip.c: Trying to put 'BYE sip:792' onto UDP socket destined for 10.250.10.40:5060 [Nov 25 19:02:09] DEBUG[9723] devicestate.c: Notification of state change to be queued on device/channel SIP/cisco [Nov 25 19:02:09] DEBUG[9723] rtp.c: Channel '' has no RTP, not doing anything [Nov 25 19:02:09] DEBUG[9723] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Nov 25 19:02:09] DEBUG[9723] pbx.c: Spawn extension (internal,0011,2) exited non-zero on 'SIP/1102-00000007' [Nov 25 19:02:09] VERBOSE[9723] logger.c: == Spawn extension (internal, 0011, 2) exited non-zero on 'SIP/1102-00000007' [Nov 25 19:02:09] DEBUG[9723] channel.c: Soft-Hanging up channel 'SIP/1102-00000007' [Nov 25 19:02:09] DEBUG[9723] channel.c: Hanging up channel 'SIP/1102-00000007' [Nov 25 19:02:09] DEBUG[9723] chan_sip.c: Hangup call SIP/1102-00000007, SIP callid 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:02:09] DEBUG[9723] chan_sip.c: update_call_counter(1102) - decrement call limit counter on hangup [Nov 25 19:02:09] DEBUG[9723] chan_sip.c: Updating call counter for incoming call [Nov 25 19:02:09] DEBUG[9723] chan_sip.c: Call from peer '1102' removed from call limit 10 [Nov 25 19:02:09] DEBUG[9723] devicestate.c: Notification of state change to be queued on device/channel SIP/1102 [Nov 25 19:02:09] DEBUG[9723] devicestate.c: Notification of state change to be queued on device/channel SIP/1102 [Nov 25 19:02:09] DEBUG[9361] devicestate.c: No provider found, checking channel drivers for SIP - cisco [Nov 25 19:02:09] DEBUG[9361] chan_sip.c: Checking device state for peer cisco [Nov 25 19:02:09] DEBUG[9361] devicestate.c: Changing state for SIP/cisco - state 1 (Not in use) [Nov 25 19:02:09] DEBUG[9361] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [Nov 25 19:02:09] DEBUG[9361] chan_sip.c: Checking device state for peer 1102 [Nov 25 19:02:09] DEBUG[9361] devicestate.c: Changing state for SIP/1102 - state 1 (Not in use) [Nov 25 19:02:09] DEBUG[9361] devicestate.c: No provider found, checking channel drivers for SIP - 1102 [Nov 25 19:02:09] DEBUG[9361] chan_sip.c: Checking device state for peer 1102 [Nov 25 19:02:09] DEBUG[9361] devicestate.c: Changing state for SIP/1102 - state 1 (Not in use) [Nov 25 19:02:09] DEBUG[9362] devicestate.c: No provider found, checking channel drivers for sip - 1102 [Nov 25 19:02:09] DEBUG[9362] chan_sip.c: Checking device state for peer 1102 [Nov 25 19:02:09] DEBUG[9362] devicestate.c: No provider found, checking channel drivers for sip - 1102 [Nov 25 19:02:09] DEBUG[9362] chan_sip.c: Checking device state for peer 1102 [Nov 25 19:02:09] DEBUG[9389] app_queue.c: Device 'SIP/cisco' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 25 19:02:09] DEBUG[9389] app_queue.c: Device 'SIP/1102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 25 19:02:09] DEBUG[9389] app_queue.c: Device 'SIP/1102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 25 19:02:09] VERBOSE[9366] logger.c: <--- SIP read from UDP://10.250.10.40:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK7c0fa500;rport;received=10.250.10.98 From: "1102" ;tag=as12a9653e To: ;tag=B9DEFF34-1267 Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 CSeq: 104 BYE Content-Length: 0 <-------------> [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 1 [ 85]: Via: SIP/2.0/UDP 10.210.12.253:5060;branch=z9hG4bK7c0fa500;rport;received=10.250.10.98 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 2 [ 59]: From: "1102" ;tag=as12a9653e [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 3 [ 55]: To: ;tag=B9DEFF34-1267 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 4 [ 55]: Call-ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 5 [ 13]: CSeq: 104 BYE [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 6 [ 17]: Content-Length: 0 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Header 7 [ 0]: [Nov 25 19:02:09] VERBOSE[9366] logger.c: --- (7 headers 0 lines) --- [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: = Found Their Call ID: 00366da60e319fe44eb30544293fedb3@10.210.12.253 Their Tag B9DEFF34-1267 Our tag: as12a9653e [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #81 [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Stopping retransmission on '00366da60e319fe44eb30544293fedb3@10.210.12.253' of Request 104: Match Found [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Destroying SIP dialog 00366da60e319fe44eb30544293fedb3@10.210.12.253 [Nov 25 19:02:09] VERBOSE[9366] logger.c: Really destroying SIP dialog '00366da60e319fe44eb30544293fedb3@10.210.12.253' Method: INVITE [Nov 25 19:02:09] DEBUG[9366] chan_sip.c: Destroying SIP dialog 78e873b4-613c0a43@10.210.12.104 [Nov 25 19:02:09] VERBOSE[9366] logger.c: Really destroying SIP dialog '78e873b4-613c0a43@10.210.12.104' Method: BYE [Nov 25 19:02:13] VERBOSE[9722] logger.c: -- Remote UNIX connection disconnected [Nov 25 19:02:23] VERBOSE[9366] logger.c: