Problems with dropped calls 3CX V10 SP4, Patton 4960

[efounco]

We are having problems with dropped calls. The phones will ring normally, but when the call is picked up, the line goes dead. It is currently effecting about 5% of our customers; the other 95% have no problems calling in. We are using 3CX V10 SP4 with a Patton 4960 and Cisco SPA504/508G phones. I've tried firmware versions 5.2, 5.3 and 5.8 for the Patton and firmware revisions 7.4.8a, 7.4.9a and 7.4.9c for the Cisco phones. I've also done a full system reboot without success.

Here are some logs of a dropped call, but I see nothing out of the ordinary:

14:06:22.190 [CM503008]: Call(148): Call is terminated
14:06:18.590 [CM503003]: Call(148): Call to sip:[email protected] has failed; Cause: 487 Request Terminated; from IP:192.168.168.125:5060
14:06:18.589 [CM503003]: Call(148): Call to sip:[email protected] has failed; Cause: 487 Request Terminated; from IP:192.168.168.127:5060
14:06:18.555 [CM503003]: Call(148): Call to sip:[email protected] has failed; Cause: 487 Request Terminated; from IP:192.168.168.122:5060
14:06:18.533 [CM503003]: Call(148): Call to sip:[email protected] has failed; Cause: 487 Request Terminated; from IP:192.168.168.126:2777
14:06:18.398 [CM503007]: Call(148): Device joined: sip:[email protected]:5060
14:06:18.397 [CM503007]: Call(148): Device joined: sip:[email protected]:5060
14:06:15.855 [CM505001]: Ext.248: Device info: Device Identified: [Man: Cisco;Mod: SPA Series;Rev: General] Capabilities:[reinvite, replaces, unable-no-sdp, no-recvonly] UserAgent: [Cisco/SPA508G-7.4.9a] PBX contact: [sip:[email protected]:5060]
14:06:15.855 [CM503002]: Call(148): Alerting sip:[email protected]:5060
14:06:15.854 [CM505001]: Ext.224: Device info: Device Identified: [Man: Cisco;Mod: SPA Series;Rev: General] Capabilities:[reinvite, replaces, unable-no-sdp, no-recvonly] UserAgent: [Cisco/SPA504G-7.4.9a] PBX contact: [sip:[email protected]:5060]
14:06:15.854 [CM503002]: Call(148): Alerting sip:[email protected]:5060
14:06:15.821 [CM505001]: Ext.222: Device info: Device Identified: [Man: Cisco;Mod: SPA Series;Rev: General] Capabilities:[reinvite, replaces, unable-no-sdp, no-recvonly] UserAgent: [Cisco/SPA504G-7.4.9a] PBX contact: [sip:[email protected]:5060]
14:06:15.821 [CM503002]: Call(148): Alerting sip:[email protected]:5060
14:06:15.818 [CM505001]: Ext.230: Device info: Device Identified: [Man: Cisco;Mod: SPA Series;Rev: General] Capabilities:[reinvite, replaces, unable-no-sdp, no-recvonly] UserAgent: [Cisco/SPA504G-7.4.9a] PBX contact: [sip:[email protected]:5060]
14:06:15.818 [CM503002]: Call(148): Alerting sip:[email protected]:5060
14:06:15.717 [CM505001]: Ext.250: Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [snom-m9/9.4.12-a] PBX contact: [sip:[email protected]:5060]
14:06:15.717 [CM503002]: Call(148): Alerting sip:[email protected]:2777;transport=udp;line=v1by80
14:06:15.578 [CM503025]: Call(148): Calling RingAll501[Ext.222,Ext.224,Ext.230,Ext.248,Ext.250]@[Dev:sip:[email protected]:2777;transport=udp;line=v1by80]
14:06:15.575 [CM503025]: Call(148): Calling RingAll501[Ext.222,Ext.224,Ext.230,Ext.248,Ext.250]@[Dev:sip:[email protected]:5060]
14:06:15.571 [CM503025]: Call(148): Calling RingAll501[Ext.222,Ext.224,Ext.230,Ext.248,Ext.250]@[Dev:sip:[email protected]:5060]
14:06:15.568 [CM503025]: Call(148): Calling RingAll501[Ext.222,Ext.224,Ext.230,Ext.248,Ext.250]@[Dev:sip:[email protected]:5060]
14:06:15.564 [CM503025]: Call(148): Calling RingAll501[Ext.222,Ext.224,Ext.230,Ext.248,Ext.250]@[Dev:sip:[email protected]:5060]
14:06:15.519 [CM503004]: Call(148): Route 1: RingAll501[Ext.222,Ext.224,Ext.230,Ext.248,Ext.250]@[Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5060,Dev:sip:[email protected]:2777;transport=udp;line=v1by80]
14:06:15.518 [CM503010]: Making route(s) to <sip:[email protected]:5060>
14:06:15.516 [CM503001]: Call(148): Incoming call from 636305xxxx@(Ln.10000@Patton4960) to <sip:[email protected]:5060>

 

