Toggle sidebar Toggle sidebar

Diagnosing VOIP Dropouts

Status
Not open for further replies.

Whizz IT

Forum User
Joined
Aug 20, 2020
Messages
8
Reaction score
0
Hi All,

I'm trying to diagnose VOIP drop outs for a client, however I'm not too familiar with the log files and data within them.
I'm currently looking at this snippet from the 3CXMediaServer log file-

Code: 
09:12:30.388|7fdfbd7ad700|Trace|MSEndPoint.cpp(3347): 9:Receiver RoundTripTime=20.499603(current=3806874750.388071)
09:12:30.388|7fdfbd7ad700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=80:
V=2
P=0
DWORDS=12
BYTES=52
type=SR
RC=1
  SSRC  =2625771101
SR:
  NTP   =1722392.480004(18456.480469)
  RTPTS =3717241003
  pcount=5356
  ocount=856960
    RR[0]:
      SSRC  =1909372395
      FLOST =  0.00%
      CLOST =0
      ESN   =55346
      JITT  =43
      LSR   =19555.54
      DLSR  =6.35
09:12:30.389|7fdfbd7ad700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=40:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =2625771101
SR:
  NTP   =1722397.480004(18461.480469)
  RTPTS =3717281003
  pcount=5606
  ocount=896960
09:12:30.389|7fdfbd7ad700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=40:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =2625771101
SR:
  NTP   =1722402.480004(18466.480469)
  RTPTS =3717321003
  pcount=5856
  ocount=936960
09:12:30.389|7fdfbd7ad700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=52:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =313559774
SR:
  NTP   =3806867530.109619(12362.109375)
  RTPTS =2592832285
  pcount=44072
  ocount=6522656
09:12:30.389|7fdfbd7ad700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=52:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =313559774
SR:
  NTP   =3806867535.128418(12367.128906)
  RTPTS =2592872445
  pcount=44323
  ocount=6559804
09:12:30.389|7fdfbd7ad700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=52:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =313559774
SR:
  NTP   =3806867540.129639(12372.129883)
  RTPTS =2592912445
  pcount=44573
  ocount=6596804
09:12:30.389|7fdfbd7ad700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=52:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =313559774
SR:
  NTP   =3806867545.148438(12377.148438)
  RTPTS =2592952605
  pcount=44824
  ocount=6633952
09:12:30.788|7fdfbdfae700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=52:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =48814597
SR:
  NTP   =3806867529.726318(12361.726562)
  RTPTS =1889487423
  pcount=5761
  ocount=852628
09:12:30.788|7fdfbdfae700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=52:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =48814597
SR:
  NTP   =3806867534.727051(12366.726562)
  RTPTS =1889527423
  pcount=6011
  ocount=889628
09:12:30.789|7fdfbdfae700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=52:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =48814597
SR:
  NTP   =3806867539.728760(12371.728516)
  RTPTS =1889567423
  pcount=6261
  ocount=926628
09:12:30.789|7fdfbdfae700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=52:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =48814597
SR:
  NTP   =3806867544.747070(12376.747070)
  RTPTS =1889607583
  pcount=6512
  ocount=963776
09:12:30.789|7fdfbdfae700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=52:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =48814597
SR:
  NTP   =3806867549.748047(12381.748047)
  RTPTS =1889647583
  pcount=6762
  ocount=1000776
09:12:30.793|7fdfbe7af700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=40:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =2816200240
SR:
  NTP   =6110615.950007(15767.950195)
  RTPTS =1327738899
  pcount=44124
  ocount=7059840
09:12:30.793|7fdfbe7af700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=56:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =2816200240
SR:
  NTP   =6110620.950007(15772.950195)
  RTPTS =1327778899
  pcount=44374
  ocount=7099840
09:12:31.261|7fdfbefb0700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=48:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =122037084
SR:
  NTP   =3806867528.273438(12360.273438)
  RTPTS =1890916127
  pcount=5259
  ocount=778332
09:12:31.461|7fdfbefb0700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=48:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =122037084
SR:
  NTP   =3806867533.292236(12365.291992)
  RTPTS =1890956287
  pcount=5510
  ocount=815480
09:12:31.461|7fdfbefb0700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=28:
V=2
P=0
DWORDS=1
BYTES=8
type=RR
RC=0
  SSRC  =122037084
09:12:31.462|7fdfbefb0700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=28:
V=2
P=0
DWORDS=1
BYTES=8
type=RR
RC=0
  SSRC  =122037084
