Sporadic interruptions between call flow service and queue manager service

[lanb]

Hi

Some incoming calls are silent for the caller, and do not ring our internal phones.

What it should happen (~80% of the calls) :
Call incoming -> Redirect to an application call flow -> queue 800 (ring all) -> caller hears the waiting music -> An extension pick up the call -> end of call

What it happens when the problem occurs (~20% of the calls) :
Call incoming -> Redirect to an application call flow -> queue 800
But here, the caller does not hear anything, the call is in the switchboard but does not trigger the ring all process (no extension ringing)

Our workaround is actually to park the call with the switchboard, and unpark it with the phone (if the caller waited, because as he has no sound at all, usually he hangs up quickly)

The sip communication between 3cx and the trunk is good. Tcpdump show no error, only silent RTP stream for the problematic calls.
Logs in 3cxSystemService.log are very useful :

Normal calls are like this (phone numbers are replaced by stars) :
2019/07/18 06:57:16.171|12704|0029|Info|CHR: #1: Seg[1/#1] 4669520261aa(**)=>6ca4ab4d8559(Ext.testcfdv160.Main) (06:51:51.129..06:51:51.709) Ringing Connected
2019/07/18 06:57:16.172|12704|0029|Info|CHR: #2: Seg[1/#2] 4669520261aa(**)=>e50bc578a83c(Ext.testcfdv160.Main) (06:51:51.709..06:51:51.804) Talking ReplacedDst by 82b952437423(Ext.800)
2019/07/18 06:57:16.174|12704|0029|Info|CHR: #3: Seg[1/#3] 4669520261aa(**)=>7c1f2a56f9b9(Ext.800) (06:51:51.804..06:51:51.955) Ringing Connected
2019/07/18 06:57:16.175|12704|0029|Info|CHR: #4: Seg[1/#4] 4669520261aa(**)=>82b952437423(Ext.800) (06:51:51.955..06:53:47.926) Talking ReplacedDst by 52be7854c583(Ext.201)
2019/07/18 06:57:16.176|12704|0029|Info|CHR: #5: Seg[1/#5] 4669520261aa(**)=>93089c0586fa(Ext.201) (06:53:04.046..06:53:19.560) Ringing MissedQCalls
2019/07/18 06:57:16.177|12704|0029|Info|CHR: #6: Seg[1/#6] 4669520261aa(**)=>91707e2550ff(Ext.201) (06:53:19.560..06:53:35.074) Ringing MissedQCalls
2019/07/18 06:57:16.178|12704|0029|Info|CHR: #7: Seg[1/#7] 4669520261aa(**)=>8936417de059(Ext.201) (06:53:35.074..06:53:47.925) Ringing Connected
2019/07/18 06:57:16.179|12704|0029|Info|CHR: #8: Seg[1/#8] 4669520261aa(**)=>52be7854c583(Ext.201) (06:53:47.925..06:57:16.094) Talking TerminatedByDst




Problematic calls are like this :
2019/07/19 01:38:08.710|954|0042|Info|CHR: #1: Seg[1/#1] 75491d6028ca(**)=>10a009050f3f(Ext.testcfdv160.Main) (01:27:56.360..01:27:56.889) Ringing Connected
2019/07/19 01:38:08.721|954|0042|Info|CHR: #2: Seg[1/#2] 75491d6028ca(**)=>82b1b12cfded(Ext.testcfdv160.Main) (01:27:56.889..01:27:56.987) Talking ReplacedDst by 4dee3b2891f5(Ext.800)
2019/07/19 01:38:08.722|954|0042|Info|CHR: #3: Seg[1/#3] 75491d6028ca(**)=>61c08c2a9a5a(Ext.800) (01:27:56.987..01:27:57.155) Ringing Connected
2019/07/19 01:38:08.722|954|0042|Info|CHR: #4: Seg[1/#4] 75491d6028ca(**)=>4dee3b2891f5(Ext.800) (01:27:57.155..01:28:06.980) Talking QFwdToDNA by a779bb7f37a6(Ext.SP0)
2019/07/19 01:38:08.723|954|0042|Info|CHR: #5: Seg[1/#5] 75491d6028ca(**)=>9da6707b8613(Ext.SP0) (01:28:06.980..01:28:07.269) Ringing Connected
2019/07/19 01:38:08.723|954|0042|Info|CHR: #6: Seg[1/#6] 75491d6028ca(**)=>a779bb7f37a6(Ext.SP0) (01:28:07.269..01:28:15.469) Talking ReplacedDst by fd6c3b4b641a(Ext.201)
2019/07/19 01:38:08.724|954|0042|Info|CHR: #7: Seg[2/#7] fd6c3b4b641a(Ext.201)=>b47a1c75bb01(Ext.SP0) (01:28:14.806..01:28:15.092) Ringing Connected
2019/07/19 01:38:08.724|954|0042|Info|CHR: #8: Seg[2/#8] fd6c3b4b641a(Ext.201)=>f774150ac64a(Ext.SP0) (01:28:15.092..01:28:15.481) Talking TransferSrc
2019/07/19 01:38:08.725|954|0042|Info|CHR: #9: Seg[1/#9] 75491d6028ca(**)=>fd6c3b4b641a(Ext.201) (01:28:15.469..01:38:08.612) Talking TerminatedByDst