[efounco]

Our problem appears to be related to specific numbers calling in. We see their Caller ID information on the phone's display, but when the line is picked up, the call drops 100% of the time and the phone shows a missed call, WTF!

 

[efounco]

So, after a bit of testing and hair pulling, I think I found the cause of my problems. My issues are similar to the ones described here by another member:

wrong link <-- Searching...

After removed the single Snom M9 from the ring group, everything appears to be fine. It's a very strange issues because it's triggered by some callers and not others.

 

[snowsam]

I'm having the same problem after upgrading from v10 Sp3 to SP4 (and then a day later to SP5). Inbound calls with no audio were not occurring with SP3, but are with SP4 and 5. Very puzzling.

We are also using a Patton 4960 and are using Yealink phones. I have not tried updating the yealink or Patton firmwares yet, but both were current in July of this past summer.

If you have an more ideas, please share.

Sam

 

[snowsam]

Further info. I have debug logs from patton showing both a good call and and failed call and am able to see a difference.

I've highlighted where I saw the difference. I still don't know if this is a Patton problem, 3cx problem, or end-link problem, but at least I am making a little progress.

Good:

19:13:06 SIP_SI> [EP IF_SIP_0-00b4c848 SES 0xb69d88] < Stack: ACK
19:13:06 SIP_SI> [EP IF_SIP_0-00b4c848 SES 0xb69d88] < SM : Event 'Stk-Acked' (State 'Reestablishing-Incoming')
19:13:06 SIP_SI> [EP IF_SIP_0-00b4c848 SES 0xb69d88 SDP] < SM : Event 'RX-Ack' (State 'Negotiated')
19:13:06 SIP_SI> [EP IF_SIP_0-00b4c848 SES 0xb69d88] > SM : New state 'Established'
19:13:06 SIP_SI> [EP IF_SIP_0-00b4c848 SES 0xb69d88] > SM : Action 'App-Connected'
19:13:06 SIP_SI> [EP IF_SIP_0-00b4c848] < SM : Event 'Active-Session-Connected' (Active State 'Connected', Passive State 'Idle')
19:13:10 CC > [EP IF_SIP_0-00b4c848/active] Set call-leg property: Quality-Of-Service -> MOS 4.40, RTP, G.711 u-law (20ms), Local: Rx 89 pkts, 14240 bytes, 0 lost, jitter 0 ms, Tx 394 pkts, 63040 bytes, rtt 0 ms, Remote: Rx 0 pkts, 0 bytes, 0 lost, jitter 0 ms, Tx 0 pkts, 0 bytes, rtt 0 ms
19:13:15 CC > [EP IF_SIP_0-00b4c848/active] Set call-leg property: Quality-Of-Service -> MOS 4.40, RTP, G.711 u-law (20ms), Local: Rx 370 pkts, 59200 bytes, 0 lost, jitter 0 ms, Tx 675 pkts, 108000 bytes, rtt 0 ms, Remote: Rx 0 pkts, 0 bytes, 0 lost, jitter 0 ms, Tx 0 pkts, 0 bytes, rtt 0 ms
19:13:19 SIP_TR> [STACK] < Stack: from 172.18.9.6
BYE sip:[email protected]:5060 SIP/2.0

Failed:

18:16:49 SIP_SI> [EP IF_SIP_0-0100c0e8 SES 0xb4c848] < Stack: ACK
18:16:49 SIP_SI> [EP IF_SIP_0-0100c0e8 SES 0xb4c848] < SM : Event 'Stk-Acked' (State 'Reestablishing-Incoming')
18:16:49 SIP_SI> [EP IF_SIP_0-0100c0e8 SES 0xb4c848 SDP] < SM : Event 'RX-Ack' (State 'Negotiated')
18:16:49 SIP_SI> [EP IF_SIP_0-0100c0e8 SES 0xb4c848] > SM : New state 'Established'
18:16:49 SIP_SI> [EP IF_SIP_0-0100c0e8 SES 0xb4c848] > SM : Action 'App-Connected'
18:16:49 SIP_SI> [EP IF_SIP_0-0100c0e8] < SM : Event 'Active-Session-Connected' (Active State 'Connected', Passive State 'Idle')
18:16:49 SIP_SI> [EP IF_SIP_0-0100c0e8] Connection Broken
18:16:54 CC > [EP IF_SIP_0-0100c0e8/active] Set call-leg property: Quality-Of-Service -> MOS 4.40, RTP, G.711 u-law (20ms), Local: Rx 157 pkts, 25120 bytes, 0 lost, jitter 0 ms, Tx 394 pkts, 63040 bytes, rtt 0 ms, Remote: Rx 0 pkts, 0 bytes, 0 lost, jitter 0 ms, Tx 0 pkts, 0 bytes, rtt 0 ms
18:16:59 CC > [EP IF_SIP_0-0100c0e8/active] Set call-leg property: Quality-Of-Service -> MOS 4.40, RTP, G.711 u-law (20ms), Local: Rx 157 pkts, 25120 bytes, 0 lost, jitter 0 ms, Tx 675 pkts, 108000 bytes, rtt 0 ms, Remote: Rx 0 pkts, 0 bytes, 0 lost, jitter 0 ms, Tx 0 pkts, 0 bytes, rtt 0 ms
18:17:09 CC > [EP IF_SIP_0-0100c0e8/active] Set call-leg property: Quality-Of-Service -> MOS 4.40, RTP, G.711 u-law (20ms), Local: Rx 157 pkts, 25120 bytes, 0 lost, jitter 0 ms, Tx 1011 pkts, 161760 bytes, rtt 0 ms, Remote: Rx 0 pkts, 0 bytes, 0 lost, jitter 0 ms, Tx 0 pkts, 0 bytes, rtt 0 ms
18:17:14 CC > [EP IF_SIP_0-0100c0e8/active] Set call-leg property: Quality-Of-Service -> MOS 4.40, RTP, G.711 u-law (20ms), Local: Rx 157 pkts, 25120 bytes, 0 lost, jitter 0 ms, Tx 1329 pkts, 212640 bytes, rtt 0 ms, Remote: Rx 0 pkts, 0 bytes, 0 lost, jitter 0 ms, Tx 0 pkts, 0 bytes, rtt 0 ms
18:17:19 CC > [EP IF_SIP_0-0100c0e8/active] Set call-leg property: Quality-Of-Service -> MOS 4.40, RTP, G.711 u-law (20ms), Local: Rx 157 pkts, 25120 bytes, 0 lost, jitter 0 ms, Tx 1649 pkts, 263840 bytes, rtt 0 ms, Remote: Rx 0 pkts, 0 bytes, 0 lost, jitter 0 ms, Tx 0 pkts, 0 bytes, rtt 0 ms
18:17:20 SIP_TR> [STACK] < Stack: from 172.18.9.6
BYE sip:[email protected]:5060 SIP/2.0

--> One thing I did not mention before is that these calls are coming in on our main number and then going into a call queue. While I can get failed (and good) calls when calling in via the main number and queue, I have not yet been able to get a failed call when calling the DID that is mapped directly to my extension.

So maybe the problem is in how 3cx is handling the call as it goes through the queue?

 

[snowsam]

A quite a few test calls later, I am fairly certain that this is a call queue issue.

If I set my main number to come in on a ring group then I can call in over and over with no issues.

I change it back to a call queue (my usual default destination) and I get a broken connection error 20-60% of the time.

-Sam

 

[efounco]

I'm not sure if our problems are related, but I removed the Snom M9 from the ring group and my problems went away. I read somewhere that after using a packet sniffer, someone discovered that the Snom M9 would intermittently send a disconnect message to to server for no reason. Thus, no useable log information would be present in 3CX. For now it is easier to use the Snom elsewhere than trying to resolve intermittent issues that could potentially cost our company thousands.