09:12:31.462|7fdfbefb0700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=40:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =3373090960
SR:
  NTP   =3539360.470004(416.470001)
  RTPTS =3211349806
  pcount=5822
  ocount=931520
09:12:31.462|7fdfbefb0700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=60:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =3373090960
SR:
  NTP   =3539365.470004(421.470001)
  RTPTS =3211389806
  pcount=6072
  ocount=971520
09:12:31.462|7fdfbefb0700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=40:
V=2
P=0
DWORDS=6
BYTES=28
type=SR
RC=0
  SSRC  =3373090960
SR:
  NTP   =3539370.470004(426.470001)
  RTPTS =3211429806
  pcount=6322
  ocount=1011520
09:12:31.462|7fdfbefb0700|Debug|MSEndPoint.cpp(1243): 4:[email protected]:5482 received SR_RR report:
RTCP total len=28:
V=2
P=0
DWORDS=1
BYTES=8
type=RR
RC=0
  SSRC  =122037084
09:12:31.305|7fdfc07b3700|Debug|MSEndPoint.cpp(3038): 4:[email protected]:5482 SR_RR sent:

RTCP total len=100:
V=2
P=0
DWORDS=12
BYTES=52
type=SR
RC=1
  SSRC  =734709273
SR:
  NTP   =3806874751.305592(19583.304688)
  RTPTS =2083796710
  pcount=5547
  ocount=887520
    RR[0]:
      SSRC  =3373090960
      FLOST = 78.91%
      CLOST =47
      ESN   =5595
      JITT  =8900
      LSR   =406.47
      DLSR  =29.32
09:12:31.527|7fdfc07b3700|Debug|MSEndPoint.cpp(3038): 4:[email protected]:5482 SR_RR sent:

To me it seems like something drops and then is reconnected, hence the high percentage of "FLOST" (Frames Lost?)
I'm assume this is around the point where the VOIP drops, are there any other log files I should be looking at to diagnose whether the drop is at the 3CX end, or the trunk end?
 
If this is call dropouts you are talking about best to use Wireshark. If I experience such issue I will normally run dumpcap over the period of a day for the client an have them report any drop out occurrences. Something like:

cd /usr/bin
dumpcap -i 1 -w /tmp/trace.pcapng

Whilst doing this I will often setup something like a STUN phone from my location here to the customer system and make a call and keep it running for a long period to show no call drops.

As in most cases it is normally a network/firewall issue (unless they are hitting their maximum time limit set by the sytem).
 
eddv123 said:
If this is call dropouts you are talking about best to use Wireshark. If I experience such issue I will normally run dumpcap over the period of a day for the client an have them report any drop out occurrences. Something like:

cd /usr/bin
dumpcap -i 1 -w /tmp/trace.pcapng

Whilst doing this I will often setup something like a STUN phone from my location here to the customer system and make a call and keep it running for a long period to show no call drops.

As in most cases it is normally a network/firewall issue (unless they are hitting their maximum time limit set by the sytem).
Click to expand...

Indeed this is call dropouts that I am looking into.
I will try and run a dumpcap over a day and see what's going on there too.
Is there anything I need to be on the look out for in the dump?
 
Well get accurate information of the calling parties and time of call. Locate in Wireshark under:
Telephony >> VoIP calls

And use the Flow sequence tab of the call, you should see a reason for the call termination and most importantly who it was sent by.
 
eddv123 said:
Well get accurate information of the calling parties and time of call. Locate in Wireshark under:
Telephony >> VoIP calls

And use the Flow sequence tab of the call, you should see a reason for the call termination and most importantly who it was sent by.
Click to expand...

Ok sounds good. I will do this as soon as I can and report back with results when they let me know about the next call that drops out.
 
Ok, So I've got a report of a call drop out, but I'm not sure what I'm looking for inside the wireshark dump.
 
As mentioned about go to Telephony >> VoIP Calls and either filter the call so you can see just those packets only, or look at the call flow tab.

The call flow gives the requests and responses (see attached for example) you can clearly see (although I have changed the IP addresses to represent PBX and Provider) a 486 BUSY message coming back from the provider (see the arrows) this is the sorts of things you need to identify.

My example is an issue during call setup where yours should be occurring mid-call (which means RTP packets maybe present).
 

Attachments

  • 486.jpg
    486.jpg
    31.3 KB · Views: 21
So I had a further chat with the client, and they have advised that the call actually drops out mid call, but doesn't totally disconnect. Just the voice drops out. If they wait long enough, then the voice comes back and the call continues.

