Skip to content

Commit 81da63e

Browse files
vincentkamrstam
vincentkam
authored and
rstam
committed
CSHARP-2147: Add logging of heartbeat information and SDAM state transitions
1 parent fe9ff1f commit 81da63e

19 files changed

+1034
-6
lines changed

‎src/MongoDB.Driver.Core.Dotnet/MongoDB.Driver.Core.Dotnet.csproj

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,10 @@
1818
<Compile Include="..\MongoDB.Driver.Core\**\*.cs;..\MongoDB.Shared\ApplicationNameHelper.cs;..\MongoDB.Shared\Hasher.cs;..\MongoDB.Shared\MaxTimeHelper.cs" Exclude="bin\**;obj\**;**\*.xproj;packages\**" />
1919
</ItemGroup>
2020

21+
<ItemGroup>
22+
<PackageReference Include="System.Diagnostics.TextWriterTraceListener" Version="4.0.0" />
23+
</ItemGroup>
24+
2125
<ItemGroup>
2226
<ProjectReference Include="..\MongoDB.Bson.Dotnet\MongoDB.Bson.Dotnet.csproj" />
2327
</ItemGroup>

‎src/MongoDB.Driver.Core/Core/Clusters/MultiServerCluster.cs

Lines changed: 88 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@
2424
using MongoDB.Driver.Core.Async;
2525
using MongoDB.Driver.Core.Configuration;
2626
using MongoDB.Driver.Core.Events;
27+
using MongoDB.Driver.Core.Events.Diagnostics;
2728
using MongoDB.Driver.Core.Misc;
2829
using MongoDB.Driver.Core.Servers;
2930

@@ -51,6 +52,7 @@ internal sealed class MultiServerCluster : Cluster
5152
private readonly Action<ClusterAddedServerEvent> _addedServerEventHandler;
5253
private readonly Action<ClusterRemovingServerEvent> _removingServerEventHandler;
5354
private readonly Action<ClusterRemovedServerEvent> _removedServerEventHandler;
55+
private readonly Action<SdamInformationEvent> _sdamInformationEventHandler;
5456

5557
// constructors
5658
public MultiServerCluster(ClusterSettings settings, IClusterableServerFactory serverFactory, IEventSubscriber eventSubscriber)
@@ -80,6 +82,7 @@ public MultiServerCluster(ClusterSettings settings, IClusterableServerFactory se
8082
eventSubscriber.TryGetEventHandler(out _addedServerEventHandler);
8183
eventSubscriber.TryGetEventHandler(out _removingServerEventHandler);
8284
eventSubscriber.TryGetEventHandler(out _removedServerEventHandler);
85+
eventSubscriber.TryGetEventHandler(out _sdamInformationEventHandler);
8386
}
8487

