Skip to content

Commit 8db27a3

Browse files
committed
NCBC-4187: Config versions is sometimes null in logs
Motivation ========== Debug-level logs for KV ops that aren't vBucket-mapped (e.g. GetClusterConfig, Hello) emit "configVersion: null" because op.ConfigVersion is only set in CouchbaseBucket.SendAsync for vBucket ops. The version is still known on the ClusterNode itself via NodesAdapter.ConfigVersion, so the log is unnecessarily lossy. Modification ============ - Added private helper EffectiveConfigVersion(IOperation op) on ClusterNode that returns op.ConfigVersion ?? this.ConfigVersion. - Updated the six KV/circuit-breaker LoggerMessage call sites in ExecuteOp / SendAsyncWithCircuitBreaker to use the helper. - No functional/behavioural change; op.ConfigVersion is unchanged Result ====== GetClusterConfig and other non-vBucket ops now log the node's known configVersion (e.g. "configVersion: 1/874") instead of "null". Change-Id: I791635e885ebd27d1da1baeee07bf3bca6a8644f Reviewed-on: https://review.couchbase.org/c/couchbase-net-client/+/244330 Reviewed-by: Jeffry Morris <jeffrymorris@gmail.com> Tested-by: Build Bot <build@couchbase.com>
1 parent 8999b1b commit 8db27a3

1 file changed

Lines changed: 13 additions & 6 deletions

File tree

src/Couchbase/Core/ClusterNode.cs

Lines changed: 13 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -128,6 +128,13 @@ public ClusterNode(ClusterContext context, ObjectPool<OperationBuilder> operatio
128128
/// </summary>
129129
public ConfigVersion? ConfigVersion => NodesAdapter?.ConfigVersion;
130130

131+
/// <summary>
132+
/// Returns the operation's <see cref="IOperation.ConfigVersion"/> when set, otherwise
133+
/// falls back to this node's current <see cref="ConfigVersion"/>. Used for logging so
134+
/// non-vBucket-mapped operations (e.g. GetClusterConfig, Hello) don't log "null".
135+
/// </summary>
136+
private ConfigVersion? EffectiveConfigVersion(IOperation op) => op.ConfigVersion ?? ConfigVersion;
137+
131138
public bool IsAssigned => Owner != null;
132139

133140
public IBucket Owner
@@ -606,7 +613,7 @@ private Task<ResponseStatus> ExecuteOpImmediatelyAsync(IConnectionPool connectio
606613

607614
private async Task<ResponseStatus> ExecuteOp(Func<IOperation, object, CancellationToken, Task> sender, IOperation op, object state, CancellationTokenPair tokenPair = default)
608615
{
609-
LogKvExecutingOperation(op.OpCode, _redactor.SystemData(EndPoint), _redactor.UserData(op.Key), op.Opaque, op.ConfigVersion);
616+
LogKvExecutingOperation(op.OpCode, _redactor.SystemData(EndPoint), _redactor.UserData(op.Key), op.Opaque, EffectiveConfigVersion(op));
610617
var operationStopwatch = LightweightStopwatch.StartNew();
611618
TimeSpan? operationLatency;
612619
var appTelemetryRequestType = AppTelemetryUtils.GetAppTelemetryKvRequestType(op);
@@ -628,7 +635,7 @@ private async Task<ResponseStatus> ExecuteOp(Func<IOperation, object, Cancellati
628635

629636
if (!status.Failure(op.OpCode))
630637
{
631-
LogKvOperationCompleted(op.OpCode, _redactor.SystemData(EndPoint), _redactor.UserData(op.Key), op.Opaque, op.ConfigVersion);
638+
LogKvOperationCompleted(op.OpCode, _redactor.SystemData(EndPoint), _redactor.UserData(op.Key), op.Opaque, EffectiveConfigVersion(op));
632639

633640
if (appTelemetryRequestType.HasValue)
634641
{
@@ -646,7 +653,7 @@ private async Task<ResponseStatus> ExecuteOp(Func<IOperation, object, Cancellati
646653
return status;
647654
}
648655

649-
LogKvStatusReturned(status, op.OpCode, _redactor.SystemData(EndPoint), _redactor.UserData(op.Key), op.Opaque, op.ConfigVersion);
656+
LogKvStatusReturned(status, op.OpCode, _redactor.SystemData(EndPoint), _redactor.UserData(op.Key), op.Opaque, EffectiveConfigVersion(op));
650657

651658
if (status == ResponseStatus.TransportFailure && op is Hello && ErrorMap == null)
652659
{
@@ -754,7 +761,7 @@ private async Task<ResponseStatus> ExecuteOp(Func<IOperation, object, Cancellati
754761
_logger.LogWarning("KV Operation timed out in ({elapsed}) less than timeout target ({timeout}) for {opaque}", op.Elapsed, op.Timeout, op.Opaque);
755762
}
756763

757-
LogKvOperationTimeout(_redactor.SystemData(EndPoint), op.OpCode, _redactor.UserData(op.Key), op.Opaque, op.ConfigVersion, op.IsSent);
764+
LogKvOperationTimeout(_redactor.SystemData(EndPoint), op.OpCode, _redactor.UserData(op.Key), op.Opaque, EffectiveConfigVersion(op), op.IsSent);
758765
MetricTracker.KeyValue.TrackTimeout(op.OpCode);
759766

760767
if (appTelemetryRequestType.HasValue)
@@ -804,7 +811,7 @@ private async Task<ResponseStatus> ExecuteOp(Func<IOperation, object, Cancellati
804811
}
805812
catch (Exception e)
806813
{
807-
LogKvOperationFailed(e, op.OpCode,_redactor.SystemData(EndPoint),_redactor.UserData(op.Key), op.Opaque, op.Header.Status, op.ConfigVersion);
814+
LogKvOperationFailed(e, op.OpCode,_redactor.SystemData(EndPoint),_redactor.UserData(op.Key), op.Opaque, op.Header.Status, EffectiveConfigVersion(op));
808815

809816
throw;
810817
}
@@ -1045,7 +1052,7 @@ private void UpdateCircuitBreaker(IOperation op, Exception? exception)
10451052
{
10461053
if (_circuitBreaker.CompletionCallback(exception))
10471054
{
1048-
LogCircuitBreakerMarkFailure(op.OpCode,_redactor.SystemData(ConnectionPool.EndPoint), _redactor.SystemData(op.Key), op.Opaque, op.ConfigVersion);
1055+
LogCircuitBreakerMarkFailure(op.OpCode,_redactor.SystemData(ConnectionPool.EndPoint), _redactor.SystemData(op.Key), op.Opaque, EffectiveConfigVersion(op));
10491056

10501057
_circuitBreaker.MarkFailure();
10511058
}

0 commit comments

Comments
 (0)