*CLI> core set debug 100 Core debug was 19 and is now 100 *CLI> core set verbose 100 Verbosity was 19 and is now 100 *CLI> sip set debug 100 SIP Debugging enabled *CLI> *CLI> <--- SIP read from 195.94.224.220:50148 ---> INVITE sip:74952232731@195.94.224.196:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 195.94.224.220:5060 From: ;tag=112ADBB4-67A To: Date: Tue, 27 Mar 2007 12:10:35 GMT Call-ID: 9C57A1-DB9311DB-B46FC974-50F5039D@195.94.224.220 Supported: 100rel Cisco-Guid: 10206073-3683848667-3027093876-1358234525 User-Agent: Cisco-SIPGateway/IOS-12.x CSeq: 101 INVITE Max-Forwards: 6 Timestamp: 1174997435 Contact: Expires: 180 Content-Type: application/sdp Content-Length: 242 v=0 o=CiscoSystemsSIP-GW-UserAgent 8215 2564 IN IP4 195.94.224.220 s=SIP Call c=IN IP4 195.94.224.220 t=0 0 m=audio 19086 RTP/AVP 18 8 101 a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 0 [ 61]: INVITE sip:74952232731@195.94.224.196:5060;user=phone SIP/2.0 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 1 [ 37]: Via: SIP/2.0/UDP 195.94.224.220:5060 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 2 [ 54]: From: ;tag=112ADBB4-67A [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 3 [ 47]: To: [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 4 [ 35]: Date: Tue, 27 Mar 2007 12:10:35 GMT [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 5 [ 57]: Call-ID: 9C57A1-DB9311DB-B46FC974-50F5039D@195.94.224.220 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 6 [ 17]: Supported: 100rel [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 7 [ 53]: Cisco-Guid: 10206073-3683848667-3027093876-1358234525 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 8 [ 37]: User-Agent: Cisco-SIPGateway/IOS-12.x [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 9 [ 16]: CSeq: 101 INVITE [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 10 [ 15]: Max-Forwards: 6 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 11 [ 21]: Timestamp: 1174997435 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 12 [ 56]: Contact: [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 13 [ 12]: Expires: 180 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 14 [ 29]: Content-Type: application/sdp [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 15 [ 19]: Content-Length: 242 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 16 [ 0]: [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Body 0 [ 3]: v=0 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Body 1 [ 62]: o=CiscoSystemsSIP-GW-UserAgent 8215 2564 IN IP4 195.94.224.220 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Body 2 [ 10]: s=SIP Call [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Body 3 [ 23]: c=IN IP4 195.94.224.220 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Body 4 [ 5]: t=0 0 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Body 5 [ 30]: m=audio 19086 RTP/AVP 18 8 101 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Body 6 [ 21]: a=rtpmap:18 G729/8000 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Body 9 [ 15]: a=fmtp:101 0-15 --- (16 headers 10 lines) --- [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:2846 do_setnat: Setting NAT on RTP to Off [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:2851 do_setnat: Setting NAT on VRTP to Off [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4667 sip_alloc: Allocating new SIP dialog for 9C57A1-DB9311DB-B46FC974-50F5039D@195.94.224.220 - INVITE (With RTP) [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:15368 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:1831 parse_sip_options: Begin: parsing SIP "Supported: 100rel" [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:1839 parse_sip_options: Found SIP option: -100rel- [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:1845 parse_sip_options: Matched SIP option: 100rel Sending to 195.94.224.220 : 5060 (no NAT) [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:13998 handle_request_invite: Initializing initreq for method INVITE - callid 9C57A1-DB9311DB-B46FC974-50F5039D@195.94.224.220 Using INVITE request as basis request - 9C57A1-DB9311DB-B46FC974-50F5039D@195.94.224.220 [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '4992711790' No user '4992711790' in SIP users list [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE host = '195.94.224.220' [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:16664 build_peer: -REALTIME- peer built. Name: cisco2. Peer objects: 1 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:2718 realtime_peer: -REALTIME- loading peer from database to memory. Name: cisco2. Peer objects: 1 Found peer 'cisco2' for '4992711790' from 195.94.224.220:50148 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:2846 do_setnat: Setting NAT on RTP to Off [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:2851 do_setnat: Setting NAT on VRTP to Off [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:2588 sip_destroy_peer: Destroying SIP peer cisco2 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:2616 sip_destroy_peer: -REALTIME- peer Destroyed. Name: cisco2. Realtime Peer objects: 0 Found RTP audio format 18 Found RTP audio format 8 Found RTP audio format 101 Peer audio RTP is at port 195.94.224.220:19086 Found description format G729 for ID 18 Found description format PCMA for ID 8 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:5537 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x108 (alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x8 (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 195.94.224.220:19086 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:5628 process_sdp: We're settling with these formats: 0x8 (alaw) [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:14079 handle_request_invite: Checking SIP call limits for device [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:3309 update_call_counter: Updating call counter for incoming call Looking for 74952232731 in default (domain 195.94.224.196) [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '74952232731' AND context = 'default' AND priority = '1' [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4130 sip_new: *** Our native formats are 0x8 (alaw) [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4131 sip_new: *** Joint capabilities are 0x8 (alaw) [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4132 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4133 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4163 sip_new: This channel will not be able to handle video. [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:8494 build_route: build_route: Contact hop: list_route: hop: [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:14154 handle_request_invite: SIP/195.94.224.220-081e84f8: New call is still down.... Trying... <--- Transmitting (no NAT) to 195.94.224.220:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 195.94.224.220:5060;received=195.94.224.220 From: ;tag=112ADBB4-67A To: Call-ID: 9C57A1-DB9311DB-B46FC974-50F5039D@195.94.224.220 CSeq: 101 INVITE User-Agent: Asterisk PBX SVN-trunk-r57993M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 27 16:17:39] DEBUG[30987]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/195.94.224.220-081e84f8 [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '74952232731' AND context = 'default' AND priority = '1' [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '74952232731' AND context = 'default' AND priority = '1' [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '74952232731' AND context = 'default' AND priority = '1' [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions WHERE exten = '74952232731' AND context = 'default' AND priority = '1' -- Executing AGI("SIP/195.94.224.220-081e84f8", "vc-admin") -- Launched AGI Script /var/lib/asterisk/agi-bin/vc-admin [Mar 27 16:17:39] DEBUG[30987]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 195.94.224.220 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:16000 sip_devicestate: Checking device state for peer 195.94.224.220 [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '195.94.224.220' [Mar 27 16:17:39] DEBUG[30987]: devicestate.c:428 do_state_change: Changing state for SIP/195.94.224.220 - state 2 (In use) [Mar 27 16:17:39] DEBUG[30987]: app_queue.c:568 changethread: Device 'SIP/195.94.224.220' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 27 16:17:39] DEBUG[30987]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/195.94.224.220-081e84f8 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:3765 sip_answer: SIP answering channel: SIP/195.94.224.220-081e84f8 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:6958 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:6680 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:6682 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 195.94.224.196 port 14932 Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:6843 add_sdp: -- Done with adding codecs to SDP [Mar 27 16:17:39] DEBUG[30987]: channel.c:2325 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=22) [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:6903 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) <--- Reliably Transmitting (no NAT) to 195.94.224.220:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 195.94.224.220:5060;received=195.94.224.220 From: ;tag=112ADBB4-67A To: ;tag=as5ea8559c Call-ID: 9C57A1-DB9311DB-B46FC974-50F5039D@195.94.224.220 CSeq: 101 INVITE User-Agent: Asterisk PBX SVN-trunk-r57993M Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 244 v=0 o=root 30984 30984 IN IP4 195.94.224.196 s=session c=IN IP4 195.94.224.196 t=0 0 m=audio 14932 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:2117 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1 [Mar 27 16:17:39] DEBUG[30987]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 195.94.224.220 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:16000 sip_devicestate: Checking device state for peer 195.94.224.220 [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:809 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 27 16:17:39] DEBUG[30987]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '195.94.224.220' [Mar 27 16:17:39] DEBUG[30987]: devicestate.c:428 do_state_change: Changing state for SIP/195.94.224.220 - state 2 (In use) [Mar 27 16:17:39] DEBUG[30987]: app_queue.c:568 changethread: Device 'SIP/195.94.224.220' changed to state '2' (In use) but we don't care because they're not a member of any queue. <--- SIP read from 195.94.224.220:53720 ---> ACK sip:74952232731@195.94.224.196:5060 SIP/2.0 Via: SIP/2.0/UDP 195.94.224.220:5060 From: ;tag=112ADBB4-67A To: ;tag=as5ea8559c Date: Tue, 27 Mar 2007 12:10:35 GMT Call-ID: 9C57A1-DB9311DB-B46FC974-50F5039D@195.94.224.220 Max-Forwards: 6 Content-Length: 0 CSeq: 101 ACK <-------------> [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 0 [ 47]: ACK sip:74952232731@195.94.224.196:5060 SIP/2.0 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 1 [ 37]: Via: SIP/2.0/UDP 195.94.224.220:5060 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 2 [ 54]: From: ;tag=112ADBB4-67A [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 3 [ 62]: To: ;tag=as5ea8559c [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 4 [ 35]: Date: Tue, 27 Mar 2007 12:10:35 GMT [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 5 [ 57]: Call-ID: 9C57A1-DB9311DB-B46FC974-50F5039D@195.94.224.220 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 6 [ 15]: Max-Forwards: 6 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 7 [ 17]: Content-Length: 0 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 8 [ 13]: CSeq: 101 ACK [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4945 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:4731 find_call: = Found Their Call ID: 9C57A1-DB9311DB-B46FC974-50F5039D@195.94.224.220 Their Tag 112ADBB4-67A Our tag: as5ea8559c [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:15368 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:2225 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1 [Mar 27 16:17:39] DEBUG[30987]: chan_sip.c:2236 __sip_ack: Stopping retransmission on '9C57A1-DB9311DB-B46FC974-50F5039D@195.94.224.220' of Response 101: Match Found testtesttest vc-admin: Playing welcome message... [Mar 27 16:17:39] DEBUG[30987]: channel.c:2791 set_format: Set channel SIP/195.94.224.220-081e84f8 to write format ulaw -- Playing 'silence/2' (escape_digits=0123456789) (sample_offset 0)