ВидеоКонф(ВКС)  ::   FAQ  ::   Поиск  ::   Регистрация  ::   Вход

FreePBX 13.0.195.12 рвет исходящие соединения

Обо всем касательно TrixBox, Elastix, AstPBX и всех других дистрибутивов

Модераторы: april22, Zavr2008

FreePBX 13.0.195.12 рвет исходящие соединения

Сообщение DmitrySidorov » 24 дек 2018, 16:51

День добрый.
есть freepbx 13.0.195.12
Обнаружили, что он часто рвет соединение. Т.е. соединение устанавливается , а потом он посылает на АТС CANCEL.
Странность, когда стали проверять, это происходит не на всех звонках, только МГ и сотовые.
При проверке на сотовый номер - примерно 50% таких обрывов, т.е. часть звонков проходит , часть нет, на один и тот же номер.
Транк один на телфин, грешил на модуль битрикса, который звонки подхватывает и в себя пишет, но при отключении его, не подтвердилось.

Ниже лог такого звонка:
[Показать] Спойлер:
2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@from-internal:1] Gosub("SIP/404-00000609", "sub-iub24-xfer,s,1()") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-iub24-xfer:1] ExecIf("SIP/404-00000609", "0?Set(CALLER_NUMBER_CHAN=)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-iub24-xfer:2] ExecIf("SIP/404-00000609", "0?Set(CALLER_NUMBER_CHAN=)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-iub24-xfer:3] GotoIf("SIP/404-00000609", "0?cut:skip") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-iub24-xfer:9] ExecIf("SIP/404-00000609", "0?Set(ARRAY(__DIRECTION,__REC_CHAN,__TRANSFER,__TRANSFERER,__B24_CALL_ID)=TRANSFER,,BLINDTRANSFER,,)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-iub24-xfer:10] ExecIf("SIP/404-00000609", "0?Set(ARRAY(__DIRECTION,__REC_CHAN,SHARED(REC_CHAN,,B24_CALL_ID),__TRANSFER,__TRANSFERER)=TRANSFER,,,ATTENDEDTRANSFER,,)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-iub24-xfer:11] Return("SIP/404-00000609", "") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@from-internal:2] GotoIf("SIP/404-00000609", "0?ext-local,1123,1:followme-check,1123,1") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-check:1] Gosub("SIP/404-00000609", "followme-sub,1123,1()") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:1] Macro("SIP/404-00000609", "user-callerid,") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/404-00000609", "TOUCH_MONITOR=1543937941.2248") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/404-00000609", "AMPUSER=404") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/404-00000609", "0?report") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/404-00000609", "1?Set(REALCALLERIDNUM=404)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/404-00000609", "AMPUSER=404") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/404-00000609", "0?limit") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/404-00000609", "AMPUSERCIDNAME=Sidorov") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("SIP/404-00000609", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("SIP/404-00000609", "0?report") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:10] Set("SIP/404-00000609", "AMPUSERCID=404") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:11] Set("SIP/404-00000609", "__DIAL_OPTIONS=Ttr") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:12] Set("SIP/404-00000609", "CALLERID(all)="Sidorov" <404>") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("SIP/404-00000609", "0?limit") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("SIP/404-00000609", "0?Set(GROUP(concurrency_limit)=404)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:15] NoOp("SIP/404-00000609", "Macro Depth is 1") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("SIP/404-00000609", "1?report2:macroerror") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("SIP/404-00000609", "0?continue") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:18] Set("SIP/404-00000609", "__TTL=64") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:19] GotoIf("SIP/404-00000609", "1?continue") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:35] Set("SIP/404-00000609", "CALLERID(number)=404") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:36] Set("SIP/404-00000609", "CALLERID(name)=Sidorov") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:37] GotoIf("SIP/404-00000609", "0?cnum") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:38] Set("SIP/404-00000609", "CDR(cnam)=Sidorov") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:39] Set("SIP/404-00000609", "CDR(cnum)=404") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-user-callerid:40] Set("SIP/404-00000609", "CHANNEL(language)=ru") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:2] Set("SIP/404-00000609", "DIAL_OPTIONS=TtrI") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:3] Set("SIP/404-00000609", "CONNECTEDLINE(num,i)=1123") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:4] Gosub("SIP/404-00000609", "sub-presencestate-display,s,1(1123)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-presencestate-display:1] Goto("SIP/404-00000609", "state-not_set,1") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [state-not_set@sub-presencestate-display:1] Set("SIP/404-00000609", "PRESENCESTATE_DISPLAY=") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [state-not_set@sub-presencestate-display:2] Return("SIP/404-00000609", "") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:5] Set("SIP/404-00000609", "CONNECTEDLINE(name)=Roma_vologda_mob") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:6] Set("SIP/404-00000609", "FM_DIALSTATUS=NOT_INUSE") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:7] Set("SIP/404-00000609", "__EXTTOCALL=1123") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:8] Set("SIP/404-00000609", "__PICKUPMARK=1123") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:9] Macro("SIP/404-00000609", "blkvm-setifempty,") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/404-00000609", "1?init") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-blkvm-setifempty:4] Set("SIP/404-00000609", "__BLKVM_CHANNEL=SIP/404-00000609") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-blkvm-setifempty:5] Set("SIP/404-00000609", "SHARED(BLKVM,SIP/404-00000609)=TRUE") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-blkvm-setifempty:6] Set("SIP/404-00000609", "GOSUB_RETVAL=TRUE") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/404-00000609", "") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:10] GotoIf("SIP/404-00000609", "1?skipov") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:13] Set("SIP/404-00000609", "RRNODEST=") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:14] Set("SIP/404-00000609", "__NODEST=1123") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:15] GosubIf("SIP/404-00000609", "0?sub-fmsetcid,s,1()") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:16] GotoIf("SIP/404-00000609", "1?skipprepend") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:18] Set("SIP/404-00000609", "RecordMethod=Group") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:19] Gosub("SIP/404-00000609", "sub-record-check,s,1(exten,1123,)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/404-00000609", "0?initialized") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:2] Set("SIP/404-00000609", "__REC_STATUS=INITIALIZED") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:3] Set("SIP/404-00000609", "NOW=1543937941") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:4] Set("SIP/404-00000609", "__DAY=04") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:5] Set("SIP/404-00000609", "__MONTH=12") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:6] Set("SIP/404-00000609", "__YEAR=2018") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:7] Set("SIP/404-00000609", "__TIMESTR=20181204-183901") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:8] Set("SIP/404-00000609", "__FROMEXTEN=404") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:9] Set("SIP/404-00000609", "__MON_FMT=wav") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/404-00000609", "Recordings initialized") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/404-00000609", "1?Set(ARG3=dontcare)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:12] Set("SIP/404-00000609", "REC_POLICY_MODE_SAVE=") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/404-00000609", "0?Set(REC_STATUS=NO)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/404-00000609", "5?checkaction") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/404-00000609", "1?sub-record-check,exten,1") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:1] NoOp("SIP/404-00000609", "Exten Recording Check between 404 and 1123") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:2] Set("SIP/404-00000609", "CALLTYPE=internal") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:3] ExecIf("SIP/404-00000609", "0?Set(CALLTYPE=)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:4] Set("SIP/404-00000609", "CALLEE=dontcare") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:5] ExecIf("SIP/404-00000609", "0?Set(CALLEE=dontcare)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:6] GotoIf("SIP/404-00000609", "0?callee") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:7] GotoIf("SIP/404-00000609", "1?caller") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:13] Set("SIP/404-00000609", "RECMODE=dontcare") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:14] ExecIf("SIP/404-00000609", "0?Set(RECMODE=dontcare)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:15] ExecIf("SIP/404-00000609", "1?Set(RECMODE=dontcare)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:16] Gosub("SIP/404-00000609", "recordcheck,1(dontcare,internal,1123)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/404-00000609", "Starting recording check against dontcare") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/404-00000609", "dontcare") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/404-00000609", "") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [exten@sub-record-check:17] Return("SIP/404-00000609", "") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:20] GotoIf("SIP/404-00000609", "1?skipdring") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:23] Set("SIP/404-00000609", "STRATEGY=ringall") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:24] Set("SIP/404-00000609", "__RVOL=") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:25] GotoIf("SIP/404-00000609", "0?skipsimple") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:26] GotoIf("SIP/404-00000609", "1 ?skipsimple") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:28] Set("SIP/404-00000609", "RingGroupMethod=ringall") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:29] Set("SIP/404-00000609", "_FMGRP=1123") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:30] GotoIf("SIP/404-00000609", "1?DIALGRP") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:34] ExecIf("SIP/404-00000609", "1?Set(DOPTS=TtrI):Set(DOPTS=m(Ring)TtI)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:35] GotoIf("SIP/404-00000609", "0?doconfirm") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:36] GotoIf("SIP/404-00000609", "0?ringallv21") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:37] Macro("SIP/404-00000609", "dial,20,TtrI,89535053129#") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:1] NoOp("SIP/404-00000609", "Blind Transfer: , Attended Transfer: , User: 404, Alert Info: ") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:2] ExecIf("SIP/404-00000609", "1?Set(ALERT_INFO=)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:3] ExecIf("SIP/404-00000609", "0?Set(ALERT_INFO=)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:4] ExecIf("SIP/404-00000609", "0?Set(ALERT_INFO=)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:5] ExecIf("SIP/404-00000609", "0?Set(CHANNEL(musicclass)=)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:6] AGI("SIP/404-00000609", "dialparties.agi") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_request: dialparties.agi
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_channel: SIP/404-00000609
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_language: ru
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_type: SIP
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_uniqueid: 1543937941.2248
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_version: 13.22.0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_callerid: 404
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_calleridname: Sidorov
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_callingpres: 0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_callingani2: 0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_callington: 0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_callingtns: 0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_dnid: 1123
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_rdnis: unknown
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_context: macro-dial
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_extension: s
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_priority: 6
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_enhanced: 0.0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_accountcode:
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> agi_threadid: 140590699087616
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >>
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "Starting New Dialparties.agi" 1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE CWINUSEBUSY
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1 (1)
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE ASTVERSION
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1 (13.22.0)
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE CWIGNORE
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE CFIGNORE
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE AMPUSER
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1 (404)
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE HAS_EXTENSION_STATE
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "Caller ID name is 'Sidorov' number is '404'" 1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "CW Ignore is: " 1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "CF Ignore is: " 1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "CW IN_USE/BUSY is: 1" 1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE QUEUEWAIT
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << SET VARIABLE __KEEPCID "TRUE"
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << SET VARIABLE DIALSTATUS_CW ""
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE ARG1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1 (20)
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE ARG2
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1 (TtrI)
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE RingGroupMethod
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1 (ringall)
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE ALERT_INFO
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1 ()
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE SIPADDHEADER
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE FMGRP
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1 (1123)
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE PR_DIALSTATUS
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE NODEST
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1 (1123)
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE RINGGROUP_INDEX
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE USE_CONFIRMATION
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "USE_CONFIRMATION: 'FALSE'" 5
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "RINGGROUP_INDEX: ''" 5
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "Methodology of ring is 'ringall'" 1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE ARG3
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1 (89535053129#)
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "Added extension 89535053129# to extension map" 3
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE ARG4
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE SCREEN
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE FROM_DID
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << DATABASE GET "CF" "89535053129#"
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "Extension 89535053129# cf is disabled" 3
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << DATABASE GET "CW" "89535053129#"
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << DATABASE GET "CFB" "89535053129#"
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << DATABASE GET "CFU" "89535053129#"
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "extnum 89535053129# has: cw: 0; hascfb: 0 [] hascfu: 0 []" 4
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "Built External dialstring component for 89535053129: Local/89535053129@from-internal/n" 4
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << SET VARIABLE FILTERED_DIAL "89535053129"
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "Filtered ARG3: 89535053129" 3
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "NODEST: 1123 adding M(auto-blkvm) to dialopts: TtrIM(auto-blkvm)" 4
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << VERBOSE "NODEST: 1123 blkvm enabled macro already in dialopts: TtrIM(auto-blkvm)" 4
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << GET VARIABLE DIRECTION
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << SET VARIABLE ds "Local/89535053129@from-internal/n,20,TtrIM(auto-blkvm)"
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << SET PRIORITY normdial
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << SET VARIABLE TIMEOUT "20"
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Rx << SET VARIABLE DIALOPTS "TtrIM(auto-blkvm)"
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Tx >> 200 result=1
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] res_agi.c: <SIP/404-00000609>AGI Script dialparties.agi completed, returning 0
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:9] NoOp("SIP/404-00000609", "Returned from dialparties with groups to dial") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:10] NoOp("SIP/404-00000609", "ringall array ") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:11] Set("SIP/404-00000609", "__FMGL_DIAL=") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:12] Set("SIP/404-00000609", "LOOPCNT=1") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:13] Set("SIP/404-00000609", "ITER=1") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:14] Set("SIP/404-00000609", "__EXTTOCALL=89535053129") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:15] NoOp("SIP/404-00000609", "Working with 89535053129") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:16] ExecIf("SIP/404-00000609", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:17] ExecIf("SIP/404-00000609", "0?Set(HASH(__SIPHEADERS,Alert-Info)=Normal;volume=)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:18] Set("SIP/404-00000609", "ITER=2") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:19] GotoIf("SIP/404-00000609", "0?ndloopbegin") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:20] Macro("SIP/404-00000609", "dial-ringall-predial-hook,") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial-ringall-predial-hook:1] GosubIf("SIP/404-00000609", "0?sub-dialin-hook-iub24,s,1()") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:21] ExecIf("SIP/404-00000609", "0?Set(ds=Local/89535053129@from-internal/n,20,TtrIM(auto-blkvm)g)") in new stack
[2018-12-04 18:39:01] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:22] Dial("SIP/404-00000609", "Local/89535053129@from-internal/n,20,TtrIM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2018-12-04 18:39:08] VERBOSE[25379][C-00000b61] app_dial.c: Local/89535053129@from-internal-00000133;1 is making progress passing it to SIP/404-00000609
[2018-12-04 18:39:11] VERBOSE[25382][C-00000b61] pbx.c: Executing [s@macro-blkvm-clr:1] Set("SIP/Telphin_56_out-0000060a", "SHARED(BLKVM,SIP/404-00000609)=") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:23] Set("SIP/404-00000609", "DIALSTATUS=NOANSWER") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:24] GosubIf("SIP/404-00000609", "0?NOANSWER,1()") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:25] NoOp("SIP/404-00000609", "Returning since nobody answered") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-dial:26] MacroExit("SIP/404-00000609", "") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:38] Goto("SIP/404-00000609", "nextstep") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:45] Set("SIP/404-00000609", "RingGroupMethod=") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:46] GotoIf("SIP/404-00000609", "0?nodest") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:47] Set("SIP/404-00000609", "__NODEST=") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:48] Set("SIP/404-00000609", "__PICKUPMARK=") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:49] Macro("SIP/404-00000609", "blkvm-clr,") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-blkvm-clr:1] Set("SIP/404-00000609", "SHARED(BLKVM,SIP/404-00000609)=") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-blkvm-clr:2] Set("SIP/404-00000609", "GOSUB_RETVAL=") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("SIP/404-00000609", "") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:50] Set("SIP/404-00000609", "DIALSTATUS=NOANSWER") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:51] GotoIf("SIP/404-00000609", "0?dohangup") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@followme-sub:52] Goto("SIP/404-00000609", "ext-local,1123,dest") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@ext-local:4] Set("SIP/404-00000609", "__PICKUPMARK=") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [1123@ext-local:5] Goto("SIP/404-00000609", ",return,1") in new stack
[2018-12-04 18:39:11] WARNING[25379][C-00000b61] pbx.c: Channel 'SIP/404-00000609' sent to invalid extension but no invalid handler: context,exten,priority=ext-local,return,1
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [h@ext-local:1] Macro("SIP/404-00000609", "hangupcall,") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/404-00000609", "1?theend") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/404-00000609", "0?Set(CDR(recordingfile)=)") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/404-00000609", "") in new stack
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/404-00000609' in macro 'hangupcall'
[2018-12-04 18:39:11] VERBOSE[25379][C-00000b61] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/404-00000609'


