Nov 11 17:25:51 DEBUG[19784] pbx.c: Launching 'Dial' Nov 11 17:25:51 VERBOSE[19784] logger.c: -- Executing Dial("SIP/ext2006-21ca", "SIP/613@fwd|60|twW") in new stack Nov 11 17:25:51 DEBUG[19784] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) Nov 11 17:25:51 DEBUG[19784] chan_sip.c: Setting NAT on RTP to 0 Nov 11 17:25:51 DEBUG[19784] chan_sip.c: Setting NAT on VRTP to 0 Nov 11 17:25:51 DEBUG[19784] acl.c: ##### Testing 69.90.155.70 with 192.168.254.0 Nov 11 17:25:51 DEBUG[19784] chan_sip.c: Target address 69.90.155.70 is not local, substituting externip Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable STACK-macro-dialfwd-s-3. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable MACRO_DEPTH. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable STACK-macro-dialfwd-s-2. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable PLAYBACKSTATUS. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable STACK-macro-dialfwd-s-1. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable ARG2. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable ARG1. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable MACRO_PRIORITY. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable MACRO_CONTEXT. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable MACRO_EXTEN. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable STACK-home-*393613-1. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable SIPCALLID. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable SIPUSERAGENT. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable SIPDOMAIN. Nov 11 17:25:51 DEBUG[19784] channel.c: Not copying variable SIPURI. Nov 11 17:25:51 DEBUG[19784] chan_sip.c: Outgoing Call for 613 Nov 11 17:25:51 DEBUG[19784] chan_sip.c: Updating call counter for outgoing call Nov 11 17:25:51 VERBOSE[19784] logger.c: -- Called 613@fwd Nov 11 17:25:51 DEBUG[19784] channel.c: Set channel SIP/fwd-0d24 to read format ulaw Nov 11 17:25:51 DEBUG[19784] channel.c: Set channel SIP/ext2006-21ca to write format ulaw Nov 11 17:25:51 DEBUG[19784] channel.c: Set channel SIP/ext2006-21ca to read format ulaw Nov 11 17:25:51 DEBUG[19784] channel.c: Set channel SIP/fwd-0d24 to write format ulaw Nov 11 17:25:51 DEBUG[19778] chan_sip.c: = Found Their Call ID: 09263cbc3697bde26f5f1f1f51d6ba9a@fwd.pulver.com Their Tag Our tag: as0cd63f08 Nov 11 17:25:51 DEBUG[19778] chan_sip.c: Acked pending invite 102 Nov 11 17:25:51 DEBUG[19778] chan_sip.c: Stopping retransmission on '09263cbc3697bde26f5f1f1f51d6ba9a@fwd.pulver.com' of Request 102: Match Found Nov 11 17:25:51 DEBUG[19778] chan_sip.c: SIP response 407 to standard invite Nov 11 17:25:51 DEBUG[19778] chan_sip.c: Auth attempt 1 on INVITE Nov 11 17:25:51 DEBUG[19778] chan_sip.c: = Found Their Call ID: 09263cbc3697bde26f5f1f1f51d6ba9a@fwd.pulver.com Their Tag Our tag: as0cd63f08 Nov 11 17:25:51 DEBUG[19778] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '09263cbc3697bde26f5f1f1f51d6ba9a@fwd.pulver.com' Request 103: Found Nov 11 17:25:51 DEBUG[19778] chan_sip.c: SIP response 100 to standard invite Nov 11 17:25:51 DEBUG[19778] chan_sip.c: = Found Their Call ID: 09263cbc3697bde26f5f1f1f51d6ba9a@fwd.pulver.com Their Tag Our tag: as0cd63f08 Nov 11 17:25:51 DEBUG[19778] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '09263cbc3697bde26f5f1f1f51d6ba9a@fwd.pulver.com' Request 103: Found Nov 11 17:25:51 DEBUG[19778] chan_sip.c: SIP response 180 to standard invite Nov 11 17:25:51 VERBOSE[19784] logger.c: -- SIP/fwd-0d24 is ringing Nov 11 17:25:51 DEBUG[19784] channel.c: Driver for channel 'SIP/ext2006-21ca' does not support indication 3, emulating it Nov 11 17:25:51 DEBUG[19784] channel.c: Set channel SIP/ext2006-21ca to write format slin Nov 11 17:25:51 DEBUG[19784] channel.c: Scheduling timer at 160 sample intervals Nov 11 17:25:51 DEBUG[19775] chan_sip.c: Checking device state for peer fwd Nov 11 17:25:51 DEBUG[19775] devicestate.c: Changing state for SIP/fwd - state 6 (Ringing) Nov 11 17:25:51 DEBUG[19787] app_queue.c: Device 'SIP/fwd' changed to state '6' (Ringing) Nov 11 17:25:51 DEBUG[19784] channel.c: Generator got voice, switching to phase locked mode Nov 11 17:25:51 DEBUG[19784] channel.c: Scheduling timer at 0 sample intervals Nov 11 17:25:51 DEBUG[19784] rtp.c: Difference is 1120, ms is 160 Nov 11 17:25:52 DEBUG[19784] rtp.c: Got RTCP report of 92 bytes Nov 11 17:25:58 DEBUG[19778] chan_sip.c: = Found Their Call ID: 09263cbc3697bde26f5f1f1f51d6ba9a@fwd.pulver.com Their Tag as40697c62 Our tag: as0cd63f08 Nov 11 17:25:58 DEBUG[19778] chan_sip.c: Acked pending invite 103 Nov 11 17:25:58 DEBUG[19778] chan_sip.c: Stopping retransmission on '09263cbc3697bde26f5f1f1f51d6ba9a@fwd.pulver.com' of Request 103: Match Found Nov 11 17:25:58 DEBUG[19778] chan_sip.c: SIP response 200 to standard invite Nov 11 17:25:58 DEBUG[19778] chan_sip.c: build_route: Record-Route hop: Nov 11 17:25:58 VERBOSE[19784] logger.c: -- SIP/fwd-0d24 answered SIP/ext2006-21ca Nov 11 17:25:58 DEBUG[19784] channel.c: Set channel SIP/ext2006-21ca to write format ulaw Nov 11 17:25:58 DEBUG[19784] channel.c: Scheduling timer at 0 sample intervals Nov 11 17:25:58 DEBUG[19784] channel.c: Set channel SIP/ext2006-21ca to read format ulaw Nov 11 17:25:58 DEBUG[19784] channel.c: Set channel SIP/fwd-0d24 to write format ulaw Nov 11 17:25:58 DEBUG[19784] channel.c: Set channel SIP/fwd-0d24 to read format ulaw Nov 11 17:25:58 DEBUG[19784] channel.c: Set channel SIP/ext2006-21ca to write format ulaw Nov 11 17:25:58 VERBOSE[19784] logger.c: -- Attempting native bridge of SIP/ext2006-21ca and SIP/fwd-0d24 Nov 11 17:25:58 DEBUG[19775] chan_sip.c: Checking device state for peer fwd Nov 11 17:25:58 DEBUG[19775] devicestate.c: Changing state for SIP/fwd - state 2 (In use) Nov 11 17:25:58 DEBUG[19788] app_queue.c: Device 'SIP/fwd' changed to state '2' (In use) Nov 11 17:25:58 DEBUG[19784] rtp.c: Ooh, format changed from unknown to ulaw Nov 11 17:26:02 DEBUG[19784] rtp.c: Got RTCP report of 92 bytes Nov 11 17:26:02 DEBUG[19778] chan_sip.c: = No match Their Call ID: 09263cbc3697bde26f5f1f1f51d6ba9a@fwd.pulver.com Their Tag as40697c62 Our tag: as0cd63f08 Nov 11 17:26:02 DEBUG[19778] chan_sip.c: = No match Their Call ID: 6fd2f1a7-b3533c71-d0c76fd0@192.168.254.252 Their Tag 276F381B-6C2375CA Our tag: as72b8cfb8 Nov 11 17:26:02 DEBUG[19778] chan_sip.c: = No match Their Call ID: 783c5f2822890bd01036fed017900b74@192.168.254.250 Their Tag cb2000b247d89723001a836145f3b053.3cdb Our tag: as7e760e73 Nov 11 17:26:02 DEBUG[19778] chan_sip.c: = No match Their Call ID: 59122c13379e0f6918f7d2e2050cc3c4@192.168.254.250 Their Tag b11cb9bb270104b49a99a995b8c68544.6166 Our tag: as48b07ddd Nov 11 17:26:02 DEBUG[19778] chan_sip.c: = No match Their Call ID: 79d9cf5557cc3d1842b03e58795c8201@192.168.254.250 Their Tag 21a483426c2cd5d9b85bffe6bba40a2e.157f Our tag: as4987399d Nov 11 17:26:02 DEBUG[19778] acl.c: ##### Testing 192.168.254.252 with 192.168.254.0 Nov 11 17:26:02 DEBUG[19778] chan_sip.c: Allocating new SIP dialog for e8bc8d8d-b2389077-5dd84f06@192.168.254.252 - SUBSCRIBE (No RTP) Nov 11 17:26:02 DEBUG[19778] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Nov 11 17:26:03 DEBUG[19778] chan_sip.c: = Found Their Call ID: e8bc8d8d-b2389077-5dd84f06@192.168.254.252 Their Tag 443BA41-554B8420 Our tag: as07fbc871 Nov 11 17:26:03 DEBUG[19778] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Nov 11 17:26:05 DEBUG[19784] rtp.c: Sending dtmf: 42 (*), at 192.168.254.252 Nov 11 17:26:05 DEBUG[19784] rtp.c: Sending dtmf: 49 (1), at 192.168.254.252 Nov 11 17:26:08 DEBUG[19778] chan_sip.c: Auto destroying call '79d9cf5557cc3d1842b03e58795c8201@192.168.254.250' Nov 11 17:26:08 DEBUG[19778] chan_sip.c: Auto destroying call '783c5f2822890bd01036fed017900b74@192.168.254.250' Nov 11 17:26:08 DEBUG[19778] chan_sip.c: Auto destroying call '59122c13379e0f6918f7d2e2050cc3c4@192.168.254.250' Nov 11 17:26:09 DEBUG[19784] rtp.c: Sending dtmf: 42 (*), at 192.168.254.252 Nov 11 17:26:09 DEBUG[19784] rtp.c: Sending dtmf: 49 (1), at 192.168.254.252 Nov 11 17:26:12 DEBUG[19784] rtp.c: Got RTCP report of 92 bytes Nov 11 17:26:13 DEBUG[19784] rtp.c: Sending dtmf: 42 (*), at 192.168.254.252 Nov 11 17:26:13 DEBUG[19784] rtp.c: Sending dtmf: 49 (1), at 192.168.254.252 Nov 11 17:26:17 DEBUG[19784] rtp.c: Sending dtmf: 42 (*), at 192.168.254.252 Nov 11 17:26:17 DEBUG[19784] rtp.c: Ignore potential DTMF echo from '69.90.168.13' Nov 11 17:26:17 DEBUG[19784] rtp.c: Sending dtmf: 49 (1), at 192.168.254.252 Nov 11 17:26:21 DEBUG[19784] rtp.c: Sending dtmf: 42 (*), at 192.168.254.252 Nov 11 17:26:21 DEBUG[19784] rtp.c: Ignore potential DTMF echo from '69.90.168.13' Nov 11 17:26:21 DEBUG[19784] rtp.c: Sending dtmf: 49 (1), at 192.168.254.252 Nov 11 17:26:22 DEBUG[19784] rtp.c: Got RTCP report of 92 bytes Nov 11 17:26:25 DEBUG[19784] rtp.c: Sending dtmf: 42 (*), at 192.168.254.252 Nov 11 17:26:25 DEBUG[19784] rtp.c: Ignore potential DTMF echo from '69.90.168.13' Nov 11 17:26:25 DEBUG[19784] rtp.c: Sending dtmf: 49 (1), at 192.168.254.252 Nov 11 17:26:26 DEBUG[19780] chan_iax2.c: Allocate call number Nov 11 17:26:26 DEBUG[19780] chan_iax2.c: Registration created on call 2