4-5 second audio drop out intermittently

FreePBX Installation / Upgrade
1

I’d like to ask for some help in troubleshooting a FreePBX 14 system that experiences 4-5 seconds of dropped audio during calls several times per week. I did a new installation of FreePBX 14 because I was experiencing a similar problem on FreePBX 13 with similar hardware. I replaced all the hardware (except one network card) and did a fresh installation of FreePBX 14 Distro.

I’m currently running a VM with 1 socket, 4 virtual CPUs and 2.7GB of memory and about 40 extensions. I suspect the system is lagging at times which is causing the dropouts. What I want is a methodology to prove that. HTOP shows minimal CPU load during normal operation, but I don’t have a way of knowing if it is intermittently spiking.

2

Can you post a call trace? https://wiki.freepbx.org/display/SUP/Providing+Great+Debug#ProvidingGreatDebug-AsteriskLogs-PartII

3

It’s very difficult to post a call trace because the problem only happens a few times a week and it’s to random extensions. I have however had Spectrum (the SIP trunk provider) monitoring the call traffic and they have said there is some packet loss on the the trunk network interface. However the PBX network interface shows zero dropped packets (by doing ifconfig). The network card is connected directly to the Spectrum trunk ESBC (gateway). I’ve also use mtr and found no packet loss between the PBX and the gateway.

The customer has indicated that the audio dropout is always 4-5 seconds. That’s another thing that leads me to believe it is a performance lag rather than a network issue, which I’m speculate would be less consistent.

When I look at the stats in FreePBX I don’t see any meaningful spikes and I also don’t see any meaningful spikes in the (XCP-NG) VM Host performance graphs. I think I may need more memory, but the CPU utilization is pretty low as seen in HTOP.

I’m hoping for a way to log performance spikes and cross reference those with reported instances of audio dropouts.

Thank you,
Russ

4

I should have read your link before my reply. I was able to use the process that you linked to do the call trace.
Russ

5

