*CLI> *CLI> *CLI> *CLI> *CLI> set debug 4 Core debug was 0 and is now 4 *CLI> set verbose 4 Verbosity was 1 and is now 4 *CLI> sip debug SIP Debugging enabled *CLI> <-- SIP read from 10.1.1.160:5060: Jul 10 17:48:55 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: (0) --- (0 headers 0 lines) Nat keepalive --- *CLI> *CLI> *CLI> *CLI> *CLI> *CLI> *CLI> *CLI> *CLI> *CLI> *CLI> *CLI> *CLI> *CLI> <-- SIP read from 10.3.2.111:5060: INVITE sip:7401@10.3.3.239;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKb59d29fc06d3aee8 From: ;tag=3923113e3b920438 To: Contact: Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 18807 INVITE User-Agent: Grandstream BT100 1.0.5.11 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 298 v=0 o=6111 8000 8000 IN IP4 10.3.2.111 s=SIP Call c=IN IP4 10.3.2.111 t=0 0 m=audio 5004 RTP/AVP 0 8 18 2 15 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:15 G728/8000 a=ptime:10 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: INVITE sip:7401@10.3.3.239;user=phone SIP/2.0 (45) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKb59d29fc06d3aee8 (58) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: ;tag=3923113e3b920438 (59) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: (36) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Contact: (41) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: Call-ID: 9f095dcd69affc54@10.3.2.111 (36) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: CSeq: 18807 INVITE (18) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: User-Agent: Grandstream BT100 1.0.5.11 (38) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: Max-Forwards: 70 (16) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Content-Type: application/sdp (29) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: Content-Length: 298 (19) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 12: (0) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: v=0 (3) Jul 10 17:49:13 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: o=6111 8000 8000 IN IP4 10.3.2.111 (34) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: s=SIP Call (10) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: c=IN IP4 10.3.2.111 (19) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: t=0 0 (5) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: m=audio 5004 RTP/AVP 0 8 18 2 15 101 (36) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:18 G729/8000 (21) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:15 G728/8000 (21) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=ptime:10 (10) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=fmtp:101 0-11 (15) --- (12 headers 14 lines)--- Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3189 sip_alloc: Allocating new SIP dialog for 9f095dcd69affc54@10.3.2.111 - INVITE (With RTP) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:11183 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - 9f095dcd69affc54@10.3.2.111 Sending to 10.3.2.111 : 5060 (non-NAT) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:7201 check_user_full: Setting NAT on RTP to 0 Reliably Transmitting (no NAT) to 10.3.2.111:5060: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKb59d29fc06d3aee8;received=10.3.2.111 From: ;tag=3923113e3b920438 To: ;tag=as2964afde Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 18807 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Proxy-Authenticate: Digest realm="asterisk", nonce="42317b0d" Content-Length: 0 --- Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #11 Scheduling destruction of call '9f095dcd69affc54@10.3.2.111' in 15000 ms Found user '6111' <-- SIP read from 10.1.1.160:5060: Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: (0) --- (0 headers 0 lines) Nat keepalive --- <-- SIP read from 10.3.2.111:5060: ACK sip:7401@10.3.3.239;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKb59d29fc06d3aee8 From: ;tag=3923113e3b920438 To: ;tag=as2964afde Contact: Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 18807 ACK User-Agent: Grandstream BT100 1.0.5.11 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: ACK sip:7401@10.3.3.239;user=phone SIP/2.0 (42) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKb59d29fc06d3aee8 (58) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: ;tag=3923113e3b920438 (59) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: ;tag=as2964afde (51) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Contact: (41) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: Call-ID: 9f095dcd69affc54@10.3.2.111 (36) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: CSeq: 18807 ACK (15) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: User-Agent: Grandstream BT100 1.0.5.11 (38) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: Max-Forwards: 70 (16) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Content-Length: 0 (17) Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: (0) --- (11 headers 0 lines)--- Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:11183 handle_request: **** Received ACK (6) - Command in SIP ACK Jul 10 17:49:14 DEBUG[13795]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #11 Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '9f095dcd69affc54@10.3.2.111' of Response 18807: Match Found <-- SIP read from 10.3.2.111:5060: INVITE sip:7401@10.3.3.239;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKac52711770099ead From: ;tag=3923113e3b920438 To: Contact: Proxy-Authorization: DIGEST username="6111", realm="asterisk", algorithm=MD5, uri="sip:7401@10.3.3.239;user=phone", nonce="42317b0d", response="c3a5fc69bf3d82c8811c6e1ec7fca70f" Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 18808 INVITE User-Agent: Grandstream BT100 1.0.5.11 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 298 v=0 o=6111 8000 8000 IN IP4 10.3.2.111 s=SIP Call c=IN IP4 10.3.2.111 t=0 0 m=audio 5004 RTP/AVP 0 8 18 2 15 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:15 G728/8000 a=ptime:10 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: INVITE sip:7401@10.3.3.239;user=phone SIP/2.0 (45) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKac52711770099ead (58) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: ;tag=3923113e3b920438 (59) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: (36) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Contact: (41) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: Proxy-Authorization: DIGEST username="6111", realm="asterisk", algorithm=MD5, uri="sip:7401@10.3.3.239;user=phone", nonce="42317b0d", response="c3a5fc69bf3d82c8811c6e1ec7fca70f" (177) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: Call-ID: 9f095dcd69affc54@10.3.2.111 (36) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: CSeq: 18808 INVITE (18) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: User-Agent: Grandstream BT100 1.0.5.11 (38) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: Max-Forwards: 70 (16) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: Content-Type: application/sdp (29) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 12: Content-Length: 298 (19) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 13: (0) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: v=0 (3) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: o=6111 8000 8000 IN IP4 10.3.2.111 (34) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: s=SIP Call (10) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: c=IN IP4 10.3.2.111 (19) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: t=0 0 (5) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: m=audio 5004 RTP/AVP 0 8 18 2 15 101 (36) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:18 G729/8000 (21) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:15 G728/8000 (21) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=ptime:10 (10) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=fmtp:101 0-11 (15) --- (13 headers 14 lines)--- Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:11183 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - 9f095dcd69affc54@10.3.2.111 Sending to 10.3.2.111 : 5060 (non-NAT) Jul 10 17:49:15 DEBUG[13795]: chan_sip.c:7201 check_user_full: Setting NAT on RTP to 0 Found user '6111' Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 18 Found RTP audio format 2 Found RTP audio format 15 Found RTP audio format 101 ast_rtp_set_peer: rtp->nat=0: them->sin_addr.s_addr=0xa03026f: sin_port=0x138c Peer audio RTP is at port 10.3.2.111:5004 Jul 10 17:49:16 DEBUG[13795]: chan_sip.c:3646 process_sdp: Peer audio RTP is at port 10.3.2.111:5004 Found description format PCMU Found description format PCMA Found description format G729 Found description format G726-32 Found description format G728 Found description format telephone-event Capabilities: us - 0x4 (ulaw), peer - audio=0x11c (ulaw|alaw|g726|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Jul 10 17:49:16 DEBUG[13795]: chan_sip.c:10543 handle_request_invite: Checking SIP call limits for device 6111 Jul 10 17:49:16 DEBUG[13795]: chan_sip.c:2209 update_call_counter: Updating call counter for incoming call Looking for 7401 in from-internal (domain 10.3.3.239) Jul 10 17:49:16 DEBUG[13795]: chan_sip.c:6183 build_route: build_route: Contact hop: list_route: hop: Transmitting (no NAT) to 10.3.2.111:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKac52711770099ead;received=10.3.2.111 From: ;tag=3923113e3b920438 To: Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 18808 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jul 10 17:49:16 DEBUG[13789]: chan_sip.c:11714 sip_devicestate: Checking device state for peer 6111 Jul 10 17:49:16 DEBUG[13789]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/6111-b192' <-- SIP read from 10.3.2.111:5060: INVITE sip:7401@10.3.3.239;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKac52711770099ead From: ;tag=3923113e3b920438 To: Contact: Proxy-Authorization: DIGEST username="6111", realm="asterisk", algorithm=MD5, uri="sip:7401@10.3.3.239;user=phone", nonce="42317b0d", response="c3a5fc69bf3d82c8811c6e1ec7fca70f" Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 18808 INVITE User-Agent: Grandstream BT100 1.0.5.11 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 298 v=0 o=6111 8000 8000 IN IP4 10.3.2.111 s=SIP Call c=IN IP4 10.3.2.111 t=0 0 m=audio 5004 RTP/AVP 0 8 18 2 15 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:15 G728/8000 a=ptime:10 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 Jul 10 17:49:16 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' Jul 10 17:49:16 DEBUG[13789]: devicestate.c:187 do_state_change: Changing state for SIP/6111 - state 2 (In use) Jul 10 17:49:16 DEBUG[13789]: chan_sip.c:11714 sip_devicestate: Checking device state for peer 6111 -- Executing Macro("SIP/6111-b192", "exten-vm|novm|7401") in new stack Jul 10 17:49:16 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' Jul 10 17:49:16 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: INVITE sip:7401@10.3.3.239;user=phone SIP/2.0 (45) -- Executing Macro("SIP/6111-b192", "user-callerid") in new stack Device 'SIP/6111' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jul 10 17:49:16 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKac52711770099ead (58) Jul 10 17:49:16 DEBUG[13805]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 17:49:16 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: ;tag=3923113e3b920438 (59) Jul 10 17:49:16 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: (36) Jul 10 17:49:16 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/6111-b192", "0?report") in new stack Jul 10 17:49:16 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Contact: (41) Jul 10 17:49:17 DEBUG[13805]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jul 10 17:49:17 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: Proxy-Authorization: DIGEST username="6111", realm="asterisk", algorithm=MD5, uri="sip:7401@10.3.3.239;user=phone", nonce="42317b0d", response="c3a5fc69bf3d82c8811c6e1ec7fca70f" (177) Jul 10 17:49:17 DEBUG[13805]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 17:49:17 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: Call-ID: 9f095dcd69affc54@10.3.2.111 (36) Jul 10 17:49:17 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/6111-b192", "0?start") in new stack Jul 10 17:49:17 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: CSeq: 18808 INVITE (18) Jul 10 17:49:17 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: User-Agent: Grandstream BT100 1.0.5.11 (38) Jul 10 17:49:17 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: Max-Forwards: 70 (16) Jul 10 17:49:17 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Jul 10 17:49:17 DEBUG[13805]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: Content-Type: application/sdp (29) Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 12: Content-Length: 298 (19) Jul 10 17:49:18 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '6111' Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 13: (0) Jul 10 17:49:18 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/6111-b192", "REALCALLERIDNUM=6111") in new stack Jul 10 17:49:18 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/6111-b192", "REALCALLERIDNUM is 6111") in new stack Jul 10 17:49:18 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '6111' Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: v=0 (3) Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: o=6111 8000 8000 IN IP4 10.3.2.111 (34) Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: s=SIP Call (10) Jul 10 17:49:18 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/6111-b192", "AMPUSER=6111") in new stack Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: c=IN IP4 10.3.2.111 (19) Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: t=0 0 (5) Jul 10 17:49:18 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'voip6111' Jul 10 17:49:18 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/6111-b192", "AMPUSERCIDNAME=voip6111") in new stack Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: m=audio 5004 RTP/AVP 0 8 18 2 15 101 (36) Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jul 10 17:49:18 DEBUG[13805]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) Jul 10 17:49:18 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/6111-b192", "0?report") in new stack Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:18 G729/8000 (21) Jul 10 17:49:18 DEBUG[13805]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) Jul 10 17:49:18 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/6111-b192", "CALLERID(all)=voip6111 <6111>") in new stack Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:15 G728/8000 (21) Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=ptime:10 (10) Jul 10 17:49:18 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"voip6111" <6111>' Jul 10 17:49:18 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' -- Executing NoOp("SIP/6111-b192", "Using CallerID "voip6111" <6111>") in new stack Jul 10 17:49:18 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jul 10 17:49:21 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=fmtp:101 0-11 (15) --- (13 headers 14 lines)--- Jul 10 17:49:21 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/6111-b192", "FROMCONTEXT=exten-vm") in new stack Jul 10 17:49:21 DEBUG[13795]: chan_sip.c:11183 handle_request: **** Received INVITE (5) - Command in SIP INVITE Jul 10 17:49:21 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/6111-b192", "VMBOX=novm") in new stack Jul 10 17:49:21 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/6111-b192", "EXTTOCALL=7401") in new stack Jul 10 17:49:21 DEBUG[13795]: chan_sip.c:11197 handle_request: Ignoring SIP message because of retransmit (INVITE Seqno 18808, ours 18808) Ignoring this INVITE request Jul 10 17:49:21 DEBUG[13795]: chan_sip.c:10597 handle_request_invite: Got a SIP re-invite for call 9f095dcd69affc54@10.3.2.111 Transmitting (no NAT) to 10.3.2.111:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKac52711770099ead;received=10.3.2.111 From: ;tag=3923113e3b920438 To: Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 18808 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jul 10 17:49:21 DEBUG[13805]: db.c:200 ast_db_get: Unable to find key '7401' in family 'CFU' Jul 10 17:49:22 DEBUG[13805]: func_db.c:69 function_db_read: DB: CFU/7401 not found in database. <-- SIP read from 10.1.1.160:5060: REGISTER sip:10.3.3.239 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.160:5060;rport;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD From: x-lite-john-pc ;tag=1188366162 To: x-lite-john-pc Contact: "x-lite-john-pc" Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 CSeq: 70680 REGISTER Expires: 1800 Max-Forwards: 70 User-Agent: X-Lite release 1105x Content-Length: 0 Jul 10 17:49:22 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '' Jul 10 17:49:22 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/6111-b192", "CFUEXT=") in new stack Jul 10 17:49:22 DEBUG[13805]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: REGISTER sip:10.3.3.239 SIP/2.0 (31) Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.160:5060;rport;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD (85) Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: x-lite-john-pc ;tag=1188366162 (67) Jul 10 17:49:22 DEBUG[13805]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 17:49:22 DEBUG[13805]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 17:49:22 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '' Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: x-lite-john-pc (50) Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Contact: "x-lite-john-pc" (62) Jul 10 17:49:22 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Set' -- Executing Set("SIP/6111-b192", "RT=") in new stack Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 (52) Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: CSeq: 70680 REGISTER (20) Jul 10 17:49:22 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' -- Executing Macro("SIP/6111-b192", "record-enable|7401|IN") in new stack Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: Expires: 1800 (13) Jul 10 17:49:22 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '0' Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: Max-Forwards: 70 (16) Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: User-Agent: X-Lite release 1105x (32) Jul 10 17:49:22 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' -- Executing GotoIf("SIP/6111-b192", "0 > 0?2:4") in new stack -- Goto (macro-record-enable,s,4) Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Content-Length: 0 (17) Jul 10 17:49:22 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: (0) --- (11 headers 0 lines)--- Jul 10 17:49:22 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'AGI' -- Executing AGI("SIP/6111-b192", "recordingcheck|20060710-174922|1152553756.0") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck Jul 10 17:49:30 DEBUG[13795]: chan_sip.c:3189 sip_alloc: Allocating new SIP dialog for E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 - REGISTER (No RTP) recordingcheck|20060710-174922|1152553756.0: Inbound recording not enabled Jul 10 17:49:30 DEBUG[13795]: chan_sip.c:11183 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER -- AGI Script recordingcheck completed, returning 0 Jul 10 17:49:30 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'NoOp' Using latest REGISTER request as basis request -- Executing NoOp("SIP/6111-b192", "No recording needed") in new stack Sending to 10.1.1.160 : 5060 (NAT) Transmitting (NAT) to 10.1.1.160:5060: SIP/2.0 404 Not found Via: SIP/2.0/UDP 10.1.1.160:5060;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD;received=10.1.1.160;rport=5060 From: x-lite-john-pc ;tag=1188366162 To: x-lite-john-pc ;tag=as46ad7b08 Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 CSeq: 70680 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jul 10 17:49:30 DEBUG[13805]: pbx.c:1589 pbx_substitute_variables_helper_full: Expression result is '0' Jul 10 17:49:30 DEBUG[13795]: chan_sip.c:6637 register_verify: SIP REGISTER attempt failed for (null) : Bad digest user Jul 10 17:49:30 NOTICE[13795]: chan_sip.c:11089 handle_request_register: Registration from 'x-lite-john-pc ' failed for '10.1.1.160' - Username/auth name mismatch Jul 10 17:49:30 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'GotoIf' Scheduling destruction of call 'E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239' in 15000 ms -- Executing GotoIf("SIP/6111-b192", "0?dolocaldial|1") in new stack <-- SIP read from 10.1.1.160:5060: REGISTER sip:10.3.3.239 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.160:5060;rport;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD From: x-lite-john-pc ;tag=1188366162 To: x-lite-john-pc Contact: "x-lite-john-pc" Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 CSeq: 70680 REGISTER Expires: 1800 Max-Forwards: 70 User-Agent: X-Lite release 1105x Content-Length: 0 Jul 10 17:49:31 DEBUG[13805]: pbx.c:6175 pbx_builtin_gotoif: Not taking any branch Jul 10 17:49:31 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Macro' -- Executing Macro("SIP/6111-b192", "dial|||7401") in new stack Header 0: REGISTER sip:10.3.3.239 SIP/2.0 (31) Jul 10 17:49:31 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'AGI' -- Executing AGI("SIP/6111-b192", "dialparties.agi") in new stack Jul 10 17:49:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.160:5060;rport;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD (85) -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi Jul 10 17:49:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: x-lite-john-pc ;tag=1188366162 (67) Jul 10 17:49:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: x-lite-john-pc (50) Jul 10 17:49:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Contact: "x-lite-john-pc" (62) Jul 10 17:49:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 (52) dialparties.agi: Starting New Dialparties.agi Jul 10 17:49:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: CSeq: 70680 REGISTER (20) -- dialparties.agi: priority is 1 Jul 10 17:49:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: Expires: 1800 (13) dialparties.agi: Caller ID name is 'voip6111' number is '6111' Jul 10 17:49:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: Max-Forwards: 70 (16) dialparties.agi: Methodology of ring is 'none' Jul 10 17:49:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: User-Agent: X-Lite release 1105x (32) -- dialparties.agi: Added extension 7401 to extension map Jul 10 17:49:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Content-Length: 0 (17) Jul 10 17:49:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: (0) Jul 10 17:49:32 DEBUG[13805]: db.c:200 ast_db_get: Unable to find key '7401' in family 'CF' -- dialparties.agi: Extension 7401 cf is disabled --- (11 headers 0 lines)Jul 10 17:49:32 DEBUG[13805]: db.c:200 ast_db_get: Unable to find key '7401' in family 'DND' --- Jul 10 17:49:32 DEBUG[13795]: chan_sip.c:11183 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER -- dialparties.agi: Extension 7401 do not disturb is disabled Ignoring SIP message because of retransmit (REGISTER Seqno 70680, ours 70680) Using latest REGISTER request as basis request Sending to 10.1.1.160 : 5060 (NAT) Transmitting (NAT) to 10.1.1.160:5060: SIP/2.0 404 Not found Via: SIP/2.0/UDP 10.1.1.160:5060;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD;received=10.1.1.160;rport=5060 From: x-lite-john-pc ;tag=1188366162 To: x-lite-john-pc ;tag=as46ad7b08 Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 CSeq: 70680 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jul 10 17:49:32 DEBUG[13805]: db.c:200 ast_db_get: Unable to find key '7401' in family 'CW' Jul 10 17:49:32 DEBUG[13805]: db.c:200 ast_db_get: Unable to find key '7401' in family 'CFB' Jul 10 17:49:33 DEBUG[13805]: db.c:200 ast_db_get: Unable to find key '7401' in family 'CFU' > dialparties.agi: extnum: 7401 > dialparties.agi: exthascw: 0.c:6637 register_verify: SIP REGISTER attempt failed for (null) : Bad digest user > dialparties.agi: exthascfb: 0.c:11089 handle_request_register: Registration from 'x-lite-john-pc ' failed for '10.1.1.160' - Username/auth name mismatch Scheduling destruction of call 'E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239' in 15000 ms <-- SIP read from 10.1.1.160:5060: REGISTER sip:10.3.3.239 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.160:5060;rport;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD From: x-lite-john-pc ;tag=1188366162 To: x-lite-john-pc Contact: "x-lite-john-pc" Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 CSeq: 70680 REGISTER Expires: 1800 Max-Forwards: 70 User-Agent: X-Lite release 1105x Content-Length: 0 Jul 10 17:49:34 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: REGISTER sip:10.3.3.239 SIP/2.0 (31) > dialparties.agi: extcfb: Jul 10 17:49:34 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.160:5060;rport;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD (85) > dialparties.agi: exthascfu: 0c:3405 parse_request: Header 2: From: x-lite-john-pc ;tag=1188366162 (67) > dialparties.agi: extcfu: Jul 10 17:49:34 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: x-lite-john-pc (50) Jul 10 17:49:34 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Contact: "x-lite-john-pc" (62) Jul 10 17:49:34 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 (52) Jul 10 17:49:34 DEBUG[13809]: manager.c:1249 process_message: Manager received command 'login' Jul 10 17:49:34 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: CSeq: 70680 REGISTER (20) Jul 10 17:49:34 DEBUG[13809]: config.c:595 config_text_file_load: Parsing /etc/asterisk/manager.conf Jul 10 17:49:34 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: Expires: 1800 (13) Jul 10 17:49:34 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: Max-Forwards: 70 (16) Jul 10 17:49:34 DEBUG[13809]: acl.c:199 ast_append_ha: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer Jul 10 17:49:35 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: User-Agent: X-Lite release 1105x (32) Jul 10 17:49:35 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Content-Length: 0 (17) Jul 10 17:49:35 DEBUG[13809]: acl.c:199 ast_append_ha: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer Jul 10 17:49:35 DEBUG[13809]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 0.0.0.0 Jul 10 17:49:35 DEBUG[13809]: acl.c:211 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.0 == Manager 'ken' logged on from 127.0.0.1 Jul 10 17:49:35 DEBUG[13809]: manager.c:1249 process_message: Manager received command 'ExtensionState' Jul 10 17:49:35 DEBUG[13809]: manager.c:1249 process_message: Manager received command 'Logoff' Jul 10 17:49:35 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: (0) == Manager 'ken' logged off from 127.0.0.1 > dialparties.agi: ExtensionState: 0 -- dialparties.agi: Checking CW and CFB status for extension 7401 -- dialparties.agi: DbSet CALLTRACE/7401 to 6111 -- AGI Script dialparties.agi completed, returning 0 Jul 10 17:49:35 DEBUG[13805]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/6111-b192", "OOH323/ken_op||") in new stack Jul 10 17:49:35 WARNING[13805]: manager.c:1535 manager_event: Disconnecting slow (or gone) manager session! Jul 10 17:49:35 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-10. Jul 10 17:49:35 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. Jul 10 17:49:35 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable ds. --- (11 headers 0 lines)Not copying variable STACK-macro-dial-s-1.ariables: --- Jul 10 17:49:35 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable ARG3. Jul 10 17:49:35 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable ARG2. Jul 10 17:49:35 DEBUG[13795]: chan_sip.c:11183 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Jul 10 17:49:35 DEBUG[13795]: chan_sip.c:11197 handle_request: Ignoring SIP message because of retransmit (REGISTER Seqno 70680, ours 70680) Jul 10 17:49:35 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable ARG1. Using latest REGISTER request as basis request Jul 10 17:49:35 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. Sending to 10.1.1.160 : 5060 (NAT) Jul 10 17:49:36 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. Jul 10 17:49:37 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. Transmitting (NAT) to 10.1.1.160:5060: SIP/2.0 404 Not found Via: SIP/2.0/UDP 10.1.1.160:5060;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD;received=10.1.1.160;rport=5060 From: x-lite-john-pc ;tag=1188366162 To: x-lite-john-pc ;tag=as46ad7b08 Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 CSeq: 70680 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jul 10 17:49:37 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-9. Jul 10 17:49:37 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-8. Jul 10 17:49:37 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-5. Jul 10 17:49:37 DEBUG[13795]: chan_sip.c:6637 register_verify: SIP REGISTER attempt failed for (null) : Bad digest user Jul 10 17:49:37 NOTICE[13795]: chan_sip.c:11089 handle_request_register: Registration from 'x-lite-john-pc ' failed for '10.1.1.160' - Username/auth name mismatch Scheduling destruction of call 'E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239' in 15000 ms Jul 10 17:49:37 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-4. Jul 10 17:49:44 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-1. <-- SIP read from 10.1.1.160:5060: REGISTER sip:10.3.3.239 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.160:5060;rport;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD From: x-lite-john-pc ;tag=1188366162 To: x-lite-john-pc Contact: "x-lite-john-pc" Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 CSeq: 70680 REGISTER Expires: 1800 Max-Forwards: 70 User-Agent: X-Lite release 1105x Content-Length: 0 Jul 10 17:49:44 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-7. Jul 10 17:49:44 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: REGISTER sip:10.3.3.239 SIP/2.0 (31) Jul 10 17:49:44 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.160:5060;rport;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD (85) Jul 10 17:49:44 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: x-lite-john-pc ;tag=1188366162 (67) Jul 10 17:49:44 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: x-lite-john-pc (50) Jul 10 17:49:44 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable RT. Jul 10 17:49:44 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Contact: "x-lite-john-pc" (62) Jul 10 17:49:44 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 (52) Jul 10 17:49:44 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-6. Jul 10 17:49:44 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: CSeq: 70680 REGISTER (20) Jul 10 17:49:44 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable CFUEXT. Jul 10 17:49:44 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-5. Jul 10 17:49:44 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: Expires: 1800 (13) Jul 10 17:49:44 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable EXTTOCALL. Jul 10 17:49:44 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: Max-Forwards: 70 (16) Jul 10 17:49:44 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-4. Jul 10 17:49:44 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: User-Agent: X-Lite release 1105x (32) Jul 10 17:49:45 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Content-Length: 0 (17) Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable VMBOX. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-3. Jul 10 17:49:45 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: (0) --- (11 headers 0 lines)--- Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable FROMCONTEXT. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-2. Jul 10 17:49:45 DEBUG[13795]: chan_sip.c:11183 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Jul 10 17:49:45 DEBUG[13795]: chan_sip.c:11197 handle_request: Ignoring SIP message because of retransmit (REGISTER Seqno 70680, ours 70680) Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-9. Using latest REGISTER request as basis request Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-8. Sending to 10.1.1.160 : 5060 (NAT)nel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-7. Transmitting (NAT) to 10.1.1.160:5060: SIP/2.0 404 Not found Via: SIP/2.0/UDP 10.1.1.160:5060;branch=z9hG4bKBB0CFFA61B0A4D96A3A0AAB65A26F9FD;received=10.1.1.160;rport=5060 From: x-lite-john-pc ;tag=1188366162 To: x-lite-john-pc ;tag=as46ad7b08 Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 CSeq: 70680 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME. Jul 10 17:49:45 DEBUG[13795]: chan_sip.c:6637 register_verify: SIP REGISTER attempt failed for (null) : Bad digest user Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-6. Jul 10 17:49:45 NOTICE[13795]: chan_sip.c:11089 handle_request_register: Registration from 'x-lite-john-pc ' failed for '10.1.1.160' - Username/auth name mismatch Scheduling destruction of call 'E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239' in 15000 ms <-- SIP read from 10.1.1.160:5060: Jul 10 17:49:45 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: (0) Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable DB_RESULT. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable AMPUSER. --- (0 headers 0 lines)Not copying variable STACK-macro-user-callerid-s-5.: Nat keepalive --- Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-4. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable REALCALLERIDNUM. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-3. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-2. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-1. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-1. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable STACK-from-internal-7401-1. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable SIPCALLID. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. Jul 10 17:49:45 DEBUG[13805]: channel.c:2829 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called ken_op -- ast_channel_make_compatible: src=0x4: dst=0x4 Jul 10 17:49:46 DEBUG[13805]: channel.c:2350 set_format: Set channel OOH323/ken_op-46ec to read format ulaw Jul 10 17:49:46 DEBUG[13805]: channel.c:2350 set_format: Set channel SIP/6111-b192 to write format ulaw Jul 10 17:49:46 DEBUG[13805]: channel.c:2350 set_format: Set channel SIP/6111-b192 to read format ulaw Jul 10 17:49:46 DEBUG[13805]: channel.c:2350 set_format: Set channel OOH323/ken_op-46ec to write format ulaw -- OOH323/ken_op-46ec is ringing Jul 10 17:49:46 DEBUG[13789]: devicestate.c:187 do_state_change: Changing state for OOH323/ken_op - state 6 (Ringing) Transmitting (no NAT) to 10.3.2.111:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKac52711770099ead;received=10.3.2.111 From: ;tag=3923113e3b920438 To: ;tag=as07ff7962 Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 18808 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jul 10 17:49:46 DEBUG[13810]: app_queue.c:523 changethread: Device 'OOH323/ken_op' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. -- OOH323/ken_op-46ec answered SIP/6111-b192 Jul 10 17:49:48 DEBUG[13789]: devicestate.c:187 do_state_change: Changing state for OOH323/ken_op - state 2 (In use) -- ast_channel_make_compatible: src=0x4: dst=0x4 ast_rtp_set_peer: rtp->nat=0: them->sin_addr.s_addr=0xa01019b: sin_port=0x6b8 Jul 10 17:49:48 DEBUG[13811]: app_queue.c:523 changethread: Device 'OOH323/ken_op' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jul 10 17:49:48 DEBUG[13805]: channel.c:2350 set_format: Set channel SIP/6111-b192 to read format ulaw Jul 10 17:49:48 DEBUG[13805]: channel.c:2350 set_format: Set channel OOH323/ken_op-46ec to write format ulaw Jul 10 17:49:48 DEBUG[13805]: channel.c:2350 set_format: Set channel OOH323/ken_op-46ec to read format ulaw Jul 10 17:49:48 DEBUG[13805]: channel.c:2350 set_format: Set channel SIP/6111-b192 to write format ulaw Jul 10 17:49:48 DEBUG[13789]: chan_sip.c:11714 sip_devicestate: Checking device state for peer 6111 Jul 10 17:49:48 DEBUG[13789]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/6111-b192' Jul 10 17:49:48 DEBUG[13805]: chan_sip.c:2540 sip_answer: sip_answer(SIP/6111-b192) We're at 10.3.3.239 port 13818 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP Jul 10 17:49:48 DEBUG[13789]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/6111-b192' Reliably Transmitting (no NAT) to 10.3.2.111:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKac52711770099ead;received=10.3.2.111 From: ;tag=3923113e3b920438 To: ;tag=as07ff7962 Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 18808 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 212 v=0 o=root 13805 13805 IN IP4 10.3.3.239 s=session c=IN IP4 10.3.3.239 t=0 0 m=audio 13818 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Jul 10 17:49:48 DEBUG[13805]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #17 Jul 10 17:49:48 DEBUG[13789]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/6111-b192' -- ast_channel_bridge is being called: (1) flags=0x0 Jul 10 17:49:48 DEBUG[13789]: devicestate.c:187 do_state_change: Changing state for SIP/6111 - state 2 (In use) <-- SIP read from 10.3.2.111:5060: ACK sip:7401@10.3.3.239 SIP/2.0 Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKa26b3b00f8a7e4a6 From: ;tag=3923113e3b920438 To: ;tag=as07ff7962 Contact: Proxy-Authorization: DIGEST username="6111", realm="asterisk", algorithm=MD5, uri="sip:7401@10.3.3.239", nonce="42317b0d", response="8b72f9754523cba7699b3b477b518a76" Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 18808 ACK User-Agent: Grandstream BT100 1.0.5.11 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 Jul 10 17:49:48 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: ACK sip:7401@10.3.3.239 SIP/2.0 (31) -- ast_channel_bridge is being called: (2) c0-bridge=268845296: c1-bridge=268845296 Jul 10 17:49:48 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.2.111;branch=z9hG4bKa26b3b00f8a7e4a6 (58) -- Attempting native bridge of SIP/6111-b192 and OOH323/ken_op-46ec Jul 10 17:49:48 DEBUG[13812]: app_queue.c:523 changethread: Device 'SIP/6111' changed to state '2' (In use) but we don't care because they're not a member of any queue. Jul 10 17:49:48 DEBUG[13789]: chan_sip.c:11714 sip_devicestate: Checking device state for peer 6111 Jul 10 17:49:48 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: ;tag=3923113e3b920438 (59) Jul 10 17:49:48 DEBUG[13805]: chan_sip.c:12974 sip_set_rtp_peer: Deferring reinvite on SIP '9f095dcd69affc54@10.3.2.111' - It's audio will be redirected to IP 10.1.1.155 Jul 10 17:49:48 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: ;tag=as07ff7962 (51) Jul 10 17:49:48 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Contact: (41) Jul 10 17:49:49 DEBUG[13805]: channel.c:1957 ast_read: Dropping duplicate answer! -- &Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: -- SRAHeader 5: Proxy-Authorization: DIGEST username="6111", realm="asterisk", algorithm=MD5, uri="sip:7401@10.3.3.239", nonce="42317b0d", response="8b72f9754523cba7699b3b477b518a76" (166) Jul 10 17:49:49 DEBUG[13805]: rtp.c:1375 ast_rtp_write: Ooh, format changed from unknown to ulaw Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: Call-ID: 9f095dcd69affc54@10.3.2.111 (36) -- *Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: CSeq: 18808 ACK (15) -- SWJul 10 17:49:49 DEBUG[13805]: rtp.c:1375 ast_rtp_write: Ooh, format changed from unknown to ulaw Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: User-Agent: Grandstream BT100 1.0.5.11 (38) Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: Max-Forwards: 70 (16) Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: Content-Length: 0 (17) Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 12: (0) --- (12 headers 0 lines)--- Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:11183 handle_request: **** Received ACK (6) - Command in SIP ACK Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #17 Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '9f095dcd69affc54@10.3.2.111' of Response 18808: Match Found Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:9613 check_pendings: Sending pending reinvite on '9f095dcd69affc54@10.3.2.111' set_destination: Parsing for address/port to send to set_destination: set destination to 10.3.2.111, port 5060 X-asterisk-info: redirect=0xa01019b: peer=0xa03026f We're at 10.3.3.239 port 13818 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: INVITE sip:6111@10.3.2.111 SIP/2.0 (34) Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK616639b7 (55) Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: ;tag=as07ff7962 (53) Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: ;tag=3923113e3b920438 (57) Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Contact: (30) Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: Call-ID: 9f095dcd69affc54@10.3.2.111 (36) Jul 10 17:49:49 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: CSeq: 102 INVITE (16) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: User-Agent: Asterisk PBX (24) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: Max-Forwards: 70 (16) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: X-asterisk-info: SIP re-invite (RTP bridge) (45) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: Content-Type: application/sdp (29) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 12: Content-Length: 211 (19) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 13: (0) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: v=0 (3) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: o=root 13805 13806 IN IP4 10.1.1.155 (36) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: s=session (9) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: c=IN IP4 10.1.1.155 (19) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: t=0 0 (5) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: m=audio 1720 RTP/AVP 0 101 (26) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=fmtp:101 0-16 (15) Jul 10 17:49:50 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=silenceSupp:off - - - - (25) 13 headers, 10 lines Reliably Transmitting (no NAT) to 10.3.2.111:5060: INVITE sip:6111@10.3.2.111 SIP/2.0 Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK616639b7 From: ;tag=as07ff7962 To: ;tag=3923113e3b920438 Contact: Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 211 v=0 o=root 13805 13806 IN IP4 10.1.1.155 s=session c=IN IP4 10.1.1.155 t=0 0 m=audio 1720 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Jul 10 17:49:51 DEBUG[13795]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #18 -- & -- SRA <-- SIP read from 10.3.2.111:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK616639b7 From: ;tag=as07ff7962 To: ;tag=3923113e3b920438 Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 102 INVITE User-Agent: Grandstream BT100 1.0.5.11 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 195 v=0 o=6111 8000 8000 IN IP4 10.3.2.111 s=SIP Call c=IN IP4 10.3.2.111 t=0 0 m=audio 5004 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 Jul 10 17:49:51 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: SIP/2.0 200 OK (14) Jul 10 17:49:51 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK616639b7 (55) Jul 10 17:49:51 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: ;tag=as07ff7962 (53) -- *Jul 10 17:49:51 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: ;tag=3923113e3b920438 (57) -- SWJul 10 17:49:51 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Call-ID: 9f095dcd69affc54@10.3.2.111 (36) Jul 10 17:49:51 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: CSeq: 102 INVITE (16) Jul 10 17:49:51 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: User-Agent: Grandstream BT100 1.0.5.11 (38) Jul 10 17:49:51 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: Contact: (41) Jul 10 17:49:51 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: Content-Type: application/sdp (29) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Content-Length: 195 (19) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: (0) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: v=0 (3) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: o=6111 8000 8000 IN IP4 10.3.2.111 (34) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: s=SIP Call (10) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: c=IN IP4 10.3.2.111 (19) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: t=0 0 (5) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: m=audio 5004 RTP/AVP 0 101 (26) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=ptime:20 (10) Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) -- *Jul 10 17:49:52 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=fmtp:101 0-11 (15) --- (11 headers 10 lines)--- Jul 10 17:50:01 DEBUG[13795]: chan_sip.c:11360 sipsock_read: Failed to grab lock, trying again... -- SWJul 10 17:50:01 DEBUG[13805]: rtp.c:1730 ast_rtp_bridge: Oooh, 'OOH323/ken_op-46ec' changed end address to 0.0.0.0:0 (format 0) *CLI> Jul 10 17:50:01 DEBUG[13805]: rtp.c:1732 ast_rtp_bridge: Oooh, 'OOH323/ken_op-46ec' changed end vaddress to 0.0.0.0:0 (format 0) Jul 10 17:50:02 DEBUG[13795]: chan_sip.c:1379 __sip_ack: Acked pending invite 102 Jul 10 17:50:02 DEBUG[13795]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #18 Jul 10 17:50:02 DEBUG[13795]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '9f095dcd69affc54@10.3.2.111' of Request 102: Match Found Jul 10 17:50:02 DEBUG[13795]: chan_sip.c:9628 handle_response_invite: SIP response 200 to RE-invite on outgoing call 9f095dcd69affc54@10.3.2.111 Found RTP audio format 0 Found RTP audio format 101 ast_rtp_set_peer: rtp->nat=0: them->sin_addr.s_addr=0xa03026f: sin_port=0x138c Peer audio RTP is at port 10.3.2.111:5004 Jul 10 17:50:02 DEBUG[13795]: chan_sip.c:3646 process_sdp: Peer audio RTP is at port 10.3.2.111:5004 Found description format PCMU Jul 10 17:50:02 DEBUG[13805]: rtp.c:1734 ast_rtp_bridge: Oooh, 'OOH323/ken_op-46ec' was 10.1.1.155:1720/(format 0) Jul 10 17:50:02 DEBUG[13805]: rtp.c:1736 ast_rtp_bridge: Oooh, 'OOH323/ken_op-46ec' was 0.0.0.0:0/(format 0) Found description format telephone-event Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Jul 10 17:50:02 DEBUG[13795]: chan_sip.c:6183 build_route: build_route: Contact hop: list_route: hop: set_destination: Parsing for address/port to send to set_destination: set destination to 10.3.2.111, port 5060 Transmitting (no NAT) to 10.3.2.111:5060: ACK sip:6111@10.3.2.111;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK239f8b6d From: ;tag=as07ff7962 To: ;tag=3923113e3b920438 Contact: Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Jul 10 17:50:02 DEBUG[13805]: chan_sip.c:12968 sip_set_rtp_peer: Sending reinvite on SIP '9f095dcd69affc54@10.3.2.111' - It's audio soon redirected to IP 10.3.3.239 set_destination: Parsing for address/port to send to set_destination: set destination to 10.3.2.111, port 5060 X-asterisk-info: redirect=0x0: peer=0xa03026f We're at 10.3.3.239 port 13818 Jul 10 17:50:02 DEBUG[13795]: chan_sip.c:1323 __sip_autodestruct: Auto destroying call 'E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239' Destroying call 'E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239' Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 0: INVITE sip:6111@10.3.2.111;user=phone SIP/2.0 (45) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK76571f96 (55) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 2: From: ;tag=as07ff7962 (53) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 3: To: ;tag=3923113e3b920438 (57) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 4: Contact: (30) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 5: Call-ID: 9f095dcd69affc54@10.3.2.111 (36) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 6: CSeq: 103 INVITE (16) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 7: User-Agent: Asterisk PBX (24) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 8: Max-Forwards: 70 (16) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 10: X-asterisk-info: SIP re-invite (RTP bridge) (45) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 11: Content-Type: application/sdp (29) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 12: Content-Length: 212 (19) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3405 parse_request: Header 13: (0) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3437 parse_request: Line: v=0 (3) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3437 parse_request: Line: o=root 13805 13807 IN IP4 10.3.3.239 (36) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3437 parse_request: Line: s=session (9) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3437 parse_request: Line: c=IN IP4 10.3.3.239 (19) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3437 parse_request: Line: t=0 0 (5) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3437 parse_request: Line: m=audio 13818 RTP/AVP 0 101 (27) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3437 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3437 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3437 parse_request: Line: a=fmtp:101 0-16 (15) Jul 10 17:50:03 DEBUG[13805]: chan_sip.c:3437 parse_request: Line: a=silenceSupp:off - - - - (25) 13 headers, 10 lines Reliably Transmitting (no NAT) to 10.3.2.111:5060: INVITE sip:6111@10.3.2.111;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK76571f96 From: ;tag=as07ff7962 To: ;tag=3923113e3b920438 Contact: Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 103 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-asterisk-info: SIP re-invite (RTP bridge) Content-Type: application/sdp Content-Length: 212 v=0 o=root 13805 13807 IN IP4 10.3.3.239 s=session c=IN IP4 10.3.3.239 t=0 0 m=audio 13818 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Jul 10 17:50:04 DEBUG[13805]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #19 <-- SIP read from 10.1.1.160:5060: Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: (0) --- (0 headers 0 lines) Nat keepalive --- Jul 10 17:50:04 DEBUG[13805]: rtp.c:1801 ast_rtp_bridge: Oooh, got a hangup <-- SIP read from 10.3.2.111:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK76571f96 From: ;tag=as07ff7962 To: ;tag=3923113e3b920438 Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 103 INVITE User-Agent: Grandstream BT100 1.0.5.11 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 195 v=0 o=6111 8000 8000 IN IP4 10.3.2.111 s=SIP Call c=IN IP4 10.3.2.111 t=0 0 m=audio 5004 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 Jul 10 17:50:04 DEBUG[13805]: chan_sip.c:12974 sip_set_rtp_peer: Deferring reinvite on SIP '9f095dcd69affc54@10.3.2.111' - It's audio will be redirected to IP 10.3.3.239 Jul 10 17:50:04 DEBUG[13805]: channel.c:3505 ast_channel_bridge: Returning from native bridge, channels: SIP/6111-b192, OOH323/ken_op-46ec Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: SIP/2.0 200 OK (14) Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK76571f96 (55) Jul 10 17:50:04 DEBUG[13805]: channel.c:1323 ast_hangup: Hanging up channel 'OOH323/ken_op-46ec' Jul 10 17:50:04 DEBUG[13789]: devicestate.c:187 do_state_change: Changing state for OOH323/ken_op - state 0 (Unknown) Jul 10 17:50:04 DEBUG[13805]: app_dial.c:1619 dial_exec_full: Exiting with DIALSTATUS=ANSWER. Jul 10 17:50:04 DEBUG[13813]: app_queue.c:523 changethread: Device 'OOH323/ken_op' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: ;tag=as07ff7962 (53) Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: ;tag=3923113e3b920438 (57) Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Call-ID: 9f095dcd69affc54@10.3.2.111 (36) Jul 10 17:50:04 DEBUG[13805]: app_macro.c:231 macro_exec: Spawn extension (macro-dial,s,10) exited non-zero on 'SIP/6111-b192' in macro 'dial' Jul 10 17:50:04 DEBUG[13805]: app_macro.c:231 macro_exec: Spawn extension (macro-dial,s,10) exited non-zero on 'SIP/6111-b192' in macro 'exten-vm' Jul 10 17:50:04 DEBUG[13805]: pbx.c:2316 __ast_pbx_run: Spawn extension (macro-dial,s,10) exited non-zero on 'SIP/6111-b192' Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: CSeq: 103 INVITE (16) Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: User-Agent: Grandstream BT100 1.0.5.11 (38) Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: Contact: (41) Jul 10 17:50:04 DEBUG[13805]: cdr_addon_mysql.c:206 mysql_log: cdr_mysql: inserting a CDR record. Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: Content-Type: application/sdp (29) Jul 10 17:50:04 DEBUG[13805]: cdr_addon_mysql.c:222 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2006-07-10 17:49:16','\"voip6111\" <6111>','6111','7401','from-internal', 'SIP/6111-b192','OOH323/ken_op-46ec','Dial','OOH323/ken_op||',48,16,'ANSWERED',3,'','1152553756.0') Jul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Content-Length: 195 (19) Jul 10 17:50:04 ERROR[13805]: cdr_addon_mysql.c:226 mysql_log: mysql_cdr: Failed to insert into database: (1146) Table 'asterisk.cdr' doesn't existJul 10 17:50:04 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: (0) Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"voip6111" <6111>' Jul 10 17:50:05 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: v=0 (3) Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '6111' Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '7401' Jul 10 17:50:05 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: o=6111 8000 8000 IN IP4 10.3.2.111 (34) Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'from-internal' Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/6111-b192' Jul 10 17:50:05 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: s=SIP Call (10) Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'OOH323/ken_op-46ec' Jul 10 17:50:05 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: c=IN IP4 10.3.2.111 (19) Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' Jul 10 17:50:05 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: t=0 0 (5) Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'OOH323/ken_op||' Jul 10 17:50:05 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: m=audio 5004 RTP/AVP 0 101 (26) Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-07-10 17:49:16' Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-07-10 17:49:48' Jul 10 17:50:05 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-07-10 17:50:04' Jul 10 17:50:05 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=ptime:20 (10) Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '48' Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '16' Jul 10 17:50:05 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) Jul 10 17:50:05 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' Jul 10 17:50:05 DEBUG[13795]: chan_sip.c:3437 parse_request: Line: a=fmtp:101 0-11 (15) Jul 10 17:50:06 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' --- (11 headers 10 lines)Jul 10 17:50:06 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jul 10 17:50:06 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1152553756.0' --- Jul 10 17:50:06 DEBUG[13805]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' Jul 10 17:50:06 DEBUG[13795]: chan_sip.c:11360 sipsock_read: Failed to grab lock, trying again... Jul 10 17:50:06 DEBUG[13795]: chan_sip.c:11360 sipsock_read: Failed to grab lock, trying again... Jul 10 17:50:06 DEBUG[13795]: chan_sip.c:11360 sipsock_read: Failed to grab lock, trying again... Jul 10 17:50:06 DEBUG[13805]: channel.c:1323 ast_hangup: Hanging up channel 'SIP/6111-b192' Jul 10 17:50:06 DEBUG[13805]: chan_sip.c:2418 sip_hangup: Hangup call SIP/6111-b192, SIP callid 9f095dcd69affc54@10.3.2.111) Jul 10 17:50:06 DEBUG[13805]: chan_sip.c:2426 sip_hangup: update_call_counter(6111) - decrement call limit counter Jul 10 17:50:06 DEBUG[13805]: chan_sip.c:2209 update_call_counter: Updating call counter for outgoing call Jul 10 17:50:06 DEBUG[13795]: chan_sip.c:1379 __sip_ack: Acked pending invite 103 Jul 10 17:50:06 DEBUG[13795]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #19 Jul 10 17:50:06 DEBUG[13789]: chan_sip.c:11714 sip_devicestate: Checking device state for peer 6111 Jul 10 17:50:06 DEBUG[13789]: devicestate.c:187 do_state_change: Changing state for SIP/6111 - state 1 (Not in use) Jul 10 17:50:06 DEBUG[13814]: app_queue.c:523 changethread: Device 'SIP/6111' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. Jul 10 17:50:06 DEBUG[13789]: chan_sip.c:11714 sip_devicestate: Checking device state for peer 6111 Jul 10 17:50:06 DEBUG[13795]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '9f095dcd69affc54@10.3.2.111' of Request 103: Match Found Jul 10 17:50:06 DEBUG[13795]: chan_sip.c:9630 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 ast_rtp_set_peer: rtp->nat=0: them->sin_addr.s_addr=0xa03026f: sin_port=0x138c Peer audio RTP is at port 10.3.2.111:5004 Jul 10 17:50:06 DEBUG[13795]: chan_sip.c:3646 process_sdp: Peer audio RTP is at port 10.3.2.111:5004 Found description format PCMU Found description format telephone-event Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Jul 10 17:50:06 DEBUG[13795]: chan_sip.c:6126 build_route: build_route: Retaining previous route: set_destination: Parsing for address/port to send to set_destination: set destination to 10.3.2.111, port 5060 Transmitting (no NAT) to 10.3.2.111:5060: ACK sip:6111@10.3.2.111;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK2fabe752 From: ;tag=as07ff7962 To: ;tag=3923113e3b920438 Contact: Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 103 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- set_destination: Parsing for address/port to send to set_destination: set destination to 10.3.2.111, port 5060 Reliably Transmitting (no NAT) to 10.3.2.111:5060: CANCEL sip:6111@10.3.2.111;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK2fabe752 From: ;tag=as07ff7962 To: ;tag=3923113e3b920438 Contact: Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 103 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Jul 10 17:50:07 DEBUG[13795]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #20 Scheduling destruction of call '9f095dcd69affc54@10.3.2.111' in 32000 ms <-- SIP read from 10.3.2.111:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK2fabe752 From: ;tag=as07ff7962 To: ;tag=3923113e3b920438 Call-ID: 9f095dcd69affc54@10.3.2.111 CSeq: 103 CANCEL User-Agent: Grandstream BT100 1.0.5.11 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 *CLI> Jul 10 17:50:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: SIP/2.0 200 OK (14) Jul 10 17:50:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.3.3.239:5060;branch=z9hG4bK2fabe752 (55) Jul 10 17:50:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: ;tag=as07ff7962 (53) Jul 10 17:50:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: ;tag=3923113e3b920438 (57) Jul 10 17:50:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Call-ID: 9f095dcd69affc54@10.3.2.111 (36) Jul 10 17:50:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: CSeq: 103 CANCEL (16) Jul 10 17:50:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: User-Agent: Grandstream BT100 1.0.5.11 (38) Jul 10 17:50:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: Contact: (41) Jul 10 17:50:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Jul 10 17:50:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: Content-Length: 0 (17) Jul 10 17:50:14 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: (0) --- (10 headers 0 lines)--- Jul 10 17:50:15 DEBUG[13795]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #20 Jul 10 17:50:15 DEBUG[13795]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '9f095dcd69affc54@10.3.2.111' of Request 103: Match Found Destroying call '9f095dcd69affc54@10.3.2.111' <-- SIP read from 10.1.1.160:5060: Jul 10 17:50:15 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: (0) --- (0 headers 0 lines) Nat keepalive --- <-- SIP read from 10.1.1.160:5060: Jul 10 17:50:30 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: (0) --- (0 headers 0 lines) Nat keepalive --- <-- SIP read from 10.1.1.160:5060: REGISTER sip:10.3.3.239 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.160:5060;rport;branch=z9hG4bK09A7009CE7204E5896239F5A70D39C85 From: x-lite-john-pc ;tag=1188366162 To: x-lite-john-pc Contact: "x-lite-john-pc" Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 CSeq: 70681 REGISTER Expires: 1800 Max-Forwards: 70 User-Agent: X-Lite release 1105x Content-Length: 0 Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 0: REGISTER sip:10.3.3.239 SIP/2.0 (31) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.160:5060;rport;branch=z9hG4bK09A7009CE7204E5896239F5A70D39C85 (85) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 2: From: x-lite-john-pc ;tag=1188366162 (67) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 3: To: x-lite-john-pc (50) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 4: Contact: "x-lite-john-pc" (62) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 5: Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 (52) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 6: CSeq: 70681 REGISTER (20) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 7: Expires: 1800 (13) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 8: Max-Forwards: 70 (16) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 9: User-Agent: X-Lite release 1105x (32) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 10: Content-Length: 0 (17) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3405 parse_request: Header 11: (0) --- (11 headers 0 lines)--- Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:3189 sip_alloc: Allocating new SIP dialog for E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 - REGISTER (No RTP) Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:11183 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 10.1.1.160 : 5060 (NAT) Transmitting (NAT) to 10.1.1.160:5060: SIP/2.0 404 Not found Via: SIP/2.0/UDP 10.1.1.160:5060;branch=z9hG4bK09A7009CE7204E5896239F5A70D39C85;received=10.1.1.160;rport=5060 From: x-lite-john-pc ;tag=1188366162 To: x-lite-john-pc ;tag=as3acb10b2 Call-ID: E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239 CSeq: 70681 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- Jul 10 17:50:31 DEBUG[13795]: chan_sip.c:6637 register_verify: SIP REGISTER attempt failed for (null) : Bad digest user Jul 10 17:50:31 NOTICE[13795]: chan_sip.c:11089 handle_request_register: Registration from 'x-lite-john-pc ' failed for '10.1.1.160' - Username/auth name mismatch Scheduling destruction of call 'E1856D92235F4A7599B507B7DFA12BF8@10.3.3.239' in 15000 ms *CLI> set debug 0 Core debug is now OFF *CLI> set verbose 0 Verbosity is now OFF *CLI> sip no debug SIP Debugging Disabled