Ниже лог аналогичного звонка (сегодня тестировали) со стороны оператора:
[Показать] Спойлер:
1. U 2018/12/24 13:46:27.824605 194.67.55.58:5060 -> 213.170.92.166:5060

Call-ID: 30487970136a49e63aab93cc50b80d4e@194.67.55.58:5060
CSeq: 102 INVITE
User-Agent: FPBX-13.0.195.12(13.22.0)
Date: Mon, 24 Dec 2018 10:46:27 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 443

v=0
o=root 862917463 862917463 IN IP4 194.67.55.58
s=Asterisk PBX 13.22.0
c=IN IP4 194.67.55.58
t=0 0
m=audio 15558 RTP/AVP 0 8 3 111 9 18 4 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
2. U 2018/12/24 13:46:27.825119 213.170.92.166:5060 -> 194.67.55.58:5060
SIP/2.0 100 Auth trying
Via: SIP/2.0/UDP 194.67.55.58:5060;branch=z9hG4bK4f9c6823;rport=5060;received=194.67.55.58
From: <sip:00098902@194.67.55.58>;tag=as4901d952
To: <sip:73953337564@sip.telphin.com:5060>
Call-ID: 30487970136a49e63aab93cc50b80d4e@194.67.55.58:5060
CSeq: 102 INVITE
Server: Telphin SoftSwitch
Content-Length: 0
3. U 2018/12/24 13:46:27.825971 *********:5060 -> ********:5060
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP **********:5060;branch=z9hG4bK4f9c6823;rport=5060;received=*********
From: <sip:00098902@194.67.55.58>;tag=as4901d952
To: <sip:***********@sip.telphin.com:5060>;tag=6a7cce437f5452f52a8f71086849ca1f.92dd
Call-ID: 30487970136a49e63aab93cc50b80d4e@*********:5060
CSeq: 102 INVITE
Proxy-Authenticate: Digest realm="sip.telphin.com", nonce="XCC6L1wguQOChUsyfKRrUFCtaQSQO9ph"
Server: Telphin SoftSwitch
Content-Length: 0
4. U 2018/12/24 13:46:27.843080**********:5060 ->********5060
ACK sip:73953337564@sip.telphin.com:5060 SIP/2.0
Via: SIP/2.0/UDP ************:5060;branch=z9hG4bK4f9c6823;rport
Max-Forwards: 70
From: <sip:00098902@*********>;tag=as4901d952
To: <sip:********@sip.telphin.com:5060>;tag=6a7cce437f5452f52a8f71086849ca1f.92dd
Contact: <sip:00098902@********:5060>
Call-ID: 30487970136a49e63aab93cc50b80d4e@********:5060
CSeq: 102 ACK
User-Agent: FPBX-13.0.195.12(13.22.0)
Content-Length: 0
5. U 2018/12/24 13:46:27.844583 **********:5060 -> ************:5060
INVITE sip:*************@sip.telphin.com:5060 SIP/2.0
Via: SIP/2.0/UDP *************:5060;branch=z9hG4bK2203e75f;rport
Max-Forwards: 70
From: <sip:00098902@**********>;tag=as4901d952
To: <sip:*************@sip.telphin.com:5060>
Contact: <sip:00098902@***********:5060>
Call-ID: 30487970136a49e63aab93cc50b80d4e@*************:5060
CSeq: 103 INVITE
User-Agent: FPBX-13.0.195.12(13.22.0)
Proxy-Authorization: Digest username="00098902", realm="sip.telphin.com", algorithm=MD5, uri="sip:************@sip.telphin.com:5060", nonce="XCC6L1wguQOChUsyfKRrUFCtaQSQO9ph", response="41579f3dc72c062e5ef4d8a48a26e082"
Date: Mon, 24 Dec 2018 10:46:27 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 443