[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:1] Macro(“PJSIP/305-0000094f”, “user-callerid,LIMIT,EXTERNAL,”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:1] Set(“PJSIP/305-0000094f”, “TOUCH_MONITOR=1556380876.2556”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:2] Set(“PJSIP/305-0000094f”, “AMPUSER=305”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:3] GotoIf(“PJSIP/305-0000094f”, “0?report”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:4] ExecIf(“PJSIP/305-0000094f”, “1?Set(REALCALLERIDNUM=305)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:5] Set(“PJSIP/305-0000094f”, “AMPUSER=305”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:6] GotoIf(“PJSIP/305-0000094f”, “0?limit”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:7] Set(“PJSIP/305-0000094f”, “AMPUSERCIDNAME=Hidden”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:8] ExecIf(“PJSIP/305-0000094f”, “0?Set(__CIDMASQUERADING=TRUE)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:9] GotoIf(“PJSIP/305-0000094f”, “0?report”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:10] Set(“PJSIP/305-0000094f”, “AMPUSERCID=305”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:11] Set(“PJSIP/305-0000094f”, “__DIAL_OPTIONS=HhTtr”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:12] Set(“PJSIP/305-0000094f”, “CALLERID(all)=“Hidden” <305>”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:13] GotoIf(“PJSIP/305-0000094f”, “0?limit”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:14] ExecIf(“PJSIP/305-0000094f”, “1?Set(GROUP(concurrency_limit)=305)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:15] ExecIf(“PJSIP/305-0000094f”, “0?Set(CHANNEL(language)=)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:16] NoOp(“PJSIP/305-0000094f”, “Macro Depth is 1”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:17] GotoIf(“PJSIP/305-0000094f”, “1?report2:macroerror”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:18] GotoIf(“PJSIP/305-0000094f”, “1?continue”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:37] Set(“PJSIP/305-0000094f”, “CALLERID(number)=305”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:38] Set(“PJSIP/305-0000094f”, “CALLERID(name)=Hidden”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:39] GotoIf(“PJSIP/305-0000094f”, “0?cnum”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:40] Set(“PJSIP/305-0000094f”, “CDR(cnam)=XXXXX”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:41] Set(“PJSIP/305-0000094f”, “CDR(cnum)=305”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:42] Set(“PJSIP/305-0000094f”, “CHANNEL(language)=en”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:2] Gosub(“PJSIP/305-0000094f”, “sub-record-check,s,1(out,5551212,dontcare)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:1] GotoIf(“PJSIP/305-0000094f”, “0?initialized”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:2] Set(“PJSIP/305-0000094f”, “__REC_STATUS=INITIALIZED”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:3] Set(“PJSIP/305-0000094f”, “NOW=1556380876”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:4] Set(“PJSIP/305-0000094f”, “__DAY=27”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:5] Set(“PJSIP/305-0000094f”, “__MONTH=04”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:6] Set(“PJSIP/305-0000094f”, “__YEAR=2019”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:7] Set(“PJSIP/305-0000094f”, “__TIMESTR=20190427-120116”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:8] Set(“PJSIP/305-0000094f”, “__FROMEXTEN=305”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:9] Set(“PJSIP/305-0000094f”, “__MON_FMT=wav”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:10] NoOp(“PJSIP/305-0000094f”, “Recordings initialized”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:11] ExecIf(“PJSIP/305-0000094f”, “0?Set(ARG3=dontcare)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:12] Set(“PJSIP/305-0000094f”, “REC_POLICY_MODE_SAVE=”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:13] ExecIf(“PJSIP/305-0000094f”, “0?Set(REC_STATUS=NO)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:14] GotoIf(“PJSIP/305-0000094f”, “3?checkaction”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:17] GotoIf(“PJSIP/305-0000094f”, “1?sub-record-check,out,1”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx_builtins.c: Goto (sub-record-check,out,1)
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:1] NoOp(“PJSIP/305-0000094f”, “Outbound Recording Check from 305 to 5551212”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:2] Set(“PJSIP/305-0000094f”, “RECMODE=dontcare”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:3] ExecIf(“PJSIP/305-0000094f”, “1?Goto(routewins)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx_builtins.c: Goto (sub-record-check,out,7)
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:7] Gosub(“PJSIP/305-0000094f”, “recordcheck,1(dontcare,out,5551212)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:1] NoOp(“PJSIP/305-0000094f”, “Starting recording check against dontcare”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:2] Goto(“PJSIP/305-0000094f”, “dontcare”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:3] Return(“PJSIP/305-0000094f”, “”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:8] Return(“PJSIP/305-0000094f”, “”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:3] ExecIf(“PJSIP/305-0000094f”, “0 ?Set(CDR(accountcode)=)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:4] Set(“PJSIP/305-0000094f”, “MOHCLASS=default”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:5] ExecIf(“PJSIP/305-0000094f”, "0?Set(TRUNKCIDOVERRIDE=“Hidden>)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:6] Set(“PJSIP/305-0000094f”, “_NODEST=”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:7] Macro(“PJSIP/305-0000094f”, “dialout-trunk,3,5551212,off”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:1] Set(“PJSIP/305-0000094f”, “DIAL_TRUNK=3”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:2] ExecIf(“PJSIP/305-0000094f”, “0?Set(DIAL_OPTIONS=Hhtr)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:3] GosubIf(“PJSIP/305-0000094f”, “0?sub-pincheck,s,1()”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:4] ExecIf(“PJSIP/305-0000094f”, “0?Set(CALLERID(num)=114)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:5] GotoIf(“PJSIP/305-0000094f”, “0?disabletrunk,1”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:6] Set(“PJSIP/305-0000094f”, “DIAL_NUMBER=5551212”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:7] Set(“PJSIP/305-0000094f”, “DIAL_TRUNK_OPTIONS=HhTtr”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:8] Set(“PJSIP/305-0000094f”, “OUTBOUND_GROUP=OUT_3”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:9] Set(“PJSIP/305-0000094f”, “DIAL_TRUNK_OPTIONS=T”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:10] GotoIf(“PJSIP/305-0000094f”, “0?nomax”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:11] GotoIf(“PJSIP/305-0000094f”, “0?chanfull”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:12] GotoIf(“PJSIP/305-0000094f”, “0?skipoutcid”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:13] Macro(“PJSIP/305-0000094f”, “outbound-callerid,3”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:1] NoOp(“PJSIP/305-0000094f”, “305”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:2] NoOp(“PJSIP/305-0000094f”, “”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:3] NoOp(“PJSIP/305-0000094f”, “off”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:4] ExecIf(“PJSIP/305-0000094f”, “0?Set(CALLERPRES(name-pres)=)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:5] ExecIf(“PJSIP/305-0000094f”, “0?Set(CALLERPRES(num-pres)=)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:6] ExecIf(“PJSIP/305-0000094f”, “0?Set(REALCALLERIDNUM=305)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:7] ExecIf(“PJSIP/305-0000094f”, “0?Set(AMPUSER=305)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:8] GotoIf(“PJSIP/305-0000094f”, “1?normcid”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx_builtins.c: Goto (macro-outbound-callerid,s,12)
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:12] Set(“PJSIP/305-0000094f”, “USEROUTCID=Hidden”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:13] Set(“PJSIP/305-0000094f”, “EMERGENCYCID=Hidden”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:14] Set(“PJSIP/305-0000094f”, “TRUNKOUTCID=”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]d-callerid:15] GotoIf(“PJSIP/305-0000094f”, “1?trunkcid”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx_builtins.c: Goto (macro-outbound-callerid,s,21)
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:21] ExecIf(“PJSIP/305-0000094f”, “1?Set(CALLERID(all)=)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:22] ExecIf(“PJSIP/305-0000094f”, “1?Set(CALLERID(all)=Hidden)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:23] ExecIf(“PJSIP/305-0000094f”, “0?Set(CALLERID(all)=)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:24] ExecIf(“PJSIP/305-0000094f”, “0?Set(CALLERPRES(name-pres)=prohib_passed_screen)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:25] ExecIf(“PJSIP/305-0000094f”, “0?Set(CALLERPRES(num-pres)=prohib_passed_screen)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:26] Set(“PJSIP/305-0000094f”, “CDR(outbound_cnum)=Hidden”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:27] Set(“PJSIP/305-0000094f”, “CDR(outbound_cnam)=”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:14] GosubIf(“PJSIP/305-0000094f”, “0?sub-flp-3,s,1()”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:15] Set(“PJSIP/305-0000094f”, “OUTNUM=5551212”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:16] Set(“PJSIP/305-0000094f”, “custom=PJSIP”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:17] ExecIf(“PJSIP/305-0000094f”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:18] ExecIf(“PJSIP/305-0000094f”, “0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:19] Macro(“PJSIP/305-0000094f”, “dialout-trunk-predial-hook,”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:1] MacroExit(“PJSIP/305-0000094f”, “”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:20] GotoIf(“PJSIP/305-0000094f”, “0?bypass,1”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:21] ExecIf(“PJSIP/305-0000094f”, “1?Set(CONNECTEDLINE(num,i)=5551212)”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:22] GotoIf(“PJSIP/305-0000094f”, “0?customtrunk”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:23] Dial(“PJSIP/305-0000094f”, “PJSIP/[email protected],300,Tb(func-apply-sipheaders^s^1,(3))”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] app_stack.c: PJSIP/TW-00000950 Internal Gosub(func-apply-sipheaders,s,1(3)) start
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:1] NoOp(“PJSIP/TW-00000950”, “Applying SIP Headers to channel PJSIP/TW-00000950”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:2] Set(“PJSIP/TW-00000950”, “TECH=PJSIP”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:3] Set(“PJSIP/TW-00000950”, “SIPHEADERKEYS=”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:4] While(“PJSIP/TW-00000950”, “0”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] app_while.c: Jumping to priority 11
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:12] Return(“PJSIP/TW-00000950”, “”) in new stack
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] app_stack.c: Spawn extension (from-pstn, 5551212, 1) exited non-zero on ‘PJSIP/TW-00000950’
[2019-04-27 12:01:16] VERBOSE[68565][C-000004d9] app_stack.c: PJSIP/TW-00000950 Internal Gosub(func-apply-sipheaders,s,1(3)) complete GOSUB_RETVAL=
[2019-04-27 12:01:17] VERBOSE[68565][C-000004d9] app_dial.c: Called PJSIP/[email protected]
[2019-04-27 12:01:19] VERBOSE[68565][C-000004d9] app_dial.c: PJSIP/TW-00000950 is making progress passing it to PJSIP/305-0000094f
[2019-04-27 12:01:19] VERBOSE[68565][C-000004d9] app_dial.c: PJSIP/TW-00000950 is making progress passing it to PJSIP/305-0000094f
[2019-04-27 12:01:19] DEBUG[68565][C-000004d9] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address 192.168.3.1:11826
[2019-04-27 12:01:24] VERBOSE[68565][C-000004d9] app_dial.c: PJSIP/TW-00000950 answered PJSIP/305-0000094f
[2019-04-27 12:01:24] VERBOSE[68567][C-000004d9] bridge_channel.c: Channel PJSIP/TW-00000950 joined ‘simple_bridge’ basic-bridge <40f66681-d18c-45f5-aa37-bcba22eb88de>
[2019-04-27 12:01:24] VERBOSE[68565][C-000004d9] bridge_channel.c: Channel PJSIP/305-0000094f joined ‘simple_bridge’ basic-bridge <40f66681-d18c-45f5-aa37-bcba22eb88de>
[2019-04-27 12:29:24] DEBUG[68565][C-000004d9] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address 192.168.3.1:11826
[2019-04-27 12:29:24] VERBOSE[68567][C-000004d9] res_musiconhold.c: Started music on hold, class ‘default’, on channel ‘PJSIP/TW-00000950’
[2019-04-27 12:30:18] VERBOSE[68567][C-000004d9] res_musiconhold.c: Stopped music on hold on PJSIP/TW-00000950
[2019-04-27 12:30:18] DEBUG[68565][C-000004d9] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address 192.168.3.1:11826
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] bridge_channel.c: Channel PJSIP/305-0000094f left ‘simple_bridge’ basic-bridge <40f66681-d18c-45f5-aa37-bcba22eb88de>
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] app_macro.c: Spawn extension (macro-dialout-trunk, s, 23) exited non-zero on ‘PJSIP/305-0000094f’ in macro ‘dialout-trunk’
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] pbx.c: Spawn extension (from-internal, 5551212, 7) exited non-zero on ‘PJSIP/305-0000094f’
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:1] Macro(“PJSIP/305-0000094f”, “hangupcall”) in new stack
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:1] GotoIf(“PJSIP/305-0000094f”, “1?theend”) in new stack
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2019-04-27 12:37:19] VERBOSE[68567][C-000004d9] bridge_channel.c: Channel PJSIP/TW-00000950 left ‘simple_bridge’ basic-bridge <40f66681-d18c-45f5-aa37-bcba22eb88de>
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:3] ExecIf(“PJSIP/305-0000094f”, “0?Set(CDR(recordingfile)=)”) in new stack
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:4] NoOp(“PJSIP/305-0000094f”, "PJSIP/TW-00000950 montior file= ") in new stack
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:5] GotoIf(“PJSIP/305-0000094f”, “1?skipagi”) in new stack
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] pbx_builtins.c: Goto (macro-hangupcall,s,7)
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] pbx.c: Executing [[email protected]:7] Hangup(“PJSIP/305-0000094f”, “”) in new stack
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] app_macro.c: Spawn extension (macro-hangupcall, s, 7) exited non-zero on ‘PJSIP/305-0000094f’ in macro ‘hangupcall’
[2019-04-27 12:37:19] VERBOSE[68565][C-000004d9] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on ‘PJSIP/305-0000094f’
[[email protected] asterisk]#

