Double Dialing

[Stan Coleman]

UPDATE 03/02/2017 01:49 PM Central: Time between dialing is 60 seconds not the 1 second I posted. Patrick Sparkman very eloquently corrected me in his post.

We have an issue were Conductor will call a Participant twice in the same conference. The first call gets connected and shows up as Ad-Hoc in TMS. Depending on how the receiving codec is setup the second call either never connects or it connects a second time. All our endpoints are setup to not except a second call when in a call so it doesn't cause us a lot of issues. However we have several outside organizations that we connect to that DO allow multiple incoming calls at the same time. For those units the second call connects as well as the first call. The second call that connects also connects as Ad-Hoc and the system starts dialing a third time. The multiple connections go on and on until either we reach maximum connections on the endpoint or someone gets tired of all the high pitched feedback and calls us.

This issue appears to be completely random. We can go for days or weeks with no issues and then have a day full of them. All our calls are scheduled and the issue doesn't always effect the same conference in the reoccurring series. However we have seen cases where it will be specific to a reoccurring scheduled call as well. We are using our system to connect Classrooms together. The classes are schedule for 16 weeks in advance so the reoccurring scheduled calls are very large. Classes that happen 5 times a week for 16 weeks generate a large number of conferences. We have had it happen when we load down the bridges with 6-8 conferences running an average of 6 endpoints a piece and when we only have 2 conferences on the bridge. Load doesn't appear to be part of the issue. All conferences do start at the same time. It's not uncommon to have 6 conferences all start at the exact same minute.

When you look in the VCSc log you will see that there are two requests to add the endpoint separated by about a second.

2017-03-01 08:00:14	SIP (INVITE)	10.xxx.xxx.xxx	sip:Greeley/W_LSRM200_211@xxx.xxx.xxx.211	Found	View
2017-03-01 07:59:14	SIP (INVITE)	10.xxx.xxx.xxx	sip:Greeley/W_LSRM200_211@xxx.xxx.xxx.211	Found	View

This may be a poor example because its an H323 call. You'll just have to trust me that it happens on both H323 and SIP calls.

Each call to the participant has it's own Call Serial Number and Tag. Other than that the logs in VCSc look identical for both calls. All the same rules are applied to both calls. If the call goes outside our network then there are two more calls listed on VCSe with the exact same time stamps as VCSc.

It has happened when we connect to our in-house SX80's, C60's and when we connect to Lifesize and Polycom units.

Our setup is TMS, Conductor, Three MCU5320's, Three VCSc and one VCSe. Really need the Communities help on this one as I have had a TAC case open for months on this with no resolution. TMS,Conductor the MCU's and VCS's are all on the same subnet and in the same rack.

[Patrick Sparkman]

I've seen this issue occur for H323 calls that doesn't include a domain after the alias, see bug CSCun68407.  It happens when Conductor sends the call to the VCS, and the VCS IP address gets appended to the alias.  Workaround is to set "Connection Attempts for Scheduled Calls" to 1 under Admin Tools > Configuration > Conference Settings, which will only have TMS dial out to the endpoint once.

[Stan Coleman]

That might fix the H323 issue but what about the SIP side? We have it happen on SIP calls as well. Would that be the same fix?

I'm going to set the Calls to 1 and see what happens.

[Patrick Sparkman]

I've never seen the issue occur for SIP calls, but TMS can sometimes be slow to update the status of an endpoint whether it's connected in the conference or not. If that is the case, the connection timeout might be triggered and TMS would try to connect again, so I'd also check the timeout value that's configured, as it might be set too low. 

[Stan Coleman]

Timeout was set at 60 seconds. I put it back to default of 30. Don't think that's the issue though because the 1 second between calls is the same for SIP calls as well. If an endpoint is timing out in under a second that would be amazing. :-)

Only time will tell if switching "Connection Attempts for Scheduled Calls" from 4 to 1 will make a difference on both H323 and SIP.

[Patrick Sparkman]

If the connection attempts was set to 4 with a connection timeout of 60 seconds, that would explain why TMS dialed out to the endpoint exactly a minute after the first dial attempt. Check the event log for the conference in question within TMS, you'll probably end up seeing two dial attempts before TMS registers the endpoint actually being connected in the conference. Ic this is the case, you can either increase the connection timeout or reduce the connection attempts. 

[Stan Coleman]

I need to have my eye prescription checked again. :-)

This the difference between calls is 60 seconds like your correctly stated. However TMS does know the first call is connected. At least to some degree. Within seconds of the call being placed you will see the connection show up in TMS as Ad-Hoc. So while it knows it's connected it somehow doesn't attribute the connection to the conference for which it just dialed.