v=0
o=root 862917463 862917464 IN IP4 194.67.55.58
s=Asterisk PBX 13.22.0
c=IN IP4 194.67.55.58
t=0 0
m=audio 15558 RTP/AVP 0 8 3 111 9 18 4 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:9 G722/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:4 G723/8000
a=fmtp:4 annexa=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
6. U 2018/12/24 13:46:27.844973 *********:5060 -> *************:5060
SIP/2.0 100 Auth trying
Via: SIP/2.0/UDP *************:5060;branch=z9hG4bK2203e75f;rport=5060;received=**********
From: <sip:00098902@*************>;tag=as4901d952
To: <sip:***********@sip.telphin.com:5060>
Call-ID: 30487970136a49e63aab93cc50b80d4e@*************:5060
CSeq: 103 INVITE
Server: Telphin SoftSwitch
Content-Length: 0
7. U 2018/12/24 13:46:27.853099 ***********:5060 -> ************:5060
SIP/2.0 100 Trying
Via: SIP/2.0/UDP ************:5060;branch=z9hG4bK2203e75f;rport=5060;received=************
From: <sip:00098902@************>;tag=as4901d952
To: <sip:*************@sip.telphin.com:5060>
Call-ID: 30487970136a49e63aab93cc50b80d4e@************:5060
CSeq: 103 INVITE
Server: Telphin SoftSwitch
Content-Length: 0
8. U 2018/12/24 13:46:31.462339 ************:5060 -> ***********:5060
SIP/2.0 183 Session Progress
Record-Route: <sip:**************:5064;lr;did=48b.1112>
Record-Route: <sip:************@************:5062;lr=on;ftag=as4901d952>
Record-Route: <sip:************;lr=on;ftag=as4901d952;ldi=48b2.5c18>
Via: SIP/2.0/UDP ************:5060;received=************;branch=z9hG4bK2203e75f;rport=5060
From: <sip:00098902@*************>;tag=as4901d952
To: <sip:**************@sip.telphin.com:5060>;tag=sbc.284.867.1545648387
Call-ID: 30487970136a49e63aab93cc50b80d4e@*************:5060
CSeq: 103 INVITE
Content-Type: application/sdp
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,REGISTER,INFO,PRACK,SUBSCRIBE,NOTIFY,UPDATE,MESSAGE,REFER
Contact: <sip:***************:5068>
Server: Telphin SBC B2B
Content-Length: 232

