sip*CLI> <--- SIP read from 10.10.119.225:54252 ---> INVITE sip:9973@10.10.119.251:5060 SIP/2.0 Via: SIP/2.0/UDP 10.10.119.225:5060;branch=z9hG4bK13BBC1C7A Remote-Party-ID: "Setup" ;party=calling;screen=yes;privacy=off From: "Setup" ;tag=53CB3B5C-F9B To: Date: Mon, 12 Feb 2007 15:25:54 GMT Call-ID: 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 Supported: 100rel,timer,resource-priority,replaces Min-SE: 1800 Cisco-Guid: 703373727-3118731739-2723807245-3989561264 User-Agent: Cisco-SIPGateway/IOS-12.x Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER CSeq: 101 INVITE Max-Forwards: 70 Timestamp: 1171293954 Contact: Expires: 180 Allow-Events: telephone-event Content-Type: application/sdp Content-Disposition: session;handling=required Content-Length: 235 v=0 o=CiscoSystemsSIP-GW-UserAgent 6825 4872 IN IP4 10.10.119.225 s=SIP Call c=IN IP4 10.10.119.225 t=0 0 m=audio 18314 RTP/AVP 18 8 c=IN IP4 10.10.119.225 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 <-------------> [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 0: INVITE sip:9973@10.10.119.251:5060 SIP/2.0 (49) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.119.225:5060;branch=z9hG4bK13BBC1C7A (61) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 2: Remote-Party-ID: "Setup" ;party=calling;screen=yes;privacy=off (97) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 3: From: "Setup" ;tag=53CB3B5C-F9B (66) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 4: To: (35) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 5: Date: Mon, 12 Feb 2007 15:25:54 GMT (35) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 6: Call-ID: 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 (60) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 7: Supported: 100rel,timer,resource-priority,replaces (50) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 8: Min-SE: 1800 (13) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 9: Cisco-Guid: 703373727-3118731739-2723807245-3989561264 (54) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 10: User-Agent: Cisco-SIPGateway/IOS-12.x (37) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 11: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER (97) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 12: CSeq: 101 INVITE (16) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 13: Max-Forwards: 70 (16) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 14: Timestamp: 1171293954 (21) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 15: Contact: (45) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 16: Expires: 180 (12) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 17: Allow-Events: telephone-event (29) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 18: Content-Type: application/sdp (29) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 19: Content-Disposition: session;handling=required (46) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 20: Content-Length: 235 (19) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 21: (0) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: v=0 (3) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 6825 4872 IN IP4 10.10.119.225 (63) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: s=SIP Call (10) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: c=IN IP4 10.10.119.225 (24) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: t=0 0 (5) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: m=audio 18314 RTP/AVP 18 8 (26) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: c=IN IP4 10.10.119.225 (24) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: a=fmtp:18 annexb=no (19) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) --- (21 headers 10 lines) --- [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:2572 do_setnat: Setting NAT on RTP to Off [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4292 sip_alloc: Allocating new SIP dialog for 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 - INVITE (With RTP) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:14562 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:1677 parse_sip_options: Begin: parsing SIP "Supported: 100rel,timer,resource-priority,replaces" [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:1685 parse_sip_options: Found SIP option: -100rel- [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:1691 parse_sip_options: Matched SIP option: 100rel [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:1685 parse_sip_options: Found SIP option: -timer- [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:1691 parse_sip_options: Matched SIP option: timer [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:1685 parse_sip_options: Found SIP option: -resource-priority- [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:1691 parse_sip_options: Matched SIP option: resource-priority [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:1685 parse_sip_options: Found SIP option: -replaces- [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:1691 parse_sip_options: Matched SIP option: replaces Sending to 10.10.119.225 : 5060 (no NAT) Using INVITE request as basis request - 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 Found peer 'cisco' [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:2572 do_setnat: Setting NAT on RTP to Off Found RTP audio format 18 Found RTP audio format 8 Peer audio RTP is at port 10.10.119.225:18314 Found description format G729 for ID 18 Got unsupported a:fmtp in SDP offer Found description format PCMA for ID 8 [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:5097 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x108 (alaw|g729), peer - audio=0x108 (alaw|g729)/video=0x0 (nothing), combined - 0x108 (alaw|g729) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) Peer audio RTP is at port 10.10.119.225:18314 [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:5177 process_sdp: We're settling with these formats: 0x108 (alaw|g729) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:13350 handle_request_invite: Checking SIP call limits for device [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:3000 update_call_counter: Updating call counter for incoming call Looking for 9973 in remote (domain 10.10.119.251) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:3795 sip_new: *** Our native formats are 0x100 (g729) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:3796 sip_new: *** Joint capabilities are 0x108 (alaw|g729) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:3797 sip_new: *** Our capabilities are 0x108 (alaw|g729) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:3798 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:3821 sip_new: This channel will not be able to handle video. [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:7940 build_route: build_route: Contact hop: list_route: hop: [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:13425 handle_request_invite: SIP/10.10.119.225-081e2bc0: New call is still down.... Trying... <--- Transmitting (no NAT) to 10.10.119.225:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.119.225:5060;branch=z9hG4bK13BBC1C7A;received=194.181.119.225 From: "Setup" ;tag=53CB3B5C-F9B To: Call-ID: 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 12 16:25:20] DEBUG[8329]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/10.10.119.225-081e2bc0 [Feb 12 16:25:20] DEBUG[8309]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 10.10.119.225 [Feb 12 16:25:20] DEBUG[8309]: chan_sip.c:15167 sip_devicestate: Checking device state for peer 10.10.119.225 [Feb 12 16:25:20] DEBUG[8309]: channel.c:1020 channel_find_locked: Avoiding initial deadlock for channel '0x81b32e0' [Feb 12 16:25:20] DEBUG[11057]: pbx.c:1769 pbx_extension_helper: Launching 'Set' -- Executing [9973@remote:1] Set("SIP/10.10.119.225-081e2bc0", "__TRANSFER_CONTEXT=test_1") in new stack [Feb 12 16:25:20] DEBUG[11057]: pbx.c:1769 pbx_extension_helper: Launching 'Goto' -- Executing [9973@remote:2] Goto("SIP/10.10.119.225-081e2bc0", "test_1|9973|1") in new stack -- Goto (test_1,9973,1) [Feb 12 16:25:20] DEBUG[11057]: pbx.c:1769 pbx_extension_helper: Launching 'Dial' -- Executing [9973@test_1:1] Dial("SIP/10.10.119.225-081e2bc0", "SIP/9973|60|tT") in new stack [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:15233 sip_request_call: Asked to create a SIP channel with formats: 0x100 (g729) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4292 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:2572 do_setnat: Setting NAT on RTP to On [Feb 12 16:25:20] DEBUG[8309]: devicestate.c:287 do_state_change: Changing state for SIP/10.10.119.225 - state 2 (In use) [Feb 12 16:25:20] DEBUG[11059]: app_queue.c:546 changethread: Device 'SIP/10.10.119.225' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:3795 sip_new: *** Our native formats are 0x8 (alaw) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:3796 sip_new: *** Joint capabilities are 0x0 (nothing) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:3797 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:3798 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:3800 sip_new: *** Our preferred formats from the incoming channel are 0x100 (g729) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:3821 sip_new: This channel will not be able to handle video. [Feb 12 16:25:20] DEBUG[11057]: rtp.c:1579 ast_rtp_make_compatible: Seeded SDP of 'SIP/9973-081e4140' with that of 'SIP/10.10.119.225-081e2bc0' [Feb 12 16:25:20] DEBUG[11057]: channel.c:3295 ast_channel_inherit_variables: Not copying variable STACK-test_1-9973-1. [Feb 12 16:25:20] DEBUG[11057]: channel.c:3295 ast_channel_inherit_variables: Not copying variable STACK-remote-9973-2. [Feb 12 16:25:20] DEBUG[11057]: channel.c:3290 ast_channel_inherit_variables: Copying hard-transferable variable TRANSFER_CONTEXT. [Feb 12 16:25:20] DEBUG[11057]: channel.c:3295 ast_channel_inherit_variables: Not copying variable STACK-remote-9973-1. [Feb 12 16:25:20] DEBUG[11057]: channel.c:3295 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 12 16:25:20] DEBUG[11057]: channel.c:3295 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 12 16:25:20] DEBUG[11057]: channel.c:3295 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 12 16:25:20] DEBUG[11057]: channel.c:3295 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:2827 sip_call: Outgoing Call for 9973 [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:3000 update_call_counter: Updating call counter for outgoing call [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:2842 sip_call: Our T38 capability (3840), joint T38 capability (3840) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:6158 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:6159 add_sdp: ** Our prefcodec: 0x100 (g729) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:6176 add_sdp: This call needs video offers, but there's no video support enabled! Audio is at 10.10.119.251 port 18498 Adding codec 0x8 (alaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:6290 add_sdp: -- Done with adding codecs to SDP [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:6335 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 0: INVITE sip:9973@217.9.162.2 SIP/2.0 (40) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK6ea50007;rport (66) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 2: From: "Setup" ;tag=as2e7933c4 (64) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 3: To: (31) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 4: Contact: (40) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 5: Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 (57) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 6: CSeq: 102 INVITE (16) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 9: Date: Mon, 12 Feb 2007 15:25:20 GMT (35) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 11: Supported: replaces (19) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 13: Content-Length: 293 (19) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4555 parse_request: Header 14: (0) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: v=0 (3) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: o=root 11057 11057 IN IP4 10.10.119.251 (41) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: s=session (9) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: c=IN IP4 10.10.119.251 (24) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: t=0 0 (5) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: m=audio 18498 RTP/AVP 8 3 0 101 (31) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: a=silenceSupp:off - - - - (25) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: a=ptime:20 (10) [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:4587 parse_request: Line: a=sendrecv (10) Reliably Transmitting (NAT) to 217.9.162.2:5060: INVITE sip:9973@217.9.162.2 SIP/2.0 Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK6ea50007;rport From: "Setup" ;tag=as2e7933c4 To: Contact: Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Mon, 12 Feb 2007 15:25:20 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 293 v=0 o=root 11057 11057 IN IP4 10.10.119.251 s=session c=IN IP4 10.10.119.251 t=0 0 m=audio 18498 RTP/AVP 8 3 0 101 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Feb 12 16:25:20] DEBUG[11057]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1267 -- Called 9973 [Feb 12 16:25:20] DEBUG[11057]: channel.c:2839 set_format: Set channel SIP/9973-081e4140 to read format slin [Feb 12 16:25:20] DEBUG[11057]: channel.c:2839 set_format: Set channel SIP/10.10.119.225-081e2bc0 to write format slin [Feb 12 16:25:20] DEBUG[11057]: channel.c:2839 set_format: Set channel SIP/10.10.119.225-081e2bc0 to read format slin [Feb 12 16:25:20] DEBUG[11057]: channel.c:2839 set_format: Set channel SIP/9973-081e4140 to write format slin sip*CLI> <--- SIP read from 217.9.162.2:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK6ea50007;rport From: "Setup" ;tag=as2e7933c4 To: ;tag=1c457754529 Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 CSeq: 102 INVITE Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-MP-112 FXS/v.4.80A.038.004 Content-Length: 0 <-------------> [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 0: SIP/2.0 100 Trying (18) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK6ea50007;rport (66) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 2: From: "Setup" ;tag=as2e7933c4 (64) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 3: To: ;tag=1c457754529 (47) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 4: Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 (57) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 6: Supported: em,timer,replaces,path (33) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 7: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 8: Server: Audiocodes-Sip-Gateway-MP-112 FXS/v.4.80A.038.004 (57) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 9: Content-Length: 0 (17) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:2119 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #1267 - INVITE (got response) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:2128 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251' Request 102: Found [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:11597 handle_response_invite: SIP response 100 to standard invite sip*CLI> <--- SIP read from 217.9.162.2:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK6ea50007;rport From: "Setup" ;tag=as2e7933c4 To: ;tag=1c457754529 Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 CSeq: 102 INVITE Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-MP-112 FXS/v.4.80A.038.004 Content-Length: 0 <-------------> [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK6ea50007;rport (66) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 2: From: "Setup" ;tag=as2e7933c4 (64) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 3: To: ;tag=1c457754529 (47) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 4: Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 (57) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 6: Contact: (36) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 7: Supported: em,timer,replaces,path (33) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 8: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 9: Server: Audiocodes-Sip-Gateway-MP-112 FXS/v.4.80A.038.004 (57) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 10: Content-Length: 0 (17) [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 11: (0) --- (11 headers 0 lines) --- [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:2128 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251' Request 102: Found [Feb 12 16:25:20] DEBUG[8329]: chan_sip.c:11597 handle_response_invite: SIP response 180 to standard invite [Feb 12 16:25:20] DEBUG[8329]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/9973-081e4140 -- SIP/9973-081e4140 is ringing [Feb 12 16:25:20] DEBUG[11057]: rtp.c:1514 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/10.10.119.225-081e2bc0' with that of 'SIP/9973-081e4140' <--- Transmitting (no NAT) to 10.10.119.225:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.10.119.225:5060;branch=z9hG4bK13BBC1C7A;received=194.181.119.225 From: "Setup" ;tag=53CB3B5C-F9B To: ;tag=as2885078b Call-ID: 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 12 16:25:20] DEBUG[8309]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 9973 [Feb 12 16:25:20] DEBUG[8309]: chan_sip.c:15167 sip_devicestate: Checking device state for peer 9973 [Feb 12 16:25:20] DEBUG[8309]: devicestate.c:287 do_state_change: Changing state for SIP/9973 - state 1 (Not in use) [Feb 12 16:25:20] DEBUG[11060]: app_queue.c:546 changethread: Device 'SIP/9973' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. sip*CLI> <--- SIP read from 217.9.162.2:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK6ea50007;rport From: "Setup" ;tag=as2e7933c4 To: ;tag=1c457754529 Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 CSeq: 102 INVITE Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE Server: Audiocodes-Sip-Gateway-MP-112 FXS/v.4.80A.038.004 Content-Type: application/sdp Content-Length: 229 v=0 o=AudiocodesGW 457770372 457770245 IN IP4 217.9.162.2 s=Phone-Call c=IN IP4 217.9.162.2 t=0 0 m=audio 6000 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv <-------------> [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK6ea50007;rport (66) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 2: From: "Setup" ;tag=as2e7933c4 (64) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 3: To: ;tag=1c457754529 (47) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 4: Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 (57) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 6: Contact: (36) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 7: Supported: em,timer,replaces,path (33) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 8: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 9: Server: Audiocodes-Sip-Gateway-MP-112 FXS/v.4.80A.038.004 (57) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 10: Content-Type: application/sdp (29) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 11: Content-Length: 229 (19) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 12: (0) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: v=0 (3) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: o=AudiocodesGW 457770372 457770245 IN IP4 217.9.162.2 (53) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: s=Phone-Call (12) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: c=IN IP4 217.9.162.2 (20) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: t=0 0 (5) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: m=audio 6000 RTP/AVP 8 101 (26) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: a=fmtp:101 0-15 (15) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: a=ptime:20 (10) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4587 parse_request: Line: a=sendrecv (10) --- (12 headers 11 lines) --- [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:2068 __sip_ack: Acked pending invite 102 [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251' of Request 102: Match Not Found [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:11597 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 8 Found RTP audio format 101 Peer audio RTP is at port 217.9.162.2:6000 Found description format PCMA for ID 8 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:5097 process_sdp: T38 state changed to 0 on channel SIP/9973-081e4140 Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x8 (alaw)/video=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 217.9.162.2:6000 [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:5177 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:5184 process_sdp: We have an owner, now see if we need to change this call [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:5199 process_sdp: Queueing UNHOLD! [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:3000 update_call_counter: Updating call counter for outgoing call [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:7940 build_route: build_route: Contact hop: list_route: hop: [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:5613 reqprep: Strict routing enforced for session 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 set_destination: Parsing for address/port to send to set_destination: set destination to 217.9.162.2, port 5060 Transmitting (NAT) to 217.9.162.2:5060: ACK sip:9973@217.9.162.2 SIP/2.0 Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK04a39487;rport From: "Setup" ;tag=as2e7933c4 To: ;tag=1c457754529 Contact: Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- -- Call on SIP/9973-081e4140 left from hold [Feb 12 16:25:24] DEBUG[11057]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/9973-081e4140 -- SIP/9973-081e4140 answered SIP/10.10.119.225-081e2bc0 [Feb 12 16:25:24] DEBUG[11057]: rtp.c:1514 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/10.10.119.225-081e2bc0' with that of 'SIP/9973-081e4140' [Feb 12 16:25:24] DEBUG[11057]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/10.10.119.225-081e2bc0 [Feb 12 16:25:24] DEBUG[11057]: chan_sip.c:3453 sip_answer: SIP answering channel: SIP/10.10.119.225-081e2bc0 [Feb 12 16:25:24] DEBUG[11057]: chan_sip.c:6390 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 12 16:25:24] DEBUG[11057]: chan_sip.c:6158 add_sdp: ** Our capability: 0x108 (alaw|g729) Video flag: True [Feb 12 16:25:24] DEBUG[11057]: chan_sip.c:6159 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 10.10.119.251 port 13620 Adding codec 0x100 (g729) to SDP Adding codec 0x8 (alaw) to SDP [Feb 12 16:25:24] DEBUG[11057]: chan_sip.c:6290 add_sdp: -- Done with adding codecs to SDP [Feb 12 16:25:24] DEBUG[11057]: chan_sip.c:6335 add_sdp: Done building SDP. Settling with this capability: 0x108 (alaw|g729) <--- Reliably Transmitting (no NAT) to 10.10.119.225:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.119.225:5060;branch=z9hG4bK13BBC1C7A;received=194.181.119.225 From: "Setup" ;tag=53CB3B5C-F9B To: ;tag=as2885078b Call-ID: 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 237 v=0 o=root 11057 11057 IN IP4 10.10.119.251 s=session c=IN IP4 10.10.119.251 t=0 0 m=audio 13620 RTP/AVP 18 8 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Feb 12 16:25:24] DEBUG[11057]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1269 [Feb 12 16:25:24] DEBUG[8309]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 9973 [Feb 12 16:25:24] DEBUG[8309]: chan_sip.c:15167 sip_devicestate: Checking device state for peer 9973 [Feb 12 16:25:24] DEBUG[8309]: devicestate.c:287 do_state_change: Changing state for SIP/9973 - state 1 (Not in use) [Feb 12 16:25:24] DEBUG[8309]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 10.10.119.225 [Feb 12 16:25:24] DEBUG[8309]: chan_sip.c:15167 sip_devicestate: Checking device state for peer 10.10.119.225 [Feb 12 16:25:24] DEBUG[8309]: devicestate.c:287 do_state_change: Changing state for SIP/10.10.119.225 - state 2 (In use) [Feb 12 16:25:24] DEBUG[11061]: app_queue.c:546 changethread: Device 'SIP/9973' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 12 16:25:24] DEBUG[11062]: app_queue.c:546 changethread: Device 'SIP/10.10.119.225' changed to state '2' (In use) but we don't care because they're not a member of any queue. sip*CLI> <--- SIP read from 10.10.119.225:54252 ---> ACK sip:9973@10.10.119.251:5060 SIP/2.0 Via: SIP/2.0/UDP 10.10.119.225:5060;branch=z9hG4bK13BBD1E28 From: "Setup" ;tag=53CB3B5C-F9B To: ;tag=as2885078b Date: Mon, 12 Feb 2007 15:25:54 GMT Call-ID: 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 Max-Forwards: 70 CSeq: 101 ACK Content-Length: 0 <-------------> [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 0: ACK sip:9973@10.10.119.251:5060 SIP/2.0 (46) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.119.225:5060;branch=z9hG4bK13BBD1E28 (61) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 2: From: "Setup" ;tag=53CB3B5C-F9B (66) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 3: To: ;tag=as2885078b (50) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 4: Date: Mon, 12 Feb 2007 15:25:54 GMT (35) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 5: Call-ID: 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 (60) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 7: CSeq: 101 ACK (13) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 8: Content-Length: 0 (17) [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:14562 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:2076 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1269 [Feb 12 16:25:24] DEBUG[8329]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225' of Response 101: Match Not Found [Feb 12 16:25:24] DEBUG[11057]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to alaw [Feb 12 16:25:24] DEBUG[11057]: rtp.c:2687 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Feb 12 16:25:24] DEBUG[11057]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to g729 [Feb 12 16:25:24] DEBUG[11057]: rtp.c:2687 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 [Feb 12 16:25:24] DEBUG[11057]: rtp.c:871 ast_rtcp_read: Got RTCP report of 68 bytes [Feb 12 16:25:27] DEBUG[11057]: rtp.c:871 ast_rtcp_read: Got RTCP report of 136 bytes [Feb 12 16:25:29] DEBUG[8329]: chan_sip.c:2007 __sip_autodestruct: Auto destroying SIP dialog '3992428641222007152524@217.9.162.2' [Feb 12 16:25:29] DEBUG[8329]: chan_sip.c:3106 sip_destroy: Destroying SIP dialog 3992428641222007152524@217.9.162.2 Really destroying SIP dialog '3992428641222007152524@217.9.162.2' Method: OPTIONS [Feb 12 16:25:30] DEBUG[11057]: rtp.c:871 ast_rtcp_read: Got RTCP report of 136 bytes [Feb 12 16:25:31] DEBUG[11057]: rtp.c:871 ast_rtcp_read: Got RTCP report of 68 bytes sip*CLI> <--- SIP read from 217.9.162.2:5060 ---> BYE sip:8200@10.10.119.251 SIP/2.0 Via: SIP/2.0/UDP 217.9.162.2;branch=z9hG4bKac497624569 Max-Forwards: 70 From: ;tag=1c457754529 To: "Setup" ;tag=as2e7933c4 Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 CSeq: 1 BYE Contact: Supported: em,timer,replaces,path Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE User-Agent: Audiocodes-Sip-Gateway-MP-112 FXS/v.4.80A.038.004 Reason: Q.850 ;cause=16 Content-Length: 0 <-------------> [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 0: BYE sip:8200@10.10.119.251 SIP/2.0 (41) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 1: Via: SIP/2.0/UDP 217.9.162.2;branch=z9hG4bKac497624569 (54) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 3: From: ;tag=1c457754529 (49) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 4: To: "Setup" ;tag=as2e7933c4 (62) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 5: Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 (57) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 6: CSeq: 1 BYE (11) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 7: Contact: (36) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 8: Supported: em,timer,replaces,path (33) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 9: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 10: User-Agent: Audiocodes-Sip-Gateway-MP-112 FXS/v.4.80A.038.004 (61) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 11: Reason: Q.850 ;cause=16 (23) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 12: Content-Length: 0 (17) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 13: (0) --- (13 headers 0 lines) --- [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:14562 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 217.9.162.2 : 5060 (NAT) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:1630 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:14139 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 217.9.162.2:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 217.9.162.2;branch=z9hG4bKac497624569;received=217.9.162.2 From: ;tag=1c457754529 To: "Setup" ;tag=as2e7933c4 Call-ID: 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251 CSeq: 1 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 12 16:25:36] DEBUG[11057]: channel.c:3794 ast_generic_bridge: Didn't get a frame from channel: SIP/9973-081e4140 [Feb 12 16:25:36] DEBUG[11057]: channel.c:4112 ast_channel_bridge: Bridge stops bridging channels SIP/10.10.119.225-081e2bc0 and SIP/9973-081e4140 [Feb 12 16:25:36] DEBUG[11057]: channel.c:1687 ast_hangup: Hanging up channel 'SIP/9973-081e4140' [Feb 12 16:25:36] DEBUG[11057]: chan_sip.c:3304 sip_hangup: Hangup call SIP/9973-081e4140, SIP callid 1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251) [Feb 12 16:25:36] DEBUG[11057]: chan_sip.c:3312 sip_hangup: update_call_counter(9973) - decrement call limit counter on hangup [Feb 12 16:25:36] DEBUG[11057]: chan_sip.c:3000 update_call_counter: Updating call counter for outgoing call [Feb 12 16:25:36] DEBUG[11057]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/9973-081e4140 [Feb 12 16:25:36] DEBUG[8309]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 9973 [Feb 12 16:25:36] DEBUG[8309]: chan_sip.c:15167 sip_devicestate: Checking device state for peer 9973 [Feb 12 16:25:36] DEBUG[8309]: devicestate.c:287 do_state_change: Changing state for SIP/9973 - state 1 (Not in use) [Feb 12 16:25:36] DEBUG[11057]: rtp.c:1474 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 12 16:25:36] DEBUG[11057]: app_dial.c:1658 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 12 16:25:36] DEBUG[11057]: pbx.c:2367 __ast_pbx_run: Spawn extension (test_1,9973,1) exited non-zero on 'SIP/10.10.119.225-081e2bc0' == Spawn extension (test_1, 9973, 1) exited non-zero on 'SIP/10.10.119.225-081e2bc0' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1769 pbx_extension_helper: Launching 'NoOp' -- Executing [h@test_1:1] NoOp("SIP/10.10.119.225-081e2bc0", "RTPAUDIOQOS = ") in new stack [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '"Setup" <8200>' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '8200' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '9973' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'test_1' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/10.10.119.225-081e2bc0' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/9973-081e4140' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'NoOp' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'RTPAUDIOQOS = ' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-12 16:25:20' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-12 16:25:24' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-12 16:25:36' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '16' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '12' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1171293920.326' [Feb 12 16:25:36] DEBUG[11057]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 12 16:25:36] DEBUG[11057]: channel.c:1687 ast_hangup: Hanging up channel 'SIP/10.10.119.225-081e2bc0' [Feb 12 16:25:36] DEBUG[11057]: chan_sip.c:3304 sip_hangup: Hangup call SIP/10.10.119.225-081e2bc0, SIP callid 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@194.181.119.225) [Feb 12 16:25:36] DEBUG[11057]: chan_sip.c:3312 sip_hangup: update_call_counter() - decrement call limit counter on hangup [Feb 12 16:25:36] DEBUG[11057]: chan_sip.c:3000 update_call_counter: Updating call counter for incoming call Scheduling destruction of SIP dialog '29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225' in 32000 ms (Method: ACK) [Feb 12 16:25:36] DEBUG[11057]: chan_sip.c:5613 reqprep: Strict routing enforced for session 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 set_destination: Parsing for address/port to send to set_destination: set destination to 10.10.119.225, port 5060 Reliably Transmitting (no NAT) to 10.10.119.225:5060: BYE sip:8200@10.10.119.225:5060 SIP/2.0 Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK3d2713b7;rport From: ;tag=as2885078b To: "Setup" ;tag=53CB3B5C-F9B Call-ID: 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Feb 12 16:25:36] DEBUG[11057]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1273 [Feb 12 16:25:36] DEBUG[11057]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/10.10.119.225-081e2bc0 [Feb 12 16:25:36] DEBUG[8309]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 10.10.119.225 [Feb 12 16:25:36] DEBUG[8309]: chan_sip.c:15167 sip_devicestate: Checking device state for peer 10.10.119.225 [Feb 12 16:25:36] DEBUG[8309]: devicestate.c:287 do_state_change: Changing state for SIP/10.10.119.225 - state 1 (Not in use) [Feb 12 16:25:36] DEBUG[11063]: app_queue.c:546 changethread: Device 'SIP/9973' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 12 16:25:36] DEBUG[11064]: app_queue.c:546 changethread: Device 'SIP/10.10.119.225' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. sip*CLI> <--- SIP read from 10.10.119.225:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK3d2713b7;rport From: ;tag=as2885078b To: "Setup" ;tag=53CB3B5C-F9B Date: Mon, 12 Feb 2007 15:26:10 GMT Call-ID: 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 BYE Reason: Q.850;cause=16 Content-Length: 0 <-------------> [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 1: Via: SIP/2.0/UDP 10.10.119.251:5060;branch=z9hG4bK3d2713b7;rport (66) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 2: From: ;tag=as2885078b (52) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 3: To: "Setup" ;tag=53CB3B5C-F9B (64) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 4: Date: Mon, 12 Feb 2007 15:26:10 GMT (35) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 5: Call-ID: 29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225 (60) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 7: CSeq: 102 BYE (13) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 8: Reason: Q.850;cause=16 (22) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 9: Content-Length: 0 (17) [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:4555 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:2076 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1273 [Feb 12 16:25:36] DEBUG[8329]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225' of Request 102: Match Not Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '1d0603f656ac9e7e3418bf3860fbed75@10.10.119.251' Method: BYE RTP-stats * Our Receiver: SSRC: 516295631 Received packets: 611 Lost packets: 2 Jitter: 0.0006 Transit: -0.0019 RR-count: 0 * Our Sender: SSRC: 2066550924 Sent packets: 614 Lost packets: 3 Jitter: 0 SR-count: 2 RTT: -0.392137 Really destroying SIP dialog '29ED3DC7-B9E411DB-8CC0A5A6-F170E6EE@10.10.119.225' Method: ACK RTP-stats * Our Receiver: SSRC: 426473441 Received packets: 614 Lost packets: 0 Jitter: 0.0000 Transit: 0.0002 RR-count: 0 * Our Sender: SSRC: 1163977418 Sent packets: 611 Lost packets: 0 Jitter: 560 SR-count: 2 RTT: -0.089656