Skip to content

Commit faf51dc

Browse files
tanderson-ldkinyoklion
tanderson-ld
and
kinyoklion
authored
chore: adds logging to composite data source (#216)
**Requirements** - [x] I have added test coverage for new or changed functionality - [x] I have followed the repository's [pull request submission guidelines](../blob/main/CONTRIBUTING.md#submitting-pull-requests) - [x] I have validated my changes against all supported platform versions **Describe the solution you've provided** Adds friendly descriptions of composites / sources and logging to help debug how the FDv2DataSource is moving. Example output: ``` [LaunchDarkly.Sdk] INFO: Starting LaunchDarkly client 8.11.0-beta.1+2516a64b90f6defdddc5e8d7058c87da880b035a [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: FDv2DataSource started Initializers. [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: Created LaunchDarkly FDv2 polling data source [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: Initializers started FDv2PollingDataSource. [LaunchDarkly.Sdk.FDv2DataSource] INFO: Starting LaunchDarkly FDv2 polling with interval: 30000 milliseconds [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: Polling LaunchDarkly for feature flag updates [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: Making FDv2 polling request to https://sdk.launchdarkly.com/sdk/poll [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: Received FDv2 polling response [LaunchDarkly.Sdk.FDv2DataSource] INFO: First polling request successful [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: FDv2DataSource has blocked factory used to create Initializers from being used again. [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: FDv2DataSource is going to dispose of Initializers. [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: FDv2DataSource at Synchronizers. [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: FDv2DataSource started Synchronizers. [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: Created LaunchDarkly streaming data source [LaunchDarkly.Sdk.FDv2DataSource] DEBUG: Synchronizers started FDv2StreamingDataSource. [LaunchDarkly.Sdk.FDv2DataSource] INFO: Connecting to LaunchDarkly stream ``` <!-- CURSOR_SUMMARY --> --- > [!NOTE] > Improves observability and API clarity for data source orchestration. > > - Adds `compositeDescription` and `Logger` to `CompositeSource`; logs starts, disposals, transitions, and factory blocks; custom exhaustion message; `ToString()` for sources > - Renames `BlacklistCurrent` to `BlockCurrent` in `ICompositeSourceActionable` and all call sites; updates tests accordingly > - Wires logger into `FDv2DataSource.CreateFDv2DataSource` and `FDv2DataSystem`; uses sublogger `FDv2DataSourceSubLog` > - Adds `ToString()` to `FDv2PollingDataSource` and `FDv2StreamingDataSource` > - `ActionApplierTimedFallbackAndRecovery` now logs when falling back/recovering and takes a `Logger` > > <sup>Written by [Cursor Bugbot](https://cursor.com/dashboard?tab=bugbot) for commit a529e4a. This will update automatically on new commits. Configure [here](https://cursor.com/dashboard?tab=bugbot).</sup> <!-- /CURSOR_SUMMARY --> --------- Co-authored-by: Ryan Lamb <4955475+kinyoklion@users.noreply.github.com>
1 parent 2005848 commit faf51dc

8 files changed

Lines changed: 128 additions & 46 deletions

File tree

‎pkgs/sdk/server/src/Internal/DataSources/CompositeDataSource/CompositeSource.cs‎

Lines changed: 45 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
using System;
22
using System.Collections.Generic;
33
using System.Threading.Tasks;
4+
using LaunchDarkly.Logging;
45
using LaunchDarkly.Sdk.Server.Interfaces;
56
using LaunchDarkly.Sdk.Server.Subsystems;
67

@@ -18,6 +19,8 @@ internal sealed class CompositeSource : IDataSource, ICompositeSourceActionable
1819
// We also use a small, non-recursive action queue so that any re-entrant calls
1920
// from action applier logic is serialized and processed iteratively instead
2021
// of recursively, avoiding the risk of stack overflows.
22+
private readonly string _compositeDescription;
23+
private readonly Logger _log;
2124
private readonly object _lock = new object();
2225
private readonly Queue<Action> _pendingActions = new Queue<Action>();
2326
private bool _isProcessingActions;
@@ -37,12 +40,16 @@ internal sealed class CompositeSource : IDataSource, ICompositeSourceActionable
3740
/// <summary>
3841
/// Creates a new <see cref="CompositeSource"/>.
3942
/// </summary>
43+
/// <param name="compositeDescription">description of the composite source for logging purposes</param>
4044
/// <param name="updatesSink">the sink that receives updates from the active source</param>
4145
/// <param name="factoryTuples">the ordered list of source factories and their associated action applier factories</param>
46+
/// <param name="logger">the logger instance to use</param>
4247
/// <param name="circular">whether to loop off the end of the list back to the start when fallback occurs</param>
4348
public CompositeSource(
49+
string compositeDescription,
4450
IDataSourceUpdatesV2 updatesSink,
4551
IList<(SourceFactory Factory, ActionApplierFactory ActionApplierFactory)> factoryTuples,
52+
Logger logger,
4653
bool circular = true)
4754
{
4855
if (updatesSink is null)
@@ -54,6 +61,9 @@ public CompositeSource(
5461
throw new ArgumentNullException(nameof(factoryTuples));
5562
}
5663

64+
_compositeDescription = compositeDescription;
65+
_log = logger;
66+
5767
_originalUpdateSink = updatesSink;
5868
_sanitizedUpdateSink = new DataSourceUpdatesSanitizer(updatesSink);
5969

@@ -66,6 +76,11 @@ public CompositeSource(
6676
);
6777
}
6878

79+
/// <summary>
80+
/// Returns a string representation of this data source for informational purposes.
81+
/// </summary>
82+
public override string ToString() => _compositeDescription;
83+
6984
/// <summary>
7085
/// When <see cref="Start"/> is called, the current data source is started. This should only be called once.
7186
/// </summary>
@@ -201,7 +216,7 @@ private void TryFindNextUnderLock()
201216
var errorInfo = new DataSourceStatus.ErrorInfo
202217
{
203218
Kind = DataSourceStatus.ErrorKind.Unknown,
204-
Message = "CompositeDataSource has exhausted all available sources.",
219+
Message = "Composite source " + _compositeDescription + " has exhausted its constituent sources.",
205220
Time = DateTime.Now
206221
};
207222
InternalDispose(errorInfo);
@@ -275,6 +290,7 @@ public Task<bool> StartCurrent()
275290
{
276291
try
277292
{
293+
_log.Debug("{0} started {1}.", _compositeDescription, dataSourceToStart.ToString());
278294
var result = await dataSourceToStart.Start().ConfigureAwait(false);
279295
tcs.TrySetResult(result);
280296
}
@@ -306,6 +322,9 @@ public void DisposeCurrent()
306322
{
307323
lock (_lock)
308324
{
325+
String currentDescription = _currentDataSource?.ToString();
326+
_log.Debug("{0} is going to dispose of {1}.", _compositeDescription, currentDescription);
327+
309328
// cut off all the update proxies that have been handed out first, this is
310329
// necessary to avoid a cascade of actions leading to callbacks leading to actions, etc.
311330
_disableableTracker.DisablePreviouslyTracked();
@@ -331,6 +350,9 @@ public void GoToNext()
331350
{
332351
lock (_lock)
333352
{
353+
// Get description of current source before disposing it
354+
String previousDescription = _currentDataSource?.ToString();
355+
334356
// cut off all the update proxies that have been handed out first, this is
335357
// necessary to avoid a cascade of actions leading to callbacks leading to actions, etc.
336358
_disableableTracker.DisablePreviouslyTracked();
@@ -343,7 +365,8 @@ public void GoToNext()
343365

344366
TryFindNextUnderLock();
345367

346-
// if there is no next source, there's nothing more to do
368+
String currentDescription = _currentDataSource?.ToString();
369+
logTransition(previousDescription, currentDescription);
347370
}
348371
});
349372
}
@@ -359,6 +382,8 @@ public void GoToFirst()
359382
{
360383
lock (_lock)
361384
{
385+
String previousDescription = _currentDataSource?.ToString();
386+
362387
// moving always disconnects the current source
363388
_disableableTracker.DisablePreviouslyTracked();
364389

@@ -371,7 +396,9 @@ public void GoToFirst()
371396
_sourcesList.Reset();
372397
TryFindNextUnderLock();
373398

374-
// if there are no sources, there's nothing more to do
399+
String currentDescription = _currentDataSource?.ToString();
400+
401+
logTransition(previousDescription, currentDescription);
375402
}
376403
});
377404
}
@@ -388,7 +415,7 @@ public bool IsAtFirst()
388415
}
389416
}
390417