v=0
o=- 223347280 223347280 IN IP4 ***************
s=SBC call
c=IN IP4 ************
t=0 0
m=audio 53454 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=ptime:20
a=fmtp:101 0-15
a=fmtp:18 annexb=no
9. U 2018/12/24 13:46:31.625224 ***********:5060 -> ***********:5060
CANCEL sip:************@sip.telphin.com:5060 SIP/2.0
Via: SIP/2.0/UDP **************:5060;branch=z9hG4bK2203e75f;rport
Max-Forwards: 70
From: <sip:00098902@**********>;tag=as4901d952
To: <sip:**********@sip.telphin.com:5060>
Call-ID: 30487970136a49e63aab93cc50b80d4e@**********:5060
CSeq: 103 CANCEL
User-Agent: FPBX-13.0.195.12(13.22.0)
Content-Length: 0
10. U 2018/12/24 13:46:31.625680 **********:5060 -> **********:5060
SIP/2.0 200 canceling
Via: SIP/2.0/UDP **********:5060;branch=z9hG4bK2203e75f;rport=5060;received=**********
From: <sip:00098902@**********>;tag=as4901d952
To: <sip:**********@sip.telphin.com:5060>;tag=d7c013bffb9c942f3697db6f3cea72b4-c0f7
Call-ID: 30487970136a49e63aab93cc50b80d4e@**********:5060
CSeq: 103 CANCEL
Server: Telphin SoftSwitch
Content-Length: 0
11. U 2018/12/24 13:46:31.645491 **********:5060 -> **********:5060
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP **********:5060;received=**********;branch=z9hG4bK2203e75f;rport=5060
From: <sip:00098902@**********>;tag=as4901d952
To: <sip:**********@sip.telphin.com:5060>;tag=sbc.284.867.1545648387
Call-ID: 30487970136a49e63aab93cc50b80d4e@**********:5060
CSeq: 103 INVITE
Contact: <sip:195.222.186.122:5068>
Server: Telphin SBC B2B
Content-Length: 0
12. U 2018/12/24 13:46:31.668975 **********:5060 -> **********:5060
ACK sip:195.222.186.122:5068 SIP/2.0
Via: SIP/2.0/UDP **********:5060;branch=z9hG4bK2203e75f;rport
Max-Forwards: 70
From: <sip:00098902@**********>;tag=as4901d952
To: <sip:**********@sip.telphin.com:5060>;tag=sbc.284.867.1545648387
Contact: <sip:00098902@**********:5060>
Call-ID: 30487970136a49e63aab93cc50b80d4e@**********:5060
CSeq: 103 ACK
User-Agent: FPBX-13.0.195.12(13.22.0)
Content-Length: 0
DmitrySidorov
 