6

This is when the call got connected, it confirmed the audio and joined the channel bridge 5 seconds later.

Here it got a confirmation for audio when the call was placed on hold, and when the call resumed.

I don’t see anything obvious here. Might be I missed something (I’m on mobile)

Do you know when they lost audio? The only time it makes sense is when the call got connected, but that’s still before both parties were connected…

7

I asked the customer when in the call,the audio dropped out and he was emphatic that it happened at 12:20. I’m confused by that because that time doesn’t even show up as meaningful in the debug as I read it.

Do you have any suggestions in terms of trying to look at other logs at around the same time, such as some Linux log?

The only other time I experienced something like this that wasn’t trunk related was when I had changed the hostname and the DNS wasn’t quite right. When that system attempted to do voicemail to email delivery it would cause audio issues. In that case, we turned off voicemail to email completely and I fixed the hostname issue and the problems immediately went away.

In this case, I have 127.0.0.1 as the first DNS server and the router as the second, plus 8.8.8.8. Do you think I should get rid of everything except 127.0.0.1? The host name is properly set in system admin.

Russ

8

This morning, I decided to remove our router from the DNS list so I now have just 127.0.0.1 and 8.8.8.8. I did have a couple DNS entries in the router that related to the PBX, which I think are correct, but I want rule them out and I don’t really see any reason to have the router in there. Plus having the router as a DNS server was one thing that is different than my other hosts (onsite and virtual) from this system.