391-
public void BlacklistCurrent()
418+
public void BlockCurrent()
392419
{
393420
if (_disposed)
394421
{
@@ -405,14 +432,28 @@ public void BlacklistCurrent()
405432
return;
406433
}
407434

435+
String currentDescription = _currentDataSource?.ToString();
436+
408437
// remove the factory tuple for our current entry
409438
// note: blacklisting does not tear down the current data source, it just prevents it from being used again
410439
_sourcesList.Remove(_currentEntry);
411440
_currentEntry = default;
441+
442+
_log.Debug("{0} has blocked factory used to create {1} from being used again.", _compositeDescription, currentDescription);
412443
}
413444
});
414445
}
415446

447+
private void logTransition(String previousDescription, String currentDescription) {
448+
if (previousDescription != null && currentDescription != null) {
449+
_log.Debug("{0} transitioned from {1} to {2}.", _compositeDescription, previousDescription, currentDescription);
450+
} else if (previousDescription != null) {
451+
_log.Debug("{0} transitioned away from {1}.", _compositeDescription, previousDescription);
452+
} else if (currentDescription != null) {
453+
_log.Debug("{0} at {1}.", _compositeDescription, currentDescription);
454+
}
455+
}
456+
416457
#endregion
417458
}
418459
}

‎pkgs/sdk/server/src/Internal/DataSources/CompositeDataSource/ICompositeSourceActionable.cs‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -34,10 +34,10 @@ internal interface ICompositeSourceActionable
3434
bool IsAtFirst();
3535

