RTU: interlayer.log как основа глубокого анализа вызова

     В РТУ если совсем уж не понятно что и как, то можно зайти в детальную отладку

rtu1:~# grep 8612116254 /var/log/centrex/interlayer.log

21.05.2019 10:33:09.607096 0004 DBG iCall.1752662 <-- CallBegin: src "202" on 92.60.92.214:5060, dst "88612116254", local 92.60.87.6:5060, reg "", transaction Transaction(id=41261, counter=21).

21.05.2019 10:33:09.629843 0004 DBG oCall.1752663 <-- DoRegisterCall: src "4959802661", dst "88612116254", ip "213.134.200.62:5060", zone "voip", phone: , mediaGroupId: "1ab536684c8284f852dc836feef18d59"

21.05.2019 10:33:35.329080 0004 DBG iCall.1752706 <-- CallBegin: src "202" on 92.60.92.214:5060, dst "88612116254", local 92.60.87.6:5060, reg "", transaction Transaction(id=41704, counter=30).

21.05.2019 10:33:35.351799 0004 DBG oCall.1752707 <-- DoRegisterCall: src "4959802661", dst "88612116254", ip "213.134.200.62:5060", zone "voip", phone: , mediaGroupId: "b0fb49d549bc7e043859fe239bc98db1"

Цветами выделены два отдельных вызова на 1 и тот же номер, здесь нам интересны плечи(леги) вызова: у любого вызова 2 плеча
первое - это пришедший(input) вызов на гибкий коммутатор, он его отработал и направил куда надо это выходное(Output) второе плечо.
Найдя вызов мы находим и номера плеч, а дальше по ним производим выборку:

rtu1:~# egrep '(iCall.1752662|oCall.1752663)' /var/log/centrex/interlayer.log

21.05.2019 10:33:09.607060 0004 DBG iCall.1752662 Created (id = "af2011327b9a11e9bfe8e41f1369c1c8"). Total call count: 80 - Switch("Switch_1"), 56 - Node.3("signaling-1"), 80 - sipEndPoint.

21.05.2019 10:33:09.607096 0004 DBG iCall.1752662 <-- CallBegin: src "202" on 92.60.92.214:5060, dst "88612116254", local 92.60.87.6:5060, reg "", transaction Transaction(id=41261, counter=21).

21.05.2019 10:33:09.607139 0004 DBG iCall.1752662 --> OnRegisterCall

21.05.2019 10:33:09.622950 0004 DBG iCall.1752662 DoAcceptedCall mediaGroupId: "1ab536684c8284f852dc836feef18d59"

21.05.2019 10:33:09.622975 0004 DBG iCall.1752662 --> OnCapabilitiesCall

21.05.2019 10:33:09.629790 0004 DBG oCall.1752663 Created (id = "c108427c3afe04cfdde52ef404538d5b"). Total call count: 81 - Switch("Switch_1"), 57 - Node.3("signaling-1"), 81 - sipEndPoint.

21.05.2019 10:33:09.629843 0004 DBG oCall.1752663 <-- DoRegisterCall: src "4959802661", dst "88612116254", ip "213.134.200.62:5060", zone "voip", phone: , mediaGroupId: "1ab536684c8284f852dc836feef18d59"

21.05.2019 10:33:09.629890 0004 DBG oCall.1752663 --> CreateCall (link=Link(pointer=-1277647544, name='signaling-1'), protocol=SignalingLogic, type=Notification, transaction=Transaction(id=0, counter=0), cookie="Cookie("", 0)")

21.05.2019 10:33:09.630218 0004 DBG oCall.1752663 --> Setup (link=Link(pointer=-1277647544, name='signaling-1'), protocol=SignalingLogic, type=Notification, transaction=Transaction(id=0, counter=0), cookie="Cookie("", 0)")

21.05.2019 10:33:09.630281 0004 DBG oCall.1752663 --> OnRegisterCall

21.05.2019 10:33:09.646400 0004 DBG oCall.1752663 <-- SetMedia (call state = WaitForFirstSetMedia)

21.05.2019 10:33:09.646431 0004 DBG oCall.1752663 Voice1 media stream id = "af266c587b9a11e9bfe8e41f1369c1c8", on "media-3".

21.05.2019 10:33:09.646451 0004 DBG oCall.1752663 Voice2 media stream is not active.

21.05.2019 10:33:09.646468 0004 DBG oCall.1752663 Video media stream is not active.

21.05.2019 10:33:09.646486 0004 DBG oCall.1752663 Fax media stream is not active.

21.05.2019 10:33:09.646503 0004 DBG oCall.1752663 Dtmf media stream is not active.

21.05.2019 10:33:09.646605 0004 DBG oCall.1752663 --> OnMediaStartCall