8588
// methods
@@ -327,7 +330,10 @@ private ClusterDescription ProcessReplicaSetChange(ClusterDescription clusterDes
327330
if (_maxElectionInfo != null)
328331
{
329332
isCurrentPrimaryStale = _maxElectionInfo.IsStale(args.NewServerDescription.ReplicaSetConfig.Version.Value, args.NewServerDescription.ElectionId);
330-
var isReportedPrimaryStale = !isCurrentPrimaryStale;
333+
var isReportedPrimaryStale = _maxElectionInfo.IsFresher(
334+
args.NewServerDescription.ReplicaSetConfig.Version.Value,
335+
args.NewServerDescription.ElectionId);
336+
331337

332338
if (isReportedPrimaryStale && args.NewServerDescription.ElectionId != null)
333339
{
@@ -336,6 +342,20 @@ private ClusterDescription ProcessReplicaSetChange(ClusterDescription clusterDes
336342
{
337343
var server = _servers.SingleOrDefault(x => EndPointHelper.Equals(args.NewServerDescription.EndPoint, x.EndPoint));
338344
server.Invalidate();
345+
346+
_sdamInformationEventHandler?.Invoke(new SdamInformationEvent(() =>
347+
string.Format(
348+
@"Invalidating server: Setting ServerType to ""Unknown"" for {0} because it " +
349+
@"claimed to be the replica set primary for replica set ""{1}"" but sent a " +
350+
@"(setVersion, electionId) tuple of ({2}, {3}) that was less than than the " +
351+
@"largest tuple seen, (maxSetVersion, maxElectionId), of ({4}, {5}).",
352+
args.NewServerDescription.EndPoint,
353+
args.NewServerDescription.ReplicaSetConfig.Name,
354+
args.NewServerDescription.ReplicaSetConfig.Version,
355+
args.NewServerDescription.ElectionId,
356+
_maxElectionInfo.SetVersion,
357+
_maxElectionInfo.ElectionId)));
358+
339359
return clusterDescription.WithServerDescription(
340360
new ServerDescription(server.ServerId, server.EndPoint));
341361
}
@@ -344,6 +364,58 @@ private ClusterDescription ProcessReplicaSetChange(ClusterDescription clusterDes
344364

345365
if (isCurrentPrimaryStale)
346366
{
367+
if (_maxElectionInfo == null)
368+
{
369+
_sdamInformationEventHandler?.Invoke(new SdamInformationEvent(() =>
370+
string.Format(
371+
@"Initializing (maxSetVersion, maxElectionId): Saving tuple " +
372+
@"(setVersion, electionId) of ({0}, {1}) as (maxSetVersion, maxElectionId) for " +
373+
@"replica set ""{2}"" because replica set primary {3} sent ({0}, {1}), the first " +
374+
@"(setVersion, electionId) tuple ever seen for replica set ""{4}"".",
375+
args.NewServerDescription.ReplicaSetConfig.Version,
376+
args.NewServerDescription.ElectionId,
377+
args.NewServerDescription.ReplicaSetConfig.Name,
378+
args.NewServerDescription.EndPoint,
379+
args.NewServerDescription.ReplicaSetConfig.Name)));
380+
}
381+
else
382+
{
383+
if (_maxElectionInfo.SetVersion < args.NewServerDescription.ReplicaSetConfig.Version.Value)
384+
{
385+
_sdamInformationEventHandler?.Invoke(new SdamInformationEvent(() =>
386+
string.Format(
387+
@"Updating stale setVersion: Updating the current " +
388+
@"(maxSetVersion, maxElectionId) tuple from ({0}, {1}) to ({2}, {3}) for " +
389+
@"replica set ""{4}"" because replica set primary {5} sent ({6}, {7})—a larger " +
390+
@"(setVersion, electionId) tuple then the saved tuple, ({0}, {1}).",
391+
_maxElectionInfo.SetVersion,
392+
_maxElectionInfo.ElectionId,
393+
args.NewServerDescription.ReplicaSetConfig.Version,
394+
args.NewServerDescription.ElectionId,
395+
args.NewServerDescription.ReplicaSetConfig.Name,
396+
args.NewServerDescription.EndPoint,
397+
args.NewServerDescription.ReplicaSetConfig.Version,
398+
args.NewServerDescription.ElectionId))) ;
399+
}
400+
else // current primary is stale & setVersion is not stale ⇒ the electionId must be stale
401+
{
402+
_sdamInformationEventHandler?.Invoke(new SdamInformationEvent(() =>
403+
string.Format(
404+
@"Updating stale electionId: Updating the current " +
405+
@"(maxSetVersion, maxElectionId) tuple from ({0}, {1}) to ({2}, {3}) for " +
406+
@"replica set ""{4}"" because replica set primary {5} sent ({6}, {7})—" +
407+
@"a larger (setVersion, electionId) tuple than the saved tuple, ({0}, {1}).",
408+
_maxElectionInfo.SetVersion,
409+
_maxElectionInfo.ElectionId,
410+
args.NewServerDescription.ReplicaSetConfig.Version,
411+
args.NewServerDescription.ElectionId,
412+
args.NewServerDescription.ReplicaSetConfig.Name,
413+
args.NewServerDescription.EndPoint,
414+
args.NewServerDescription.ReplicaSetConfig.Version,
415+
args.NewServerDescription.ElectionId)));
416+
}
417+
}
418+
347419
_maxElectionInfo = new ElectionInfo(
348420
args.NewServerDescription.ReplicaSetConfig.Version.Value,
349421
args.NewServerDescription.ElectionId);
@@ -522,6 +594,13 @@ public ElectionInfo(int setVersion, ElectionId electionId)
522594

523595
public ElectionId ElectionId => _electionId;
524596

597+
public bool IsFresher(int setVersion, ElectionId electionId)
598+
{
599+
return
600+
_setVersion > setVersion ||
601+
_setVersion == setVersion && _electionId != null && _electionId.CompareTo(electionId) > 0;
602+
}
603+
525604
public bool IsStale(int setVersion, ElectionId electionId)
526605
{
527606
if (_setVersion < setVersion)
@@ -532,13 +611,18 @@ public bool IsStale(int setVersion, ElectionId electionId)
532611
{
533612
return false;
534613
}
535-
614+
// Now it must be that _setVersion == setVersion
536615
if (_electionId == null)
537616
{
538617
return true;
539618
}
540-
541-
return _electionId.CompareTo(electionId) <= 0;
619+
620+
return _electionId.CompareTo(electionId) < 0;
621+
622+
/* above is equivalent to:
623+
* return
624+
* _setVersion < setVersion
625+
* || _setVersion == setVersion && (_electionId == null || _electionId.CompareTo(electionId) < 0); */
542626
}
543627
}
544628
}

‎src/MongoDB.Driver.Core/Core/Configuration/ClusterBuilder.cs

Lines changed: 30 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,12 +14,15 @@
1414
*/
1515

1616
using System;
17+
using System.Diagnostics;
18+
using System.IO;
1719
using System.Linq;
1820
using System.Reflection;
1921
using MongoDB.Driver.Core.Clusters;
2022
using MongoDB.Driver.Core.ConnectionPools;
2123
using MongoDB.Driver.Core.Connections;
2224
using MongoDB.Driver.Core.Events;
25+
using MongoDB.Driver.Core.Events.Diagnostics;
2326
using MongoDB.Driver.Core.Misc;
2427
using MongoDB.Driver.Core.Servers;
2528

@@ -30,11 +33,15 @@ namespace MongoDB.Driver.Core.Configuration
3033
/// </summary>
3134
public class ClusterBuilder
3235
{
36+
// constants
37+
private const string __traceSourceName = "MongoDB-SDAM";
38+
3339
// fields
3440
private EventAggregator _eventAggregator;
3541
private ClusterSettings _clusterSettings;
3642
private ConnectionPoolSettings _connectionPoolSettings;
3743
private ConnectionSettings _connectionSettings;
44+
private SdamLoggingSettings _sdamLoggingSettings;
3845
private ServerSettings _serverSettings;
3946
private SslStreamSettings _sslStreamSettings;
4047
private Func<IStreamFactory, IStreamFactory> _streamFactoryWrapper;
@@ -47,6 +54,7 @@ public class ClusterBuilder
4754
public ClusterBuilder()
4855
{
4956
_clusterSettings = new ClusterSettings();
57+
_sdamLoggingSettings = new SdamLoggingSettings(null);
5058
_serverSettings = new ServerSettings();
5159
_connectionPoolSettings = new ConnectionPoolSettings();
5260
_connectionSettings = new ConnectionSettings();
@@ -138,6 +146,28 @@ public ClusterBuilder ConfigureConnectionPool(Func<ConnectionPoolSettings, Conne
138146
_connectionPoolSettings = configurator(_connectionPoolSettings);
139147
return this;
140148
}
149+
150+
/// <summary>
151+
/// Configures the SDAM logging settings.
152+
/// </summary>
153+
/// <param name="configurator">The SDAM logging settings configurator delegate.</param>
154+
/// <returns>A reconfigured cluster builder.</returns>
155+
public ClusterBuilder ConfigureSdamLogging(Func<SdamLoggingSettings, SdamLoggingSettings> configurator)
156+
{
157+
_sdamLoggingSettings = configurator(_sdamLoggingSettings);
158+
if (!_sdamLoggingSettings.IsLoggingEnabled)
159+
{
160+
return this;
161+
}
162+
var traceSource = new TraceSource(__traceSourceName, SourceLevels.All);
163+
traceSource.Listeners.Clear(); // remove the default listener
164+
var listener = _sdamLoggingSettings.ShouldLogToStdout
165+
? new TextWriterTraceListener(Console.Out)
166+
: new TextWriterTraceListener(new FileStream(_sdamLoggingSettings.LogFilename, FileMode.Append));
167+
listener.TraceOutputOptions = TraceOptions.DateTime;
168+
traceSource.Listeners.Add(listener);
169+
return this.Subscribe(new TraceSourceSdamEventSubscriber(traceSource));
170+
}
141171

142172
/// <summary>
143173
/// Configures the server settings.

‎src/MongoDB.Driver.Core/Core/Configuration/ClusterBuilderExtensions.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -261,7 +261,7 @@ public static ClusterBuilder UsePerformanceCounters(this ClusterBuilder builder,
261261
return builder.Subscribe(subscriber);
262262
}
263263
#endif
264-
264+
265265
/// <summary>
266266
/// Configures the cluster to trace events to the specified <paramref name="traceSource"/>.
267267
/// </summary>

‎src/MongoDB.Driver.Core/Core/Configuration/SdamLoggingSettings.cs

Lines changed: 61 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,61 @@
1+
/* Copyright 2018–present MongoDB Inc.
2+
*
3+
* Licensed under the Apache License, Version 2.0 (the "License");
4+
* you may not use this file except in compliance with the License.
5+
* You may obtain a copy of the License at
6+
*
7+
* http://www.apache.org/licenses/LICENSE-2.0
8+
*
9+
* Unless required by applicable law or agreed to in writing, software
10+
* distributed under the License is distributed on an "AS IS" BASIS,
11+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12+
* See the License for the specific language governing permissions and
13+
* limitations under the License.
14+
*/
15+
16+
namespace MongoDB.Driver.Core.Configuration
17+
{
18+
/// <summary>
19+
/// Represents settings for SDAM logging.
20+
/// </summary>
21+
public class SdamLoggingSettings
22+
{
23+
private readonly string _logFilename;
24+
25+
/// <summary>
26+
/// Initializes a new instance of the <see cref="SdamLoggingSettings"/> class.
27+
/// </summary>
28+
/// <param name="logFilename">The filename to log to. An empty string or null will disable logging.
29+
/// "stdout" sneds output to stdout. </param>
30+
public SdamLoggingSettings(Optional<string> logFilename = default(Optional<string>))
31+
{
32+
_logFilename = logFilename.WithDefault(null);
33+
}
34+
35+
/// <summary>
36+
/// The filename to log to.
37+
/// </summary>
38+
public string LogFilename => _logFilename;
39+
40+
// methods
41+
/// <summary>
42+
/// Returns a new SdamLoggingSettings instance with some settings changed.
43+
/// </summary>
44+
/// <param name="logFilename">The filename.</param>
45+
/// <returns>A new SdamLoggingSettings instance.</returns>
46+
public SdamLoggingSettings With(Optional<string> logFilename = default(Optional<string>))
47+
{
48+
return new SdamLoggingSettings(logFilename: logFilename.WithDefault(_logFilename));
49+
}
50+
51+
/// <summary>
52+
/// Whether or not SDAM logging is enabled.
53+
/// </summary>
54+
internal bool IsLoggingEnabled => !string.IsNullOrEmpty(_logFilename);
55+
56+
/// <summary>
57+
/// Whether or not logging should be written to stdout.
58+
/// </summary>
59+
internal bool ShouldLogToStdout => _logFilename == "stdout";
60+
}
61+
}

‎src/MongoDB.Driver.Core/Core/Events/Diagnostics/TraceSourceEventSubscriber.cs

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -90,6 +90,11 @@ private void Handle(ClusterDescriptionChangedEvent @event)
9090
Info(TraceSourceEventHelper.ClusterIdBase + 8, "{0}: {1}", TraceSourceEventHelper.Label(@event.OldDescription.ClusterId), @event.NewDescription);
9191
}
9292

93+
private void Handle(SdamInformationEvent @event)
94+
{
95+
Info(TraceSourceEventHelper.ClusterIdBase + 9, "{0}", @event);
96+
}
97+
9398
// Servers
9499
private void Handle(ServerOpeningEvent @event)
95100
{

0 commit comments

Comments
 (0)