We can see the park/unpark method to get the call

So the problematics call seems to go to the queue manager, but :

• caller does not hear music
• extensions do not ring
• And the queue manager log does not show any activity during this call as you can see (the call starts at 01:27:56) :

Queuemanager.log
2019/07/19 01:27:38.918|1003|0003|Info|Statistics:
Current state report:
== Queues:
* Queue 800 cin: act=0/stat=0 poll=0 serv=0
# Calls in polling pool:
# Calls in servicing pool:
* Queue 804 cin: act=0/stat=0 poll=0 serv=0
# Calls in polling pool:
# Calls in servicing pool:
* Queue 801 cin: act=0/stat=0 poll=0 serv=0
# Calls in polling pool:
# Calls in servicing pool:
== Agents:
- Ag.201 Dial:201 Logged-IN Reg: Yes; Qs: [+800 +804]
- Ag.202 Dial:202 Logged-IN Reg: Yes; Qs: [+800]
- Ag.203 Dial:203 Logged-IN Reg: Yes; Qs: [+800]
- Ag.200 Dial:200 Logged-IN Reg: Yes; Qs: [+801]

2019/07/19 01:27:42.854|1003|0006|Info|Statistics:
Poll processor state:
=Normal requests:
=Total: 0 requests / 0 active

2019/07/19 01:27:52.857|1003|0006|Info|Statistics:
Poll processor state:
=Normal requests:
=Total: 0 requests / 0 active

2019/07/19 01:28:02.860|1003|0006|Info|Statistics:
Poll processor state:
=Normal requests:
=Total: 0 requests / 0 active

2019/07/19 01:28:08.918|1003|0003|Info|Statistics:
Current state report:
== Queues:
* Queue 800 cin: act=0/stat=0 poll=0 serv=0
# Calls in polling pool:
# Calls in servicing pool:
* Queue 804 cin: act=0/stat=0 poll=0 serv=0
# Calls in polling pool:
# Calls in servicing pool:
* Queue 801 cin: act=0/stat=0 poll=0 serv=0
# Calls in polling pool:
# Calls in servicing pool:
== Agents:
- Ag.201 Dial:201 Logged-IN Reg: Yes; Qs: [+800 +804]
- Ag.202 Dial:202 Logged-IN Reg: Yes; Qs: [+800]
- Ag.203 Dial:203 Logged-IN Reg: Yes; Qs: [+800]
- Ag.200 Dial:200 Logged-IN Reg: Yes; Qs: [+801]





I restarted the queue manager service, I restarted the VM and the problem is always there.
I am on the 3cx version debian 9, 16.0.1.273
What can I do to explore/resolve this issue ?

Thanks for your help

 

[lanb]

3CXIVR.log shows also that the queue manager does not work :

