[Jul 10 21:19:47] DEBUG[47765] pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x7ff0c8003e68) [Jul 10 21:19:47] VERBOSE[47765] res_pjsip_logger.c: <--- Received SIP request (872 bytes) from UDP:2.2.2.2:33744 ---> ˙INVITE sip:17274428141@1.1.1.1;transport=udp SIP/2.0 ˙Via: SIP/2.0/UDP 2.2.2.2:33744;branch=z9hG4bK-d8754z-2d644b7b4ae71527-1---d8754z-;rport ˙Max-Forwards: 70 ˙Contact: ˙To: ˙From: "7274907254";tag=97375f4d ˙Call-ID: YzM1ZDcwMDE2YzQ4Y2M5NDE2M2UzMmE0Y2NlZDMzZTY ˙CSeq: 1 INVITE ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO ˙Content-Type: application/sdp ˙Supported: replaces ˙User-Agent: Bria 3 release 3.5.5 stamp 71238 ˙Content-Length: 260 ˙ ˙v=0 ˙o=- 13049515176944184 1 IN IP4 2.2.2.2 ˙s=Bria 3 release 3.5.5 stamp 71238 ˙c=IN IP4 2.2.2.2 ˙t=0 0 ˙m=audio 58148 RTP/AVP 0 18 101 ˙a=rtpmap:18 G729/8000 ˙a=fmtp:18 annexb=yes ˙a=rtpmap:101 telephone-event/8000 ˙a=fmtp:101 0-15 ˙a=sendrecv ˙ [Jul 10 21:19:47] DEBUG[52480] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x7ff0c8005db8) [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_user.c: Could not identify endpoint by username '7274907254' [Jul 10 21:19:47] DEBUG[52480] netsock2.c: Splitting '2.2.2.2' into... [Jul 10 21:19:47] DEBUG[52480] netsock2.c: ...host '2.2.2.2' and port ''. [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.1' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.2' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.3' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.4' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.5' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.6' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.7' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.8' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.9' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.10' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.11' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.12' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.13' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.14' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.15' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.16' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.17' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.18' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.19' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 matches identify 'Client.2.2.2.2' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint Client.2.2.2.2 [Jul 10 21:19:47] DEBUG[52480] pjsip: tsx0x7ff98c005 ..Transaction created for Request msg INVITE/cseq=1 (rdata0x7ff0c8005db8) [Jul 10 21:19:47] DEBUG[52480] pjsip: tsx0x7ff98c005 .Incoming Request msg INVITE/cseq=1 (rdata0x7ff0c8005db8) in state Null [Jul 10 21:19:47] DEBUG[52480] pjsip: tsx0x7ff98c005 ..State changed from Null to Trying, event=RX_MSG [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 ...Transaction tsx0x7ff98c005008 state changed to Trying [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 .UAS dialog created [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 .Module mod-invite added as dialog usage, data=0x7ff95c004f28 [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 ..Session count inc to 2 by mod-invite [Jul 10 21:19:47] DEBUG[52480] pjsip: inv0x7ff98c007 .UAS invite session created for dialog dlg0x7ff98c007008 [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 .Module Session Module added as dialog usage, data=(nil) [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 ..Session count inc to 2 by Session Module [Jul 10 21:19:47] DEBUG[52480] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52480] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52480] netsock2.c: Splitting '2.2.2.2' into... [Jul 10 21:19:47] DEBUG[52480] netsock2.c: ...host '2.2.2.2' and port ''. [Jul 10 21:19:47] DEBUG[52480] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7ff95c00d0e8' [Jul 10 21:19:47] DEBUG[52480] res_rtp_asterisk.c: Allocated port 11700 for RTP instance '0x7ff95c00d0e8' [Jul 10 21:19:47] DEBUG[52480] pjsip: icess0x7ff95c0 ICE session created, comp_cnt=2, role is Unknown agent [Jul 10 21:19:47] DEBUG[52480] netsock2.c: Splitting '1.1.1.1' into... [Jul 10 21:19:47] DEBUG[52480] netsock2.c: ...host '1.1.1.1' and port ''. [Jul 10 21:19:47] DEBUG[52480] pjsip: icess0x7ff95c0 Candidate 0 added: comp_id=1, type=host, foundation=Hd04ea2dd, addr=1.1.1.1:11700, base=1.1.1.1:11700, prio=0x7effffff (2130706431) [Jul 10 21:19:47] DEBUG[52480] rtp_engine.c: RTP instance '0x7ff95c00d0e8' is setup and ready to go [Jul 10 21:19:47] DEBUG[52480] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7ff95c00d0e8' [Jul 10 21:19:47] DEBUG[52480] netsock2.c: Splitting '1.1.1.1' into... [Jul 10 21:19:47] DEBUG[52480] netsock2.c: ...host '1.1.1.1' and port ''. [Jul 10 21:19:47] DEBUG[52480] pjsip: icess0x7ff95c0 Candidate 1 added: comp_id=2, type=host, foundation=Hd04ea2dd, addr=1.1.1.1:11701, base=1.1.1.1:11701, prio=0x7efffffe (2130706430) [Jul 10 21:19:47] DEBUG[52480] pjsip: icess0x7ff95c0 Destroying ICE session 0x7ff95c014f68 [Jul 10 21:19:47] DEBUG[52480] pjsip: stuse0x7ff95c0 STUN session 0x7ff95c0042a8 destroy request, ref_cnt=4 [Jul 10 21:19:47] DEBUG[52480] pjsip: stuse0x7ff95c0 STUN session 0x7ff95c017388 destroy request, ref_cnt=3 [Jul 10 21:19:47] DEBUG[52480] pjsip: ice_session.c ICE session 0x7ff95c014f68 destroyed [Jul 10 21:19:47] DEBUG[52480] pjsip: stun_session.c STUN session 0x7ff95c0042a8 destroyed [Jul 10 21:19:47] DEBUG[52480] pjsip: stun_session.c STUN session 0x7ff95c017388 destroyed [Jul 10 21:19:47] DEBUG[52480] rtp_engine.c: Setting payload 0 based on m type on 0x7ff998137380 [Jul 10 21:19:47] DEBUG[52480] rtp_engine.c: Setting payload 18 based on m type on 0x7ff998137380 [Jul 10 21:19:47] DEBUG[52480] rtp_engine.c: Setting payload 101 based on m type on 0x7ff998137380 [Jul 10 21:19:47] DEBUG[52480] rtp_engine.c: Copying payload 0 from 0x7ff998137380 to 0x7ff95c00d228 [Jul 10 21:19:47] DEBUG[52480] rtp_engine.c: Copying payload 18 from 0x7ff998137380 to 0x7ff95c00d228 [Jul 10 21:19:47] DEBUG[52480] rtp_engine.c: Copying payload 101 from 0x7ff998137380 to 0x7ff95c00d228 [Jul 10 21:19:47] DEBUG[52480] pjsip: endpoint .Response msg 100/INVITE/cseq=1 (tdta0x7ff98c003f50) created [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 .Initial answer Response msg 100/INVITE/cseq=1 (tdta0x7ff98c003f50) [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Jul 10 21:19:47] DEBUG[52480] pjsip: inv0x7ff98c007 .Sending Response msg 100/INVITE/cseq=1 (tdta0x7ff98c003f50) [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7ff98c003f50) [Jul 10 21:19:47] DEBUG[52480] pjsip: tsx0x7ff98c005 ..Sending Response msg 100/INVITE/cseq=1 (tdta0x7ff98c003f50) in state Trying [Jul 10 21:19:47] VERBOSE[52480] res_pjsip_logger.c: <--- Transmitting SIP response (308 bytes) to UDP:2.2.2.2:33744 ---> ˙SIP/2.0 100 Trying ˙v: SIP/2.0/UDP 2.2.2.2:33744;rport;received=2.2.2.2;branch=z9hG4bK-d8754z-2d644b7b4ae71527-1---d8754z- ˙i: YzM1ZDcwMDE2YzQ4Y2M5NDE2M2UzMmE0Y2NlZDMzZTY ˙f: "7274907254" ;tag=97375f4d ˙t: ˙CSeq: 1 INVITE ˙l: 0 ˙ ˙ [Jul 10 21:19:47] DEBUG[52480] pjsip: tsx0x7ff98c005 ...State changed from Trying to Proceeding, event=TX_MSG [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 ....Transaction tsx0x7ff98c005008 state changed to Proceeding [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The state change pertains to the session with Client.2.2.2.2 [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff98c005008) [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: There is no transaction involved in this state change [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The current inv state is INCOMING [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Sending response [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Method is INVITE, Response is 100 Trying [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The state change pertains to the session with Client.2.2.2.2 [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff98c005008) [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The transaction involved in this state change is 0x7ff98c005008 [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The current transaction state is Proceeding [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The transaction state change event is TX_MSG [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The current inv state is INCOMING [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Method is INVITE [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 Module NAT added as dialog usage, data=(nil) [Jul 10 21:19:47] DEBUG[52480] chan_pjsip.c: Started PBX on new PJSIP channel PJSIP/Client.2.2.2.2-00000001 [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_strings.c: c1=48, c2=57 [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_strings.c: Allowed: 0123456789 [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function FILTER(0-9,17274428141) result is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Goto' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@inbound:1] Goto("PJSIP/Client.2.2.2.2-00000001", "inboundfiltered,17274428141,1") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Goto (inboundfiltered,17274428141,1) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _Z. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _Z. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Goto' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@inboundfiltered:1] Goto("PJSIP/Client.2.2.2.2-00000001", "inpoint,17274428141,1") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Goto (inpoint,17274428141,1) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@inpoint:1] Set("PJSIP/Client.2.2.2.2-00000001", "GROUP()=trunkgroup1") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CHANNEL(audiowriteformat) result is 'ulaw' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@inpoint:2] Set("PJSIP/Client.2.2.2.2-00000001", "CODEC=ulaw") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@inpoint:3] Set("PJSIP/Client.2.2.2.2-00000001", "CALLERID(name-pres)=allowed") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@inpoint:4] Set("PJSIP/Client.2.2.2.2-00000001", "CALLERID(num-pres)=allowed") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CHANNEL(channeltype) result is 'PJSIP' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'GotoIf' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@inpoint:5] GotoIf("PJSIP/Client.2.2.2.2-00000001", "0?h323,17274428141,1") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Not taking any branch [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CHANNEL(pjsip,remote_addr) result is '2.2.2.2:33744' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'GotoIf' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@inpoint:6] GotoIf("PJSIP/Client.2.2.2.2-00000001", "0?salida") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Not taking any branch [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function GROUP_COUNT(trunkgroup1) result is '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CALLERID(num) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CHANNEL(pjsip,remote_addr) result is '2.2.2.2:33744' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Verbose' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@inpoint:7] Verbose("PJSIP/Client.2.2.2.2-00000001", "2,ACTIVE CALLS 1 17274428141-ANI->7274907254 IP:->2.2.2.2:33744") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] app_verbose.c: == ACTIVE CALLS 1 17274428141-ANI->7274907254 IP:->2.2.2.2:33744 [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CHANNEL(pjsip,remote_addr) result is '2.2.2.2:33744' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'B2.2.2.2' is NULL [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function EXISTS() result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'GotoIf' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@inpoint:8] GotoIf("PJSIP/Client.2.2.2.2-00000001", "0?balancerx,17274428141,1") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Not taking any branch [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Goto' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@inpoint:9] Goto("PJSIP/Client.2.2.2.2-00000001", "gateway,17274428141,1") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Goto (gateway,17274428141,1) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Evaluating 'CHANNEL(pjsip,remote_addr)' (from 'CHANNEL(pjsip,remote_addr)}' len 26) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CHANNEL(pjsip,remote_addr) result is '2.2.2.2:33744' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CUT(CHANNEL(pjsip,remote_addr),\:,1) result is '2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@gateway:1] Set("PJSIP/Client.2.2.2.2-00000001", "SIPIP=C2.2.2.2") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SIPIP' is 'C2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Verbose' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@gateway:2] Verbose("PJSIP/Client.2.2.2.2-00000001", "2,Federico C2.2.2.2") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] app_verbose.c: == Federico C2.2.2.2 [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@gateway:3] Set("PJSIP/Client.2.2.2.2-00000001", "destino=17274428141") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'destino' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'destino' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'GotoIf' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@gateway:4] GotoIf("PJSIP/Client.2.2.2.2-00000001", "0?gateway,17274428141,turnpike") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Not taking any branch [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CALLERID(num) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CALLERID(num) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CALLERID(num) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function IF(0?274907254:7274907254) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@gateway:5] Set("PJSIP/Client.2.2.2.2-00000001", "CALLERID(num)=7274907254") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CALLERID(num) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CALLERID(num) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function IF(0?0000000000:7274907254) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@gateway:6] Set("PJSIP/Client.2.2.2.2-00000001", "CALLERID(num)=7274907254") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CALLERID(num) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@gateway:7] Set("PJSIP/Client.2.2.2.2-00000001", "CALLERID(name)=7274907254") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CALLERID(num) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@gateway:8] Set("PJSIP/Client.2.2.2.2-00000001", "anix=7274907254") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CHANNEL(channeltype) result is 'PJSIP' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CALLERID(num) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function CALLERID(name) result is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SIPIP' is 'C2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Verbose' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@gateway:9] Verbose("PJSIP/Client.2.2.2.2-00000001", "2,PJSIP--17274428141 From:7274907254 Name:7274907254 Origin: C2.2.2.2") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] app_verbose.c: == PJSIP--17274428141 From:7274907254 Name:7274907254 Origin: C2.2.2.2 [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SIPIP' is 'C2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'destino' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'C2.2.2.2P1727' is NULL [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function EXISTS() result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'GotoIf' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@gateway:10] GotoIf("PJSIP/Client.2.2.2.2-00000001", "0?gateway,hasprefix,1") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Not taking any branch [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SIPIP' is 'C2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'C2.2.2.2' is '145' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function EXISTS(145) result is '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'GotoIf' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@gateway:11] GotoIf("PJSIP/Client.2.2.2.2-00000001", "1?gateway,hasnoprefix,1") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Goto (gateway,hasnoprefix,1) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- first found-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SIPIP' is 'C2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'C2.2.2.2' is '145' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [hasnoprefix@gateway:1] Set("PJSIP/Client.2.2.2.2-00000001", "X=145") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- first found-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [hasnoprefix@gateway:2] Set("PJSIP/Client.2.2.2.2-00000001", "PREFIX=""") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Nothing strange about this match [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- first found-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- hasnoprefix [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'destino' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Goto' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [hasnoprefix@gateway:3] Goto("PJSIP/Client.2.2.2.2-00000001", "defaultproc,17274428141,1") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Goto (defaultproc,17274428141,1) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'X' is '145' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'H145' is 'E' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function EXISTS(E) result is '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'GotoIf' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@defaultproc:1] GotoIf("PJSIP/Client.2.2.2.2-00000001", "1?redirect,17274428141,1") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Goto (redirect,17274428141,1) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'PREFIX' is '""' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'X' is '145' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SIPIP' is 'C2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Verbose' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:1] Verbose("PJSIP/Client.2.2.2.2-00000001", "0,Redirect Prefix "" Client 145 from 2.2.2.2") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] app_verbose.c: Redirect Prefix "" Client 145 from 2.2.2.2 [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'NoCDR' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:2] NoCDR("PJSIP/Client.2.2.2.2-00000001", "") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Evaluating 'ARG1' (from 'ARG1}'' len 4) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'ARG1' is '7274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_odbc.c: Got collength of 3 and maxcol of 10 for column 'lrn' (offset 0) [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_odbc.c: Got coldata of '8134029999' [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_odbc.c: buf is now set to '8134029999' [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_odbc.c: Got collength of 6 and maxcol of 10 for column 'grtype' (offset 1) [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_odbc.c: Got coldata of '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_odbc.c: buf is now set to '8134029999,1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_odbc.c: buf is now set to '8134029999,1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] res_odbc.c: odbc_release_obj2(0x7ff9781cf248) called (obj->txf = (nil)) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function MYSQL_LRN(7274428141) result is '8134029999,1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:3] Set("PJSIP/Client.2.2.2.2-00000001", "ARRAY(LRN,GRTYPE)=8134029999,1") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_strings.c: array (LRN,GRTYPE=8134029999,1) [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_strings.c: array set value (LRN=8134029999) [Jul 10 21:19:47] DEBUG[52483][C-00000001] func_strings.c: array set value (GRTYPE=1) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'LRN' is '8134029999' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'LRN' is '8134029999' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function IF(0?0:8134029999) result is '8134029999' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:4] Set("PJSIP/Client.2.2.2.2-00000001", "LRN=8134029999") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'GRTYPE' is '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'GRTYPE' is '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function IF(0?0:1) result is '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:5] Set("PJSIP/Client.2.2.2.2-00000001", "GRTYPE=1") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'LRN' is '8134029999' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'LRN' is '8134029999' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function IF(0?7274428141:8134029999) result is '8134029999' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:6] Set("PJSIP/Client.2.2.2.2-00000001", "LRNX=8134029999") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'anix' is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'X' is '145' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'CODEC' is 'ulaw' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'LRN' is '8134029999' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'GRTYPE' is '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Verbose' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:7] Verbose("PJSIP/Client.2.2.2.2-00000001", "2,17274428141,7274907254,145,ulaw,8134029999,1") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] app_verbose.c: == 17274428141,7274907254,145,ulaw,8134029999,1 [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'X' is '145' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'H145' is 'E' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:8] Set("PJSIP/Client.2.2.2.2-00000001", "FM=E") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'FM' is 'E' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Verbose' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:9] Verbose("PJSIP/Client.2.2.2.2-00000001", "2,Redirection Format E") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] app_verbose.c: == Redirection Format E [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'anix' is '7274907254' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:10] Set("PJSIP/Client.2.2.2.2-00000001", "CALLERID(all)=7274907254") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SIPIP' is 'C2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:11] Set("PJSIP/Client.2.2.2.2-00000001", "CHANNEL(accountcode)=2.2.2.2") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function SPRINTF(%c,59) result is ';' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:12] Set("PJSIP/Client.2.2.2.2-00000001", "SC=;") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function SPRINTF(%c,58) result is ':' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:13] Set("PJSIP/Client.2.2.2.2-00000001", "COLON=:") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'FM' is 'E' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'GotoIf' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:14] GotoIf("PJSIP/Client.2.2.2.2-00000001", "0?formatb") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Not taking any branch [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'FM' is 'E' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'GotoIf' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:15] GotoIf("PJSIP/Client.2.2.2.2-00000001", "0?formatc") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Not taking any branch [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'FM' is 'E' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '0' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'GotoIf' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:16] GotoIf("PJSIP/Client.2.2.2.2-00000001", "0?formatd") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Not taking any branch [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'FM' is 'E' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'GotoIf' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:17] GotoIf("PJSIP/Client.2.2.2.2-00000001", "1?formate") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Goto (redirect,17274428141,27) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'LRNX' is '8134029999' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Expression result is '1' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SC' is ';' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'LRNX' is '8134029999' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SC' is ';' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SIPIP' is 'C2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'EXTEN' is '17274428141' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SC' is ';' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'SIPIP' is 'C2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Function IF(1?17274428141;rn=+18134029999;npdi@2.2.2.2:17274428141;npdi@2.2.2.2) result is '17274428141;rn=+18134029999;npdi@2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Set' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:27] Set("PJSIP/Client.2.2.2.2-00000001", "TR=17274428141;rn=+18134029999;npdi@2.2.2.2") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Goto' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:28] Goto("PJSIP/Client.2.2.2.2-00000001", "transfer") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Goto (redirect,17274428141,30) [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'TR' is '17274428141;rn=+18134029999;npdi@2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Transfer' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:30] Transfer("PJSIP/Client.2.2.2.2-00000001", "PJSIP/17274428141;rn=+18134029999;npdi@2.2.2.2") in new stack [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Result of 'TR' is '17274428141;rn=+18134029999;npdi@2.2.2.2' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: Launching 'Verbose' [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Executing [17274428141@redirect:31] Verbose("PJSIP/Client.2.2.2.2-00000001", "2,Transferred: 17274428141;rn=+18134029999;npdi@2.2.2.2") in new stack [Jul 10 21:19:47] VERBOSE[52483][C-00000001] app_verbose.c: == Transferred: 17274428141;rn=+18134029999;npdi@2.2.2.2 [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return because scoreboard has a match with '/'--- _X. [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: returning an exact match-- _X. [Jul 10 21:19:47] VERBOSE[52483][C-00000001] pbx.c: -- Auto fallthrough, channel 'PJSIP/Client.2.2.2.2-00000001' status is 'UNKNOWN' [Jul 10 21:19:47] DEBUG[52483][C-00000001] channel.c: Soft-Hanging (0x10) up channel 'PJSIP/Client.2.2.2.2-00000001' [Jul 10 21:19:47] DEBUG[52483][C-00000001] pbx.c: return at end of func [Jul 10 21:19:47] DEBUG[52483][C-00000001] channel.c: Hanging up channel 'PJSIP/Client.2.2.2.2-00000001' [Jul 10 21:19:47] DEBUG[52483][C-00000001] chan_pjsip.c: AST hangup cause 0 (no match found in PJSIP) [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Method is INVITE, Response is 603 Decline [Jul 10 21:19:47] DEBUG[52480] pjsip: inv0x7ff98c007 .Sending Response msg 603/INVITE/cseq=1 (tdta0x7ff98c003f50) [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 ..Sending Response msg 603/INVITE/cseq=1 (tdta0x7ff98c003f50) [Jul 10 21:19:47] DEBUG[52480] pjsip: tsx0x7ff98c005 ..Sending Response msg 603/INVITE/cseq=1 (tdta0x7ff98c003f50) in state Proceeding [Jul 10 21:19:47] VERBOSE[52480] res_pjsip_logger.c: <--- Transmitting SIP response (373 bytes) to UDP:2.2.2.2:33744 ---> ˙SIP/2.0 603 Decline ˙v: SIP/2.0/UDP 2.2.2.2:33744;rport;received=2.2.2.2;branch=z9hG4bK-d8754z-2d644b7b4ae71527-1---d8754z- ˙i: YzM1ZDcwMDE2YzQ4Y2M5NDE2M2UzMmE0Y2NlZDMzZTY ˙f: "7274907254" ;tag=97375f4d ˙t: ;tag=5ba34fb7-5ba9-4c91-b6c0-a8710287c197 ˙CSeq: 1 INVITE ˙Reason: Q.850;cause=0 ˙l: 0 ˙ ˙ [Jul 10 21:19:47] DEBUG[52480] pjsip: tsx0x7ff98c005 ...State changed from Proceeding to Completed, event=TX_MSG [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 ....Transaction tsx0x7ff98c005008 state changed to Completed [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The state change pertains to the session with Client.2.2.2.2 [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff98c005008) [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: There is no transaction involved in this state change [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The current inv state is DISCONNCTD [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Source of transaction state change is TX_MSG [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Sending response [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Method is INVITE, Response is 603 Decline [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 ......Session count dec to 3 by mod-invite [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: inv_session 0x7ff95c004f28 has no ast session [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff98c005008) [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The transaction involved in this state change is 0x7ff98c005008 [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The current transaction state is Completed [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The transaction state change event is TX_MSG [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The current inv state is DISCONNCTD [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Destroying SIP session with endpoint Client.2.2.2.2 [Jul 10 21:19:47] DEBUG[52480] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff95c00d0e8' [Jul 10 21:19:47] DEBUG[52480] rtp_engine.c: Destroyed RTP instance '0x7ff95c00d0e8' [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 .Session count dec to 0 by Session Module [Jul 10 21:19:47] DEBUG[47748] cdr.c: Finalized CDR for PJSIP/Client.2.2.2.2-00000001 - start 1405041587.895245 answer 0.000000 end 1405041587.920078 dispo FAILED [Jul 10 21:19:47] DEBUG[47748] cdr.c: Skipping CDR for PJSIP/Client.2.2.2.2-00000001 since we weren't answered [Jul 10 21:19:47] DEBUG[52480] taskprocessor.c: destroying taskprocessor 'ee0c015e-f05a-4b89-9995-0b3356f05373' [Jul 10 21:19:47] DEBUG[47744] devicestate.c: No provider found, checking channel drivers for PJSIP - Client.2.2.2.2 [Jul 10 21:19:47] DEBUG[47744] devicestate.c: Changing state for PJSIP/Client.2.2.2.2 - state 1 (Not in use) [Jul 10 21:19:47] DEBUG[47765] pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1 (rdata0x7ff0c8001ff8) [Jul 10 21:19:47] VERBOSE[47765] res_pjsip_logger.c: <--- Received SIP request (402 bytes) from UDP:2.2.2.2:33744 ---> ˙ACK sip:17274428141@1.1.1.1;transport=udp SIP/2.0 ˙Via: SIP/2.0/UDP 2.2.2.2:33744;branch=z9hG4bK-d8754z-2d644b7b4ae71527-1---d8754z-;rport ˙Max-Forwards: 70 ˙To: ;tag=5ba34fb7-5ba9-4c91-b6c0-a8710287c197 ˙From: "7274907254";tag=97375f4d ˙Call-ID: YzM1ZDcwMDE2YzQ4Y2M5NDE2M2UzMmE0Y2NlZDMzZTY ˙CSeq: 1 ACK ˙Content-Length: 0 ˙ ˙ [Jul 10 21:19:47] DEBUG[52480] pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1 (rdata0x7ff0c8004728) [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_user.c: Could not identify endpoint by username '7274907254' [Jul 10 21:19:47] DEBUG[52480] netsock2.c: Splitting '2.2.2.2' into... [Jul 10 21:19:47] DEBUG[52480] netsock2.c: ...host '2.2.2.2' and port ''. [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.208.78.162.192' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.107.23.93.209' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.107.23.93.209' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.208.78.137.148' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.208.78.137.171' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.208.78.162.192' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.206.169.153.14' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.208.78.137.176' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.208.78.136.78' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.208.78.137.177' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.85.195.88.170' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.208.78.137.174' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.66.175.125.119' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.72.167.203.204' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.208.78.160.96' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.8.19.245.233' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.208.78.137.175' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.66.175.125.123' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 does not match identify 'Client.184.168.75.215' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Source address 2.2.2.2:33744 matches identify 'Client.2.2.2.2' [Jul 10 21:19:47] DEBUG[52480] res_pjsip_endpoint_identifier_ip.c: Retrieved endpoint Client.2.2.2.2 [Jul 10 21:19:47] DEBUG[52480] pjsip: tsx0x7ff98c005 .Incoming Request msg ACK/cseq=1 (rdata0x7ff0c8004728) in state Completed [Jul 10 21:19:47] DEBUG[52480] pjsip: tsx0x7ff98c005 ..State changed from Completed to Confirmed, event=RX_MSG [Jul 10 21:19:47] DEBUG[52480] pjsip: dlg0x7ff98c007 ...Transaction tsx0x7ff98c005008 state changed to Confirmed [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: inv_session 0x7ff95c004f28 has no ast session [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The inv session still has an invite_tsx (0x7ff98c005008) [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The transaction involved in this state change is 0x7ff98c005008 [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The current transaction state is Confirmed [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The transaction state change event is RX_MSG [Jul 10 21:19:47] DEBUG[52480] res_pjsip_session.c: The current inv state is DISCONNCTD [Jul 10 21:19:47] DEBUG[47765] pjsip: tsx0x7ff98c005 Timeout timer event [Jul 10 21:19:47] DEBUG[47765] pjsip: tsx0x7ff98c005 .State changed from Confirmed to Terminated, event=TIMER [Jul 10 21:19:47] DEBUG[47765] pjsip: dlg0x7ff98c007 ..Transaction tsx0x7ff98c005008 state changed to Terminated [Jul 10 21:19:47] DEBUG[47765] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE [Jul 10 21:19:47] DEBUG[47765] res_pjsip_session.c: inv_session 0x7ff95c004f28 has no ast session [Jul 10 21:19:47] DEBUG[47765] res_pjsip_session.c: The inv session does NOT have an invite_tsx [Jul 10 21:19:47] DEBUG[47765] res_pjsip_session.c: The transaction involved in this state change is 0x7ff98c005008 [Jul 10 21:19:47] DEBUG[47765] res_pjsip_session.c: The current transaction state is Terminated [Jul 10 21:19:47] DEBUG[47765] res_pjsip_session.c: The transaction state change event is TIMER [Jul 10 21:19:47] DEBUG[47765] res_pjsip_session.c: The current inv state is DISCONNCTD [Jul 10 21:19:47] DEBUG[47765] pjsip: dlg0x7ff98c007 ...Dialog destroyed [Jul 10 21:19:47] DEBUG[47765] pjsip: tsx0x7ff98c005 Timeout timer event [Jul 10 21:19:47] DEBUG[47765] pjsip: tsx0x7ff98c005 .State changed from Terminated to Destroyed, event=TIMER [Jul 10 21:19:47] DEBUG[47765] pjsip: tdta0x7ff98c00 ..Destroying txdata Response msg 603/INVITE/cseq=1 (tdta0x7ff98c003f50) [Jul 10 21:19:47] DEBUG[47765] pjsip: tsx0x7ff98c005 Transaction destroyed! [Jul 10 21:19:56] VERBOSE[52468] asterisk.c: -- Remote UNIX connection disconnected [Jul 10 21:20:36] VERBOSE[47738] asterisk.c: -- Remote UNIX connection