[2015-03-04 07:56:31] VERBOSE[1392] asterisk.c: -- Remote UNIX connection [2015-03-04 07:56:48] VERBOSE[26218] chan_sip.c: ˙<--- SIP read from TCP:172.16.254.71:49194 ---> ˙ ˙ ˙<-------------> [2015-03-04 07:56:48] VERBOSE[26227] chan_sip.c: ˙<--- SIP read from TCP:10.10.7.33:57306 ---> ˙ ˙ ˙<-------------> [2015-03-04 07:57:00] VERBOSE[1816] chan_sip.c: Reliably Transmitting (no NAT) to 10.10.10.220:5060: ˙OPTIONS sip:10.10.10.220 SIP/2.0 ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK03024bc2 ˙Max-Forwards: 70 ˙From: "Unknown" ;tag=as211a7a2c ˙To: ˙Contact: ˙Call-ID: 4d9fd83d2968ffc0045011533c690b12@10.10.10.71:5060 ˙CSeq: 102 OPTIONS ˙User-Agent: FPBX-2.11.0(11.7.0) ˙Date: Wed, 04 Mar 2015 12:57:00 GMT ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 0 ˙ ˙ ˙--- [2015-03-04 07:57:00] VERBOSE[24946] chan_sip.c: ˙<--- SIP read from TCP:10.10.10.220:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK03024bc2 ˙From: "Unknown" ;tag=as211a7a2c ˙To: ;tag=1624489050 ˙Date: Wed, 04 Mar 2015 12:36:41 GMT ˙Call-ID: 4d9fd83d2968ffc0045011533c690b12@10.10.10.71:5060 ˙CSeq: 102 OPTIONS ˙Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY ˙Content-Length: 0 ˙ ˙<-------------> [2015-03-04 07:57:00] VERBOSE[24946] chan_sip.c: --- (9 headers 0 lines) --- [2015-03-04 07:57:01] VERBOSE[1816] chan_sip.c: Really destroying SIP dialog '4d9fd83d2968ffc0045011533c690b12@10.10.10.71:5060' Method: OPTIONS [2015-03-04 07:57:04] VERBOSE[1816] chan_sip.c: Reliably Transmitting (no NAT) to 10.10.10.220:5060: ˙OPTIONS sip:10.10.10.220 SIP/2.0 ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK3a557b58 ˙Max-Forwards: 70 ˙From: "Unknown" ;tag=as6ff4e7d1 ˙To: ˙Contact: ˙Call-ID: 2e523b1632f7d0ea56c0887760c38d45@10.10.10.71:5060 ˙CSeq: 102 OPTIONS ˙User-Agent: FPBX-2.11.0(11.7.0) ˙Date: Wed, 04 Mar 2015 12:57:04 GMT ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 0 ˙ ˙ ˙--- [2015-03-04 07:57:04] VERBOSE[24946] chan_sip.c: ˙<--- SIP read from TCP:10.10.10.220:5060 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK3a557b58 ˙From: "Unknown" ;tag=as6ff4e7d1 ˙To: ;tag=1416622318 ˙Date: Wed, 04 Mar 2015 12:36:45 GMT ˙Call-ID: 2e523b1632f7d0ea56c0887760c38d45@10.10.10.71:5060 ˙CSeq: 102 OPTIONS ˙Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY ˙Content-Length: 0 ˙ ˙<-------------> [2015-03-04 07:57:04] VERBOSE[24946] chan_sip.c: --- (9 headers 0 lines) --- [2015-03-04 07:57:05] VERBOSE[1816] chan_sip.c: Really destroying SIP dialog '2e523b1632f7d0ea56c0887760c38d45@10.10.10.71:5060' Method: OPTIONS [2015-03-04 07:57:16] VERBOSE[26218] chan_sip.c: ˙<--- SIP read from TCP:172.16.254.71:49194 ---> ˙INVITE sip:5222@10.10.10.71 SIP/2.0 ˙Via: SIP/2.0/TCP 172.16.254.71:49194;branch=z9hG4bK4Pe3dpOUAvyqG5sY;rport ˙Contact: ˙Max-Forwards: 70 ˙From: ;tag=B6DC09BD85018083362621A44B3F2361 ˙Allow: OPTIONS, INVITE, ACK, REFER, CANCEL, BYE, NOTIFY ˙Supported: replaces, path ˙User-Agent: AcrBt Softphone ˙To: ˙Content-Type: application/sdp ˙Call-ID: FBD5898099E2CB3F344E7861D81694D461E3444C ˙CSeq: 1 INVITE ˙Content-Length: 373 ˙ ˙v=0 ˙o=- 9563979248 41789 IN IP4 172.26.170.170 ˙s=jdbzluw ˙c=IN IP4 172.16.254.71 ˙t=0 0 ˙m=audio 34834 RTP/AVP 106 105 0 101 ˙a=rtpmap:101 telephone-event/8000 ˙a=rtpmap:105 OPUS/48000/2 ˙a=rtpmap:106 OPUS/48000/2 ˙a=fmtp:101 0-15 ˙a=fmtp:105 maxplaybackrate=8000;useinbandfec=1;usedtx=1 ˙a=fmtp:106 maxplaybackrate=16000;useinbandfec=1;usedtx=1 ˙a=ptime:20 ˙a=sendrecv ˙<-------------> [2015-03-04 07:57:16] VERBOSE[26218] chan_sip.c: --- (13 headers 14 lines) --- [2015-03-04 07:57:16] VERBOSE[26218] chan_sip.c: Sending to 172.16.254.71:49194 (NAT) [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Sending to 172.16.254.71:49194 (NAT) [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Using INVITE request as basis request - FBD5898099E2CB3F344E7861D81694D461E3444C [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Found peer '6204' for '6204' from 172.16.254.71:49194 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: ˙<--- Reliably Transmitting (no NAT) to 172.16.254.71:49194 ---> ˙SIP/2.0 401 Unauthorized ˙Via: SIP/2.0/TCP 172.16.254.71:49194;branch=z9hG4bK4Pe3dpOUAvyqG5sY;received=172.16.254.71;rport=49194 ˙From: ;tag=B6DC09BD85018083362621A44B3F2361 ˙To: ;tag=as599d4d00 ˙Call-ID: FBD5898099E2CB3F344E7861D81694D461E3444C ˙CSeq: 1 INVITE ˙Server: FPBX-2.11.0(11.7.0) ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7aaffa43" ˙Content-Length: 0 ˙ ˙ ˙<------------> [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Scheduling destruction of SIP dialog 'FBD5898099E2CB3F344E7861D81694D461E3444C' in 6976 ms (Method: INVITE) [2015-03-04 07:57:16] VERBOSE[26218] chan_sip.c: ˙<--- SIP read from TCP:172.16.254.71:49194 ---> ˙ACK sip:5222@10.10.10.71 SIP/2.0 ˙Via: SIP/2.0/TCP 172.16.254.71:49194;branch=z9hG4bK4Pe3dpOUAvyqG5sY;rport ˙Max-Forwards: 70 ˙Call-ID: FBD5898099E2CB3F344E7861D81694D461E3444C ˙From: ;tag=B6DC09BD85018083362621A44B3F2361 ˙To: ;tag=as599d4d00 ˙CSeq: 1 ACK ˙Content-Length: 0 ˙ ˙<-------------> [2015-03-04 07:57:16] VERBOSE[26218] chan_sip.c: --- (8 headers 0 lines) --- [2015-03-04 07:57:16] VERBOSE[26218] chan_sip.c: ˙<--- SIP read from TCP:172.16.254.71:49194 ---> ˙INVITE sip:5222@10.10.10.71 SIP/2.0 ˙Via: SIP/2.0/TCP 172.16.254.71:49194;branch=z9hG4bKS5GXA8RzaPP7N84s;rport ˙Contact: ˙Max-Forwards: 70 ˙From: ;tag=B6DC09BD85018083362621A44B3F2361 ˙Allow: OPTIONS, INVITE, ACK, REFER, CANCEL, BYE, NOTIFY ˙Supported: replaces, path ˙User-Agent: AcrBt Softphone ˙To: ˙Content-Type: application/sdp ˙Call-ID: FBD5898099E2CB3F344E7861D81694D461E3444C ˙CSeq: 2 INVITE ˙Authorization: Digest username="6204",realm="asterisk",algorithm=MD5,uri="sip:5222@10.10.10.71",nonce="7aaffa43",response="f908dec90fc9b7fe48b4d9241f733af2" ˙Content-Length: 373 ˙ ˙v=0 ˙o=- 9563979248 41789 IN IP4 172.26.170.170 ˙s=jdbzluw ˙c=IN IP4 172.16.254.71 ˙t=0 0 ˙m=audio 34834 RTP/AVP 106 105 0 101 ˙a=rtpmap:101 telephone-event/8000 ˙a=rtpmap:105 OPUS/48000/2 ˙a=rtpmap:106 OPUS/48000/2 ˙a=fmtp:101 0-15 ˙a=fmtp:105 maxplaybackrate=8000;useinbandfec=1;usedtx=1 ˙a=fmtp:106 maxplaybackrate=16000;useinbandfec=1;usedtx=1 ˙a=ptime:20 ˙a=sendrecv ˙<-------------> [2015-03-04 07:57:16] VERBOSE[26218] chan_sip.c: --- (14 headers 14 lines) --- [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Sending to 172.16.254.71:49194 (no NAT) [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Using INVITE request as basis request - FBD5898099E2CB3F344E7861D81694D461E3444C [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Found peer '6204' for '6204' from 172.16.254.71:49194 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] netsock2.c: == Using SIP RTP TOS bits 184 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] netsock2.c: == Using SIP RTP CoS mark 5 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Found RTP audio format 106 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Found RTP audio format 105 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Found RTP audio format 0 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Found RTP audio format 101 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Found audio description format telephone-event for ID 101 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Found audio description format OPUS for ID 105 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Found audio description format OPUS for ID 106 [2015-03-04 07:57:16] WARNING[26218][C-00000798] chan_sip.c: Got Opus maxplaybackrate=8000 [2015-03-04 07:57:16] WARNING[26218][C-00000798] chan_sip.c: Got Opus maxplaybackrate=16000 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Capabilities: us - (ulaw|opus), peer - audio=(ulaw|opus)/video=(nothing)/text=(nothing), combined - (ulaw|opus) [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Peer audio RTP is at port 172.16.254.71:34834 [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: Looking for 5222 in from-internal (domain 10.10.10.71) [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: list_route: hop: [2015-03-04 07:57:16] VERBOSE[26218][C-00000798] chan_sip.c: ˙<--- Transmitting (no NAT) to 172.16.254.71:49194 ---> ˙SIP/2.0 100 Trying ˙Via: SIP/2.0/TCP 172.16.254.71:49194;branch=z9hG4bKS5GXA8RzaPP7N84s;received=172.16.254.71;rport=49194 ˙From: ;tag=B6DC09BD85018083362621A44B3F2361 ˙To: ˙Call-ID: FBD5898099E2CB3F344E7861D81694D461E3444C ˙CSeq: 2 INVITE ˙Server: FPBX-2.11.0(11.7.0) ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Contact: ˙Content-Length: 0 ˙ ˙ ˙<------------> [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [5222@from-internal:1] Goto("SIP/6204-00000763", "injection-5,5222,1") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (injection-5,5222,1) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [5222@injection-5:1] NoOp("SIP/6204-00000763", "Entering Injection: InjectDirectHook") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [5222@injection-5:2] GotoIf("SIP/6204-00000763", "1?dialexternal:continue") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (injection-5,5222,3) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [5222@injection-5:3] NoOp("SIP/6204-00000763", "Dialing external number 5222") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [5222@injection-5:4] Goto("SIP/6204-00000763", "outbound-allroutes,5222,1") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (outbound-allroutes,5222,1) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [5222@outbound-allroutes:1] Macro("SIP/6204-00000763", "user-callerid,LIMIT,EXTERNAL,") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:1] Set("SIP/6204-00000763", "TOUCH_MONITOR=1425473836.3651") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:2] Set("SIP/6204-00000763", "AMPUSER=6204") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:3] GotoIf("SIP/6204-00000763", "0?report") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:4] ExecIf("SIP/6204-00000763", "1?Set(REALCALLERIDNUM=6204)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:5] Set("SIP/6204-00000763", "AMPUSER=6204") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/6204-00000763", "0?limit") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:7] Set("SIP/6204-00000763", "AMPUSERCIDNAME=FrpbxUser B") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:8] GotoIf("SIP/6204-00000763", "0?report") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:9] Set("SIP/6204-00000763", "AMPUSERCID=6204") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:10] Set("SIP/6204-00000763", "__DIAL_OPTIONS=Ttr") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:11] Set("SIP/6204-00000763", "CALLERID(all)="FrpbxUser B" <6204>") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:12] GotoIf("SIP/6204-00000763", "0?limit") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:13] ExecIf("SIP/6204-00000763", "1?Set(GROUP(concurrency_limit)=6204)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:14] GosubIf("SIP/6204-00000763", "7?sub-ccss,s,1(outbound-allroutes,5222)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-ccss:1] ExecIf("SIP/6204-00000763", "0?Return()") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-ccss:2] Set("SIP/6204-00000763", "CCSS_SETUP=TRUE") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-ccss:3] GosubIf("SIP/6204-00000763", "0?monitor_config,1(outbound-allroutes,5222):monitor_default,1(outbound-allroutes,5222)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/6204-00000763", "0?is_exten") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/6204-00000763", "") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [monitor_default@sub-ccss:3] Return("SIP/6204-00000763", "FALSE") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:15] GotoIf("SIP/6204-00000763", "1?continue") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (macro-user-callerid,s,28) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:28] Set("SIP/6204-00000763", "CALLERID(number)=6204") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:29] Set("SIP/6204-00000763", "CALLERID(name)=FrpbxUser B") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:30] Set("SIP/6204-00000763", "CDR(cnum)=6204") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:31] Set("SIP/6204-00000763", "CDR(cnam)=FrpbxUser B") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-user-callerid:32] Set("SIP/6204-00000763", "CHANNEL(language)=en") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [5222@outbound-allroutes:2] Set("SIP/6204-00000763", "MOHCLASS=default") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [5222@outbound-allroutes:3] Set("SIP/6204-00000763", "_NODEST=") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [5222@outbound-allroutes:4] Gosub("SIP/6204-00000763", "sub-record-check,s,1(out,5222,)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:1] Set("SIP/6204-00000763", "REC_POLICY_MODE_SAVE=") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:2] GotoIf("SIP/6204-00000763", "1?check") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (sub-record-check,s,7) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:7] Set("SIP/6204-00000763", "__MON_FMT=wav") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:8] GotoIf("SIP/6204-00000763", "1?next") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (sub-record-check,s,11) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:11] ExecIf("SIP/6204-00000763", "0?Return()") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:12] ExecIf("SIP/6204-00000763", "0?Set(__REC_POLICY_MODE=)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:13] GotoIf("SIP/6204-00000763", "0?out,1") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:14] Set("SIP/6204-00000763", "__REC_STATUS=INITIALIZED") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:15] Set("SIP/6204-00000763", "NOW=1425473836") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:16] Set("SIP/6204-00000763", "__DAY=04") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:17] Set("SIP/6204-00000763", "__MONTH=03") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:18] Set("SIP/6204-00000763", "__YEAR=2015") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:19] Set("SIP/6204-00000763", "__TIMESTR=20150304-075716") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:20] Set("SIP/6204-00000763", "__FROMEXTEN=6204") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:21] Set("SIP/6204-00000763", "__CALLFILENAME=out-5222-6204-20150304-075716-1425473836.3651") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@sub-record-check:22] Goto("SIP/6204-00000763", "out,1") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (sub-record-check,out,1) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [out@sub-record-check:1] ExecIf("SIP/6204-00000763", "1?Set(__REC_POLICY_MODE=dontcare)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [out@sub-record-check:2] GosubIf("SIP/6204-00000763", "0?record,1(exten,5222,6204)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [out@sub-record-check:3] Return("SIP/6204-00000763", "") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [5222@outbound-allroutes:5] Macro("SIP/6204-00000763", "dialout-trunk,3,5222,,off") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/6204-00000763", "DIAL_TRUNK=3") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/6204-00000763", "0?sub-pincheck,s,1()") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/6204-00000763", "0?disabletrunk,1") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/6204-00000763", "DIAL_NUMBER=5222") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:5] Set("SIP/6204-00000763", "DIAL_TRUNK_OPTIONS=Ttr") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:6] Set("SIP/6204-00000763", "OUTBOUND_GROUP=OUT_3") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/6204-00000763", "1?nomax") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (macro-dialout-trunk,s,9) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/6204-00000763", "0?skipoutcid") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:10] Set("SIP/6204-00000763", "DIAL_TRUNK_OPTIONS=Tt") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:11] Macro("SIP/6204-00000763", "outbound-callerid,3") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/6204-00000763", "0?Set(CALLERPRES()=)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/6204-00000763", "0?Set(REALCALLERIDNUM=6204)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/6204-00000763", "1?normcid") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (macro-outbound-callerid,s,6) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:6] Set("SIP/6204-00000763", "USEROUTCID=FrpbxUser B <6204>") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:7] Set("SIP/6204-00000763", "EMERGENCYCID=") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:8] Set("SIP/6204-00000763", "TRUNKOUTCID=") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/6204-00000763", "1?trunkcid") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (macro-outbound-callerid,s,14) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/6204-00000763", "0?Set(CALLERID(all)=)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/6204-00000763", "1?Set(CALLERID(all)=FrpbxUser B <6204>)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/6204-00000763", "0?Set(CALLERID(all)=)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/6204-00000763", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:18] Set("SIP/6204-00000763", "CDR(outbound_cnum)=6204") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outbound-callerid:19] Set("SIP/6204-00000763", "CDR(outbound_cnam)=FrpbxUser B") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/6204-00000763", "0?sub-flp-3,s,1()") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:13] Set("SIP/6204-00000763", "OUTNUM=5222") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:14] Set("SIP/6204-00000763", "custom=SIP/scCUCM91") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/6204-00000763", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Tt)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/6204-00000763", "0?Set(DIAL_TRUNK_OPTIONS=TtM(confirm))") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:17] Macro("SIP/6204-00000763", "dialout-trunk-predial-hook,") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/6204-00000763", "") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/6204-00000763", "0?bypass,1") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/6204-00000763", "1?Set(CONNECTEDLINE(num,i)=5222)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/6204-00000763", "1?Set(CONNECTEDLINE(name,i)=CID:6204)") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/6204-00000763", "0?customtrunk") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:22] Dial("SIP/6204-00000763", "SIP/scCUCM91/5222,300,Tt") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] netsock2.c: == Using SIP RTP TOS bits 184 [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] netsock2.c: == Using SIP RTP CoS mark 5 [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] chan_sip.c: Audio is at 13904 [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] chan_sip.c: Adding codec 100003 (ulaw) to SDP [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] chan_sip.c: Reliably Transmitting (no NAT) to 10.10.10.220:5060: ˙INVITE sip:5222@10.10.10.220 SIP/2.0 ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK202673fb ˙Max-Forwards: 70 ˙From: "FrpbxUser B" ;tag=as2ca2cb68 ˙To: ˙Contact: ˙Call-ID: 191fe5aa6bf223ae6702ca963d757c24@10.10.10.220 ˙CSeq: 102 INVITE ˙User-Agent: FPBX-2.11.0(11.7.0) ˙Date: Wed, 04 Mar 2015 12:57:16 GMT ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Type: application/sdp ˙Content-Length: 231 ˙ ˙v=0 ˙o=root 258198525 258198525 IN IP4 10.10.10.71 ˙s=Asterisk PBX 11.7.0 ˙c=IN IP4 10.10.10.71 ˙t=0 0 ˙m=audio 13904 RTP/AVP 0 101 ˙a=rtpmap:0 PCMU/8000 ˙a=rtpmap:101 telephone-event/8000 ˙a=fmtp:101 0-16 ˙a=ptime:20 ˙a=sendrecv ˙ ˙--- [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] app_dial.c: -- Called SIP/scCUCM91/5222 [2015-03-04 07:57:16] VERBOSE[24946] chan_sip.c: ˙<--- SIP read from TCP:10.10.10.220:5060 ---> ˙SIP/2.0 100 Trying ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK202673fb ˙From: "FrpbxUser B" ;tag=as2ca2cb68 ˙To: ˙Date: Wed, 04 Mar 2015 12:36:57 GMT ˙Call-ID: 191fe5aa6bf223ae6702ca963d757c24@10.10.10.220 ˙CSeq: 102 INVITE ˙Allow-Events: presence ˙Content-Length: 0 ˙ ˙<-------------> [2015-03-04 07:57:16] VERBOSE[24946] chan_sip.c: --- (9 headers 0 lines) --- [2015-03-04 07:57:16] VERBOSE[26228] chan_sip.c: ˙<--- SIP read from TCP:10.10.10.220:41631 ---> ˙INVITE sip:6203@10.10.10.71:5060 SIP/2.0 ˙Via: SIP/2.0/TCP 10.10.10.220:5060;branch=z9hG4bK16955ed2e3b ˙From: "FrpbxUser B" ;tag=13562~ec10f85c-7bbc-4d9e-89d3-c62eca8ee3dd-30550148 ˙To: ˙Date: Wed, 04 Mar 2015 12:36:57 GMT ˙Call-ID: 24050000-4f61fc69-152-dc0a0a0a@10.10.10.220 ˙Supported: timer,resource-priority,replaces ˙Min-SE: 1800 ˙User-Agent: Cisco-CUCM9.1 ˙Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY ˙CSeq: 101 INVITE ˙Expires: 180 ˙Allow-Events: presence ˙Supported: X-cisco-srtp-fallback ˙Supported: Geolocation ˙Cisco-Guid: 0604307456-0000065536-0000000077-3691645450 ˙Session-Expires: 1800 ˙P-Asserted-Identity: "FrpbxUser B" ˙Remote-Party-ID: "FrpbxUser B" ;party=calling;screen=yes;privacy=off ˙Contact: ˙Max-Forwards: 69 ˙Content-Length: 0 ˙ ˙<-------------> [2015-03-04 07:57:16] VERBOSE[26228] chan_sip.c: --- (22 headers 0 lines) --- [2015-03-04 07:57:16] VERBOSE[26228] chan_sip.c: Sending to 10.10.10.220:41631 (NAT) [2015-03-04 07:57:16] VERBOSE[26228][C-00000799] chan_sip.c: Sending to 10.10.10.220:41631 (NAT) [2015-03-04 07:57:16] VERBOSE[26228][C-00000799] chan_sip.c: Using INVITE request as basis request - 24050000-4f61fc69-152-dc0a0a0a@10.10.10.220 [2015-03-04 07:57:16] VERBOSE[26228][C-00000799] chan_sip.c: Found peer '6204' for '6204' from 10.10.10.220:41631 [2015-03-04 07:57:16] VERBOSE[26228][C-00000799] chan_sip.c: ˙<--- Reliably Transmitting (no NAT) to 10.10.10.220:5060 ---> ˙SIP/2.0 401 Unauthorized ˙Via: SIP/2.0/TCP 10.10.10.220:5060;branch=z9hG4bK16955ed2e3b;received=10.10.10.220 ˙From: "FrpbxUser B" ;tag=13562~ec10f85c-7bbc-4d9e-89d3-c62eca8ee3dd-30550148 ˙To: ;tag=as0c71ee64 ˙Call-ID: 24050000-4f61fc69-152-dc0a0a0a@10.10.10.220 ˙CSeq: 101 INVITE ˙Server: FPBX-2.11.0(11.7.0) ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7f39702a" ˙Content-Length: 0 ˙ ˙ ˙<------------> [2015-03-04 07:57:16] VERBOSE[26228][C-00000799] chan_sip.c: Scheduling destruction of SIP dialog '24050000-4f61fc69-152-dc0a0a0a@10.10.10.220' in 6976 ms (Method: INVITE) [2015-03-04 07:57:16] VERBOSE[26228] chan_sip.c: ˙<--- SIP read from TCP:10.10.10.220:41631 ---> ˙ACK sip:6203@10.10.10.71:5060 SIP/2.0 ˙Via: SIP/2.0/TCP 10.10.10.220:5060;branch=z9hG4bK16955ed2e3b ˙From: "FrpbxUser B" ;tag=13562~ec10f85c-7bbc-4d9e-89d3-c62eca8ee3dd-30550148 ˙To: ;tag=as0c71ee64 ˙Date: Wed, 04 Mar 2015 12:36:57 GMT ˙Call-ID: 24050000-4f61fc69-152-dc0a0a0a@10.10.10.220 ˙Max-Forwards: 70 ˙CSeq: 101 ACK ˙Allow-Events: presence ˙Content-Length: 0 ˙ ˙<-------------> [2015-03-04 07:57:16] VERBOSE[26228] chan_sip.c: --- (10 headers 0 lines) --- [2015-03-04 07:57:16] VERBOSE[24946] chan_sip.c: ˙<--- SIP read from TCP:10.10.10.220:5060 ---> ˙SIP/2.0 401 Unauthorized ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK202673fb ˙From: "FrpbxUser B" ;tag=as2ca2cb68 ˙To: ;tag=13561~ec10f85c-7bbc-4d9e-89d3-c62eca8ee3dd-30550145 ˙Date: Wed, 04 Mar 2015 12:36:57 GMT ˙Call-ID: 191fe5aa6bf223ae6702ca963d757c24@10.10.10.220 ˙CSeq: 102 INVITE ˙Allow-Events: presence ˙Reason: Q.850; cause=21 ˙Content-Length: 0 ˙ ˙<-------------> [2015-03-04 07:57:16] VERBOSE[24946] chan_sip.c: --- (10 headers 0 lines) --- [2015-03-04 07:57:16] VERBOSE[24946][C-00000798] chan_sip.c: Transmitting (no NAT) to 10.10.10.220:5060: ˙ACK sip:5222@10.10.10.220 SIP/2.0 ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK202673fb ˙Max-Forwards: 70 ˙From: "FrpbxUser B" ;tag=as2ca2cb68 ˙To: ;tag=13561~ec10f85c-7bbc-4d9e-89d3-c62eca8ee3dd-30550145 ˙Contact: ˙Call-ID: 191fe5aa6bf223ae6702ca963d757c24@10.10.10.220 ˙CSeq: 102 ACK ˙User-Agent: FPBX-2.11.0(11.7.0) ˙Content-Length: 0 ˙ ˙ ˙--- [2015-03-04 07:57:16] NOTICE[24946][C-00000798] chan_sip.c: Failed to authenticate on INVITE to '"FrpbxUser B" ;tag=as2ca2cb68' [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] app_dial.c: -- SIP/scCUCM91-00000764 is circuit-busy [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] app_dial.c: == Everyone is busy/congested at this time (1:0/1/0) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:23] NoOp("SIP/6204-00000763", "Dial failed for some reason with DIALSTATUS = CONGESTION and HANGUPCAUSE = 21") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-dialout-trunk:24] GotoIf("SIP/6204-00000763", "0?continue,1:s-CONGESTION,1") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (macro-dialout-trunk,s-CONGESTION,1) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s-CONGESTION@macro-dialout-trunk:1] Set("SIP/6204-00000763", "RC=21") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s-CONGESTION@macro-dialout-trunk:2] Goto("SIP/6204-00000763", "21,1") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (macro-dialout-trunk,21,1) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [21@macro-dialout-trunk:1] Goto("SIP/6204-00000763", "continue,1") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Goto (macro-dialout-trunk,continue,1) [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [continue@macro-dialout-trunk:1] NoOp("SIP/6204-00000763", "TRUNK Dial failed due to CONGESTION HANGUPCAUSE: 21 - failing through to other trunks") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [continue@macro-dialout-trunk:2] Set("SIP/6204-00000763", "CALLERID(number)=6204") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [5222@outbound-allroutes:6] Macro("SIP/6204-00000763", "outisbusy,") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outisbusy:1] Progress("SIP/6204-00000763", "") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] chan_sip.c: Audio is at 16356 [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] chan_sip.c: Adding codec 100030 (opus) to SDP [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] chan_sip.c: Adding codec 100003 (ulaw) to SDP [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] chan_sip.c: ˙<--- Transmitting (no NAT) to 172.16.254.71:49194 ---> ˙SIP/2.0 183 Session Progress ˙Via: SIP/2.0/TCP 172.16.254.71:49194;branch=z9hG4bKS5GXA8RzaPP7N84s;received=172.16.254.71;rport=49194 ˙From: ;tag=B6DC09BD85018083362621A44B3F2361 ˙To: ;tag=as3739af60 ˙Call-ID: FBD5898099E2CB3F344E7861D81694D461E3444C ˙CSeq: 2 INVITE ˙Server: FPBX-2.11.0(11.7.0) ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Contact: ˙Content-Type: application/sdp ˙Content-Length: 355 ˙ ˙v=0 ˙o=root 1959008736 1959008736 IN IP4 10.10.10.71 ˙s=Asterisk PBX 11.7.0 ˙c=IN IP4 10.10.10.71 ˙t=0 0 ˙m=audio 16356 RTP/AVP 105 0 101 ˙a=rtpmap:105 opus/48000/2 ˙a=maxptime:60 ˙a=fmtp:105 maxplaybackrate=16000; stereo=0; sprop-stereo=0; useinbandfec=0 ˙a=rtpmap:0 PCMU/8000 ˙a=rtpmap:101 telephone-event/8000 ˙a=fmtp:101 0-16 ˙a=ptime:20 ˙a=sendrecv ˙ ˙<------------> [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outisbusy:2] GotoIf("SIP/6204-00000763", "0?emergency,1") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outisbusy:3] GotoIf("SIP/6204-00000763", "0?intracompany,1") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outisbusy:4] Playback("SIP/6204-00000763", "all-circuits-busy-now&pls-try-call-later, noanswer") in new stack [2015-03-04 07:57:16] VERBOSE[26239][C-00000798] file.c: -- Playing 'all-circuits-busy-now.slin' (language 'en') [2015-03-04 07:57:17] VERBOSE[1816] chan_sip.c: Really destroying SIP dialog '191fe5aa6bf223ae6702ca963d757c24@10.10.10.220' Method: INVITE [2015-03-04 07:57:18] VERBOSE[26239][C-00000798] file.c: -- Playing 'pls-try-call-later.slin' (language 'en') [2015-03-04 07:57:18] VERBOSE[26227] chan_sip.c: ˙<--- SIP read from TCP:10.10.7.33:57306 ---> ˙ ˙ ˙<-------------> [2015-03-04 07:57:19] VERBOSE[1816] chan_sip.c: Reliably Transmitting (no NAT) to 10.10.7.33:57306: ˙OPTIONS sip:6203@10.10.7.33:57306;transport=tcp SIP/2.0 ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK4cd9fec9 ˙Max-Forwards: 70 ˙From: "Unknown" ;tag=as210458f6 ˙To: ˙Contact: ˙Call-ID: 6a6eabb62ab60f391bb10a0e3e33088e@10.10.10.71:5060 ˙CSeq: 102 OPTIONS ˙User-Agent: FPBX-2.11.0(11.7.0) ˙Date: Wed, 04 Mar 2015 12:57:19 GMT ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 0 ˙ ˙ ˙--- [2015-03-04 07:57:19] VERBOSE[26227] chan_sip.c: ˙<--- SIP read from TCP:10.10.7.33:57306 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK4cd9fec9 ˙Contact: ˙From: "Unknown" ;tag=as210458f6 ˙Call-ID: 6a6eabb62ab60f391bb10a0e3e33088e@10.10.10.71:5060 ˙CSeq: 102 OPTIONS ˙To: ˙Allow: OPTIONS, INVITE, ACK, REFER, CANCEL, BYE, NOTIFY ˙Supported: replaces, path ˙Accept: application/sdp ˙Content-Length: 0 ˙ ˙<-------------> [2015-03-04 07:57:19] VERBOSE[26227] chan_sip.c: --- (11 headers 0 lines) --- [2015-03-04 07:57:20] VERBOSE[1816] chan_sip.c: Reliably Transmitting (no NAT) to 172.16.254.71:49194: ˙OPTIONS sip:6204@172.16.254.71:49194;transport=tcp SIP/2.0 ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK559c4019 ˙Max-Forwards: 70 ˙From: "Unknown" ;tag=as4dc36119 ˙To: ˙Contact: ˙Call-ID: 7e2cd6b76754052152cdc73f78dc0e0f@10.10.10.71:5060 ˙CSeq: 102 OPTIONS ˙User-Agent: FPBX-2.11.0(11.7.0) ˙Date: Wed, 04 Mar 2015 12:57:20 GMT ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙Content-Length: 0 ˙ ˙ ˙--- [2015-03-04 07:57:20] VERBOSE[1816] chan_sip.c: Really destroying SIP dialog '6a6eabb62ab60f391bb10a0e3e33088e@10.10.10.71:5060' Method: OPTIONS [2015-03-04 07:57:20] VERBOSE[26218] chan_sip.c: ˙<--- SIP read from TCP:172.16.254.71:49194 ---> ˙SIP/2.0 200 OK ˙Via: SIP/2.0/TCP 10.10.10.71:5060;branch=z9hG4bK559c4019 ˙Contact: ˙From: "Unknown" ;tag=as4dc36119 ˙Call-ID: 7e2cd6b76754052152cdc73f78dc0e0f@10.10.10.71:5060 ˙CSeq: 102 OPTIONS ˙To: ˙Allow: OPTIONS, INVITE, ACK, REFER, CANCEL, BYE, NOTIFY ˙Supported: replaces, path ˙Accept: application/sdp ˙Content-Length: 0 ˙ ˙<-------------> [2015-03-04 07:57:20] VERBOSE[26218] chan_sip.c: --- (11 headers 0 lines) --- [2015-03-04 07:57:20] VERBOSE[26239][C-00000798] pbx.c: -- Executing [s@macro-outisbusy:5] Congestion("SIP/6204-00000763", "20") in new stack [2015-03-04 07:57:20] VERBOSE[26239][C-00000798] chan_sip.c: ˙<--- Reliably Transmitting (no NAT) to 172.16.254.71:49194 ---> ˙SIP/2.0 503 Service Unavailable ˙Via: SIP/2.0/TCP 172.16.254.71:49194;branch=z9hG4bKS5GXA8RzaPP7N84s;received=172.16.254.71;rport=49194 ˙From: ;tag=B6DC09BD85018083362621A44B3F2361 ˙To: ;tag=as3739af60 ˙Call-ID: FBD5898099E2CB3F344E7861D81694D461E3444C ˙CSeq: 2 INVITE ˙Server: FPBX-2.11.0(11.7.0) ˙Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH ˙Supported: replaces, timer ˙X-Asterisk-HangupCause: Call Rejected ˙X-Asterisk-HangupCauseCode: 21 ˙Content-Length: 0 ˙ ˙ ˙<------------> [2015-03-04 07:57:20] WARNING[26239][C-00000798] channel.c: Prodding channel 'SIP/6204-00000763' failed [2015-03-04 07:57:20] VERBOSE[26239][C-00000798] app_macro.c: == Spawn extension (macro-outisbusy, s, 5) exited non-zero on 'SIP/6204-00000763' in macro 'outisbusy' [2015-03-04 07:57:20] VERBOSE[26239][C-00000798] pbx.c: == Spawn extension (outbound-allroutes, 5222, 6) exited non-zero on 'SIP/6204-00000763' [2015-03-04 07:57:20] VERBOSE[26218] chan_sip.c: ˙<--- SIP read from TCP:172.16.254.71:49194 ---> ˙ACK sip:5222@10.10.10.71 SIP/2.0 ˙Via: SIP/2.0/TCP 172.16.254.71:49194;branch=z9hG4bKS5GXA8RzaPP7N84s;rport ˙Max-Forwards: 70 ˙Call-ID: FBD5898099E2CB3F344E7861D81694D461E3444C ˙From: ;tag=B6DC09BD85018083362621A44B3F2361 ˙To: ;tag=as3739af60 ˙CSeq: 2 ACK ˙Content-Length: 0 ˙ ˙<-------------> [2015-03-04 07:57:20] VERBOSE[26218] chan_sip.c: --- (8 headers 0 lines) --- [2015-03-04 07:57:21] VERBOSE[1816] chan_sip.c: Really destroying SIP dialog '7e2cd6b76754052152cdc73f78dc0e0f@10.10.10.71:5060' Method: OPTIONS [2015-03-04 07:57:21] VERBOSE[1816] chan_sip.c: Really destroying SIP dialog 'FBD5898099E2CB3F344E7861D81694D461E3444C' Method: INVITE [2015-03-04 07:57:23] VERBOSE[1816] chan_sip.c: Really destroying SIP dialog '24050000-4f61fc69-152-dc0a0a0a@10.10.10.220' Method: INVITE [2015-03-04 07:57:27] VERBOSE[26237] asterisk.c: -- Remote UNIX connection disconnected