03-02-2017 08:18 AM - edited 03-18-2019 12:50 PM
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.
SIP (INVITE) |
10.xxx.xxx.xxx |
Found |
|||
SIP (INVITE) |
10.xxx.xxx.xxx |
Found |
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.
03-02-2017 09:54 AM
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.
03-02-2017 09:54 AM
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.
03-02-2017 10:08 AM
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.
03-02-2017 10:20 AM
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.
03-02-2017 11:15 AM
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.
03-02-2017 11:44 AM
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.
03-03-2017 09:30 AM
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.
03-06-2017 10:05 AM
:-(
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.
03-17-2017 08:00 AM
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.
03-17-2017 08:49 AM
Can you provide the log from a conference within CCC, so we can see exactly what TMS is seeing happening in the conference?
03-17-2017 08:53 AM
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.
03-17-2017 09:12 AM
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.
03-17-2017 09:36 AM
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.
03-17-2017 10:34 AM
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?
Discover and save your favorite ideas. Come back to expert answers, step-by-step guides, recent topics, and more.
New here? Get started with these tips. How to use Community New member guide