Ending call on one phone disconnects another call

[757performance]

Hi! I'm running a single WellTech 2540 gateway with a current up-to-date 3CX install. I never noticed it before, but from time to time a user will report after a lengthy phone call, if another user gets a call and hangs up, their line disconnects to dead air. After some time datalogging in Verbose, I've found the following out:

- At the precise moment a call is disconnected, the 3CX server still believes the call is ongoing. Timestamps agree with this. The user can hang up and 3CX gets a BYE from the Cisco handset.
- I haven't been able to verify this, but it seems this is more problematic on longer phone calls. I do not believe we have firewall issues since the gateway is inside our LAN.
- No other issues to report, everything is standard configuration via 3CX config files. Just this annoying thing!

Here is a log, my notes are in bold. Any ideas or help is appreciated!

01-Jun-2016 16:23:14.626 Leg L:776.1[Line:90001<<2523010352] is terminated: Cause: BYE from PBX
01-Jun-2016 16:23:14.626 [CM503008]: Call(C:776): Call is terminated
01-Jun-2016 16:23:14.625 Leg L:776.3[Extn] is terminated: Cause: BYE from 192.168.1.11:5060
Hangup by user on 101, BYE is received by 3CX and call drops off the server monitor
01-Jun-2016 16:22:56.861 Currently active calls - 1: [776]
01-Jun-2016 16:22:56.861 Currently active calls - 1: [776]
01-Jun-2016 16:22:43.817 Leg L:777.1[Line:90002<<anonymous] is terminated: Cause: BYE from PBX
01-Jun-2016 16:22:43.817 [CM503008]: Call(C:777): Call is terminated
01-Jun-2016 16:22:43.817 Leg L:777.3[Extn] is terminated: Cause: BYE from 192.168.1.16:5060
hangup by user on 102, causing 101 to instantly go to dead air after the BYE
01-Jun-2016 16:22:26.851 Currently active calls - 3: [776,777,778]
01-Jun-2016 16:21:56.843 Currently active calls - 2: [776,777]
01-Jun-2016 16:21:24.836 Currently active calls - 2: [776,777]
01-Jun-2016 16:20:54.828 Currently active calls - 2: [776,777]
01-Jun-2016 16:20:22.819 Currently active calls - 2: [776,777]
01-Jun-2016 16:19:52.812 Currently active calls - 2: [776,777]
01-Jun-2016 16:19:20.806 Currently active calls - 2: [776,777]
01-Jun-2016 16:18:48.798 Currently active calls - 2: [776,777]
01-Jun-2016 16:18:18.792 Currently active calls - 2: [776,777]
01-Jun-2016 16:17:47.085 Leg L:777.2[Ivr] is terminated: Cause: BYE from 127.0.0.1:5483
01-Jun-2016 16:17:46.883 [CM503007]: Call(C:777): Extn:102 has joined, contact <sip:[email protected]:5060>
01-Jun-2016 16:17:46.882 L:777.3[Extn] has joined to L:777.1[Line:90002<<anonymous]
01-Jun-2016 16:17:46.882 NAT/ALG check:L:777.3[Extn] RESPONSE 200 on 'INVITE' - basic check passed. No information for extended checks
01-Jun-2016 16:17:46.783 Currently active calls - 2: [776,777]
01-Jun-2016 16:17:43.337 [CM503025]: Call(C:777): Calling T:RingAll:800@[Dev:sip:[email protected]:5060] for L:777.1[Line:90002<<anonymous]
01-Jun-2016 16:17:43.335 [CM503027]: Call(C:777): From: Line:90002<<anonymous ("7574994653" <sip:[email protected]:5060>) to T:RingAll:800@[Dev:sip:[email protected]:5060]
01-Jun-2016 16:17:43.335 [CM503004]: Call(C:777): Route 1: from L:777.1[Line:90002<<anonymous] to T:RingAll:800@[Dev:sip:[email protected]:5060]
01-Jun-2016 16:17:43.335 L:777.1[Line:90002<<anonymous] target's endpoint Extn:101 is Busy
Call is routed to 102 only since 101 is on line with Brent
01-Jun-2016 16:17:43.335 [CM505002]: Gateway:[WellTech2540] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [4PORT_GW] PBX contact: [sip:[email protected]:5060]
01-Jun-2016 16:17:43.133 NAT/ALG check:L:777.2[Ivr] REQUEST 'INVITE' - basic check passed. No information for extended checks
01-Jun-2016 16:17:37.401 [MS211000] C:777.1: 192.168.1.5:16545 is delivering DTMF using RTP payload (RFC2833). In-Band DTMF tone detection is disabled for this call segment.
01-Jun-2016 16:17:28.641 [CM503007]: Call(C:777): Ivr:801 has joined, contact <sip:[email protected]:5483>
01-Jun-2016 16:17:28.641 [CM503007]: Call(C:777): Line:90002<<anonymous has joined, contact <sip:[email protected]:8080>
01-Jun-2016 16:17:28.640 L:777.2[Ivr] has joined to L:777.1[Line:90002<<anonymous]
01-Jun-2016 16:17:28.640 NAT/ALG check:L:777.2[Ivr] RESPONSE 200 on 'INVITE' - basic check passed. No information for extended checks
01-Jun-2016 16:17:28.491 [CM503025]: Call(C:777): Calling T:Ivr:801@[Dev:sip:[email protected]:5483;rinstance=5c3142e4c60cc177] for L:777.1[Line:90002<<anonymous]
01-Jun-2016 16:17:28.441 [CM503027]: Call(C:777): From: Line:90002<<anonymous ("7574994653" <sip:[email protected]:5060>) to T:Ivr:801@[Dev:sip:[email protected]:5483;rinstance=5c3142e4c60cc177]
01-Jun-2016 16:17:28.441 [CM503004]: Call(C:777): Route 1: from L:777.1[Line:90002<<anonymous] to T:Ivr:801@[Dev:sip:[email protected]:5483;rinstance=5c3142e4c60cc177]
01-Jun-2016 16:17:28.441 [CM505002]: Gateway:[WellTech2540] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [4PORT_GW] PBX contact: [sip:[email protected]:5060]
01-Jun-2016 16:17:28.441 [CM503001]: Call(C:777): Incoming call from Line:90002<<anonymous to <sip:[email protected]:5060>
01-Jun-2016 16:17:28.441 Line limit check: Current # of calls for line Lc:90002(@WellTech2540[<sip:[email protected]:8080>]) is 1; limit is 1
01-Jun-2016 16:17:28.441 NAT/ALG check:L:777.1[Line:90002<<anonymous] REQUEST 'INVITE' - basic check passed. No information for extended checks
Line 2 is calling in, beginning of dropped call.....?
01-Jun-2016 16:17:28.438 [CM503012]: Inbound specific hours w/o holidays rule (unnamed) for 90002 forwards to DN:801
01-Jun-2016 16:17:28.161 [CM102001]: Authentication failed for AuthFail Recv Req INVITE from 192.168.1.5:8080 tid=-e44-37bc83-12d8ceaf Call-ID=761dc0-501a8c0-1f90-55022-e44-3be74212-e44:
INVITE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.5:8080;rport=8080;branch=z9hG4bK-e44-37bc83-12d8ceaf
Max-Forwards: 70
Contact: <sip:[email protected]:8080>
To: <sip:[email protected]:5060>
From: "7574994653"<sip:[email protected]:8080>;tag=755198-501a8c0-1f90-55022-e44-55c75e58-e44
Call-ID: 761dc0-501a8c0-1f90-55022-e44-3be74212-e44
CSeq: 2 INVITE
Content-Type: application/sdp
Proxy-Authorization: Digest username="90001",realm="3CXPhoneSystem",nonce="414d535c0d5fd3d895:dd0acd519ab8a6c1c4c4a49724fadcc5",uri="sip:[email protected]:5060",response="ee58f1be2d885f8d202edb3fd66567e0",algorithm=MD5
Supported: replaces
User-Agent: 4PORT_GW
Content-Length: 269