3636
/// <summary>
37-
/// Blacklists the current source. This prevents the current source from being used again.
38-
/// Note that blacklisting does not tear down the current data source, it just prevents it from being used again.
37+
/// Blocks the the current source's factory. This prevents the current source's factory from being used again.
38+
/// Note that this does not tear down the current data source, it just prevents its factory from being used again.
3939
/// </summary>
40-
void BlacklistCurrent();
40+
void BlockCurrent();
4141
}
4242
}
4343

‎pkgs/sdk/server/src/Internal/DataSystem/FDv2DataSystem.cs‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -88,7 +88,8 @@ public static FDv2DataSystem Create(Logger logger, Configuration configuration,
8888
new List<SourceFactory>
8989
{
9090
FactoryWithContext(clientContext)(dataSystemConfiguration.FDv1FallbackSynchronizer)
91-
}
91+
},
92+
logger
9293
);
9394

9495
var dataSourceStatusProvider = new DataSourceStatusProviderImpl(dataSourceUpdates);

‎pkgs/sdk/server/src/Internal/FDv2DataSources/FDv2DataSource.cs‎

Lines changed: 24 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,7 @@
22
using System.Collections.Generic;
33
using System.Threading;
44
using System.Threading.Tasks;
5+
using LaunchDarkly.Logging;
56
using LaunchDarkly.Sdk.Server.Interfaces;
67
using LaunchDarkly.Sdk.Server.Internal.DataSources;
78
using LaunchDarkly.Sdk.Server.Subsystems;
@@ -21,20 +22,24 @@ internal static partial class FDv2DataSource
2122
/// <param name="initializers">List of data source factories used for initialization</param>
2223
/// <param name="synchronizers">List of data source factories used for synchronization</param>
2324
/// <param name="fdv1Synchronizers">List of data source factories used for FDv1 synchronization if fallback to FDv1 occurs</param>
25+
/// <param name="logger">the logger instance to use</param>
2426
/// <returns>a new data source instance</returns>
2527
public static IDataSource CreateFDv2DataSource(
2628
IDataSourceUpdatesV2 updatesSink,
2729
IList<SourceFactory> initializers,
2830
IList<SourceFactory> synchronizers,
29-
IList<SourceFactory> fdv1Synchronizers)
31+
IList<SourceFactory> fdv1Synchronizers,
32+
Logger logger)
3033
{
34+
var sublogger = logger.SubLogger(LogNames.FDv2DataSourceSubLog);
35+
3136
// Here we make a combined composite source, with the initializer source first which switches or falls back to the
3237
// synchronizer source when the initializer succeeds or when the initializer source reports Off (all initializers failed)
3338
ActionApplierFactory blacklistWhenSuccessOrOff =
3439
(actionable) => new ActionApplierBlacklistWhenSuccessOrOff(actionable);
3540
ActionApplierFactory fastFallbackApplierFactory = (actionable) => new ActionApplierFastFallback(actionable);
3641
ActionApplierFactory timedFallbackAndRecoveryApplierFactory =
37-
(actionable) => new ActionApplierTimedFallbackAndRecovery(actionable);
42+
(actionable) => new ActionApplierTimedFallbackAndRecovery(actionable, sublogger);
3843

3944
ActionApplierFactory fdv1FallbackApplierFactory = (actionable) => new FDv1FallbackActionApplier(actionable);
4045

@@ -64,7 +69,7 @@ public static IDataSource CreateFDv2DataSource(
6469
}
6570

6671
// The common data source updates implements both IDataSourceUpdates and IDataSourceUpdatesV2.
67-
return new CompositeSource(sink, initializerFactory, circular: false);
72+
return new CompositeSource("Initializers", sink, initializerFactory, sublogger, circular: false);
6873
},
6974
(actionable) => new CompositeObserver(
7075
initializationObserver, blacklistWhenSuccessOrOff(actionable))
@@ -86,7 +91,7 @@ public static IDataSource CreateFDv2DataSource(
8691
timedFallbackAndRecoveryApplierFactory));
8792
}
8893

