ast3-gos-be*CLI> <-- SIP read from x.X.X.X:5060: INVITE sip:3271492060@x.X.X.X:5060;user=phone SIP/2.0 From: ;tag=227077ce To: CSeq: 1 INVITE Call-ID: 11c69a4370da90635a1c75c71583e952@sx3000 Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK2f84421b4 Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REGISTER,PRACK,INFO,UPDATE,SUBSCRIBE,NOTIFY,MESSAGE,REFER Max-Forwards: 70 Supported: 100rel Contact: Content-Length: 460 Content-Type: multipart/mixed;boundary=ssboundary-1_ --ssboundary-1_ Content-Length: 243 Content-Type: application/sdp v=0 o=HuaweiSoftX3000 8398238 8398238 IN IP4 10.10.13.4 s=Sip Call c=IN IP4 x.x.x.x t=0 0 m=audio 30544 RTP/AVP 18 8 0 4 a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:4 G723/8000 a=fmtp:18 annexb=yes --ssboundary-1_ Content-Length: 35 Content-Type: application/isup;version=ITU-T92+  Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:3271492060@x.x.x.x:5060;user=phone SIP/2.0 (59) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: From: ;tag=227077ce (61) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: (45) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: CSeq: 1 INVITE (14) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 11c69a4370da90635a1c75c71583e952@sx3000 (48) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK2f84421b4 (58) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Allow: INVITE,ACK,CANCEL,OPTIONS,BYE,REGISTER,PRACK,INFO,UPDATE,SUBSCRIBE,NOTIFY,MESSAGE,REFER (94) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Max-Forwards: 70 (16) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Supported: 100rel (17) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: Contact: (56) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 10: Content-Length: 460 (19) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 11: Content-Type: multipart/mixed;boundary=ssboundary-1_ (52) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 12: (0) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: --ssboundary-1_ (15) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: Content-Length: 243 (19) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: Content-Type: application/sdp (29) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: (0) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: o=HuaweiSoftX3000 8398238 8398238 IN IP4 10.10.13.4 (51) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: s=Sip Call (10) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: c=IN IP4 x.x.x.x (21) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: m=audio 30544 RTP/AVP 18 8 0 4 (30) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:18 G729/8000 (21) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:4 G723/8000 (20) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:18 annexb=yes (20) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: (0) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: --ssboundary-1_ (15) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: Content-Length: 35 (18) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: Content-Type: application/isup;version=ITU-T92+ (47) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: (0) --- (12 headers 21 lines) --- Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for 11c69a4370da90635a1c75c71583e952@sx3000 - INVITE (With RTP) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:11256 handle_request: **** Received INVITE (5) - Command in SIP INVITE Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:1014 parse_sip_options: Begin: parsing SIP "Supported: 100rel" Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:1026 parse_sip_options: Found SIP option: -100rel- Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:1032 parse_sip_options: Matched SIP option: 100rel Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:1043 parse_sip_options: * SIP extension value: 2 for call 11c69a4370da90635a1c75c71583e952@sx3000 Using INVITE request as basis request - 11c69a4370da90635a1c75c71583e952@sx3000 Sending to x.x.x.x : 5060 (non-NAT) Found peer 'xxxx' Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:7345 check_user_full: Setting NAT on RTP to 0 Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:10607 handle_request_invite: Hm.... No sdp for the moment Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:10616 handle_request_invite: Checking SIP call limits for device Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:2220 update_call_counter: Updating call counter for incoming call Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:2275 update_call_counter: Call from peer 'xxxxx' is 1 out of 30 Looking for 3271492060 in xxxxx (domain x.x.x.x) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:6233 build_route: build_route: Contact hop: list_route: hop: Transmitting (no NAT) to x.x.x.x:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK2f84421b4;received=x.x.x.x From: ;tag=227077ce To: Call-ID: 11c69a4370da90635a1c75c71583e952@sx3000 CSeq: 1 INVITE User-Agent: gatewaycomms Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Nov 21 09:40:01 DEBUG[22189]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/x.x.x.x-081c6000", "SIP/02643271492060@VERAZ||t") in new stack Nov 21 09:40:01 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer x.x.x.x Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:1888 create_addr_from_peer: Setting NAT on RTP to 0 Nov 21 09:40:01 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/x.x.x.x - state 2 (In use) Nov 21 09:40:01 DEBUG[22191]: app_queue.c:500 changethread: Device 'SIP/x.x.x.x' changed to state '2' (In use) but we don't care because they're not a member of any queue. Nov 21 09:40:01 DEBUG[22189]: channel.c:2894 ast_channel_inherit_variables: Not copying variable STACK-xxxxx-3271492060-1. Nov 21 09:40:01 DEBUG[22189]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPCALLID. Nov 21 09:40:01 DEBUG[22189]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Nov 21 09:40:01 DEBUG[22189]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPURI. Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:2082 sip_call: Outgoing Call for 02643271492060 Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:02643271492060@172.16.100.100 SIP/2.0 (48) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP 10.100.20.11:5060;branch=z9hG4bK20ce7001;rport (63) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 2: From: "249155552134" ;tag=as3f1b69dd (67) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 3: To: (39) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 4: Contact: (40) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 5: Call-ID: 63bded0b1b0077b0638e28455cc158b6@10.100.20.11 (54) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 6: CSeq: 102 INVITE (16) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 7: User-Agent: gatewaycomms (24) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 8: Max-Forwards: 70 (16) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 9: Date: Tue, 21 Nov 2006 08:40:01 GMT (35) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 11: Content-Type: application/sdp (29) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 12: Content-Length: 183 (19) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3427 parse_request: Header 13: (0) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3459 parse_request: Line: o=root 15864 15864 IN IP4 10.100.20.11 (38) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3459 parse_request: Line: s=session (9) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.100.20.11 (21) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3459 parse_request: Line: m=audio 26638 RTP/AVP 18 (24) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3459 parse_request: Line: a=rtpmap:18 G729/8000 (21) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3459 parse_request: Line: a=fmtp:18 annexb=no (19) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:3459 parse_request: Line: a=silenceSupp:off - - - - (25) Nov 21 09:40:01 DEBUG[22189]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #115 -- Called 02643271492060@VERAZ Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 100 Trying (18) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 63bded0b1b0077b0638e28455cc158b6@10.100.20.11 (54) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: "249155552134" ;tag=as3f1b69dd (67) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=11815 (49) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: CSeq: 102 INVITE (16) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: Via: SIP/2.0/UDP 10.100.20.11:5060;branch=z9hG4bK20ce7001;rport (63) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Supported: timer,100rel (23) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Content-Length: 0 (17) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: (0) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:1458 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #115 - INVITE (got response) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '63bded0b1b0077b0638e28455cc158b6@10.100.20.11' Request 102: Found Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:9686 handle_response_invite: SIP response 100 to standard invite Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 200 OK (14) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK58ceae23 (64) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: ;tag=t1164098367-co2951 (58) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "unknown" ;tag=as4f6440c6 (58) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 350cd38e39198c1f0a7e30632c5310b7@x.x.x.x (55) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 CANCEL (16) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: User-Agent: ENS2.2.102-IS4-RMRG1001-RG575-EP0-CO2951-CPO00829 (61) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Content-Length: 0 (17) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: (0) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:1402 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #114 Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '350cd38e39198c1f0a7e30632c5310b7@x.x.x.x' of Request 102: Match Found Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 487 Request Terminated (30) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK58ceae23 (64) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: ;tag=t1164098367-co2951 (58) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "unknown" ;tag=as4f6440c6 (58) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 350cd38e39198c1f0a7e30632c5310b7@x.x.x.x (55) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Contact: (45) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: User-Agent: ENS2.2.102-IS4-RMRG1001-RG575-EP0-CO2951-CPO00829 (61) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 0 (17) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: (0) Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '350cd38e39198c1f0a7e30632c5310b7@x.x.x.x' of Request 102: Match Not Found Nov 21 09:40:01 DEBUG[21989]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:0432204395448@10.100.20.11:5060;user=phone SIP/2.0 (61) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 6994090221306621223-1164098401@172.16.100.100 (54) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: sip:unknown@172.16.100.100:5060;tag=11815 (47) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: (52) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Content-Type: application/sdp (29) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 1 INVITE (14) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Via: SIP/2.0/UDP 172.16.100.100:5060;branch=z9hG4bK-611000000003ad27-ac106464-195091 (84) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Contact: sip:unknown@172.16.100.100:5060 (40) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Allow: INVITE,CANCEL,BYE,ACK,REFER,UPDATE (41) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: Supported: timer,100rel (23) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 10: Max-Forwards: 70 (16) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 11: Content-Length: 226 (19) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 12: (0) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: o=MG4000|2.0 109291 109291 IN IP4 10.57.3.24 (44) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: s=- (3) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.57.3.24 (19) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: m=audio 28504 RTP/AVP 18 0 101 13 (33) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-15 (15) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:18 annexb=yes (20) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=ptime:40 (10) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:13 CN/8000 (19) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for 6994090221306621223-1164098401@172.16.100.100 - INVITE (With RTP) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:11256 handle_request: **** Received INVITE (5) - Command in SIP INVITE Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:1014 parse_sip_options: Begin: parsing SIP "Supported: timer,100rel" Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:1026 parse_sip_options: Found SIP option: -timer- Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:1032 parse_sip_options: Matched SIP option: timer Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:1026 parse_sip_options: Found SIP option: -100rel- Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:1032 parse_sip_options: Matched SIP option: 100rel Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:1043 parse_sip_options: * SIP extension value: 6 for call 6994090221306621223-1164098401@172.16.100.100 Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:7345 check_user_full: Setting NAT on RTP to 0 Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:10616 handle_request_invite: Checking SIP call limits for device Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:2220 update_call_counter: Updating call counter for incoming call Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:6233 build_route: build_route: Contact hop: sip:unknown@172.16.100.100:5060 Nov 21 09:40:02 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer 5060 Nov 21 09:40:02 DEBUG[22193]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' Nov 21 09:40:02 DEBUG[21984]: devicestate.c:187 do_state_change: -- Executing Dial("SIP/5060-081e6240", "SIP/2204395448@193.19.106.179||t") in new stack Changing state for SIP/5060 - state 4 (Invalid) Nov 21 09:40:02 DEBUG[22194]: app_queue.c:500 changethread: Device 'SIP/5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Nov 21 09:40:02 DEBUG[22193]: channel.c:2894 ast_channel_inherit_variables: Not copying variable STACK-default-0432204395448-1. Nov 21 09:40:02 DEBUG[22193]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPCALLID. Nov 21 09:40:02 DEBUG[22193]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Nov 21 09:40:02 DEBUG[22193]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPURI. Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:2082 sip_call: Outgoing Call for 2204395448 Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:2204395448@193.19.106.179 SIP/2.0 (44) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK51b1a3c8;rport (64) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 2: From: "unknown" ;tag=as3f7080de (58) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 3: To: (35) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 4: Contact: (36) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 5: Call-ID: 265e3eb76958caa95e167e096206dc49@x.x.x.x (55) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 6: CSeq: 102 INVITE (16) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 7: User-Agent: gatewaycomms (24) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 8: Max-Forwards: 70 (16) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 9: Date: Tue, 21 Nov 2006 08:40:02 GMT (35) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 11: Content-Type: application/sdp (29) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 12: Content-Length: 185 (19) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3427 parse_request: Header 13: (0) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3459 parse_request: Line: o=root 15864 15864 IN IP4 x.x.x.x (39) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3459 parse_request: Line: s=session (9) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3459 parse_request: Line: c=IN IP4 x.x.x.x (22) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3459 parse_request: Line: m=audio 17634 RTP/AVP 18 (24) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3459 parse_request: Line: a=rtpmap:18 G729/8000 (21) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3459 parse_request: Line: a=fmtp:18 annexb=no (19) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:3459 parse_request: Line: a=silenceSupp:off - - - - (25) Nov 21 09:40:02 DEBUG[22193]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #116 -- Called 2204395448@193.19.106.179 Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 100 Trying (18) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK51b1a3c8 (64) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: (35) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "unknown" ;tag=as3f7080de (58) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 265e3eb76958caa95e167e096206dc49@x.x.x.x (55) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: User-Agent: ENS2.2.102-IS4-RMRG0-RG575-EP0-CO2959-CPO00000 (58) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Content-Length: 0 (17) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: (0) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:1458 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #116 - INVITE (got response) Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '265e3eb76958caa95e167e096206dc49@x.x.x.x' Request 102: Found Nov 21 09:40:02 DEBUG[21989]: chan_sip.c:9686 handle_response_invite: SIP response 100 to standard invite Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 183 Session Progress (28) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK51b1a3c8 (64) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: ;tag=t1164098402-co2959 (58) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "unknown" ;tag=as3f7080de (58) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 265e3eb76958caa95e167e096206dc49@x.x.x.x (55) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Contact: (45) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: User-Agent: ENS2.2.102-IS4-RMRG1001-RG575-EP0-CO2959-CPO01066 (61) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Content-Type: application/sdp (29) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: Content-Length: 217 (19) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 10: (0) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: o=- 4282827241 4282827241 IN IP4 193.19.106.179 (47) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: s=ENS Session (13) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: c=IN IP4 41.208.147.68 (22) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: m=audio 45944 RTP/AVP 18 101 (28) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:18 G729/8000 (21) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-15 (15) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=sendrecv (10) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '265e3eb76958caa95e167e096206dc49@x.x.x.x' Request 102: Found Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:9686 handle_response_invite: SIP response 183 to standard invite -- SIP/193.19.106.179-081ab8d8 is making progress passing it to SIP/5060-081e6240 Nov 21 09:40:03 DEBUG[22193]: rtp.c:411 ast_rtcp_read: Got RTCP report of 28 bytes Nov 21 09:40:03 DEBUG[22193]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to g729 Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 183 Session Progress (28) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 63bded0b1b0077b0638e28455cc158b6@10.100.20.11 (54) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: "249155552134" ;tag=as3f1b69dd (67) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=11815 (49) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: CSeq: 102 INVITE (16) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: Via: SIP/2.0/UDP 10.100.20.11:5060;branch=z9hG4bK20ce7001;rport (63) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Supported: timer,100rel (23) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Content-Length: 0 (17) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: (0) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '63bded0b1b0077b0638e28455cc158b6@10.100.20.11' Request 102: Found Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:9686 handle_response_invite: SIP response 183 to standard invite Nov 21 09:40:03 DEBUG[22193]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 183 Session Progress (28) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 63bded0b1b0077b0638e28455cc158b6@10.100.20.11 (54) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: "249155552134" ;tag=as3f1b69dd (67) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=11815 (49) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Content-Type: application/sdp (29) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Via: SIP/2.0/UDP 10.100.20.11:5060;branch=z9hG4bK20ce7001;rport (63) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Supported: timer,100rel (23) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 143 (19) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: (0) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: o=MG4000|2.0 19413 19413 IN IP4 10.100.1.23 (43) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: s=- (3) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.100.1.23 (20) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: m=audio 55540 RTP/AVP 18 (24) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:18 annexb=no (19) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=ptime:40 (10) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '63bded0b1b0077b0638e28455cc158b6@10.100.20.11' Request 102: Found Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:9686 handle_response_invite: SIP response 183 to standard invite -- SIP/VERAZ-08195d00 is making progress passing it to SIP/x.x.x.x-081c6000 We're at x.x.x.x port 37946 Adding codec 0x100 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP Transmitting (no NAT) to x.x.x.x:5060: SIP/2.0 183 Session Progress Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK2f84421b4;received=x.x.x.x From: ;tag=227077ce To: ;tag=as6ce1b37f Call-ID: 11c69a4370da90635a1c75c71583e952@sx3000 CSeq: 1 INVITE User-Agent: gatewaycomms Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 241 v=0 o=root 15864 15864 IN IP4 x.x.x.x s=session c=IN IP4 x.x.x.x t=0 0 m=audio 37946 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 - - - - --- Nov 21 09:40:03 DEBUG[22189]: rtp.c:411 ast_rtcp_read: Got RTCP report of 28 bytes Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 180 Ringing (19) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 63bded0b1b0077b0638e28455cc158b6@10.100.20.11 (54) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: "249155552134" ;tag=as3f1b69dd (67) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=11815 (49) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Content-Type: application/sdp (29) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Via: SIP/2.0/UDP 10.100.20.11:5060;branch=z9hG4bK20ce7001;rport (63) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Supported: timer,100rel (23) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 143 (19) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: (0) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: o=MG4000|2.0 19413 19413 IN IP4 10.100.1.23 (43) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: s=- (3) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.100.1.23 (20) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: m=audio 55540 RTP/AVP 18 (24) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:18 annexb=no (19) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=ptime:40 (10) Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '63bded0b1b0077b0638e28455cc158b6@10.100.20.11' Request 102: Found Nov 21 09:40:03 DEBUG[21989]: chan_sip.c:9686 handle_response_invite: SIP response 180 to standard invite Nov 21 09:40:03 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer VERAZ -- SIP/VERAZ-08195d00 is ringing Nov 21 09:40:03 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/VERAZ - state 6 (Ringing) Nov 21 09:40:03 DEBUG[22196]: app_queue.c:500 changethread: Device 'SIP/VERAZ' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. Transmitting (no NAT) to x.x.x.x:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK2f84421b4;received=x.x.x.x From: ;tag=227077ce To: ;tag=as6ce1b37f Call-ID: 11c69a4370da90635a1c75c71583e952@sx3000 CSeq: 1 INVITE User-Agent: gatewaycomms Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- -- SIP/VERAZ-08195d00 is making progress passing it to SIP/x.x.x.x-081c6000 Nov 21 09:40:03 DEBUG[22189]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:0432209947912@10.100.20.11:5060;user=phone SIP/2.0 (61) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 6994090221306621227-1164098404@172.16.100.100 (54) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: ;tag=29562 (64) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: (52) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Content-Type: application/sdp (29) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 1 INVITE (14) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Via: SIP/2.0/UDP 172.16.100.100:5060;branch=z9hG4bK-611000000003ad2b-ac106464-195094 (84) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Contact: sip:23276515911@172.16.100.100:5060;user=phone (55) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Allow: INVITE,CANCEL,BYE,ACK,REFER,UPDATE (41) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: Supported: timer,100rel (23) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 10: Max-Forwards: 70 (16) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 11: Content-Length: 228 (19) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 12: (0) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: o=MG4000|2.0 113661 113661 IN IP4 10.57.2.201 (45) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: s=- (3) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.57.2.201 (20) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: m=audio 53556 RTP/AVP 18 0 101 13 (33) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-15 (15) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:18 annexb=yes (20) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=ptime:40 (10) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:13 CN/8000 (19) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for 6994090221306621227-1164098404@172.16.100.100 - INVITE (With RTP) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:11256 handle_request: **** Received INVITE (5) - Command in SIP INVITE Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:1014 parse_sip_options: Begin: parsing SIP "Supported: timer,100rel" Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:1026 parse_sip_options: Found SIP option: -timer- Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:1032 parse_sip_options: Matched SIP option: timer Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:1026 parse_sip_options: Found SIP option: -100rel- Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:1032 parse_sip_options: Matched SIP option: 100rel Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:1043 parse_sip_options: * SIP extension value: 6 for call 6994090221306621227-1164098404@172.16.100.100 Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:7345 check_user_full: Setting NAT on RTP to 0 Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:10616 handle_request_invite: Checking SIP call limits for device Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:2220 update_call_counter: Updating call counter for incoming call Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:6233 build_route: build_route: Contact hop: sip:23276515911@172.16.100.100:5060;user=phone Nov 21 09:40:05 DEBUG[22198]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' Nov 21 09:40:05 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: -- Executing Dial("SIP/5060-0818f1b0", "SIP/2209947912@193.19.106.179||t") in new stack Checking device state for peer 5060 Nov 21 09:40:05 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/5060 - state 4 (Invalid) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Nov 21 09:40:05 DEBUG[22199]: app_queue.c:500 changethread: Device 'SIP/5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. Nov 21 09:40:05 DEBUG[22198]: channel.c:2894 ast_channel_inherit_variables: Not copying variable STACK-default-0432209947912-1. Nov 21 09:40:05 DEBUG[22198]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPCALLID. Nov 21 09:40:05 DEBUG[22198]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Nov 21 09:40:05 DEBUG[22198]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPURI. Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:2082 sip_call: Outgoing Call for 2209947912 Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:2209947912@193.19.106.179 SIP/2.0 (44) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK039e4d86;rport (64) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 2: From: "23276515911" ;tag=as4ad9385c (66) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 3: To: (35) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 4: Contact: (40) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 5: Call-ID: 4c813cbf10250ed35e47114a58bc2478@x.x.x.x (55) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 6: CSeq: 102 INVITE (16) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 7: User-Agent: gatewaycomms (24) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 8: Max-Forwards: 70 (16) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 9: Date: Tue, 21 Nov 2006 08:40:05 GMT (35) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 11: Content-Type: application/sdp (29) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 12: Content-Length: 185 (19) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3427 parse_request: Header 13: (0) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3459 parse_request: Line: o=root 15864 15864 IN IP4 x.x.x.x (39) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3459 parse_request: Line: s=session (9) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3459 parse_request: Line: c=IN IP4 x.x.x.x (22) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3459 parse_request: Line: m=audio 14710 RTP/AVP 18 (24) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3459 parse_request: Line: a=rtpmap:18 G729/8000 (21) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3459 parse_request: Line: a=fmtp:18 annexb=no (19) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:3459 parse_request: Line: a=silenceSupp:off - - - - (25) Nov 21 09:40:05 DEBUG[22198]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #117 -- Called 2209947912@193.19.106.179 Nov 21 09:40:05 DEBUG[22163]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: INFO sip:0432209951248@10.100.20.11:5060;user=phone SIP/2.0 (59) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 6994090221306621205-1164098376@172.16.100.100 (54) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: anonymous ;tag=16841 (59) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=as471d453c (67) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: CSeq: 2 INFO (12) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: Via: SIP/2.0/UDP 172.16.100.100:5060;branch=z9hG4bK-611000000003ad15-ac106464-195096 (84) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Supported: timer,100rel (23) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Max-Forwards: 70 (16) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 11 (18) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: Content-Type: application/dtmf-relay (36) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 10: (0) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: Signal= # (9) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:11256 handle_request: **** Received INFO (13) - Command in SIP INFO * DTMF-relay event received: # Nov 21 09:40:05 DEBUG[22163]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #118 Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 100 Trying (18) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK039e4d86 (64) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: (35) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "23276515911" ;tag=as4ad9385c (66) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 4c813cbf10250ed35e47114a58bc2478@x.x.x.x (55) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: User-Agent: ENS2.2.102-IS4-RMRG0-RG575-EP0-CO2960-CPO00000 (58) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Content-Length: 0 (17) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: (0) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:1458 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #117 - INVITE (got response) Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4c813cbf10250ed35e47114a58bc2478@x.x.x.x' Request 102: Found Nov 21 09:40:05 DEBUG[21989]: chan_sip.c:9686 handle_response_invite: SIP response 100 to standard invite Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: INFO sip:0432209951248@10.100.20.11:5060;user=phone SIP/2.0 (59) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 6994090221306621205-1164098376@172.16.100.100 (54) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: anonymous ;tag=16841 (59) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=as471d453c (67) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: CSeq: 3 INFO (12) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: Via: SIP/2.0/UDP 172.16.100.100:5060;branch=z9hG4bK-611000000003ad15-ac106464-195097 (84) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Supported: timer,100rel (23) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Max-Forwards: 70 (16) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 11 (18) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: Content-Type: application/dtmf-relay (36) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 10: (0) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: Signal= # (9) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:11256 handle_request: **** Received INFO (13) - Command in SIP INFO * DTMF-relay event received: # Nov 21 09:40:06 DEBUG[22163]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #119 Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 200 OK (14) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK79151e52 (64) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: ;tag=t1164098376-co2953 (58) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "anonymous" ;tag=as6c97933d (62) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 755c59fe4b4895007651ebb82f268a04@x.x.x.x (55) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 103 INFO (14) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: User-Agent: ENS2.2.102-IS4-RMRG1001-RG575-EP0-CO2953-CPO00900 (61) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Content-Length: 0 (17) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: (0) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:1402 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #118 Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '755c59fe4b4895007651ebb82f268a04@x.x.x.x' of Request 103: Match Found Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 200 OK (14) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK1f6bf68b (64) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: ;tag=t1164098376-co2953 (58) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "anonymous" ;tag=as6c97933d (62) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 755c59fe4b4895007651ebb82f268a04@x.x.x.x (55) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 104 INFO (14) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: User-Agent: ENS2.2.102-IS4-RMRG1001-RG575-EP0-CO2953-CPO00900 (61) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Content-Length: 0 (17) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: (0) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:1402 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #119 Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '755c59fe4b4895007651ebb82f268a04@x.x.x.x' of Request 104: Match Found Nov 21 09:40:06 DEBUG[22163]: rtp.c:411 ast_rtcp_read: Got RTCP report of 24 bytes Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: BYE sip:0432209951248@10.100.20.11:5060;user=phone SIP/2.0 (58) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 6994090221306621205-1164098376@172.16.100.100 (54) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: anonymous ;tag=16841 (59) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=as471d453c (67) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: CSeq: 4 BYE (11) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: Via: SIP/2.0/UDP 172.16.100.100:5060;branch=z9hG4bK-611000000003ad15-ac106464-195098 (84) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Supported: timer,100rel (23) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Max-Forwards: 70 (16) Nov 21 09:40:06 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 0 (17) Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: (0) Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:11256 handle_request: **** Received BYE (8) - Command in SIP BYE Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:10905 handle_request_bye: Received bye, issuing owner hangup .Nov 21 09:40:07 DEBUG[22163]: channel.c:3369 ast_generic_bridge: Didn't get a frame from channel: SIP/anonymous.invalid-081df420 Nov 21 09:40:07 DEBUG[22163]: channel.c:3654 ast_channel_bridge: Bridge stops bridging channels SIP/anonymous.invalid-081df420 and SIP/193.19.106.179-081ee8e0 Nov 21 09:40:07 DEBUG[22163]: channel.c:1364 ast_hangup: Hanging up channel 'SIP/193.19.106.179-081ee8e0' Nov 21 09:40:07 DEBUG[22163]: chan_sip.c:2430 sip_hangup: Hangup call SIP/193.19.106.179-081ee8e0, SIP callid 755c59fe4b4895007651ebb82f268a04@x.x.x.x) Nov 21 09:40:07 DEBUG[22163]: chan_sip.c:2438 sip_hangup: update_call_counter(2209951248) - decrement call limit counter Nov 21 09:40:07 DEBUG[22163]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call Nov 21 09:40:07 DEBUG[22163]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #121 Nov 21 09:40:07 DEBUG[22163]: app_dial.c:1635 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Nov 21 09:40:07 DEBUG[22163]: pbx.c:2316 __ast_pbx_run: Spawn extension (default,0432209951248,1) exited non-zero on 'SIP/anonymous.invalid-081df420' == Spawn extension (default, 0432209951248, 1) exited non-zero on 'SIP/anonymous.invalid-081df420' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"anonymous" ' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'anonymous' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0432209951248' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'default' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/anonymous.invalid-081df420' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/193.19.106.179-081ee8e0' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/2209951248@193.19.106.179||t' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-21 09:39:36' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-21 09:39:53' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-21 09:40:07' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '31' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '14' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1164098376.52' Nov 21 09:40:07 DEBUG[22163]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 21 09:40:07 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer 193.19.106.179 Nov 21 09:40:07 DEBUG[22163]: channel.c:1364 ast_hangup: Hanging up channel 'SIP/anonymous.invalid-081df420' Nov 21 09:40:07 DEBUG[22163]: chan_sip.c:2430 sip_hangup: Hangup call SIP/anonymous.invalid-081df420, SIP callid 6994090221306621205-1164098376@172.16.100.100) Nov 21 09:40:07 DEBUG[22163]: chan_sip.c:2438 sip_hangup: update_call_counter() - decrement call limit counter Nov 21 09:40:07 DEBUG[22163]: chan_sip.c:2220 update_call_counter: Updating call counter for incoming call Nov 21 09:40:07 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/193.19.106.179 - state 2 (In use) Nov 21 09:40:07 DEBUG[22201]: app_queue.c:500 changethread: Device 'SIP/193.19.106.179' changed to state '2' (In use) but we don't care because they're not a member of any queue. Nov 21 09:40:07 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer anonymous.invalid Nov 21 09:40:07 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/anonymous.invalid - state 4 (Invalid) Nov 21 09:40:07 DEBUG[22202]: app_queue.c:500 changethread: Device 'SIP/anonymous.invalid' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 200 OK (14) Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK1379e578 (64) Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: ;tag=t1164098376-co2953 (58) Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "anonymous" ;tag=as6c97933d (62) Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 755c59fe4b4895007651ebb82f268a04@x.x.x.x (55) Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 105 BYE (13) Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: User-Agent: ENS2.2.102-IS4-RMRG1001-RG575-EP0-CO2953-CPO00900 (61) Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Content-Length: 0 (17) Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: (0) Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:1402 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #121 Nov 21 09:40:07 DEBUG[21989]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '755c59fe4b4895007651ebb82f268a04@x.x.x.x' of Request 105: Match Found Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 183 Session Progress (28) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK039e4d86 (64) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: ;tag=t1164098405-co2960 (58) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "23276515911" ;tag=as4ad9385c (66) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 4c813cbf10250ed35e47114a58bc2478@x.x.x.x (55) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Contact: (45) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: User-Agent: ENS2.2.102-IS4-RMRG1001-RG575-EP0-CO2960-CPO01094 (61) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Content-Type: application/sdp (29) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: Content-Length: 217 (19) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 10: (0) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: o=- 4280535332 4280535332 IN IP4 193.19.106.179 (47) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: s=ENS Session (13) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: c=IN IP4 41.208.147.68 (22) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: m=audio 43972 RTP/AVP 18 101 (28) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:18 G729/8000 (21) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-15 (15) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=sendrecv (10) Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4c813cbf10250ed35e47114a58bc2478@x.x.x.x' Request 102: Found Nov 21 09:40:08 DEBUG[21989]: chan_sip.c:9686 handle_response_invite: SIP response 183 to standard invite -- SIP/193.19.106.179-081b62f8 is making progress passing it to SIP/5060-0818f1b0 Nov 21 09:40:08 DEBUG[22189]: rtp.c:411 ast_rtcp_read: Got RTCP report of 60 bytes Nov 21 09:40:08 DEBUG[22198]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to g729 Nov 21 09:40:09 DEBUG[22198]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes Nov 21 09:40:09 DEBUG[22198]: rtp.c:502 ast_rtp_read: Forcing Marker bit, because SSRC has changed Nov 21 09:40:09 DEBUG[22198]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes Nov 21 09:40:09 DEBUG[22189]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:0432209927554@10.100.20.11:5060;user=phone SIP/2.0 (61) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 6994090221306621233-1164098409@172.16.100.100 (54) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: ;tag=15449 (61) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: (52) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Content-Type: application/sdp (29) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 1 INVITE (14) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Via: SIP/2.0/UDP 172.16.100.100:5060;branch=z9hG4bK-611000000003ad31-ac106464-195101 (84) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Contact: sip:35422122@172.16.100.100:5060;user=phone (52) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Allow: INVITE,CANCEL,BYE,ACK,REFER,UPDATE (41) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: Supported: timer,100rel (23) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 10: Max-Forwards: 70 (16) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 11: Content-Length: 224 (19) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 12: (0) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: o=MG4000|2.0 24549 24549 IN IP4 10.57.3.22 (42) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: s=- (3) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.57.3.22 (19) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: m=audio 41912 RTP/AVP 18 0 101 13 (33) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-15 (15) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:18 annexb=yes (20) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=ptime:40 (10) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:13 CN/8000 (19) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for 6994090221306621233-1164098409@172.16.100.100 - INVITE (With RTP) Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:11256 handle_request: **** Received INVITE (5) - Command in SIP INVITE Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:1014 parse_sip_options: Begin: parsing SIP "Supported: timer,100rel" Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:1026 parse_sip_options: Found SIP option: -timer- Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:1032 parse_sip_options: Matched SIP option: timer Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:1026 parse_sip_options: Found SIP option: -100rel- Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:1032 parse_sip_options: Matched SIP option: 100rel Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:1043 parse_sip_options: * SIP extension value: 6 for call 6994090221306621233-1164098409@172.16.100.100 Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:7345 check_user_full: Setting NAT on RTP to 0 Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:10616 handle_request_invite: Checking SIP call limits for device Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:2220 update_call_counter: Updating call counter for incoming call Nov 21 09:40:09 DEBUG[21989]: chan_sip.c:6233 build_route: build_route: Contact hop: sip:35422122@172.16.100.100:5060;user=phone Nov 21 09:40:09 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer 5060 Nov 21 09:40:09 DEBUG[22204]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/5060-081bf758", "SIP/2209927554@193.19.106.179||t") in new stack Nov 21 09:40:09 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/5060 - state 4 (Invalid) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3176 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Nov 21 09:40:09 DEBUG[22205]: app_queue.c:500 changethread: Device 'SIP/5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. Nov 21 09:40:09 DEBUG[22204]: channel.c:2894 ast_channel_inherit_variables: Not copying variable STACK-default-0432209927554-1. Nov 21 09:40:09 DEBUG[22204]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPCALLID. Nov 21 09:40:09 DEBUG[22204]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Nov 21 09:40:09 DEBUG[22204]: channel.c:2894 ast_channel_inherit_variables: Not copying variable SIPURI. Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:2082 sip_call: Outgoing Call for 2209927554 Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 0: INVITE sip:2209927554@193.19.106.179 SIP/2.0 (44) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK0d5c9e2c;rport (64) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 2: From: "35422122" ;tag=as714bb21a (60) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 3: To: (35) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 4: Contact: (37) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 5: Call-ID: 63bed57d7ebf4d2d624d75723f0ece28@x.x.x.x (55) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 6: CSeq: 102 INVITE (16) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 7: User-Agent: gatewaycomms (24) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 8: Max-Forwards: 70 (16) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 9: Date: Tue, 21 Nov 2006 08:40:09 GMT (35) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 11: Content-Type: application/sdp (29) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 12: Content-Length: 185 (19) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3427 parse_request: Header 13: (0) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3459 parse_request: Line: o=root 15864 15864 IN IP4 x.x.x.x (39) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3459 parse_request: Line: s=session (9) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3459 parse_request: Line: c=IN IP4 x.x.x.x (22) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3459 parse_request: Line: m=audio 12216 RTP/AVP 18 (24) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3459 parse_request: Line: a=rtpmap:18 G729/8000 (21) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3459 parse_request: Line: a=fmtp:18 annexb=no (19) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:3459 parse_request: Line: a=silenceSupp:off - - - - (25) Nov 21 09:40:09 DEBUG[22204]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #122 -- Called 2209927554@193.19.106.179 Nov 21 09:40:10 DEBUG[22193]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 100 Trying (18) Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK0d5c9e2c (64) Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: (35) Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "35422122" ;tag=as714bb21a (60) Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 63bed57d7ebf4d2d624d75723f0ece28@x.x.x.x (55) Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: User-Agent: ENS2.2.102-IS4-RMRG0-RG575-EP0-CO2962-CPO00000 (58) Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Content-Length: 0 (17) Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: (0) Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:1458 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #122 - INVITE (got response) Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '63bed57d7ebf4d2d624d75723f0ece28@x.x.x.x' Request 102: Found Nov 21 09:40:10 DEBUG[21989]: chan_sip.c:9686 handle_response_invite: SIP response 100 to standard invite Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: CANCEL sip:0432209927554@10.100.20.11:5060;user=phone SIP/2.0 (61) Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 6994090221306621233-1164098409@172.16.100.100 (54) Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: ;tag=15449 (61) Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: (52) Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: CSeq: 1 CANCEL (14) Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: Via: SIP/2.0/UDP 172.16.100.100:5060;branch=z9hG4bK-611000000003ad31-ac106464-195101 (84) Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Supported: timer,100rel (23) Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Max-Forwards: 70 (16) Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 0 (17) Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: (0) Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:11256 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL Nov 21 09:40:12 DEBUG[21989]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #123 Nov 21 09:40:12 DEBUG[22204]: channel.c:1364 ast_hangup: Hanging up channel 'SIP/193.19.106.179-0819b240' Nov 21 09:40:12 DEBUG[22204]: chan_sip.c:2430 sip_hangup: Hangup call SIP/193.19.106.179-0819b240, SIP callid 63bed57d7ebf4d2d624d75723f0ece28@x.x.x.x) Nov 21 09:40:12 DEBUG[22204]: chan_sip.c:2438 sip_hangup: update_call_counter(2209927554) - decrement call limit counter Nov 21 09:40:12 DEBUG[22204]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call Nov 21 09:40:12 DEBUG[22204]: chan_sip.c:1391 __sip_ack: Acked pending invite 102 Nov 21 09:40:12 DEBUG[22204]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '63bed57d7ebf4d2d624d75723f0ece28@x.x.x.x' of Request 102: Match Found Nov 21 09:40:12 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer 193.19.106.179 Nov 21 09:40:12 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/193.19.106.179 - state 2 (In use) Nov 21 09:40:12 DEBUG[22207]: app_queue.c:500 changethread: Device 'SIP/193.19.106.179' changed to state '2' (In use) but we don't care because they're not a member of any queue. Nov 21 09:40:12 DEBUG[22204]: app_dial.c:1635 dial_exec_full: Exiting with DIALSTATUS=CANCEL. Nov 21 09:40:12 DEBUG[22204]: pbx.c:2316 __ast_pbx_run: Spawn extension (default,0432209927554,1) exited non-zero on 'SIP/5060-081bf758' == Spawn extension (default, 0432209927554, 1) exited non-zero on 'SIP/5060-081bf758' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '35422122' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '35422122' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0432209927554' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'default' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/5060-081bf758' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/193.19.106.179-0819b240' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/2209927554@193.19.106.179||t' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-21 09:40:09' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-21 09:40:12' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '3' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1164098409.62' Nov 21 09:40:12 DEBUG[22204]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 21 09:40:12 DEBUG[22204]: channel.c:1364 ast_hangup: Hanging up channel 'SIP/5060-081bf758' Nov 21 09:40:12 DEBUG[22204]: chan_sip.c:2430 sip_hangup: Hangup call SIP/5060-081bf758, SIP callid 6994090221306621233-1164098409@172.16.100.100) Nov 21 09:40:12 DEBUG[22204]: chan_sip.c:2438 sip_hangup: update_call_counter() - decrement call limit counter Nov 21 09:40:12 DEBUG[22204]: chan_sip.c:2220 update_call_counter: Updating call counter for incoming call Nov 21 09:40:12 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer 5060 Nov 21 09:40:12 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/5060 - state 4 (Invalid) Nov 21 09:40:12 DEBUG[22208]: app_queue.c:500 changethread: Device 'SIP/5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 183 Session Progress (28) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK0d5c9e2c (64) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: ;tag=t1164098410-co2962 (58) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "35422122" ;tag=as714bb21a (60) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 63bed57d7ebf4d2d624d75723f0ece28@x.x.x.x (55) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Contact: (45) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: User-Agent: ENS2.2.102-IS4-RMRG1001-RG575-EP0-CO2962-CPO01132 (61) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Content-Type: application/sdp (29) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: Content-Length: 217 (19) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 10: (0) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: o=- 4283187047 4283187047 IN IP4 193.19.106.179 (47) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: s=ENS Session (13) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: c=IN IP4 41.208.147.68 (22) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: m=audio 42876 RTP/AVP 18 101 (28) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:18 G729/8000 (21) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:101 0-15 (15) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=sendrecv (10) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:1467 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '63bed57d7ebf4d2d624d75723f0ece28@x.x.x.x' Request 102: Not Found Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:9686 handle_response_invite: SIP response 183 to standard invite Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #125 Nov 21 09:40:13 DEBUG[22189]: rtp.c:411 ast_rtcp_read: Got RTCP report of 60 bytes Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 200 OK (14) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Via: SIP/2.0/UDP x.x.x.x:5060;rport;branch=z9hG4bK3d75eaa3 (64) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: ;tag=t1164098410-co2962 (58) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: From: "35422122" ;tag=as714bb21a (60) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 63bed57d7ebf4d2d624d75723f0ece28@x.x.x.x (55) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 103 BYE (13) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: User-Agent: ENS2.2.102-IS4-RMRG1001-RG575-EP0-CO2962-CPO01132 (61) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Content-Length: 0 (17) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: (0) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:1402 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #125 Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '63bed57d7ebf4d2d624d75723f0ece28@x.x.x.x' of Request 103: Match Found Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:1194 retrans_pkt: SIP TIMER: Rescheduling retransmission #123 (1) SIP/2.0 - 1 Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:1208 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #123)) Nov 21 09:40:13 DEBUG[22193]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 200 OK (14) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 63bded0b1b0077b0638e28455cc158b6@10.100.20.11 (54) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: "249155552134" ;tag=as3f1b69dd (67) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: ;tag=11815 (49) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Content-Type: application/sdp (29) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: CSeq: 102 INVITE (16) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Via: SIP/2.0/UDP 10.100.20.11:5060;branch=z9hG4bK20ce7001;rport (63) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Contact: sip:02643271492060@172.16.100.100:5060;user=phone (58) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Supported: timer,100rel (23) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: Content-Length: 143 (19) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 10: (0) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: v=0 (3) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: o=MG4000|2.0 19413 19413 IN IP4 10.100.1.23 (43) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: s=- (3) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: c=IN IP4 10.100.1.23 (20) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: t=0 0 (5) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: m=audio 55540 RTP/AVP 18 (24) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=fmtp:18 annexb=no (19) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:3459 parse_request: Line: a=ptime:40 (10) Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:1391 __sip_ack: Acked pending invite 102 Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '63bded0b1b0077b0638e28455cc158b6@10.100.20.11' of Request 102: Match Found Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:9686 handle_response_invite: SIP response 200 to standard invite Nov 21 09:40:13 DEBUG[21989]: chan_sip.c:6233 build_route: build_route: Contact hop: sip:02643271492060@172.16.100.100:5060;user=phone -- SIP/VERAZ-08195d00 answered SIP/x.x.x.x-081c6000 Nov 21 09:40:13 DEBUG[22189]: chan_sip.c:2560 sip_answer: sip_answer(SIP/x.x.x.x-081c6000) We're at x.x.x.x port 37946 Adding codec 0x100 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (no NAT) to x.x.x.x:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK2f84421b4;received=x.x.x.x From: ;tag=227077ce To: ;tag=as6ce1b37f Call-ID: 11c69a4370da90635a1c75c71583e952@sx3000 CSeq: 1 INVITE User-Agent: gatewaycomms Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 241 v=0 o=root 15864 15865 IN IP4 x.x.x.x s=session c=IN IP4 x.x.x.x t=0 0 m=audio 37946 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 - - - - --- Nov 21 09:40:13 DEBUG[22189]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #127 Nov 21 09:40:13 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer VERAZ Nov 21 09:40:13 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/VERAZ - state 2 (In use) Nov 21 09:40:13 DEBUG[22209]: app_queue.c:500 changethread: Device 'SIP/VERAZ' changed to state '2' (In use) but we don't care because they're not a member of any queue. Nov 21 09:40:13 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer x.x.x.x Nov 21 09:40:13 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/x.x.x.x - state 2 (In use) Nov 21 09:40:13 DEBUG[22210]: app_queue.c:500 changethread: Device 'SIP/x.x.x.x' changed to state '2' (In use) but we don't care because they're not a member of any queue. ast3-gos-be*CLI> <-- SIP read from x.x.x.x:5060: ACK sip:3271492060@x.x.x.x SIP/2.0 From: ;tag=227077ce To: ;tag=as6ce1b37f CSeq: 1 ACK Call-ID: 11c69a4370da90635a1c75c71583e952@sx3000 Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bKc15742b16 Max-Forwards: 70 Content-Length: 0 Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: ACK sip:3271492060@x.x.x.x SIP/2.0 (40) Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: From: ;tag=227077ce (61) Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: ;tag=as6ce1b37f (60) Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: CSeq: 1 ACK (11) Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 11c69a4370da90635a1c75c71583e952@sx3000 (48) Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bKc15742b16 (58) Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Max-Forwards: 70 (16) Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Content-Length: 0 (17) Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: (0) --- (8 headers 0 lines) --- Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:11256 handle_request: **** Received ACK (6) - Command in SIP ACK Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:1402 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #127 Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '11c69a4370da90635a1c75c71583e952@sx3000' of Response 1: Match Found Nov 21 09:40:14 DEBUG[22198]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:1194 retrans_pkt: SIP TIMER: Rescheduling retransmission #123 (2) SIP/2.0 - 1 Nov 21 09:40:14 DEBUG[21989]: chan_sip.c:1208 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #123)) Nov 21 09:40:15 DEBUG[22189]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes Nov 21 09:40:16 DEBUG[21989]: chan_sip.c:1194 retrans_pkt: SIP TIMER: Rescheduling retransmission #123 (3) SIP/2.0 - 1 Nov 21 09:40:16 DEBUG[21989]: chan_sip.c:1208 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #123)) Nov 21 09:40:18 DEBUG[22189]: rtp.c:411 ast_rtcp_read: Got RTCP report of 60 bytes Nov 21 09:40:19 DEBUG[22189]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes Nov 21 09:40:19 DEBUG[22189]: rtp.c:411 ast_rtcp_read: Got RTCP report of 24 bytes Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: BYE sip:249155552134@10.100.20.11:5060;user=phone SIP/2.0 (57) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: Call-ID: 63bded0b1b0077b0638e28455cc158b6@10.100.20.11 (54) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: From: ;tag=11815 (51) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: To: "249155552134" ;tag=as3f1b69dd (65) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: CSeq: 1 BYE (11) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: Via: SIP/2.0/UDP 172.16.100.100:5060;branch=z9hG4bK-811000000003ad23-ac106464-195105 (84) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Supported: timer,100rel (23) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: Max-Forwards: 70 (16) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 8: Content-Length: 0 (17) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 9: (0) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:11256 handle_request: **** Received BYE (8) - Command in SIP BYE Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:10905 handle_request_bye: Received bye, issuing owner hangup .Nov 21 09:40:19 DEBUG[22189]: channel.c:3369 ast_generic_bridge: Didn't get a frame from channel: SIP/VERAZ-08195d00 Nov 21 09:40:19 DEBUG[22189]: channel.c:3654 ast_channel_bridge: Bridge stops bridging channels SIP/x.x.x.x-081c6000 and SIP/VERAZ-08195d00 Nov 21 09:40:19 DEBUG[22189]: channel.c:1364 ast_hangup: Hanging up channel 'SIP/VERAZ-08195d00' Nov 21 09:40:19 DEBUG[22189]: chan_sip.c:2430 sip_hangup: Hangup call SIP/VERAZ-08195d00, SIP callid 63bded0b1b0077b0638e28455cc158b6@10.100.20.11) Nov 21 09:40:19 DEBUG[22189]: chan_sip.c:2438 sip_hangup: update_call_counter(02643271492060) - decrement call limit counter Nov 21 09:40:19 DEBUG[22189]: chan_sip.c:2220 update_call_counter: Updating call counter for outgoing call Nov 21 09:40:19 DEBUG[22189]: app_dial.c:1635 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Nov 21 09:40:19 DEBUG[22189]: pbx.c:2316 __ast_pbx_run: Spawn extension (xxxxx,3271492060,1) exited non-zero on 'SIP/x.x.x.x-081c6000' == Spawn extension (xxxxx, 3271492060, 1) exited non-zero on 'SIP/x.x.x.x-081c6000' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '249155552134' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '249155552134' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '3271492060' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'xxxxx' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/x.x.x.x-081c6000' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/VERAZ-08195d00' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/02643271492060@VERAZ||t' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-21 09:40:01' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-21 09:40:13' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-11-21 09:40:19' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '18' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '6' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1164098401.56' Nov 21 09:40:19 DEBUG[22189]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Nov 21 09:40:19 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer VERAZ Nov 21 09:40:19 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/VERAZ - state 1 (Not in use) Nov 21 09:40:19 DEBUG[22211]: app_queue.c:500 changethread: Device 'SIP/VERAZ' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Nov 21 09:40:19 DEBUG[22189]: channel.c:1364 ast_hangup: Hanging up channel 'SIP/x.x.x.x-081c6000' Nov 21 09:40:19 DEBUG[22189]: chan_sip.c:2430 sip_hangup: Hangup call SIP/x.x.x.x-081c6000, SIP callid 11c69a4370da90635a1c75c71583e952@sx3000) Nov 21 09:40:19 DEBUG[22189]: chan_sip.c:2438 sip_hangup: update_call_counter() - decrement call limit counter Nov 21 09:40:19 DEBUG[22189]: chan_sip.c:2220 update_call_counter: Updating call counter for incoming call Nov 21 09:40:19 DEBUG[22189]: chan_sip.c:2258 update_call_counter: Call from peer 'xxxxx' removed from call limit 30 Scheduling destruction of call '11c69a4370da90635a1c75c71583e952@sx3000' in 32000 ms set_destination: Parsing for address/port to send to set_destination: set destination to x.x.x.x, port 5060 Reliably Transmitting (no NAT) to x.x.x.x:5060: BYE sip:249155552134@x.x.x.x:5060 SIP/2.0 Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK061822db;rport From: ;tag=as6ce1b37f To: ;tag=227077ce Contact: Call-ID: 11c69a4370da90635a1c75c71583e952@sx3000 CSeq: 102 BYE User-Agent: gatewaycomms Max-Forwards: 70 Content-Length: 0 --- Nov 21 09:40:19 DEBUG[22189]: chan_sip.c:1306 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #129 Nov 21 09:40:19 DEBUG[21984]: chan_sip.c:11798 sip_devicestate: Checking device state for peer x.x.x.x Nov 21 09:40:19 DEBUG[21984]: devicestate.c:187 do_state_change: Changing state for SIP/x.x.x.x - state 1 (Not in use) Nov 21 09:40:19 DEBUG[22212]: app_queue.c:500 changethread: Device 'SIP/x.x.x.x' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. ast3-gos-be*CLI> <-- SIP read from x.x.x.x:5060: SIP/2.0 200 OK From: ;tag=as6ce1b37f To: ;tag=227077ce CSeq: 102 BYE Call-ID: 11c69a4370da90635a1c75c71583e952@sx3000 Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK061822db;rport=5060 Content-Length: 0 Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 0: SIP/2.0 200 OK (14) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 1: From: ;tag=as6ce1b37f (62) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 2: To: ;tag=227077ce (59) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 3: CSeq: 102 BYE (13) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 4: Call-ID: 11c69a4370da90635a1c75c71583e952@sx3000 (48) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 5: Via: SIP/2.0/UDP x.x.x.x:5060;branch=z9hG4bK061822db;rport=5060 (69) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 6: Content-Length: 0 (17) Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:3427 parse_request: Header 7: (0) --- (7 headers 0 lines) --- Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:1402 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #129 Nov 21 09:40:19 DEBUG[21989]: chan_sip.c:1414 __sip_ack: Stopping retransmission on '11c69a4370da90635a1c75c71583e952@sx3000' of Request 102: Match Found Destroying call '11c69a4370da90635a1c75c71583e952@sx3000' Nov 21 09:40:20 DEBUG[21989]: chan_sip.c:1194 retrans_pkt: SIP TIMER: Rescheduling retransmission #123 (4) SIP/2.0 - 1 Nov 21 09:40:20 DEBUG[21989]: chan_sip.c:1208 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 4000 ms (t1 500 ms (Retrans id #123)) Nov 21 09:40:21 DEBUG[22193]: rtp.c:411 ast_rtcp_read: Got RTCP report of 48 bytes ast3-gos-be*CLI> show version Asterisk SVN-branch-1.2-r47842 built by root @ ast3-gos-be on a i686 running Linux on 2006-11-20 15:45:12 UTC