Сообщений: 3
Зарегистрирован: 24 дек 2018, 15:53

Re: FreePBX 13.0.195.12 рвет исходящие соединения

Сообщение Zavr2008 » 24 дек 2018, 21:08

Это не странность - это неуважение к форумчанам выкладывать подобные портянки без спойлера.
Также неумение изучить тему Asterisk за NAT, об этом писалось и неоднократно: localnet, externip, directmedia... также и SIP ALG отключение..
Настройки SIP то где?
Российские шлюзы E1 Alvis-GW. Модернизация УПАТС с E1, Установка FreePBX, Системы антифрод "в разрыв" потоков E1 PRI / SS#7 ISUP.
Аватар пользователя
Zavr2008
 
Сообщений: 2158
Зарегистрирован: 27 янв 2011, 01:35

Re: FreePBX 13.0.195.12 рвет исходящие соединения

Сообщение DmitrySidorov » 25 дек 2018, 11:42

Извиняюсь, исправить я так понимаю уже нельзя.
local,external выставлены. SIP ALG отключен. Это базовые настройки. Проблема в том, что ошибка плавающая, т.е. я могу сделать 10 звонков подряд на сотовый номер и из них 50% успешны. Звонки на городские проходят все.
Конфиги ниже.
sip_general_additions.conf:
[Показать] Спойлер:
vmexten=*97
useragent=FPBX-13.0.195.12(13.22.0)
language=ru
disallow=all
allow=ulaw
allow=alaw
allow=gsm
allow=g726
allow=g722
allow=g729
allow=g723
context=from-sip-external
callerid=Unknown
notifyringing=yes
notifyhold=yes
tos_sip=cs3
tos_audio=ef
tos_video=af41
alwaysauthreject=yes
limitonpeers=yes
context=from-sip-external
callevents=no
tcpenable=no
bindport=5060
jbenable=no
srvlookup=no
rtptimeout=30
rtpkeepalive=0
rtpholdtimeout=300
registertimeout=20
allowguest=no
tlsbindaddr=[::]:5161
tlsclientmethod=tlsv1
tlsenable=no
registerattempts=0
notifyringing=yes
notifyhold=yes
canreinvite=no
checkmwi=10
defaultexpiry=120
videosupport=no
g726nonstandard=no
maxcallbitrate=384
maxexpiry=3600
minexpiry=60
nat=force_rport,comedia
ALLOW_SIP_ANON=no
callerid=Unknown
externip=**********
localnet=10.0.0.0/24
localnet=10.0.1.0/24
localnet=10.0.2.0/24
localnet=192.168.0.0/24
localnet=10.0.3.0/24
DmitrySidorov
 
