[Feb 12 16:19:27] VERBOSE[30059] chan_sip.c: ÿ<--- SIP read from UDP:10.10.19.28:54113 ---> ÿINVITE sip:999017@10.10.19.3:5060 SIP/2.0 ÿVia: SIP/2.0/UDP 10.10.19.28:5060;x-route-tag="cid:15817@10.10.19.28";branch=z9hG4bK1DA6F6 ÿRemote-Party-ID: ;party=calling;screen=no;privacy=off ÿFrom: ;tag=33F281F0-1DFB ÿTo: ÿDate: Wed, 12 Feb 2014 16:19:27 GMT ÿCall-ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 ÿSupported: 100rel,timer,resource-priority,replaces,sdp-anat ÿMin-SE: 1800 ÿCisco-Guid: 1199460414-2469925347-2160491625-4139583488 ÿUser-Agent: Cisco-SIPGateway/IOS-15.2.4.M4 ÿAllow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER ÿCSeq: 101 INVITE ÿMax-Forwards: 70 ÿTimestamp: 1392221967 ÿContact: ÿExpires: 180 ÿAllow-Events: telephone-event ÿContent-Type: application/sdp ÿContent-Disposition: session;handling=required ÿContent-Length: 270 ÿ ÿv=0 ÿo=CiscoSystemsSIP-GW-UserAgent 2628 4435 IN IP4 10.10.19.28 ÿs=SIP Call ÿc=IN IP4 10.10.19.28 ÿt=0 0 ÿm=audio 16752 RTP/AVP 18 101 ÿc=IN IP4 10.10.19.28 ÿa=rtpmap:18 G729/8000 ÿa=fmtp:18 annexb=no ÿa=rtpmap:101 telephone-event/8000 ÿa=fmtp:101 0-16 ÿa=ptime:60 ÿ<-------------> [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 0 [ 42]: INVITE sip:999017@10.10.19.3:5060 SIP/2.0 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 1 [ 92]: Via: SIP/2.0/UDP 10.10.19.28:5060;x-route-tag="cid:15817@10.10.19.28";branch=z9hG4bK1DA6F6 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 2 [ 76]: Remote-Party-ID: ;party=calling;screen=no;privacy=off [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 3 [ 47]: From: ;tag=33F281F0-1DFB [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 4 [ 28]: To: [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 5 [ 35]: Date: Wed, 12 Feb 2014 16:19:27 GMT [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 6 [ 57]: Call-ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 7 [ 59]: Supported: 100rel,timer,resource-priority,replaces,sdp-anat [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 8 [ 12]: Min-SE: 1800 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 9 [ 55]: Cisco-Guid: 1199460414-2469925347-2160491625-4139583488 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 10 [ 42]: User-Agent: Cisco-SIPGateway/IOS-15.2.4.M4 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 11 [ 97]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 12 [ 16]: CSeq: 101 INVITE [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 13 [ 16]: Max-Forwards: 70 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 14 [ 21]: Timestamp: 1392221967 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 15 [ 37]: Contact: [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 16 [ 12]: Expires: 180 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 17 [ 29]: Allow-Events: telephone-event [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 18 [ 29]: Content-Type: application/sdp [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 19 [ 46]: Content-Disposition: session;handling=required [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 20 [ 19]: Content-Length: 270 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Header 21 [ 0]: [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 0 [ 3]: v=0 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 1 [ 60]: o=CiscoSystemsSIP-GW-UserAgent 2628 4435 IN IP4 10.10.19.28 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 2 [ 10]: s=SIP Call [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 3 [ 21]: c=IN IP4 10.10.19.28 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 4 [ 5]: t=0 0 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 5 [ 28]: m=audio 16752 RTP/AVP 18 101 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 6 [ 21]: c=IN IP4 10.10.19.28 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 7 [ 21]: a=rtpmap:18 G729/8000 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 8 [ 19]: a=fmtp:18 annexb=no [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-16 [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Body 11 [ 10]: a=ptime:60 [Feb 12 16:19:27] VERBOSE[30059] chan_sip.c: --- (21 headers 12 lines) --- [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: = Looking for Call ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 (Checking From) --From tag 33F281F0-1DFB --To-tag [Feb 12 16:19:27] DEBUG[30059] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Feb 12 16:19:27] DEBUG[30059] acl.c: For destination '10.10.19.28', our source address is '10.10.19.3'. [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.10.19.3:5060 [Feb 12 16:19:27] DEBUG[30059] netsock2.c: Splitting '10.10.19.28:5060' into... [Feb 12 16:19:27] DEBUG[30059] netsock2.c: ...host '10.10.19.28' and port '5060'. [Feb 12 16:19:27] VERBOSE[30059] chan_sip.c: Sending to 10.10.19.28:5060 (no NAT) [Feb 12 16:19:27] DEBUG[30059] chan_sip.c: Allocating new SIP dialog for 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 - INVITE (No RTP) [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Feb 12 16:19:27] DEBUG[30059][C-0000000a] sip/reqresp_parser.c: Begin: parsing SIP "Supported: 100rel,timer,resource-priority,replaces,sdp-anat" [Feb 12 16:19:27] DEBUG[30059][C-0000000a] sip/reqresp_parser.c: Found SIP option: -100rel- [Feb 12 16:19:27] DEBUG[30059][C-0000000a] sip/reqresp_parser.c: Matched SIP option: 100rel [Feb 12 16:19:27] DEBUG[30059][C-0000000a] sip/reqresp_parser.c: Found SIP option: -timer- [Feb 12 16:19:27] DEBUG[30059][C-0000000a] sip/reqresp_parser.c: Matched SIP option: timer [Feb 12 16:19:27] DEBUG[30059][C-0000000a] sip/reqresp_parser.c: Found SIP option: -resource-priority- [Feb 12 16:19:27] DEBUG[30059][C-0000000a] sip/reqresp_parser.c: Matched SIP option: resource-priority [Feb 12 16:19:27] DEBUG[30059][C-0000000a] sip/reqresp_parser.c: Found SIP option: -replaces- [Feb 12 16:19:27] DEBUG[30059][C-0000000a] sip/reqresp_parser.c: Matched SIP option: replaces [Feb 12 16:19:27] DEBUG[30059][C-0000000a] sip/reqresp_parser.c: Found SIP option: -sdp-anat- [Feb 12 16:19:27] DEBUG[30059][C-0000000a] sip/reqresp_parser.c: Matched SIP option: sdp-anat [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.19.28:5060' into... [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.19.28' and port '5060'. [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: Sending to 10.10.19.28:5060 (no NAT) [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Initializing initreq for method INVITE - callid 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: Using INVITE request as basis request - 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.19.28' into... [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.19.28' and port ''. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '2000' AND host = 'dynamic' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '2000' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE host = '10.10.19.28' AND port = '54113' AND callbackextension = '999017' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE host = '10.10.19.28' AND port = '54113' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE ipaddr = '10.10.19.28' AND port = '54113' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE host = '10.10.19.28' AND insecure LIKE '%port%' ORDER BY host [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE ipaddr = '10.10.19.28' AND insecure LIKE '%port%' ORDER BY ipaddr [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE host = '10.10.19.28' AND port = '54113' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE ipaddr = '10.10.19.28' AND port = '54113' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE host = '10.10.19.28' AND insecure LIKE '%port%' ORDER BY host [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE ipaddr = '10.10.19.28' AND insecure LIKE '%port%' ORDER BY ipaddr [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: No matching peer for '2000' from '10.10.19.28:54113' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fd1040174e8' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_rtp_asterisk.c: Allocated port 13052 for RTP instance '0x7fd1040174e8' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] rtp_engine.c: RTP instance '0x7fd1040174e8' is setup and ready to go [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fd1040174e8' [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] netsock2.c: == Using SIP RTP TOS bits 184 [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] netsock2.c: == Using SIP RTP CoS mark 5 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Setting NAT on RTP to Off [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Processing session-level SDP o=CiscoSystemsSIP-GW-UserAgent 2628 4435 IN IP4 10.10.19.28... OK. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED OR FAILED. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.19.28' into... [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.19.28' and port ''. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Processing session-level SDP c=IN IP4 10.10.19.28... OK. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: Found RTP audio format 18 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] rtp_engine.c: Setting payload 18 based on m type on 0x7fd0ba1ecbe0 [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: Found RTP audio format 101 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] rtp_engine.c: Setting payload 101 based on m type on 0x7fd0ba1ecbe0 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.19.28' into... [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.19.28' and port ''. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 10.10.19.28... OK. [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: Found audio description format G729 for ID 18 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: Found audio description format telephone-event for ID 101 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP a=ptime:60... OK. [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: Capabilities: us - (g729), peer - audio=(g729)/video=(nothing)/text=(nothing), combined - (g729) [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fd1040174e8' [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: Peer audio RTP is at port 10.10.19.28:16752 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] rtp_engine.c: Copying payload 18 from 0x7fd0ba1ecbe0 to 0x7fd1040176b0 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] rtp_engine.c: Copying payload 101 from 0x7fd0ba1ecbe0 to 0x7fd1040176b0 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fd1040174e8' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: We're settling with these formats: (g729) [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Checking SIP call limits for device [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Updating call counter for incoming call [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.19.3:5060' into... [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.19.3' and port ''. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.19.28' into... [Feb 12 16:19:27] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.19.28' and port ''. [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: Looking for 999017 in default (domain 10.10.19.3) [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: *** Our native formats are (g729) [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: *** Joint capabilities are (g729) [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: *** Our capabilities are (g729) [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: *** AST_CODEC_CHOOSE formats are g729 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: This channel will not be able to handle video. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: build_route: Contact hop: [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: list_route: hop: [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Incoming INVITE with 'timer' option supported [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: INVITE also has "Min-SE" header. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Received Min-SE: 1800 [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Session timer started: 107 - 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 900000ms [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: SIP/10.10.19.28-00000014: New call is still down.... Trying... [Feb 12 16:19:27] VERBOSE[30059][C-0000000a] chan_sip.c: ÿ<--- Transmitting (no NAT) to 10.10.19.28:5060 ---> ÿSIP/2.0 100 Trying ÿVia: SIP/2.0/UDP 10.10.19.28:5060;x-route-tag="cid:15817@10.10.19.28";branch=z9hG4bK1DA6F6;received=10.10.19.28 ÿFrom: ;tag=33F281F0-1DFB ÿTo: ÿCall-ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 ÿCSeq: 101 INVITE ÿServer: Asterisk Server ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ÿSupported: replaces, timer ÿSession-Expires: 1800;refresher=uas ÿContact: ÿContent-Length: 0 ÿ ÿ ÿ<------------> [Feb 12 16:19:27] DEBUG[30059][C-0000000a] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 10.10.19.28:5060 [Feb 12 16:19:27] DEBUG[29966] devicestate.c: No provider found, checking channel drivers for SIP - 10.10.19.28 [Feb 12 16:19:27] DEBUG[29966] chan_sip.c: Checking device state for peer 10.10.19.28 [Feb 12 16:19:27] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.19.28' AND host = 'dynamic' [Feb 12 16:19:27] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.19.28' [Feb 12 16:19:27] DEBUG[29966] devicestate.c: Changing state for SIP/10.10.19.28 - state 4 (Invalid) [Feb 12 16:19:27] DEBUG[29966] devicestate.c: device 'SIP/10.10.19.28' state '4' [Feb 12 16:19:27] DEBUG[30070] app_queue.c: Device 'SIP/10.10.19.28' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '999017' AND host = 'dynamic' [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[30059][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '999017' [Feb 12 16:19:27] DEBUG[27022][C-0000000a] pbx.c: Launching 'Dial' [Feb 12 16:19:27] VERBOSE[27022][C-0000000a] pbx.c: -- Executing [999017@default:1] Dial("SIP/10.10.19.28-00000014", "SIP/5555@10.10.4.58,,e") in new stack [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Asked to create a SIP channel with formats: (g729) [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Allocating new SIP dialog for 0d76ddba6aabe0d623f8642b0b20875e@(null) - INVITE (No RTP) [Feb 12 16:19:27] DEBUG[27022][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.4.58' AND host = 'dynamic' [Feb 12 16:19:27] DEBUG[27022][C-0000000a] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.4.58' [Feb 12 16:19:27] DEBUG[27022][C-0000000a] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fd0f401b748' [Feb 12 16:19:27] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Allocated port 14592 for RTP instance '0x7fd0f401b748' [Feb 12 16:19:27] DEBUG[27022][C-0000000a] rtp_engine.c: RTP instance '0x7fd0f401b748' is setup and ready to go [Feb 12 16:19:27] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fd0f401b748' [Feb 12 16:19:27] VERBOSE[27022][C-0000000a] netsock2.c: == Using SIP RTP TOS bits 184 [Feb 12 16:19:27] VERBOSE[27022][C-0000000a] netsock2.c: == Using SIP RTP CoS mark 5 [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Setting NAT on RTP to Off [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Feb 12 16:19:27] DEBUG[27022][C-0000000a] netsock2.c: Splitting '10.10.4.58' into... [Feb 12 16:19:27] DEBUG[27022][C-0000000a] netsock2.c: ...host '10.10.4.58' and port ''. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] acl.c: For destination '10.10.4.58', our source address is '10.10.19.3'. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.10.19.3:5060 [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Setting NAT on RTP to Off [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: SIP call-id changed from '0d76ddba6aabe0d623f8642b0b20875e@(null)' to '620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060' [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: *** Our native formats are (g729) [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: *** Joint capabilities are (g729) [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: *** Our capabilities are (g729) [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: *** AST_CODEC_CHOOSE formats are g729 [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: *** Our preferred formats from the incoming channel are (g729) [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: This channel will not be able to handle video. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] channel_internal_api.c: Channel Call ID changing from [C-0000000a] to [C-0000000a] [Feb 12 16:19:27] DEBUG[27022][C-0000000a] channel.c: Not copying variable DIALEDTIME. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] channel.c: Not copying variable ANSWEREDTIME. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] channel.c: Not copying variable DIALEDPEERNAME. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] channel.c: Not copying variable DIALEDPEERNUMBER. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] channel.c: Not copying variable DIALSTATUS. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] channel.c: Not copying variable SIPCALLID. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] channel.c: Not copying variable SIPDOMAIN. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] channel.c: Not copying variable SIPURI. [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Outgoing Call for 5555 [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Updating call counter for outgoing call [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: ** Our capability: (g729) Video flag: False Text flag: False [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: ** Our prefcodec: (g729) [Feb 12 16:19:27] VERBOSE[27022][C-0000000a] chan_sip.c: Audio is at 14592 [Feb 12 16:19:27] VERBOSE[27022][C-0000000a] chan_sip.c: Adding codec 100008 (g729) to SDP [Feb 12 16:19:27] VERBOSE[27022][C-0000000a] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: -- Done with adding codecs to SDP [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Done building SDP. Settling with this capability: (g729) [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Initializing initreq for method INVITE - callid 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 0 [ 35]: INVITE sip:5555@10.10.4.58 SIP/2.0 [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 1 [ 56]: Via: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK13200307 [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 3 [ 43]: From: ;tag=as3911212c [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 4 [ 26]: To: [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 5 [ 36]: Contact: [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 6 [ 58]: Call-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 8 [ 27]: User-Agent: Asterisk Server [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 9 [ 35]: Date: Wed, 12 Feb 2014 16:19:27 GMT [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Feb 12 16:19:27] VERBOSE[27022][C-0000000a] chan_sip.c: Reliably Transmitting (no NAT) to 10.10.4.58:5060: ÿINVITE sip:5555@10.10.4.58 SIP/2.0 ÿVia: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK13200307 ÿMax-Forwards: 70 ÿFrom: ;tag=as3911212c ÿTo: ÿContact: ÿCall-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 ÿCSeq: 102 INVITE ÿUser-Agent: Asterisk Server ÿDate: Wed, 12 Feb 2014 16:19:27 GMT ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ÿSupported: replaces, timer ÿContent-Type: application/sdp ÿContent-Length: 281 ÿ ÿv=0 ÿo=root 918198641 918198641 IN IP4 10.10.19.3 ÿs=Asterisk PBX 11.7.0 ÿc=IN IP4 10.10.19.3 ÿt=0 0 ÿm=audio 14592 RTP/AVP 18 101 ÿa=rtpmap:18 G729/8000 ÿa=fmtp:18 annexb=no ÿa=rtpmap:101 telephone-event/8000 ÿa=fmtp:101 0-16 ÿa=silenceSupp:off - - - - ÿa=ptime:20 ÿa=sendrecv ÿ ÿ--- [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #109 [Feb 12 16:19:27] DEBUG[27022][C-0000000a] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.10.4.58:5060 [Feb 12 16:19:27] VERBOSE[27022][C-0000000a] app_dial.c: -- Called SIP/5555@10.10.4.58 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: SIP TIMER: Rescheduling retransmission #109 (1) INVITE - 5 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #109)) [Feb 12 16:19:28] VERBOSE[30059] chan_sip.c: Retransmitting #1 (no NAT) to 10.10.4.58:5060: ÿINVITE sip:5555@10.10.4.58 SIP/2.0 ÿVia: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK13200307 ÿMax-Forwards: 70 ÿFrom: ;tag=as3911212c ÿTo: ÿContact: ÿCall-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 ÿCSeq: 102 INVITE ÿUser-Agent: Asterisk Server ÿDate: Wed, 12 Feb 2014 16:19:27 GMT ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ÿSupported: replaces, timer ÿContent-Type: application/sdp ÿContent-Length: 281 ÿ ÿv=0 ÿo=root 918198641 918198641 IN IP4 10.10.19.3 ÿs=Asterisk PBX 11.7.0 ÿc=IN IP4 10.10.19.3 ÿt=0 0 ÿm=audio 14592 RTP/AVP 18 101 ÿa=rtpmap:18 G729/8000 ÿa=fmtp:18 annexb=no ÿa=rtpmap:101 telephone-event/8000 ÿa=fmtp:101 0-16 ÿa=silenceSupp:off - - - - ÿa=ptime:20 ÿa=sendrecv ÿ ÿ--- [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 10.10.4.58:5060 [Feb 12 16:19:28] VERBOSE[30059] chan_sip.c: ÿ<--- SIP read from UDP:10.10.4.56:5060 ---> ÿSIP/2.0 100 Trying ÿDate: Wed, 12 Feb 2014 16:20:12 GMT ÿFrom: ;tag=as3911212c ÿAllow-Events: telephone-event ÿContent-Length: 0 ÿTo: ÿCall-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 ÿVia: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK13200307 ÿCSeq: 102 INVITE ÿServer: Cisco-SIPGateway/IOS-12.x ÿ ÿ<-------------> [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 1 [ 35]: Date: Wed, 12 Feb 2014 16:20:12 GMT [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 2 [ 43]: From: ;tag=as3911212c [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 3 [ 29]: Allow-Events: telephone-event [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 4 [ 17]: Content-Length: 0 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 5 [ 26]: To: [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 6 [ 58]: Call-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 7 [ 56]: Via: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK13200307 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 8 [ 16]: CSeq: 102 INVITE [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 9 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Feb 12 16:19:28] VERBOSE[30059] chan_sip.c: --- (10 headers 0 lines) --- [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: = Looking for Call ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 (Checking To) --From tag as3911212c --To-tag [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: *** SIP TIMER: Cancelling retransmission #109 - INVITE (got response) [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060' Request 102: Found [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: SIP response 100 to standard invite [Feb 12 16:19:28] VERBOSE[30059] chan_sip.c: ÿ<--- SIP read from UDP:10.10.4.56:5060 ---> ÿSIP/2.0 200 OK ÿDate: Wed, 12 Feb 2014 16:20:12 GMT ÿAllow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER ÿFrom: ;tag=as3911212c ÿAllow-Events: telephone-event ÿSupported: replaces ÿSupported: sdp-anat ÿContent-Length: 267 ÿTo: ;tag=888AC2DC-1FEC ÿContact: ÿContent-Disposition: session;handling=required ÿContent-Type: application/sdp ÿCall-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 ÿVia: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK13200307 ÿCSeq: 102 INVITE ÿServer: Cisco-SIPGateway/IOS-12.x ÿ ÿv=0 ÿo=CiscoSystemsSIP-GW-UserAgent 5853 2684 IN IP4 10.10.4.56 ÿs=SIP Call ÿc=IN IP4 10.10.4.56 ÿt=0 0 ÿm=audio 17366 RTP/AVP 18 101 ÿc=IN IP4 10.10.4.56 ÿa=rtpmap:18 G729/8000 ÿa=fmtp:18 annexb=no ÿa=rtpmap:101 telephone-event/8000 ÿa=fmtp:101 0-16 ÿa=ptime:20 ÿ<-------------> [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 1 [ 35]: Date: Wed, 12 Feb 2014 16:20:12 GMT [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 2 [ 97]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 3 [ 43]: From: ;tag=as3911212c [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 4 [ 29]: Allow-Events: telephone-event [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 5 [ 19]: Supported: replaces [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 6 [ 19]: Supported: sdp-anat [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 7 [ 19]: Content-Length: 267 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 8 [ 44]: To: ;tag=888AC2DC-1FEC [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 9 [ 36]: Contact: [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 10 [ 46]: Content-Disposition: session;handling=required [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 12 [ 58]: Call-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 13 [ 56]: Via: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK13200307 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 14 [ 16]: CSeq: 102 INVITE [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 15 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 16 [ 0]: [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 0 [ 3]: v=0 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 1 [ 59]: o=CiscoSystemsSIP-GW-UserAgent 5853 2684 IN IP4 10.10.4.56 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 2 [ 10]: s=SIP Call [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.10.4.56 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 4 [ 5]: t=0 0 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 5 [ 28]: m=audio 17366 RTP/AVP 18 101 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 6 [ 20]: c=IN IP4 10.10.4.56 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 7 [ 21]: a=rtpmap:18 G729/8000 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 8 [ 19]: a=fmtp:18 annexb=no [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-16 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 11 [ 10]: a=ptime:20 [Feb 12 16:19:28] VERBOSE[30059] chan_sip.c: --- (16 headers 12 lines) --- [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: = Looking for Call ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 (Checking To) --From tag as3911212c --To-tag 888AC2DC-1FEC [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Acked pending invite 102 [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Stopping retransmission on '620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060' of Request 102: Match Found [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: SIP response 200 to standard invite [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Processing session-level SDP o=CiscoSystemsSIP-GW-UserAgent 5853 2684 IN IP4 10.10.4.56... OK. [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Processing session-level SDP s=SIP Call... UNSUPPORTED OR FAILED. [Feb 12 16:19:28] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.4.56' into... [Feb 12 16:19:28] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.4.56' and port ''. [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Processing session-level SDP c=IN IP4 10.10.4.56... OK. [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: Found RTP audio format 18 [Feb 12 16:19:28] DEBUG[30059][C-0000000a] rtp_engine.c: Setting payload 18 based on m type on 0x7fd0ba1ed3b0 [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: Found RTP audio format 101 [Feb 12 16:19:28] DEBUG[30059][C-0000000a] rtp_engine.c: Setting payload 101 based on m type on 0x7fd0ba1ed3b0 [Feb 12 16:19:28] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.4.56' into... [Feb 12 16:19:28] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.4.56' and port ''. [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 10.10.4.56... OK. [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: Found audio description format G729 for ID 18 [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP a=fmtp:18 annexb=no... OK. [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: Found audio description format telephone-event for ID 101 [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: Capabilities: us - (g729), peer - audio=(g729)/video=(nothing)/text=(nothing), combined - (g729) [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Feb 12 16:19:28] DEBUG[30059][C-0000000a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fd0f401b748' [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: Peer audio RTP is at port 10.10.4.56:17366 [Feb 12 16:19:28] DEBUG[30059][C-0000000a] rtp_engine.c: Copying payload 18 from 0x7fd0ba1ed3b0 to 0x7fd0f401b910 [Feb 12 16:19:28] DEBUG[30059][C-0000000a] rtp_engine.c: Copying payload 101 from 0x7fd0ba1ed3b0 to 0x7fd0f401b910 [Feb 12 16:19:28] DEBUG[30059][C-0000000a] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fd0f401b748' [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: We're settling with these formats: (g729) [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: We have an owner, now see if we need to change this call [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Setting native formats after processing SDP. peer joint formats (g729), old nativeformats (g729) [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Updating call counter for outgoing call [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: build_route: Contact hop: [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: list_route: hop: [Feb 12 16:19:28] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.4.56:5060' into... [Feb 12 16:19:28] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.4.56' and port '5060'. [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Strict routing enforced for session 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: set_destination: Parsing for address/port to send to [Feb 12 16:19:28] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.4.56:5060' into... [Feb 12 16:19:28] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.4.56' and port '5060'. [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: set_destination: set destination to 10.10.4.56:5060 [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: Transmitting (no NAT) to 10.10.4.56:5060: ÿACK sip:5555@10.10.4.56:5060 SIP/2.0 ÿVia: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK3d5e36de ÿMax-Forwards: 70 ÿFrom: ;tag=as3911212c ÿTo: ;tag=888AC2DC-1FEC ÿContact: ÿCall-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 ÿCSeq: 102 ACK ÿUser-Agent: Asterisk Server ÿContent-Length: 0 ÿ ÿ ÿ--- [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Trying to put 'ACK sip:861' onto UDP socket destined for 10.10.4.56:5060 [Feb 12 16:19:28] VERBOSE[27022][C-0000000a] app_dial.c: -- SIP/10.10.4.58-00000015 answered SIP/10.10.19.28-00000014 [Feb 12 16:19:28] DEBUG[29966] devicestate.c: No provider found, checking channel drivers for SIP - 10.10.4.58 [Feb 12 16:19:28] DEBUG[29966] chan_sip.c: Checking device state for peer 10.10.4.58 [Feb 12 16:19:28] DEBUG[27022][C-0000000a] rtp_engine.c: Setting early bridge SDP of 'SIP/10.10.19.28-00000014' with that of 'SIP/10.10.4.58-00000015' [Feb 12 16:19:28] DEBUG[27022][C-0000000a] chan_sip.c: SIP answering channel: SIP/10.10.19.28-00000014 [Feb 12 16:19:28] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Setting the marker bit due to a source update [Feb 12 16:19:28] DEBUG[27022][C-0000000a] chan_sip.c: Setting framing from config on incoming call [Feb 12 16:19:28] DEBUG[27022][C-0000000a] chan_sip.c: ** Our capability: (g729) Video flag: True Text flag: True [Feb 12 16:19:28] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:28] DEBUG[27022][C-0000000a] chan_sip.c: ** Our prefcodec: (nothing) [Feb 12 16:19:28] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.4.58' AND host = 'dynamic' [Feb 12 16:19:28] VERBOSE[27022][C-0000000a] chan_sip.c: Audio is at 13052 [Feb 12 16:19:28] VERBOSE[27022][C-0000000a] chan_sip.c: Adding codec 100008 (g729) to SDP [Feb 12 16:19:28] VERBOSE[27022][C-0000000a] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Feb 12 16:19:28] DEBUG[27022][C-0000000a] chan_sip.c: -- Done with adding codecs to SDP [Feb 12 16:19:28] DEBUG[27022][C-0000000a] chan_sip.c: Done building SDP. Settling with this capability: (g729) [Feb 12 16:19:28] VERBOSE[27022][C-0000000a] chan_sip.c: ÿ<--- Reliably Transmitting (no NAT) to 10.10.19.28:5060 ---> ÿSIP/2.0 200 OK ÿVia: SIP/2.0/UDP 10.10.19.28:5060;x-route-tag="cid:15817@10.10.19.28";branch=z9hG4bK1DA6F6;received=10.10.19.28 ÿFrom: ;tag=33F281F0-1DFB ÿTo: ;tag=as215096a3 ÿCall-ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 ÿCSeq: 101 INVITE ÿServer: Asterisk Server ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ÿSupported: replaces, timer ÿSession-Expires: 1800;refresher=uas ÿContact: ÿContent-Type: application/sdp ÿRequire: timer ÿContent-Length: 283 ÿ ÿv=0 ÿo=root 1631856383 1631856383 IN IP4 10.10.19.3 ÿs=Asterisk PBX 11.7.0 ÿc=IN IP4 10.10.19.3 ÿt=0 0 ÿm=audio 13052 RTP/AVP 18 101 ÿa=rtpmap:18 G729/8000 ÿa=fmtp:18 annexb=no ÿa=rtpmap:101 telephone-event/8000 ÿa=fmtp:101 0-16 ÿa=silenceSupp:off - - - - ÿa=ptime:60 ÿa=sendrecv ÿ ÿ<------------> [Feb 12 16:19:28] DEBUG[27022][C-0000000a] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #111 [Feb 12 16:19:28] DEBUG[27022][C-0000000a] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.10.19.28:5060 [Feb 12 16:19:28] DEBUG[27022][C-0000000a] features.c: bridge answer set, chan answer set [Feb 12 16:19:28] DEBUG[27022][C-0000000a] features.c: Removing dialed interfaces datastore on SIP/10.10.4.58-00000015 since we're bridging [Feb 12 16:19:28] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Setting the marker bit due to a source update [Feb 12 16:19:28] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Setting the marker bit due to a source update [Feb 12 16:19:28] DEBUG[27022][C-0000000a] rtp_engine.c: Packetization differs between RTP streams (60 != 20 or 20 != 60). Cannot native bridge in RTP [Feb 12 16:19:28] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:28] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.4.58' [Feb 12 16:19:28] DEBUG[29966] devicestate.c: Changing state for SIP/10.10.4.58 - state 4 (Invalid) [Feb 12 16:19:28] DEBUG[29966] devicestate.c: device 'SIP/10.10.4.58' state '4' [Feb 12 16:19:28] DEBUG[29966] devicestate.c: No provider found, checking channel drivers for SIP - 10.10.19.28 [Feb 12 16:19:28] DEBUG[29966] chan_sip.c: Checking device state for peer 10.10.19.28 [Feb 12 16:19:28] DEBUG[30070] app_queue.c: Device 'SIP/10.10.4.58' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 12 16:19:28] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:28] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.19.28' AND host = 'dynamic' [Feb 12 16:19:28] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:28] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.19.28' [Feb 12 16:19:28] DEBUG[29966] devicestate.c: Changing state for SIP/10.10.19.28 - state 4 (Invalid) [Feb 12 16:19:28] DEBUG[29966] devicestate.c: device 'SIP/10.10.19.28' state '4' [Feb 12 16:19:28] DEBUG[30070] app_queue.c: Device 'SIP/10.10.19.28' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 12 16:19:28] VERBOSE[30059] chan_sip.c: ÿ<--- SIP read from UDP:10.10.19.28:54113 ---> ÿACK sip:999017@10.10.19.3:5060 SIP/2.0 ÿVia: SIP/2.0/UDP 10.10.19.28:5060;x-route-tag="cid:15817@10.10.19.28";branch=z9hG4bK1DBB1F ÿFrom: ;tag=33F281F0-1DFB ÿTo: ;tag=as215096a3 ÿDate: Wed, 12 Feb 2014 16:19:27 GMT ÿCall-ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 ÿMax-Forwards: 70 ÿCSeq: 101 ACK ÿAllow-Events: telephone-event ÿContent-Length: 0 ÿ ÿ<-------------> [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 0 [ 39]: ACK sip:999017@10.10.19.3:5060 SIP/2.0 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 1 [ 92]: Via: SIP/2.0/UDP 10.10.19.28:5060;x-route-tag="cid:15817@10.10.19.28";branch=z9hG4bK1DBB1F [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 2 [ 47]: From: ;tag=33F281F0-1DFB [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 3 [ 43]: To: ;tag=as215096a3 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 4 [ 35]: Date: Wed, 12 Feb 2014 16:19:27 GMT [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 5 [ 57]: Call-ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 7 [ 13]: CSeq: 101 ACK [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 8 [ 29]: Allow-Events: telephone-event [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 9 [ 17]: Content-Length: 0 [Feb 12 16:19:28] VERBOSE[30059] chan_sip.c: --- (10 headers 0 lines) --- [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: = Looking for Call ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 (Checking From) --From tag 33F281F0-1DFB --To-tag as215096a3 [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #111 [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Stopping retransmission on '477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28' of Response 101: Match Found [Feb 12 16:19:28] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: 0x7fd104026520 -- Probation learning mode pass with source address 10.10.19.28:16752 [Feb 12 16:19:28] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Ooh, format changed from unknown to g729 [Feb 12 16:19:28] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Created smoother: format: g729 ms: 20 len: 20 [Feb 12 16:19:28] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7fd0f401b748' [Feb 12 16:19:28] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: 0x7fd0f4009600 -- Probation learning mode pass with source address 10.10.4.56:17366 [Feb 12 16:19:28] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Ooh, format changed from unknown to g729 [Feb 12 16:19:28] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Created smoother: format: g729 ms: 60 len: 60 [Feb 12 16:19:28] VERBOSE[30059] chan_sip.c: ÿ<--- SIP read from UDP:10.10.4.56:5060 ---> ÿSIP/2.0 200 OK ÿDate: Wed, 12 Feb 2014 16:20:12 GMT ÿAllow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER ÿFrom: ;tag=as3911212c ÿAllow-Events: telephone-event ÿSupported: replaces ÿSupported: sdp-anat ÿContent-Length: 267 ÿTo: ;tag=888AC2DC-1FEC ÿContact: ÿContent-Disposition: session;handling=required ÿContent-Type: application/sdp ÿCall-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 ÿVia: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK13200307 ÿCSeq: 102 INVITE ÿServer: Cisco-SIPGateway/IOS-12.x ÿ ÿv=0 ÿo=CiscoSystemsSIP-GW-UserAgent 5853 2684 IN IP4 10.10.4.56 ÿs=SIP Call ÿc=IN IP4 10.10.4.56 ÿt=0 0 ÿm=audio 17366 RTP/AVP 18 101 ÿc=IN IP4 10.10.4.56 ÿa=rtpmap:18 G729/8000 ÿa=fmtp:18 annexb=no ÿa=rtpmap:101 telephone-event/8000 ÿa=fmtp:101 0-16 ÿa=ptime:20 ÿ<-------------> [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 1 [ 35]: Date: Wed, 12 Feb 2014 16:20:12 GMT [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 2 [ 97]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 3 [ 43]: From: ;tag=as3911212c [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 4 [ 29]: Allow-Events: telephone-event [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 5 [ 19]: Supported: replaces [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 6 [ 19]: Supported: sdp-anat [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 7 [ 19]: Content-Length: 267 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 8 [ 44]: To: ;tag=888AC2DC-1FEC [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 9 [ 36]: Contact: [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 10 [ 46]: Content-Disposition: session;handling=required [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 11 [ 29]: Content-Type: application/sdp [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 12 [ 58]: Call-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 13 [ 56]: Via: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK13200307 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 14 [ 16]: CSeq: 102 INVITE [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 15 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Header 16 [ 0]: [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 0 [ 3]: v=0 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 1 [ 59]: o=CiscoSystemsSIP-GW-UserAgent 5853 2684 IN IP4 10.10.4.56 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 2 [ 10]: s=SIP Call [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 3 [ 20]: c=IN IP4 10.10.4.56 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 4 [ 5]: t=0 0 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 5 [ 28]: m=audio 17366 RTP/AVP 18 101 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 6 [ 20]: c=IN IP4 10.10.4.56 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 7 [ 21]: a=rtpmap:18 G729/8000 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 8 [ 19]: a=fmtp:18 annexb=no [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 10 [ 15]: a=fmtp:101 0-16 [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: Body 11 [ 10]: a=ptime:20 [Feb 12 16:19:28] VERBOSE[30059] chan_sip.c: --- (16 headers 12 lines) --- [Feb 12 16:19:28] DEBUG[30059] chan_sip.c: = Looking for Call ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 (Checking To) --From tag as3911212c --To-tag 888AC2DC-1FEC [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Stopping retransmission on '620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060' of Request 102: Match Not Found [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Strict routing enforced for session 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: set_destination: Parsing for address/port to send to [Feb 12 16:19:28] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.4.56:5060' into... [Feb 12 16:19:28] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.4.56' and port '5060'. [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: set_destination: set destination to 10.10.4.56:5060 [Feb 12 16:19:28] VERBOSE[30059][C-0000000a] chan_sip.c: Transmitting (no NAT) to 10.10.4.56:5060: ÿACK sip:5555@10.10.4.56:5060 SIP/2.0 ÿVia: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK3d1f1b98 ÿMax-Forwards: 70 ÿFrom: ;tag=as3911212c ÿTo: ;tag=888AC2DC-1FEC ÿContact: ÿCall-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 ÿCSeq: 102 ACK ÿUser-Agent: Asterisk Server ÿContent-Length: 0 ÿ ÿ ÿ--- [Feb 12 16:19:28] DEBUG[30059][C-0000000a] chan_sip.c: Trying to put 'ACK sip:861' onto UDP socket destined for 10.10.4.56:5060 [Feb 12 16:19:32] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Feb 12 16:19:35] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Feb 12 16:19:40] VERBOSE[29961] asterisk.c: -- Remote UNIX connection [Feb 12 16:19:41] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Got RTCP report of 88 bytes [Feb 12 16:19:42] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Changing ssrc from 1359782123 to 1516501316 due to a source change [Feb 12 16:19:47] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Feb 12 16:19:52] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Got RTCP report of 132 bytes [Feb 12 16:19:55] VERBOSE[30059] chan_sip.c: ÿ<--- SIP read from UDP:10.10.19.28:54113 ---> ÿBYE sip:999017@10.10.19.3:5060 SIP/2.0 ÿVia: SIP/2.0/UDP 10.10.19.28:5060;x-route-tag="cid:15817@10.10.19.28";branch=z9hG4bK1DC1353 ÿFrom: ;tag=33F281F0-1DFB ÿTo: ;tag=as215096a3 ÿDate: Wed, 12 Feb 2014 16:19:27 GMT ÿCall-ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 ÿUser-Agent: Cisco-SIPGateway/IOS-15.2.4.M4 ÿMax-Forwards: 70 ÿTimestamp: 1392221995 ÿCSeq: 102 BYE ÿReason: Q.850;cause=16 ÿP-RTP-Stat: PS=452,OS=27120,PR=160,OR=9600,PL=0,JI=16,LA=1,DU=27 ÿContent-Length: 0 ÿ ÿ<-------------> [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 0 [ 39]: BYE sip:999017@10.10.19.3:5060 SIP/2.0 [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 1 [ 93]: Via: SIP/2.0/UDP 10.10.19.28:5060;x-route-tag="cid:15817@10.10.19.28";branch=z9hG4bK1DC1353 [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 2 [ 47]: From: ;tag=33F281F0-1DFB [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 3 [ 43]: To: ;tag=as215096a3 [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 4 [ 35]: Date: Wed, 12 Feb 2014 16:19:27 GMT [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 5 [ 57]: Call-ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 6 [ 42]: User-Agent: Cisco-SIPGateway/IOS-15.2.4.M4 [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 7 [ 16]: Max-Forwards: 70 [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 8 [ 21]: Timestamp: 1392221995 [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 9 [ 13]: CSeq: 102 BYE [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 10 [ 22]: Reason: Q.850;cause=16 [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 11 [ 64]: P-RTP-Stat: PS=452,OS=27120,PR=160,OR=9600,PL=0,JI=16,LA=1,DU=27 [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: Header 12 [ 17]: Content-Length: 0 [Feb 12 16:19:55] VERBOSE[30059] chan_sip.c: --- (13 headers 0 lines) --- [Feb 12 16:19:55] DEBUG[30059] chan_sip.c: = Looking for Call ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 (Checking From) --From tag 33F281F0-1DFB --To-tag as215096a3 [Feb 12 16:19:55] DEBUG[30059][C-0000000a] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Feb 12 16:19:55] DEBUG[30059][C-0000000a] chan_sip.c: Initializing initreq for method BYE - callid 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 [Feb 12 16:19:55] DEBUG[30059][C-0000000a] netsock2.c: Splitting '10.10.19.28:5060' into... [Feb 12 16:19:55] DEBUG[30059][C-0000000a] netsock2.c: ...host '10.10.19.28' and port '5060'. [Feb 12 16:19:55] VERBOSE[30059][C-0000000a] chan_sip.c: Sending to 10.10.19.28:5060 (no NAT) [Feb 12 16:19:55] DEBUG[30059][C-0000000a] chan_sip.c: Setting SIP_ALREADYGONE on dialog 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 [Feb 12 16:19:55] DEBUG[30059][C-0000000a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fd1040174e8' [Feb 12 16:19:55] DEBUG[30059][C-0000000a] chan_sip.c: Session timer stopped: 107 - 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 [Feb 12 16:19:55] VERBOSE[30059][C-0000000a] chan_sip.c: Scheduling destruction of SIP dialog '477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28' in 32000 ms (Method: BYE) [Feb 12 16:19:55] DEBUG[30059][C-0000000a] chan_sip.c: Received bye, issuing owner hangup [Feb 12 16:19:55] VERBOSE[30059][C-0000000a] chan_sip.c: ÿ<--- Transmitting (no NAT) to 10.10.19.28:5060 ---> ÿSIP/2.0 200 OK ÿVia: SIP/2.0/UDP 10.10.19.28:5060;x-route-tag="cid:15817@10.10.19.28";branch=z9hG4bK1DC1353;received=10.10.19.28 ÿFrom: ;tag=33F281F0-1DFB ÿTo: ;tag=as215096a3 ÿCall-ID: 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 ÿCSeq: 102 BYE ÿServer: Asterisk Server ÿAllow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ÿSupported: replaces, timer ÿContent-Length: 0 ÿ ÿ ÿ<------------> [Feb 12 16:19:55] DEBUG[30059][C-0000000a] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.10.19.28:5060 [Feb 12 16:19:55] DEBUG[27022][C-0000000a] channel.c: Didn't get a frame from channel: SIP/10.10.19.28-00000014 [Feb 12 16:19:55] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Setting the marker bit due to a source update [Feb 12 16:19:55] DEBUG[27022][C-0000000a] channel.c: Bridge stops bridging channels SIP/10.10.19.28-00000014 and SIP/10.10.4.58-00000015 [Feb 12 16:19:55] DEBUG[27022][C-0000000a] cdr_mysql.c: Inserting a CDR record. [Feb 12 16:19:55] DEBUG[27022][C-0000000a] cdr_mysql.c: SQL command as follows: INSERT INTO cdrs (`start_time`,`stop_time`,`duration`,`billsec`,`channel`,`disposition`,`lastapp`,`lastdata`) VALUES ('2014-02-12 16:19:27','2014-02-12 16:19:55','28','27','SIP/10.10.19.28-00000014','ANSWERED','Dial','SIP/5555@10.10.4.58,,e') [Feb 12 16:19:55] DEBUG[27022][C-0000000a] channel.c: Hanging up channel 'SIP/10.10.4.58-00000015' [Feb 12 16:19:55] DEBUG[27022][C-0000000a] chan_sip.c: Hangup call SIP/10.10.4.58-00000015, SIP callid 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:55] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fd0f401b748' [Feb 12 16:19:55] VERBOSE[27022][C-0000000a] chan_sip.c: Scheduling destruction of SIP dialog '620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060' in 32000 ms (Method: INVITE) [Feb 12 16:19:55] DEBUG[27022][C-0000000a] chan_sip.c: Strict routing enforced for session 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:55] VERBOSE[27022][C-0000000a] chan_sip.c: set_destination: Parsing for address/port to send to [Feb 12 16:19:55] DEBUG[27022][C-0000000a] netsock2.c: Splitting '10.10.4.56:5060' into... [Feb 12 16:19:55] DEBUG[27022][C-0000000a] netsock2.c: ...host '10.10.4.56' and port '5060'. [Feb 12 16:19:55] VERBOSE[27022][C-0000000a] chan_sip.c: set_destination: set destination to 10.10.4.56:5060 [Feb 12 16:19:55] VERBOSE[27022][C-0000000a] chan_sip.c: Reliably Transmitting (no NAT) to 10.10.4.56:5060: ÿBYE sip:5555@10.10.4.56:5060 SIP/2.0 ÿVia: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK35f50b54 ÿMax-Forwards: 70 ÿFrom: ;tag=as3911212c ÿTo: ;tag=888AC2DC-1FEC ÿCall-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 ÿCSeq: 103 BYE ÿUser-Agent: Asterisk Server ÿX-Asterisk-HangupCause: Normal Clearing ÿX-Asterisk-HangupCauseCode: 16 ÿContent-Length: 0 ÿ ÿ ÿ--- [Feb 12 16:19:55] DEBUG[27022][C-0000000a] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #116 [Feb 12 16:19:55] DEBUG[27022][C-0000000a] chan_sip.c: Trying to put 'BYE sip:861' onto UDP socket destined for 10.10.4.56:5060 [Feb 12 16:19:55] DEBUG[29966] devicestate.c: No provider found, checking channel drivers for SIP - 10.10.4.58 [Feb 12 16:19:55] DEBUG[29966] chan_sip.c: Checking device state for peer 10.10.4.58 [Feb 12 16:19:55] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:55] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.4.58' AND host = 'dynamic' [Feb 12 16:19:55] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:55] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.4.58' [Feb 12 16:19:55] DEBUG[29966] devicestate.c: Changing state for SIP/10.10.4.58 - state 4 (Invalid) [Feb 12 16:19:55] DEBUG[29966] devicestate.c: device 'SIP/10.10.4.58' state '4' [Feb 12 16:19:55] DEBUG[30070] app_queue.c: Device 'SIP/10.10.4.58' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 12 16:19:55] DEBUG[27022][C-0000000a] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Feb 12 16:19:55] DEBUG[27022][C-0000000a] pbx.c: Spawn extension (default,999017,1) exited non-zero on 'SIP/10.10.19.28-00000014' [Feb 12 16:19:55] VERBOSE[27022][C-0000000a] pbx.c: == Spawn extension (default, 999017, 1) exited non-zero on 'SIP/10.10.19.28-00000014' [Feb 12 16:19:55] DEBUG[27022][C-0000000a] channel.c: Soft-Hanging up channel 'SIP/10.10.19.28-00000014' [Feb 12 16:19:55] DEBUG[27022][C-0000000a] channel.c: Hanging up channel 'SIP/10.10.19.28-00000014' [Feb 12 16:19:55] DEBUG[27022][C-0000000a] chan_sip.c: Hangup call SIP/10.10.19.28-00000014, SIP callid 477EEC66-933811E3-8487D367-DBF5FAC4@10.10.19.28 [Feb 12 16:19:55] DEBUG[27022][C-0000000a] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fd1040174e8' [Feb 12 16:19:55] DEBUG[29966] devicestate.c: No provider found, checking channel drivers for SIP - 10.10.19.28 [Feb 12 16:19:55] DEBUG[29966] chan_sip.c: Checking device state for peer 10.10.19.28 [Feb 12 16:19:55] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:55] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.19.28' AND host = 'dynamic' [Feb 12 16:19:55] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Connection okay. [Feb 12 16:19:55] DEBUG[29966] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '10.10.19.28' [Feb 12 16:19:55] DEBUG[29966] devicestate.c: Changing state for SIP/10.10.19.28 - state 4 (Invalid) [Feb 12 16:19:55] DEBUG[29966] devicestate.c: device 'SIP/10.10.19.28' state '4' [Feb 12 16:19:55] DEBUG[30070] app_queue.c: Device 'SIP/10.10.19.28' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: SIP TIMER: Rescheduling retransmission #116 (1) BYE - 8 [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #116)) [Feb 12 16:19:56] VERBOSE[30059] chan_sip.c: Retransmitting #1 (no NAT) to 10.10.4.56:5060: ÿBYE sip:5555@10.10.4.56:5060 SIP/2.0 ÿVia: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK35f50b54 ÿMax-Forwards: 70 ÿFrom: ;tag=as3911212c ÿTo: ;tag=888AC2DC-1FEC ÿCall-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 ÿCSeq: 103 BYE ÿUser-Agent: Asterisk Server ÿX-Asterisk-HangupCause: Normal Clearing ÿX-Asterisk-HangupCauseCode: 16 ÿContent-Length: 0 ÿ ÿ ÿ--- [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Trying to put 'BYE sip:861' onto UDP socket destined for 10.10.4.56:5060 [Feb 12 16:19:56] VERBOSE[30059] chan_sip.c: ÿ<--- SIP read from UDP:10.10.4.56:5060 ---> ÿSIP/2.0 200 OK ÿReason: Q.850;cause=16 ÿDate: Wed, 12 Feb 2014 16:20:40 GMT ÿFrom: ;tag=as3911212c ÿContent-Length: 0 ÿTo: ;tag=888AC2DC-1FEC ÿCall-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 ÿVia: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK35f50b54 ÿServer: Cisco-SIPGateway/IOS-12.x ÿCSeq: 103 BYE ÿ ÿ<-------------> [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 1 [ 22]: Reason: Q.850;cause=16 [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 2 [ 35]: Date: Wed, 12 Feb 2014 16:20:40 GMT [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 3 [ 43]: From: ;tag=as3911212c [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 4 [ 17]: Content-Length: 0 [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 5 [ 44]: To: ;tag=888AC2DC-1FEC [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 6 [ 58]: Call-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 7 [ 56]: Via: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK35f50b54 [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 8 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 9 [ 13]: CSeq: 103 BYE [Feb 12 16:19:56] VERBOSE[30059] chan_sip.c: --- (10 headers 0 lines) --- [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: = Looking for Call ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 (Checking To) --From tag as3911212c --To-tag 888AC2DC-1FEC [Feb 12 16:19:56] DEBUG[30059][C-0000000a] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #116 [Feb 12 16:19:56] DEBUG[30059][C-0000000a] chan_sip.c: Stopping retransmission on '620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060' of Request 103: Match Found [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Destroying SIP dialog 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:56] VERBOSE[30059] chan_sip.c: Really destroying SIP dialog '620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060' Method: INVITE [Feb 12 16:19:56] DEBUG[30059] rtp_engine.c: Destroyed RTP instance '0x7fd0f401b748' [Feb 12 16:19:56] VERBOSE[30059] chan_sip.c: ÿ<--- SIP read from UDP:10.10.4.56:5060 ---> ÿSIP/2.0 200 OK ÿFrom: ;tag=as3911212c ÿContent-Length: 0 ÿTo: ;tag=888AC2DC-1FEC ÿCall-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 ÿVia: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK35f50b54 ÿCSeq: 103 BYE ÿ ÿ<-------------> [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 1 [ 43]: From: ;tag=as3911212c [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 2 [ 17]: Content-Length: 0 [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 3 [ 44]: To: ;tag=888AC2DC-1FEC [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 4 [ 58]: Call-ID: 620ace9467aa3017090f98a54491d8e8@10.10.19.3:5060 [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 5 [ 56]: Via: SIP/2.0/UDP 10.10.19.3:5060;branch=z9hG4bK35f50b54 [Feb 12 16:19:56] DEBUG[30059] chan_sip.c: Header 6 [ 13]: CSeq: 103 BYE [Feb 12 16:19:56] VERBOSE[30059] chan_sip.c: --- (7 headers 0 lines) ---