21.05.2019 10:33:09.646726 0004 DBG oCall.1752663 --> SetMediaAck (link=Link(pointer=-1277647544, name='signaling-1'), protocol=SignalingLogic, type=Notification, transaction=Transaction(id=0, counter=0), cookie="Cookie("", 0)")

21.05.2019 10:33:09.684093 0004 DBG iCall.1752662 <-- DoAcceptedCapabilities

21.05.2019 10:33:09.684110 0004 DBG iCall.1752662 callAck.config.media.mediaGroupId: "1ab536684c8284f852dc836feef18d59"

21.05.2019 10:33:09.684151 0004 DBG iCall.1752662 --> CallAck (link=Link(pointer=-1277647544, name='signaling-1'), protocol=SignalingLogic, type=Response, transaction=Transaction(id=41261, counter=21), cookie="Cookie("", 0)")

21.05.2019 10:33:09.700170 0004 DBG iCall.1752662 <-- CallTerminated: code 65574 (local reason code 38: "ldcMaxCallsReached"), transaction Transaction(id=41266, counter=22).

21.05.2019 10:33:09.700190 0004 DBG iCall.1752662 time: st 05/21/2019 07:33:09, al 01/01/0001 00:00:00, cn 01/01/0001 00:00:00, dc 05/21/2019 07:33:09.

21.05.2019 10:33:09.700238 0004 DBG iCall.1752662 --> OnUnregisterCall

21.05.2019 10:33:09.700316 0004 DBG iCall.1752662 Deleted (id = "af2011327b9a11e9bfe8e41f1369c1c8"). Total call count: 80 - Switch("Switch_1"), 56 - Node.3("signaling-1"), 80 - sipEndPoint.

21.05.2019 10:33:09.711149 0004 DBG oCall.1752663 <-- DoUnregisterCall. Reason = "", code = "UnknownCause"

21.05.2019 10:33:09.711175 0004 DBG oCall.1752663 BeginCallTerminate. ResultCode="Unknown cause", code=65574, "65574 (local reason code 38: "ldcMaxCallsReached")". Call state Proxy_Ready

21.05.2019 10:33:09.711201 0004 DBG oCall.1752663 --> Terminate (link=Link(pointer=-1277647544, name='signaling-1'), protocol=SignalingLogic, type=Notification, transaction=Transaction(id=0, counter=0), cookie="Cookie("", 0)")

21.05.2019 10:33:09.718210 0004 DBG oCall.1752663 <-- CallTerminated: code 65574 (local reason code 38: "ldcMaxCallsReached"), transaction Transaction(id=41291, counter=18).

21.05.2019 10:33:09.718241 0004 DBG oCall.1752663 time: st 05/21/2019 07:33:09, al 01/01/0001 00:00:00, cn 01/01/0001 00:00:00, dc 05/21/2019 07:33:09.

21.05.2019 10:33:09.718282 0004 DBG oCall.1752663 --> OnUnregisterCall

21.05.2019 10:33:09.718359 0004 DBG oCall.1752663 Deleted (id = "c108427c3afe04cfdde52ef404538d5b"). Total call count: 79 - Switch("Switch_1"), 55 - Node.3("signaling-1"), 79 - sipEndPoint.