example for a correct call (There is a line "NEW QMR .... -> 800) :

21/07/2019 10:42:38.216 [0000041b] 1833 NEW RPT : ********** -> testcfdv160.Main (testcfdv160.Main)
21/07/2019 10:42:38.216 [0000041b] DR Added new session 1833, total 5
21/07/2019 10:42:38.216 [0000041b] I_vEwla4H19lbxXPq3nXYQ..02c500b5a QM answered and created IVR session
21/07/2019 10:42:38.217 [0000041b] I_vEwla4H19lbxXPq3nXYQ..02c500b5a QM established
21/07/2019 10:42:38.217 [0000041b] QM UpdateCall I_vEwla4H19lbxXPq3nXYQ..02c500b5a: 6 active
21/07/2019 10:42:38.217 [00000421] 1833 PLAY id = 1 : #ONHOLD = /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/onhold.wav BG
21/07/2019 10:42:38.252 [0000041a] z-Gdt9yN_EDSCabz8m_How..06cb3123f QM Prompt #4 played back
21/07/2019 10:42:38.430 [00000421] 1833 QM Cancel playback in mode 3
21/07/2019 10:42:38.439 [000003ea] QM UpdateConnection: inserting new entry APSdXkI5jVtjdnyr26L5cw..086e83311: 7 active
21/07/2019 10:42:38.446 [000003ea] QM Removed AC I_vEwla4H19lbxXPq3nXYQ..02c500b5a: 7 active
21/07/2019 10:42:38.481 [0000041b] 1834 NEW QMR : ********** -> 800 (800)
21/07/2019 10:42:38.481 [0000041b] DR Added new session 1834, total 6
21/07/2019 10:42:38.482 [0000041b] APSdXkI5jVtjdnyr26L5cw..086e83311 QM answered and created IVR session
21/07/2019 10:42:38.482 [0000041b] APSdXkI5jVtjdnyr26L5cw..086e83311 QM established
21/07/2019 10:42:38.482 [0000041b] QM UpdateCall APSdXkI5jVtjdnyr26L5cw..086e83311: 7 active
21/07/2019 10:42:38.482 [00000421] 1834 PLAY id = 1 : /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/Predec_standard_8khz_mono.wav = /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/Predec_standard_8khz_mono.wav BG
21/07/2019 10:42:38.582 [0000041b] DR Session 1833 has been ended by PBX, total 5

And for a bogus one (No line for new QMR) :

21/07/2019 10:42:23.299 [0000041b] QM UpdateCall inserting new entry X55grERUowCqsVZpdtnyEQ..03feff06d: 6 active
21/07/2019 10:42:23.678 [0000041b] 1832 NEW RPT : ********** -> testcfdv160.Main (testcfdv160.Main)
21/07/2019 10:42:23.678 [0000041b] DR Added new session 1832, total 6
21/07/2019 10:42:23.678 [0000041b] X55grERUowCqsVZpdtnyEQ..03feff06d QM answered and created IVR session
21/07/2019 10:42:23.681 [0000041b] X55grERUowCqsVZpdtnyEQ..03feff06d QM established
21/07/2019 10:42:23.681 [0000041b] QM UpdateCall X55grERUowCqsVZpdtnyEQ..03feff06d: 6 active
21/07/2019 10:42:23.681 [00000421] 1832 PLAY id = 1 : #ONHOLD = /var/lib/3cxpbx/Instance1/Data/Ivr/Prompts/onhold.wav BG
21/07/2019 10:42:23.854 [00000421] 1832 QM Cancel playback in mode 3
21/07/2019 10:42:23.887 [000003ea] QM UpdateConnection: inserting new entry f0MYeVtKQHOAWOWJq03x8w..0a7cb9c4d: 7 active
21/07/2019 10:42:23.895 [000003ea] QM Removed AC X55grERUowCqsVZpdtnyEQ..03feff06d: 7 active
21/07/2019 10:42:24.030 [0000041b] DR Session 1832 has been ended by PBX, total 5
21/07/2019 10:42:24.030 [00000421] 1832 DELETE
...
21/07/2019 10:42:56.068 [000003ea] QM Removed AC and call f0MYeVtKQHOAWOWJq03x8w..0a7cb9c4d: 6 active

An idea to wake up the queue manager at each call ?

 

[lanb]

I updated the 3cx server to the last version and it changed nothing.

But I discovered that removing the CFD solved the problem (but I need a CFD to route the calls...). There is no abandoned calls if I put the inbound rule DID -> Ext (Queue number) instead of DID -> CFD
So as it is a problem between CFD and QueueManager, I open a new Post in the CFD Forum

 

[JohnS_3CX]

Hi @lanb

Call incoming -> Redirect to an application call flow -> queue 800 (ring all) -> caller hears the waiting music -> An extension pick up the call -> end of call

I was thinking the same when I saw your post, because I'm not sure when the CFD application contains. I will close this thread since it's better suited for CFD section.