Сообщений: 3
Зарегистрирован: 24 дек 2018, 15:53

Re: FreePBX 13.0.195.12 рвет исходящие соединения

Сообщение Vlad1983 » 25 дек 2018, 12:29

убрал под спойлеры логи в первом посте
ЛС: @rostel
Vlad1983
 
Сообщений: 4251
Зарегистрирован: 09 авг 2011, 11:51

Re: FreePBX 13.0.195.12 рвет исходящие соединения

Сообщение ded » 25 дек 2018, 12:48

TC, включите sip set debug on ip_addr_telphin (core set verbose 0 можно поставить, чтобы не анализировать лог самой freePBX),
пускай метёт всё в /var/log/asterisk/full

При обнаружении порванного звонка, или вам сообщили - "вот сейчас звонок с/на номер +79012345678 порвался!" находите этот диалог, смотрите подробности по sip debug, будет понятно с какой стороны CANCEL or BYE.
Я так подозреваю, что причина разрыва будет что-то вроде - Out of media in RTP stream within timeout 1800 vsec или сколько там.
Последний раз редактировалось ded 25 дек 2018, 12:56, всего редактировалось 1 раз.
ded
 
Сообщений: 15801
Зарегистрирован: 26 авг 2010, 19:00

Re: FreePBX 13.0.195.12 рвет исходящие соединения

Сообщение Zavr2008 » 25 дек 2018, 12:56

Настроек транка так и не увидел.
И если это проблема NAT, у Вас будет явная разница между входящими и исходящими.
Российские шлюзы E1 Alvis-GW. Модернизация УПАТС с E1, Установка FreePBX, Системы антифрод "в разрыв" потоков E1 PRI / SS#7 ISUP.
Аватар пользователя
Zavr2008
 
Сообщений: 2158
Зарегистрирован: 27 янв 2011, 01:35

Re: FreePBX 13.0.195.12 рвет исходящие соединения

Сообщение DmitrySidorov » 25 дек 2018, 13:20

Спасибо, тему можно закрывать. Проблема была в 729м кодеке
DmitrySidorov
 
Сообщений: 3
Зарегистрирован: 24 дек 2018, 15:53


Вернуться в Готовые VoIP дистрибутивы

Кто сейчас на форуме

Сейчас этот форум просматривают: нет зарегистрированных пользователей и гости: 11

© 2008 — 2024 Asterisk.ru
Digium, Asterisk and AsteriskNOW are registered trademarks of Digium, Inc.
Design and development by PostMet-Netzwerk GmbH