v=0
o=90001 22 22 IN IP4 192.168.1.5
s=CTIPHONE
c=IN IP4 192.168.1.5
t=0 0
m=audio 16545 RTP/AVP 8 0 4 18 101
a=rtpmap:8 PCMA/8000
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:4 G723/8000
a=rtpmap:18 G729/8000
a=fmtp:101 0-11
a=rtpmap:101 telephone-event/8000
; Reason: Credentials don't match, check that authorization-ID and password match the ones in extension settings
Big data dump, need to investiage this section
01-Jun-2016 16:17:24.599 Leg L:776.2[Ivr] is terminated: Cause: BYE from 127.0.0.1:5483
01-Jun-2016 16:17:24.511 Leg L:776.4[Extn] is terminated: Cause: 487 Request Terminated/INVITE from 192.168.1.16:5060
01-Jun-2016 16:17:24.511 [CM503003]: Call(C:776): Call to <sip:[email protected]:5060> has failed; Cause: 487 Request Terminated/INVITE from 192.168.1.16:5060
01-Jun-2016 16:17:24.398 [CM503007]: Call(C:776): Extn:101 has joined, contact <sip:[email protected]:5060>
01-Jun-2016 16:17:24.397 L:776.3[Extn] has joined to L:776.1[Line:90001<<2523010352]
01-Jun-2016 16:17:24.397 NAT/ALG check:L:776.3[Extn] RESPONSE 200 on 'INVITE' - basic check passed. No information for extended checks
user picks up 101
01-Jun-2016 16:17:22.531 [CM503025]: Call(C:776): Calling T:RingAll:800@[Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5060] for L:776.1[Line:90001<<2523010352]
01-Jun-2016 16:17:22.530 [CM503025]: Call(C:776): Calling T:RingAll:800@[Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5060] for L:776.1[Line:90001<<2523010352]
01-Jun-2016 16:17:22.478 [CM503027]: Call(C:776): From: Line:90001<<2523010352 ("7574562277" <sip:[email protected]:5060>) to T:RingAll:800@[Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5060]
PBX ringing 101, 102
01-Jun-2016 16:17:22.478 [CM503004]: Call(C:776): Route 1: from L:776.1[Line:90001<<2523010352] to T:RingAll:800@[Dev:sip:[email protected]:5060,Dev:sip:[email protected]:5060]
Call routed to front call group
01-Jun-2016 16:17:22.477 [CM505002]: Gateway:[WellTech2540] Device info: Device Not Identified: User Agent not matched; Capabilities:[reinvite, replaces, able-no-sdp, recvonly] UserAgent: [4PORT_GW] PBX contact: [sip:[email protected]:5060]
01-Jun-2016 16:17:22.276 NAT/ALG check:L:776.2[Ivr] REQUEST 'INVITE' - basic check passed. No information for extended checks
01-Jun-2016 16:17:16.777 Currently active calls - 1: [776]
01-Jun-2016 16:17:16.623 [MS211000] C:776.1: 192.168.1.5:16408 is delivering DTMF using RTP payload (RFC2833). In-Band DTMF tone detection is disabled for this call segment.
01-Jun-2016 16:17:00.351 [CM503007]: Call(C:776): Ivr:801 has joined, contact <sip:[email protected]:5483>
01-Jun-2016 16:17:00.351 [CM503007]: Call(C:776): Line:90001<<2523010352 has joined, contact <sip:[email protected]:8080>
01-Jun-2016 16:17:00.350 L:776.2[Ivr] has joined to L:776.1[Line:90001<<2523010352]
Call passes into voice attendant
01-Jun-2016 16:17:00.350 NAT/ALG check:L:776.2[Ivr] RESPONSE 200 on 'INVITE' - basic check passed. No information for extended checks
VOIP GW initiates call to PBX

 

