test-cr1*CLI> <-- SIP read from 216.126.144.16:5060: INVITE sip:12246239233@216.126.144.18:5060;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP 216.126.144.16;branch=z9hG4bK342a.e8c425d4.0 Via: SIP/2.0/UDP 216.126.129.144:5060;branch=z9hG4bK-mt0e5a9en9o0;rport=5060 From: "PIPEOUT" ;tag=gs5uxr1gli To: Call-ID: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 CSeq: 1 INVITE Max-Forwards: 69 Contact: ;flow-id=1 P-Key-Flags: keys="3" User-Agent: snom320/6.5.6 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Session-Expires: 3600;refresher=uas Min-SE: 90 Content-Type: application/sdp Content-Length: 457 v=0 o=root 1763753396 1763753396 IN IP4 216.126.129.144 s=call c=IN IP4 216.126.129.144 t=0 0 m=audio 54754 RTP/AVP 18 0 8 2 3 4 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:K9qs293Xec7yJPrGP4eRyrm9wYrWjOSl2/RbmKFq a=rtpmap:18 g729/8000 a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:2 g726-32/8000 a=rtpmap:3 gsm/8000 a=rtpmap:4 g723/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=encryption:optional a=sendrecv May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 0: INVITE sip:12246239233@216.126.144.18:5060;transport=udp SIP/2.0 (64) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 1: Record-Route: (56) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 2: Via: SIP/2.0/UDP 216.126.144.16;branch=z9hG4bK342a.e8c425d4.0 (61) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 3: Via: SIP/2.0/UDP 216.126.129.144:5060;branch=z9hG4bK-mt0e5a9en9o0;rport=5060 (76) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 4: From: "PIPEOUT" ;tag=gs5uxr1gli (59) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 5: To: (47) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 6: Call-ID: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 (55) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 7: CSeq: 1 INVITE (14) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 8: Max-Forwards: 69 (16) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 9: Contact: ;flow-id=1 (67) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 10: P-Key-Flags: keys="3" (21) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 11: User-Agent: snom320/6.5.6 (25) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 12: Accept: application/sdp (23) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 13: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 14: Allow-Events: talk, hold, refer (31) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 15: Supported: timer, 100rel, replaces, callerid (44) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 16: Session-Expires: 3600;refresher=uas (35) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 17: Min-SE: 90 (10) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 18: Content-Type: application/sdp (29) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 19: Content-Length: 457 (19) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 20: (0) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: v=0 (3) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: o=root 1763753396 1763753396 IN IP4 216.126.129.144 (51) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: s=call (6) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: c=IN IP4 216.126.129.144 (24) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: t=0 0 (5) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: m=audio 54754 RTP/AVP 18 0 8 2 3 4 101 (38) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:K9qs293Xec7yJPrGP4eRyrm9wYrWjOSl2/RbmKFq (82) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=rtpmap:18 g729/8000 (21) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=rtpmap:8 pcma/8000 (20) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=rtpmap:2 g726-32/8000 (23) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=rtpmap:3 gsm/8000 (19) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=rtpmap:4 g723/8000 (20) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=fmtp:101 0-16 (15) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=ptime:20 (10) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=encryption:optional (21) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=sendrecv (10) --- (20 headers 18 lines) --- May 16 11:26:42 DEBUG[32528]: chan_sip.c:3217 sip_alloc: Allocating new SIP dialog for 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 - INVITE (With RTP) May 16 11:26:42 DEBUG[32528]: chan_sip.c:11375 handle_request: **** Received INVITE (5) - Command in SIP INVITE May 16 11:26:42 DEBUG[32528]: chan_sip.c:1016 parse_sip_options: Begin: parsing SIP "Supported: timer, 100rel, replaces, callerid" May 16 11:26:42 DEBUG[32528]: chan_sip.c:1028 parse_sip_options: Found SIP option: -timer- May 16 11:26:42 DEBUG[32528]: chan_sip.c:1034 parse_sip_options: Matched SIP option: timer May 16 11:26:42 DEBUG[32528]: chan_sip.c:1028 parse_sip_options: Found SIP option: -100rel- May 16 11:26:42 DEBUG[32528]: chan_sip.c:1034 parse_sip_options: Matched SIP option: 100rel May 16 11:26:42 DEBUG[32528]: chan_sip.c:1028 parse_sip_options: Found SIP option: -replaces- May 16 11:26:42 DEBUG[32528]: chan_sip.c:1034 parse_sip_options: Matched SIP option: replaces May 16 11:26:42 DEBUG[32528]: chan_sip.c:1028 parse_sip_options: Found SIP option: -callerid- May 16 11:26:42 DEBUG[32528]: chan_sip.c:1039 parse_sip_options: Found no match for SIP option: callerid (Please file bug report!) May 16 11:26:42 DEBUG[32528]: chan_sip.c:1045 parse_sip_options: * SIP extension value: 7 for call 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 Using INVITE request as basis request - 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 Sending to 216.126.144.16 : 5060 (NAT) SNI: In 'check_user_full' SNI: Contact: list_route: hop: Transmitting (NAT) to 216.126.144.16:5060: SIP/2.0 100 Trying v: SIP/2.0/UDP 216.126.144.16;branch=z9hG4bK342a.e8c425d4.0;received=216.126.144.16 v: SIP/2.0/UDP 216.126.129.144:5060;branch=z9hG4bK-mt0e5a9en9o0;rport=5060 f: "PIPEOUT" ;tag=gs5uxr1gli t: i: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 CSeq: 1 INVITE User-Agent: PAETEC VoIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY m: : 0t-cr1*CLI> May 16 11:26:42 DEBUG[32521]: res_config_mysql.c:778 mysql_reconnect: MySQL RealTime: Everything is fine. May 16 11:26:42 DEBUG[32521]: res_config_mysql.c:245 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE sipe = '216.126.144.16' May 16 11:26:42 DEBUG[32521]: devicestate.c:187 do_state_change: Changing state for SIP/216.126.144.16 - state 2 (In use) [[[ SNIP LOTS OF EXTENSIONS/DIALPLAN IF/ELSE/GOTO/ETC. ]]] May 16 11:26:42 DEBUG[2535]: pbx.c:1697 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/216.126.144.16-081d4650", "SIP/chi2-vgw1/12246239233|120|o") in new stack May 16 11:26:42 DEBUG[2535]: chan_sip.c:3217 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) May 16 11:26:42 DEBUG[2535]: chan_sip.c:1915 create_addr_from_peer: Setting NAT on RTP to 524288 May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-external-2246239233-1. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-tendigit-2246239233-400. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-tendigit-2246239233-6. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable SIPE. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-tendigit-2246239233-5. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-tendigit-2246239233-4. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable ACTIVE. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-tendigit-2246239233-3. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-tendigit-2246239233-2. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable CALLERSER. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-tendigit-2246239233-1. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-sixtynine-2246239233-6. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable SIXNINE. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-sixtynine-2246239233-5. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-sixtynine-2246239233-2. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-sixtynine-2246239233-1. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-default-term-2246239233-20. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-default-term-2246239233-10. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-default-term-2246239233-9. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-default-term-2246239233-8. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-default-term-2246239233-7. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-default-term-2246239233-6. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-default-term-2246239233-5. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-default-term-2246239233-2. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable USERCONTEXT. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-default-term-2246239233-1. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-pipeout-12246239233-15. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-pipeout-12246239233-12. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-pipeout-12246239233-11. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable VE_NEXT_HOP. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-pipeout-12246239233-10. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-pipeout-12246239233-9. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-pipeout-12246239233-4. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-pipeout-12246239233-3. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-pipeout-12246239233-2. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable STACK-pipeout-12246239233-1. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable SIPCALLID. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. May 16 11:26:42 DEBUG[2535]: channel.c:2908 ast_channel_inherit_variables: Not copying variable SIPURI. May 16 11:26:42 DEBUG[2535]: chan_sip.c:2109 sip_call: Outgoing Call for 12246239233 May 16 11:26:42 DEBUG[2535]: chan_sip.c:2254 update_call_counter: Updating call counter for outgoing call May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 0: INVITE sip:12246239233@64.24.35.193 SIP/2.0 (43) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 1: v: SIP/2.0/UDP 216.126.144.18:5060;branch=z9hG4bK55fa51d5;rport (63) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 2: f: "PIPEOUT" ;tag=as1c0645af (59) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 3: t: (33) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 4: m: (34) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 5: i: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 (50) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 6: CSeq: 102 INVITE (16) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 7: User-Agent: PAETEC VoIP (23) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 8: Max-Forwards: 70 (16) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 9: Date: Wed, 16 May 2007 16:26:42 GMT (35) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 11: c: application/sdp (18) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 12: l: 220 (6) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3468 parse_request: Header 13: (0) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3500 parse_request: Line: v=0 (3) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3500 parse_request: Line: o=root 32507 32507 IN IP4 216.126.144.18 (40) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3500 parse_request: Line: s=session (9) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3500 parse_request: Line: c=IN IP4 216.126.144.18 (23) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3500 parse_request: Line: t=0 0 (5) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3500 parse_request: Line: m=audio 16628 RTP/AVP 0 101 (27) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3500 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3500 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3500 parse_request: Line: a=fmtp:101 0-16 (15) May 16 11:26:42 DEBUG[2535]: chan_sip.c:3500 parse_request: Line: a=silenceSupp:off - - - - (25) May 16 11:26:42 DEBUG[2535]: chan_sip.c:1308 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #293 -- Called chi2-vgw1/12246239233 May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 0: SIP/2.0 100 Trying (18) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 1: Via: SIP/2.0/UDP 216.126.144.18:5060;branch=z9hG4bK55fa51d5;received=216.126.144.18;rport=5060 (94) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 2: From: "PIPEOUT" ;tag=as1c0645af (62) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 3: To: (34) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 4: Call-ID: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 (56) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 5: CSeq: 102 INVITE (16) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 6: User-Agent: Asterisk PBX (24) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 8: Contact: (39) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 9: Content-Length: 0 (17) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 10: (0) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3265 find_call: = Found Their Call ID: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 Their Tag Our tag: as1c0645af May 16 11:26:42 DEBUG[32528]: chan_sip.c:1460 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #293 - INVITE (got response) May 16 11:26:42 DEBUG[32528]: chan_sip.c:1469 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18' Request 102: Found May 16 11:26:42 DEBUG[32528]: chan_sip.c:9777 handle_response_invite: SIP response 100 to standard invite May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 0: SIP/2.0 183 Session Progress (28) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 1: Via: SIP/2.0/UDP 216.126.144.18:5060;branch=z9hG4bK55fa51d5;received=216.126.144.18;rport=5060 (94) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 2: From: "PIPEOUT" ;tag=as1c0645af (62) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 3: To: ;tag=as3e1fa184 (49) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 4: Call-ID: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 (56) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 5: CSeq: 102 INVITE (16) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 6: User-Agent: Asterisk PBX (24) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 8: Contact: (39) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 9: Content-Type: application/sdp (29) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 10: Content-Length: 214 (19) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 11: (0) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: v=0 (3) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: o=root 7743 7743 IN IP4 64.24.35.193 (36) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: s=session (9) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: c=IN IP4 64.24.35.193 (21) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: t=0 0 (5) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: m=audio 17692 RTP/AVP 0 101 (27) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=fmtp:101 0-16 (15) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=silenceSupp:off - - - - (25) May 16 11:26:42 DEBUG[32528]: chan_sip.c:3265 find_call: = Found Their Call ID: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 Their Tag Our tag: as1c0645af May 16 11:26:42 DEBUG[32528]: chan_sip.c:1469 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18' Request 102: Found May 16 11:26:42 DEBUG[32528]: chan_sip.c:9777 handle_response_invite: SIP response 183 to standard invite -- SIP/chi2-vgw1-082461b0 is making progress passing it to SIP/216.126.144.16-081d4650 We're at 216.126.144.18 port 28840 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP Transmitting (NAT) to 216.126.144.16:5060: SIP/2.0 183 Session Progress v: SIP/2.0/UDP 216.126.144.16;branch=z9hG4bK342a.e8c425d4.0;received=216.126.144.16 v: SIP/2.0/UDP 216.126.129.144:5060;branch=z9hG4bK-mt0e5a9en9o0;rport=5060 f: "PIPEOUT" ;tag=gs5uxr1gli t: ;tag=as5baa3629 i: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 CSeq: 1 INVITE User-Agent: PAETEC VoIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY m: c: application/sdp l: 220 v=0 o=root 32507 32507 IN IP4 216.126.144.18 s=session c=IN IP4 216.126.144.18 t=0 0 m=audio 28840 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- May 16 11:26:42 DEBUG[2535]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to ulaw May 16 11:26:42 DEBUG[2535]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes May 16 11:26:43 DEBUG[2535]: rtp.c:1361 ast_rtp_write: Ooh, format changed from unknown to ulaw May 16 11:26:47 DEBUG[2535]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes May 16 11:26:48 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 0: SIP/2.0 180 Ringing (19) May 16 11:26:48 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 1: Via: SIP/2.0/UDP 216.126.144.18:5060;branch=z9hG4bK55fa51d5;received=216.126.144.18;rport=5060 (94) May 16 11:26:48 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 2: From: "PIPEOUT" ;tag=as1c0645af (62) May 16 11:26:48 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 3: To: ;tag=as3e1fa184 (49) May 16 11:26:48 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 4: Call-ID: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 (56) May 16 11:26:48 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 5: CSeq: 102 INVITE (16) May 16 11:26:48 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 6: User-Agent: Asterisk PBX (24) May 16 11:26:48 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) May 16 11:26:48 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 8: Contact: (39) May 16 11:26:48 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 9: Content-Length: 0 (17) May 16 11:26:48 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 10: (0) May 16 11:26:48 DEBUG[32528]: chan_sip.c:3265 find_call: = Found Their Call ID: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 Their Tag as3e1fa184 Our tag: as1c0645af May 16 11:26:48 DEBUG[32528]: chan_sip.c:1469 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18' Request 102: Found May 16 11:26:48 DEBUG[32528]: chan_sip.c:9777 handle_response_invite: SIP response 180 to standard invite -- SIP/chi2-vgw1-082461b0 is ringing Transmitting (NAT) to 216.126.144.16:5060: SIP/2.0 180 Ringing v: SIP/2.0/UDP 216.126.144.16;branch=z9hG4bK342a.e8c425d4.0;received=216.126.144.16 v: SIP/2.0/UDP 216.126.129.144:5060;branch=z9hG4bK-mt0e5a9en9o0;rport=5060 f: "PIPEOUT" ;tag=gs5uxr1gli t: ;tag=as5baa3629 i: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 CSeq: 1 INVITE User-Agent: PAETEC VoIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY m: l: 0 --- May 16 11:26:48 DEBUG[32521]: chan_sip.c:11923 sip_devicestate: Checking device state for peer chi2-vgw1 May 16 11:26:48 DEBUG[32521]: devicestate.c:187 do_state_change: Changing state for SIP/chi2-vgw1 - state 6 (Ringing) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 0: SIP/2.0 200 OK (14) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 1: Via: SIP/2.0/UDP 216.126.144.18:5060;branch=z9hG4bK55fa51d5;received=216.126.144.18;rport=5060 (94) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 2: From: "PIPEOUT" ;tag=as1c0645af (62) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 3: To: ;tag=as3e1fa184 (49) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 4: Call-ID: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 (56) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 5: CSeq: 102 INVITE (16) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 6: User-Agent: Asterisk PBX (24) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 8: Contact: (39) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 9: Content-Type: application/sdp (29) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 10: Content-Length: 214 (19) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 11: (0) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: v=0 (3) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: o=root 7743 7744 IN IP4 64.24.35.193 (36) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: s=session (9) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: c=IN IP4 64.24.35.193 (21) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: t=0 0 (5) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: m=audio 17692 RTP/AVP 0 101 (27) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=fmtp:101 0-16 (15) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3500 parse_request: Line: a=silenceSupp:off - - - - (25) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3265 find_call: = Found Their Call ID: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 Their Tag as3e1fa184 Our tag: as1c0645af May 16 11:26:52 DEBUG[32528]: chan_sip.c:1393 __sip_ack: Acked pending invite 102 May 16 11:26:52 DEBUG[32528]: chan_sip.c:1416 __sip_ack: Stopping retransmission on '4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18' of Request 102: Match Found May 16 11:26:52 DEBUG[32528]: chan_sip.c:9777 handle_response_invite: SIP response 200 to standard invite May 16 11:26:52 DEBUG[32528]: chan_sip.c:6293 build_route: build_route: Contact hop: -- SIP/chi2-vgw1-082461b0 answered SIP/216.126.144.16-081d4650 May 16 11:26:52 DEBUG[2535]: chan_sip.c:2596 sip_answer: sip_answer(SIP/216.126.144.16-081d4650) We're at 216.126.144.18 port 28840 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (NAT) to 216.126.144.16:5060: SIP/2.0 200 OK v: SIP/2.0/UDP 216.126.144.16;branch=z9hG4bK342a.e8c425d4.0;received=216.126.144.16 v: SIP/2.0/UDP 216.126.129.144:5060;branch=z9hG4bK-mt0e5a9en9o0;rport=5060 Record-Route: f: "PIPEOUT" ;tag=gs5uxr1gli t: ;tag=as5baa3629 i: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 CSeq: 1 INVITE User-Agent: PAETEC VoIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY m: c: application/sdp l: 220 v=0 o=root 32507 32508 IN IP4 216.126.144.18 s=session c=IN IP4 216.126.144.18 t=0 0 m=audio 28840 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- May 16 11:26:52 DEBUG[2535]: chan_sip.c:1308 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #294 -- Attempting native bridge of SIP/216.126.144.16-081d4650 and SIP/chi2-vgw1-082461b0 May 16 11:26:52 DEBUG[32521]: chan_sip.c:11923 sip_devicestate: Checking device state for peer chi2-vgw1 May 16 11:26:52 DEBUG[32521]: devicestate.c:187 do_state_change: Changing state for SIP/chi2-vgw1 - state 2 (In use) May 16 11:26:52 DEBUG[32521]: chan_sip.c:11923 sip_devicestate: Checking device state for peer 216.126.144.16 May 16 11:26:52 DEBUG[32521]: res_config_mysql.c:778 mysql_reconnect: MySQL RealTime: Everything is fine. May 16 11:26:52 DEBUG[32521]: res_config_mysql.c:245 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE sipe = '216.126.144.16' May 16 11:26:52 DEBUG[32521]: devicestate.c:187 do_state_change: Changing state for SIP/216.126.144.16 - state 2 (In use) test-cr1*CLI> <-- SIP read from 216.126.144.16:5060: ACK sip:12246239233@216.126.144.18:5060;transport=udp SIP/2.0 Record-Route: Via: SIP/2.0/UDP 216.126.144.16;branch=z9hG4bK342a.e8c425d4.2 Via: SIP/2.0/UDP 216.126.129.144:5060;branch=z9hG4bK-z09psnq7mnkn;rport=5060 Route: From: "PIPEOUT" ;tag=gs5uxr1gli To: ;tag=as5baa3629 Call-ID: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 CSeq: 1 ACK Max-Forwards: 69 Contact: ;flow-id=1 Content-Length: 0 May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 0: ACK sip:12246239233@216.126.144.18:5060;transport=udp SIP/2.0 (61) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 1: Record-Route: (56) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 2: Via: SIP/2.0/UDP 216.126.144.16;branch=z9hG4bK342a.e8c425d4.2 (61) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 3: Via: SIP/2.0/UDP 216.126.129.144:5060;branch=z9hG4bK-z09psnq7mnkn;rport=5060 (76) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 4: Route: (49) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 5: From: "PIPEOUT" ;tag=gs5uxr1gli (59) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 6: To: ;tag=as5baa3629 (62) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 7: Call-ID: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 (55) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 8: CSeq: 1 ACK (11) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 9: Max-Forwards: 69 (16) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 10: Contact: ;flow-id=1 (67) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 11: Content-Length: 0 (17) May 16 11:26:52 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 12: (0) --- (12 headers 0 lines) --- May 16 11:26:52 DEBUG[32528]: chan_sip.c:3265 find_call: = No match Their Call ID: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 Their Tag as3e1fa184 Our tag: as1c0645af May 16 11:26:52 DEBUG[32528]: chan_sip.c:3265 find_call: = Found Their Call ID: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 Their Tag gs5uxr1gli Our tag: as5baa3629 May 16 11:26:52 DEBUG[32528]: chan_sip.c:11375 handle_request: **** Received ACK (6) - Command in SIP ACK May 16 11:26:52 DEBUG[32528]: chan_sip.c:1404 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #294 May 16 11:26:52 DEBUG[32528]: chan_sip.c:1416 __sip_ack: Stopping retransmission on '3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168' of Response 1: Match Found May 16 11:26:52 DEBUG[2535]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes May 16 11:26:53 DEBUG[32528]: app.c:278 ast_app_ve_messagecount: messagecount_ve function for name 51044 May 16 11:26:57 DEBUG[2535]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes May 16 11:27:02 DEBUG[2535]: rtp.c:411 ast_rtcp_read: Got RTCP report of 52 bytes May 16 11:27:04 DEBUG[32528]: app.c:278 ast_app_ve_messagecount: messagecount_ve function for name 51044 May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 0: BYE sip:8478797684@216.126.144.18 SIP/2.0 (41) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 1: Via: SIP/2.0/UDP 64.24.35.193:5060;branch=z9hG4bK0ac05cbe;rport (63) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 2: From: ;tag=as3e1fa184 (51) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 3: To: "PIPEOUT" ;tag=as1c0645af (60) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 4: Contact: (39) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 5: Call-ID: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 (56) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 6: CSeq: 102 BYE (13) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 7: User-Agent: Asterisk PBX (24) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 8: Max-Forwards: 70 (16) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 9: Content-Length: 0 (17) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 10: (0) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3265 find_call: = Found Their Call ID: 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18 Their Tag as3e1fa184 Our tag: as1c0645af May 16 11:27:07 DEBUG[32528]: chan_sip.c:11375 handle_request: **** Received BYE (8) - Command in SIP BYE May 16 11:27:07 DEBUG[32528]: chan_sip.c:11015 handle_request_bye: Received bye, issuing owner hangup May 16 11:27:07 DEBUG[2535]: channel.c:3386 ast_generic_bridge: Didn't get a frame from channel: SIP/chi2-vgw1-082461b0 May 16 11:27:07 DEBUG[2535]: channel.c:3675 ast_channel_bridge: Bridge stops bridging channels SIP/216.126.144.16-081d4650 and SIP/chi2-vgw1-082461b0 May 16 11:27:07 DEBUG[2535]: channel.c:1371 ast_hangup: Hanging up channel 'SIP/chi2-vgw1-082461b0' May 16 11:27:07 DEBUG[2535]: chan_sip.c:2466 sip_hangup: Hangup call SIP/chi2-vgw1-082461b0, SIP callid 4687ebcd6a2f05b23c6fa4f679051169@216.126.144.18) May 16 11:27:07 DEBUG[2535]: chan_sip.c:2474 sip_hangup: update_call_counter(12246239233) - decrement call limit counter May 16 11:27:07 DEBUG[2535]: chan_sip.c:2254 update_call_counter: Updating call counter for outgoing call May 16 11:27:07 DEBUG[2535]: app_dial.c:1644 dial_exec_full: Exiting with DIALSTATUS=ANSWER. May 16 11:27:07 DEBUG[2535]: pbx.c:2336 __ast_pbx_run: Spawn extension (external,2246239233,1) exited non-zero on 'SIP/216.126.144.16-081d4650' == Spawn extension (external, 2246239233, 1) exited non-zero on 'SIP/216.126.144.16-081d4650' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '"PIPEOUT" <8478797684>' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '8478797684' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '2246239233' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is 'external' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is 'SIP/216.126.144.16-081d4650' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is 'SIP/chi2-vgw1-082461b0' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is 'Dial' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is 'SIP/chi2-vgw1/12246239233|120|o' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '2007-05-16 11:26:42' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '2007-05-16 11:26:52' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '2007-05-16 11:27:07' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '25' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '15' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '50' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '1179332802.138' May 16 11:27:07 DEBUG[2535]: pbx.c:1542 pbx_substitute_variables_helper_full: Function result is '(null)' May 16 11:27:07 DEBUG[32521]: chan_sip.c:11923 sip_devicestate: Checking device state for peer chi2-vgw1 May 16 11:27:07 DEBUG[32521]: devicestate.c:187 do_state_change: Changing state for SIP/chi2-vgw1 - state 1 (Not in use) May 16 11:27:07 DEBUG[2535]: channel.c:1371 ast_hangup: Hanging up channel 'SIP/216.126.144.16-081d4650' May 16 11:27:07 DEBUG[2535]: chan_sip.c:2466 sip_hangup: Hangup call SIP/216.126.144.16-081d4650, SIP callid 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168) May 16 11:27:07 DEBUG[2535]: chan_sip.c:2474 sip_hangup: update_call_counter() - decrement call limit counter May 16 11:27:07 DEBUG[2535]: chan_sip.c:2254 update_call_counter: Updating call counter for incoming call Scheduling destruction of call '3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168' in 32000 ms set_destination: Parsing for address/port to send to set_destination: set destination to 216.126.144.16, port 5060 Reliably Transmitting (NAT) to 216.126.144.16:5060: BYE f: ;tag=as5baa3629 t: "PIPEOUT" ;tag=gs5uxr1gli i: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 CSeq: 102 BYE User-Agent: PAETEC VoIP Max-Forwards: 70 l: 0 --- May 16 11:27:07 DEBUG[2535]: chan_sip.c:1308 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #296 May 16 11:27:07 DEBUG[32521]: chan_sip.c:11923 sip_devicestate: Checking device state for peer 216.126.144.16 test-cr1*CLI> <-- SIP read from 216.126.144.16:5060: SIP/2.0 500 Server Internal Error - Cannot load gateways v: SIP/2.0/UDP 216.126.144.18:5060;branch=z9hG4bK22b21baa;rport=5060 f: ;tag=as5baa3629 t: "PIPEOUT" ;tag=gs5uxr1gli i: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 CSeq: 102 BYE Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 216.126.144.16:5060 "Noisy feedback tells: pid=9348 req_src_ip=216.126.144.18 req_src_port=5060 in_uri=;tag=as5baa3629 (61) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 3: t: "PIPEOUT" ;tag=gs5uxr1gli (56) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 4: i: 3c56efb32bf2-yl1a6dbv3ugu@snom320-000413246168 (49) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 5: CSeq: 102 BYE (13) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 6: Server: OpenSer (1.1.0-notls (i386/linux)) (42) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 7: Content-Length: 0 (17) May 16 11:27:07 DEBUG[32528]: chan_sip.c:3468 parse_request: Header 8: Warning: 392 216.126.144.16:5060 "Noisy feedback tells: pid=9348 req_src_ip=216.126.144.18 req_src_port=5060 in_uri= quit root@test-cr1:~#