rtu1:~# egrep '(iCall.1752706|oCall.1752707)' /var/log/centrex/interlayer.log
21.05.2019 10:33:35.329058 0004 DBG iCall.1752706 Created (id = "be756cd67b9a11e9bfe8e41f1369c1c8"). Total call count: 80 - Switch("Switch_1"), 58 - Node.3("signaling-1"), 80 - sipEndPoint.
21.05.2019 10:33:35.329080 0004 DBG iCall.1752706 <-- CallBegin: src "202" on 92.60.92.214:5060, dst "88612116254", local 92.60.87.6:5060, reg "", transaction Transaction(id=41704, counter=30).
21.05.2019 10:33:35.329109 0004 DBG iCall.1752706 --> OnRegisterCall
21.05.2019 10:33:35.335750 0004 DBG iCall.1752706 DoAcceptedCall mediaGroupId: "b0fb49d549bc7e043859fe239bc98db1"
21.05.2019 10:33:35.335771 0004 DBG iCall.1752706 --> OnCapabilitiesCall
21.05.2019 10:33:35.351748 0004 DBG oCall.1752707 Created (id = "574e55e93837fddbc362a9a7b12b8db3"). Total call count: 81 - Switch("Switch_1"), 59 - Node.3("signaling-1"), 81 - sipEndPoint.
21.05.2019 10:33:35.351799 0004 DBG oCall.1752707 <-- DoRegisterCall: src "4959802661", dst "88612116254", ip "213.134.200.62:5060", zone "voip", phone: , mediaGroupId: "b0fb49d549bc7e043859fe239bc98db1"
21.05.2019 10:33:35.351841 0004 DBG oCall.1752707 --> CreateCall (link=Link(pointer=-1277647544, name='signaling-1'), protocol=SignalingLogic, type=Notification, transaction=Transaction(id=0, counter=0), cookie="Cookie("", 0)")
21.05.2019 10:33:35.352108 0004 DBG oCall.1752707 --> Setup (link=Link(pointer=-1277647544, name='signaling-1'), protocol=SignalingLogic, type=Notification, transaction=Transaction(id=0, counter=0), cookie="Cookie("", 0)")
21.05.2019 10:33:35.352173 0004 DBG oCall.1752707 --> OnRegisterCall
21.05.2019 10:33:35.397983 0004 DBG oCall.1752707 <-- SetMedia (call state = WaitForFirstSetMedia)
21.05.2019 10:33:35.398009 0004 DBG oCall.1752707 Voice1 media stream id = "be7fa7507b9a11e9bfe8e41f1369c1c8", on "media-2".
21.05.2019 10:33:35.398030 0004 DBG oCall.1752707 Voice2 media stream is not active.
21.05.2019 10:33:35.398045 0004 DBG oCall.1752707 Video media stream is not active.
21.05.2019 10:33:35.398061 0004 DBG oCall.1752707 Fax media stream is not active.
21.05.2019 10:33:35.398076 0004 DBG oCall.1752707 Dtmf media stream is not active.
21.05.2019 10:33:35.398146 0004 DBG oCall.1752707 --> OnMediaStartCall
21.05.2019 10:33:35.398253 0004 DBG oCall.1752707 --> SetMediaAck (link=Link(pointer=-1277647544, name='signaling-1'), protocol=SignalingLogic, type=Notification, transaction=Transaction(id=0, counter=0), cookie="Cookie("", 0)")
21.05.2019 10:33:35.409114 0004 DBG iCall.1752706 <-- DoAcceptedCapabilities
21.05.2019 10:33:35.409129 0004 DBG iCall.1752706 callAck.config.media.mediaGroupId: "b0fb49d549bc7e043859fe239bc98db1"
21.05.2019 10:33:35.409169 0004 DBG iCall.1752706 --> CallAck (link=Link(pointer=-1277647544, name='signaling-1'), protocol=SignalingLogic, type=Response, transaction=Transaction(id=41704, counter=30), cookie="Cookie("", 0)")
21.05.2019 10:33:35.446999 0004 DBG iCall.1752706 <-- CallTerminated: code 65574 (local reason code 38: "ldcMaxCallsReached"), transaction Transaction(id=41682, counter=32).
21.05.2019 10:33:35.447018 0004 DBG iCall.1752706 time: st 05/21/2019 07:33:35, al 01/01/0001 00:00:00, cn 01/01/0001 00:00:00, dc 05/21/2019 07:33:35.
21.05.2019 10:33:35.447058 0004 DBG iCall.1752706 --> OnUnregisterCall
21.05.2019 10:33:35.447131 0004 DBG iCall.1752706 Deleted (id = "be756cd67b9a11e9bfe8e41f1369c1c8"). Total call count: 80 - Switch("Switch_1"), 58 - Node.3("signaling-1"), 80 - sipEndPoint.
21.05.2019 10:33:35.453738 0004 DBG oCall.1752707 <-- DoUnregisterCall. Reason = "", code = "UnknownCause"
21.05.2019 10:33:35.453766 0004 DBG oCall.1752707 BeginCallTerminate. ResultCode="Unknown cause", code=65574, "65574 (local reason code 38: "ldcMaxCallsReached")". Call state Proxy_Ready
21.05.2019 10:33:35.453855 0004 DBG oCall.1752707 --> Terminate (link=Link(pointer=-1277647544, name='signaling-1'), protocol=SignalingLogic, type=Notification, transaction=Transaction(id=0, counter=0), cookie="Cookie("", 0)")
21.05.2019 10:33:35.460862 0004 DBG oCall.1752707 <-- CallTerminated: code 65574 (local reason code 38: "ldcMaxCallsReached"), transaction Transaction(id=41695, counter=19).
21.05.2019 10:33:35.460888 0004 DBG oCall.1752707 time: st 05/21/2019 07:33:35, al 01/01/0001 00:00:00, cn 01/01/0001 00:00:00, dc 05/21/2019 07:33:35.
21.05.2019 10:33:35.460945 0004 DBG oCall.1752707 --> OnUnregisterCall
21.05.2019 10:33:35.461060 0004 DBG oCall.1752707 Deleted (id = "574e55e93837fddbc362a9a7b12b8db3"). Total call count: 79 - Switch("Switch_1"), 57 - Node.3("signaling-1"), 79 - sipEndPoint.
rtu1:~#