89-
return new CompositeSource(sink, synchronizersFactoryTuples);
94+
return new CompositeSource("Synchronizers", sink, synchronizersFactoryTuples, sublogger);
9095
},
9196
(actionable) =>
9297
{
@@ -116,12 +121,12 @@ public static IDataSource CreateFDv2DataSource(
116121
timedFallbackAndRecoveryApplierFactory)); // fdv1 synchronizers behave same as synchronizers
117122
}
118123

119-
return new CompositeSource(sink, fdv1SynchronizersFactoryTuples);
124+
return new CompositeSource("FDv1FallbackSynchronizers", sink, fdv1SynchronizersFactoryTuples, sublogger);
120125
}, (applier) => fallbackSynchronizationObserver
121126
));
122127
}
123128

124-
return new CompletingDataSource(new CompositeSource(updatesSink, underlyingComposites, circular: false),
129+
return new CompletingDataSource(new CompositeSource("FDv2DataSource", updatesSink, underlyingComposites, sublogger, circular: false),
125130
initializationTracker);
126131
}
127132

@@ -170,6 +175,7 @@ public void Apply(ChangeSet<ItemDescriptor> changeSet)
170175
internal class ActionApplierTimedFallbackAndRecovery : IDataSourceObserver
171176
{
172177
private readonly ICompositeSourceActionable _actionable;
178+
private readonly Logger _log;
173179
private readonly object _lock = new object();
174180
private Task _fallbackTask;
175181
private CancellationTokenSource _fallbackCanceller;
@@ -180,14 +186,15 @@ internal class ActionApplierTimedFallbackAndRecovery : IDataSourceObserver
180186
private static readonly TimeSpan DefaultInterruptedFallbackTimeout = TimeSpan.FromMinutes(2);
181187
private static readonly TimeSpan DefaultValidRecoveryTimeout = TimeSpan.FromMinutes(5);
182188

183-
public ActionApplierTimedFallbackAndRecovery(ICompositeSourceActionable actionable)
184-
: this(actionable, DefaultInterruptedFallbackTimeout, DefaultValidRecoveryTimeout)
189+
public ActionApplierTimedFallbackAndRecovery(ICompositeSourceActionable actionable, Logger logger)
190+
: this(actionable, logger, DefaultInterruptedFallbackTimeout, DefaultValidRecoveryTimeout)
185191
{
186192
}
187193

188-
internal ActionApplierTimedFallbackAndRecovery(ICompositeSourceActionable actionable, TimeSpan interruptedFallbackTimeout, TimeSpan validRecoveryTimeout)
194+
internal ActionApplierTimedFallbackAndRecovery(ICompositeSourceActionable actionable, Logger logger, TimeSpan interruptedFallbackTimeout, TimeSpan validRecoveryTimeout)
189195
{
190196
_actionable = actionable ?? throw new ArgumentNullException(nameof(actionable));
197+
_log = logger ?? throw new ArgumentNullException(nameof(logger));
191198
_interruptedFallbackTimeout = interruptedFallbackTimeout;
192199
_validRecoveryTimeout = validRecoveryTimeout;
193200
}
@@ -213,7 +220,7 @@ public void UpdateStatus(DataSourceState newState, DataSourceStatus.ErrorInfo? n
213220
{
214221
if (newError != null && !newError.Value.Recoverable)
215222
{
216-
_actionable.BlacklistCurrent();
223+
_actionable.BlockCurrent();
217224
}
218225
_actionable.DisposeCurrent();
219226
_actionable.GoToNext();
@@ -250,6 +257,8 @@ public void UpdateStatus(DataSourceState newState, DataSourceStatus.ErrorInfo? n
250257
_fallbackCanceller = null;
251258
_fallbackTask = null;
252259

260+
_log.Warn("Current data source has been interrupted for more than {0} minutes, falling back to next source.", _interruptedFallbackTimeout.TotalMinutes);
261+
253262
// Do the fallback: dispose current, go to next, start current
254263
_actionable.DisposeCurrent();
255264
_actionable.GoToNext();
@@ -298,6 +307,8 @@ public void UpdateStatus(DataSourceState newState, DataSourceStatus.ErrorInfo? n
298307
_recoveryCanceller = null;
299308
_recoveryTask = null;
300309

310+
_log.Info("Current data source has been valid for more than {0} minutes, recovering to primary source.", _validRecoveryTimeout.TotalMinutes);
311+
301312
// Do the recovery: dispose current, go to first, start current
302313
_actionable.DisposeCurrent();
303314
_actionable.GoToFirst();
@@ -367,7 +378,7 @@ public void UpdateStatus(DataSourceState newState, DataSourceStatus.ErrorInfo? n
367378
// When Off status is seen, blacklist current, dispose current, go to next, and start current
368379
if (newState == DataSourceState.Off)
369380
{
370-
_actionable.BlacklistCurrent();
381+
_actionable.BlockCurrent();
371382
_actionable.DisposeCurrent();
372383
_actionable.GoToNext();
373384
_actionable.StartCurrent();
@@ -382,7 +393,7 @@ public void Apply(ChangeSet<ItemDescriptor> changeSet)
382393
// From a forward development perspective this could be because we had a local stale selector which was
383394
// persisted in some way, and we are getting up to date via an initializer.
384395
if (changeSet.Selector.IsEmpty) return;
385-
_actionable.BlacklistCurrent();
396+
_actionable.BlockCurrent();
386397
_actionable.DisposeCurrent();
387398
_actionable.GoToNext();
388399
_actionable.StartCurrent();
@@ -402,7 +413,7 @@ public void UpdateStatus(DataSourceState newState, DataSourceStatus.ErrorInfo? n
402413
{
403414
if (newError != null && newError.Value.FDv1Fallback)
404415
{
405-
_actionable.BlacklistCurrent(); // blacklist the synchronizers altogether
416+
_actionable.BlockCurrent(); // blacklist the synchronizers altogether
406417
_actionable.DisposeCurrent(); // dispose the synchronizers
407418
_actionable.GoToNext(); // go to the FDv1 fallback synchronizer
408419
_actionable.StartCurrent(); // start the FDv1 fallback synchronizer

‎pkgs/sdk/server/src/Internal/FDv2DataSources/FDv2PollingDataSource.cs‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,11 @@ internal sealed class FDv2PollingDataSource : IDataSource
3333
private bool _disposed = false;
3434
private readonly AtomicBoolean _shuttingDown = new AtomicBoolean(false);
3535

36+
/// <summary>
37+
/// Returns a string representation of this data source for informational purposes.
38+
/// </summary>
39+
public override string ToString() => "FDv2PollingDataSource";
40+
3641
internal FDv2PollingDataSource(
3742
LdClientContext context,
3843
IDataSourceUpdates dataSourceUpdates,

‎pkgs/sdk/server/src/Internal/FDv2DataSources/FDv2StreamingDataSource.cs‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -57,6 +57,11 @@ internal delegate IEventSource EventSourceCreator(Uri streamUri,
5757
private bool _disposed = false;
5858
private readonly AtomicBoolean _shuttingDown = new AtomicBoolean(false);
5959

60+
/// <summary>
61+
/// Returns a string representation of this data source for informational purposes.
62+
/// </summary>
63+
public override string ToString() => "FDv2StreamingDataSource";
64+
6065
internal FDv2StreamingDataSource(
6166
LdClientContext context,
6267
IDataSourceUpdates dataSourceUpdates,

0 commit comments

Comments
 (0)