[Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: <--- SIP read from UDP:95.77.93.8:5060 ---> INVITE sip:0311XXXXXX@95.77.93.8:5060;user=phone SIP/2.0 Via: SIP/2.0/UDP 95.77.93.8:5060;branch=z9hG4bKtnidpu002g80uhstg4h1.1 From: 0723XXXXXX ;tag=1013365926 To: 0311XXXXXX Call-ID: 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro CSeq: 1 INVITE Max-Forwards: 69 Supported: timer Session-Expires: 2300 Min-SE: 200 Contact: 0723XXXXXX Allow: INVITE,ACK,PRACK,SUBSCRIBE,BYE,CANCEL,NOTIFY,INFO,REFER,UPDATE Content-Type: application/sdp Content-Length: 588 v=0 o=- 56724210 0 IN IP4 95.77.93.8 s=Cisco SDP 0 c=IN IP4 95.77.93.8 t=0 0 m=audio 21974 RTP/AVP 0 8 18 99 101 102 2 15 103 4 104 105 106 107 125 100 a=rtpmap:99 G.729a/8000 a=rtpmap:101 G.726-16/8000 a=rtpmap:102 G.726-24/8000 a=rtpmap:103 G.723.1-H/8000 a=rtpmap:104 G.723.1-L/8000 a=rtpmap:105 G.729b/8000 a=rtpmap:106 G.723.1a-H/8000 a=rtpmap:107 G.723.1a-L/8000 a=rtpmap:125 G.nX64/8000 a=rtpmap:100 X-NSE/8000 a=fmtp:100 200-202 a=X-sqn:0 a=X-cap: 1 audio RTP/AVP 100 a=X-cpar: a=rtpmap:100 X-NSE/8000 a=X-cpar: a=fmtp:100 200-202 a=X-cap: 2 image udptl t38 <-------------> [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: --- (14 headers 22 lines) --- [Dec 29 11:53:47] VERBOSE[10266] netsock.c: == Using UDPTL TOS bits 184 [Dec 29 11:53:47] VERBOSE[10266] netsock.c: == Using UDPTL CoS mark 5 [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Setting NAT on UDPTL to Off [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Allocating new SIP dialog for 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro - INVITE (No RTP) [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Sending to 95.77.93.8:5060 (no NAT) [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Initializing initreq for method INVITE - callid 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Using INVITE request as basis request - 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found peer 'upc-trunk' for '0723XXXXXX' from 95.77.93.8:5060 [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Setting NAT on UDPTL to On [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x1c8496f8' [Dec 29 11:53:47] DEBUG[10266] res_rtp_asterisk.c: Allocated port 44948 for RTP instance '0x1c8496f8' [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: RTP instance '0x1c8496f8' is setup and ready to go [Dec 29 11:53:47] DEBUG[10266] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x1c8496f8' [Dec 29 11:53:47] VERBOSE[10266] netsock2.c: == Using SIP RTP TOS bits 184 [Dec 29 11:53:47] VERBOSE[10266] netsock2.c: == Using SIP RTP CoS mark 5 [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Setting NAT on RTP to On [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Setting NAT on UDPTL to On [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 0 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Setting payload 0 based on m type on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 8 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Setting payload 8 based on m type on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 18 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Setting payload 18 based on m type on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 99 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Setting payload 99 based on m type on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 101 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Setting payload 101 based on m type on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 102 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Setting payload 102 based on m type on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 2 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 15 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 103 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Setting payload 103 based on m type on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 4 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Setting payload 4 based on m type on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 104 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Setting payload 104 based on m type on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 105 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Setting payload 105 based on m type on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 106 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Setting payload 106 based on m type on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 107 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 125 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found RTP audio format 100 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Unsetting payload 99 on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found unknown media description format G.729a for ID 99 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Unsetting payload 101 on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found unknown media description format G.726-16 for ID 101 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Unsetting payload 102 on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found unknown media description format G.726-24 for ID 102 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Unsetting payload 103 on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found unknown media description format G.723.1-H for ID 103 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Unsetting payload 104 on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found unknown media description format G.723.1-L for ID 104 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Unsetting payload 105 on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found unknown media description format G.729b for ID 105 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Unsetting payload 106 on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found unknown media description format G.723.1a-H for ID 106 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Unsetting payload 107 on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found unknown media description format G.723.1a-L for ID 107 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Unsetting payload 125 on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found unknown media description format G.nX64 for ID 125 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Unsetting payload 100 on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Found unknown media description format X-NSE for ID 100 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Incorporating payload 0 on 0x41382970 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Incorporating payload 4 on 0x41382970 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Incorporating payload 8 on 0x41382970 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Incorporating payload 18 on 0x41382970 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Capabilities: us - 0x4c (ulaw|alaw|slin), peer - audio=0x10d (g723|ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xc (ulaw|alaw) [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x0 (nothing), combined - 0x0 (nothing) [Dec 29 11:53:47] DEBUG[10266] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x1c8496f8' [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Peer audio RTP is at port 95.77.93.8:21974 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Copying payload 0 from 0x41382970 to 0x1c8498c0 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Copying payload 4 from 0x41382970 to 0x1c8498c0 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Copying payload 8 from 0x41382970 to 0x1c8498c0 [Dec 29 11:53:47] DEBUG[10266] rtp_engine.c: Copying payload 18 from 0x41382970 to 0x1c8498c0 [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Peer doesn't provide T.38 UDPTL [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw) [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Checking SIP call limits for device [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: Looking for 0311XXXXXX in from-sip-external (domain 95.77.93.8:5060) [Dec 29 11:53:47] DEBUG[10266] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [Dec 29 11:53:47] DEBUG[10266] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: build_route: Contact hop: 0723XXXXXX [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: list_route: hop: [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Incoming INVITE with 'timer' option supported and "Session-Expires" header. [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Session-Expires: 2300 [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Received Min-SE: 200 [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Session timer started: 359 - 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: SIP/upc-trunk-00000001: New call is still down.... Trying... [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: <--- Transmitting (NAT) to 95.77.93.8:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 95.77.93.8:5060;branch=z9hG4bKtnidpu002g80uhstg4h1.1;received=95.77.93.8;rport=5060 From: 0723XXXXXX ;tag=1013365926 To: 0311XXXXXX Call-ID: 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro CSeq: 1 INVITE Server: FPBX-2.8.1(1.8.7.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 <------------> [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 95.77.93.8:5060 [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'NoOp' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [0311XXXXXX@from-sip-external:1] NoOp("SIP/upc-trunk-00000001", "Received incoming SIP connection from unknown peer to 0311XXXXXX") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Expression result is '0' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Function result is '0311XXXXXX' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Set' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [0311XXXXXX@from-sip-external:2] Set("SIP/upc-trunk-00000001", "DID=0311XXXXXX") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Goto' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [0311XXXXXX@from-sip-external:3] Goto("SIP/upc-trunk-00000001", "s,1") in new stack [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Goto (from-sip-external,s,1) [Dec 29 11:53:47] DEBUG[10340] pbx.c: Expression result is '1' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'GotoIf' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [s@from-sip-external:1] GotoIf("SIP/upc-trunk-00000001", "1?checklang:noanonymous") in new stack [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Goto (from-sip-external,s,2) [Dec 29 11:53:47] DEBUG[10340] pbx.c: Expression result is '1' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'GotoIf' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [s@from-sip-external:2] GotoIf("SIP/upc-trunk-00000001", "1?setlanguage:from-trunk,0311XXXXXX,1") in new stack [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Goto (from-sip-external,s,3) [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Set' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [s@from-sip-external:3] Set("SIP/upc-trunk-00000001", "CHANNEL(language)=ro") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Goto' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [s@from-sip-external:4] Goto("SIP/upc-trunk-00000001", "from-trunk,0311XXXXXX,1") in new stack [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Goto (from-trunk,0311XXXXXX,1) [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Set' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [0311XXXXXX@from-trunk:1] Set("SIP/upc-trunk-00000001", "__FROM_DID=0311XXXXXX") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Gosub' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [0311XXXXXX@from-trunk:2] Gosub("SIP/upc-trunk-00000001", "cidlookup,cidlookup_1,1") in new stack [Dec 29 11:53:47] DEBUG[10340] app_stack.c: Channel SIP/upc-trunk-00000001 has no datastore, so we're allocating one. [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'MYSQL' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [cidlookup_1@cidlookup:1] MYSQL("SIP/upc-trunk-00000001", "Connect connid localhost cid cid cid") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Function result is '0723XXXXXX' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'MYSQL' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [cidlookup_1@cidlookup:2] MYSQL("SIP/upc-trunk-00000001", "Query resultid 1 SELECT `name` FROM callerids WHERE `number` LIKE '%0723XXXXXX%'") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'MYSQL' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [cidlookup_1@cidlookup:3] MYSQL("SIP/upc-trunk-00000001", "Fetch fetchid 2 CALLERID(name)") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'MYSQL' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [cidlookup_1@cidlookup:4] MYSQL("SIP/upc-trunk-00000001", "Clear 2") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'MYSQL' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [cidlookup_1@cidlookup:5] MYSQL("SIP/upc-trunk-00000001", "Disconnect 1") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Return' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [cidlookup_1@cidlookup:6] Return("SIP/upc-trunk-00000001", "") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Gosub' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [0311XXXXXX@from-trunk:3] Gosub("SIP/upc-trunk-00000001", "app-blacklist-check,s,1") in new stack [Dec 29 11:53:47] DEBUG[10340] db.c: Unable to find key '0723XXXXXX' in family 'blacklist' [Dec 29 11:53:47] DEBUG[10340] db.c: Unable to find key 'CallerID name' in family 'blacklist' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Function result is '0' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Expression result is '0' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'GotoIf' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("SIP/upc-trunk-00000001", "0?blacklisted") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Not taking any branch [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Set' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [s@app-blacklist-check:2] Set("SIP/upc-trunk-00000001", "CALLED_BLACKLIST=1") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Return' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [s@app-blacklist-check:3] Return("SIP/upc-trunk-00000001", "") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Function result is 'CallerID name' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Expression result is '0' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Function result is '0723XXXXXX' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'ExecIf' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [0311XXXXXX@from-trunk:4] ExecIf("SIP/upc-trunk-00000001", "0 ?Set(CALLERID(name)=0723XXXXXX)") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Ringing' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [0311XXXXXX@from-trunk:5] Ringing("SIP/upc-trunk-00000001", "") in new stack [Dec 29 11:53:47] VERBOSE[10340] chan_sip.c: <--- Transmitting (NAT) to 95.77.93.8:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 95.77.93.8:5060;branch=z9hG4bKtnidpu002g80uhstg4h1.1;received=95.77.93.8;rport=5060 From: 0723XXXXXX ;tag=1013365926 To: 0311XXXXXX ;tag=as42341271 Call-ID: 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro CSeq: 1 INVITE Server: FPBX-2.8.1(1.8.7.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Length: 0 <------------> [Dec 29 11:53:47] DEBUG[10340] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 95.77.93.8:5060 [Dec 29 11:53:47] DEBUG[10340] pbx.c: Function result is 'allowed_not_screened' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Set' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [0311XXXXXX@from-trunk:6] Set("SIP/upc-trunk-00000001", "__CALLINGPRES_SV=allowed_not_screened") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Set' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [0311XXXXXX@from-trunk:7] Set("SIP/upc-trunk-00000001", "CALLERPRES()=allowed_not_screened") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Goto' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [0311XXXXXX@from-trunk:8] Goto("SIP/upc-trunk-00000001", "app-announcement-1,s,1") in new stack [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Goto (app-announcement-1,s,1) [Dec 29 11:53:47] DEBUG[10340] pbx.c: Function result is 'NO ANSWER' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Expression result is '0' [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'GotoIf' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [s@app-announcement-1:1] GotoIf("SIP/upc-trunk-00000001", "0?begin") in new stack [Dec 29 11:53:47] DEBUG[10340] pbx.c: Not taking any branch [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Answer' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [s@app-announcement-1:2] Answer("SIP/upc-trunk-00000001", "") in new stack [Dec 29 11:53:47] DEBUG[10340] chan_sip.c: SIP answering channel: SIP/upc-trunk-00000001 [Dec 29 11:53:47] DEBUG[10340] chan_sip.c: Setting framing from config on incoming call [Dec 29 11:53:47] DEBUG[10340] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True [Dec 29 11:53:47] DEBUG[10340] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Dec 29 11:53:47] VERBOSE[10340] chan_sip.c: Audio is at 5060 [Dec 29 11:53:47] VERBOSE[10340] chan_sip.c: Adding codec 0x4 (ulaw) to SDP [Dec 29 11:53:47] VERBOSE[10340] chan_sip.c: Adding codec 0x8 (alaw) to SDP [Dec 29 11:53:47] VERBOSE[10340] chan_sip.c: <--- Reliably Transmitting (NAT) to 95.77.93.8:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 95.77.93.8:5060;branch=z9hG4bKtnidpu002g80uhstg4h1.1;received=95.77.93.8;rport=5060 From: 0723XXXXXX ;tag=1013365926 To: 0311XXXXXX ;tag=as42341271 Call-ID: 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro CSeq: 1 INVITE Server: FPBX-2.8.1(1.8.7.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Session-Expires: 1800;refresher=uas Contact: Content-Type: application/sdp Content-Length: 198 v=0 o=root 1073029180 1073029180 IN IP4 10.1.14.2 s=Asterisk PBX 1.8.7.0 c=IN IP4 10.1.14.2 t=0 0 m=audio 44948 RTP/AVP 0 8 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=ptime:20 a=sendrecv <------------> [Dec 29 11:53:47] DEBUG[10340] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 95.77.93.8:5060 [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: <--- SIP read from UDP:95.77.93.8:5060 ---> ACK sip:0311XXXXXX@95.77.93.8:5060 SIP/2.0 Via: SIP/2.0/UDP 95.77.93.8:5060;branch=z9hG4bKu7per71030cg6ikdo1n0.1 From: 0723XXXXXX ;tag=1013365926 To: 0311XXXXXX ;tag=as42341271 Call-ID: 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro CSeq: 1 ACK Max-Forwards: 69 Content-Length: 0 <-------------> [Dec 29 11:53:47] VERBOSE[10266] chan_sip.c: --- (8 headers 0 lines) --- [Dec 29 11:53:47] DEBUG[10266] chan_sip.c: Stopping retransmission on '407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro' of Response 1: Match Found [Dec 29 11:53:47] DEBUG[10340] pbx.c: Launching 'Wait' [Dec 29 11:53:47] VERBOSE[10340] pbx.c: -- Executing [s@app-announcement-1:3] Wait("SIP/upc-trunk-00000001", "1") in new stack [Dec 29 11:53:47] DEBUG[10340] channel.c: Set channel SIP/upc-trunk-00000001 to write format slin [Dec 29 11:53:47] DEBUG[10340] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Dec 29 11:53:47] DEBUG[10340] channel.c: Started silence generator on 'SIP/upc-trunk-00000001' [Dec 29 11:53:47] DEBUG[10340] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Dec 29 11:53:47] DEBUG[10340] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Dec 29 11:53:48] DEBUG[10340] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Dec 29 11:53:48] DEBUG[10340] channel.c: Stopped silence generator on 'SIP/upc-trunk-00000001' [Dec 29 11:53:48] DEBUG[10340] channel.c: Set channel SIP/upc-trunk-00000001 to write format ulaw [Dec 29 11:53:48] DEBUG[10340] pbx.c: Launching 'Goto' [Dec 29 11:53:48] VERBOSE[10340] pbx.c: -- Executing [s@app-announcement-1:4] Goto("SIP/upc-trunk-00000001", "app-blackhole,hangup,1") in new stack [Dec 29 11:53:48] VERBOSE[10340] pbx.c: -- Goto (app-blackhole,hangup,1) [Dec 29 11:53:48] DEBUG[10340] pbx.c: Launching 'NoOp' [Dec 29 11:53:48] VERBOSE[10340] pbx.c: -- Executing [hangup@app-blackhole:1] NoOp("SIP/upc-trunk-00000001", "Blackhole Dest: Hangup") in new stack [Dec 29 11:53:48] DEBUG[10340] pbx.c: Launching 'Hangup' [Dec 29 11:53:48] VERBOSE[10340] pbx.c: -- Executing [hangup@app-blackhole:2] Hangup("SIP/upc-trunk-00000001", "") in new stack [Dec 29 11:53:48] DEBUG[10340] pbx.c: Spawn extension (app-blackhole,hangup,2) exited non-zero on 'SIP/upc-trunk-00000001' [Dec 29 11:53:48] VERBOSE[10340] pbx.c: == Spawn extension (app-blackhole, hangup, 2) exited non-zero on 'SIP/upc-trunk-00000001' [Dec 29 11:53:48] DEBUG[10340] channel.c: Soft-Hanging up channel 'SIP/upc-trunk-00000001' [Dec 29 11:53:48] DEBUG[10340] channel.c: Hanging up channel 'SIP/upc-trunk-00000001' [Dec 29 11:53:48] DEBUG[10340] chan_sip.c: Hanging up zombie call. Be scared. [Dec 29 11:53:48] DEBUG[10340] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x1c8496f8' [Dec 29 11:53:48] VERBOSE[10340] chan_sip.c: Scheduling destruction of SIP dialog '407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro' in 6400 ms (Method: ACK) [Dec 29 11:53:48] DEBUG[10340] chan_sip.c: Session timer stopped: 359 - 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro [Dec 29 11:53:48] DEBUG[10340] chan_sip.c: Strict routing enforced for session 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro [Dec 29 11:53:48] VERBOSE[10340] chan_sip.c: set_destination: Parsing for address/port to send to [Dec 29 11:53:48] VERBOSE[10340] chan_sip.c: set_destination: set destination to 95.77.93.8:5060 [Dec 29 11:53:48] VERBOSE[10340] chan_sip.c: Reliably Transmitting (NAT) to 95.77.93.8:5060: BYE sip:0723XXXXXX@95.77.93.8:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.1.14.2:5060;branch=z9hG4bK04d8aaeb;rport Max-Forwards: 70 From: 0311XXXXXX ;tag=as42341271 To: 0723XXXXXX ;tag=1013365926 Call-ID: 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro CSeq: 102 BYE User-Agent: FPBX-2.8.1(1.8.7.0) X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- [Dec 29 11:53:48] DEBUG[10340] chan_sip.c: Trying to put 'BYE sip:072' onto UDP socket destined for 95.77.93.8:5060 [Dec 29 11:53:48] DEBUG[10340] cdr_mysql.c: Inserting a CDR record. [Dec 29 11:53:48] DEBUG[10340] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`lastapp`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`) VALUES ('2011-12-29 11:53:47','\"CallerID name\" <0723XXXXXX>','0723XXXXXX','hangup','app-blackhole','SIP/upc-trunk-00000001','Hangup','1','1','ANSWERED','3','1325152427.1') [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is '2011-12-29 11:53:47' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is '"CallerID name" <0723XXXXXX>' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is 'app-blackhole' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is 'SIP/upc-trunk-00000001' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is '(null)' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is 'Hangup' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is '(null)' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is '1' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is '1' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is 'ANSWERED' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is 'DOCUMENTATION' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is '(null)' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is '1325152427.1' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is '(null)' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is '(null)' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is '0723XXXXXX' [Dec 29 11:53:48] DEBUG[10340] pbx.c: Function result is 'hangup' [Dec 29 11:53:48] DEBUG[10340] cdr_sqlite3_custom.c: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test,src,dst) VALUES ('2011-12-29 11:53:47','"CallerID name" <0723XXXXXX>','app-blackhole','SIP/upc-trunk-00000001','','Hangup','','1','1','ANSWERED','DOCUMENTATION','','1325152427.1','','','0723XXXXXX','hangup') [Dec 29 11:53:48] VERBOSE[10266] chan_sip.c: <--- SIP read from UDP:95.77.93.8:5060 ---> SIP/2.0 400 Bad Request Via: SIP/2.0/UDP 95.77.93.8:5060;received=10.1.14.2;branch=z9hG4bK04d8aaeb;rport=5060 From: 0311XXXXXX ;tag=as42341271 To: 0723XXXXXX ;tag=1013365926 Call-ID: 407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro CSeq: 102 BYE Content-Length: 0 <-------------> [Dec 29 11:53:48] VERBOSE[10266] chan_sip.c: --- (7 headers 0 lines) --- [Dec 29 11:53:48] DEBUG[10266] chan_sip.c: Stopping retransmission on '407324df-5f589695-2dbb5795-39a2@pgw-sip.voip.astralnet.ro' of Request 102: Match Found [Dec 29 11:53:48] VERBOSE[10266] chan_sip.c: SIP Response message for INCOMING dialog BYE arrived [Dec 29 11:53:48] VERBOSE[10266] chan_sip.c: -- Incoming call: Got SIP response 400 "Bad Request" back from 95.77.93.8:5060 [Dec 29 11:53:52] DEBUG[10266] chan_sip.c: Allocating new SIP dialog for 6907ceb63386744066757b693ad88862@127.0.0.1:0 - OPTIONS (No RTP) [Dec 29 11:53:52] DEBUG[10266] chan_sip.c: Initializing initreq for method OPTIONS - callid 05b891fc6b85c58e0910954331dd7f32@10.10.20.220:5060 [Dec 29 11:53:52] DEBUG[10266] chan_sip.c: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.10.20.38:5061 [Dec 29 11:53:53] DEBUG[10266] chan_sip.c: Stopping retransmission on '05b891fc6b85c58e0910954331dd7f32@10.10.20.220:5060' of Request 102: Match Found