I'm not too familiar with SIP technology, what could be possible causes of this issue?
 
Whizz IT said:
So I had a further chat with the client, and they have advised that the call actually drops out mid call, but doesn't totally disconnect. Just the voice drops out. If they wait long enough, then the voice comes back and the call continues.

I'm not too familiar with SIP technology, what could be possible causes of this issue?
Click to expand...
Every call? Some calls? Same time during the call (i.e. at 32 seconds in)? Are they using a mobile device? (or webclient or desktop app or something else?) Does that device have wired or wireless or cellular? 3CX local or in cloud?

There is a lot of variable in play here and without either the capture or more information we can only guess. I'm going to guess call reconnection is in place here, so mobile device roaming between wifi/cellular
 
Whizz IT said:
Just the voice drops
Click to expand...

Im still going to go with firewall and since RTP (voice/audio) uses UDP for traffic I think it is very possible somewhere that a firewall is closing the pin hole used for the audio. This guide on UDP timeout should give you a pretty good outline: https://docs.skyswitch.com/en/articles/579-what-does-udp-timeout-mean

I had a similar issue with 3CX-SBC tunnel port (which uses port 5090) dropping its tunnel due to a firewall closing its pin-hole. It finally emerged that they had added another firewall/router/gateway in the path between SBC and network edge without consulting with us first.
 
SweetAction said:
Every call? Some calls? Same time during the call (i.e. at 32 seconds in)? Are they using a mobile device? (or webclient or desktop app or something else?) Does that device have wired or wireless or cellular? 3CX local or in cloud?

There is a lot of variable in play here and without either the capture or more information we can only guess. I'm going to guess call reconnection is in place here, so mobile device roaming between wifi/cellular
Click to expand...

Only happens on some calls, they're not sure at what time but "fairly quickly". Using Yealink T46S phones, 3CX hosted locally.

I'm aware I'm not making it very easy to troubleshoot, and my apologies for that. Trying to get the right information from the client is difficult at best because I'm not always on site.

eddv123 said:
Im still going to go with firewall and since RTP (voice/audio) uses UDP for traffic I think it is very possible somewhere that a firewall is closing the pin hole used for the audio. This guide on UDP timeout should give you a pretty good outline: https://docs.skyswitch.com/en/articles/579-what-does-udp-timeout-mean

I had a similar issue with 3CX-SBC tunnel port (which uses port 5090) dropping its tunnel due to a firewall closing its pin-hole. It finally emerged that they had added another firewall/router/gateway in the path between SBC and network edge without consulting with us first.
Click to expand...

Thanks for this, I will follow this up and see how I go.
 
Whizz IT said:
Only happens on some calls, they're not sure at what time but "fairly quickly". Using Yealink T46S phones, 3CX hosted locally.

I'm aware I'm not making it very easy to troubleshoot, and my apologies for that. Trying to get the right information from the client is difficult at best because I'm not always on site.



Thanks for this, I will follow this up and see how I go.
Click to expand...

This does narrow it quite a bit. It's unlikely to be endpoint related and either trunk or sip server (3CX). It does need the capture and like stated above, first step is to see if the RTP packets stop.

Does the firewall checker pass? What make/model of firewall?
 
SweetAction said:
This does narrow it quite a bit. It's unlikely to be endpoint related and either trunk or sip server (3CX). It does need the capture and like stated above, first step is to see if the RTP packets stop.

Does the firewall checker pass? What make/model of firewall?
Click to expand...

It's a Mikrotik router, just using the built in firewall. However I just realised I've left out probably a very important piece of information.

The VOIP service is a Telstra (Aussie Telecoms company) Business VOIP Service, they have their own VOIP endpoint which 3CX is talking to, there is a direct connection between 3CX and the VOIP endpoint.

The VOIP endpoint is a OneAcess One425, which communicates back to Telstra. So any packet captures I do will likely only pinpoint any issues between 3CX and the One425. However as long as I can prove that there is no drop outs between 3CX and the One425 then I can safely say that the issue is not with the 3CX setup.

I will attempt to do a capture again and try and get some data for us to work with.

Thanks for your assistance!
 
Ok, so I got a dump of the conversation that had a drop out, I've attached the Call Flow of the conversation. Is that what we need to help us diagnose the issue?
 

Attachments

Status
Not open for further replies.

Latest Posts

Forum statistics

Threads
111,962
Messages
589,995
Members
164,867
Latest member
swegner
3CX Logo Footer Copyright © Sitemap Privacy
Top Bottom