В обоих вызовах мы видим ошибку, в это время со шлюзов идет такое сообщение:

319     <Call   4482>   : ******  Call Created status(InitiatedByFXS) ver(8.28:2006-02-06-00-00) time(1558456849) ****
320     <CEP    010100> : Calling number(101)
321     <CEP    010100> : Call id(112ae45c-1e6e-6caa-9d20-0002a408f2f0) callNum(4482)
322     <Call   4480>   : Digit(2) at CalleeDeterminedWaitDigit
323     <Call   4480>   : MatchedAll
324     <Call   4482>   : Digit(8) at InitiatedByFXS
325     <Call   4482>   : MatchedAll
326     <Call   4482>   : Digit(9) at CalleeDeterminedWaitDigit
327     <Call   4482>   : MatchedAll
328     <Call   4482>   : Digit(9) at CalleeDeterminedWaitDigit
329     <Call   4482>   : MatchedAll
330     <Call   4480>   : Digit(9) at CalleeDeterminedWaitDigit
331     <Call   4480>   : MatchedAll
332     <Call   4482>   : Digit(1) at CalleeDeterminedWaitDigit
333     <Call   4482>   : MatchedAll
334     <Call   4482>   : Digit(2) at CalleeDeterminedWaitDigit
335     <Call   4482>   : MatchedAll
336     <Call   4482>   : Digit(3) at CalleeDeterminedWaitDigit
337     <Call   4482>   : MatchedAll
338     <Call   4482>   : Digit(4) at CalleeDeterminedWaitDigit
339     <Call   4482>   : MatchedAll
340     <Call   4482>   : Digit(5) at CalleeDeterminedWaitDigit
341     <Call   4482>   : MatchedAll
342     <Call   4480>   : Digit(6) at CalleeDeterminedWaitDigit
343     <Call   4480>   : MatchedAll
344     <Call   4482>   : Digit(7) at CalleeDeterminedWaitDigit
345     <Call   4482>   : MatchedAll
346     <Call   4482>   : Digit(8) at CalleeDeterminedWaitDigit
347     <Call   4482>   : MatchedAll
348     <Call   4482>   : Digit(8) at CalleeDeterminedWaitDigit
349     <Call   4482>   : MatchedAll
350     <Time   4480>   : Inter digit timer timeout.
351     <Call   4480>   : Digit(#) at CalleeDeterminedWaitDigit
352     <Call   4480>   : MatchAllProcess After Sorted
                          <0>  id(100) dest(000T) prefer(0) selected(2510)
353     <Call   4480>   : Initiate callee with dial-peer(000T) status(CalleeDeterminedAll) id(032ae45c-686e-d682-9d1b-0002a408f2f0)
354     <NetEP  4480>   : InitiateOutCall: calledNum(00089991234567) callingNum(4995190352) target(1.12.123.38)
355     <NetEP  4480>   : DoCall: calledAddr(89057606206@213.134.195.38) callingAddr(260506#74995190352)
356     <H323   4480>   : local capabilities.
                          number of capabilities = 5
                                  1 : g711alaw-64k
                                  2 : g729-8k
                                  3 : T.38
                                  4 : UserInput/basicString
                                  5 : UserInput/hookflash
357     <H225   4480>   : Try signalling TCP connect (1.12.123.38:1720)
358     <H225   4480>   : Signalling TCP connect success (4480)
359     <Q931   4480>   : Send SETUP
360     <Time   4482>   : Inter digit timer timeout.
361     <Call   4482>   : Digit(#) at CalleeDeterminedWaitDigit
362     <Call   4482>   : MatchAllProcess After Sorted
                          <0>  id(200) dest(001T) prefer(0) selected(319)
363     <Call   4482>   : Initiate callee with dial-peer(001T) status(CalleeDeterminedAll) id(112ae45c-1e6e-6caa-9d20-0002a408f2f0)
364     <NetEP  4482>   : InitiateOutCall: calledNum(00189263727041) callingNum(101) target(92.60.87.6)
365     <NetEP  4482>   : DoCall: calledAddr(sip:89263727041@92.60.87.6) callingAddr(101)
366     <SIP    0>      : No authentication information available
367     <SIP    4482>   : Send INVITE Request
368     <SIP    4482>   : Receive 100 Trying
369     <SIP    4482>   : Transaction (735 INVITE) proceeding
370     <SIP    4482>   : Receive 503 Maximum calls number has been reached
371     <SIP    4482>   : Transaction (735 INVITE) completed
372     <SIP    4482>   : Send ACK Request

Ошибка со стороны сервиса т.к. 5ХХ
По сути мы получили:  
Service Unavailable – сервер в настоящее время не в состоянии обработать запрос из-за временной  перегрузки или технического 
                                     обслуживания сервера.

На этом все!