Russ

9

Unfortunately, removing the router DNS did nothing. Several users reported the 5 second dropout today during calls.

Russ

10

I used the debug process above to check the call history of another call that experienced a 5 second dropout during the call. There was nothing in the log at the time of the dropout. I’m thinking this way of analyzing this issue isn’t going to help unfortunately.

If anyone has any other suggestions, I would appreciate it.

Russ

11

Here is the Cron log during the time of the audio drop out in case it might be something that is executing in the background:

Apr 29 14:21:01 pbx CROND[21785]: (asterisk) CMD (/usr/sbin/fwconsole calendar --sync 2>&1 > /dev/null)
Apr 29 14:21:01 pbx CROND[21786]: (asterisk) CMD (php /var/lib/asterisk/bin/vqplus_generate_periodical_events.php > /dev/null 2>&1)
Apr 29 14:21:01 pbx CROND[21787]: (asterisk) CMD (/usr/sbin/fwconsole pms wu_alert > /dev/null 2>&1)
Apr 29 14:21:01 pbx CROND[21788]: (asterisk) CMD ([ -x /var/lib/asterisk/bin/schedtc.php ] && /var/lib/asterisk/bin/schedtc.php)
Apr 29 14:21:01 pbx CROND[21793]: (asterisk) CMD ([ -x /var/www/html/admin/modules/dashboard/scheduler.php ] && /var/www/html/admin/modules/dashboard/scheduler.php > /dev/null 2>&1)
Apr 29 14:21:01 pbx CROND[21796]: (asterisk) CMD (/usr/sbin/fwconsole queuestats --syncall >> /tmp/reader.log 2>&1)
Apr 29 14:21:01 pbx CROND[21795]: (asterisk) CMD (/var/lib/asterisk/bin/pagepro-scheduler.php 2>&1 >/dev/null)
Apr 29 14:21:01 pbx crontab[21835]: (asterisk) LIST (asterisk)
Apr 29 14:21:01 pbx crontab[21839]: (asterisk) LIST (asterisk)
Apr 29 14:21:01 pbx crontab[21841]: (asterisk) LIST (asterisk)