Call in question actually shows the first connection taking place in about 34 seconds in the TMS log. Call starts at 6:59:00 PM and connects at 6:59:34 PM according to the TMS log. At 7:00:01 PM TMS starts to redial endpoint in question.

If TMS doesn't think it's connected why does the second call register with a different Call Serial Number and Call Tag? If it thinks it's not connected wouldn't it just use the original Serial Number and Call Tag and redial? The new Call Serial Number and Call Tag makes me think it's a totally separate call not associated with the first. Am I wrong?

I think for now I'll just leave "Allocation Attempts for Scheduled Calls" set to 1 and "Connection Timeout for Scheduled Calls and Allocation" set to 30 seconds (the default). I've made it 3 hours and 7 Video Conferences after making the changes with no Double Dials.

[Stan Coleman]

UPDATE: So far no Doubles. Finished yesterday with no Doubles and have made it through 18 Conferences today with no Doubles. Monday will be a better test as it has more conferences scheduled than any other day of the week. Won't really know if it's fixed until we make it through at least one week maybe two. Looks like we could be on the right track though.

Thanks everyone for your input.

[Stan Coleman]

:-(

Well it appears to have cut down on the number of Double Dials but hasn't completely eliminated it. This time the Participant that Double Dialed connected within 4 seconds of the conference start. However CTC reported it as connecting as Ad-Hoc and continued on in an attempt to connect the same Participant again.

[Stan Coleman]

So far nothing has worked and the issue just keeps getting worse. At the beginning of the Semester we had about 2 weeks with no Double Dials. Then in weeks 3 and 4 it started up again. Every week it's gotten worse. Up until this week it only affected our internal connections. Since we don't allow a second inbound call when in a call it wasn't much more than a inconvenience. Starting last week it has now started to affect calls we make outside our network. Those units may or may not allow a second inbound call. Of course when they do allow a second call and they answer the call the second time we have a huge audio issue.

Only change we have made in the last couple of weeks was the one Patrick Sparkman suggested, which didn't work. Last night we rebooted all three MCU5320 combos and the TMS. Today we are still Double Dialing.

Workaround is to set "Connection Attempts for Scheduled Calls" to 1 under Admin Tools > Configuration > Conference Settings, which will only have TMS dial out to the endpoint once.

[Patrick Sparkman]

Can you provide the log from a conference within CCC, so we can see exactly what TMS is seeing happening in the conference?

[Stan Coleman]

What do you want logs from? VCS? TMS? MCU? Wouldn't hurt to provide a short description of where to find the log file to make sure we are talking about the same log.

[Patrick Sparkman]

When you have a conference open within Conference Control Center (CCC) in TMS, there is an Event Log tab where TMS logs events that occur in the conference.

[Stan Coleman]

Here is a log with a couple of Double Dials in it. I altered the text to remove or alter IP Addresses, Host Names, Alias's and User Names. Double Dials are RKEA131 and LEX213.

Date            Type        User    System        Description

3/17/17 10:53:51 AM    CallInfo        CTC    Instance: Meeting released on port meet.xxxxx.scheduled@mydomainname.edu
3/17/17 10:53:00 AM    CallInfo        CTC    Instance: Sent in video 1 minutes left of conference message
3/17/17 10:50:13 AM    CallDisconnect        CTC    Instance: Call disconnected: sip:CNEC904@mydomainname.edu, CCC Columbus 904. Normal, unspecified
3/17/17 10:49:43 AM    CallInfo        CTC    Instance: Duo video closed. Source: CCC Columbus 904
3/17/17 10:49:01 AM    CallInfo        CTC    Instance: Sent in video 5 minutes left of conference message
3/17/17 10:03:05 AM    CallConnected        CTC    Instance: Call connected: sip:RLEX213@mydomainname.edu. MCU: 10.xxx.xxx.xxx (MCU1).
3/17/17 10:02:35 AM    CallInfo        CTC    Instance: SIP Dial => RLEX213@mydomainname.edu
3/17/17 10:02:34 AM    CallInfo        CNEC904    Instance: Sent message to participant CNEC904: Connecting participant failed: RLEX213. Trying to reconnect.
3/17/17 10:02:34 AM    CallInfo                Instance: Trying to reconnect calls
3/17/17 10:02:34 AM    CallDisconnect        CTC    Instance: Call disconnected: sip:RLEX213@mydomainname.edu, CCC Lexington 213. Normal, unspecified
3/17/17 10:02:34 AM    CallDisconnect        CTC    Instance: Call disconnected: RKEA131@mydomainname.edu, RKEA131@mydomainname.edu. Normal, unspecified
3/17/17 10:02:19 AM    CallInfo    Stan Operator-A    CTC    Instance: Disconnect: CCC Lexington 213
3/17/17 10:02:03 AM    CallInfo    Stan Operator-A    CTC    Instance: Disconnect: RKEA131@mydomainname.edu
3/17/17 10:01:38 AM    ConferenceInfo    Stan Operator-A        Instance: Is an exception to the recurrent series
3/17/17 10:01:38 AM    ConferenceInfo    Stan Operator-A        Instance: Updated
3/17/17 10:01:34 AM    ConferenceInfo        CTC    Instance: Ad hoc call added: RKEA131@mydomainname.edu
3/17/17 10:01:34 AM    CallInfo        CTC    Instance: Duo video opened. Source: CNEC904
3/17/17 10:01:30 AM    ConferenceInfo    Stan Operator-A        Instance: Is an exception to the recurrent series
3/17/17 10:01:30 AM    ConferenceInfo    Stan Operator-A        Instance: Participant removed: RKEA131
3/17/17 10:01:30 AM    ConferenceInfo    Stan Operator-A        Instance: Updated
3/17/17 10:01:04 AM    CallInfo        CNEC904    Instance: Sent message to participant CNEC904: Connecting participant failed: RKEA131. Trying to reconnect.
3/17/17 10:01:02 AM    CallInfo        CTC    Instance: SIP Dial => RKEA131@mydomainname.edu
3/17/17 10:01:02 AM    CallInfo        CTC    Instance: SIP Dial => RLEX213@mydomainname.edu
3/17/17 10:01:02 AM    CallInfo        CNEC904    Instance: Sent message to participant CNEC904: Connecting participant failed: RLEX213. Trying to reconnect.
3/17/17 10:01:02 AM    CallInfo                Instance: Trying to reconnect calls
3/17/17 10:01:02 AM    CallDisconnect        CTC    Instance: Call disconnected: RKEA131@mydomainname.edu, RKEA131@mydomainname.edu. Normal, unspecified
3/17/17 10:00:32 AM    CallInfo        CTC    Instance: SIP Dial => RLEX213@mydomainname.edu
3/17/17 10:00:31 AM    CallInfo        CNEC904    Instance: Sent message to participant CNEC904: Connecting participant failed: RLEX213. Trying to reconnect.
3/17/17 10:00:31 AM    CallInfo                Instance: Trying to reconnect calls
3/17/17 10:00:01 AM    CallInfo        CTC    Instance: SIP Dial => RLEX213@mydomainname.edu
3/17/17 10:00:01 AM    CallInfo        CNEC904    Instance: Sent message to participant CNEC904: Connecting participant failed: RLEX213. Trying to reconnect.
3/17/17 10:00:01 AM    CallInfo                Instance: Trying to reconnect calls
3/17/17 9:59:32 AM    CallInfo        CNEC904    Instance: Sent message to participant CNEC904: Connecting participant failed: RKEA131. Trying to reconnect.
3/17/17 9:59:31 AM    CallInfo        CTC    Instance: SIP Dial => RKEA131@mydomainname.edu
3/17/17 9:59:31 AM    CallInfo        CTC    Instance: SIP Dial => RLEX213@mydomainname.edu
3/17/17 9:59:31 AM    CallInfo        CNEC904    Instance: Sent message to participant CNEC904: Connecting participant failed: RLEX213. Trying to reconnect.
3/17/17 9:59:31 AM    CallInfo                Instance: Trying to reconnect calls
3/17/17 9:59:31 AM    CallConnected        CTC    Instance: Call connected: sip:HPLT236@mydomainname.edu. MCU: 10.xxx.xxx.xxx (MCU1).
3/17/17 9:59:31 AM    CallConnected        CTC    Instance: Call connected: sip:CNEC904@mydomainname.edu. MCU: 10.xxx.xxx.xxx (MCU1).
3/17/17 9:59:31 AM    CallConnected        CTC    Instance: Call connected: sip:GICC103@mydomainname.edu. MCU: 10.xxx.xxx.xxx (MCU1).
3/17/17 9:59:30 AM    CallConnected        CTC    Instance: Call connected: sip:RKEA131@mydomainname.edu. MCU: 10.xxx.xxx.xxx (MCU1).
3/17/17 9:59:30 AM    CallConnected        CTC    Instance: Call connected: sip:RLEX213@mydomainname.edu. MCU: 10.xxx.xxx.xxx (MCU1).
3/17/17 9:59:02 AM    ConferenceInfo        CTC    Instance: Ad hoc call added: omitted-by-bridge
3/17/17 9:59:02 AM    ConferenceInfo        CTC    Instance: Ad hoc call added: omitted-by-bridge
3/17/17 9:59:02 AM    CallConnected        CTC    Instance: Call connected: sip:TCS.NECE904@mydomainname.edu. MCU: 10.xxx.xxx.xxx (MCU1).
3/17/17 9:59:02 AM    CallInfo        CTC    Instance: SIP Dial => HPLT236@mydomainname.edu
3/17/17 9:59:01 AM    CallInfo        CTC    Instance: SIP Dial => CNEC904@mydomainname.edu
3/17/17 9:59:01 AM    CallInfo        CTC    Instance: SIP Dial => GICC103@mydomainname.edu
3/17/17 9:59:01 AM    CallInfo        CTC    Instance: SIP Dial => RKEA131@mydomainname.edu
3/17/17 9:59:00 AM    CallInfo        CTC    Instance: SIP Dial => RLEX213@mydomainname.edu
3/17/17 9:59:00 AM    CallInfo        HPLT236    Instance: Sent message to participant HPLT236: Scheduled call being connected
3/17/17 9:59:00 AM    CallInfo        HPLT236    Instance: Meeting allocated on port: 1
3/17/17 9:59:00 AM    CallInfo        CNEC904    Instance: Sent message to participant CNEC904: Scheduled call being connected
3/17/17 9:59:00 AM    CallInfo        CNEC904    Instance: Meeting allocated on port: 1
3/17/17 9:59:00 AM    CallInfo        GICC103    Instance: Sent message to participant GICC103: Scheduled call being connected
3/17/17 9:59:00 AM    CallInfo        GICC103    Instance: Meeting allocated on port: 1
3/17/17 9:59:00 AM    CallInfo        RKEA131    Instance: Sent message to participant RKEA131: Scheduled call being connected
3/17/17 9:59:00 AM    CallInfo        RKEA131    Instance: Meeting allocated on port: 1
3/17/17 9:59:00 AM    CallInfo        RLEX213    Instance: Sent message to participant RLEX213: Scheduled call being connected
3/17/17 9:59:00 AM    CallInfo        RLEX213    Instance: Meeting allocated on port: 1
3/17/17 9:59:00 AM    CallInfo        CTC    Instance: SIP Dial => TCS.NECE904@mydomainname.edu
3/17/17 9:54:00 AM    CallInfo        CTC    Instance: Meeting allocated on port: meet.xxxxx.scheduled@mydomainname.edu
3/17/17 9:54:00 AM    ConferenceInfo                Instance: Non-secure conference. Original value of the setting was 'if possible' and not all participants support encryption.
3/17/17 9:54:00 AM    ConferenceActive                Instance: Started
3/17/17 9:44:04 AM    ConferenceInfo                Instance: The main participant will start the conference 5 minutes early.
3/17/17 9:44:04 AM    ConferenceInfo                Instance: Registered
1/25/17 4:17:40 PM    ConferenceInfo    Diana Operator1        Instance: Updated
1/25/17 4:17:40 PM    ConferenceInfo    Diana Operator1        Conference: Participant removed: RHOL104
1/25/17 4:17:40 PM    ConferenceInfo    Diana Operator1        Conference: Updated
1/20/17 10:32:32 AM    ConferenceInfo    Diana Operator1        Instance: Updated
1/20/17 10:32:32 AM    ConferenceInfo    Diana Operator1        Conference: Participant removed: GICC522
1/20/17 10:32:32 AM    ConferenceInfo    Diana Operator1        Conference: Participant added: GICC103
1/20/17 10:32:32 AM    ConferenceInfo    Diana Operator1        Conference: Updated
1/11/17 10:42:32 AM    ConferenceInfo    Jason Operatr        Instance: Created, start time 03/17/2017 09:59:00 -05:00
1/11/17 10:42:32 AM    ConferenceInfo    Jason Operatr        Conference: Recurrence changed from Occurs every Monday, Wednesday and Friday effective Friday, January 13, 2017 until Friday, May 5, 2017. to Occurs every Monday, Wednesday and Friday effective Friday, January 13, 2017 until Wednesday, May 3, 2017.
1/11/17 10:42:32 AM    ConferenceInfo    Jason Operatr        Conference: Recreated
1/11/17 10:35:03 AM    ConferenceInfo    Jason Operatr        Conference: Updated
1/11/17 10:31:45 AM    ConferenceInfo    Jason Operatr        Conference: Updated
1/11/17 10:19:01 AM    ConferenceInfo    Jason Operatr        Conference: Recurrent series created, Occurs every Monday, Wednesday and Friday effective Friday, January 13, 2017 until Friday, May 5, 2017.

[Patrick Sparkman]

I'm not sure what is going on, with the connection setting changes you made prviously, TMS shouldn't be reconnecting an already connected call.  You said you decreased the connection timeout, what happens if you increase it, since I see the first reconnect occur at 30 seconds?