[leejor]

The only thing that stands out as a bit odd, is the port number of the two trunks involved...

contact <sip:90002@192.168.1.5:8080>

Contact: <sip:90001@192.168.1.5:8080>

I'm not familiar with the WellTech gateways but is 8080 normally used, and if so, just the one port number for all trunks?

 

[757performance]

The only thing that stands out as a bit odd, is the port number of the two trunks involved...

contact <sip:90002@192.168.1.5:8080>

Contact: <sip:90001@192.168.1.5:8080>

I'm not familiar with the WellTech gateways but is 8080 normally used, and if so, just the one port number for all trunks?

I'm pretty new to VOIP in general since everything here was 20 years old until recently, but in the gateway's VOIP settings, I've got the following:

SIP Local Port: 8080
In the manual it says.. "SIP Local Port: The SIP local service port (default is 8080)"

It kind of makes sense, that if I've got two calls using the exact same port one termination would terminate audio on the other and give me the problems I'm having. There is no option in that menu to define per-trunk ports. In the gateway's SIP trunk menu, both Proxy & Outbound Server ports are set to 5060.

 

[leejor]

In the gateway's SIP trunk menu, both Proxy & Outbound Server ports are set to 5060.

If 5060 is used in the 3CX trunk settings for that gateway, then that is what the gateway must also use as it s local port. You should be able to change either end but they must match.

 

