From: "Miloserdov Dmitry" Received: from one.bis.ru ([82.138.63.1] verified) by mail.bestvoip.ru (CommuniGate Pro SMTP 6.2c3) with ESMTPS id 2870247 for CGatePro@ru.stalker.com; Sun, 21 May 2017 13:34:12 +0300 Received: from x-mail.bis.corp ([192.168.1.5]:47172 helo=bis.ru) by one.bis.ru with esmtp (Exim 4.69) (envelope-from ) id 1dCOBL-0007MG-Br for CGatePro@ru.stalker.com; Sun, 21 May 2017 13:33:51 +0300 Received: from [95.220.161.185] (account dmiloserdov@bis.ru) by bis.ru (CommuniGate Pro XIMSS 6.1.15) with HTTPU id 6527320 for CGatePro@ru.stalker.com; Sun, 21 May 2017 13:33:50 +0300 X-Mailer: CommuniGate Pronto! HTML5 6.1.15.3471 Subject: =?utf-8?B?UmU6IFtDR1BdIGF1dG8tYXR0ZW5kYW50INC00LvRjyDQvdC1?= =?utf-8?B?0YHQvtCy0YHQtdC8INC70L7QutCw0LvRjNC90YvRhSDQvdC+0LzQtdGA?= =?utf-8?B?0L7Qsg==?= MIME-Version: 1.0 In-Reply-To: References: To: "CommuniGate Pro Russian Discussions" Date: Sun, 21 May 2017 13:33:50 +0300 Message-ID: Content-Type: text/plain; charset="utf-8"; format="flowed" Content-Transfer-Encoding: 8bit X-Drweb-SpamState: no X-Drweb-SpamScore: 0 X-DrWeb-SpamReason: gggruggvucftvghtrhhoucdtuddrfeeljedrvdehucetufdoteggodetrfcurfhrohhfihhlvgemuceonhhonhgvqeenuceurghilhhouhhtmecupfdsteenuc X-Antivirus: Dr.Web (R) for Unix mail servers drweb plugin ver.6.0.2.0 X-Antivirus-Code: 0x100000 On Sun, 21 May 2017 11:48:03 +0300 "Dmitry Akindinov" wrote: > Здравствуйте. > > On 2017-05-21 10:53, Miloserdov Dmitry wrote: >> On Sat, 20 May 2017 07:58:33 +0300 >> "Dmitry Akindinov" wrote: >>>>> Какая-то из сторон не поддерживает session timers и не хочет >>>>> отвечать на OPTIONS в диалоге. Попробуйте в WebAdmin -> Settings -> >>>>>Real-Time -> Nodes изменить таймер сессий по умолчанию на радикально >>>>>большое значение (скажем, два часа.) Если поможет, то это оно. >>>> >>>> Попробую. >>>> Но дело в том что перед разрывом соединения нет вообще никаких sip >>>>запросов ни в какую сторону. >>> >>> В логе, кусочек которого вы показали, речь шла именно о неудаче >>>обновить таймер сессии с помощью OPTIONS. Стоит поднять уровень лога >>>SIP Transport - будет хорошо видно запросы и ответы. >>> >>>> По сети перед разрывом ходят обычные RTP пакеты и CGP просто >>>>перестает их принимать и отвечает icmp-port-unreachable. >>>> Ниже запись sip трафика для проблемного звонка. Разрыв произошел >>>>между 14 и 15 пакетами на 151 секунде >>> >>> А зачем и кому там столько BYE? Уже с 7-го пакета. Это не похоже на >>>нормальный диалог. А ACK (предположительно - начало диалога) был 6-м. >>>То есть, CGPro практически сразу после установления диалога начал его >>>разрывать, а шлюз не отвечал. 15-м пакетом был BYE уже от шлюза, на >>>который CGPro ответил, что этого диалога нет давно. >>> В логах CGPro можно увидеть гораздо больше, если сделать их чуть >>>подробнее. >> >> Зачем не знаю. Первый не 7ой а третий, остальные точная копия. >> То есть попытки разорвать соединения начались еще до того как >>автосекретарь успел принять звонок. >> Похоже это проблема из-за контакт центра. > Надо бы подробные логи звонка. Стесняетесь сюда - тогда на >support@communigate.com. Там отвечают. > >> Контакт центр настроен, а IVR в нем нет - хотелось обойтись >>стандартным. > IVR в Контакт-центре есть, он там шораздо человечнее по интерфейсу, >чем базовый. Имел в виду "Контакт центр настроен, а IVR в нем не настроен" В базовом задаются первые цифры и длина добавочного номера, а в CC просто предлагают просто "разрешить звонки на добавочные номера". Я сходу не нашел на какие номера можно будет звонить, так как часть номеров у меня не локальные для CGP >> Или так делать нельзя, не поддерживаемая конфигурация? >> Отключение правила переадресующего входящие на ccincoming#pbx убрало >>все эти преждевременные BYE. Про проблемы с разрывом через 2 минуты >>пока не знаю протестирую в понедельник. > > Вот всё-таки хорошо было бы увидеть подробные логи в оригинальной >конфигурации. Ниже кусок лога в начале того звонка. От INVITE до OK между ними было два BYE. 19:01:12.739 5 SIP [0.0.0.0]:5060 <- [GWhost]:5060 inp(752): INVITE sip:4444@CGPhost:5060 SIP/2.0\r\nVia: SIP/2.0/UDP GWhost:5060;rpo 19:01:12.739 5 SIP UDP: SIPDATA-205873 preprocessing 19:01:12.739 2 SIPDATA-205873 inp: req [0.0.0.0]:5060 <- udp[GWhost]:5060 INVITE(752 bytes) sip:4444@CGPhost:5060 19:01:12.739 5 SIPDATA-205873 inp: INVITE sip:4444@CGPhost:5060 SIP/2.0 19:01:12.739 5 SIPDATA-205873 inp: Via: SIP/2.0/UDP GWhost:5060;rport;branch=z9hG4bKPjXo6wYpSGqFkOLtuFsx3FXjASKbVCoAYp 19:01:12.739 5 SIPDATA-205873 inp: Max-Forwards: 70 19:01:12.739 5 SIPDATA-205873 inp: From: "2043" ;tag=g.ezdHKEb947tJnY2MBXHrzUtaPrgGaz 19:01:12.739 5 SIPDATA-205873 inp: To: 19:01:12.739 5 SIPDATA-205873 inp: Contact: 19:01:12.739 5 SIPDATA-205873 inp: Call-ID: LQhtcSgIh.Ss1O-Z4UzH.e7vQuvz2ixE 19:01:12.739 5 SIPDATA-205873 inp: CSeq: 10447 INVITE 19:01:12.739 5 SIPDATA-205873 inp: Category: 227 19:01:12.739 5 SIPDATA-205873 inp: Content-Type: application/sdp 19:01:12.739 5 SIPDATA-205873 inp: Content-Length: 241 19:01:12.739 5 SIPDATA-205873 inp: 19:01:12.739 5 SIPDATA-205873 inp: v=0 19:01:12.739 5 SIPDATA-205873 inp: o=mgapp 1011228939 155821362 IN IP4 GWhost 19:01:12.739 5 SIPDATA-205873 inp: s=- 19:01:12.739 5 SIPDATA-205873 inp: c=IN IP4 GWhost 19:01:12.739 5 SIPDATA-205873 inp: t=0 0 19:01:12.739 5 SIPDATA-205873 inp: m=audio 21678 RTP/AVP 8 0 101 19:01:12.739 5 SIPDATA-205873 inp: a=rtpmap:8 PCMA/8000 19:01:12.739 5 SIPDATA-205873 inp: a=rtpmap:0 PCMU/8000 19:01:12.739 5 SIPDATA-205873 inp: a=rtpmap:101 telephone-event/8000 19:01:12.739 5 SIPDATA-205873 inp: a=fmtp:101 0-16 19:01:12.739 5 SIPDATA-205873 inp: a=ptime:30 19:01:12.739 5 SIPDATA-205873 inp: a=sendrecv 19:01:12.739 4 SIPDATA-205873 Hash=792139193 19:01:12.739 4 SIPS-101880 enqueued 19:01:12.739 5 SIPS-101880 INITIAL posted 19:01:12.739 2 SIPDATA-205873 created SIPS-101880 19:01:12.739 5 SIP UDP: SIPDATA-205873 preprocessed 19:01:12.740 5 SIPS(1) 101880: processing INITIAL 19:01:12.740 2 SIPS-101880 SIPDATA-205873 INVITE sip:4444@CGPhost:5060 from udp[GWhost]:5060 19:01:12.740 4 SIPS-101880 workarounds: BadCRYPTO 19:01:12.740 2 SIPDATA-205874 out: rsp [0.0.0.0]:5060 -> udp[GWhost]:5060 100-INVITE(345 bytes) 19:01:12.740 5 SIPDATA-205874 out: SIP/2.0 100 Trying 19:01:12.740 5 SIPDATA-205874 out: Via: SIP/2.0/UDP GWhost:5060;rport=5060;branch=z9hG4bKPjXo6wYpSGqFkOLtuFsx3FXjASKbVCoAYp 19:01:12.740 5 SIPDATA-205874 out: From: "2043" ;tag=g.ezdHKEb947tJnY2MBXHrzUtaPrgGaz 19:01:12.740 5 SIPDATA-205874 out: To: 19:01:12.740 5 SIPDATA-205874 out: Call-ID: LQhtcSgIh.Ss1O-Z4UzH.e7vQuvz2ixE 19:01:12.740 5 SIPDATA-205874 out: CSeq: 10447 INVITE 19:01:12.740 5 SIPDATA-205874 out: Server: CommuniGatePro/6.1.15 19:01:12.740 5 SIPDATA-205874 out: Content-Length: 0 19:01:12.740 5 SIPDATA-205874 out: 19:01:12.740 5 SIP [0.0.0.0]:5060 -> [GWhost]:5060 out(345): SIP/2.0 100 Trying\r\nVia: SIP/2.0/UDP GWhost:5060;rport=5060;branch=z9hG4bK 19:01:12.740 2 SIPS-101880 SIPDATA-205874 100-INVITE(trying) sent [0.0.0.0]:5060 -> udp[GWhost]:5060 19:01:12.740 4 SIGNAL-126490 enqueued 19:01:12.740 5 SIGNAL-126490 INITIAL posted 19:01:12.740 2 SIPS-101880 SIGNAL-126490 created 19:01:12.740 5 SIGNAL(1) 126490: processing INITIAL 19:01:12.740 5 SIPS(1) 101880: idling 19:01:12.740 2 SIGNAL-126490 SIPS-101880: INVITE(10447) sip:4444@CGPhost:5060 19:01:12.740 2 DIALOG-001792 created for SIGNAL-126490:[GWhost] 19:01:12.740 4 DIALOG-001792 enqueued 19:01:12.740 2 SIGNAL-126490 DIALOG-001792 created 19:01:12.740 4 SIGNAL-126490 AOR added: sip:4444@CGPhost:5060 19:01:12.740 4 SIGNAL-126490 applying server rules 19:01:12.740 5 SIGNAL-126490 processing 1 rules. stage=0 19:01:12.740 5 SIGNALRULE-126490 rule(ccOut_domain) condition #3(Authenticated) is false 19:01:12.740 5 SIGNAL-126490 1 of 1 rules processed 19:01:12.740 5 SIGNAL-126490 timeout set for 900s 19:01:12.740 2 SIGNAL-126490 INVITE sip:4444@CGPhost:5060 via sip:4444@CGPhost:5060 19:01:12.741 4 DIALOG-001792 callee set: pbx@my.domain 19:01:12.741 4 SIGNAL-126490 applying Account rules 19:01:12.741 5 SIGNAL-126490 processing 2 rules. stage=-1 19:01:12.741 4 SIGNALRULE-126490 rule(PBX Center starter) conditions met 19:01:12.741 4 SIGNALRULE-126490 rule(PBX Center starter): -> sip:pbx#pbx@my.domain 19:01:12.741 2 SIGNALRULE-126490 rule(PBX Center starter): redirected 19:01:12.741 5 SIGNAL-126490 1 of 2 rules processed 19:01:12.741 4 SIGNAL-126490 AOR added: sip:pbx#pbx@my.domain 19:01:12.741 2 SIGNAL-126490 redirected by Rules 19:01:12.741 5 SIGNAL-126490 timeout immediate set 19:01:12.741 2 SIGNAL-126490 INVITE sip:pbx#pbx@my.domain 19:01:12.741 2 PBXLEG-016008 'pbx' created for ACCOUNT(pbx@my.domain) 19:01:12.741 2 SIGNAL-126490 SIPS-101880: {1/2} sent to NODE-016008: INVITE sip:pbx#pbx@my.domain 19:01:12.741 5 SIGNAL(1) 126490: enqueued (0 secs) 19:01:12.741 5 SIGNAL(1) 126490: timeout 19:01:12.741 4 SIGNAL-126490 stage timeout (0 sec) 19:01:12.741 5 SIGNAL-126490 processing 1 rules. stage=0 19:01:12.741 4 SIGNALRULE-126490 rule(ccIn_domain) conditions met 19:01:12.741 2 PBXLEG-016008 started <- DIALOG-001792: 2043@GWhost(sip:2043@GWhost:5060;user=phone)(noUPDATE)(noREFER) 19:01:12.741 2 PBXLEG-016008 session refresh=300(active) 19:01:12.741 2 PBXLEG-016008 pbx.sppr(Main) started 19:01:12.741 4 SIGNALRULE-126490 rule(ccIn_domain): -> sip:ccincoming%23pbx@my.domain 19:01:12.742 2 PBXLEG-016008 ProgramLog: "calledUser = 4444" 19:01:12.742 2 SIGNALRULE-126490 rule(ccIn_domain): redirected 19:01:12.742 5 SIGNAL-126490 1 of 1 rules processed 19:01:12.742 4 SIGNAL-126490 cancelling all 19:01:12.742 4 SIGNAL-126490 {1/2} NODE-016008 cancelled 19:01:12.742 4 SIGNAL-126490 AOR added: sip:ccincoming%23pbx@my.domain 19:01:12.742 5 SIGNAL-126490 timeout set for 900s 19:01:12.742 2 SIGNAL-126490 INVITE sip:ccincoming%23pbx@my.domain 19:01:12.742 2 PBXLEG-016010 'ccincoming' created for ACCOUNT(pbx@my.domain) 19:01:12.742 2 MEDIA-001718 created for PBXLEG-016008: audio([0.0.0.0]:60000 8000Hz ssrc=44445011) 19:01:12.742 2 SIGNAL-126490 SIPS-101880: {2/3} sent to NODE-016010: INVITE sip:ccincoming%23pbx@my.domain 19:01:12.742 2 MEDIA-001718 audio offer SDP set:{101=DTMF 8=PCMA/8000} <-> [GWhost]:21678:21679 {101=DTMF 8=PCMA/8000,0=PCMU/8000,101=telephone-event/8000} 19:01:12.742 2 MEDIA-001718 processor started 19:01:12.742 2 PBXLEG-016010 started <- DIALOG-001792: 2043@GWhost(sip:2043@GWhost:5060;user=phone)(noUPDATE)(noREFER) 19:01:12.742 2 PBXLEG-016010 session refresh=300(active) 19:01:12.742 2 PBXLEG-016010 ccincoming.sppr(Main) started 19:01:12.742 2 PBXLEG-016008 session refresh=300(active) 19:01:12.742 5 SIGNAL(1) 126490: enqueued (900 secs) 19:01:12.742 2 MEDIA-001718 local answer SDP composed 19:01:12.743 4 DIALOG-001792 CALLEE(9CABB95B-16008-4F0B520B) created 19:01:12.743 2 MEDIA-001718 remote SDP retrieved 19:01:12.743 2 PBXLEG-016010 CLI command: GetNamedTask contactcenter@my.domain 19:01:12.743 2 PBXLEG-016008 SIGNAL-126490 200-INVITE response sent 19:01:12.743 5 SIGNAL-126490 FINAL posted 19:01:12.743 2 PBXLEG-016008 accepting started 19:01:12.743 5 SIGNAL(3) 126490: processing FINAL 19:01:12.743 2 PBXLEG-016008 incoming request CANCEL-ed after our 2xx-response 19:01:12.743 4 SIGNAL-126490 {1/2} NODE-016008 reported final(200) 19:01:12.743 4 SIGNAL-126490 DIALOG-001792 updating on <- 200-INVITE 19:01:12.743 4 SIGNAL-126492 enqueued 19:01:12.743 2 PBXLEG-016010 ProgramLog: "2 Main(2043@GWhost): general settings read: {agentInitialStatus=last;agentPty=7;agentSkill=4;alertTimeout=30;groupPty=5;logLevel=5;ringStrategy=random;waitingMusicList=(holdmusic);}" 19:01:12.743 4 DIALOG-001792 expiration timer set to 300 sec 19:01:12.743 4 SIGNAL-126490 200-INVITE call Record-Route[0] is reverted 19:01:12.743 3 SIGNAL-126490 supplementary 200-INVITE: upstreaming 19:01:12.743 2 SIGNAL-126490 SIPS-101880(resending): 200-INVITE upstreaming 19:01:12.743 5 SIPS-101880 SUPPLUPSTREAM posted 19:01:12.743 5 SIGNAL-126492 INITIAL posted 19:01:12.743 2 SIPDATA-000000 submitted to SIPS-101880 to suppl-upstream 19:01:12.743 5 SIGNAL(3) 126490: enqueued (900 secs) 19:01:12.743 5 SIGNAL(3) 126492: processing INITIAL 19:01:12.743 2 PBXLEG-016008 disconnected 19:01:12.743 2 SIGNAL-126492 NULL-000000: BYE(1) sip:2043@GWhost:5060;user=phone 19:01:12.743 2 PBXLEG-016008 program stopped 19:01:12.743 4 SIGNAL-126492 DIALOG-001792 updating on <- BYE 19:01:12.743 2 PBXLEG-016010 ProgramLog: "4 Main(2043@GWhost): Remote SDP active media types (audio): 19:01:12.744 5 SIPC(2) 005922: processing INITIAL 19:01:12.744 2 SIPC-005922 SIGNAL-126492 BYE sip:2043@GWhost:5060;maddr=GWhost;user=phone 19:01:12.744 5 SIGNAL(3) 126492: enqueued (900 secs) 19:01:12.744 4 SIPC-005922 resolving sip:GWhost:5060;maddr=GWhost 19:01:12.744 4 SIPC-005922 trying: sip:GWhost:5060 19:01:12.744 2 PBXLEG-016010 ProgramLog: "2 Main(2043@GWhost): IVR NOT found for number: 4444" 19:01:12.744 5 SIPC-005922 timeout set for 2s 19:01:12.744 2 SIPDATA-205875 out: req [CGPhost]:5060 -> udp[GWhost]:5060 BYE(537 bytes) sip:2043@GWhost:5060;maddr=GWhost;user=phone 19:01:12.744 5 SIPDATA-205875 out: BYE sip:2043@GWhost:5060;maddr=GWhost;user=phone SIP/2.0 19:01:12.744 5 SIPDATA-205875 out: Via: SIP/2.0/UDP CGPhost:5060;branch=z9hG4bK5922;rport 19:01:12.744 5 SIPDATA-205875 out: P-CGP-Identity: pbx@my.domain 19:01:12.744 5 SIPDATA-205875 out: Max-Forwards: 15 19:01:12.744 5 SIPDATA-205875 out: From: ;tag=9CABB95B-16008-4F0B520B 19:01:12.744 5 SIPDATA-205875 out: To: "2043" ;tag=g.ezdHKEb947tJnY2MBXHrzUtaPrgGaz 19:01:12.744 5 SIPDATA-205875 out: Call-ID: LQhtcSgIh.Ss1O-Z4UzH.e7vQuvz2ixE 19:01:12.744 5 SIPDATA-205875 out: Contact: 19:01:12.744 5 SIPDATA-205875 out: CSeq: 1 BYE 19:01:12.744 5 SIPDATA-205875 out: Reason: SIP;cause=400;text="Request cancelled" 19:01:12.744 5 SIPDATA-205875 out: User-Agent: CommuniGatePro-callLeg/6.1.15 19:01:12.744 5 SIPDATA-205875 out: Content-Length: 0 19:01:12.744 5 SIPDATA-205875 out: 19:01:12.744 5 SIP [0.0.0.0]:5060 -> [GWhost]:5060 out(537): BYE sip:2043@GWhost:5060;maddr=GWhost;user=phone SIP/2.0\r\nVia: SIP/2 19:01:12.744 2 SIPC-005922 SIPDATA-205875 BYE sip:2043@GWhost:5060;maddr=GWhost;user=phone sent [CGPhost]:5060 -> udp[GWhost]:5060 19:01:12.744 5 SIPC(2) 005922: enqueued (2 secs) 19:01:12.744 2 PBXLEG-016010 ProgramLog: "3 Main(2043@GWhost): RouteAddress: {host=\"[GWhost]\";module=SMTP;object=2043;} -> {host=pbx@my.domain;module=LOCAL;object=\"\";}" 19:01:12.744 2 PBXLEG-016010 ProgramLog: "2 Main(2043@GWhost): CG-Card CRM request: {op=getTel;param=2043;}" 19:01:12.745 2 PBXLEG-016010 CLI command: ListAccountSessions pbx@my.domain PROTOCOL WebUser 19:01:12.745 2 PBXLEG-016010 CLI command: GetSession 8482-OX24uyn2rQUFUoeHPG4L Domain my.domain 19:01:12.745 2 PBXLEG-016010 ProgramLog: "2 Main(2043@GWhost): CG-Card CRM result: #NULL#" 19:01:12.746 2 PBXLEG-016010 ProgramLog: "3 Main(2043@GWhost): original: 2043@GWhost -> 4444@CGPhost" 19:01:12.746 2 PBXLEG-016010 ProgramLog: "3 Main(2043@GWhost): routed: #NULL# -> pbx@my.domain" 19:01:12.746 2 PBXLEG-016010 ProgramLog: "3 Main(2043@GWhost): failed to read 'pbx@my.domain' CC settings: failed to read CC settings file: \"/private/contactcenter/ccobjects/pbx.settings\"" 19:01:12.746 2 PBXLEG-016010 ProgramLog: "2 Main(2043@GWhost): bypassing CC: 2043@GWhost -> 4444@CGPhost" 19:01:12.747 3 PBXLEG-016010 failed to open '2043@GWhost'. Error Code=account is not available on this system 19:01:12.747 2 PBXLEG-016010 ProgramLog: "3 Main(2043@GWhost): record in bypass Enabled: From(NO), Impersonate(YES), To(YES)" 19:01:12.747 2 PBXLEG-016010 ProgramLog: "callerLeg:{\"\"=\"sip:4444@CGPhost:5060;fromCC=true\";Call-ID=LQhtcSgIh.Ss1O-Z4UzH.e7vQuvz2ixE.bypassCC;From=\"sip:2043@GWhost\";Max-Forwards=#69;P-CGP-Local=cc;fromName=2043;impersonate=pbx@my.domain;noBeeps=YES;referMode=peer;useMixer=YES;}" 19:01:12.747 2 PBXLEG-016010 spawning PBXLEG-016012 19:01:12.747 2 PBXLEG-016012 spawned by PBXLEG-016010 19:01:12.748 2 PBXLEG-016012 callerleg.sppi(bridgeCaller) started 19:01:12.748 2 PBXLEG-016012 impersonated as itself(pbx@my.domain) 19:01:12.748 2 MEDIA-001719 created for PBXLEG-016012: audio([0.0.0.0]:60002 8000Hz ssrc=44445012) 19:01:12.748 2 MEDIA-001719 processor started 19:01:12.748 2 MEDIA-001719 local offer SDP composed 19:01:12.748 2 PBXLEG-016012 calling sip:4444@CGPhost:5060;fromCC=true(SDP) 19:01:12.748 4 SIGNAL-126494 enqueued 19:01:12.748 5 SIGNAL-126494 INITIAL posted 19:01:12.748 5 SIGNAL(1) 126494: processing INITIAL 19:01:12.748 2 SIGNAL-126494 NODE-016012: INVITE(1) sip:4444@CGPhost:5060;fromCC=true 19:01:12.748 2 DIALOG-001793 created for SIGNAL-126494:[*] 19:01:12.748 4 DIALOG-001793 enqueued 19:01:12.749 2 SIGNAL-126494 DIALOG-001793 created 19:01:12.749 4 DIALOG-001793 caller set: pbx@my.domain 19:01:12.749 4 SIGNAL-126494 AOR added: sip:4444@CGPhost:5060;fromCC=true 19:01:12.749 4 SIGNAL-126494 applying server rules 19:01:12.749 5 SIGNAL-126494 processing 1 rules. stage=0 19:01:12.749 5 SIGNALRULE-126494 rule(ccOut_domain) condition #2(Submit Address) is false 19:01:12.749 5 SIGNAL-126494 1 of 1 rules processed 19:01:12.749 5 SIGNAL-126494 timeout set for 900s 19:01:12.749 2 SIGNAL-126494 INVITE sip:4444@CGPhost:5060;fromCC=true via sip:4444@CGPhost:5060;fromCC=true 19:01:12.749 4 DIALOG-001793 callee set: pbx@my.domain 19:01:12.749 4 SIGNAL-126494 applying Account rules 19:01:12.749 5 SIGNAL-126494 processing 2 rules. stage=-1 19:01:12.749 4 SIGNALRULE-126494 rule(PBX Center starter) conditions met 19:01:12.749 4 SIGNALRULE-126494 rule(PBX Center starter): -> sip:pbx#pbx@my.domain 19:01:12.749 2 SIGNALRULE-126494 rule(PBX Center starter): redirected 19:01:12.749 5 SIGNAL-126494 1 of 2 rules processed 19:01:12.749 4 SIGNAL-126494 AOR added: sip:pbx#pbx@my.domain 19:01:12.749 2 SIGNAL-126494 redirected by Rules 19:01:12.749 5 SIGNAL-126494 timeout immediate set 19:01:12.749 2 SIGNAL-126494 INVITE sip:pbx#pbx@my.domain 19:01:12.749 2 PBXLEG-016014 'pbx' created for ACCOUNT(pbx@my.domain) 19:01:12.749 2 SIGNAL-126494 NODE-016012: {1/2} sent to NODE-016014: INVITE sip:pbx#pbx@my.domain 19:01:12.749 5 SIGNAL(1) 126494: enqueued (0 secs) 19:01:12.749 5 SIGNAL(1) 126494: timeout 19:01:12.749 4 SIGNAL-126494 stage timeout (0 sec) 19:01:12.749 5 SIGNAL-126494 processing 1 rules. stage=0 19:01:12.749 5 SIGNALRULE-126494 rule(ccIn_domain) condition #2(RequestURI) is false 19:01:12.749 5 SIGNAL-126494 1 of 1 rules processed 19:01:12.749 5 SIGNAL-126494 timeout set for 900s 19:01:12.749 5 SIGNAL(1) 126494: enqueued (900 secs) 19:01:12.750 2 PBXLEG-016014 started <- DIALOG-001793: 2043@GWhost(sip:signode-16012-4F0B520B@my.domain) 19:01:12.750 2 PBXLEG-016014 session refresh=300(passive) 19:01:12.750 2 PBXLEG-016014 peer authenticated as 'pbx@my.domain' 19:01:12.750 2 PBXLEG-016014 pbx.sppr(Main) started 19:01:12.750 2 PBXLEG-016014 ProgramLog: "calledUser = 4444" 19:01:12.750 2 MEDIA-001720 created for PBXLEG-016014: audio([0.0.0.0]:60004 8000Hz ssrc=44445013) 19:01:12.750 2 MEDIA-001720 processor started 19:01:12.750 2 MEDIA-001720 audio offer SDP set:{101=DTMF 0=PCMU/8000} <-> [127.0.0.1]:60002:*60003 {101=DTMF 0=PCMU/8000,8=PCMA/8000,101=telephone-event/8000} rtcpping=M:1719:1618460727 dtls=actpass crypto 19:01:12.750 2 PBXLEG-016014 session refresh=300(passive) 19:01:12.750 2 MEDIA-001720 local answer SDP composed 19:01:12.750 4 DIALOG-001793 CALLEE(7EB64DF8-16014-4F0B520B) created 19:01:12.751 2 MEDIA-001720 remote SDP retrieved 19:01:12.751 2 PBXLEG-016014 SIGNAL-126494 200-INVITE response sent 19:01:12.751 5 SIGNAL-126494 FINAL posted 19:01:12.751 2 PBXLEG-016014 accepting started 19:01:12.751 5 SIGNAL(3) 126494: processing FINAL 19:01:12.751 4 SIGNAL-126494 {1/2} NODE-016014 reported final(200) 19:01:12.751 4 SIGNAL-126494 DIALOG-001793 updating on <- 200-INVITE 19:01:12.751 4 DIALOG-001793 expiration timer set to 300 sec 19:01:12.751 4 SIGNAL-126494 200-INVITE call Record-Route[0] is reverted 19:01:12.751 4 SIGNAL-126494 collected code=200(OK) 19:01:12.751 2 DIALOG-001793 CALLEE(7EB64DF8-16014-4F0B520B) connected 19:01:12.751 4 DIALOG-001793 updating caller info 19:01:12.751 2 ACCOUNT(pbx) out call connected. alerting=0 sec 19:01:12.751 4 DIALOG-001793 updating callee info 19:01:12.751 2 ACCOUNT(pbx) inp call connected. alerting=0 sec 19:01:12.751 2 SIGNAL-126494 200-INVITE reporting 19:01:12.751 5 SIGNAL(3) 126494: killing 19:01:12.751 4 SIGNAL-126494 dequeued 19:01:12.751 2 SIGNAL-126494 releasing 19:01:12.751 2 MEDIA-001719 audio answer SDP set:{101=DTMF 0=PCMU/8000} <-> [127.0.0.1]:60004:*60005 {101=DTMF 0=PCMU/8000,8=PCMA/8000,101=telephone-event/8000} rtcpping=M:1720:1564737788 19:01:12.751 2 PBXLEG-016012 started -> DIALOG-001793: 4444@CGPhost(sip:signode-16014-4F0B520B@my.domain) 19:01:12.751 2 PBXLEG-016012 session refresh=300(active) 19:01:12.752 4 SIGNAL-126496 enqueued 19:01:12.752 5 SIGNAL-126496 DOWNSTREAM posted 19:01:12.752 2 PBXLEG-016012 event([asyncCallFinal]) retrieved 19:01:12.752 5 SIGNAL(1) 126496: processing DOWNSTREAM 19:01:12.752 2 SIGNAL-126496 NODE-016012:downstreaming ACK(1) sip:signode-16014-4F0B520B@my.domain 19:01:12.752 4 SIGNAL-126496 DIALOG-001793 updating on -> ACK 19:01:12.752 2 SIGNAL-126496 NODE-016012 downstreamed to NODE-016014: ACK sip:signode-16014-4F0B520B@my.domain 19:01:12.752 5 SIGNAL(1) 126496: killing 19:01:12.752 4 SIGNAL-126496 dequeued 19:01:12.752 2 SIGNAL-126496 releasing 19:01:12.844 2 MEDIA-001718 processor finished 19:01:12.944 2 MEDIA-001718 released. 0(0) <-> 0(0) 19:01:12.944 2 MEDIA-001718 channel released 19:01:12.944 2 PBXLEG-016008 releasing 19:01:14.000 5 SIPC(2) 005922: timeout 19:01:14.000 3 SIPC-005922 calling timeout, resending 19:01:14.000 5 SIPC-005922 timeout set for 1s 19:01:14.000 2 SIPDATA-205876 out: req [CGPhost]:5060 -> udp[GWhost]:5060 BYE(537 bytes) sip:2043@GWhost:5060;maddr=GWhost;user=phone 19:01:14.000 5 SIPDATA-205876 out: BYE sip:2043@GWhost:5060;maddr=GWhost;user=phone SIP/2.0 19:01:14.000 5 SIPDATA-205876 out: Via: SIP/2.0/UDP CGPhost:5060;branch=z9hG4bK5922;rport 19:01:14.000 5 SIPDATA-205876 out: P-CGP-Identity: pbx@my.domain 19:01:14.000 5 SIPDATA-205876 out: Max-Forwards: 15 19:01:14.000 5 SIPDATA-205876 out: From: ;tag=9CABB95B-16008-4F0B520B 19:01:14.000 5 SIPDATA-205876 out: To: "2043" ;tag=g.ezdHKEb947tJnY2MBXHrzUtaPrgGaz 19:01:14.000 5 SIPDATA-205876 out: Call-ID: LQhtcSgIh.Ss1O-Z4UzH.e7vQuvz2ixE 19:01:14.000 5 SIPDATA-205876 out: Contact: 19:01:14.000 5 SIPDATA-205876 out: CSeq: 1 BYE 19:01:14.000 5 SIPDATA-205876 out: Reason: SIP;cause=400;text="Request cancelled" 19:01:14.000 5 SIPDATA-205876 out: User-Agent: CommuniGatePro-callLeg/6.1.15 19:01:14.000 5 SIPDATA-205876 out: Content-Length: 0 19:01:14.000 5 SIPDATA-205876 out: 19:01:14.000 5 SIP [0.0.0.0]:5060 -> [GWhost]:5060 out(537): BYE sip:2043@GWhost:5060;maddr=GWhost;user=phone SIP/2.0\r\nVia: SIP/2 19:01:14.000 2 SIPC-005922 SIPDATA-205876 BYE sip:2043@GWhost:5060;maddr=GWhost;user=phone sent [CGPhost]:5060 -> udp[GWhost]:5060 19:01:14.000 5 SIPC(2) 005922: enqueued (1 secs) 19:01:14.748 3 MEDIA-001719 adjusting sender timer: 2000ms 19:01:14.749 3 MEDIA-001720 adjusting sender timer: 2000ms 19:01:14.749 3 MEDIA-001719 adjusting sender timer: -88ms 19:01:14.749 2 PBXLEG-016010 event(connected) from NODE-016012 retrieved 19:01:14.749 2 MEDIA-001720 audio inp(1,55E0)44445012 sourced 19:01:14.749 2 MEDIA-001719 audio inp(1,55E8)44445013 sourced 19:01:14.749 3 MEDIA-001720 adjusting sender timer: -89ms 19:01:14.749 3 MEDIA-001719 adjusting sender timer: -89ms 19:01:14.749 3 MEDIA-001720 adjusting sender timer: -89ms 19:01:14.749 3 MEDIA-001719 adjusting sender timer: -89ms 19:01:14.749 3 MEDIA-001720 adjusting sender timer: -89ms 19:01:14.749 2 MEDIA-001721 created for PBXLEG-016010: audio([0.0.0.0]:60000 8000Hz ssrc=44445014) 19:01:14.749 3 MEDIA-001720 adjusting sender timer: -89ms 19:01:14.749 2 MEDIA-001721 processor started 19:01:14.749 2 MEDIA-001721 audio offer SDP set:{101=DTMF 8=PCMA/8000} <-> [GWhost]:21678:21679 {101=DTMF 8=PCMA/8000,0=PCMU/8000,101=telephone-event/8000} 19:01:14.749 3 MEDIA-001720 adjusting sender timer: -89ms 19:01:14.749 2 PBXLEG-016010 session refresh=300(active) 19:01:14.749 3 MEDIA-001720 adjusting sender timer: -89ms 19:01:14.749 2 MEDIA-001721 local answer SDP composed 19:01:14.749 4 DIALOG-001792 CALLEE(9FB79CDF-16010-4F0B520B) created 19:01:14.750 3 MEDIA-001720 adjusting sender timer: -89ms 19:01:14.750 2 MEDIA-001721 remote SDP retrieved 19:01:14.750 3 MEDIA-001720 adjusting sender timer: -89ms 19:01:14.750 2 PBXLEG-016010 SIGNAL-126490 200-INVITE response sent 19:01:14.750 5 SIGNAL-126490 FINAL posted 19:01:14.750 5 SIGNAL(2) 126490: processing FINAL 19:01:14.750 4 SIGNAL-126490 {2/3} NODE-016010 reported final(200) 19:01:14.750 3 MEDIA-001720 adjusting sender timer: -90ms 19:01:14.750 4 SIGNAL-126490 DIALOG-001792 updating on <- 200-INVITE 19:01:14.750 4 DIALOG-001792 expiration timer set to 300 sec 19:01:14.750 4 SIGNAL-126490 200-INVITE call Record-Route[0] is reverted 19:01:14.750 3 MEDIA-001720 adjusting sender timer: -90ms 19:01:14.750 4 SIGNAL-126490 collected code=200(OK) 19:01:14.750 2 DIALOG-001792 CALLEE(9FB79CDF-16010-4F0B520B) connected 19:01:14.750 4 DIALOG-001792 workarounds: BadCRYPTO <-> 19:01:14.750 3 MEDIA-001720 adjusting sender timer: -90ms 19:01:14.750 2 DIALOG-001792 removing 1 CALLEE element(s) 19:01:14.750 4 DIALOG-001792 updating callee info 19:01:14.750 3 MEDIA-001720 adjusting sender timer: -90ms 19:01:14.750 2 ACCOUNT(pbx) inp call connected. alerting=2 sec 19:01:14.750 2 PBXLEG-016010 accepting started 19:01:14.750 2 SIGNAL-126490 200-INVITE reporting 19:01:14.750 5 SIPS-101880 FINAL posted 19:01:14.750 5 SIGNAL(2) 126490: killing 19:01:14.750 4 SIGNAL-126490 dequeued 19:01:14.750 5 SIPS(3) 101880: processing FINAL 19:01:14.750 2 SIGNAL-126490 releasing 19:01:14.750 5 SIPS-101880 RRs: response=1,orig=0,nOrig=0,inserted=0 19:01:14.750 2 SIPDATA-205877 out: rsp [0.0.0.0]:5060 -> udp[GWhost]:5060 200-INVITE(1018 bytes) 19:01:14.751 5 SIPDATA-205877 out: SIP/2.0 200 OK 19:01:14.751 5 SIPDATA-205877 out: Via: SIP/2.0/UDP GWhost:5060;rport=5060;branch=z9hG4bKPjXo6wYpSGqFkOLtuFsx3FXjASKbVCoAYp 19:01:14.751 5 SIPDATA-205877 out: Record-Route: 19:01:14.751 5 SIPDATA-205877 out: Record-Route: 19:01:14.751 5 SIPDATA-205877 out: From: "2043" ;tag=g.ezdHKEb947tJnY2MBXHrzUtaPrgGaz 19:01:14.751 5 SIPDATA-205877 out: To: ;tag=9FB79CDF-16010-4F0B520B 19:01:14.751 5 SIPDATA-205877 out: Call-ID: LQhtcSgIh.Ss1O-Z4UzH.e7vQuvz2ixE 19:01:14.751 5 SIPDATA-205877 out: CSeq: 10447 INVITE 19:01:14.751 5 SIPDATA-205877 out: Contact: 19:01:14.751 5 SIPDATA-205877 out: Supported: 100rel,timer,replaces,histinfo,precondition 19:01:14.751 5 SIPDATA-205877 out: Allow: INVITE,OPTIONS,INFO,MESSAGE,PRACK,UPDATE,REFER 19:01:14.751 5 SIPDATA-205877 out: Session-Expires: 300;refresher=uas 19:01:14.751 5 SIPDATA-205877 out: User-Agent: CommuniGatePro-callLeg/6.1.15 19:01:14.751 5 SIPDATA-205877 out: Content-Type: application/sdp 19:01:14.751 5 SIPDATA-205877 out: Content-Length: 322 19:01:14.751 5 SIPDATA-205877 out: 19:01:14.751 5 SIPDATA-205877 out: v=0 19:01:14.751 5 SIPDATA-205877 out: o=CGPLeg016010 2262769664 1131384833 IN IP4 WANIP 19:01:14.751 5 SIPDATA-205877 out: s=- 19:01:14.751 5 SIPDATA-205877 out: c=IN IP4 CGPhost 19:01:14.751 5 SIPDATA-205877 out: t=0 0 19:01:14.751 5 SIPDATA-205877 out: m=audio 60000 RTP/AVP 8 0 101 19:01:14.751 5 SIPDATA-205877 out: a=rtpmap:8 PCMA/8000 19:01:14.751 5 SIPDATA-205877 out: a=rtpmap:0 PCMU/8000 19:01:14.751 5 SIPDATA-205877 out: a=rtpmap:101 telephone-event/8000 19:01:14.751 5 SIPDATA-205877 out: a=fmtp:101 0-15 19:01:14.751 5 SIPDATA-205877 out: a=sendrecv 19:01:14.751 5 SIPDATA-205877 out: a=ice-pwd:E976CEE7B5479DCD005D9F7 19:01:14.751 5 SIPDATA-205877 out: a=ice-ufrag:cgp1721+0 19:01:14.751 5 SIPDATA-205877 out: a=rtcpping:M:1721:926756558 19:01:14.751 5 SIP [0.0.0.0]:5060 -> [GWhost]:5060 out(1018): SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP GWhost:5060;rport=5060;branch=z9hG4bKPjXo 19:01:14.751 2 SIPS-101880 SIPDATA-205877 200-INVITE(final) sent [0.0.0.0]:5060 -> udp[GWhost]:5060 19:01:14.751 5 SIPS-101880 timeout set for 32s 19:01:14.751 5 SIPS(3) 101880: enqueued (32 secs) 19:01:14.752 5 SIP [0.0.0.0]:5060 <- [GWhost]:5060 inp(455): ACK sip:signode-16010-4F0B520B@CGPhost SIP/2.0\r\nVia: SIP/2.0/UDP GWhost