Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: INVITE sip:6989085@sip.wmis.net:5060 SIP/2.0 (46) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 216.109.205.115:5060;branch=z9hG4bK-92c3e-2106 (63) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: To: (37) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: From: "CPW Computer Systems, Inc." ;tag=10262-2c3e-2104 (91) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: CSeq: 9783 INVITE (17) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: a11ce-10262-46092c3e-2105-216.109.205.115 (50) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Date: Tue, 27 Mar 2007 14:37:50 GMT (35) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Max-Forwards: 70 (16) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: Contact: (39) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Accept: application/sdp (23) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,NOTIFY (49) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 11: Supported: replaces, rel100 (27) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 12: User-Agent: IST-OIS-6.5.1.3 (27) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 13: Content-Type: application/sdp (29) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 14: Content-Length: 255 (19) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 15: (0) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: v=0 (3) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: o=- 1175006270 1175006271 IN IP4 216.109.205.115 (48) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: s=Call (6) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: c=IN IP4 216.109.205.115 (24) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: t=0 0 (5) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: m=audio 15186 RTP/AVP 0 18 96 (29) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=ptime:20 (10) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:18 G729/8000 (21) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=fmtp:18 annexb=no (19) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:96 telephone-event/8000 (32) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=fmtp:96 0-15 (14) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3191 in sip_alloc: Allocating new SIP dialog for a11ce-10262-46092c3e-2105-216.109.205.115 - INVITE (With RTP) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11296 in handle_request: **** Received INVITE (5) - Command in SIP INVITE Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1015 in parse_sip_options: Begin: parsing SIP "Supported: replaces, rel100" Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1027 in parse_sip_options: Found SIP option: -replaces- Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1033 in parse_sip_options: Matched SIP option: replaces Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1027 in parse_sip_options: Found SIP option: -rel100- Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1038 in parse_sip_options: Found no match for SIP option: rel100 (Please file bug report!) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1044 in parse_sip_options: * SIP extension value: 1 for call a11ce-10262-46092c3e-2105-216.109.205.115 Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:7370 in check_user_full: Setting NAT on RTP to 0 Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1307 in __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #4916215 Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1195 in retrans_pkt: SIP TIMER: Rescheduling retransmission #4916215 (1) SIP/2.0 - 1 Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1209 in retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 22 ms (t1 11 ms (Retrans id #4916215)) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: ACK sip:6989085@sip.wmis.net:5060 SIP/2.0 (43) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 216.109.205.115:5060;branch=z9hG4bK-92c3e-2106 (63) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: To: ;tag=as2189c9a9 (52) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: From: "CPW Computer Systems, Inc." ;tag=10262-2c3e-2104 (91) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: CSeq: 9783 ACK (14) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: a11ce-10262-46092c3e-2105-216.109.205.115 (50) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Date: Tue, 27 Mar 2007 14:37:50 GMT (35) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Max-Forwards: 70 (16) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: User-Agent: IST-OIS-6.5.1.3 (27) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Content-Length: 0 (17) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: (0) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11296 in handle_request: **** Received ACK (6) - Command in SIP ACK Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1403 in __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #4916215 Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1415 in __sip_ack: Stopping retransmission on 'a11ce-10262-46092c3e-2105-216.109.205.115' of Response 9783: Match Found Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: rtp.c:411 in ast_rtcp_read: Got RTCP report of 136 bytes Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: INVITE sip:6989085@sip.wmis.net:5060 SIP/2.0 (46) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 216.109.205.115:5060;branch=z9hG4bK-92c3e-2107 (63) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: To: (37) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: From: "CPW Computer Systems, Inc." ;tag=10262-2c3e-2104 (91) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: CSeq: 9784 INVITE (17) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: a11ce-10262-46092c3e-2105-216.109.205.115 (50) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Date: Tue, 27 Mar 2007 14:37:50 GMT (35) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Max-Forwards: 70 (16) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: Contact: (39) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Accept: application/sdp (23) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,OPTIONS,REFER,NOTIFY (49) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 11: Supported: replaces, rel100 (27) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 12: User-Agent: IST-OIS-6.5.1.3 (27) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 13: Proxy-Authorization: Digest username="CPW",realm="asterisk",uri="sip:6989085@sip.wmis.net:5060",nonce="438c5765",respo nse="ffd6ad818b6f21af2ffaa8f098b2dec5",algorithm=MD5 (172) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 14: Content-Type: application/sdp (29) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 15: Content-Length: 255 (19) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 16: (0) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: v=0 (3) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: o=- 1175006270 1175006271 IN IP4 216.109.205.115 (48) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: s=Call (6) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: c=IN IP4 216.109.205.115 (24) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: t=0 0 (5) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: m=audio 15186 RTP/AVP 0 18 96 (29) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=ptime:20 (10) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:18 G729/8000 (21) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=fmtp:18 annexb=no (19) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:96 telephone-event/8000 (32) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=fmtp:96 0-15 (14) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11296 in handle_request: **** Received INVITE (5) - Command in SIP INVITE Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:7370 in check_user_full: Setting NAT on RTP to 0 Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:10660 in handle_request_invite: Checking SIP call limits for device CPW Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:2228 in update_call_counter: Updating call counter for incoming call Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:6258 in build_route: build_route: Contact hop: Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11844 in sip_devicestate: Checking device state for peer CPW Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: devicestate.c:187 in do_state_change: Changing state for SIP/CPW - state 2 (In use) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: pbx.c:1542 in pbx_substitute_variables_helper_full: Function result is '6165346386' Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: pbx.c:1697 in pbx_extension_helper: Launching 'Goto' Mar 27 10:37:50 asterisk asterisk[26614]: VERBOSE[26614]: -- Executing Goto("SIP/CPW-8be02000", "outbound|6166989085|1") in new stack Mar 27 10:37:50 asterisk asterisk[26614]: VERBOSE[26614]: -- Goto (outbound,6166989085,1) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: pbx.c:1697 in pbx_extension_helper: Launching 'Goto' Mar 27 10:37:50 asterisk asterisk[26614]: VERBOSE[26614]: -- Executing Goto("SIP/CPW-8be02000", "outbound|16166989085|50") in new stack Mar 27 10:37:50 asterisk asterisk[26614]: VERBOSE[26614]: -- Goto (outbound,16166989085,50) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: pbx.c:1697 in pbx_extension_helper: Launching 'Dial' Mar 27 10:37:50 asterisk asterisk[26614]: VERBOSE[26614]: -- Executing Dial("SIP/CPW-8be02000", "SIP/192.168.2.1/16166989085|120") in new stack Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3191 in sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: channel.c:2908 in ast_channel_inherit_variables: Not copying variable STACK-outbound-16166989085-50. Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: channel.c:2908 in ast_channel_inherit_variables: Not copying variable STACK-outbound-6166989085-1. Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: channel.c:2908 in ast_channel_inherit_variables: Not copying variable STACK-residential-6989085-1. Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: channel.c:2908 in ast_channel_inherit_variables: Not copying variable SIPCALLID. Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: channel.c:2908 in ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: channel.c:2908 in ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: channel.c:2908 in ast_channel_inherit_variables: Not copying variable SIPURI. Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:2083 in sip_call: Outgoing Call for 16166989085 Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:2228 in update_call_counter: Updating call counter for outgoing call Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: INVITE sip:16166989085@192.168.2.1 SIP/2.0 (45) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.2:5060;branch=z9hG4bK2c0da067;rport (65) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: From: "CPW Computer Systems, Inc." ;tag=as25bd1e48 (81) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: To: (36) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: Contact: (40) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: 44076e60790b6f194c0e1bde1a33b1bf@192.168.2.2 (56) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: CSeq: 102 INVITE (16) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: User-Agent: Asterisk PBX (24) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: Max-Forwards: 70 (16) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Date: Tue, 27 Mar 2007 14:37:50 GMT (35) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 11: Content-Type: application/sdp (29) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 12: Content-Length: 220 (19) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 13: (0) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: v=0 (3) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: o=root 26614 26614 IN IP4 192.168.2.2 (40) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: s=session (9) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: c=IN IP4 192.168.2.2 (23) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: t=0 0 (5) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: m=audio 18702 RTP/AVP 0 101 (27) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=fmtp:101 0-16 (15) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=silenceSupp:off - - - - (25) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1307 in __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #4916217 Mar 27 10:37:50 asterisk asterisk[26614]: VERBOSE[26614]: -- Called 192.168.2.1/16166989085 Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: app_queue.c:500 in changethread: Device 'SIP/CPW' changed to state '2' (In use) but we don't care because they're not a member of any queue. Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: ACK sip:6989085@sip.wmis.net:5060 SIP/2.0 (43) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 216.109.205.115:5060;branch=z9hG4bK-92c3e-2106 (63) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: To: (37) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: From: "CPW Computer Systems, Inc." ;tag=10262-2c3e-2104 (91) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: CSeq: 9784 ACK (14) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: a11ce-10262-46092c3e-2105-216.109.205.115 (50) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Date: Tue, 27 Mar 2007 14:37:50 GMT (35) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Max-Forwards: 70 (16) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: User-Agent: IST-OIS-6.5.1.3 (27) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Content-Length: 0 (17) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: (0) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11296 in handle_request: **** Received ACK (6) - Command in SIP ACK Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1415 in __sip_ack: Stopping retransmission on 'a11ce-10262-46092c3e-2105-216.109.205.115' of Response 9784: Match Not Found Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: SIP/2.0 100 Trying (18) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.2:5060;branch=z9hG4bK2c0da067;rport (65) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: From: "CPW Computer Systems, Inc." ;tag=as25bd1e48 (81) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: To: ;tag=18278454-14CA (54) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: Date: Tue, 27 Mar 2007 14:37:50 GMT (35) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: 44076e60790b6f194c0e1bde1a33b1bf@192.168.2.2 (56) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: CSeq: 102 INVITE (16) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: Allow-Events: telephone-event (29) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Content-Length: 0 (17) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: (0) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1459 in __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #4916217 - INVITE (got response) Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1468 in __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '44076e60790b6f194c0e1bde1a33b1bf@192.168.2.2' Request 102: Found Mar 27 10:37:50 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:9711 in handle_response_invite: SIP response 100 to standard invite Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: SIP/2.0 183 Session Progress (28) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.2:5060;branch=z9hG4bK2c0da067;rport (65) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: From: "CPW Computer Systems, Inc." ;tag=as25bd1e48 (81) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: To: ;tag=18278454-14CA (54) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: Date: Tue, 27 Mar 2007 14:37:50 GMT (35) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: 44076e60790b6f194c0e1bde1a33b1bf@192.168.2.2 (56) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: CSeq: 102 INVITE (16) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: Allow-Events: telephone-event (29) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Contact: (46) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: Content-Disposition: session;handling=required (46) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 11: Content-Type: application/sdp (29) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 12: Content-Length: 289 (19) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 13: (0) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: v=0 (3) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 748 7623 IN IP4 192.168.2.1 (61) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: s=SIP Call (10) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: c=IN IP4 192.168.2.1 (23) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: t=0 0 (5) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: m=audio 16592 RTP/AVP 0 101 100 (31) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: c=IN IP4 192.168.2.1 (23) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=fmtp:101 0-16 (15) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:100 X-NSE/8000 (23) Mar 27 10:37:51 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=fmtp:100 192-194 (18) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: SIP/2.0 200 OK (14) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.2:5060;branch=z9hG4bK2c0da067;rport (65) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: From: "CPW Computer Systems, Inc." ;tag=as25bd1e48 (81) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: To: ;tag=18278454-14CA (54) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: Date: Tue, 27 Mar 2007 14:37:50 GMT (35) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: 44076e60790b6f194c0e1bde1a33b1bf@192.168.2.2 (56) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: CSeq: 102 INVITE (16) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO (86) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Allow-Events: telephone-event (29) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: Contact: (46) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 11: Content-Type: application/sdp (29) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 12: Content-Length: 289 (19) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 13: (0) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: v=0 (3) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 748 7623 IN IP4 192.168.2.1 (61) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: s=SIP Call (10) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: c=IN IP4 192.168.2.1 (23) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: t=0 0 (5) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: m=audio 16592 RTP/AVP 0 101 100 (31) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: c=IN IP4 192.168.2.1 (23) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=fmtp:101 0-16 (15) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=rtpmap:100 X-NSE/8000 (23) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3474 in parse_request: Line: a=fmtp:100 192-194 (18) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1392 in __sip_ack: Acked pending invite 102 Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1415 in __sip_ack: Stopping retransmission on '44076e60790b6f194c0e1bde1a33b1bf@192.168.2.2' of Request 102: Match Found Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:9711 in handle_response_invite: SIP response 200 to standard invite Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:6258 in build_route: build_route: Contact hop: Mar 27 10:37:59 asterisk asterisk[26614]: VERBOSE[26614]: -- SIP/192.168.2.1-844e7000 answered SIP/CPW-8be02000 Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:2570 in sip_answer: sip_answer(SIP/CPW-8be02000) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1307 in __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #4916242 Mar 27 10:37:59 asterisk asterisk[26614]: VERBOSE[26614]: -- Attempting native bridge of SIP/CPW-8be02000 and SIP/192.168.2.1-844e7000 Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11844 in sip_devicestate: Checking device state for peer 192.168.2.1 Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: devicestate.c:187 in do_state_change: Changing state for SIP/192.168.2.1 - state 2 (In use) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11844 in sip_devicestate: Checking device state for peer CPW Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: devicestate.c:187 in do_state_change: Changing state for SIP/CPW - state 2 (In use) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: app_queue.c:500 in changethread: Device 'SIP/192.168.2.1' changed to state '2' (In use) but we don't care because they're not a member of any queue. Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: app_queue.c:500 in changethread: Device 'SIP/CPW' changed to state '2' (In use) but we don't care because they're not a member of any queue. Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: ACK sip:6989085@192.168.2.2 SIP/2.0 (38) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 216.109.205.115:5060;branch=z9hG4bK-92c47-210b (63) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: To: ;tag=as42802c3a (52) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: From: "CPW Computer Systems, Inc." ;tag=10262-2c3e-2104 (91) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: CSeq: 9784 ACK (14) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: a11ce-10262-46092c3e-2105-216.109.205.115 (50) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Date: Tue, 27 Mar 2007 14:37:59 GMT (35) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Max-Forwards: 70 (16) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: User-Agent: IST-OIS-6.5.1.3 (27) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Content-Length: 0 (17) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: (0) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11296 in handle_request: **** Received ACK (6) - Command in SIP ACK Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1195 in retrans_pkt: SIP TIMER: Rescheduling retransmission #4916242 (1) SIP/2.0 - 1 Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1209 in retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 22 ms (t1 11 ms (Retrans id #4916242)) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: ACK sip:6989085@192.168.2.2 SIP/2.0 (38) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 216.109.205.115:5060;branch=z9hG4bK-92c47-210b (63) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: To: ;tag=as42802c3a (52) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: From: "CPW Computer Systems, Inc." ;tag=10262-2c3e-2104 (91) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: CSeq: 9784 ACK (14) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: a11ce-10262-46092c3e-2105-216.109.205.115 (50) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Date: Tue, 27 Mar 2007 14:37:59 GMT (35) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Max-Forwards: 70 (16) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: User-Agent: IST-OIS-6.5.1.3 (27) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Content-Length: 0 (17) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: (0) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11296 in handle_request: **** Received ACK (6) - Command in SIP ACK Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: rtp.c:411 in ast_rtcp_read: Got RTCP report of 136 bytes Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1195 in retrans_pkt: SIP TIMER: Rescheduling retransmission #4916242 (2) SIP/2.0 - 1 Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1209 in retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 44 ms (t1 11 ms (Retrans id #4916242)) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: ACK sip:6989085@192.168.2.2 SIP/2.0 (38) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 216.109.205.115:5060;branch=z9hG4bK-92c47-210b (63) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: To: ;tag=as42802c3a (52) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: From: "CPW Computer Systems, Inc." ;tag=10262-2c3e-2104 (91) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: CSeq: 9784 ACK (14) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: a11ce-10262-46092c3e-2105-216.109.205.115 (50) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Date: Tue, 27 Mar 2007 14:37:59 GMT (35) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Max-Forwards: 70 (16) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: User-Agent: IST-OIS-6.5.1.3 (27) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Content-Length: 0 (17) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: (0) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11296 in handle_request: **** Received ACK (6) - Command in SIP ACK Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1195 in retrans_pkt: SIP TIMER: Rescheduling retransmission #4916242 (3) SIP/2.0 - 1 Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1209 in retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 88 ms (t1 11 ms (Retrans id #4916242)) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: ACK sip:6989085@192.168.2.2 SIP/2.0 (38) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 216.109.205.115:5060;branch=z9hG4bK-92c47-210b (63) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: To: ;tag=as42802c3a (52) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: From: "CPW Computer Systems, Inc." ;tag=10262-2c3e-2104 (91) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: CSeq: 9784 ACK (14) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: a11ce-10262-46092c3e-2105-216.109.205.115 (50) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Date: Tue, 27 Mar 2007 14:37:59 GMT (35) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Max-Forwards: 70 (16) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: User-Agent: IST-OIS-6.5.1.3 (27) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Content-Length: 0 (17) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: (0) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11296 in handle_request: **** Received ACK (6) - Command in SIP ACK Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1195 in retrans_pkt: SIP TIMER: Rescheduling retransmission #4916242 (4) SIP/2.0 - 1 Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1209 in retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 176 ms (t1 11 ms (Retrans id #4916242)) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: ACK sip:6989085@192.168.2.2 SIP/2.0 (38) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 216.109.205.115:5060;branch=z9hG4bK-92c47-210b (63) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: To: ;tag=as42802c3a (52) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: From: "CPW Computer Systems, Inc." ;tag=10262-2c3e-2104 (91) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: CSeq: 9784 ACK (14) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: a11ce-10262-46092c3e-2105-216.109.205.115 (50) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Date: Tue, 27 Mar 2007 14:37:59 GMT (35) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Max-Forwards: 70 (16) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: User-Agent: IST-OIS-6.5.1.3 (27) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Content-Length: 0 (17) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: (0) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11296 in handle_request: **** Received ACK (6) - Command in SIP ACK Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1195 in retrans_pkt: SIP TIMER: Rescheduling retransmission #4916242 (5) SIP/2.0 - 1 Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1209 in retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 352 ms (t1 11 ms (Retrans id #4916242)) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: ACK sip:6989085@192.168.2.2 SIP/2.0 (38) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 216.109.205.115:5060;branch=z9hG4bK-92c47-210b (63) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: To: ;tag=as42802c3a (52) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: From: "CPW Computer Systems, Inc." ;tag=10262-2c3e-2104 (91) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: CSeq: 9784 ACK (14) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: a11ce-10262-46092c3e-2105-216.109.205.115 (50) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Date: Tue, 27 Mar 2007 14:37:59 GMT (35) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Max-Forwards: 70 (16) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: User-Agent: IST-OIS-6.5.1.3 (27) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Content-Length: 0 (17) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: (0) Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11296 in handle_request: **** Received ACK (6) - Command in SIP ACK Mar 27 10:37:59 asterisk asterisk[26614]: DEBUG[26614]: rtp.c:411 in ast_rtcp_read: Got RTCP report of 136 bytes Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1195 in retrans_pkt: SIP TIMER: Rescheduling retransmission #4916242 (6) SIP/2.0 - 1 Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1209 in retrans_pkt: ** SIP timers: Rescheduling retransmission 7 to 704 ms (t1 11 ms (Retrans id #4916242)) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: ACK sip:6989085@192.168.2.2 SIP/2.0 (38) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 216.109.205.115:5060;branch=z9hG4bK-92c47-210b (63) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: To: ;tag=as42802c3a (52) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: From: "CPW Computer Systems, Inc." ;tag=10262-2c3e-2104 (91) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: CSeq: 9784 ACK (14) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: a11ce-10262-46092c3e-2105-216.109.205.115 (50) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Date: Tue, 27 Mar 2007 14:37:59 GMT (35) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Max-Forwards: 70 (16) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: User-Agent: IST-OIS-6.5.1.3 (27) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: Content-Length: 0 (17) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 10: (0) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11296 in handle_request: **** Received ACK (6) - Command in SIP ACK Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: rtp.c:411 in ast_rtcp_read: Got RTCP report of 136 bytes Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: rtp.c:411 in ast_rtcp_read: Got RTCP report of 136 bytes Mar 27 10:38:00 asterisk asterisk[26614]: WARNING[26614]: chan_sip.c:1228 in retrans_pkt: Maximum retries exceeded on transmission a11ce-10262-46092c3e-2105-216.109.205.115 for seqno 9784 (Critical Response) Mar 27 10:38:00 asterisk asterisk[26614]: WARNING[26614]: chan_sip.c:1245 in retrans_pkt: Hanging up call a11ce-10262-46092c3e-2105-216.109.205.115 - no reply to our critical packet. Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: channel.c:3386 in ast_generic_bridge: Didn't get a frame from channel: SIP/CPW-8be02000 Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: channel.c:3675 in ast_channel_bridge: Bridge stops bridging channels SIP/CPW-8be02000 and SIP/192.168.2.1-844e7000 Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: channel.c:1371 in ast_hangup: Hanging up channel 'SIP/192.168.2.1-844e7000' Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:2440 in sip_hangup: Hangup call SIP/192.168.2.1-844e7000, SIP callid 44076e60790b6f194c0e1bde1a33b1bf@192.168.2.2) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:2448 in sip_hangup: update_call_counter(16166989085) - decrement call limit counter Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:2228 in update_call_counter: Updating call counter for outgoing call Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1307 in __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #4916244 Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: app_dial.c:1644 in dial_exec_full: Exiting with DIALSTATUS=ANSWER. Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: pbx.c:2336 in __ast_pbx_run: Spawn extension (outbound,16166989085,50) exited non-zero on 'SIP/CPW-8be02000' Mar 27 10:38:00 asterisk asterisk[26614]: VERBOSE[26614]: == Spawn extension (outbound, 16166989085, 50) exited non-zero on 'SIP/CPW-8be02000' Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: channel.c:1371 in ast_hangup: Hanging up channel 'SIP/CPW-8be02000' Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:2440 in sip_hangup: Hangup call SIP/CPW-8be02000, SIP callid a11ce-10262-46092c3e-2105-216.109.205.115) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:2448 in sip_hangup: update_call_counter(CPW) - decrement call limit counter Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:2228 in update_call_counter: Updating call counter for incoming call Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11844 in sip_devicestate: Checking device state for peer 192.168.2.1 Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: devicestate.c:187 in do_state_change: Changing state for SIP/192.168.2.1 - state 2 (In use) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:11844 in sip_devicestate: Checking device state for peer CPW Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: devicestate.c:187 in do_state_change: Changing state for SIP/CPW - state 2 (In use) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: app_queue.c:500 in changethread: Device 'SIP/192.168.2.1' changed to state '2' (In use) but we don't care because they're not a member of any queue. Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: app_queue.c:500 in changethread: Device 'SIP/CPW' changed to state '2' (In use) but we don't care because they're not a member of any queue. Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 0: SIP/2.0 200 OK (14) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 1: Via: SIP/2.0/UDP 192.168.2.2:5060;branch=z9hG4bK0b6e8bb2;rport (65) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 2: From: "CPW Computer Systems, Inc." ;tag=as25bd1e48 (81) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 3: To: ;tag=18278454-14CA (54) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 4: Date: Tue, 27 Mar 2007 14:38:00 GMT (35) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 5: Call-ID: 44076e60790b6f194c0e1bde1a33b1bf@192.168.2.2 (56) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 7: Content-Length: 0 (17) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 8: CSeq: 103 BYE (13) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:3442 in parse_request: Header 9: (0) Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1403 in __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #4916244 Mar 27 10:38:00 asterisk asterisk[26614]: DEBUG[26614]: chan_sip.c:1415 in __sip_ack: Stopping retransmission on '44076e60790b6f194c0e1bde1a33b1bf@192.168.2.2' of Request 103: Match Found