[757performance]

In the gateway's SIP trunk menu, both Proxy & Outbound Server ports are set to 5060.

If 5060 is used in the 3CX trunk settings for that gateway, then that is what the gateway must also use as it s local port. You should be able to change either end but they must match.

I changed the SIP Local Port to 5060 and 3CX's VOIP Gateway Port to 5060 from 8080. We'll see what happens now that all ports match...

 

[757performance]

Well, no such luck. Happened to me on a call that was about a minute and a half in the moment my co-worker hung up next to me. Only the following was on the server log...

06-Jun-2016 09:20:04.308 Leg L:1163.1[Extn] is terminated: Cause: BYE from 192.168.1.22:5060
I hung up after making sure the call was dead, nothing useful follows
06-Jun-2016 09:20:00.318 Currently active calls - 1: [1163]
At this moment, my audio goes dead, 3CX still thinks there's an ongoing call.
06-Jun-2016 09:19:41.905 Leg L:1162.1[Line:90001<<deleted customer#] is terminated: Cause: BYE from PBX
06-Jun-2016 09:19:41.905 [CM503008]: Call(C:1162): Call is terminated
06-Jun-2016 09:19:41.905 Leg L:1162.3[Extn] is terminated: Cause: BYE from 192.168.1.11:5060
06-Jun-2016 09:19:30.310 Currently active calls - 2: [1162,1163]

I suppose since I'm already in verbose I should start thinking of setting up WireShark on the server to sniff out VOIP traffic?

 

[leejor]

Wireshark would provide you with all of the SIP messages but may still not explain why the gateway is dropping the call. You may need to somehow extract logs (Syslog?) from the gateway for information on why it is dropping the trunks it is. My suspicion is that there is a misconfiguration where trunk information (ports?) have been duplicated so that the disconnect message is affecting the wrong, or more than one trunk.

Did you ever try starting from scratch, re-setting and "re-constructing" all of the trunks in both 3CX and the gateway?

 

[NickD_3CX]

Welltech gateways, by default in the GW Wizard the port is 8080 and it should not be a problem, I agree with leejor though, to see exactly what SIP messages are being exchanged between the server, the GW and the Cisco phone, capturing a problematic call with Wireshark should tell you exactly what happened as the logs viewer can sometimes be a bit misleading when trying to figure out the SIP messages that have been sent and received.