12

You mentioned earlier that HTOP does not show spiking, which makes me think that this is not related at all.

However, is your PBX up to date?

13

One way of troubleshooting intermittent issues is to continuously record all network traffic at the PBX, then examine what happened when the trouble occurred.

For example, from a root shell prompt, start a capture with
tcpdump -s 0 -C 100 -W 100 -w rbuf -Z root &
This will write a circular buffer of 100 files of 100 MB each (rbuf00, rbuf01 … rbuf99).
Be sure that you have 10 GB spare space on the drive.

When trouble is reported, locate the file containing the event, copy it to your PC and analyze it with Wireshark. It should show whether RTP stops arriving from the extension or the trunk, or whether Asterisk fails to send out the corresponding packets in a timely fashion.

It would also be useful to know: Do the dropouts affect what the extension user hears, what the remote party hears, or both? If there are two or more calls in progress at the time, are they all affected? Are the extensions involved on the same LAN as the PBX? If not, please explain. Are internal calls ever affected by this issue?

14

Thank you the excellent suggestions. I will try to do some more captures. The dropouts can be in either direction or both as far as I know. Usually what is reported is that the extension on the internal side was talking and the remote user says you cut out for a few seconds, please repeat yourself. I’ve never heard of more than one call being affected at the same time, which isn’t to say it isn’t happening. I do know from Spectrum’s analysis that there are low MOS scores for these calls and that there have been between 4 and 12 other calls in process at the same time during some of them.

I don’t know if internal (intercom) calls have been affected. I don’t have a report of that except in the case where an outside (VPN based VoIP) connection was involved. I think there are cases where that has happened when the Spectrum trunk was not involved. In other words, the call came in over the Internet connection, through the normal router over OpenVPN. The problem is not limited to OpenVPN extensions though so I don’t think that is relevant.

I did notice that there were 284 Linux updates missing. I installed them all last night. The PBX was already up to date.

15

This topic was automatically closed 14 days after the last reply. New replies are no longer allowed.