[2016-05-03 18:26:51] VERBOSE[7779] chan_sip.c: <--- SIP read from UDP:ASTERIX_IP:50206 ---> INVITE sip:CALLED_NO@EXTENSION_IP;user=phone SIP/2.0 Via: SIP/2.0/UDP ASTERIX_IP:5061;branch=z9hG4bK6205ecd7 From: "1003" ;tag=2401c78276ad1035f534f541-e606ca24 To: Call-ID: 2401c782-76ad0024-e2be580b-00b10606@ASTERIX_IP Max-Forwards: 70 Date: Tue, 03 May 2016 16:26:50 GMT CSeq: 101 INVITE User-Agent: Cisco-CP7945G/9.4.2 Contact: Expires: 180 Accept: application/sdp Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE,SUBSCRIBE,INFO Supported: replaces,join,sdp-anat,norefersub,resource-priority,extended-refer,X-cisco-callinfo,X-cisco-serviceuri,X-cisco-e scapecodes,X-cisco-service-control,X-cisco-srtp-fallback,X-cisco-monrec,X-cisco-config,X-cisco-sis-6.0.0,X-cisco-xsi-8.5.1 Allow-Events: kpml,dialog Content-Length: 351 Content-Type: application/sdp Content-Disposition: session;handling=optional v=0 o=Cisco-SIPUA 6230 0 IN IP4 ASTERIX_IP s=SIP Call t=0 0 m=audio 16384 RTP/AVP 0 8 18 102 116 101 c=IN IP4 ASTERIX_IP a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:102 L16/16000 a=rtpmap:116 iLBC/8000 a=fmtp:116 mode=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv <-------------> [2016-05-03 18:26:51] VERBOSE[7779] chan_sip.c: --- (18 headers 16 lines) --- [2016-05-03 18:26:51] VERBOSE[7779] chan_sip.c: Sending to ASTERIX_IP:50206 (NAT) [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Sending to ASTERIX_IP:50206 (NAT) [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Using INVITE request as basis request - 2401c782-76ad0024-e2be5 80b-00b10606@ASTERIX_IP [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found peer '1003' for '1003' from ASTERIX_IP:50206 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: <--- Reliably Transmitting (no NAT) to ASTERIX_IP:5061 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP ASTERIX_IP:5061;branch=z9hG4bK6205ecd7;received=ASTERIX_IP From: "1003" ;tag=2401c78276ad1035f534f541-e606ca24 To: ;tag=as19cc3c41 Call-ID: 2401c782-76ad0024-e2be580b-00b10606@ASTERIX_IP CSeq: 101 INVITE Server: FPBX-13.0.109(13.7.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="54afce74" Content-Length: 0 <------------> [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Scheduling destruction of SIP dialog '2401c782-76ad0024-e2be580 b-00b10606@ASTERIX_IP' in 6400 ms (Method: INVITE) [2016-05-03 18:26:51] VERBOSE[7779] chan_sip.c: <--- SIP read from UDP:ASTERIX_IP:52249 ---> ACK sip:CALLED_NO@EXTENSION_IP;user=phone SIP/2.0 Via: SIP/2.0/UDP ASTERIX_IP:5061;branch=z9hG4bK6205ecd7 From: "1003" ;tag=2401c78276ad1035f534f541-e606ca24 To: ;tag=as19cc3c41 Call-ID: 2401c782-76ad0024-e2be580b-00b10606@ASTERIX_IP Max-Forwards: 70 Date: Tue, 03 May 2016 16:26:50 GMT CSeq: 101 ACK Content-Length: 0 <-------------> [2016-05-03 18:26:51] VERBOSE[7779] chan_sip.c: --- (9 headers 0 lines) --- [2016-05-03 18:26:51] VERBOSE[7779] chan_sip.c: <--- SIP read from UDP:ASTERIX_IP:50206 ---> INVITE sip:CALLED_NO@EXTENSION_IP;user=phone SIP/2.0 Via: SIP/2.0/UDP ASTERIX_IP:5061;branch=z9hG4bKb7e9f708 From: "1003" ;tag=2401c78276ad1035f534f541-e606ca24 To: Call-ID: 2401c782-76ad0024-e2be580b-00b10606@ASTERIX_IP Max-Forwards: 70 Date: Tue, 03 May 2016 16:26:50 GMT CSeq: 102 INVITE User-Agent: Cisco-CP7945G/9.4.2 Contact: Authorization: Digest username="1003",realm="asterisk",uri="sip:CALLED_NO@EXTENSION_IP;user=phone",response="6acc83bc050a4 87870d950513de4bcb6",nonce="54afce74",algorithm=MD5 Expires: 180 Accept: application/sdp Allow: ACK,BYE,CANCEL,INVITE,NOTIFY,OPTIONS,REFER,REGISTER,UPDATE,SUBSCRIBE,INFO Supported: replaces,join,sdp-anat,norefersub,resource-priority,extended-refer,X-cisco-callinfo,X-cisco-serviceuri,X-cisco-e scapecodes,X-cisco-service-control,X-cisco-srtp-fallback,X-cisco-monrec,X-cisco-config,X-cisco-sis-6.0.0,X-cisco-xsi-8.5.1 Allow-Events: kpml,dialog Content-Length: 351 Content-Type: application/sdp Content-Disposition: session;handling=optional v=0 o=Cisco-SIPUA 6230 0 IN IP4 ASTERIX_IP s=SIP Call t=0 0 m=audio 16384 RTP/AVP 0 8 18 102 116 101 c=IN IP4 ASTERIX_IP a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:102 L16/16000 a=rtpmap:116 iLBC/8000 a=fmtp:116 mode=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv <-------------> [2016-05-03 18:26:51] VERBOSE[7779] chan_sip.c: --- (19 headers 16 lines) --- [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Sending to ASTERIX_IP:5061 (no NAT) [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Using INVITE request as basis request - 2401c782-76ad0024-e2be5 80b-00b10606@ASTERIX_IP [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found peer '1003' for '1003' from ASTERIX_IP:50206 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] netsock2.c: Using SIP RTP TOS bits 184 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] netsock2.c: Using SIP RTP CoS mark 5 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found RTP audio format 0 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found RTP audio format 8 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found RTP audio format 18 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found RTP audio format 102 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found RTP audio format 116 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found RTP audio format 101 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found audio description format PCMU for ID 0 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found audio description format PCMA for ID 8 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found audio description format G729 for ID 18 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found audio description format L16 for ID 102 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found audio description format iLBC for ID 116 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Found audio description format telephone-event for ID 101 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Capabilities: us - (ulaw|alaw|gsm|g726), peer - audio=(ulaw|ala w|g729|slin16|ilbc)/video=(nothing)/text=(nothing), combined - (ulaw|alaw) [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), pee r - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Peer audio RTP is at port ASTERIX_IP:16384 [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: Looking for CALLED_NO in from-internal (domain EXTENSION_IP) [2016-05-03 18:26:51] WARNING[7661] res_odbc.c: SetConnectAttr (Txn isolation) returned an error: HY000: [MySQL][ODBC 5.1 D river]MySQL server has gone away [2016-05-03 18:26:51] WARNING[7661] res_odbc.c: SQL Execute returned an error -1: 08S01: [MySQL][ODBC 5.1 Driver][mysqld-5. 5.44-0+deb8u1]MySQL server has gone away (74) [2016-05-03 18:26:51] WARNING[7661] res_odbc.c: SQL Execute error -1! Verifying connection to asteriskcdrdb [MySQL-asterisk cdrdb]... [2016-05-03 18:26:51] WARNING[7661] res_odbc.c: Connection is down attempting to reconnect... [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] sip/route.c: sip_route_dump: route/path hop: [2016-05-03 18:26:51] VERBOSE[7779][C-00000025] chan_sip.c: <--- Transmitting (no NAT) to ASTERIX_IP:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP ASTERIX_IP:5061;branch=z9hG4bKb7e9f708;received=ASTERIX_IP From: "1003" ;tag=2401c78276ad1035f534f541-e606ca24 To: Call-ID: 2401c782-76ad0024-e2be580b-00b10606@ASTERIX_IP CSeq: 102 INVITE Server: FPBX-13.0.109(13.7.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: Content-Length: 0 <------------> [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [CALLED_NO@from-internal:1] Macro("SIP/1003-0000004a", "u ser-callerid,LIMIT,EXTERNAL,") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/1003-0000004a", "TOUCH_ MONITOR=1462292811.74") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/1003-0000004a", "AMPUSE R=1003") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/1003-0000004a", "0?r eport") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/1003-0000004a", "1?S et(REALCALLERIDNUM=1003)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/1003-0000004a", "AMPUSE R=1003") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/1003-0000004a", "0?l imit") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/1003-0000004a", "AMPUSE RCIDNAME=XXXXXXXXXX") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/1003-0000004a", "0?r eport") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:9] Set("SIP/1003-0000004a", "AMPUSE RCID=1003") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/1003-0000004a", "__DIA L_OPTIONS=Ttr") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/1003-0000004a", "CALLE RID(all)="XXXXXXXXXX" <1003>") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:12] GotoIf("SIP/1003-0000004a", "0? limit") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("SIP/1003-0000004a", "1? Set(GROUP(concurrency_limit)=1003)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:14] GotoIf("SIP/1003-0000004a", "1? continue") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Goto (macro-user-callerid,s,27) [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:27] Set("SIP/1003-0000004a", "CALLE RID(number)=1003") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:28] Set("SIP/1003-0000004a", "CALLE RID(name)=XXXXXXXXXX") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:29] Set("SIP/1003-0000004a", "CDR(c num)=1003") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/1003-0000004a", "CDR(c nam)=XXXXXXXXXX") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-user-callerid:31] Set("SIP/1003-0000004a", "CHANN EL(language)=en") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [CALLED_NO@from-internal:2] Gosub("SIP/1003-0000004a", "s ub-record-check,s,1(out,CALLED_NO,dontcare)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/1003-0000004a", "0?init ialized") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:2] Set("SIP/1003-0000004a", "__REC_STA TUS=INITIALIZED") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:3] Set("SIP/1003-0000004a", "NOW=14622 92811") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:4] Set("SIP/1003-0000004a", "__DAY=03" ) in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:5] Set("SIP/1003-0000004a", "__MONTH=0 5") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:6] Set("SIP/1003-0000004a", "__YEAR=20 16") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:7] Set("SIP/1003-0000004a", "__TIMESTR =20160503-182651") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:8] Set("SIP/1003-0000004a", "__FROMEXT EN=1003") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:9] Set("SIP/1003-0000004a", "__MON_FMT =wav") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/1003-0000004a", "Recordi ngs initialized") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/1003-0000004a", "0?Set (ARG3=dontcare)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:12] Set("SIP/1003-0000004a", "REC_POLI CY_MODE_SAVE=") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/1003-0000004a", "0?Set (REC_STATUS=NO)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/1003-0000004a", "3?che ckaction") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Goto (sub-record-check,s,17) [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/1003-0000004a", "1?sub -record-check,out,1") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Goto (sub-record-check,out,1) [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [out@sub-record-check:1] NoOp("SIP/1003-0000004a", "Outbou nd Recording Check from 1003 to CALLED_NO") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [out@sub-record-check:2] Set("SIP/1003-0000004a", "RECMODE =dontcare") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [out@sub-record-check:3] ExecIf("SIP/1003-0000004a", "1?Go to(routewins)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Goto (sub-record-check,out,7) [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [out@sub-record-check:7] Gosub("SIP/1003-0000004a", "recor dcheck,1(dontcare,out,CALLED_NO)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/1003-0000004a", "Starting recording check against dontcare") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/1003-0000004a", "dontcare") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Goto (sub-record-check,recordcheck,3) [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/1003-0000004a ", "") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [out@sub-record-check:8] Return("SIP/1003-0000004a", "") i n new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [CALLED_NO@from-internal:3] Set("SIP/1003-0000004a", "MOH CLASS=default") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [CALLED_NO@from-internal:4] Set("SIP/1003-0000004a", "_NO DEST=") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [CALLED_NO@from-internal:5] Macro("SIP/1003-0000004a", "d ialout-trunk,1,CALLED_NO,,on") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:1] Set("SIP/1003-0000004a", "DIAL_T RUNK=1") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:2] GosubIf("SIP/1003-0000004a", "0? sub-pincheck,s,1()") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:3] GotoIf("SIP/1003-0000004a", "0?d isabletrunk,1") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:4] Set("SIP/1003-0000004a", "DIAL_N UMBER=CALLED_NO") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:5] Set("SIP/1003-0000004a", "DIAL_T RUNK_OPTIONS=Ttr") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:6] Set("SIP/1003-0000004a", "OUTBOU ND_GROUP=OUT_1") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:7] GotoIf("SIP/1003-0000004a", "0?n omax") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:8] GotoIf("SIP/1003-0000004a", "0?c hanfull") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:9] GotoIf("SIP/1003-0000004a", "0?s kipoutcid") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:10] Set("SIP/1003-0000004a", "DIAL_ TRUNK_OPTIONS=Tt") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:11] Macro("SIP/1003-0000004a", "out bound-callerid,1") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:1] ExecIf("SIP/1003-0000004a", "0?Set(CALLERPRES(name-pres)=)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:2] ExecIf("SIP/1003-0000004a", "0?Set(CALLERPRES(num-pres)=)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:3] ExecIf("SIP/1003-0000004a", "0?Set(REALCALLERIDNUM=1003)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:4] GotoIf("SIP/1003-0000004a", "1?normcid") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Goto (macro-outbound-callerid,s,7) [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:7] Set("SIP/1003-0000004a", "US EROUTCID="Steve"") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:8] Set("SIP/1003-0000004a", "EM ERGENCYCID=") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:9] Set("SIP/1003-0000004a", "TR UNKOUTCID=+3399XXXXXXXXXX") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:10] GotoIf("SIP/1003-0000004a", "1?trunkcid") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Goto (macro-outbound-callerid,s,15) [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:15] ExecIf("SIP/1003-0000004a", "1?Set(CALLERID(all)=+3399XXXXXXXXXX)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:16] ExecIf("SIP/1003-0000004a", "1?Set(CALLERID(all)="Steve")") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:17] ExecIf("SIP/1003-0000004a", "0?Set(CALLERID(all)=)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:18] ExecIf("SIP/1003-0000004a", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:19] ExecIf("SIP/1003-0000004a", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:20] Set("SIP/1003-0000004a", "C DR(outbound_cnum)=XXXXXXXXXX") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-outbound-callerid:21] Set("SIP/1003-0000004a", "C DR(outbound_cnam)=Steve") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:12] GosubIf("SIP/1003-0000004a", "0 ?sub-flp-1,s,1()") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:13] Set("SIP/1003-0000004a", "OUTNU M=CALLED_NO") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:14] Set("SIP/1003-0000004a", "custo m=SIP/SFR_Lys") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:15] ExecIf("SIP/1003-0000004a", "0? Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:16] ExecIf("SIP/1003-0000004a", "0? Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:17] Macro("SIP/1003-0000004a", "dia lout-trunk-predial-hook,") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/1003 -0000004a", "") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:18] GotoIf("SIP/1003-0000004a", "0? bypass,1") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:19] ExecIf("SIP/1003-0000004a", "1? Set(CONNECTEDLINE(num,i)=CALLED_NO)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:20] ExecIf("SIP/1003-0000004a", "1? Set(CONNECTEDLINE(name,i)=CID:XXXXXXXXXX)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:21] ExecIf("SIP/1003-0000004a", "0? Set(CONNECTEDLINE(name,i)=CID:(Hidden)XXXXXXXXXX)") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:22] GotoIf("SIP/1003-0000004a", "0? customtrunk") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:23] Dial("SIP/1003-0000004a", "SIP/ SFR_Lys/CALLED_NO,300,Tt") in new stack [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] netsock2.c: Using SIP RTP TOS bits 184 [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] netsock2.c: Using SIP RTP CoS mark 5 [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] chan_sip.c: Audio is at 17412 [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] chan_sip.c: Adding codec ulaw to SDP [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] chan_sip.c: Adding codec alaw to SDP [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] chan_sip.c: Adding codec gsm to SDP [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] chan_sip.c: Adding codec g726 to SDP [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] chan_sip.c: Reliably Transmitting (NAT) to 91.68.1.28:5064: INVITE sip:CALLED_NO@internet.p-cscf.sfr.net:5064 SIP/2.0 Via: SIP/2.0/UDP PUBLIC_IP:5061;branch=z9hG4bK0e3ac761;rport Max-Forwards: 70 From: "Steve" ;tag=as46f9aaf9 To: Contact: Call-ID: 26efc70b51829837116733bc141600b9@ims.mnc010.mcc208.3gppnetwork.org CSeq: 102 INVITE User-Agent: FPBX-13.0.109(13.7.0) Date: Tue, 03 May 2016 16:26:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 323 v=0 o=root 910752456 910752456 IN IP4 PUBLIC_IP s=Asterisk PBX 13.7.0 c=IN IP4 PUBLIC_IP t=0 0 m=audio 17412 RTP/AVP 0 8 3 111 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [2016-05-03 18:26:51] VERBOSE[2654][C-00000025] app_dial.c: Called SIP/SFR_Lys/CALLED_NO [2016-05-03 18:26:51] VERBOSE[7779] chan_sip.c: Retransmitting #1 (NAT) to 91.68.1.28:5064: INVITE sip:CALLED_NO@internet.p-cscf.sfr.net:5064 SIP/2.0 Via: SIP/2.0/UDP PUBLIC_IP:5061;branch=z9hG4bK0e3ac761;rport Max-Forwards: 70 From: "Steve" ;tag=as46f9aaf9 To: Contact: Call-ID: 26efc70b51829837116733bc141600b9@ims.mnc010.mcc208.3gppnetwork.org CSeq: 102 INVITE User-Agent: FPBX-13.0.109(13.7.0) Date: Tue, 03 May 2016 16:26:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 323 v=0 o=root 910752456 910752456 IN IP4 PUBLIC_IP s=Asterisk PBX 13.7.0 c=IN IP4 PUBLIC_IP t=0 0 m=audio 17412 RTP/AVP 0 8 3 111 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [2016-05-03 18:26:52] VERBOSE[7779] chan_sip.c: Retransmitting #2 (NAT) to 91.68.1.28:5064: INVITE sip:CALLED_NO@internet.p-cscf.sfr.net:5064 SIP/2.0 Via: SIP/2.0/UDP PUBLIC_IP:5061;branch=z9hG4bK0e3ac761;rport Max-Forwards: 70 From: "Steve" ;tag=as46f9aaf9 To: Contact: Call-ID: 26efc70b51829837116733bc141600b9@ims.mnc010.mcc208.3gppnetwork.org CSeq: 102 INVITE User-Agent: FPBX-13.0.109(13.7.0) Date: Tue, 03 May 2016 16:26:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 323 v=0 o=root 910752456 910752456 IN IP4 PUBLIC_IP s=Asterisk PBX 13.7.0 c=IN IP4 PUBLIC_IP t=0 0 m=audio 17412 RTP/AVP 0 8 3 111 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [2016-05-03 18:26:54] VERBOSE[7779] chan_sip.c: Retransmitting #3 (NAT) to 91.68.1.28:5064: INVITE sip:CALLED_NO@internet.p-cscf.sfr.net:5064 SIP/2.0 Via: SIP/2.0/UDP PUBLIC_IP:5061;branch=z9hG4bK0e3ac761;rport Max-Forwards: 70 From: "Steve" ;tag=as46f9aaf9 To: Contact: Call-ID: 26efc70b51829837116733bc141600b9@ims.mnc010.mcc208.3gppnetwork.org CSeq: 102 INVITE User-Agent: FPBX-13.0.109(13.7.0) Date: Tue, 03 May 2016 16:26:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 323 v=0 o=root 910752456 910752456 IN IP4 PUBLIC_IP s=Asterisk PBX 13.7.0 c=IN IP4 PUBLIC_IP t=0 0 m=audio 17412 RTP/AVP 0 8 3 111 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv <-------------> [2016-05-03 18:26:55] VERBOSE[7779] chan_sip.c: --- (7 headers 0 lines) --- [2016-05-03 18:26:55] VERBOSE[7779] chan_sip.c: Really destroying SIP dialog '1427d34d1d4b59071ce595012aa225ef@PUBLIC_IP:5 061' Method: OPTIONS [2016-05-03 18:26:56] NOTICE[7661] res_odbc.c: Connecting asteriskcdrdb [2016-05-03 18:26:56] NOTICE[7661] res_odbc.c: res_odbc: Connected to asteriskcdrdb [MySQL-asteriskcdrdb] [2016-05-03 18:26:57] VERBOSE[7779] chan_sip.c: <-------------> [2016-05-03 18:26:58] VERBOSE[7779] chan_sip.c: Retransmitting #4 (NAT) to 91.68.1.28:5064: INVITE sip:CALLED_NO@internet.p-cscf.sfr.net:5064 SIP/2.0 Via: SIP/2.0/UDP PUBLIC_IP:5061;branch=z9hG4bK0e3ac761;rport Max-Forwards: 70 From: "Steve" ;tag=as46f9aaf9 To: Contact: Call-ID: 26efc70b51829837116733bc141600b9@ims.mnc010.mcc208.3gppnetwork.org CSeq: 102 INVITE User-Agent: FPBX-13.0.109(13.7.0) Date: Tue, 03 May 2016 16:26:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 323 v=0 o=root 910752456 910752456 IN IP4 PUBLIC_IP s=Asterisk PBX 13.7.0 c=IN IP4 PUBLIC_IP t=0 0 m=audio 17412 RTP/AVP 0 8 3 111 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [2016-05-03 18:27:06] VERBOSE[7779] chan_sip.c: Retransmitting #5 (NAT) to 91.68.1.28:5064: INVITE sip:CALLED_NO@internet.p-cscf.sfr.net:5064 SIP/2.0 Via: SIP/2.0/UDP PUBLIC_IP:5061;branch=z9hG4bK0e3ac761;rport Max-Forwards: 70 From: "Steve" ;tag=as46f9aaf9 To: Contact: Call-ID: 26efc70b51829837116733bc141600b9@ims.mnc010.mcc208.3gppnetwork.org CSeq: 102 INVITE User-Agent: FPBX-13.0.109(13.7.0) Date: Tue, 03 May 2016 16:26:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 323 v=0 o=root 910752456 910752456 IN IP4 PUBLIC_IP s=Asterisk PBX 13.7.0 c=IN IP4 PUBLIC_IP t=0 0 m=audio 17412 RTP/AVP 0 8 3 111 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [2016-05-03 18:27:22] VERBOSE[7779] chan_sip.c: Retransmitting #6 (NAT) to 91.68.1.28:5064: INVITE sip:CALLED_NO@internet.p-cscf.sfr.net:5064 SIP/2.0 Via: SIP/2.0/UDP PUBLIC_IP:5061;branch=z9hG4bK0e3ac761;rport Max-Forwards: 70 From: "Steve" ;tag=as46f9aaf9 To: Contact: Call-ID: 26efc70b51829837116733bc141600b9@ims.mnc010.mcc208.3gppnetwork.org CSeq: 102 INVITE User-Agent: FPBX-13.0.109(13.7.0) Date: Tue, 03 May 2016 16:26:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Content-Type: application/sdp Content-Length: 323 v=0 o=root 910752456 910752456 IN IP4 PUBLIC_IP s=Asterisk PBX 13.7.0 c=IN IP4 PUBLIC_IP t=0 0 m=audio 17412 RTP/AVP 0 8 3 111 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=maxptime:150 a=sendrecv --- [2016-05-03 18:27:23] VERBOSE[7779] chan_sip.c: Scheduling destruction of SIP dialog '26efc70b51829837116733bc141600b9@ims. mnc010.mcc208.3gppnetwork.org' in 32000 ms (Method: INVITE) [2016-05-03 18:27:23] WARNING[7779] chan_sip.c: Retransmission timeout reached on transmission 26efc70b51829837116733bc1416 00b9@ims.mnc010.mcc208.3gppnetwork.org for seqno 102 (Critical Request) -- See https://wiki.asterisk.org/wiki/display/AST/S IP+Retransmissions Packet timed out after 32000ms with no response [2016-05-03 18:27:23] WARNING[7779] chan_sip.c: Hanging up call 26efc70b51829837116733bc141600b9@ims.mnc010.mcc208.3gppnetw ork.org - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions). [2016-05-03 18:27:23] VERBOSE[2654][C-00000025] app_dial.c: SIP/SFR_Lys-0000004b is circuit-busy [2016-05-03 18:27:23] VERBOSE[2654][C-00000025] app_dial.c: Everyone is busy/congested at this time (1:0/1/0) [2016-05-03 18:27:23] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:24] NoOp("SIP/1003-0000004a", "Dial failed for some reason with DIALSTATUS = CONGESTION and HANGUPCAUSE = 18") in new stack [2016-05-03 18:27:23] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-dialout-trunk:25] GotoIf("SIP/1003-0000004a", "1? continue,1:s-CONGESTION,1") in new stack [2016-05-03 18:27:23] VERBOSE[2654][C-00000025] pbx.c: Goto (macro-dialout-trunk,continue,1) [2016-05-03 18:27:23] VERBOSE[2654][C-00000025] pbx.c: Executing [continue@macro-dialout-trunk:1] NoOp("SIP/1003-0000004a", "TRUNK Dial failed due to CONGESTION HANGUPCAUSE: 18 - failing through to other trunks") in new stack [2016-05-03 18:27:23] VERBOSE[2654][C-00000025] pbx.c: Executing [continue@macro-dialout-trunk:2] ExecIf("SIP/1003-0000004a ", "1?Set(CALLERID(number)=1003)") in new stack [2016-05-03 18:27:23] VERBOSE[2654][C-00000025] pbx.c: Executing [CALLED_NO@from-internal:6] Macro("SIP/1003-0000004a", "o utisbusy,") in new stack [2016-05-03 18:27:23] WARNING[2654][C-00000025] app_macro.c: No such context 'macro-outisbusy' for macro 'outisbusy'. Was c alled by CALLED_NO@from-internal [2016-05-03 18:27:23] VERBOSE[2654][C-00000025] pbx.c: Executing [CALLED_NO@from-internal:7] Wait("SIP/1003-0000004a", "1" ) in new stack [2016-05-03 18:27:24] VERBOSE[7779] chan_sip.c: Really destroying SIP dialog '26efc70b51829837116733bc141600b9@ims.mnc010.m cc208.3gppnetwork.org' Method: INVITE [2016-05-03 18:27:24] VERBOSE[2654][C-00000025] pbx.c: Executing [CALLED_NO@from-internal:8] Congestion("SIP/1003-0000004a ", "20") in new stack [2016-05-03 18:27:24] VERBOSE[2654][C-00000025] chan_sip.c: <--- Reliably Transmitting (no NAT) to ASTERIX_IP:5061 ---> SIP/2.0 503 Service Unavailable Via: SIP/2.0/UDP ASTERIX_IP:5061;branch=z9hG4bKb7e9f708;received=ASTERIX_IP From: "1003" ;tag=2401c78276ad1035f534f541-e606ca24 To: ;tag=as19d183f9 Call-ID: 2401c782-76ad0024-e2be580b-00b10606@ASTERIX_IP CSeq: 102 INVITE Server: FPBX-13.0.109(13.7.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer X-Asterisk-HangupCause: No user responding X-Asterisk-HangupCauseCode: 18 Content-Length: 0 <------------> [2016-05-03 18:27:24] WARNING[2654][C-00000025] channel.c: Prodding channel 'SIP/1003-0000004a' failed [2016-05-03 18:27:24] VERBOSE[2654][C-00000025] pbx.c: Spawn extension (from-internal, CALLED_NO, 8) exited non-zero on 'S IP/1003-0000004a' [2016-05-03 18:27:24] VERBOSE[2654][C-00000025] pbx.c: Executing [h@from-internal:1] Macro("SIP/1003-0000004a", "hangupcall ") in new stack [2016-05-03 18:27:24] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/1003-0000004a", "1?thee nd") in new stack [2016-05-03 18:27:24] VERBOSE[2654][C-00000025] pbx.c: Goto (macro-hangupcall,s,3) [2016-05-03 18:27:24] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/1003-0000004a", "0?Set( CDR(recordingfile)=)") in new stack [2016-05-03 18:27:24] VERBOSE[2654][C-00000025] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/1003-0000004a", "") in new stack [2016-05-03 18:27:24] VERBOSE[2654][C-00000025] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'S IP/1003-0000004a' in macro 'hangupcall' [2016-05-03 18:27:24] VERBOSE[2654][C-00000025] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/1003-0 000004a' [2016-05-03 18:27:24] VERBOSE[7779] chan_sip.c: <--- SIP read from UDP:ASTERIX_IP:52450 ---> ACK sip:CALLED_NO@EXTENSION_IP;user=phone SIP/2.0 Via: SIP/2.0/UDP ASTERIX_IP:5061;branch=z9hG4bKb7e9f708 From: "1003" ;tag=2401c78276ad1035f534f541-e606ca24 To: ;tag=as19d183f9 Call-ID: 2401c782-76ad0024-e2be580b-00b10606@ASTERIX_IP Max-Forwards: 70 Date: Tue, 03 May 2016 16:27:23 GMT CSeq: 102 ACK Content-Length: 0 <-------------> [2016-05-03 18:27:24] VERBOSE[7779] chan_sip.c: --- (9 headers 0 lines) --- [2016-05-03 18:27:24] VERBOSE[7779] chan_sip.c: Really destroying SIP dialog '2401c782-76ad0024-e2be580b-00b10606@192.168.1 .37' Method: ACK [2016-05-03 18:40:14] NOTICE[7779] chan_sip.c: -- Re-registration for +3399XXXXXXXXXX@internet.p-cscf.sfr.net [2016-05-03 18:40:14] VERBOSE[7779] chan_sip.c: REGISTER 12 headers, 0 lines [2016-05-03 18:40:14] VERBOSE[7779] chan_sip.c: Reliably Transmitting (NAT) to 91.68.1.28:5064: REGISTER sip:ims.mnc010.mcc208.3gppnetwork.org SIP/2.0 Via: SIP/2.0/UDP PUBLIC_IP:5061;branch=z9hG4bK792f6918;rport Max-Forwards: 70 From: ;tag=as484dae23 To: Call-ID: 575d047407a4d63f3f882657240806d9@127.0.1.1 CSeq: 152 REGISTER Supported: replaces, timer User-Agent: FPBX-13.0.109(13.7.0) Authorization: Digest username="NDIXXXXXXXXXX.LIBERTALK@sfr.fr", realm="sfr.fr", algorithm=MD5, uri="sip:ims.mnc010.mcc208. 3gppnetwork.org", nonce="b7c90365728c66bdbf3054aea940e9703dc8f84c0708", response="3a0e7abf2730b6c51225da80de636192", opaque ="ALU:QbkRBthOEgEQAkhWV1hYRAIBHgkdHwQCQ1lFRk5WGBkpdio3JnZ0ZiAnOGI-KD1-PzcnbmBmbmg_", qop=auth, cnonce="77c4823a", nc=000000 02 Expires: 3600 Contact: Content-Length: 0 --- [2016-05-03 18:40:14] VERBOSE[7779] chan_sip.c: <--- SIP read from UDP:91.68.1.28:5064 ---> SIP/2.0 401 Unauthorized Call-ID: 575d047407a4d63f3f882657240806d9@127.0.1.1 Via: SIP/2.0/UDP PUBLIC_IP:5061;received=PUBLIC_IP;branch=z9hG4bK792f6918;rport=5061 To: ;tag=54596242-5728d46e26be9013 From: ;tag=as484dae23 CSeq: 152 REGISTER Date: Tue, 03 May 2016 16:40:14 GMT Server: Alcatel-Lucent-HPSS/3.0.3 WWW-Authenticate: Digest realm="sfr.fr", nonce="b7c5728d46c9036dbf3054aea940e9703dc8f84c0308", opaque="ALU:QbkRBthOEgEQAkhW V1hYRAIBHgkdHwQCQ1lFRk5WGBkpdio3JnZ0ZiAnOGI-KD1-PzcnbmBmbmg_", algorithm=MD5, qop="auth" Content-Length: 0 <-------------> [2016-05-03 18:40:14] VERBOSE[7779] chan_sip.c: --- (10 headers 0 lines) --- [2016-05-03 18:40:14] VERBOSE[7779] chan_sip.c: Responding to challenge, registration to domain/host name internet.p-cscf.s fr.net [2016-05-03 18:40:14] VERBOSE[7779] chan_sip.c: REGISTER 12 headers, 0 lines [2016-05-03 18:40:14] VERBOSE[7779] chan_sip.c: Reliably Transmitting (NAT) to 91.68.1.28:5064: REGISTER sip:ims.mnc010.mcc208.3gppnetwork.org SIP/2.0 Via: SIP/2.0/UDP PUBLIC_IP:5061;branch=z9hG4bK58651a17;rport Max-Forwards: 70 From: ;tag=as484dae23 To: Call-ID: 575d047407a4d63f3f882657240806d9@127.0.1.1 CSeq: 153 REGISTER Supported: replaces, timer User-Agent: FPBX-13.0.109(13.7.0) Authorization: Digest username="NDIXXXXXXXXXX.LIBERTALK@sfr.fr", realm="sfr.fr", algorithm=MD5, uri="sip:ims.mnc010.mcc208. 3gppnetwork.org", nonce="b7c5728d46c9036dbf3054aea940e9703dc8f84c0308", response="35e1e0d50575908ebd0a147bb44654aa", opaque ="ALU:QbkRBthOEgEQAkhWV1hYRAIBHgkdHwQCQ1lFRk5WGBkpdio3JnZ0ZiAnOGI-KD1-PzcnbmBmbmg_", qop=auth, cnonce="189adbec", nc=000000 01 Expires: 3600 Contact: Content-Length: 0 --- [2016-05-03 18:40:14] VERBOSE[7779] chan_sip.c: <--- SIP read from UDP:91.68.1.28:5064 ---> SIP/2.0 200 OK Call-ID: 575d047407a4d63f3f882657240806d9@127.0.1.1 Via: SIP/2.0/UDP PUBLIC_IP:5061;received=PUBLIC_IP;branch=z9hG4bK58651a17;rport=5061 To: ;tag=54596242-5728d46e2c67260c From: ;tag=as484dae23 CSeq: 153 REGISTER Allow-Events: reg Contact: ;expires=3142 Date: Tue, 03 May 2016 16:40:14 GMT Path: P-Associated-URI: P-Associated-URI: Server: Alcatel-Lucent-HPSS/3.0.3 Content-Length: 0 <-------------> [2016-05-03 18:40:14] VERBOSE[7779] chan_sip.c: --- (14 headers 0 lines) --- [2016-05-03 18:40:14] NOTICE[7779] chan_sip.c: Outbound Registration: Expiry for internet.p-cscf.sfr.net is 3600 sec (Sched uling reregistration in 3585 s) [2016-05-03 18:40:14] VERBOSE[7779] chan_sip.c: Really destroying SIP dialog '575d047407a4d63f3f882657240806d9@127.0.1.1' M ethod: REGISTER