[Nov 25 09:10:11] VERBOSE[1958] asterisk.c: Remote UNIX connection [Nov 25 09:10:42] Asterisk 13.0.1 built by root @ ip-10-0-0-10.localdomain on a x86_64 running Linux on 2014-11-21 11:56:40 UTC [Nov 25 09:10:42] DEBUG[2482] config.c: Parsing /etc/asterisk/logger.conf [Nov 25 09:10:42] VERBOSE[2482] config.c: Parsing '/etc/asterisk/logger.conf': Found [Nov 25 09:10:42] VERBOSE[2482] logger.c: Asterisk Queue Logger restarted [Nov 25 09:15:40] DEBUG[2581] manager.c: Running action 'Login' [Nov 25 09:15:40] VERBOSE[2581] manager.c: Manager 'asteriskcalvoz' logged on from 127.0.0.1 [Nov 25 09:15:40] DEBUG[2581] manager.c: Running action 'Originate' [Nov 25 09:15:40] VERBOSE[2584] dial.c: Called 881000ClicktoCall@a2billing-did2/n [Nov 25 09:15:40] DEBUG[2585][C-00000000] pbx.c: Launching 'AGI' [Nov 25 09:15:40] VERBOSE[2585][C-00000000] pbx.c: Executing [881000ClicktoCall@a2billing-did2:1] AGI("Local/881000ClicktoCall@a2billing-did2-00000000;2", "a2billing.php,3,did") in new stack [Nov 25 09:15:40] VERBOSE[2585][C-00000000] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/a2billing.php [Nov 25 09:15:40] DEBUG[2585][C-00000000] pbx.c: Result of 'IDCONF' is NULL [Nov 25 09:15:41] DEBUG[2585][C-00000000] pbx.c: Result of 'A2B_CUSTOM1' is NULL [Nov 25 09:15:41] DEBUG[2585][C-00000000] pbx.c: Result of 'A2B_CUSTOM2' is NULL [Nov 25 09:15:41] VERBOSE[2585][C-00000000] res_agi.c: AGI Script Executing Application: (DIAL) Options: (SIP/voip2cNT2P1/99901553484147771,40,HRrL(4290000:61000:30000)) [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Asked to create a SIP channel with formats: (slin) [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Allocating new SIP dialog for 30fbe5b428245ea646cc428a53266266@10.0.0.10:5060 - INVITE (No RTP) [Nov 25 09:15:41] DEBUG[2585][C-00000000] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fcaa400e2e8' [Nov 25 09:15:41] DEBUG[2585][C-00000000] res_rtp_asterisk.c: Allocated port 11384 for RTP instance '0x7fcaa400e2e8' [Nov 25 09:15:41] DEBUG[2585][C-00000000] rtp_engine.c: RTP instance '0x7fcaa400e2e8' is setup and ready to go [Nov 25 09:15:41] DEBUG[2585][C-00000000] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fcaa400e2e8' [Nov 25 09:15:41] VERBOSE[2585][C-00000000] netsock2.c: Using SIP RTP CoS mark 5 [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Setting NAT on RTP to On [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Nov 25 09:15:41] DEBUG[2585][C-00000000] acl.c: For destination '216.53.4.1', our source address is '10.0.0.10'. [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Target address 216.53.4.1:5060 is not local, substituting externaddr [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Setting AST_TRANSPORT_UDP with address 154.232.196.179:5060 [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Setting NAT on RTP to On [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: SIP call-id changed from '30fbe5b428245ea646cc428a53266266@10.0.0.10:5060' to '27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060' [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: *** Our native formats are (ulaw) [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: *** Joint capabilities are (nothing) [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: *** Our capabilities are (ulaw) [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: *** Our preferred formats from the incoming channel are (slin) [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: This channel will not be able to handle video. [Nov 25 09:15:41] DEBUG[2585][C-00000000] channel_internal_api.c: Channel Call ID changing from [C-00000000] to [C-00000000] [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Outgoing Call for 99901553484147771 [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Updating call counter for outgoing call [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: ** Our capability: (ulaw) Video flag: False Text flag: False [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: ** Our prefcodec: (slin) [Nov 25 09:15:41] VERBOSE[2585][C-00000000] chan_sip.c: Audio is at 11384 [Nov 25 09:15:41] VERBOSE[2585][C-00000000] chan_sip.c: Adding codec ulaw to SDP [Nov 25 09:15:41] VERBOSE[2585][C-00000000] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: -- Done with adding codecs to SDP [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Initializing initreq for method INVITE - callid 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 0 [ 52]: INVITE sip:99901553484147771@216.53.4.1:5060 SIP/2.0 [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK789a8bf9;rport [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 3 [ 52]: From: ;tag=as4da15014 [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 4 [ 43]: To: [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 5 [ 45]: Contact: [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 6 [ 61]: Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 8 [ 29]: User-Agent: NGN voip2c Telecom [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 9 [ 35]: Date: Tue, 25 Nov 2014 11:15:41 GMT [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 10 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Nov 25 09:15:41] VERBOSE[2585][C-00000000] chan_sip.c: Reliably Transmitting (NAT) to 216.53.4.1:5060: INVITE sip:99901553484147771@216.53.4.1:5060 SIP/2.0 Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK789a8bf9;rport Max-Forwards: 70 From: ;tag=as4da15014 To: Contact: Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 CSeq: 102 INVITE User-Agent: NGN voip2c Telecom Date: Tue, 25 Nov 2014 11:15:41 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 255 v=0 o=root 1386945157 1386945157 IN IP4 154.232.196.179 s=Asterisk PBX 13.0.1 c=IN IP4 154.232.196.179 t=0 0 m=audio 11384 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #410 [Nov 25 09:15:41] DEBUG[2585][C-00000000] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 216.53.4.1:5060 [Nov 25 09:15:41] VERBOSE[2585][C-00000000] app_dial.c: Called SIP/voip2cNT2P1/99901553484147771 [Nov 25 09:15:41] DEBUG[1964] devicestate.c: No provider found, checking channel drivers for Local - 881000ClicktoCall@a2billing-did2 [Nov 25 09:15:41] DEBUG[1964] devicestate.c: Changing state for Local/881000ClicktoCall@a2billing-did2 - state 2 (In use) [Nov 25 09:15:41] DEBUG[2457] app_queue.c: Device 'Local/881000ClicktoCall@a2billing-did2' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 25 09:15:41] VERBOSE[2584] dial.c: Local/881000ClicktoCall@a2billing-did2-00000000;1 is ringing [Nov 25 09:15:41] VERBOSE[2428] chan_sip.c: <--- SIP read from UDP:216.53.4.1:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK789a8bf9;received=154.232.196.179;rport=5060 From: ;tag=as4da15014 To: Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 Contact: CSeq: 102 INVITE Server: sbc_5 Content-Length: 0 <-------------> [Nov 25 09:15:41] DEBUG[2428] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Nov 25 09:15:41] DEBUG[2428] chan_sip.c: Header 1 [ 94]: Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK789a8bf9;received=154.232.196.179;rport=5060 [Nov 25 09:15:41] DEBUG[2428] chan_sip.c: Header 2 [ 52]: From: ;tag=as4da15014 [Nov 25 09:15:41] DEBUG[2428] chan_sip.c: Header 3 [ 43]: To: [Nov 25 09:15:41] DEBUG[2428] chan_sip.c: Header 4 [ 61]: Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:15:41] DEBUG[2428] chan_sip.c: Header 5 [ 30]: Contact: [Nov 25 09:15:41] DEBUG[2428] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Nov 25 09:15:41] DEBUG[2428] chan_sip.c: Header 7 [ 13]: Server: sbc_5 [Nov 25 09:15:41] DEBUG[2428] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Nov 25 09:15:41] VERBOSE[2428] chan_sip.c: --- (9 headers 0 lines) --- [Nov 25 09:15:41] DEBUG[2428] chan_sip.c: = Looking for Call ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 (Checking To) --From tag as4da15014 --To-tag [Nov 25 09:15:41] DEBUG[2428][C-00000000] chan_sip.c: *** SIP TIMER: Cancelling retransmission #410 - INVITE (got response) [Nov 25 09:15:41] DEBUG[2428][C-00000000] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060' Request 102: Found [Nov 25 09:15:41] DEBUG[2428][C-00000000] chan_sip.c: SIP response 100 to standard invite [Nov 25 09:15:44] VERBOSE[2428] chan_sip.c: <--- SIP read from UDP:216.53.4.1:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK789a8bf9;received=154.232.196.179;rport=5060 From: ;tag=as4da15014 To: ;tag=sbcsipuas_1_C58173_20141125061541088_b59sb08 Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 Contact: CSeq: 102 INVITE Server: sbc_5 Content-Type: application/sdp Content-Length: 160 v=0 o=SBCSIPUAS 1714278191 1 IN IP4 169.132.138.41 s=SBCSIPUAS SIP STACK v1.0 c=IN IP4 169.132.138.41 t=0 0 m=audio 23744 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Header 0 [ 28]: SIP/2.0 183 Session Progress [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Header 1 [ 94]: Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK789a8bf9;received=154.232.196.179;rport=5060 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Header 2 [ 52]: From: ;tag=as4da15014 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Header 3 [ 92]: To: ;tag=sbcsipuas_1_C58173_20141125061541088_b59sb08 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Header 4 [ 61]: Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Header 5 [ 30]: Contact: [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Header 7 [ 13]: Server: sbc_5 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Header 8 [ 29]: Content-Type: application/sdp [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Header 9 [ 19]: Content-Length: 160 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Header 10 [ 0]: [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Body 0 [ 3]: v=0 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Body 1 [ 46]: o=SBCSIPUAS 1714278191 1 IN IP4 169.132.138.41 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Body 2 [ 26]: s=SBCSIPUAS SIP STACK v1.0 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Body 3 [ 23]: c=IN IP4 169.132.138.41 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Body 5 [ 23]: m=audio 23744 RTP/AVP 0 [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 25 09:15:44] VERBOSE[2428] chan_sip.c: --- (10 headers 7 lines) --- [Nov 25 09:15:44] DEBUG[2428] chan_sip.c: = Looking for Call ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 (Checking To) --From tag as4da15014 --To-tag sbcsipuas_1_C58173_20141125061541088_b59sb08 [Nov 25 09:15:44] DEBUG[2428][C-00000000] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060' Request 102: Found [Nov 25 09:15:44] DEBUG[2428][C-00000000] chan_sip.c: SIP response 183 to standard invite [Nov 25 09:15:44] VERBOSE[2428][C-00000000] sip/route.c: sip_route_dump: route/path hop: [Nov 25 09:15:44] DEBUG[2428][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Nov 25 09:15:44] DEBUG[2428][C-00000000] chan_sip.c: Processing session-level SDP o=SBCSIPUAS 1714278191 1 IN IP4 169.132.138.41... OK. [Nov 25 09:15:44] DEBUG[2428][C-00000000] chan_sip.c: Processing session-level SDP s=SBCSIPUAS SIP STACK v1.0... UNSUPPORTED OR FAILED. [Nov 25 09:15:44] DEBUG[2428][C-00000000] netsock2.c: Splitting '169.132.138.41' into... [Nov 25 09:15:44] DEBUG[2428][C-00000000] netsock2.c: ...host '169.132.138.41' and port ''. [Nov 25 09:15:44] DEBUG[2428][C-00000000] chan_sip.c: Processing session-level SDP c=IN IP4 169.132.138.41... OK. [Nov 25 09:15:44] DEBUG[2428][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Nov 25 09:15:44] VERBOSE[2428][C-00000000] chan_sip.c: Found RTP audio format 0 [Nov 25 09:15:44] DEBUG[2428][C-00000000] rtp_engine.c: Setting payload 0 (0x7fcadc008f58) based on m type on 0x7fca71cb1820 [Nov 25 09:15:44] VERBOSE[2428][C-00000000] chan_sip.c: Found audio description format PCMU for ID 0 [Nov 25 09:15:44] DEBUG[2428][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Nov 25 09:15:44] VERBOSE[2428][C-00000000] chan_sip.c: Capabilities: us - (ulaw), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw) [Nov 25 09:15:44] VERBOSE[2428][C-00000000] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing) [Nov 25 09:15:44] DEBUG[2428][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fcaa400e2e8' [Nov 25 09:15:44] VERBOSE[2428][C-00000000] chan_sip.c: Peer audio RTP is at port 169.132.138.41:23744 [Nov 25 09:15:44] DEBUG[2428][C-00000000] rtp_engine.c: Copying payload 0 (0x7fcadc008fd8) from 0x7fca71cb1820 to 0x7fcaa400e428 [Nov 25 09:15:44] DEBUG[2428][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fcaa400e2e8' [Nov 25 09:15:44] DEBUG[2428][C-00000000] chan_sip.c: We're settling with these formats: (ulaw) [Nov 25 09:15:44] DEBUG[2428][C-00000000] chan_sip.c: We have an owner, now see if we need to change this call [Nov 25 09:15:44] DEBUG[2428][C-00000000] chan_sip.c: Setting native formats after processing SDP. peer joint formats (ulaw), old nativeformats (ulaw) [Nov 25 09:15:44] VERBOSE[2585][C-00000000] app_dial.c: SIP/voip2cNT2P1-00000000 is making progress passing it to Local/881000ClicktoCall@a2billing-did2-00000000;2 [Nov 25 09:15:44] DEBUG[2585][C-00000000] res_rtp_asterisk.c: 0x7fcaa400ef60 -- Probation learning mode pass with source address 169.132.138.41:23744 [Nov 25 09:15:49] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:15:49] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:15:49] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:15:49] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:15:49] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:15:49] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:15:49] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:15:49] DEBUG[2448] netsock2.c: Splitting '169.132.138.41:23745' into... [Nov 25 09:15:49] DEBUG[2448] netsock2.c: ...host '169.132.138.41' and port '23745'. [Nov 25 09:15:52] VERBOSE[2428] chan_sip.c: <--- SIP read from UDP:216.53.4.1:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK789a8bf9;received=154.232.196.179;rport=5060 From: ;tag=as4da15014 To: ;tag=sbcsipuas_1_C58173_20141125061541088_b59sb08 Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 Contact: CSeq: 102 INVITE Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,NOTIFY,INFO Server: sbc_5 Content-Type: application/sdp Content-Length: 160 v=0 o=SBCSIPUAS 1714278191 1 IN IP4 169.132.138.41 s=SBCSIPUAS SIP STACK v1.0 c=IN IP4 169.132.138.41 t=0 0 m=audio 23744 RTP/AVP 0 a=rtpmap:0 PCMU/8000 <-------------> [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 1 [ 94]: Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK789a8bf9;received=154.232.196.179;rport=5060 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 2 [ 52]: From: ;tag=as4da15014 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 3 [ 92]: To: ;tag=sbcsipuas_1_C58173_20141125061541088_b59sb08 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 4 [ 61]: Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 5 [ 30]: Contact: [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 7 [ 48]: Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,NOTIFY,INFO [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 8 [ 13]: Server: sbc_5 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 10 [ 19]: Content-Length: 160 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Header 11 [ 0]: [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Body 0 [ 3]: v=0 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Body 1 [ 46]: o=SBCSIPUAS 1714278191 1 IN IP4 169.132.138.41 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Body 2 [ 26]: s=SBCSIPUAS SIP STACK v1.0 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Body 3 [ 23]: c=IN IP4 169.132.138.41 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Body 5 [ 23]: m=audio 23744 RTP/AVP 0 [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 25 09:15:52] VERBOSE[2428] chan_sip.c: --- (11 headers 7 lines) --- [Nov 25 09:15:52] DEBUG[2428] chan_sip.c: = Looking for Call ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 (Checking To) --From tag as4da15014 --To-tag sbcsipuas_1_C58173_20141125061541088_b59sb08 [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Acked pending invite 102 [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Stopping retransmission on '27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060' of Request 102: Match Found [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: SIP response 200 to standard invite [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Processing session-level SDP o=SBCSIPUAS 1714278191 1 IN IP4 169.132.138.41... OK. [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Processing session-level SDP s=SBCSIPUAS SIP STACK v1.0... UNSUPPORTED OR FAILED. [Nov 25 09:15:52] DEBUG[2428][C-00000000] netsock2.c: Splitting '169.132.138.41' into... [Nov 25 09:15:52] DEBUG[2428][C-00000000] netsock2.c: ...host '169.132.138.41' and port ''. [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Processing session-level SDP c=IN IP4 169.132.138.41... OK. [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Nov 25 09:15:52] VERBOSE[2428][C-00000000] chan_sip.c: Found RTP audio format 0 [Nov 25 09:15:52] DEBUG[2428][C-00000000] rtp_engine.c: Setting payload 0 (0x7fcadc00ae78) based on m type on 0x7fca71cb1820 [Nov 25 09:15:52] VERBOSE[2428][C-00000000] chan_sip.c: Found audio description format PCMU for ID 0 [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Nov 25 09:15:52] VERBOSE[2428][C-00000000] chan_sip.c: Capabilities: us - (ulaw), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw) [Nov 25 09:15:52] VERBOSE[2428][C-00000000] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing) [Nov 25 09:15:52] DEBUG[2428][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fcaa400e2e8' [Nov 25 09:15:52] VERBOSE[2428][C-00000000] chan_sip.c: Peer audio RTP is at port 169.132.138.41:23744 [Nov 25 09:15:52] DEBUG[2428][C-00000000] rtp_engine.c: Copying payload 0 (0x7fcadc009868) from 0x7fca71cb1820 to 0x7fcaa400e428 [Nov 25 09:15:52] DEBUG[2428][C-00000000] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fcaa400e2e8' [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: We're settling with these formats: (ulaw) [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: We have an owner, now see if we need to change this call [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Setting native formats after processing SDP. peer joint formats (ulaw), old nativeformats (ulaw) [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Updating call counter for outgoing call [Nov 25 09:15:52] VERBOSE[2428][C-00000000] sip/route.c: sip_route_dump: route/path hop: [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Strict routing enforced for session 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:15:52] VERBOSE[2428][C-00000000] chan_sip.c: Transmitting (NAT) to 216.53.4.1:5060: ACK sip:216.53.4.1:5060 SIP/2.0 Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK4ba3e167;rport Max-Forwards: 70 From: ;tag=as4da15014 To: ;tag=sbcsipuas_1_C58173_20141125061541088_b59sb08 Contact: Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 CSeq: 102 ACK User-Agent: NGN voip2c Telecom Content-Length: 0 --- [Nov 25 09:15:52] DEBUG[2428][C-00000000] chan_sip.c: Trying to put 'ACK sip:216' onto UDP socket destined for 216.53.4.1:5060 [Nov 25 09:15:52] VERBOSE[2585][C-00000000] app_dial.c: SIP/voip2cNT2P1-00000000 answered Local/881000ClicktoCall@a2billing-did2-00000000;2 [Nov 25 09:15:52] DEBUG[2585][C-00000000] channel.c: Set channel SIP/voip2cNT2P1-00000000 to read format slin [Nov 25 09:15:52] DEBUG[2585][C-00000000] channel.c: Set channel SIP/voip2cNT2P1-00000000 to write format slin [Nov 25 09:15:52] DEBUG[2585][C-00000000] features.c: Removing dialed interfaces datastore on SIP/voip2cNT2P1-00000000 since we're bridging [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Putting interval hook 0x7fcaa401ac70 with interval 4290000 in the heap on features 0x7fca70bbbfb0 [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Putting interval hook 0x7fcaa401b0c0 with interval 4229000 in the heap on features 0x7fca70bbbfb0 [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Putting interval hook 0x7fcaa400b1c0 with interval 4290000 in the heap on features 0x7fcaa4006e00 [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge_native_rtp.c: Bridge 'f77752b3-f867-4059-a83a-971b1b263641' can not use native RTP bridge as two channels are required [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Chose bridge technology simple_bridge [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: calling simple_bridge technology constructor [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: calling simple_bridge technology start [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge_channel.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: 0x7fcaa4023128(Local/881000ClicktoCall@a2billing-did2-00000000;2) is joining [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge_channel.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: pushing 0x7fcaa4023128(Local/881000ClicktoCall@a2billing-did2-00000000;2) [Nov 25 09:15:52] DEBUG[2590][C-00000000] bridge_channel.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: 0x7fcaa4022df8(SIP/voip2cNT2P1-00000000) is joining [Nov 25 09:15:52] VERBOSE[2585][C-00000000] bridge_channel.c: Channel Local/881000ClicktoCall@a2billing-did2-00000000;2 joined 'simple_bridge' basic-bridge [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge_native_rtp.c: Bridge 'f77752b3-f867-4059-a83a-971b1b263641' can not use native RTP bridge as two channels are required [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Chose bridge technology simple_bridge [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641 is already using the new technology. [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641 is happy that channel Local/881000ClicktoCall@a2billing-did2-00000000;2 already has read format slin [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641 is happy that channel Local/881000ClicktoCall@a2billing-did2-00000000;2 already has write format slin [Nov 25 09:15:52] DEBUG[2585][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: 0x7fcaa4023128(Local/881000ClicktoCall@a2billing-did2-00000000;2) is joining simple_bridge technology [Nov 25 09:15:52] DEBUG[1964] devicestate.c: No provider found, checking channel drivers for SIP - voip2cNT2P1 [Nov 25 09:15:52] DEBUG[1964] chan_sip.c: Checking device state for peer voip2cNT2P1 [Nov 25 09:15:52] DEBUG[1964] devicestate.c: Changing state for SIP/voip2cNT2P1 - state 1 (Not in use) [Nov 25 09:15:52] DEBUG[1964] devicestate.c: No provider found, checking channel drivers for Local - 881000ClicktoCall@a2billing-did2 [Nov 25 09:15:52] DEBUG[1964] devicestate.c: Changing state for Local/881000ClicktoCall@a2billing-did2 - state 2 (In use) [Nov 25 09:15:52] VERBOSE[2584] dial.c: Local/881000ClicktoCall@a2billing-did2-00000000;1 answered [Nov 25 09:15:52] DEBUG[1964] devicestate.c: No provider found, checking channel drivers for Local - 881000ClicktoCall@a2billing-did2 [Nov 25 09:15:52] DEBUG[1964] devicestate.c: Changing state for Local/881000ClicktoCall@a2billing-did2 - state 2 (In use) [Nov 25 09:15:52] DEBUG[2584][C-00000001] pbx.c: Launching 'AGI' [Nov 25 09:15:52] VERBOSE[2584][C-00000001] pbx.c: Executing [3438181636@a2billing-callback:1] AGI("Local/881000ClicktoCall@a2billing-did2-00000000;1", "a2billing.php,6,callback") in new stack [Nov 25 09:15:52] VERBOSE[2584][C-00000001] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/a2billing.php [Nov 25 09:15:52] DEBUG[2457] app_queue.c: Device 'SIP/voip2cNT2P1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 25 09:15:52] DEBUG[2457] app_queue.c: Device 'Local/881000ClicktoCall@a2billing-did2' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 25 09:15:52] DEBUG[2457] app_queue.c: Device 'Local/881000ClicktoCall@a2billing-did2' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.0 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.0 Extension: 881000ClicktoCall Application: AppDial2 AppData: (Outgoing Line) [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.0 Variable: LEG Value: 7341621469 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.0 Variable: CBID Value: 39461-eho76mu [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.0 Variable: CALLING Value: 3438181636 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.0 Variable: CALLED Value: 7341621469 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: NewAccountCode Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.0 OldAccountCode: [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.0 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: CALLED Value: 7341621469 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: CALLING Value: 3438181636 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: CBID Value: 39461-eho76mu [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: LEG Value: 7341621469 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: NewAccountCode Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 OldAccountCode: [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: LocalBridge Privilege: call,all LocalOneChannel: Local/881000ClicktoCall@a2billing-did2-00000000;1 LocalOneChannelState: 0 LocalOneChannelStateDesc: Down LocalOneCallerIDNum: 3438181636 LocalOneCallerIDName: LocalOneConnectedLineNum: LocalOneConnectedLineName: LocalOneAccountCode: 7341621469 LocalOneContext: a2billing-did2 LocalOneExten: 881000ClicktoCall LocalOnePriority: 1 LocalOneUniqueid: 1416914140.0 LocalTwoChannel: Local/881000ClicktoCall@a2billing-did2-00000000;2 LocalTwoChannelState: 4 LocalTwoChannelStateDesc: Ring LocalTwoCallerIDNum: 3438181636 LocalTwoCallerIDName: LocalTwoConnectedLineNum: 3438181636 LocalTwoConnectedLineName: LocalTwoAccountCode: 7341621469 LocalTwoContext: a2billing-did2 LocalTwoExten: 881000ClicktoCall LocalTwoPriority: 1 LocalTwoUniqueid: 1416914140.1 Context: a2billing-did2 Exten: 881000ClicktoCall LocalOptimization: No [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all DestChannel: Local/881000ClicktoCall@a2billing-did2-00000000;1 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 3438181636 DestCallerIDName: DestConnectedLineNum: DestConnectedLineName: DestAccountCode: 7341621469 DestContext: a2billing-did2 DestExten: 881000ClicktoCall DestPriority: 1 DestUniqueid: 1416914140.0 DialString: 881000ClicktoCall@a2billing-did2/n [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Extension: 881000ClicktoCall Application: AGI AppData: a2billing.php,3,did [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: DIALSTATUS Value: [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: DIALEDPEERNUMBER Value: [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: DIALEDPEERNAME Value: [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: ANSWEREDTIME Value: [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: DIALEDTIME Value: [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing Exten: s Priority: 1 Uniqueid: 1416914141.2 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing Exten: s Priority: 1 Uniqueid: 1416914141.2 Variable: SIPCALLID Value: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 Variable: DIALEDPEERNUMBER Value: voip2cNT2P1/99901553484147771 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914141.2 Extension: 881000ClicktoCall Application: AppDial AppData: (Outgoing Line) [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914141.2 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: NewAccountCode Privilege: call,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914141.2 OldAccountCode: [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 DestChannel: SIP/voip2cNT2P1-00000000 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 881000ClicktoCall DestCallerIDName: DestConnectedLineNum: 3438181636 DestConnectedLineName: DestAccountCode: 7341621469 DestContext: a2billing DestExten: 881000ClicktoCall DestPriority: 1 DestUniqueid: 1416914141.2 DialString: voip2cNT2P1/99901553484147771 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.0 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/881000ClicktoCall@a2billing-did2 State: INUSE [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914141.2 To: 169.132.138.41:23745 From: 10.0.0.10:0 SSRC: 0x3a4793e2 PT: 201(RR) ReportCount: 1 Report0SourceSSRC: 0x09cf6374 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 145 Report0SequenceNumberCycles: 0 Report0IAJitter: 2 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914141.2 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: DIALSTATUS Value: ANSWER [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: DIALEDPEERNAME Value: SIP/voip2cNT2P1-00000000 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: DIALEDPEERNUMBER Value: voip2cNT2P1/99901553484147771 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 4 ChannelStateDesc: Ring CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 DestChannel: SIP/voip2cNT2P1-00000000 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 881000ClicktoCall DestCallerIDName: DestConnectedLineNum: 3438181636 DestConnectedLineName: DestAccountCode: 7341621469 DestContext: a2billing DestExten: DestPriority: 1 DestUniqueid: 1416914141.2 DialStatus: ANSWER [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeCreate Privilege: call,all BridgeUniqueid: f77752b3-f867-4059-a83a-971b1b263641 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: f77752b3-f867-4059-a83a-971b1b263641 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: SIP/voip2cNT2P1 State: NOT_INUSE [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.0 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all DestChannel: Local/881000ClicktoCall@a2billing-did2-00000000;1 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 3438181636 DestCallerIDName: DestConnectedLineNum: 3438181636 DestConnectedLineName: DestAccountCode: 7341621469 DestContext: a2billing-did2 DestExten: 881000ClicktoCall DestPriority: 1 DestUniqueid: 1416914140.0 DialStatus: ANSWER [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Extension: 3438181636 Application: AGI AppData: a2billing.php,6,callback [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/881000ClicktoCall@a2billing-did2 State: INUSE [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/881000ClicktoCall@a2billing-did2 State: INUSE [Nov 25 09:15:52] DEBUG[2590][C-00000000] bridge_channel.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: pushing 0x7fcaa4022df8(SIP/voip2cNT2P1-00000000) [Nov 25 09:15:52] VERBOSE[2590][C-00000000] bridge_channel.c: Channel SIP/voip2cNT2P1-00000000 joined 'simple_bridge' basic-bridge [Nov 25 09:15:52] DEBUG[2590][C-00000000] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 25 09:15:52] DEBUG[2590][C-00000000] bridge_native_rtp.c: Bridge 'f77752b3-f867-4059-a83a-971b1b263641' can not use native RTP bridge as it was forbidden while getting details [Nov 25 09:15:52] DEBUG[2590][C-00000000] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 25 09:15:52] DEBUG[2590][C-00000000] bridge.c: Bridge technology softmix does not have any capabilities we want. [Nov 25 09:15:52] DEBUG[2590][C-00000000] bridge.c: Chose bridge technology simple_bridge [Nov 25 09:15:52] DEBUG[2590][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641 is already using the new technology. [Nov 25 09:15:52] DEBUG[2590][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641 is happy that channel SIP/voip2cNT2P1-00000000 already has read format slin [Nov 25 09:15:52] DEBUG[2590][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641 is happy that channel SIP/voip2cNT2P1-00000000 already has write format slin [Nov 25 09:15:52] DEBUG[2590][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: 0x7fcaa4022df8(SIP/voip2cNT2P1-00000000) is joining simple_bridge technology [Nov 25 09:15:52] DEBUG[2590][C-00000000] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Nov 25 09:15:52] DEBUG[2590][C-00000000] res_rtp_asterisk.c: 0x7fcaa400ef60 -- Probation learning mode pass with source address 169.132.138.41:23744 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 Extension: Application: AppDial AppData: (Outgoing Line) [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: f77752b3-f867-4059-a83a-971b1b263641 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 2 Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: BRIDGEPEER Value: SIP/voip2cNT2P1-00000000 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: BRIDGEPVTCALLID Value: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:15:52] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 Variable: BRIDGEPEER Value: Local/881000ClicktoCall@a2billing-did2-00000000;2 [Nov 25 09:15:52] DEBUG[1965] cdr.c: Finalized CDR for SIP/voip2cNT2P1-00000000 - start 1416914141.017103 answer 1416914152.939741 end 1416914152.939802 dispo ANSWERED [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'IDCONF' is NULL [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:590 - uniqueid: - A2Billing AGI internal configuration: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:591 - uniqueid: - Array [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ( [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [callerid_] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [dialcommand_param_call_2did] => |70|HimL(3600000:61000:30000) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [description] => agi-config [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [asterisk_version] => 1_11 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [answer_call] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [play_audio] => 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [say_goodbye] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [play_menulanguage] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [force_language] => br [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [intro_prompt] => [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [min_credit_2call] => [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [min_duration_2bill] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [notenoughcredit_cardnumber] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [notenoughcredit_assign_newcardnumber_cid] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [use_dnid] => 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [no_auth_dnid] => Array [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ( [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [0] => 2400 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [1] => 2300 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [number_try] => 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [force_callplan_id] => [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [say_balance_after_auth] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [say_balance_after_call] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [say_rateinitial] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [say_timetocall] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [auto_setcallerid] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [force_callerid] => YES [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [cid_sanitize] => NO [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [cid_enable] => 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [cid_askpincode_ifnot_callerid] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [failover_lc_prefix] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [cid_auto_assign_card_to_cid] => 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [callerid_authentication_over_cardnumber] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [sip_iax_friends] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [sip_iax_pstn_direct_call_prefix] => 555 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [sip_iax_pstn_direct_call] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [ivr_voucher] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [ivr_voucher_prefix] => 8 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [jump_voucher_if_min_credit] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [dialcommand_param] => |37|HRrL(1800000) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [dialcommand_param_sipiax_friend] => |35|HL(3600000:61000:30000) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [switchdialcommand] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [failover_recursive_limit] => 4 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [maxtime_tocall_negatif_free_route] => 5400 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [send_reminder] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [record_call] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [monitor_formatfile] => gsm [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_force_currency] => [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [currency_association] => Array [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ( [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [0] => usd:dollars [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [1] => mxn:pesos [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [2] => eur:euros [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [3] => all:credit [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [local_dialing_addcountryprefix] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [max_call_call_2_did] => 3600 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [file_conf_enter_destination] => [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [conf_order_menulang] => en:fr:es [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [callback_bill_1stleg_ifcall_notconnected] => 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [international_prefixes] => Array [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ( [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [0] => 011 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [1] => 00 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [2] => 09 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [3] => 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [extracharge_did] => Array [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ( [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [0] => 1800 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [1] => 1900 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [extracharge_fee] => Array [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ( [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [0] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [1] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [extracharge_buyfee] => Array [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ( [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [0] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [1] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [maxtime_tounlimited_calls] => 5400 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [maxtime_tofree_calls] => 5400 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [callplan_deck_minute_threshold] => [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [disable_announcement_seconds] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [verbosity_level] => 4 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [logging_level] => 4 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [dial_balance_reservation] => 0.25 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [logger_enable] => 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [log_file] => /var/log/a2billing/a2billing.log [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [cid_auto_create_card_len] => 10 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [cid_auto_create_card] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [dialcommand_param_call_2did ] => |30|HL(3600000:61000:30000) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [currency_association_internal] => Array [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ( [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [usd] => dollars [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [mxn] => pesos [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [eur] => euros [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [all] => credit [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [file_conf_enter_menulang] => prepaid-menulang [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [ivr_voucher_prefixe] => 8 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [cheat_on_announcement_time] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [busy_timeout] => 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [lcr_mode] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:117 - uniqueid: - IDCONFIG : 6 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:118 - uniqueid: - MODE : callback [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:130 - uniqueid: - AGI Request: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: Array [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ( [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_request] => a2billing.php [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_channel] => Local/881000ClicktoCall@a2billing-did2-00000000;1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_language] => br [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_type] => Local [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_uniqueid] => 1416914140.0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_version] => 13.0.1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_callerid] => 3438181636 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_calleridname] => unknown [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_callingpres] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_callingani2] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_callington] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_callingtns] => 0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_dnid] => unknown [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_rdnis] => unknown [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_context] => a2billing-callback [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_extension] => 3438181636 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_priority] => 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_enhanced] => 0.0 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_accountcode] => 7341621469 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_threadid] => 140507452004096 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_arg_1] => 6 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [agi_arg_2] => callback [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: ) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:131 - uniqueid: - [INFO : A2Billing - v2.0.16] [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'A2B_CUSTOM1' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'A2B_CUSTOM2' is NULL [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:748 - uniqueid:1416914140.0 - get_agi_request_parameter = 3438181636 ; ; 1416914140.0 ; 7341621469 ; 3438181636 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1072 - uniqueid:1416914140.0 - [CALLBACK]:[MODE : CALLBACK] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1085 - uniqueid:1416914140.0 - [CALLBACK]:[NO ANSWER CALL] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:662 - uniqueid:1416914140.0 - FORCE LANGUAGE : br [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:672 - uniqueid:1416914140.0 - [SET CHANNEL(language) br] [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'CALLED' is '7341621469' [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'CALLING' is '3438181636' [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'MODE' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'TARIFF' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'CBID' is '39461-eho76mu' [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'LEG' is '7341621469' [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1128 - uniqueid:1416914140.0 - [CALLBACK]:[GET VARIABLE : CALLED=7341621469 | CALLING=3438181636 | MODE= | TARIFF= | CBID=39461-eho76mu | LEG=7341621469 | CALLERID=3438181636] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1132 - uniqueid:1416914140.0 - [CALLBACK : UPDATE CALLBACK AGI_RESULT : QUERY=UPDATE cc_callback_spool SET agi_result='AGI PROCESSING' WHERE uniqueid='39461-eho76mu'] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1136 - uniqueid:1416914140.0 - [CALLBACK]:[TRY : callingcard_ivr_authenticate] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:2869 - uniqueid:1416914140.0 - - Account code ::> 7341621469 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:2886 - uniqueid:1416914140.0 - - Retrieve account info SQL ::> SELECT credit, tariff, activated, inuse, simultaccess, typepaid, creditlimit, language, removeinterprefix, redial, enableexpire, UNIX_TIMESTAMP(expirationdate), expiredays, nbused, UNIX_TIMESTAMP(firstusedate), UNIX_TIMESTAMP(cc_card.creationdate), cc_card.currency, cc_card.lastname, cc_card.firstname, cc_card.email, cc_card.uipass, cc_card.id_campaign, cc_card.id, useralias, status, voicemail_permitted, voicemail_activated, cc_card.restriction, cc_country.countryprefix FROM cc_card LEFT JOIN cc_tariffgroup ON tariff = cc_tariffgroup.id LEFT JOIN cc_country ON cc_card.country = cc_country.countrycode WHERE username = '7341621469' [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:2959 - uniqueid:1416914140.0 - [credit=45.53181 :: tariff=1 :: status=1 :: isused=1 :: simultaccess=1 :: typepaid=0 :: creditlimit= :: language=br] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:780 - uniqueid:1416914140.0 - [CARD STATUS UPDATE] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:789 - uniqueid:1416914140.0 - [QUERY USING CARD UPDATE::> UPDATE cc_card SET inuse = inuse + 1, credit = credit - 0.25 WHERE username = '7341621469'] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1143 - uniqueid:1416914140.0 - [CALLBACK]:[Start] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:2528 - uniqueid:1416914140.0 - [AUTO SetCallerID] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1161 - uniqueid:1416914140.0 - [CALLBACK]:[CHANNEL STATUS : 6 = Line is up][status_channel=4]:[ORIG_CREDIT : 45.53181 - CUR_CREDIT - : 22.765905 - CREDIT MIN_CREDIT_2CALL : ] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:839 - uniqueid:1416914140.0 - use_dnid:1 && (!in_array:) && len_dnid:(10 || len_exten:10 ) && (try_num:0) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:848 - uniqueid:1416914140.0 - [USE_DNID DESTINATION ::> 3438181636] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:929 - uniqueid:1416914140.0 - DESTINATION ::> 3438181636 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:936 - uniqueid:1416914140.0 - RULES APPLY ON DESTINATION ::> 3438181636 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:97 - uniqueid:1416914140.0 - [CC_asterisk_rate-engine: (1, 3438181636)] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:118 - uniqueid:1416914140.0 - [CC_asterisk_rate-engine - CALLERID : 3438181636] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:179 - uniqueid:1416914140.0 - [rate-engine: Count Total result 2] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:344 - uniqueid:1416914140.0 - [CC_asterisk_rate-engine: Count Total result 1] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:345 - uniqueid:1416914140.0 - [CC_asterisk_rate-engine: number_trunk 1] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:1053 - uniqueid:1416914140.0 - OK - RESFINDRATE::> 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:358 - uniqueid:1416914140.0 - [CC_RATE_ENGINE_ALL_CALCULTIMEOUT (22.765905)] [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'RI' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'IB' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'BB' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'CC' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'DC' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'SC_A' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'TC_A' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'SC_B' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'TC_B' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'SC_C' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'TC_C' is NULL [Nov 25 09:15:53] DEBUG[2584][C-00000001] pbx.c: Result of 'ANSWEREDTIME' is NULL [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:364 - uniqueid:1416914140.0 - [CC_RATE_ENGINE_ALL_CALCULTIMEOUT: k=0 - res_calcultimeout:13656] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:1066 - uniqueid:1416914140.0 - RES_ALL_CALCULTIMEOUT ::> 1 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:1974 - uniqueid:1416914140.0 - TIMEOUT::> 13656 : minutes=227 - seconds=36 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1307 - uniqueid:1416914140.0 - app_callingcard: Dialing 'SIP/voip2cNT2P1/99901553438181636|37|HRrL(1800000)' with timeout of '13656'. [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1327 - uniqueid:1416914140.0 - app_callingcard: CIDGROUPID='-1' OUTBOUND CID SELECTED IS '0'. [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1223 - uniqueid:1416914140.0 - [TRUNK STATUS UPDATE : UPDATE cc_trunk SET inuse = inuse + 1 WHERE id_trunk = '36'] [Nov 25 09:15:53] VERBOSE[2584][C-00000001] res_agi.c: AGI Script Executing Application: (DIAL) Options: (SIP/voip2cNT2P1/99901553438181636,37,HRrL(1800000)) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] features.c: Setting call duration limit to 1800.000 seconds. [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Asked to create a SIP channel with formats: (slin) [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Allocating new SIP dialog for 70e7f7ef2849e0e6711b8d1a17e2c6a6@10.0.0.10:5060 - INVITE (No RTP) [Nov 25 09:15:53] DEBUG[2584][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7fcaa86ab2c8' [Nov 25 09:15:53] DEBUG[2584][C-00000001] res_rtp_asterisk.c: Allocated port 12454 for RTP instance '0x7fcaa86ab2c8' [Nov 25 09:15:53] DEBUG[2584][C-00000001] rtp_engine.c: RTP instance '0x7fcaa86ab2c8' is setup and ready to go [Nov 25 09:15:53] DEBUG[2584][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7fcaa86ab2c8' [Nov 25 09:15:53] VERBOSE[2584][C-00000001] netsock2.c: Using SIP RTP CoS mark 5 [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Setting NAT on RTP to On [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: OBPROXY: Not applying OBproxy to this call [Nov 25 09:15:53] DEBUG[2584][C-00000001] acl.c: For destination '216.53.4.1', our source address is '10.0.0.10'. [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Target address 216.53.4.1:5060 is not local, substituting externaddr [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Setting AST_TRANSPORT_UDP with address 154.232.196.179:5060 [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Setting NAT on RTP to On [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: SIP call-id changed from '70e7f7ef2849e0e6711b8d1a17e2c6a6@10.0.0.10:5060' to '64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060' [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: *** Joint capabilities are (nothing) [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: *** Our capabilities are (ulaw) [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: *** Our preferred formats from the incoming channel are (slin) [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: This channel will not be able to handle video. [Nov 25 09:15:53] DEBUG[2584][C-00000001] channel_internal_api.c: Channel Call ID changing from [C-00000001] to [C-00000001] [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Outgoing Call for 99901553438181636 [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Updating call counter for outgoing call [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: ** Our capability: (ulaw) Video flag: False Text flag: False [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: ** Our prefcodec: (slin) [Nov 25 09:15:53] VERBOSE[2584][C-00000001] chan_sip.c: Audio is at 12454 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] chan_sip.c: Adding codec ulaw to SDP [Nov 25 09:15:53] VERBOSE[2584][C-00000001] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 0 [ 52]: INVITE sip:99901553438181636@216.53.4.1:5060 SIP/2.0 [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 1 [ 65]: Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK2d6967e4;rport [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 3 [ 52]: From: ;tag=as3db1ebee [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 4 [ 43]: To: [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 5 [ 45]: Contact: [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 6 [ 61]: Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 8 [ 29]: User-Agent: NGN voip2c Telecom [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 9 [ 35]: Date: Tue, 25 Nov 2014 11:15:53 GMT [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 10 [ 90]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [Nov 25 09:15:53] VERBOSE[2584][C-00000001] chan_sip.c: Reliably Transmitting (NAT) to 216.53.4.1:5060: INVITE sip:99901553438181636@216.53.4.1:5060 SIP/2.0 Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK2d6967e4;rport Max-Forwards: 70 From: ;tag=as3db1ebee To: Contact: Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 CSeq: 102 INVITE User-Agent: NGN voip2c Telecom Date: Tue, 25 Nov 2014 11:15:53 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 255 v=0 o=root 1404707772 1404707772 IN IP4 154.232.196.179 s=Asterisk PBX 13.0.1 c=IN IP4 154.232.196.179 t=0 0 m=audio 12454 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #413 [Nov 25 09:15:53] DEBUG[2584][C-00000001] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 216.53.4.1:5060 [Nov 25 09:15:53] VERBOSE[2584][C-00000001] app_dial.c: Called SIP/voip2cNT2P1/99901553438181636 [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: DIALSTATUS Value: [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: DIALEDPEERNUMBER Value: [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: DIALEDPEERNAME Value: [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: ANSWEREDTIME Value: [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: DIALEDTIME Value: [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: Newchannel Privilege: call,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing Exten: s Priority: 1 Uniqueid: 1416914153.3 [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing Exten: s Priority: 1 Uniqueid: 1416914153.3 Variable: SIPCALLID Value: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: CallerIDName: ConnectedLineNum: ConnectedLineName: AccountCode: Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 Variable: DIALEDPEERNUMBER Value: voip2cNT2P1/99901553438181636 [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: 3438181636 Priority: 1 Uniqueid: 1416914153.3 Extension: 3438181636 Application: AppDial AppData: (Outgoing Line) [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: NewCallerid Privilege: call,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: 3438181636 Priority: 1 Uniqueid: 1416914153.3 CID-CallingPres: 0 (Presentation Allowed, Not Screened) [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: NewAccountCode Privilege: call,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 0 ChannelStateDesc: Down CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: 3438181636 Priority: 1 Uniqueid: 1416914153.3 OldAccountCode: [Nov 25 09:15:53] DEBUG[1964] devicestate.c: No provider found, checking channel drivers for Local - 881000ClicktoCall@a2billing-did2 [Nov 25 09:15:53] DEBUG[1964] devicestate.c: Changing state for Local/881000ClicktoCall@a2billing-did2 - state 2 (In use) [Nov 25 09:15:53] DEBUG[2457] app_queue.c: Device 'Local/881000ClicktoCall@a2billing-did2' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: DialBegin Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 DestChannel: SIP/voip2cNT2P1-00000001 DestChannelState: 0 DestChannelStateDesc: Down DestCallerIDNum: 3438181636 DestCallerIDName: DestConnectedLineNum: 3438181636 DestConnectedLineName: DestAccountCode: 7341621469 DestContext: a2billing DestExten: 3438181636 DestPriority: 1 DestUniqueid: 1416914153.3 DialString: voip2cNT2P1/99901553438181636 [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 [Nov 25 09:15:53] DEBUG[2581] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/881000ClicktoCall@a2billing-did2 State: INUSE [Nov 25 09:15:53] DEBUG[2590][C-00000000] channel.c: Driver for channel 'SIP/voip2cNT2P1-00000000' does not support indication 3, emulating it [Nov 25 09:15:53] DEBUG[2590][C-00000000] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Nov 25 09:15:53] DEBUG[2590][C-00000000] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [Nov 25 09:15:53] VERBOSE[2428] chan_sip.c: <--- SIP read from UDP:216.53.4.1:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK2d6967e4;received=154.232.196.179;rport=5060 From: ;tag=as3db1ebee To: Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 Contact: CSeq: 102 INVITE Server: sbc_5 Content-Length: 0 <-------------> [Nov 25 09:15:53] DEBUG[2428] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [Nov 25 09:15:53] DEBUG[2428] chan_sip.c: Header 1 [ 94]: Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK2d6967e4;received=154.232.196.179;rport=5060 [Nov 25 09:15:53] DEBUG[2428] chan_sip.c: Header 2 [ 52]: From: ;tag=as3db1ebee [Nov 25 09:15:53] DEBUG[2428] chan_sip.c: Header 3 [ 43]: To: [Nov 25 09:15:53] DEBUG[2428] chan_sip.c: Header 4 [ 61]: Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:15:53] DEBUG[2428] chan_sip.c: Header 5 [ 30]: Contact: [Nov 25 09:15:53] DEBUG[2428] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Nov 25 09:15:53] DEBUG[2428] chan_sip.c: Header 7 [ 13]: Server: sbc_5 [Nov 25 09:15:53] DEBUG[2428] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Nov 25 09:15:53] VERBOSE[2428] chan_sip.c: --- (9 headers 0 lines) --- [Nov 25 09:15:53] DEBUG[2428] chan_sip.c: = Looking for Call ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 (Checking To) --From tag as3db1ebee --To-tag [Nov 25 09:15:53] DEBUG[2428][C-00000001] chan_sip.c: *** SIP TIMER: Cancelling retransmission #413 - INVITE (got response) [Nov 25 09:15:53] DEBUG[2428][C-00000001] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060' Request 102: Found [Nov 25 09:15:53] DEBUG[2428][C-00000001] chan_sip.c: SIP response 100 to standard invite [Nov 25 09:15:54] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:15:54] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:15:54] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:15:54] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:15:54] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:15:54] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 To: 169.132.138.41:23745 From: 10.0.0.10:0 SSRC: 0x3a4793e2 PT: 200(SR) ReportCount: 1 SentNTP: 1416914154.3239723008 SentRTP: 13440 SentPackets: 84 SentOctets: 13440 Report0SourceSSRC: 0x09cf6374 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 267 Report0SequenceNumberCycles: 0 Report0IAJitter: 1 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:15:54] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:15:54] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:15:54] DEBUG[2448] netsock2.c: Splitting '169.132.138.41:23745' into... [Nov 25 09:15:54] DEBUG[2448] netsock2.c: ...host '169.132.138.41' and port '23745'. [Nov 25 09:15:59] VERBOSE[2428] chan_sip.c: <--- SIP read from UDP:216.53.4.1:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK2d6967e4;received=154.232.196.179;rport=5060 From: ;tag=as3db1ebee To: ;tag=sbcsipuas_1_C31790_20141125061553170_b12sb09 Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 Contact: CSeq: 102 INVITE Server: sbc_5 Content-Type: application/sdp Content-Length: 312 v=0 o=SBCSIPUAS 733933685 1 IN IP4 206.20.2.51 s=SBCSIPUAS SIP STACK v1.0 c=IN IP4 206.20.2.51 t=0 0 m=audio 23672 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sqn:0 a=cdsc:1 audio RTP/AVP 8 0 101 a=cpar:a=fmtp:101 0-15 a=cdsc:4 image udptl t38 a=sendrecv <-------------> [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Header 0 [ 28]: SIP/2.0 183 Session Progress [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Header 1 [ 94]: Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK2d6967e4;received=154.232.196.179;rport=5060 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Header 2 [ 52]: From: ;tag=as3db1ebee [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Header 3 [ 92]: To: ;tag=sbcsipuas_1_C31790_20141125061553170_b12sb09 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Header 4 [ 61]: Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Header 5 [ 30]: Contact: [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Header 7 [ 13]: Server: sbc_5 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Header 8 [ 29]: Content-Type: application/sdp [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Header 9 [ 19]: Content-Length: 312 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Header 10 [ 0]: [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 0 [ 3]: v=0 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 1 [ 42]: o=SBCSIPUAS 733933685 1 IN IP4 206.20.2.51 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 2 [ 26]: s=SBCSIPUAS SIP STACK v1.0 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 3 [ 20]: c=IN IP4 206.20.2.51 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 5 [ 27]: m=audio 23672 RTP/AVP 0 101 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-15 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 9 [ 7]: a=sqn:0 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 10 [ 30]: a=cdsc:1 audio RTP/AVP 8 0 101 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 11 [ 22]: a=cpar:a=fmtp:101 0-15 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 12 [ 24]: a=cdsc:4 image udptl t38 [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: Body 13 [ 10]: a=sendrecv [Nov 25 09:15:59] VERBOSE[2428] chan_sip.c: --- (10 headers 14 lines) --- [Nov 25 09:15:59] DEBUG[2428] chan_sip.c: = Looking for Call ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 (Checking To) --From tag as3db1ebee --To-tag sbcsipuas_1_C31790_20141125061553170_b12sb09 [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060' Request 102: Found [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: SIP response 183 to standard invite [Nov 25 09:15:59] VERBOSE[2428][C-00000001] sip/route.c: sip_route_dump: route/path hop: [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing session-level SDP o=SBCSIPUAS 733933685 1 IN IP4 206.20.2.51... OK. [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing session-level SDP s=SBCSIPUAS SIP STACK v1.0... UNSUPPORTED OR FAILED. [Nov 25 09:15:59] DEBUG[2428][C-00000001] netsock2.c: Splitting '206.20.2.51' into... [Nov 25 09:15:59] DEBUG[2428][C-00000001] netsock2.c: ...host '206.20.2.51' and port ''. [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 206.20.2.51... OK. [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Nov 25 09:15:59] VERBOSE[2428][C-00000001] chan_sip.c: Found RTP audio format 0 [Nov 25 09:15:59] DEBUG[2428][C-00000001] rtp_engine.c: Setting payload 0 (0x7fcadc0097a8) based on m type on 0x7fca71cb1820 [Nov 25 09:15:59] VERBOSE[2428][C-00000001] chan_sip.c: Found RTP audio format 101 [Nov 25 09:15:59] DEBUG[2428][C-00000001] rtp_engine.c: Setting payload 101 (0x7fcadc00ade8) based on m type on 0x7fca71cb1820 [Nov 25 09:15:59] VERBOSE[2428][C-00000001] chan_sip.c: Found audio description format PCMU for ID 0 [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Nov 25 09:15:59] VERBOSE[2428][C-00000001] chan_sip.c: Found audio description format telephone-event for ID 101 [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sqn:0... UNSUPPORTED OR FAILED. [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=cdsc:1 audio RTP/AVP 8 0 101... UNSUPPORTED OR FAILED. [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=cpar:a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=cdsc:4 image udptl t38... UNSUPPORTED OR FAILED. [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Nov 25 09:15:59] VERBOSE[2428][C-00000001] chan_sip.c: Capabilities: us - (ulaw), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw) [Nov 25 09:15:59] VERBOSE[2428][C-00000001] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Nov 25 09:15:59] DEBUG[2428][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fcaa86ab2c8' [Nov 25 09:15:59] VERBOSE[2428][C-00000001] chan_sip.c: Peer audio RTP is at port 206.20.2.51:23672 [Nov 25 09:15:59] DEBUG[2428][C-00000001] rtp_engine.c: Copying payload 0 (0x7fcadc00ae68) from 0x7fca71cb1820 to 0x7fcaa86ab408 [Nov 25 09:15:59] DEBUG[2428][C-00000001] rtp_engine.c: Copying payload 101 (0x7fcadc0097a8) from 0x7fca71cb1820 to 0x7fcaa86ab408 [Nov 25 09:15:59] DEBUG[2428][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fcaa86ab2c8' [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: We're settling with these formats: (ulaw) [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: We have an owner, now see if we need to change this call [Nov 25 09:15:59] DEBUG[2428][C-00000001] chan_sip.c: Setting native formats after processing SDP. peer joint formats (ulaw), old nativeformats (ulaw) [Nov 25 09:15:59] VERBOSE[2584][C-00000001] app_dial.c: SIP/voip2cNT2P1-00000001 is making progress passing it to Local/881000ClicktoCall@a2billing-did2-00000000;1 [Nov 25 09:15:59] DEBUG[2584][C-00000001] res_rtp_asterisk.c: 0x7fcaa84ae8d0 -- Probation learning mode pass with source address 206.20.2.51:23672 [Nov 25 09:15:59] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:15:59] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:15:59] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:15:59] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:15:59] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:15:59] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:15:59] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:15:59] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 To: 169.132.138.41:23745 From: 10.0.0.10:0 SSRC: 0x3a4793e2 PT: 200(SR) ReportCount: 1 SentNTP: 1416914159.3240210432 SentRTP: 53440 SentPackets: 334 SentOctets: 53440 Report0SourceSSRC: 0x09cf6374 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 353 Report0SequenceNumberCycles: 0 Report0IAJitter: 10 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:15:59] DEBUG[2448] netsock2.c: Splitting '169.132.138.41:23745' into... [Nov 25 09:15:59] DEBUG[2448] netsock2.c: ...host '169.132.138.41' and port '23745'. [Nov 25 09:16:01] VERBOSE[2428] chan_sip.c: <--- SIP read from UDP:216.53.4.1:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK2d6967e4;received=154.232.196.179;rport=5060 From: ;tag=as3db1ebee To: ;tag=sbcsipuas_1_C31790_20141125061553170_b12sb09 Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 Contact: CSeq: 102 INVITE Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,NOTIFY,INFO Server: sbc_5 Content-Type: application/sdp Content-Length: 312 v=0 o=SBCSIPUAS 733933685 1 IN IP4 206.20.2.51 s=SBCSIPUAS SIP STACK v1.0 c=IN IP4 206.20.2.51 t=0 0 m=audio 23672 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sqn:0 a=cdsc:1 audio RTP/AVP 8 0 101 a=cpar:a=fmtp:101 0-15 a=cdsc:4 image udptl t38 a=sendrecv <-------------> [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 1 [ 94]: Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK2d6967e4;received=154.232.196.179;rport=5060 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 2 [ 52]: From: ;tag=as3db1ebee [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 3 [ 92]: To: ;tag=sbcsipuas_1_C31790_20141125061553170_b12sb09 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 4 [ 61]: Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 5 [ 30]: Contact: [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 6 [ 16]: CSeq: 102 INVITE [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 7 [ 48]: Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,NOTIFY,INFO [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 8 [ 13]: Server: sbc_5 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 9 [ 29]: Content-Type: application/sdp [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 10 [ 19]: Content-Length: 312 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Header 11 [ 0]: [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 0 [ 3]: v=0 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 1 [ 42]: o=SBCSIPUAS 733933685 1 IN IP4 206.20.2.51 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 2 [ 26]: s=SBCSIPUAS SIP STACK v1.0 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 3 [ 20]: c=IN IP4 206.20.2.51 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 4 [ 5]: t=0 0 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 5 [ 27]: m=audio 23672 RTP/AVP 0 101 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-15 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 9 [ 7]: a=sqn:0 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 10 [ 30]: a=cdsc:1 audio RTP/AVP 8 0 101 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 11 [ 22]: a=cpar:a=fmtp:101 0-15 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 12 [ 24]: a=cdsc:4 image udptl t38 [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: Body 13 [ 10]: a=sendrecv [Nov 25 09:16:01] VERBOSE[2428] chan_sip.c: --- (11 headers 14 lines) --- [Nov 25 09:16:01] DEBUG[2428] chan_sip.c: = Looking for Call ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 (Checking To) --From tag as3db1ebee --To-tag sbcsipuas_1_C31790_20141125061553170_b12sb09 [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Acked pending invite 102 [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Stopping retransmission on '64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060' of Request 102: Match Found [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: SIP response 200 to standard invite [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing session-level SDP o=SBCSIPUAS 733933685 1 IN IP4 206.20.2.51... OK. [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing session-level SDP s=SBCSIPUAS SIP STACK v1.0... UNSUPPORTED OR FAILED. [Nov 25 09:16:01] DEBUG[2428][C-00000001] netsock2.c: Splitting '206.20.2.51' into... [Nov 25 09:16:01] DEBUG[2428][C-00000001] netsock2.c: ...host '206.20.2.51' and port ''. [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 206.20.2.51... OK. [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Nov 25 09:16:01] VERBOSE[2428][C-00000001] chan_sip.c: Found RTP audio format 0 [Nov 25 09:16:01] DEBUG[2428][C-00000001] rtp_engine.c: Setting payload 0 (0x7fcadc007bf8) based on m type on 0x7fca71cb1820 [Nov 25 09:16:01] VERBOSE[2428][C-00000001] chan_sip.c: Found RTP audio format 101 [Nov 25 09:16:01] DEBUG[2428][C-00000001] rtp_engine.c: Setting payload 101 (0x7fcadc007c78) based on m type on 0x7fca71cb1820 [Nov 25 09:16:01] VERBOSE[2428][C-00000001] chan_sip.c: Found audio description format PCMU for ID 0 [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Nov 25 09:16:01] VERBOSE[2428][C-00000001] chan_sip.c: Found audio description format telephone-event for ID 101 [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sqn:0... UNSUPPORTED OR FAILED. [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=cdsc:1 audio RTP/AVP 8 0 101... UNSUPPORTED OR FAILED. [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=cpar:a=fmtp:101 0-15... UNSUPPORTED OR FAILED. [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=cdsc:4 image udptl t38... UNSUPPORTED OR FAILED. [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Nov 25 09:16:01] VERBOSE[2428][C-00000001] chan_sip.c: Capabilities: us - (ulaw), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw) [Nov 25 09:16:01] VERBOSE[2428][C-00000001] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [Nov 25 09:16:01] DEBUG[2428][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fcaa86ab2c8' [Nov 25 09:16:01] VERBOSE[2428][C-00000001] chan_sip.c: Peer audio RTP is at port 206.20.2.51:23672 [Nov 25 09:16:01] DEBUG[2428][C-00000001] rtp_engine.c: Copying payload 0 (0x7fcadc001cb8) from 0x7fca71cb1820 to 0x7fcaa86ab408 [Nov 25 09:16:01] DEBUG[2428][C-00000001] rtp_engine.c: Copying payload 101 (0x7fcadc007bf8) from 0x7fca71cb1820 to 0x7fcaa86ab408 [Nov 25 09:16:01] DEBUG[2428][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7fcaa86ab2c8' [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: We're settling with these formats: (ulaw) [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: We have an owner, now see if we need to change this call [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Setting native formats after processing SDP. peer joint formats (ulaw), old nativeformats (ulaw) [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Updating call counter for outgoing call [Nov 25 09:16:01] VERBOSE[2428][C-00000001] sip/route.c: sip_route_dump: route/path hop: [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Strict routing enforced for session 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:16:01] VERBOSE[2428][C-00000001] chan_sip.c: Transmitting (NAT) to 216.53.4.1:5060: ACK sip:216.53.4.1:5060 SIP/2.0 Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK75f16612;rport Max-Forwards: 70 From: ;tag=as3db1ebee To: ;tag=sbcsipuas_1_C31790_20141125061553170_b12sb09 Contact: Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 CSeq: 102 ACK User-Agent: NGN voip2c Telecom Content-Length: 0 --- [Nov 25 09:16:01] DEBUG[2428][C-00000001] chan_sip.c: Trying to put 'ACK sip:216' onto UDP socket destined for 216.53.4.1:5060 [Nov 25 09:16:01] VERBOSE[2584][C-00000001] app_dial.c: SIP/voip2cNT2P1-00000001 answered Local/881000ClicktoCall@a2billing-did2-00000000;1 [Nov 25 09:16:01] DEBUG[2584][C-00000001] channel.c: Set channel SIP/voip2cNT2P1-00000001 to read format slin [Nov 25 09:16:01] DEBUG[2584][C-00000001] channel.c: Set channel SIP/voip2cNT2P1-00000001 to write format slin [Nov 25 09:16:01] DEBUG[2584][C-00000001] features.c: Removing dialed interfaces datastore on SIP/voip2cNT2P1-00000001 since we're bridging [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge_native_rtp.c: Bridge '9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e' can not use native RTP bridge as two channels are required [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge technology softmix has less preference than simple_bridge (10 <= 50). Skipping. [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Chose bridge technology simple_bridge [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: calling simple_bridge technology constructor [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: calling simple_bridge technology start [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge_channel.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: 0x7fcaa871d988(Local/881000ClicktoCall@a2billing-did2-00000000;1) is joining [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge_channel.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: pushing 0x7fcaa871d988(Local/881000ClicktoCall@a2billing-did2-00000000;1) [Nov 25 09:16:01] VERBOSE[2584][C-00000001] bridge_channel.c: Channel Local/881000ClicktoCall@a2billing-did2-00000000;1 joined 'simple_bridge' basic-bridge <9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e> [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge_native_rtp.c: Bridge '9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e' can not use native RTP bridge as two channels are required [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Chose bridge technology simple_bridge [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e is already using the new technology. [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e is happy that channel Local/881000ClicktoCall@a2billing-did2-00000000;1 already has read format slin [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e is happy that channel Local/881000ClicktoCall@a2billing-did2-00000000;1 already has write format slin [Nov 25 09:16:01] DEBUG[2584][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: 0x7fcaa871d988(Local/881000ClicktoCall@a2billing-did2-00000000;1) is joining simple_bridge technology [Nov 25 09:16:01] DEBUG[1964] devicestate.c: No provider found, checking channel drivers for SIP - voip2cNT2P1 [Nov 25 09:16:01] DEBUG[1964] chan_sip.c: Checking device state for peer voip2cNT2P1 [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: Newstate Privilege: call,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: 3438181636 Priority: 1 Uniqueid: 1416914153.3 [Nov 25 09:16:01] DEBUG[1964] devicestate.c: Changing state for SIP/voip2cNT2P1 - state 1 (Not in use) [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: DIALSTATUS Value: ANSWER [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: DIALEDPEERNAME Value: SIP/voip2cNT2P1-00000001 [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: DIALEDPEERNUMBER Value: voip2cNT2P1/99901553438181636 [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: DialEnd Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 DestChannel: SIP/voip2cNT2P1-00000001 DestChannelState: 6 DestChannelStateDesc: Up DestCallerIDNum: 3438181636 DestCallerIDName: DestConnectedLineNum: 3438181636 DestConnectedLineName: DestAccountCode: 7341621469 DestContext: a2billing DestExten: DestPriority: 1 DestUniqueid: 1416914153.3 DialStatus: ANSWER [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeCreate Privilege: call,all BridgeUniqueid: 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 [Nov 25 09:16:01] DEBUG[2590][C-00000000] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov 25 09:16:01] DEBUG[2590][C-00000000] res_rtp_asterisk.c: Changing ssrc from 977769442 to 935663094 due to a source change [Nov 25 09:16:01] DEBUG[2595][C-00000001] bridge_channel.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: 0x7fcaa88930a8(SIP/voip2cNT2P1-00000001) is joining [Nov 25 09:16:01] DEBUG[2595][C-00000001] bridge_channel.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: pushing 0x7fcaa88930a8(SIP/voip2cNT2P1-00000001) [Nov 25 09:16:01] VERBOSE[2595][C-00000001] bridge_channel.c: Channel SIP/voip2cNT2P1-00000001 joined 'simple_bridge' basic-bridge <9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e> [Nov 25 09:16:01] DEBUG[2595][C-00000001] bridge.c: Bridge technology holding_bridge does not have any capabilities we want. [Nov 25 09:16:01] DEBUG[2595][C-00000001] bridge_native_rtp.c: Bridge '9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e' can not use native RTP bridge as it was forbidden while getting details [Nov 25 09:16:01] DEBUG[2595][C-00000001] bridge.c: Bridge technology native_rtp is not compatible with properties of existing bridge. [Nov 25 09:16:01] DEBUG[2595][C-00000001] bridge.c: Bridge technology softmix does not have any capabilities we want. [Nov 25 09:16:01] DEBUG[2595][C-00000001] bridge.c: Chose bridge technology simple_bridge [Nov 25 09:16:01] DEBUG[2595][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e is already using the new technology. [Nov 25 09:16:01] DEBUG[2595][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e is happy that channel SIP/voip2cNT2P1-00000001 already has read format slin [Nov 25 09:16:01] DEBUG[2595][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e is happy that channel SIP/voip2cNT2P1-00000001 already has write format slin [Nov 25 09:16:01] DEBUG[2595][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: 0x7fcaa88930a8(SIP/voip2cNT2P1-00000001) is joining simple_bridge technology [Nov 25 09:16:01] DEBUG[2595][C-00000001] res_rtp_asterisk.c: Not changing SSRC since we haven't sent any RTP yet [Nov 25 09:16:01] DEBUG[1965] cdr.c: Finalized CDR for SIP/voip2cNT2P1-00000001 - start 1416914153.097710 answer 1416914161.444578 end 1416914161.445753 dispo ANSWERED [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 Extension: Application: AppDial AppData: (Outgoing Line) [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeEnter Privilege: call,all BridgeUniqueid: 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 2 Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: BRIDGEPEER Value: SIP/voip2cNT2P1-00000001 [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: BRIDGEPVTCALLID Value: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:16:01] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 Variable: BRIDGEPEER Value: Local/881000ClicktoCall@a2billing-did2-00000000;1 [Nov 25 09:16:01] DEBUG[2595][C-00000001] res_rtp_asterisk.c: Ooh, format changed from none to ulaw [Nov 25 09:16:01] DEBUG[2595][C-00000001] res_rtp_asterisk.c: 0x7fcaa84ae8d0 -- Probation learning mode pass with source address 206.20.2.51:23672 [Nov 25 09:16:01] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:03] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:04] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:04] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:04] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:04] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:04] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:04] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 To: 206.20.2.51:23673 From: 10.0.0.10:0 SSRC: 0x03099088 PT: 200(SR) ReportCount: 1 SentNTP: 1416914164.98009088 SentRTP: 1748298408 SentPackets: 53 SentOctets: 8480 Report0SourceSSRC: 0x217b9b5d Report0FractionLost: 255 Report0CumulativeLost: 65538 Report0HighestSequence: 35105 Report0SequenceNumberCycles: 1 Report0IAJitter: 3 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:04] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:04] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:04] DEBUG[2448] netsock2.c: Splitting '206.20.2.51:23673' into... [Nov 25 09:16:04] DEBUG[2448] netsock2.c: ...host '206.20.2.51' and port '23673'. [Nov 25 09:16:04] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:04] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:04] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:04] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:04] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:04] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:04] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:04] DEBUG[2448] netsock2.c: Splitting '169.132.138.41:23745' into... [Nov 25 09:16:04] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 To: 169.132.138.41:23745 From: 10.0.0.10:0 SSRC: 0x37c515f6 PT: 200(SR) ReportCount: 1 SentNTP: 1416914164.3242389504 SentRTP: 2454385328 SentPackets: 583 SentOctets: 93280 Report0SourceSSRC: 0x09cf6374 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 473 Report0SequenceNumberCycles: 0 Report0IAJitter: 3 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:04] DEBUG[2448] netsock2.c: ...host '169.132.138.41' and port '23745'. [Nov 25 09:16:05] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:06] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:09] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:09] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:09] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:09] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:09] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:09] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 To: 206.20.2.51:23673 From: 10.0.0.10:0 SSRC: 0x03099088 PT: 200(SR) ReportCount: 1 SentNTP: 1416914169.94572544 SentRTP: 1748340048 SentPackets: 277 SentOctets: 44320 Report0SourceSSRC: 0x217b9b5d Report0FractionLost: 3 Report0CumulativeLost: 65541 Report0HighestSequence: 35354 Report0SequenceNumberCycles: 1 Report0IAJitter: 10 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:09] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:09] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:09] DEBUG[2448] netsock2.c: Splitting '206.20.2.51:23673' into... [Nov 25 09:16:09] DEBUG[2448] netsock2.c: ...host '206.20.2.51' and port '23673'. [Nov 25 09:16:09] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:09] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:09] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:09] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:09] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:09] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:09] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:09] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:09] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 To: 169.132.138.41:23745 From: 10.0.0.10:0 SSRC: 0x37c515f6 PT: 200(SR) ReportCount: 1 SentNTP: 1416914169.3243421696 SentRTP: 2454425328 SentPackets: 830 SentOctets: 132800 Report0SourceSSRC: 0x09cf6374 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 690 Report0SequenceNumberCycles: 0 Report0IAJitter: 3 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:09] DEBUG[2448] netsock2.c: Splitting '169.132.138.41:23745' into... [Nov 25 09:16:09] DEBUG[2448] netsock2.c: ...host '169.132.138.41' and port '23745'. [Nov 25 09:16:11] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:12] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:12] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:14] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:14] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:14] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:14] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:14] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:14] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:14] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:14] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 To: 206.20.2.51:23673 From: 10.0.0.10:0 SSRC: 0x03099088 PT: 200(SR) ReportCount: 1 SentNTP: 1416914174.95211520 SentRTP: 1748380128 SentPackets: 441 SentOctets: 70560 Report0SourceSSRC: 0x217b9b5d Report0FractionLost: 2 Report0CumulativeLost: 65543 Report0HighestSequence: 35605 Report0SequenceNumberCycles: 1 Report0IAJitter: 2 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:14] DEBUG[2448] netsock2.c: Splitting '206.20.2.51:23673' into... [Nov 25 09:16:14] DEBUG[2448] netsock2.c: ...host '206.20.2.51' and port '23673'. [Nov 25 09:16:14] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:14] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:14] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:14] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:14] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:14] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:14] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:14] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 To: 169.132.138.41:23745 From: 10.0.0.10:0 SSRC: 0x37c515f6 PT: 200(SR) ReportCount: 1 SentNTP: 1416914174.3240071168 SentRTP: 2454465328 SentPackets: 1078 SentOctets: 172480 Report0SourceSSRC: 0x09cf6374 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 876 Report0SequenceNumberCycles: 0 Report0IAJitter: 6 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:14] DEBUG[2448] netsock2.c: Splitting '169.132.138.41:23745' into... [Nov 25 09:16:14] DEBUG[2448] netsock2.c: ...host '169.132.138.41' and port '23745'. [Nov 25 09:16:15] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:15] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:16] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:16] WARNING[2590][C-00000000] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:16] WARNING[2590][C-00000000] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:16] WARNING[2590][C-00000000] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:16] WARNING[2590][C-00000000] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:19] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:19] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:19] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:19] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:19] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:19] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:19] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 To: 206.20.2.51:23673 From: 10.0.0.10:0 SSRC: 0x03099088 PT: 200(SR) ReportCount: 1 SentNTP: 1416914179.93757440 SentRTP: 1748397928 SentPackets: 523 SentOctets: 83680 Report0SourceSSRC: 0x217b9b5d Report0FractionLost: 255 Report0CumulativeLost: 131080 Report0HighestSequence: 35854 Report0SequenceNumberCycles: 2 Report0IAJitter: 3 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:19] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:19] DEBUG[2448] netsock2.c: Splitting '206.20.2.51:23673' into... [Nov 25 09:16:19] DEBUG[2448] netsock2.c: ...host '206.20.2.51' and port '23673'. [Nov 25 09:16:19] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:19] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:19] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:19] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:19] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:19] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:19] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:19] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 To: 169.132.138.41:23745 From: 10.0.0.10:0 SSRC: 0x37c515f6 PT: 200(SR) ReportCount: 1 SentNTP: 1416914179.3242762240 SentRTP: 2454505328 SentPackets: 1322 SentOctets: 211520 Report0SourceSSRC: 0x09cf6374 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 936 Report0SequenceNumberCycles: 0 Report0IAJitter: 5 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:19] DEBUG[2448] netsock2.c: Splitting '169.132.138.41:23745' into... [Nov 25 09:16:19] DEBUG[2448] netsock2.c: ...host '169.132.138.41' and port '23745'. [Nov 25 09:16:21] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:23] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:24] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:24] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:24] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:24] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:24] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:24] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:24] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:24] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 To: 206.20.2.51:23673 From: 10.0.0.10:0 SSRC: 0x03099088 PT: 200(SR) ReportCount: 1 SentNTP: 1416914184.94633984 SentRTP: 1748460048 SentPackets: 735 SentOctets: 117600 Report0SourceSSRC: 0x217b9b5d Report0FractionLost: 3 Report0CumulativeLost: 131083 Report0HighestSequence: 36103 Report0SequenceNumberCycles: 2 Report0IAJitter: 2 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:24] DEBUG[2448] netsock2.c: Splitting '206.20.2.51:23673' into... [Nov 25 09:16:24] DEBUG[2448] netsock2.c: ...host '206.20.2.51' and port '23673'. [Nov 25 09:16:24] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:24] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:24] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:24] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:24] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:24] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:24] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 To: 169.132.138.41:23745 From: 10.0.0.10:0 SSRC: 0x37c515f6 PT: 200(SR) ReportCount: 1 SentNTP: 1416914184.3240161280 SentRTP: 2454545168 SentPackets: 1568 SentOctets: 250880 Report0SourceSSRC: 0x09cf6374 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 1176 Report0SequenceNumberCycles: 0 Report0IAJitter: 1 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:24] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:24] DEBUG[2448] netsock2.c: Splitting '169.132.138.41:23745' into... [Nov 25 09:16:24] DEBUG[2448] netsock2.c: ...host '169.132.138.41' and port '23745'. [Nov 25 09:16:25] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:27] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:27] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:28] WARNING[2590][C-00000000] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:28] WARNING[2590][C-00000000] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:28] WARNING[2590][C-00000000] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:28] WARNING[2590][C-00000000] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:28] WARNING[2595][C-00000001] chan_sip.c: Can't send 10 type frames with SIP write [Nov 25 09:16:29] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:29] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:29] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:29] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:29] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:29] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:29] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:29] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 To: 206.20.2.51:23673 From: 10.0.0.10:0 SSRC: 0x03099088 PT: 200(SR) ReportCount: 1 SentNTP: 1416914189.93876224 SentRTP: 1748499008 SentPackets: 871 SentOctets: 139360 Report0SourceSSRC: 0x217b9b5d Report0FractionLost: 253 Report0CumulativeLost: 160286 Report0HighestSequence: 9 Report0SequenceNumberCycles: 3 Report0IAJitter: 3 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:29] DEBUG[2448] netsock2.c: Splitting '206.20.2.51:23673' into... [Nov 25 09:16:29] DEBUG[2448] netsock2.c: ...host '206.20.2.51' and port '23673'. [Nov 25 09:16:29] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:29] DEBUG[2428] netsock2.c: Splitting 'ip-10-0-0-10.localdomain' into... [Nov 25 09:16:29] DEBUG[2428] netsock2.c: ...host 'ip-10-0-0-10.localdomain' and port ''. [Nov 25 09:16:29] DEBUG[2428] acl.c: Not an IPv4 nor IPv6 address, cannot get port. [Nov 25 09:16:29] DEBUG[2428] acl.c: Attached to given IP address [Nov 25 09:16:29] DEBUG[2448] netsock2.c: Splitting '10.0.0.10:0' into... [Nov 25 09:16:29] DEBUG[2448] netsock2.c: ...host '10.0.0.10' and port '0'. [Nov 25 09:16:29] DEBUG[2581] manager.c: Examining AMI event: Event: RTCPSent Privilege: reporting,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 To: 169.132.138.41:23745 From: 10.0.0.10:0 SSRC: 0x37c515f6 PT: 200(SR) ReportCount: 1 SentNTP: 1416914189.3242737664 SentRTP: 2454577328 SentPackets: 1765 SentOctets: 282400 Report0SourceSSRC: 0x09cf6374 Report0FractionLost: 0 Report0CumulativeLost: 0 Report0HighestSequence: 1282 Report0SequenceNumberCycles: 0 Report0IAJitter: 7 Report0LSR: 0 Report0DLSR: 0.0000 [Nov 25 09:16:29] DEBUG[2448] netsock2.c: Splitting '169.132.138.41:23745' into... [Nov 25 09:16:29] DEBUG[2448] netsock2.c: ...host '169.132.138.41' and port '23745'. [Nov 25 09:16:30] VERBOSE[2428] chan_sip.c: <--- SIP read from UDP:216.53.4.1:5060 ---> BYE sip:3438181636@154.232.196.179:5060 SIP/2.0 Via: SIP/2.0/UDP 216.53.4.1:5060;branch=z9hG4bK-1714278191-1 To: ;tag=as4da15014 From: ;tag=sbcsipuas_1_C58173_20141125061541088_b59sb08 Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 CSeq: 103 BYE Max-Forwards: 70 Server: sbc_5 Content-Length: 0 <-------------> [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 0 [ 46]: BYE sip:3438181636@154.232.196.179:5060 SIP/2.0 [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 1 [ 60]: Via: SIP/2.0/UDP 216.53.4.1:5060;branch=z9hG4bK-1714278191-1 [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 2 [ 50]: To: ;tag=as4da15014 [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 3 [ 94]: From: ;tag=sbcsipuas_1_C58173_20141125061541088_b59sb08 [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 4 [ 61]: Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 5 [ 13]: CSeq: 103 BYE [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 6 [ 16]: Max-Forwards: 70 [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 7 [ 13]: Server: sbc_5 [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 8 [ 17]: Content-Length: 0 [Nov 25 09:16:30] VERBOSE[2428] chan_sip.c: --- (9 headers 0 lines) --- [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: = Looking for Call ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 (Checking From) --From tag sbcsipuas_1_C58173_20141125061541088_b59sb08 --To-tag as4da15014 [Nov 25 09:16:30] DEBUG[2428][C-00000000] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Nov 25 09:16:30] DEBUG[2428][C-00000000] chan_sip.c: Initializing initreq for method BYE - callid 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:16:30] DEBUG[2428][C-00000000] netsock2.c: Splitting '216.53.4.1:5060' into... [Nov 25 09:16:30] DEBUG[2428][C-00000000] netsock2.c: ...host '216.53.4.1' and port '5060'. [Nov 25 09:16:30] VERBOSE[2428][C-00000000] chan_sip.c: Sending to 216.53.4.1:5060 (NAT) [Nov 25 09:16:30] DEBUG[2428][C-00000000] chan_sip.c: Setting SIP_ALREADYGONE on dialog 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:16:30] DEBUG[2428][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fcaa400e2e8' [Nov 25 09:16:30] VERBOSE[2428][C-00000000] chan_sip.c: Scheduling destruction of SIP dialog '27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060' in 32000 ms (Method: BYE) [Nov 25 09:16:30] DEBUG[2428][C-00000000] chan_sip.c: Received bye, issuing owner hangup [Nov 25 09:16:30] VERBOSE[2428][C-00000000] chan_sip.c: <--- Transmitting (NAT) to 216.53.4.1:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 216.53.4.1:5060;branch=z9hG4bK-1714278191-1;received=216.53.4.1;rport=5060 From: ;tag=sbcsipuas_1_C58173_20141125061541088_b59sb08 To: ;tag=as4da15014 Call-ID: 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 CSeq: 103 BYE Server: NGN voip2c Telecom Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Length: 0 <------------> [Nov 25 09:16:30] DEBUG[2428][C-00000000] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 216.53.4.1:5060 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 Variable: RTPAUDIOQOS Value: ssrc=935663094;themssrc=164586356;lp=0;rxjitter=0.000000;rxcount=1301;txjitter=0.000307;txcount=1765;rlp=0;rtt=0.000000 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: RTPAUDIOQOSBRIDGED Value: ssrc=935663094;themssrc=164586356;lp=0;rxjitter=0.000000;rxcount=1301;txjitter=0.000307;txcount=1765;rlp=0;rtt=0.000000 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: RTPAUDIOQOSJITTERBRIDGED Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: RTPAUDIOQOSLOSSBRIDGED Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: RTPAUDIOQOSRTTBRIDGED Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 [Nov 25 09:16:30] DEBUG[2590][C-00000000] bridge_channel.c: Setting 0x7fcaa4022df8(SIP/voip2cNT2P1-00000000) state from:0 to:1 [Nov 25 09:16:30] DEBUG[2590][C-00000000] bridge_channel.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: pulling 0x7fcaa4022df8(SIP/voip2cNT2P1-00000000) [Nov 25 09:16:30] VERBOSE[2590][C-00000000] bridge_channel.c: Channel SIP/voip2cNT2P1-00000000 left 'simple_bridge' basic-bridge [Nov 25 09:16:30] DEBUG[2590][C-00000000] bridge_channel.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: 0x7fcaa4022df8(SIP/voip2cNT2P1-00000000) is leaving simple_bridge technology [Nov 25 09:16:30] DEBUG[2590][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: dissolving bridge with cause 16(Normal Clearing) [Nov 25 09:16:30] DEBUG[2590][C-00000000] bridge_channel.c: Setting 0x7fcaa4023128(Local/881000ClicktoCall@a2billing-did2-00000000;2) state from:0 to:2 [Nov 25 09:16:30] DEBUG[2590][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: queueing action type:13 sub:1001 [Nov 25 09:16:30] DEBUG[2590][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641 is dissolved, not performing smart bridge operation. [Nov 25 09:16:30] DEBUG[2590][C-00000000] channel.c: Hanging up channel 'SIP/voip2cNT2P1-00000000' [Nov 25 09:16:30] DEBUG[2590][C-00000000] chan_sip.c: Hangup call SIP/voip2cNT2P1-00000000, SIP callid 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:16:30] DEBUG[2590][C-00000000] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fcaa400e2e8' [Nov 25 09:16:30] DEBUG[1964] devicestate.c: No provider found, checking channel drivers for SIP - voip2cNT2P1 [Nov 25 09:16:30] DEBUG[1964] chan_sip.c: Checking device state for peer voip2cNT2P1 [Nov 25 09:16:30] DEBUG[1964] devicestate.c: Changing state for SIP/voip2cNT2P1 - state 1 (Not in use) [Nov 25 09:16:30] DEBUG[1965] cdr.c: Finalized CDR for Local/881000ClicktoCall@a2billing-did2-00000000;2 - start 1416914140.874848 answer 1416914152.939764 end 1416914190.260930 dispo ANSWERED [Nov 25 09:16:30] DEBUG[1965] cdr.c: CDR for SIP/voip2cNT2P1-00000000 is dialed and has no Party B; discarding [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: f77752b3-f867-4059-a83a-971b1b263641 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: SIP/voip2cNT2P1-00000000 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 881000ClicktoCall CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914141.2 Cause: 16 Cause-txt: Normal Clearing [Nov 25 09:16:30] DEBUG[2585][C-00000000] bridge_channel.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: pulling 0x7fcaa4023128(Local/881000ClicktoCall@a2billing-did2-00000000;2) [Nov 25 09:16:30] VERBOSE[2585][C-00000000] bridge_channel.c: Channel Local/881000ClicktoCall@a2billing-did2-00000000;2 left 'simple_bridge' basic-bridge [Nov 25 09:16:30] DEBUG[2585][C-00000000] bridge_channel.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: 0x7fcaa4023128(Local/881000ClicktoCall@a2billing-did2-00000000;2) is leaving simple_bridge technology [Nov 25 09:16:30] DEBUG[2585][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641 is dissolved, not performing smart bridge operation. [Nov 25 09:16:30] DEBUG[2585][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: actually destroying basic bridge, nobody wants it anymore [Nov 25 09:16:30] DEBUG[2585][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: calling basic bridge destructor [Nov 25 09:16:30] DEBUG[2585][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: calling simple_bridge technology stop [Nov 25 09:16:30] DEBUG[2585][C-00000000] bridge.c: Bridge f77752b3-f867-4059-a83a-971b1b263641: calling simple_bridge technology destructor [Nov 25 09:16:30] DEBUG[2585][C-00000000] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: f77752b3-f867-4059-a83a-971b1b263641 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeDestroy Privilege: call,all BridgeUniqueid: f77752b3-f867-4059-a83a-971b1b263641 BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: ANSWEREDTIME Value: 37 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: DIALEDTIME Value: 49 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: DIALSTATUS Value: ANSWER [Nov 25 09:16:30] DEBUG[2585][C-00000000] pbx.c: Result of 'ANSWEREDTIME' is '37' [Nov 25 09:16:30] DEBUG[2585][C-00000000] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [Nov 25 09:16:30] DEBUG[2595][C-00000001] res_rtp_asterisk.c: Changing ssrc from 50958472 to 1793565424 due to a source change [Nov 25 09:16:30] VERBOSE[2585][C-00000000] res_agi.c: AGI Script a2billing.php completed, returning 0 [Nov 25 09:16:30] VERBOSE[2585][C-00000000] pbx.c: Auto fallthrough, channel 'Local/881000ClicktoCall@a2billing-did2-00000000;2' status is 'ANSWER' [Nov 25 09:16:30] DEBUG[2585][C-00000000] channel.c: Soft-Hanging (0x10) up channel 'Local/881000ClicktoCall@a2billing-did2-00000000;2' [Nov 25 09:16:30] DEBUG[2585][C-00000000] channel.c: Soft-Hanging (0x80) up channel 'Local/881000ClicktoCall@a2billing-did2-00000000;2' [Nov 25 09:16:30] DEBUG[2585][C-00000000] pbx.c: Launching 'Hangup' [Nov 25 09:16:30] VERBOSE[2585][C-00000000] pbx.c: Executing [h@a2billing-did2:1] Hangup("Local/881000ClicktoCall@a2billing-did2-00000000;2", "") in new stack [Nov 25 09:16:30] DEBUG[2585][C-00000000] channel.c: Soft-Hanging (0x20) up channel 'Local/881000ClicktoCall@a2billing-did2-00000000;2' [Nov 25 09:16:30] DEBUG[2585][C-00000000] pbx.c: Spawn extension (a2billing-did2,h,1) exited non-zero on 'Local/881000ClicktoCall@a2billing-did2-00000000;2' [Nov 25 09:16:30] VERBOSE[2585][C-00000000] pbx.c: Spawn extension (a2billing-did2, h, 1) exited non-zero on 'Local/881000ClicktoCall@a2billing-did2-00000000;2' [Nov 25 09:16:30] DEBUG[2585][C-00000000] channel.c: Hanging up channel 'Local/881000ClicktoCall@a2billing-did2-00000000;2' [Nov 25 09:16:30] DEBUG[2584][C-00000001] bridge_channel.c: Setting 0x7fcaa871d988(Local/881000ClicktoCall@a2billing-did2-00000000;1) state from:0 to:1 [Nov 25 09:16:30] DEBUG[2584][C-00000001] bridge_channel.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: pulling 0x7fcaa871d988(Local/881000ClicktoCall@a2billing-did2-00000000;1) [Nov 25 09:16:30] VERBOSE[2584][C-00000001] bridge_channel.c: Channel Local/881000ClicktoCall@a2billing-did2-00000000;1 left 'simple_bridge' basic-bridge <9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e> [Nov 25 09:16:30] DEBUG[2584][C-00000001] bridge_channel.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: 0x7fcaa871d988(Local/881000ClicktoCall@a2billing-did2-00000000;1) is leaving simple_bridge technology [Nov 25 09:16:30] DEBUG[2584][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: dissolving bridge with cause 16(Normal Clearing) [Nov 25 09:16:30] DEBUG[2584][C-00000001] bridge_channel.c: Setting 0x7fcaa88930a8(SIP/voip2cNT2P1-00000001) state from:0 to:2 [Nov 25 09:16:30] DEBUG[2584][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: queueing action type:13 sub:1001 [Nov 25 09:16:30] DEBUG[2584][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e is dissolved, not performing smart bridge operation. [Nov 25 09:16:30] DEBUG[2584][C-00000001] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Nov 25 09:16:30] DEBUG[2584][C-00000001] res_agi.c: Local/881000ClicktoCall@a2billing-did2-00000000;1 hungup [Nov 25 09:16:30] DEBUG[1964] devicestate.c: No provider found, checking channel drivers for Local - 881000ClicktoCall@a2billing-did2 [Nov 25 09:16:30] DEBUG[1964] devicestate.c: Changing state for Local/881000ClicktoCall@a2billing-did2 - state 1 (Not in use) [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 1 Uniqueid: 1416914140.1 Variable: AGISTATUS Value: SUCCESS [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: 881000ClicktoCall Priority: 2 Uniqueid: 1416914140.1 Cause: 16 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: h Priority: 1 Uniqueid: 1416914140.1 Extension: h Application: Hangup AppData: [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: HangupRequest Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Cause: 16 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;2 ChannelState: 5 ChannelStateDesc: Ringing CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-did2 Exten: h Priority: 1 Uniqueid: 1416914140.1 Cause: 16 Cause-txt: Normal Clearing [Nov 25 09:16:30] DEBUG[2595][C-00000001] bridge_channel.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: pulling 0x7fcaa88930a8(SIP/voip2cNT2P1-00000001) [Nov 25 09:16:30] VERBOSE[2595][C-00000001] bridge_channel.c: Channel SIP/voip2cNT2P1-00000001 left 'simple_bridge' basic-bridge <9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e> [Nov 25 09:16:30] DEBUG[2595][C-00000001] bridge_channel.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: 0x7fcaa88930a8(SIP/voip2cNT2P1-00000001) is leaving simple_bridge technology [Nov 25 09:16:30] DEBUG[2595][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e is dissolved, not performing smart bridge operation. [Nov 25 09:16:30] DEBUG[2595][C-00000001] res_rtp_asterisk.c: Changing ssrc from 1793565424 to 1231416228 due to a source change [Nov 25 09:16:30] DEBUG[2595][C-00000001] channel.c: Hanging up channel 'SIP/voip2cNT2P1-00000001' [Nov 25 09:16:30] DEBUG[2595][C-00000001] chan_sip.c: Hangup call SIP/voip2cNT2P1-00000001, SIP callid 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:16:30] DEBUG[2595][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7fcaa86ab2c8' [Nov 25 09:16:30] VERBOSE[2595][C-00000001] chan_sip.c: Scheduling destruction of SIP dialog '64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060' in 32000 ms (Method: INVITE) [Nov 25 09:16:30] DEBUG[2595][C-00000001] chan_sip.c: Strict routing enforced for session 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:16:30] VERBOSE[2595][C-00000001] chan_sip.c: Reliably Transmitting (NAT) to 216.53.4.1:5060: BYE sip:216.53.4.1:5060 SIP/2.0 Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK06877f0f;rport Max-Forwards: 70 From: ;tag=as3db1ebee To: ;tag=sbcsipuas_1_C31790_20141125061553170_b12sb09 Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 CSeq: 103 BYE User-Agent: NGN voip2c Telecom X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Nov 25 09:16:30] DEBUG[2595][C-00000001] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #418 [Nov 25 09:16:30] DEBUG[2595][C-00000001] chan_sip.c: Trying to put 'BYE sip:216' onto UDP socket destined for 216.53.4.1:5060 [Nov 25 09:16:30] DEBUG[1963][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: actually destroying basic bridge, nobody wants it anymore [Nov 25 09:16:30] DEBUG[1963][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: calling basic bridge destructor [Nov 25 09:16:30] DEBUG[1963][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: calling simple_bridge technology stop [Nov 25 09:16:30] DEBUG[1963][C-00000001] bridge.c: Bridge 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e: calling simple_bridge technology destructor [Nov 25 09:16:30] DEBUG[2457] app_queue.c: Device 'Local/881000ClicktoCall@a2billing-did2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 25 09:16:30] DEBUG[1964] devicestate.c: No provider found, checking channel drivers for SIP - voip2cNT2P1 [Nov 25 09:16:30] DEBUG[1964] chan_sip.c: Checking device state for peer voip2cNT2P1 [Nov 25 09:16:30] DEBUG[1964] devicestate.c: Changing state for SIP/voip2cNT2P1 - state 1 (Not in use) [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 1 Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: ANSWEREDTIME Value: 0 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: DIALEDTIME Value: 49 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: DIALSTATUS Value: ANSWER [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeLeave Privilege: call,all BridgeUniqueid: 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 Variable: RTPAUDIOQOS Value: ssrc=1231416228;themssrc=561748829;lp=160286;rxjitter=0.000000;rxcount=1418;txjitter=0.000385;txcount=895;rlp=0;rtt=0.000000 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 Variable: RTPAUDIOQOSJITTER Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000; [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 Variable: RTPAUDIOQOSLOSS Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000; [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 Variable: RTPAUDIOQOSRTT Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000; [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 Variable: RTPAUDIOQOS Value: ssrc=1231416228;themssrc=561748829;lp=160286;rxjitter=0.000000;rxcount=1418;txjitter=0.000385;txcount=895;rlp=0;rtt=0.000000 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: SIP/voip2cNT2P1-00000001 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing Exten: Priority: 1 Uniqueid: 1416914153.3 Cause: 16 Cause-txt: Normal Clearing [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: BridgeDestroy Privilege: call,all BridgeUniqueid: 9d9c3ccb-db09-4f26-a9a5-a7ea6f8de74e BridgeType: basic BridgeTechnology: simple_bridge BridgeCreator: BridgeName: BridgeNumChannels: 0 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/881000ClicktoCall@a2billing-did2 State: NOT_INUSE [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1336 - uniqueid:1416914140.0 - DIAL SIP/voip2cNT2P1/99901553438181636|37|HRrL(1800000) [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1223 - uniqueid:1416914140.0 - [TRUNK STATUS UPDATE : UPDATE cc_trunk SET inuse = inuse - 1 WHERE id_trunk = '36'] [Nov 25 09:16:30] DEBUG[2584][C-00000001] pbx.c: Result of 'ANSWEREDTIME' is '0' [Nov 25 09:16:30] DEBUG[2584][C-00000001] pbx.c: Result of 'DIALSTATUS' is 'ANSWER' [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1486 - uniqueid:1416914140.0 - -> dialstatus : ANSWER, answered time is 0 [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1490 - uniqueid:1416914140.0 - [USEDRATECARD=0] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1038 - uniqueid:1416914140.0 - :[sessiontime:0 - id_cc_package_offer:-1 - package2apply:] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1114 - uniqueid:1416914140.0 - [CC_RATE_ENGINE_UPDATESYSTEM: usedratecard K=0 - (sessiontime=0 :: dialstatus=ANSWER :: buycost=0 :: cost= : signe_cc_call=-: signe=+)] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1174 - uniqueid:1416914140.0 - [CC_asterisk_stop : SQL: DONE : result=1] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1175 - uniqueid:1416914140.0 - [CC_asterisk_stop : SQL: INSERT INTO cc_call (uniqueid, sessionid, card_id, nasipaddress, starttime, sessiontime, real_sessiontime, calledstation, terminatecauseid, stoptime, sessionbill, id_tariffgroup, id_tariffplan, id_ratecard, id_trunk, src, sipiax, buycost, id_card_package_offer, dnid, destination , a2b_custom1, a2b_custom2) VALUES ('1416914140.0', '', '1', '', SUBDATE(CURRENT_TIMESTAMP, INTERVAL 0 SECOND) , '0', '0', '3438181636', 1, now() , '-0', '1', '10', '22235', '36', '3438181636', '0', '0', NULL, '3438181636', '343818' , '', '')] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1192 - uniqueid:1416914140.0 - [CALLBACK]:[a2billing end loop num_try] RateEngine->usedratecard=0 [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:780 - uniqueid:1416914140.0 - [CARD STATUS UPDATE] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:789 - uniqueid:1416914140.0 - [QUERY USING CARD UPDATE::> UPDATE cc_card SET inuse = inuse - 1, credit = credit + 0.25 WHERE username = '7341621469'] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1539 - uniqueid:1416914140.0 - [CALLBACK 1ST LEG]:[INFO FOR THE 1ST LEG - callback_username=7341621469 [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1540 - uniqueid:1416914140.0 - [CALLBACK 1ST LEG]:[TRY : callingcard_ivr_authenticate] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:2869 - uniqueid:1416914140.0 - - Account code ::> 7341621469 [Nov 25 09:16:30] DEBUG[1965] cdr.c: Finalized CDR for Local/881000ClicktoCall@a2billing-did2-00000000;1 - start 1416914152.939789 answer 1416914152.939783 end 1416914190.291450 dispo ANSWERED [Nov 25 09:16:30] DEBUG[1965] cdr.c: CDR for SIP/voip2cNT2P1-00000001 is dialed and has no Party B; discarding [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:2886 - uniqueid:1416914140.0 - - Retrieve account info SQL ::> SELECT credit, tariff, activated, inuse, simultaccess, typepaid, creditlimit, language, removeinterprefix, redial, enableexpire, UNIX_TIMESTAMP(expirationdate), expiredays, nbused, UNIX_TIMESTAMP(firstusedate), UNIX_TIMESTAMP(cc_card.creationdate), cc_card.currency, cc_card.lastname, cc_card.firstname, cc_card.email, cc_card.uipass, cc_card.id_campaign, cc_card.id, useralias, status, voicemail_permitted, voicemail_activated, cc_card.restriction, cc_country.countryprefix FROM cc_card LEFT JOIN cc_tariffgroup ON tariff = cc_tariffgroup.id LEFT JOIN cc_country ON cc_card.country = cc_country.countrycode WHERE username = '7341621469' [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:2959 - uniqueid:1416914140.0 - [credit=45.33381 :: tariff=1 :: status=1 :: isused=0 :: simultaccess=1 :: typepaid=0 :: creditlimit= :: language=br] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:780 - uniqueid:1416914140.0 - [CARD STATUS UPDATE] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:789 - uniqueid:1416914140.0 - [QUERY USING CARD UPDATE::> UPDATE cc_card SET inuse = inuse + 1, credit = credit - 0.25 WHERE username = '7341621469'] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1551 - uniqueid:1416914140.0 - [CALLBACK 1ST LEG]:[MAKE BILLING FOR THE 1ST LEG - TARIFF:1;CALLED=7341621469] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:97 - uniqueid:1416914140.0 - [CC_asterisk_rate-engine: (1, 7341621469)] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:118 - uniqueid:1416914140.0 - [CC_asterisk_rate-engine - CALLERID : 3438181636] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:179 - uniqueid:1416914140.0 - [rate-engine: Count Total result 2] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:344 - uniqueid:1416914140.0 - [CC_asterisk_rate-engine: Count Total result 1] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:345 - uniqueid:1416914140.0 - [CC_asterisk_rate-engine: number_trunk 1] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:358 - uniqueid:1416914140.0 - [CC_RATE_ENGINE_ALL_CALCULTIMEOUT (45.33381)] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:364 - uniqueid:1416914140.0 - [CC_RATE_ENGINE_ALL_CALCULTIMEOUT: k=0 - res_calcultimeout:5400] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:a2billing.php - line:1566 - uniqueid:1416914140.0 - [CALLBACK]:[RateEngine->answeredtime=37] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1038 - uniqueid:1416914140.0 - :[sessiontime:37 - id_cc_package_offer:-1 - package2apply:] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:807 - uniqueid:1416914140.0 - [CC_RATE_ENGINE_CALCULCOST: K=0 - CALLDURATION:37 - freetimetocall_used=0 - freetimetocall_left=0] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:889 - uniqueid:1416914140.0 - [TEMP - CC_RATE_ENGINE_CALCULCOST: 1. COST: 0]:[ (42/60) * 0 ] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:974 - uniqueid:1416914140.0 - [CC_RATE_ENGINE_CALCULCOST: K=0 - BUYCOST:0 - SELLING COST:0] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1114 - uniqueid:1416914140.0 - [CC_RATE_ENGINE_UPDATESYSTEM: usedratecard K=0 - (sessiontime=37 :: dialstatus=ANSWERED :: buycost=0 :: cost=0 : signe_cc_call=-: signe=+)] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1174 - uniqueid:1416914140.0 - [CC_asterisk_stop : SQL: DONE : result=1] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1175 - uniqueid:1416914140.0 - [CC_asterisk_stop : SQL: INSERT INTO cc_call (uniqueid, sessionid, card_id, nasipaddress, starttime, sessiontime, real_sessiontime, calledstation, terminatecauseid, stoptime, sessionbill, id_tariffgroup, id_tariffplan, id_ratecard, id_trunk, src, sipiax, buycost, id_card_package_offer, dnid, destination , a2b_custom1, a2b_custom2) VALUES ('1416914140.0', '', '1', '', SUBDATE(CURRENT_TIMESTAMP, INTERVAL 37 SECOND) , '37', '37', '7341621469', 1, now() , '-0', '1', '15', '22210', '36', '3438181636', '4', '0', NULL, '7341621469', '803' , '', '')] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1199 - uniqueid:1416914140.0 - [CC_asterisk_stop 1.2: SQL: UPDATE cc_card SET credit = credit+0 , lastuse = now(), nbused = nbused + 1 WHERE username = '7341621469'] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1203 - uniqueid:1416914140.0 - UPDATE cc_trunk SET secondusedreal = secondusedreal + 37 WHERE id_trunk = '36' [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.RateEngine.php - line:1207 - uniqueid:1416914140.0 - UPDATE cc_tariffplan SET secondusedreal = secondusedreal + 37 WHERE id = '15' [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:780 - uniqueid:1416914140.0 - [CARD STATUS UPDATE] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: a2billing.php,6,callback: file:Class.A2Billing.php - line:789 - uniqueid:1416914140.0 - [QUERY USING CARD UPDATE::> UPDATE cc_card SET inuse = inuse - 1, credit = credit + 0.25 WHERE username = '7341621469'] [Nov 25 09:16:30] VERBOSE[2584][C-00000001] res_agi.c: AGI Script a2billing.php completed, returning 4 [Nov 25 09:16:30] DEBUG[2584][C-00000001] pbx.c: Spawn extension (a2billing-callback,3438181636,1) exited non-zero on 'Local/881000ClicktoCall@a2billing-did2-00000000;1' [Nov 25 09:16:30] VERBOSE[2584][C-00000001] pbx.c: Spawn extension (a2billing-callback, 3438181636, 1) exited non-zero on 'Local/881000ClicktoCall@a2billing-did2-00000000;1' [Nov 25 09:16:30] DEBUG[2584][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'Local/881000ClicktoCall@a2billing-did2-00000000;1' [Nov 25 09:16:30] DEBUG[2584][C-00000001] channel.c: Soft-Hanging (0x80) up channel 'Local/881000ClicktoCall@a2billing-did2-00000000;1' [Nov 25 09:16:30] DEBUG[2584][C-00000001] pbx.c: Launching 'Hangup' [Nov 25 09:16:30] VERBOSE[2584][C-00000001] pbx.c: Executing [h@a2billing-callback:1] Hangup("Local/881000ClicktoCall@a2billing-did2-00000000;1", "") in new stack [Nov 25 09:16:30] DEBUG[2584][C-00000001] channel.c: Soft-Hanging (0x20) up channel 'Local/881000ClicktoCall@a2billing-did2-00000000;1' [Nov 25 09:16:30] DEBUG[2584][C-00000001] pbx.c: Spawn extension (a2billing-callback,h,1) exited non-zero on 'Local/881000ClicktoCall@a2billing-did2-00000000;1' [Nov 25 09:16:30] VERBOSE[2584][C-00000001] pbx.c: Spawn extension (a2billing-callback, h, 1) exited non-zero on 'Local/881000ClicktoCall@a2billing-did2-00000000;1' [Nov 25 09:16:30] DEBUG[2584][C-00000001] channel.c: Hanging up channel 'Local/881000ClicktoCall@a2billing-did2-00000000;1' [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: VarSet Privilege: dialplan,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Variable: AGISTATUS Value: HANGUP [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: SoftHangupRequest Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: 3438181636 Priority: 1 Uniqueid: 1416914140.0 Cause: 16 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: Newexten Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: h Priority: 1 Uniqueid: 1416914140.0 Extension: h Application: Hangup AppData: [Nov 25 09:16:30] DEBUG[1964] devicestate.c: No provider found, checking channel drivers for Local - 881000ClicktoCall@a2billing-did2 [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: Hangup Privilege: call,all Channel: Local/881000ClicktoCall@a2billing-did2-00000000;1 ChannelState: 6 ChannelStateDesc: Up CallerIDNum: 3438181636 CallerIDName: ConnectedLineNum: 3438181636 ConnectedLineName: AccountCode: 7341621469 Context: a2billing-callback Exten: h Priority: 1 Uniqueid: 1416914140.0 Cause: 16 Cause-txt: Normal Clearing [Nov 25 09:16:30] DEBUG[1964] core_local.c: Checking if extension 881000ClicktoCall@a2billing-did2 exists (devicestate) [Nov 25 09:16:30] DEBUG[1964] devicestate.c: Changing state for Local/881000ClicktoCall@a2billing-did2 - state 1 (Not in use) [Nov 25 09:16:30] DEBUG[2457] app_queue.c: Device 'Local/881000ClicktoCall@a2billing-did2' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Nov 25 09:16:30] DEBUG[2581] manager.c: Examining AMI event: Event: DeviceStateChange Privilege: call,all Device: Local/881000ClicktoCall@a2billing-did2 State: NOT_INUSE [Nov 25 09:16:30] VERBOSE[2428] chan_sip.c: <--- SIP read from UDP:216.53.4.1:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK06877f0f;received=154.232.196.179;rport=5060 From: ;tag=as3db1ebee To: ;tag=sbcsipuas_1_C31790_20141125061553170_b12sb09 Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 CSeq: 103 BYE Server: sbc_5 Content-Length: 0 <-------------> [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 1 [ 94]: Via: SIP/2.0/UDP 154.232.196.179:5060;branch=z9hG4bK06877f0f;received=154.232.196.179;rport=5060 [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 2 [ 52]: From: ;tag=as3db1ebee [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 3 [ 92]: To: ;tag=sbcsipuas_1_C31790_20141125061553170_b12sb09 [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 4 [ 61]: Call-ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 5 [ 13]: CSeq: 103 BYE [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 6 [ 13]: Server: sbc_5 [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [Nov 25 09:16:30] VERBOSE[2428] chan_sip.c: --- (8 headers 0 lines) --- [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: = Looking for Call ID: 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 (Checking To) --From tag as3db1ebee --To-tag sbcsipuas_1_C31790_20141125061553170_b12sb09 [Nov 25 09:16:30] DEBUG[2428][C-00000001] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #418 [Nov 25 09:16:30] DEBUG[2428][C-00000001] chan_sip.c: Stopping retransmission on '64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060' of Request 103: Match Found [Nov 25 09:16:30] DEBUG[2428] chan_sip.c: Destroying SIP dialog 64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060 [Nov 25 09:16:30] VERBOSE[2428] chan_sip.c: Really destroying SIP dialog '64b970611ca7f7123f62839b21d4a9a2@154.232.196.179:5060' Method: INVITE [Nov 25 09:16:30] DEBUG[2428] rtp_engine.c: Destroyed RTP instance '0x7fcaa86ab2c8' [Nov 25 09:17:02] DEBUG[2428] chan_sip.c: Auto destroying SIP dialog '27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060' [Nov 25 09:17:02] DEBUG[2428] chan_sip.c: Destroying SIP dialog 27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060 [Nov 25 09:17:02] VERBOSE[2428] chan_sip.c: Really destroying SIP dialog '27a086d4727d10eb376669a6613bb0b8@154.232.196.179:5060' Method: BYE [Nov 25 09:17:02] DEBUG[2428] rtp_engine.c: Destroyed RTP instance '0x7fcaa400e2e8'