From 3cb07ae327c0fae240e8e2166ce4f0b78cbca7e2 Mon Sep 17 00:00:00 2001 From: Alex Soffronow-Pagonidis Date: Tue, 25 Aug 2026 13:08:45 +0200 Subject: [PATCH 1/6] =?UTF-8?q?TCP=20P:=20observability=20=E2=80=94=20meta?= =?UTF-8?q?data=20callbacks,=20tracing=20and=20logging?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Surfaces the metadata the server already decoded, adds an ActivitySource with trace-context propagation, and gives the client its own ILogger. The callbacks: ClickHouseTcpQueryOptions.Callbacks takes a ClickHouseTcpQueryCallbacks whose six members are the packet hooks. Progress and ProfileInfo move out of the internal protocol layer as ClickHouseTcpProgress and ClickHouseTcpProfileInfo. Progress counters are increments, so the type carries operator + rather than leaving every caller to find that out; an integration test sums them to an exact row count. Log and ProfileEvents have a schema the server fixes, so both project into owned row structs and no borrowed block reaches a caller who cannot know it is about to be released. Totals and Extremes carry the query's own result shape and stay borrowed blocks. Tracing emits the current stable OpenTelemetry database attributes, not the deprecated set the HTTP transport still uses, and ClientInfo's OpenTelemetry field is no longer a hardcoded has_trace = 0: with an ambient W3C Activity it carries the trace context, so the server's own opentelemetry_span_log rows hang off the caller's trace. The encoding is asymmetric to verify — the integration test requires the server to have recorded a span against the trace id the client sent, because a self-consistent byte-order mistake is invisible to a round trip. Logging covers the client's own lifecycle under ClickHouse.Driver.Tcp.{Client,Connection,Pool}, through source-generated LoggerMessage partials. The two events that matter most are the ones the pool deliberately swallows: a background top-up dial and a sweep both run on a timer with nobody awaiting them, so the logger is the only place either failure is reported. Server log lines are not bridged into ILogger. Re-emitting them is the caller's decision, and nothing the client does turns them on: the server's send_logs_level default is effectively silent, which a test pins. StreamAsync enumerates by hand rather than with await foreach, because a yield cannot sit inside a try that has a catch and a failed query whose span carries no error is the one thing a trace must not do. 3302 tests pass against 26.6 (26.6.3.62) and 3257 against 25.8 (25.8.32.4) — the ends of the CI matrix — with no failures. Co-Authored-By: Claude --- .../Client/ClickHouseTcpClientOptionsTests.cs | 4 + .../Client/ClickHouseTcpProgressTests.cs | 44 +++ .../Client/ConnectionPoolLoggingTests.cs | 197 ++++++++++++ .../Client/MetadataCallbackBridgeTests.cs | 249 +++++++++++++++ .../Diagnostic/ClientOperationTests.cs | 165 ++++++++++ .../Diagnostic/TcpActivityTests.cs | 291 ++++++++++++++++++ .../ClickHouseTcpCallbackIntegrationTests.cs | 264 ++++++++++++++++ .../ClickHouseTcpLoggingIntegrationTests.cs | 152 +++++++++ .../ClickHouseTcpTracingIntegrationTests.cs | 222 +++++++++++++ .../ClickHouseTcpConnectionInsertTests.cs | 2 +- .../ClickHouseTcpConnectionQueryTests.cs | 4 +- .../Protocol/ClientInfoTraceContextTests.cs | 134 ++++++++ .../Protocol/ServerPacketDecoderTests.cs | 6 +- .../Utilities/CapturingLogger.cs | 148 +++++++++ .../Client/ClickHouseTcpClient.cs | 204 +++++++++--- .../Client/ClickHouseTcpClientOptions.cs | 65 +++- .../Client/ClickHouseTcpProfileEvent.cs | 67 ++++ .../ClickHouseTcpProfileInfo.cs} | 16 +- .../Client/ClickHouseTcpProgress.cs | 98 ++++++ .../Client/ClickHouseTcpQueryCallbacks.cs | 61 ++++ .../Client/ClickHouseTcpQueryOptions.cs | 11 + .../Client/ClickHouseTcpServerLogRow.cs | 98 ++++++ .../Client/ConnectionPool.cs | 89 +++++- .../Client/IConnectionFactory.cs | 67 +++- .../Client/MetadataCallbackBridge.cs | 161 ++++++++++ .../Diagnostic/ClickHouseTcpDiagnostics.cs | 38 +++ .../Diagnostic/ClientOperation.cs | 149 +++++++++ .../Diagnostic/TcpActivity.cs | 242 +++++++++++++++ ClickHouse.Driver.Tcp/Logging/ClientLog.cs | 52 ++++ .../Logging/ConnectionLog.cs | 35 +++ ClickHouse.Driver.Tcp/Logging/PoolLog.cs | 64 ++++ .../Protocol/ClickHouseTcpConnection.cs | 4 +- ClickHouse.Driver.Tcp/Protocol/ClientInfo.cs | 44 ++- .../Protocol/MetadataHandlers.cs | 4 +- ClickHouse.Driver.Tcp/Protocol/Progress.cs | 74 ----- 35 files changed, 3369 insertions(+), 156 deletions(-) create mode 100644 ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpProgressTests.cs create mode 100644 ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolLoggingTests.cs create mode 100644 ClickHouse.Driver.Tcp.Tests/Client/MetadataCallbackBridgeTests.cs create mode 100644 ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs create mode 100644 ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs create mode 100644 ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs create mode 100644 ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs create mode 100644 ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpTracingIntegrationTests.cs create mode 100644 ClickHouse.Driver.Tcp.Tests/Protocol/ClientInfoTraceContextTests.cs create mode 100644 ClickHouse.Driver.Tcp.Tests/Utilities/CapturingLogger.cs create mode 100644 ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileEvent.cs rename ClickHouse.Driver.Tcp/{Protocol/ProfileInfo.cs => Client/ClickHouseTcpProfileInfo.cs} (73%) create mode 100644 ClickHouse.Driver.Tcp/Client/ClickHouseTcpProgress.cs create mode 100644 ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs create mode 100644 ClickHouse.Driver.Tcp/Client/ClickHouseTcpServerLogRow.cs create mode 100644 ClickHouse.Driver.Tcp/Client/MetadataCallbackBridge.cs create mode 100644 ClickHouse.Driver.Tcp/Diagnostic/ClickHouseTcpDiagnostics.cs create mode 100644 ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs create mode 100644 ClickHouse.Driver.Tcp/Diagnostic/TcpActivity.cs create mode 100644 ClickHouse.Driver.Tcp/Logging/ClientLog.cs create mode 100644 ClickHouse.Driver.Tcp/Logging/ConnectionLog.cs create mode 100644 ClickHouse.Driver.Tcp/Logging/PoolLog.cs delete mode 100644 ClickHouse.Driver.Tcp/Protocol/Progress.cs diff --git a/ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpClientOptionsTests.cs b/ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpClientOptionsTests.cs index 35bde1e6c..78c13734c 100644 --- a/ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpClientOptionsTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpClientOptionsTests.cs @@ -2,6 +2,7 @@ using System.Collections.Generic; using System.Reflection; using ClickHouse.Driver.Compression; +using Microsoft.Extensions.Logging.Abstractions; namespace ClickHouse.Driver.Tcp.Tests.Client; @@ -470,6 +471,9 @@ public void WithOwnedCustomSettings_CopiesEveryPropertyAndSnapshotsTheSettings() IdleTimeout = TimeSpan.FromSeconds(7), SweepInterval = TimeSpan.FromSeconds(8), PoolReusePolicy = ClickHouseTcpPoolReusePolicy.Fifo, + LoggerFactory = NullLoggerFactory.Instance, + IncludeSqlInActivityTags = true, + StatementMaxLength = 42, // Zstd rather than Lz4 so this stays non-default whichever codec the default becomes. Compressor = ZstdCompressor.Default, diff --git a/ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpProgressTests.cs b/ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpProgressTests.cs new file mode 100644 index 000000000..a97f9c511 --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpProgressTests.cs @@ -0,0 +1,44 @@ +namespace ClickHouse.Driver.Tcp.Tests.Client; + +// The accumulator exists because every consumer of OnProgress has to add the packets up, and a client that made +// them discover that for themselves would have most of them reporting the last step as the total. +[TestFixture] +public class ClickHouseTcpProgressTests +{ + [Test] + public void OperatorPlus_TwoIncrements_SumsEveryCounter() + { + var first = new ClickHouseTcpProgress(rows: 1, bytes: 2, totalRows: 3, wroteRows: 4, wroteBytes: 5, elapsedNs: 6); + var second = new ClickHouseTcpProgress(rows: 10, bytes: 20, totalRows: 30, wroteRows: 40, wroteBytes: 50, elapsedNs: 60); + + ClickHouseTcpProgress total = first + second; + + Assert.Multiple(() => + { + Assert.That(total.Rows, Is.EqualTo(11UL)); + Assert.That(total.Bytes, Is.EqualTo(22UL)); + Assert.That(total.TotalRows, Is.EqualTo(33UL)); + Assert.That(total.WroteRows, Is.EqualTo(44UL)); + Assert.That(total.WroteBytes, Is.EqualTo(55UL)); + Assert.That(total.ElapsedNs, Is.EqualTo(66UL)); + }); + } + + [Test] + public void Add_TwoIncrements_MatchesTheOperator() + { + var first = new ClickHouseTcpProgress(1, 2, 3, 4, 5, 6); + var second = new ClickHouseTcpProgress(10, 20, 30, 40, 50, 60); + + Assert.That(ClickHouseTcpProgress.Add(first, second), Is.EqualTo(first + second)); + } + + [Test] + public void OperatorPlus_DefaultSeed_IsTheIdentity() + { + // So a caller can fold a sequence starting from default without a special first case. + var increment = new ClickHouseTcpProgress(1, 2, 3, 4, 5, 6); + + Assert.That(default(ClickHouseTcpProgress) + increment, Is.EqualTo(increment)); + } +} diff --git a/ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolLoggingTests.cs b/ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolLoggingTests.cs new file mode 100644 index 000000000..5d087f55c --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolLoggingTests.cs @@ -0,0 +1,197 @@ +using System; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using ClickHouse.Driver.Tcp.Client; +using ClickHouse.Driver.Tcp.Logging; +using ClickHouse.Driver.Tcp.Tests.Utilities; +using Microsoft.Extensions.Logging; + +namespace ClickHouse.Driver.Tcp.Tests.Client; + +// What the pool logs, over connections that need no server. Two of these events are reachable no other way: a +// background top-up and a sweep both swallow their exceptions by design, so without a logger a failure in either +// leaves no trace at all and no test could observe it. +[TestFixture] +public class ConnectionPoolLoggingTests +{ + private static readonly CancellationToken None = CancellationToken.None; + + private CapturingLoggerFactory factory; + + [SetUp] + public void CreateFactory() => factory = new CapturingLoggerFactory(); + + [TearDown] + public void DisposeFactory() => factory.Dispose(); + + private CapturingLogger Log => factory.Logger(ClickHouseTcpDiagnostics.PoolLogCategory); + + private ClickHouseTcpClientOptions Options( + int maxPoolSize = 4, + int minPoolSize = 0, + TimeSpan? poolTimeout = null, + TimeSpan? maxConnectionLifetime = null, + TimeSpan? idleTimeout = null) + => new() + { + MaxPoolSize = maxPoolSize, + MinPoolSize = minPoolSize, + PoolTimeout = poolTimeout ?? TimeSpan.FromSeconds(30), + MaxConnectionLifetime = maxConnectionLifetime ?? TimeSpan.FromMinutes(30), + IdleTimeout = idleTimeout ?? TimeSpan.FromMinutes(5), + LoggerFactory = factory, + }; + + [Test] + public async Task RentAsync_NoLoggerFactory_AsksForNoLogger() + { + var connections = new FakeConnectionFactory(); + await using var pool = new ConnectionPool(Options() with { LoggerFactory = null }, connections, new ControlledTimeProvider()); + + await using IConnectionLease lease = await pool.RentAsync(None); + + Assert.That(factory.Categories, Is.Empty, "no factory configured means nothing is created per pool"); + } + + [Test] + public async Task RentAsync_FirstRent_LogsThatItIsOpeningOne() + { + var connections = new FakeConnectionFactory(); + await using var pool = new ConnectionPool(Options(), connections, new ControlledTimeProvider()); + + await using IConnectionLease lease = await pool.RentAsync(None); + + Assert.That(Log.WithEventId(3001), Is.Not.Empty, "no idle connection to reuse"); + } + + [Test] + public async Task RentAsync_AfterALeaseIsReturned_LogsTheReuse() + { + var connections = new FakeConnectionFactory(); + await using var pool = new ConnectionPool(Options(), connections, new ControlledTimeProvider()); + + await using (IConnectionLease first = await pool.RentAsync(None)) + { + } + + await using IConnectionLease second = await pool.RentAsync(None); + + LogEntry reused = Log.WithEventId(3000).Single(); + Assert.Multiple(() => + { + Assert.That(reused.Level, Is.EqualTo(LogLevel.Trace), "a per-operation line belongs at Trace"); + + // The count is this checkout's, so the first reuse is the connection's second operation. Reading it + // before the checkout records itself would report the previous number. + Assert.That(reused.Message, Does.Contain("its 2 operation")); + }); + } + + [Test] + public async Task Return_ConnectionNoLongerUsable_LogsTheDiscard() + { + var connections = new FakeConnectionFactory(); + await using var pool = new ConnectionPool(Options(), connections, new ControlledTimeProvider()); + + await using (IConnectionLease lease = await pool.RentAsync(None)) + { + // A terminated connection is what a failed or abandoned operation leaves behind, and the pool closes + // it on return rather than handing it to the next caller. + lease.Connection.Terminate(); + } + + Assert.That(Log.WithEventId(3002), Is.Not.Empty, "the discard is reported"); + } + + [Test] + public async Task Sweep_IdleConnectionPastItsLifetime_LogsWhatItRetired() + { + var time = new ControlledTimeProvider(); + var connections = new FakeConnectionFactory(); + await using var pool = new ConnectionPool(Options(maxConnectionLifetime: TimeSpan.FromMinutes(1)), connections, time); + + await using (IConnectionLease lease = await pool.RentAsync(None)) + { + } + + time.Advance(TimeSpan.FromMinutes(2)); + pool.Sweep(); + + LogEntry retired = Log.WithEventId(3003).Single(); + Assert.That(retired.Message, Does.Contain("Retired 1")); + } + + [Test] + public async Task Sweep_NothingExpired_LogsNothing() + { + var connections = new FakeConnectionFactory(); + await using var pool = new ConnectionPool(Options(), connections, new ControlledTimeProvider()); + + await using (IConnectionLease lease = await pool.RentAsync(None)) + { + } + + pool.Sweep(); + + Assert.That(Log.WithEventId(3003), Is.Empty, "a sweep that retires nothing is not worth a line"); + } + + [Test] + public async Task RentAsync_PoolExhausted_LogsAWarningBeforeThrowing() + { + var connections = new FakeConnectionFactory(); + await using var pool = new ConnectionPool( + Options(maxPoolSize: 1, poolTimeout: TimeSpan.FromMilliseconds(50)), + connections, + new ControlledTimeProvider()); + + await using IConnectionLease held = await pool.RentAsync(None); + + Assert.ThrowsAsync(async () => await pool.RentAsync(None)); + + LogEntry exhausted = Log.WithEventId(3004).Single(); + Assert.Multiple(() => + { + Assert.That(exhausted.Level, Is.EqualTo(LogLevel.Warning)); + Assert.That(exhausted.Message, Does.Contain("PoolTimeout")); + }); + } + + [Test] + public async Task Sweep_BackgroundTopUpDialFails_LogsTheFailureNobodyElseSees() + { + var time = new ControlledTimeProvider(); + var connections = new FakeConnectionFactory { FailNextWith = new InvalidOperationException("dial refused") }; + await using var pool = new ConnectionPool(Options(minPoolSize: 1), connections, time); + + pool.Sweep(); + if (pool.LastRefill is not null) + { + await pool.LastRefill; + } + + LogEntry failed = Log.WithEventId(3005).Single(); + Assert.Multiple(() => + { + Assert.That(failed.Level, Is.EqualTo(LogLevel.Warning)); + Assert.That(failed.Exception, Is.TypeOf(), "the swallowed exception reaches the log"); + }); + } + + [Test] + public async Task DisposeAsync_OpenPool_LogsTheDrain() + { + var connections = new FakeConnectionFactory(); + var pool = new ConnectionPool(Options(), connections, new ControlledTimeProvider()); + + await using (IConnectionLease lease = await pool.RentAsync(None)) + { + } + + await pool.DisposeAsync(); + + LogEntry draining = Log.WithEventId(3007).Single(); + Assert.That(draining.Message, Does.Contain("closing 1 idle")); + } +} diff --git a/ClickHouse.Driver.Tcp.Tests/Client/MetadataCallbackBridgeTests.cs b/ClickHouse.Driver.Tcp.Tests/Client/MetadataCallbackBridgeTests.cs new file mode 100644 index 000000000..757d799ef --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Client/MetadataCallbackBridgeTests.cs @@ -0,0 +1,249 @@ +using System; +using System.Collections.Generic; +using ClickHouse.Driver.Tcp.Client; +using ClickHouse.Driver.Tcp.Format; +using ClickHouse.Driver.Tcp.Protocol; +using ClickHouse.Driver.Tcp.Types; + +namespace ClickHouse.Driver.Tcp.Tests.Client; + +// What no server round-trip can reach: the null-when-nothing-is-listening contract, the ordering guarantee +// between the client's own observer and the caller's callback, and the schema error paths — a real server always +// sends the schema the projection expects, so only a hand-built block can drive them. The projection of a real +// server's blocks is covered by ClickHouseTcpCallbackIntegrationTests. +[TestFixture] +public class MetadataCallbackBridgeTests +{ + [Test] + public void Build_NothingSet_ReturnsNull() + { + // The read path's null check is then the whole cost of the feature for a caller who asked for nothing. + Assert.That(MetadataCallbackBridge.Build(null), Is.Null); + } + + [Test] + public void Build_EmptyCallbacksObject_ReturnsNull() + { + Assert.That(MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks()), Is.Null); + } + + [Test] + public void Build_OnlyAnInternalObserver_ReturnsHandlersForThatPacketAlone() + { + MetadataHandlers handlers = MetadataCallbackBridge.Build(null, onProgress: _ => { }); + + Assert.That(handlers, Is.Not.Null); + Assert.Multiple(() => + { + Assert.That(handlers.OnProgress, Is.Not.Null); + Assert.That(handlers.OnLog, Is.Null, "an unset callback leaves the packet discarded rather than decoded"); + Assert.That(handlers.OnProfileEvents, Is.Null); + Assert.That(handlers.OnTotals, Is.Null); + }); + } + + [Test] + public void Build_BothObservers_RunsTheClientsBeforeTheCallers() + { + // The documented ordering: a caller's callback that throws must not cost the client the telemetry it + // already had in hand. + var order = new List(); + MetadataHandlers handlers = MetadataCallbackBridge.Build( + new ClickHouseTcpQueryCallbacks { OnProgress = _ => order.Add("caller") }, + onProgress: _ => order.Add("client")); + + handlers.OnProgress(default); + + Assert.That(order, Is.EqualTo(new[] { "client", "caller" })); + } + + [Test] + public void Build_CallerCallbackThrows_TheClientObserverHasAlreadyRun() + { + var seen = new List(); + MetadataHandlers handlers = MetadataCallbackBridge.Build( + new ClickHouseTcpQueryCallbacks { OnProgress = _ => throw new InvalidOperationException("from the caller") }, + onProgress: seen.Add); + + Assert.Throws(() => handlers.OnProgress(new ClickHouseTcpProgress(3, 24, 3, 0, 0, 1))); + + Assert.That(seen, Has.Count.EqualTo(1), "the client's observer ran first, so its count survives the throw"); + Assert.That(seen[0].Rows, Is.EqualTo(3UL)); + } + + [Test] + public void OnLog_WellFormedBlock_ProjectsEveryRow() + { + var rows = new List(); + MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnServerLog = rows.Add }); + + using Block block = LogBlock(priority: 7); + handlers.OnLog(block); + + Assert.That(rows, Has.Count.EqualTo(1)); + Assert.Multiple(() => + { + // 1700000000 seconds plus 500000 microseconds, to the microsecond. + Assert.That(rows[0].EventTime, Is.EqualTo(DateTimeOffset.FromUnixTimeSeconds(1700000000).AddTicks(5000000))); + Assert.That(rows[0].HostName, Is.EqualTo("host-1")); + Assert.That(rows[0].QueryId, Is.EqualTo("query-1")); + Assert.That(rows[0].ThreadId, Is.EqualTo(4242UL)); + Assert.That(rows[0].Level, Is.EqualTo(ClickHouseTcpServerLogLevel.Debug)); + Assert.That(rows[0].Source, Is.EqualTo("executeQuery")); + Assert.That(rows[0].Text, Is.EqualTo("a message")); + }); + } + + [TestCase((sbyte)1, ClickHouseTcpServerLogLevel.Fatal)] + [TestCase((sbyte)8, ClickHouseTcpServerLogLevel.Trace)] + [TestCase((sbyte)9, ClickHouseTcpServerLogLevel.Test)] + [TestCase((sbyte)0, ClickHouseTcpServerLogLevel.Unknown)] + [TestCase((sbyte)10, ClickHouseTcpServerLogLevel.Unknown)] + [TestCase((sbyte)-1, ClickHouseTcpServerLogLevel.Unknown)] + public void OnLog_PriorityOutsideTheKnownRange_DegradesToUnknown(sbyte priority, ClickHouseTcpServerLogLevel expected) + { + // A server that grows a level must not break a caller who only wanted the message text, so an unmapped + // priority is reported rather than refused. No real server sends one, which is why this is a unit test. + var rows = new List(); + MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnServerLog = rows.Add }); + + using Block block = LogBlock(priority); + handlers.OnLog(block); + + Assert.That(rows[0].Level, Is.EqualTo(expected)); + } + + [Test] + public void OnLog_BlockMissingAColumn_ThrowsNamingIt() + { + MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnServerLog = _ => { } }); + + using var block = new Block( + string.Empty, + default, + 1, + new IColumn[] { PrimitiveColumn.FromValues("event_time", "DateTime", [1]) }, + null, + default); + + ClickHouseProtocolException thrown = Assert.Throws(() => handlers.OnLog(block)); + Assert.That(thrown.Message, Does.Contain("event_time_microseconds")); + } + + [Test] + public void OnLog_ColumnOfTheWrongType_ThrowsNamingTheTypeItGot() + { + MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnServerLog = _ => { } }); + + using Block block = LogBlock(priority: 7, threadIdColumn: new ArrayColumn("thread_id", "String", ["not a number"])); + + ClickHouseProtocolException thrown = Assert.Throws(() => handlers.OnLog(block)); + Assert.Multiple(() => + { + Assert.That(thrown.Message, Does.Contain("thread_id")); + Assert.That(thrown.Message, Does.Contain("String")); + }); + } + + [Test] + public void OnProfileEvents_ValueColumnOfAnotherWidth_ThrowsNamingIt() + { + // Every supported server sends Int64, so a different width means the packet is not the one this projects + // and reinterpreting it would report wrong numbers rather than an error. + MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnProfileEvent = _ => { } }); + + using Block block = ProfileEventsBlock(PrimitiveColumn.FromValues("value", "UInt64", [17])); + + ClickHouseProtocolException thrown = Assert.Throws(() => handlers.OnProfileEvents(block)); + Assert.Multiple(() => + { + Assert.That(thrown.Message, Does.Contain("value")); + Assert.That(thrown.Message, Does.Contain("UInt64")); + }); + } + + [Test] + public void OnProfileEvents_WellFormedBlock_ProjectsEveryField() + { + var events = new List(); + MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnProfileEvent = events.Add }); + + using Block block = ProfileEventsBlock(PrimitiveColumn.FromValues("value", "Int64", [99])); + handlers.OnProfileEvents(block); + + Assert.That(events, Has.Count.EqualTo(1)); + Assert.Multiple(() => + { + Assert.That(events[0].CurrentTime, Is.EqualTo(DateTimeOffset.FromUnixTimeSeconds(1700000000))); + Assert.That(events[0].HostName, Is.EqualTo("host-1")); + Assert.That(events[0].ThreadId, Is.EqualTo(4242UL)); + Assert.That(events[0].Type, Is.EqualTo(ClickHouseTcpProfileEventType.Increment)); + Assert.That(events[0].Name, Is.EqualTo("SelectedRows")); + Assert.That(events[0].Value, Is.EqualTo(99L)); + }); + } + + [TestCase((sbyte)2, ClickHouseTcpProfileEventType.Gauge)] + [TestCase((sbyte)0, ClickHouseTcpProfileEventType.Unknown)] + [TestCase((sbyte)3, ClickHouseTcpProfileEventType.Unknown)] + public void OnProfileEvents_TypeOutsideTheKnownRange_DegradesToUnknown(sbyte type, ClickHouseTcpProfileEventType expected) + { + var events = new List(); + MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnProfileEvent = events.Add }); + + using Block block = ProfileEventsBlock(PrimitiveColumn.FromValues("value", "Int64", [1]), type); + handlers.OnProfileEvents(block); + + Assert.That(events[0].Type, Is.EqualTo(expected)); + } + + [Test] + public void OnLog_ZeroRowBlock_InvokesNothing() + { + int calls = 0; + MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnServerLog = _ => calls++ }); + + using Block block = LogBlock(priority: 7, rowCount: 0); + handlers.OnLog(block); + + Assert.That(calls, Is.Zero); + } + + // The server's fixed Log schema, in its documented order. + private static Block LogBlock(sbyte priority, IColumn threadIdColumn = null, int rowCount = 1) + => new( + string.Empty, + default, + rowCount, + new[] + { + PrimitiveColumn.FromValues("event_time", "DateTime", [1700000000]), + PrimitiveColumn.FromValues("event_time_microseconds", "UInt32", [500000]), + new ArrayColumn("host_name", "String", ["host-1"]), + new ArrayColumn("query_id", "String", ["query-1"]), + threadIdColumn ?? PrimitiveColumn.FromValues("thread_id", "UInt64", [4242]), + PrimitiveColumn.FromValues("priority", "Int8", [priority]), + new ArrayColumn("source", "String", ["executeQuery"]), + new ArrayColumn("text", "String", ["a message"]), + }, + null, + default); + + // The server's fixed ProfileEvents schema, in its documented order. + private static Block ProfileEventsBlock(IColumn valueColumn, sbyte type = 1) + => new( + string.Empty, + default, + 1, + new[] + { + new ArrayColumn("host_name", "String", ["host-1"]), + PrimitiveColumn.FromValues("current_time", "DateTime", [1700000000]), + PrimitiveColumn.FromValues("thread_id", "UInt64", [4242]), + PrimitiveColumn.FromValues("type", "Enum8('increment' = 1, 'gauge' = 2)", [type]), + new ArrayColumn("name", "String", ["SelectedRows"]), + valueColumn, + }, + null, + default); +} diff --git a/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs b/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs new file mode 100644 index 000000000..7e08144e2 --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs @@ -0,0 +1,165 @@ +using System.Diagnostics; +using ClickHouse.Driver.Tcp.Diagnostic; +using ClickHouse.Driver.Tcp.Logging; +using ClickHouse.Driver.Tcp.Tests.Utilities; +using Microsoft.Extensions.Logging; + +namespace ClickHouse.Driver.Tcp.Tests.Diagnostic; + +// The zero-cost contract, which nothing else pins: an operation nobody is watching must not be built at all, and +// must not even read the statement's leading keyword — that scan allocates, and it would then be charged to every +// query on an unconfigured client. +[TestFixture] +public class ClientOperationTests +{ + private static readonly ClickHouseTcpClientOptions Options = new(); + + [Test] + public void Start_NoListenerNoLoggerNoCallbacks_ReturnsNull() + { + Assert.That(ClientOperation.Start(Options, logger: null, "SELECT 1", queryId: null, callbacks: null), Is.Null); + } + + [Test] + public void Start_CallbacksOnly_BuildsAnOperationWithHandlersAndNoSpan() + { + using ClientOperation operation = ClientOperation.Start( + Options, + logger: null, + "SELECT 1", + queryId: null, + new ClickHouseTcpQueryCallbacks { OnProgress = _ => { } }); + + Assert.That(operation, Is.Not.Null); + Assert.Multiple(() => + { + Assert.That(operation.Handlers, Is.Not.Null); + Assert.That(Activity.Current, Is.Null, "no listener means no span, callbacks or not"); + }); + } + + [Test] + public void Start_LoggerOnly_AccumulatesTheCountersTheCompletionLineNeeds() + { + // The counters feed the log line as well as the span, so a logger alone has to switch the accumulator on. + // Without it the completion line would report zero rows for every query. + using var factory = new CapturingLoggerFactory(); + CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); + + using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", queryId: null, callbacks: null)) + { + Assert.That(operation, Is.Not.Null); + operation.Handlers.OnProgress(new ClickHouseTcpProgress(4, 32, 4, 0, 0, 1)); + operation.Handlers.OnProgress(new ClickHouseTcpProgress(6, 48, 6, 0, 0, 1)); + operation.Succeeded(); + } + + LogEntry completed = logger.WithEventId(1001)[0]; + Assert.That(completed.Message, Does.Contain("reading 10 rows"), "the increments are summed, not overwritten"); + } + + [Test] + public void Succeeded_WriteCounters_ReportsWhatWasWrittenInsteadOfZeroRowsRead() + { + using var factory = new CapturingLoggerFactory(); + CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); + + using (ClientOperation operation = ClientOperation.Start(Options, logger, "INSERT INTO t VALUES", queryId: null, callbacks: null)) + { + operation.Handlers.OnProgress(new ClickHouseTcpProgress(0, 0, 0, 5, 40, 1)); + operation.Succeeded(); + } + + Assert.Multiple(() => + { + Assert.That(logger.WithEventId(1004), Is.Not.Empty, "an insert reports what it wrote"); + Assert.That(logger.WithEventId(1001), Is.Empty, "and not a read line of zeroes"); + }); + } + + [Test] + public void Dispose_NeitherSucceededNorFailed_ReportsTheOperationAbandoned() + { + using var factory = new CapturingLoggerFactory(); + CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); + + using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", queryId: null, callbacks: null)) + { + } + + Assert.Multiple(() => + { + Assert.That(logger.WithEventId(1003), Is.Not.Empty); + Assert.That(logger.WithEventId(1001), Is.Empty); + }); + } + + [Test] + public void Start_QueryIdSet_PutsItOnTheLogLine() + { + using var factory = new CapturingLoggerFactory(); + CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); + + using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", "my-query-id", callbacks: null)) + { + operation.Succeeded(); + } + + Assert.Multiple(() => + { + Assert.That(logger.WithEventId(1000)[0].Message, Does.Contain("my-query-id")); + Assert.That(logger.WithEventId(1001)[0].Message, Does.Contain("my-query-id"), "the completion line carries it too, concurrent operations not being adjacent in a log"); + }); + } + + [Test] + public void Start_StatementLongerThanTheLimit_TruncatesItInTheLogLine() + { + // The same knob that caps the span attribute, so one setting governs how much statement text leaves the + // client whichever channel it leaves by. + using var factory = new CapturingLoggerFactory(); + CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); + ClickHouseTcpClientOptions options = Options with { StatementMaxLength = 6 }; + + using (ClientOperation operation = ClientOperation.Start(options, logger, "SELECT 'a very long literal'", queryId: null, callbacks: null)) + { + } + + Assert.That(logger.WithEventId(1000)[0].Message, Does.EndWith("SELECT")); + } + + [Test] + public void Start_ZeroStatementMaxLength_KeepsTheStatementOutOfTheLogEntirely() + { + using var factory = new CapturingLoggerFactory(); + CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); + ClickHouseTcpClientOptions options = Options with { StatementMaxLength = 0 }; + + using (ClientOperation operation = ClientOperation.Start(options, logger, "SELECT 'secret'", queryId: null, callbacks: null)) + { + } + + Assert.That(logger.WithEventId(1000)[0].Message, Does.Not.Contain("secret")); + } + + [Test] + public void Failed_Cancellation_IsNotLoggedAsAnError() + { + // A caller cancelling is control flow, not a fault, and an Error line per cancelled query is noise a + // production configuration cannot filter out without losing real failures. + using var factory = new CapturingLoggerFactory(); + CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); + + using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", queryId: null, callbacks: null)) + { + operation.Failed(new System.OperationCanceledException()); + } + + Assert.Multiple(() => + { + Assert.That(logger.WithEventId(1005), Is.Not.Empty, "reported as cancelled"); + Assert.That(logger.WithEventId(1002), Is.Empty, "and not as a failure"); + Assert.That(logger.Entries, Has.None.Matches(e => e.Level == LogLevel.Error)); + }); + } +} diff --git a/ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs b/ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs new file mode 100644 index 000000000..672549a96 --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs @@ -0,0 +1,291 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using ClickHouse.Driver.Tcp.Diagnostic; +using ClickHouse.Driver.Tcp.Protocol; + +namespace ClickHouse.Driver.Tcp.Tests.Diagnostic; + +// The span shape, asserted through an ActivityListener. What a server round-trip cannot reach: which attributes +// are set, the exact attribute names (a renamed one is invisible to a working query), the SQL gating, and the +// error status. +[TestFixture] +public class TcpActivityTests +{ + private static readonly ClickHouseTcpClientOptions Options = new() + { + Host = "example.invalid", + Port = 9123, + Database = "analytics", + Username = "reader", + }; + + private List finished; + private ActivityListener listener; + + [SetUp] + public void Subscribe() + { + finished = []; + listener = new ActivityListener + { + ShouldListenTo = source => source.Name == ClickHouseTcpDiagnostics.ActivitySourceName, + Sample = (ref ActivityCreationOptions o) => ActivitySamplingResult.AllDataAndRecorded, + SampleUsingParentId = (ref ActivityCreationOptions o) => ActivitySamplingResult.AllDataAndRecorded, + ActivityStopped = activity => finished.Add(activity), + }; + ActivitySource.AddActivityListener(listener); + } + + [TearDown] + public void Unsubscribe() => listener.Dispose(); + + [TestCase("SELECT 1", "SELECT")] + [TestCase(" select number FROM numbers(1)", "SELECT")] + [TestCase("INSERT INTO t VALUES", "INSERT")] + [TestCase("WITH x AS (SELECT 1) SELECT * FROM x", "WITH")] + [TestCase("", null)] + [TestCase(" ", null)] + [TestCase(null, null)] + [TestCase("42", null)] + [TestCase("/* comment */ SELECT 1", null)] + [TestCase("SUPERCALIFRAGILISTIC 1", null)] + public void OperationName_Statement_ReadsTheLeadingKeywordOrNothing(string sql, string expected) + => Assert.That(TcpActivity.OperationName(sql), Is.EqualTo(expected)); + + [Test] + public void StartStatement_WithAListener_SetsTheEndpointAttributes() + { + using (Activity activity = TcpActivity.StartStatement(Options, "SELECT 1", "SELECT", queryId: null)) + { + Assert.That(activity, Is.Not.Null); + } + + Activity span = Single(); + Assert.Multiple(() => + { + Assert.That(span.OperationName, Is.EqualTo("SELECT"), "the span is named after the operation"); + Assert.That(span.Kind, Is.EqualTo(ActivityKind.Client)); + Assert.That(span.GetTagItem("db.system.name"), Is.EqualTo("clickhouse")); + Assert.That(span.GetTagItem("db.namespace"), Is.EqualTo("analytics")); + Assert.That(span.GetTagItem("db.operation.name"), Is.EqualTo("SELECT")); + Assert.That(span.GetTagItem("db.user"), Is.EqualTo("reader")); + Assert.That(span.GetTagItem("server.address"), Is.EqualTo("example.invalid")); + Assert.That(span.GetTagItem("server.port"), Is.EqualTo(9123)); + }); + } + + [Test] + public void StartStatement_UnreadableOperationName_NamesTheSpanQueryAndOmitsTheAttribute() + { + TcpActivity.StartStatement(Options, "/* only a comment */", null, queryId: null)?.Dispose(); + + Activity span = Single(); + Assert.Multiple(() => + { + Assert.That(span.OperationName, Is.EqualTo("query")); + Assert.That(span.GetTagItem("db.operation.name"), Is.Null, "no keyword read means no attribute rather than a guess"); + }); + } + + [Test] + public void StartStatement_SqlNotIncluded_OmitsTheQueryText() + { + TcpActivity.StartStatement(Options, "SELECT 'secret'", "SELECT", queryId: null)?.Dispose(); + + Assert.That(Single().GetTagItem("db.query.text"), Is.Null, "the statement is not in a trace by default"); + } + + [Test] + public void StartStatement_SqlIncluded_SetsTheQueryText() + { + ClickHouseTcpClientOptions options = Options with { IncludeSqlInActivityTags = true }; + + TcpActivity.StartStatement(options, "SELECT 1", "SELECT", queryId: null)?.Dispose(); + + Assert.That(Single().GetTagItem("db.query.text"), Is.EqualTo("SELECT 1")); + } + + [Test] + public void StartStatement_SqlLongerThanTheLimit_TruncatesTheQueryText() + { + ClickHouseTcpClientOptions options = Options with { IncludeSqlInActivityTags = true, StatementMaxLength = 6 }; + + TcpActivity.StartStatement(options, "SELECT 1", "SELECT", queryId: null)?.Dispose(); + + Assert.That(Single().GetTagItem("db.query.text"), Is.EqualTo("SELECT")); + } + + [Test] + public void StartStatement_ZeroStatementMaxLength_OmitsTheQueryText() + { + ClickHouseTcpClientOptions options = Options with { IncludeSqlInActivityTags = true, StatementMaxLength = 0 }; + + TcpActivity.StartStatement(options, "SELECT 1", "SELECT", queryId: null)?.Dispose(); + + Assert.That(Single().GetTagItem("db.query.text"), Is.Null); + } + + [Test] + public void StartStatement_QueryIdSet_ReportsItAsAnAttribute() + { + // The join key to the server's own record of the same query. + TcpActivity.StartStatement(Options, "SELECT 1", "SELECT", "my-query-id")?.Dispose(); + + Assert.That(Single().GetTagItem("db.clickhouse.query_id"), Is.EqualTo("my-query-id")); + } + + [Test] + public void StartStatement_NoQueryId_OmitsTheAttribute() + { + // Nothing useful to report: without one the server assigns an id the client never sees. + TcpActivity.StartStatement(Options, "SELECT 1", "SELECT", queryId: null)?.Dispose(); + + Assert.That(Single().GetTagItem("db.clickhouse.query_id"), Is.Null); + } + + [Test] + public void SetProgressTotals_ReadCounters_SetsTheReadAttributesAndOmitsTheWriteOnes() + { + using (Activity activity = TcpActivity.StartStatement(Options, "SELECT 1", "SELECT", queryId: null)) + { + activity.SetProgressTotals(new ClickHouseTcpProgress(rows: 12, bytes: 96, totalRows: 12, wroteRows: 0, wroteBytes: 0, elapsedNs: 5000)); + } + + Activity span = Single(); + Assert.Multiple(() => + { + Assert.That(span.GetTagItem("db.clickhouse.read_rows"), Is.EqualTo(12UL)); + Assert.That(span.GetTagItem("db.clickhouse.read_bytes"), Is.EqualTo(96UL)); + Assert.That(span.GetTagItem("db.clickhouse.elapsed_ns"), Is.EqualTo(5000UL)); + Assert.That(span.GetTagItem("db.clickhouse.written_rows"), Is.Null, "a SELECT writes nothing, so a zero tag would be noise"); + Assert.That(span.GetTagItem("db.clickhouse.written_bytes"), Is.Null); + }); + } + + [Test] + public void SetProgressTotals_WriteCounters_SetsTheWriteAttributes() + { + using (Activity activity = TcpActivity.StartStatement(Options, "INSERT INTO t VALUES", "INSERT", queryId: null)) + { + activity.SetProgressTotals(new ClickHouseTcpProgress(rows: 0, bytes: 0, totalRows: 0, wroteRows: 7, wroteBytes: 56, elapsedNs: 1)); + } + + Activity span = Single(); + Assert.Multiple(() => + { + Assert.That(span.GetTagItem("db.clickhouse.written_rows"), Is.EqualTo(7UL)); + Assert.That(span.GetTagItem("db.clickhouse.written_bytes"), Is.EqualTo(56UL)); + }); + } + + [Test] + public void SetProfileInfo_Summary_SetsTheResultAttributes() + { + using (Activity activity = TcpActivity.StartStatement(Options, "SELECT 1", "SELECT", queryId: null)) + { + activity.SetProfileInfo(new ClickHouseTcpProfileInfo(rows: 3, blocks: 1, bytes: 24, appliedLimit: false, rowsBeforeLimit: 0, calculatedRowsBeforeLimit: false)); + } + + Activity span = Single(); + Assert.Multiple(() => + { + Assert.That(span.GetTagItem("db.clickhouse.result_rows"), Is.EqualTo(3UL)); + Assert.That(span.GetTagItem("db.clickhouse.result_bytes"), Is.EqualTo(24UL)); + }); + } + + [Test] + public void SetSuccess_Completed_SetsTheOkStatus() + { + using (Activity activity = TcpActivity.StartStatement(Options, "SELECT 1", "SELECT", queryId: null)) + { + activity.SetSuccess(); + } + + Assert.That(Single().Status, Is.EqualTo(ActivityStatusCode.Ok)); + } + + [Test] + public void SetError_ServerException_SetsTheErrorStatusAndTheServerErrorCode() + { + var failure = new ClickHouseServerException(60, "UNKNOWN_TABLE", "Table missing", "stack"); + + using (Activity activity = TcpActivity.StartStatement(Options, "SELECT 1", "SELECT", queryId: null)) + { + activity.SetError(failure); + } + + Activity span = Single(); + Assert.Multiple(() => + { + Assert.That(span.Status, Is.EqualTo(ActivityStatusCode.Error)); + Assert.That(span.StatusDescription, Is.EqualTo("Table missing")); + Assert.That(span.GetTagItem("error.type"), Is.EqualTo(typeof(ClickHouseServerException).FullName)); + Assert.That(span.GetTagItem("db.response.status_code"), Is.EqualTo("60"), "the server's own error code"); + }); + } + + [Test] + public void SetError_AnyException_RecordsAnExceptionEvent() + { + var failure = new InvalidOperationException("broken"); + + using (Activity activity = TcpActivity.StartStatement(Options, "SELECT 1", "SELECT", queryId: null)) + { + activity.SetError(failure); + } + + Activity span = Single(); + ActivityEvent recorded = span.Events.Single(); + + Assert.Multiple(() => + { + Assert.That(recorded.Name, Is.EqualTo("exception")); + Assert.That(Tag(recorded, "exception.type"), Is.EqualTo(typeof(InvalidOperationException).FullName)); + Assert.That(Tag(recorded, "exception.message"), Is.EqualTo("broken")); + Assert.That(Tag(recorded, "exception.stacktrace"), Is.Not.Null); + Assert.That(span.GetTagItem("db.response.status_code"), Is.Null, "only a server error carries one"); + }); + } + + [Test] + public void StartPing_WithAListener_NamesTheSpanPingAndSetsTheEndpoint() + { + TcpActivity.StartPing(Options)?.Dispose(); + + Activity span = Single(); + Assert.Multiple(() => + { + Assert.That(span.OperationName, Is.EqualTo("ping")); + Assert.That(span.GetTagItem("server.address"), Is.EqualTo("example.invalid")); + Assert.That(span.GetTagItem("db.operation.name"), Is.Null, "a ping runs no statement"); + }); + } + + [Test] + public void StartConnect_WithAListener_NamesTheSpanConnect() + { + TcpActivity.StartConnect(Options)?.Dispose(); + + Assert.That(Single().OperationName, Is.EqualTo("connect")); + } + + [Test] + public void StartStatement_NoListener_ReturnsNull() + { + listener.Dispose(); + + Assert.That(TcpActivity.StartStatement(Options, "SELECT 1", "SELECT", queryId: null), Is.Null, "nothing listening costs no span"); + } + + private static object Tag(ActivityEvent recorded, string name) + => recorded.Tags.First(tag => tag.Key == name).Value; + + private Activity Single() + { + Assert.That(finished, Has.Count.EqualTo(1), "exactly one span"); + return finished[0]; + } +} diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs new file mode 100644 index 000000000..659de3822 --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs @@ -0,0 +1,264 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using ClickHouse.Driver.Tcp.Format; +using ClickHouse.Driver.Tcp.Types; + +namespace ClickHouse.Driver.Tcp.Tests.Integration; + +// The public callback surface, driven end to end through the client. The connection-level fan-out is covered by +// ClickHouseTcpConnectionMetadataIntegrationTests; what these add is the projection into owned rows and the fact +// that ClickHouseTcpQueryOptions.Callbacks reaches the read path at all. +[TestFixture] +[Category("Integration")] +public class ClickHouseTcpCallbackIntegrationTests +{ + private static readonly CancellationToken None = CancellationToken.None; + + private static async Task DrainAsync(ClickHouseTcpClient client, string sql, ClickHouseTcpQueryOptions options) + { + await foreach (Block block in client.StreamAsync(sql, options, None)) + { + _ = block.RowCount; + } + } + + [Test] + public async Task StreamAsync_OnProgress_ReportsIncrementsThatSumToTheRowsRead() + { + // The decisive test of the documented contract: each packet is an increment, so the sum over a query that + // reads a known number of rows is that number. Were they running totals the sum would be far larger. + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + var increments = new List(); + await DrainAsync( + client, + "SELECT sum(number) FROM numbers(2000000)", + new ClickHouseTcpQueryOptions + { + Callbacks = new ClickHouseTcpQueryCallbacks { OnProgress = increments.Add }, + }); + + ClickHouseTcpProgress total = increments.Aggregate(default(ClickHouseTcpProgress), static (sum, next) => sum + next); + Assert.Multiple(() => + { + Assert.That(increments, Has.Count.GreaterThan(1), "the server reports progress as the query runs, not once at the end"); + Assert.That(total.Rows, Is.EqualTo(2_000_000UL)); + Assert.That(total.Bytes, Is.GreaterThan(0UL)); + }); + } + + [Test] + public async Task StreamAsync_OnProfileInfo_ReportsTheResultRowCount() + { + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + var summaries = new List(); + await DrainAsync( + client, + "SELECT number FROM numbers(10)", + new ClickHouseTcpQueryOptions + { + Callbacks = new ClickHouseTcpQueryCallbacks { OnProfileInfo = summaries.Add }, + }); + + Assert.Multiple(() => + { + Assert.That(summaries, Is.Not.Empty); + Assert.That(summaries[^1].Rows, Is.EqualTo(10UL)); + }); + } + + [Test] + public async Task StreamAsync_OnServerLog_ProjectsTheServerRowsForThisQuery() + { + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + string queryId = Guid.NewGuid().ToString(); + + var rows = new List(); + await DrainAsync( + client, + "SELECT sum(number) FROM numbers(100000)", + new ClickHouseTcpQueryOptions + { + QueryId = queryId, + Settings = new Dictionary { ["send_logs_level"] = "trace" }, + Callbacks = new ClickHouseTcpQueryCallbacks { OnServerLog = rows.Add }, + }); + + Assert.That(rows, Is.Not.Empty, "the server streams trace-level log rows"); + Assert.Multiple(() => + { + Assert.That(rows.Select(r => r.QueryId), Is.All.EqualTo(queryId), "every row belongs to the query that asked for them"); + Assert.That(rows.Select(r => r.Text), Is.All.Not.Empty); + Assert.That(rows.Select(r => r.Level), Is.All.Not.EqualTo(ClickHouseTcpServerLogLevel.Unknown), "the priority column decodes to a known level"); + Assert.That(rows.Select(r => r.Source), Is.All.Not.Null); + Assert.That(rows.Select(r => r.HostName), Is.All.Not.Null); + Assert.That(rows.Select(r => r.EventTime), Is.All.GreaterThan(DateTimeOffset.UnixEpoch), "the two time columns combine into a real instant"); + Assert.That(rows.Any(r => r.ThreadId != 0), "at least one row names its thread"); + }); + } + + [Test] + public async Task StreamAsync_OnServerLog_WithoutSendLogsLevel_ReportsNothing() + { + // The callback alone changes nothing on the wire: the server's default log level is effectively silent, so + // asking for server logs is a two-part act and this is the half the client does not do for you. + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + var rows = new List(); + await DrainAsync( + client, + "SELECT sum(number) FROM numbers(100000)", + new ClickHouseTcpQueryOptions + { + Callbacks = new ClickHouseTcpQueryCallbacks { OnServerLog = rows.Add }, + }); + + Assert.That(rows, Is.Empty); + } + + [Test] + public async Task StreamAsync_OnProfileEvent_ProjectsNamedCounters() + { + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + var events = new List(); + await DrainAsync( + client, + "SELECT sum(number) FROM numbers(100000)", + new ClickHouseTcpQueryOptions + { + Callbacks = new ClickHouseTcpQueryCallbacks { OnProfileEvent = events.Add }, + }); + + Assert.That(events, Is.Not.Empty, "the server sends performance counters"); + Assert.Multiple(() => + { + Assert.That(events.Select(e => e.Name), Is.All.Not.Empty); + Assert.That(events.Select(e => e.Type), Is.All.Not.EqualTo(ClickHouseTcpProfileEventType.Unknown), "the type column decodes to a known kind"); + Assert.That(events.Select(e => e.CurrentTime), Is.All.GreaterThan(DateTimeOffset.UnixEpoch)); + Assert.That(events.Select(e => e.HostName), Is.All.Not.Null); + Assert.That(events.Any(e => e.Name == "SelectedRows"), "a counter every SELECT reports"); + }); + } + + [Test] + public async Task StreamAsync_OnTotals_LendsTheGrandTotalBlock() + { + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + int blocks = 0; + ulong grandTotal = 0; + await DrainAsync( + client, + "SELECT number % 3 AS k, count() AS c FROM numbers(100) GROUP BY k WITH TOTALS", + new ClickHouseTcpQueryOptions + { + Callbacks = new ClickHouseTcpQueryCallbacks + { + OnTotals = block => + { + blocks++; + grandTotal = ((IColumn)block[1]).Values[0]; + }, + }, + }); + + Assert.Multiple(() => + { + Assert.That(blocks, Is.EqualTo(1)); + Assert.That(grandTotal, Is.EqualTo(100UL)); + }); + } + + [Test] + public async Task StreamAsync_OnExtremes_LendsTheMinimumAndMaximumBlock() + { + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + ulong[] extremes = null; + await DrainAsync( + client, + "SELECT number FROM numbers(10)", + new ClickHouseTcpQueryOptions + { + Settings = new Dictionary { ["extremes"] = "1" }, + Callbacks = new ClickHouseTcpQueryCallbacks + { + OnExtremes = block => extremes = ((IColumn)block[0]).Values.ToArray(), + }, + }); + + Assert.That(extremes, Is.EqualTo(new ulong[] { 0, 9 })); + } + + [Test] + public async Task InsertAsync_Callbacks_ReachTheInsertAndReportTheRowsInserted() + { + // Counters rather than progress: the server slices Progress by time, and an insert this small finishes + // before the first slice, so it sends none at all. ProfileEvents it does send, so those are what show the + // callbacks reached the write path. Which counters appear is not asserted — the set differs by server + // version — only that they decode. + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + string table = $"tcp_callback_test_{Guid.NewGuid():N}"; + await client.ExecuteAsync($"CREATE TABLE {table} (id Int32) ENGINE = Memory", cancellationToken: None); + + try + { + var events = new List(); + await client.InsertAsync( + $"INSERT INTO {table} (id) VALUES", + new IColumn[] { PrimitiveColumn.FromValues("id", "Int32", [1, 2, 3, 4, 5]) }, + new ClickHouseTcpInsertOptions + { + Callbacks = new ClickHouseTcpQueryCallbacks { OnProfileEvent = events.Add }, + }, + None); + + List stored = await client.QueryAsync($"SELECT count() FROM {table}", cancellationToken: None).ToListAsync(); + + Assert.That(events, Is.Not.Empty, "the insert path passes the callbacks through"); + Assert.Multiple(() => + { + Assert.That((ulong)stored[0][0], Is.EqualTo(5UL), "observing the insert did not stop it inserting"); + Assert.That(events.Select(e => e.Name), Is.All.Not.Empty); + Assert.That(events.Select(e => e.Type), Is.All.Not.EqualTo(ClickHouseTcpProfileEventType.Unknown)); + }); + } + finally + { + await client.ExecuteAsync($"DROP TABLE IF EXISTS {table}", cancellationToken: None); + } + } + + [Test] + public async Task StreamAsync_ThrowingCallback_PropagatesAndLeavesTheClientUsable() + { + // The documented consequence of a throwing callback: the operation fails and the connection is terminated + // rather than pooled. The client stays usable because the pool redials. + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + var failure = new InvalidOperationException("from the callback"); + + InvalidOperationException thrown = Assert.ThrowsAsync(async () => + await DrainAsync( + client, + "SELECT sum(number) FROM numbers(2000000)", + new ClickHouseTcpQueryOptions + { + Callbacks = new ClickHouseTcpQueryCallbacks { OnProgress = _ => throw failure }, + })); + + Assert.That(thrown, Is.SameAs(failure)); + + long survived = 0; + await foreach (Block block in client.StreamAsync("SELECT 1", cancellationToken: None)) + { + survived = ((IColumn)block[0]).Values[0]; + } + + Assert.That(survived, Is.EqualTo(1)); + } +} diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs new file mode 100644 index 000000000..89606cb52 --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs @@ -0,0 +1,152 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using ClickHouse.Driver.Tcp.Format; +using ClickHouse.Driver.Tcp.Logging; +using ClickHouse.Driver.Tcp.Protocol; +using ClickHouse.Driver.Tcp.Tests.Utilities; +using ClickHouse.Driver.Tcp.Types; +using Microsoft.Extensions.Logging; + +namespace ClickHouse.Driver.Tcp.Tests.Integration; + +// What the client logs while running against a real server. The pool's own messages are unit-tested over fake +// connections in ConnectionPoolLoggingTests; these cover the two categories that need a server to say anything — +// the handshake result, and an operation's outcome and counters. +[TestFixture] +[Category("Integration")] +public class ClickHouseTcpLoggingIntegrationTests +{ + private static readonly CancellationToken None = CancellationToken.None; + + private CapturingLoggerFactory factory; + + [SetUp] + public void CreateFactory() => factory = new CapturingLoggerFactory(); + + [TearDown] + public void DisposeFactory() => factory.Dispose(); + + private CapturingLogger ClientLogger => factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); + + private CapturingLogger ConnectionLogger => factory.Logger(ClickHouseTcpDiagnostics.ConnectionLogCategory); + + private ClickHouseTcpClient CreateClient() + => new(TcpServerFixture.Options() with { LoggerFactory = factory }); + + private static async Task DrainAsync(ClickHouseTcpClient client, string sql) + { + await foreach (Block block in client.StreamAsync(sql, cancellationToken: None)) + { + _ = block.RowCount; + } + } + + [Test] + public async Task StreamAsync_WithALoggerFactory_LogsTheHandshakeResult() + { + await using ClickHouseTcpClient client = CreateClient(); + + await DrainAsync(client, "SELECT 1"); + + Assert.Multiple(() => + { + Assert.That(ConnectionLogger.WithEventId(2000), Is.Not.Empty, "the dial is announced before it is attempted"); + Assert.That(ConnectionLogger.WithEventId(2001).Single().Message, Does.Contain("protocol revision"), "the negotiated revision is worth having in a log"); + }); + } + + [Test] + public async Task StreamAsync_WithALoggerFactory_LogsTheStatementAndItsCounters() + { + await using ClickHouseTcpClient client = CreateClient(); + + await DrainAsync(client, "SELECT sum(number) FROM numbers(1000)"); + + LogEntry started = ClientLogger.WithEventId(1000).Single(); + LogEntry completed = ClientLogger.WithEventId(1001).Single(); + Assert.Multiple(() => + { + Assert.That(started.Level, Is.EqualTo(LogLevel.Debug)); + Assert.That(started.Message, Does.Contain("SELECT sum(number) FROM numbers(1000)")); + Assert.That(completed.Message, Does.Contain("reading 1000 rows"), "the accumulated progress increments, not the last packet"); + Assert.That(completed.Message, Does.Match(@"\d+(\.\d+)? ms")); + }); + } + + [Test] + public async Task StreamAsync_ServerRejectsTheStatement_LogsTheFailureAtError() + { + await using ClickHouseTcpClient client = CreateClient(); + + Assert.ThrowsAsync(async () => await DrainAsync(client, "SELECT * FROM no_such_table_here")); + + LogEntry failed = ClientLogger.WithEventId(1002).Single(); + Assert.Multiple(() => + { + Assert.That(failed.Level, Is.EqualTo(LogLevel.Error)); + Assert.That(failed.Exception, Is.TypeOf()); + Assert.That(ClientLogger.WithEventId(1001), Is.Empty, "a failed statement is not also reported as completed"); + }); + } + + [Test] + public async Task StreamAsync_AbandonedMidResult_LogsThatItWasAbandoned() + { + await using ClickHouseTcpClient client = CreateClient(); + + await foreach (Block block in client.StreamAsync("SELECT number FROM numbers(5000000)", cancellationToken: None)) + { + _ = block.RowCount; + break; + } + + Assert.Multiple(() => + { + Assert.That(ClientLogger.WithEventId(1003), Is.Not.Empty, "an abandoned result is why a connection is discarded rather than reused"); + Assert.That(ClientLogger.WithEventId(1001), Is.Empty); + }); + } + + [Test] + public async Task InsertAsync_WithALoggerFactory_LogsTheInsertAsItsOwnOperation() + { + await using ClickHouseTcpClient client = CreateClient(); + string table = $"tcp_logging_test_{Guid.NewGuid():N}"; + await client.ExecuteAsync($"CREATE TABLE {table} (id Int32) ENGINE = Memory", cancellationToken: None); + + try + { + await client.InsertAsync( + $"INSERT INTO {table} (id) VALUES", + new IColumn[] { PrimitiveColumn.FromValues("id", "Int32", [1, 2, 3]) }, + cancellationToken: None); + + IEnumerable inserts = ClientLogger.WithEventId(1000).Where(e => e.Message.Contains("INSERT", StringComparison.Ordinal)); + Assert.That(inserts, Is.Not.Empty, "the operation name is read from the statement"); + } + finally + { + await client.ExecuteAsync($"DROP TABLE IF EXISTS {table}", cancellationToken: None); + } + } + + [Test] + public async Task StreamAsync_LoggerFactoryBelowDebug_LogsNothingForASuccessfulStatement() + { + // The Debug lines are the chatty ones, and a production configuration at Information should carry none of + // them. The Error line for a failure is not gated this way. + factory.MinimumLevel = LogLevel.Information; + await using ClickHouseTcpClient client = CreateClient(); + + await DrainAsync(client, "SELECT 1"); + + Assert.Multiple(() => + { + Assert.That(ClientLogger.Entries, Is.Empty); + Assert.That(ConnectionLogger.Entries, Is.Empty); + }); + } +} diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpTracingIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpTracingIntegrationTests.cs new file mode 100644 index 000000000..7ae524a6a --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpTracingIntegrationTests.cs @@ -0,0 +1,222 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Linq; +using System.Threading; +using System.Threading.Tasks; +using ClickHouse.Driver.Tcp.Format; +using ClickHouse.Driver.Tcp.Protocol; +using ClickHouse.Driver.Tcp.Types; + +namespace ClickHouse.Driver.Tcp.Tests.Integration; + +// Tracing against a real server. The attribute shapes are unit-tested in TcpActivityTests; what needs a server is +// the half a self-consistent client cannot check on its own — that the trace context the client encodes into +// ClientInfo is the trace id the *server* then records, which is the only thing that proves the two ids' byte +// order rather than merely proving the writer agrees with the reader. +[TestFixture] +[Category("Integration")] +public class ClickHouseTcpTracingIntegrationTests +{ + private static readonly CancellationToken None = CancellationToken.None; + + private List finished; + private ActivityListener listener; + + [SetUp] + public void Subscribe() + { + finished = []; + listener = new ActivityListener + { + ShouldListenTo = source => source.Name == ClickHouseTcpDiagnostics.ActivitySourceName, + Sample = (ref ActivityCreationOptions o) => ActivitySamplingResult.AllDataAndRecorded, + SampleUsingParentId = (ref ActivityCreationOptions o) => ActivitySamplingResult.AllDataAndRecorded, + ActivityStopped = activity => finished.Add(activity), + }; + ActivitySource.AddActivityListener(listener); + } + + [TearDown] + public void Unsubscribe() => listener.Dispose(); + + [Test] + public async Task StreamAsync_WithAListener_ProducesOneSpanCarryingTheServerCounters() + { + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + await foreach (Block block in client.StreamAsync("SELECT sum(number) FROM numbers(500000)", cancellationToken: None)) + { + _ = block.RowCount; + } + + Activity span = finished.Single(a => a.OperationName == "SELECT"); + Assert.Multiple(() => + { + Assert.That(span.Status, Is.EqualTo(ActivityStatusCode.Ok)); + Assert.That(span.GetTagItem("db.clickhouse.read_rows"), Is.EqualTo(500_000UL), "the accumulated progress increments"); + Assert.That(span.GetTagItem("db.clickhouse.result_rows"), Is.EqualTo(1UL), "one aggregate row"); + Assert.That(span.GetTagItem("server.address"), Is.EqualTo(TcpServerFixture.Host)); + Assert.That(span.Duration, Is.GreaterThan(TimeSpan.Zero)); + }); + } + + [Test] + public async Task StreamAsync_ServerRejectsTheStatement_MarksTheSpanFailedWithTheServerErrorCode() + { + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + Assert.ThrowsAsync(async () => + { + await foreach (Block block in client.StreamAsync("SELECT * FROM no_such_table_here", cancellationToken: None)) + { + _ = block.RowCount; + } + }); + + Activity span = finished.Single(a => a.OperationName == "SELECT"); + Assert.Multiple(() => + { + Assert.That(span.Status, Is.EqualTo(ActivityStatusCode.Error)); + Assert.That(span.GetTagItem("error.type"), Is.EqualTo(typeof(ClickHouseServerException).FullName)); + Assert.That(span.GetTagItem("db.response.status_code"), Is.Not.Null, "the server's error code reaches the span"); + Assert.That(span.Events.Any(e => e.Name == "exception")); + }); + } + + [Test] + public async Task StreamAsync_AbandonedMidResult_LeavesTheSpanWithoutAStatus() + { + // Breaking out of the loop is neither success nor failure, and reporting either would be a claim the + // client cannot make about a result the caller stopped reading. + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + await foreach (Block block in client.StreamAsync("SELECT number FROM numbers(5000000)", cancellationToken: None)) + { + _ = block.RowCount; + break; + } + + Activity span = finished.Single(a => a.OperationName == "SELECT"); + Assert.That(span.Status, Is.EqualTo(ActivityStatusCode.Unset)); + } + + [Test] + public async Task PingAsync_WithAListener_ProducesAPingSpan() + { + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + await client.PingAsync(None); + + Assert.That(finished.Any(a => a.OperationName == "ping" && a.Status == ActivityStatusCode.Ok)); + } + + [Test] + public async Task PingAsync_FirstOperationOnANewClient_ProducesAConnectSpan() + { + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + await client.PingAsync(None); + + Activity connect = finished.Single(a => a.OperationName == "connect"); + Assert.Multiple(() => + { + Assert.That(connect.Status, Is.EqualTo(ActivityStatusCode.Ok)); + Assert.That(connect.GetTagItem("server.port"), Is.EqualTo(TcpServerFixture.Port)); + }); + } + + [Test] + public async Task StreamAsync_UnderARecordedSpan_SendsATraceContextTheServerRecordsAgainstTheSameTraceId() + { + // The end-to-end proof of the ClientInfo trace-context encoding. The server decodes trace_id as a UUID and + // writes its own spans against it, so finding our trace id in system.opentelemetry_span_log means the two + // byte-swapped halves and the little-endian span id were all read the way we wrote them. Getting the order + // wrong yields a different, self-consistent trace id here and no matching row. + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + var options = new ClickHouseTcpQueryOptions + { + Settings = new Dictionary { ["opentelemetry_start_trace_probability"] = "1" }, + }; + + // Cleared so the one SELECT span below is the probe query's, not this fixture's earlier spans. + finished.Clear(); + await foreach (Block block in client.StreamAsync("SELECT sum(number) FROM numbers(1000)", options, None)) + { + _ = block.RowCount; + } + + // The span the Query packet's trace-context field was written from: it is the ambient activity inside the + // iterator, where the packet is encoded. + string traceId = finished.Single(a => a.OperationName == "SELECT").TraceId.ToHexString(); + + ulong spans = await CountServerSpansAsync(client, traceId); + if (spans == 0 && !await SpanLogExistsAsync(client)) + { + // The table is created on demand, the first time the server records a span, so it can only be + // checked for after the query above — not before it. + Assert.Ignore("system.opentelemetry_span_log is not configured on this server."); + } + + Assert.That(spans, Is.GreaterThan(0UL), $"the server recorded no span against trace id {traceId}"); + } + + [Test] + public async Task StreamAsync_WithNoListener_SendsNoTraceContextAndStillRuns() + { + // Nothing listening means no ambient span, so the trace-context field takes its absent form. The query has + // to run exactly as before — a regression here would break every query, not just a traced one. + listener.Dispose(); + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + + ulong value = 0; + await foreach (Block block in client.StreamAsync("SELECT sum(number) FROM numbers(10)", cancellationToken: None)) + { + value = ((IColumn)block[0]).Values[0]; + } + + Assert.Multiple(() => + { + Assert.That(value, Is.EqualTo(45UL)); + Assert.That(finished, Is.Empty, "no listener, no spans"); + }); + } + + private static async Task SpanLogExistsAsync(ClickHouseTcpClient client) + { + List rows = await client + .QueryAsync("SELECT count() FROM system.tables WHERE database = 'system' AND name = 'opentelemetry_span_log'", cancellationToken: None) + .ToListAsync(); + return (ulong)rows[0][0] != 0; + } + + // A span's log row is queued independently of the query's response reaching us, so a flush issued right after + // can miss it. Retried rather than slept on, and reported as zero only after the last attempt. + private static async Task CountServerSpansAsync(ClickHouseTcpClient client, string traceIdHex) + { + string uuid = $"{traceIdHex[..8]}-{traceIdHex[8..12]}-{traceIdHex[12..16]}-{traceIdHex[16..20]}-{traceIdHex[20..]}"; + for (int attempt = 0; attempt < 5; attempt++) + { + await client.ExecuteAsync("SYSTEM FLUSH LOGS", cancellationToken: None); + if (!await SpanLogExistsAsync(client)) + { + await Task.Delay(TimeSpan.FromMilliseconds(200), None); + continue; + } + + List rows = await client + .QueryAsync($"SELECT count() FROM system.opentelemetry_span_log WHERE trace_id = toUUID('{uuid}')", cancellationToken: None) + .ToListAsync(); + var count = (ulong)rows[0][0]; + if (count != 0) + { + return count; + } + + await Task.Delay(TimeSpan.FromMilliseconds(200), None); + } + + return 0; + } +} diff --git a/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionInsertTests.cs b/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionInsertTests.cs index 2beb98371..e588410e1 100644 --- a/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionInsertTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionInsertTests.cs @@ -64,7 +64,7 @@ await ProgressPacketAsync(), EndOfStreamPacket()); using var connection = await ConnectedAsync(script); - var progresses = new List(); + var progresses = new List(); await connection.InsertAsync( "INSERT INTO t VALUES", Columns(UInt64Column(1, 2, 3)), diff --git a/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionQueryTests.cs b/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionQueryTests.cs index 98c124069..dc39dd24d 100644 --- a/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionQueryTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionQueryTests.cs @@ -271,7 +271,7 @@ await ProgressPacketAsync(), EndOfStreamPacket()); using var connection = await ConnectedAsync(script); - var progresses = new List(); + var progresses = new List(); await DrainAsync(connection, new MetadataHandlers { OnProgress = progresses.Add }); Assert.Multiple(() => @@ -294,7 +294,7 @@ await DataPacketAsync(new ulong[] { 5 }), EndOfStreamPacket()); using var connection = await ConnectedAsync(script); - var captured = new List(); + var captured = new List(); await DrainAsync(connection, new MetadataHandlers { OnProfileInfo = captured.Add }); Assert.Multiple(() => diff --git a/ClickHouse.Driver.Tcp.Tests/Protocol/ClientInfoTraceContextTests.cs b/ClickHouse.Driver.Tcp.Tests/Protocol/ClientInfoTraceContextTests.cs new file mode 100644 index 000000000..655637ea0 --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Protocol/ClientInfoTraceContextTests.cs @@ -0,0 +1,134 @@ +using System; +using System.Buffers.Binary; +using System.Diagnostics; +using System.Globalization; +using System.IO; +using System.Threading; +using System.Threading.Tasks; +using ClickHouse.Driver.Tcp.Protocol; + +namespace ClickHouse.Driver.Tcp.Tests.Protocol; + +// The OpenTelemetry field of ClientInfo, asserted byte-for-byte. Only a unit test can pin the encoding: a server +// round-trip proves the server accepted *something*, and the byte order of the two ids is exactly what a +// self-consistent client would get wrong invisibly. The end-to-end check that the server reads the same trace id +// we sent lives in ClickHouseTcpTracingIntegrationTests. +[TestFixture] +public class ClientInfoTraceContextTests +{ + // Chosen so every byte is distinct: a reversal, a half-swap and a straight copy all produce different output. + private const string TraceIdHex = "000102030405060708090a0b0c0d0e0f"; + + private static readonly CancellationToken None = CancellationToken.None; + + [Test] + public async Task WriteTraceContext_NoActivity_WritesTheAbsentForm() + { + byte[] written = await WriteAsync(null); + + Assert.That(written, Is.EqualTo(new byte[] { 0 }), "has_trace = 0 and nothing after it"); + } + + [Test] + public async Task WriteTraceContext_HierarchicalActivity_WritesTheAbsentForm() + { + // A hierarchical id has no trace id to send, so there is nothing to propagate even though a span exists. + using var activity = new Activity("test"); + activity.SetIdFormat(ActivityIdFormat.Hierarchical); + activity.Start(); + + byte[] written = await WriteAsync(activity); + + Assert.That(written, Is.EqualTo(new byte[] { 0 })); + } + + [Test] + public async Task WriteTraceContext_W3CActivity_WritesEachTraceIdHalfLittleEndian() + { + using Activity activity = StartW3C(traceState: null); + + byte[] written = await WriteAsync(activity); + + // The trace id is a UUID on the wire: the high half then the low half, each little-endian. So the 16 + // big-endian W3C bytes 00..0f come back as two separately reversed runs. + Assert.That( + written[1..17], + Is.EqualTo(new byte[] { 0x07, 0x06, 0x05, 0x04, 0x03, 0x02, 0x01, 0x00, 0x0F, 0x0E, 0x0D, 0x0C, 0x0B, 0x0A, 0x09, 0x08 })); + Assert.That(written[0], Is.EqualTo(1), "has_trace = 1"); + } + + [Test] + public async Task WriteTraceContext_W3CActivity_WritesSpanIdAsLittleEndianUInt64() + { + using Activity activity = StartW3C(traceState: null); + + byte[] written = await WriteAsync(activity); + + // Read back as the UInt64 the server decodes, and compared against the hex id read as one big-endian + // number — an independent formulation of the same claim, rather than a copy of the writer's steps. + ulong onWire = BinaryPrimitives.ReadUInt64LittleEndian(written[17..25]); + ulong expected = ulong.Parse(activity.SpanId.ToHexString(), NumberStyles.HexNumber, CultureInfo.InvariantCulture); + + Assert.That(onWire, Is.EqualTo(expected)); + } + + [Test] + public async Task WriteTraceContext_W3CActivityWithTraceState_WritesStateThenFlags() + { + using Activity activity = StartW3C(traceState: "vendor=abc"); + + byte[] written = await WriteAsync(activity); + + // A length-prefixed string, then the flags byte. Recorded is 1. + Assert.Multiple(() => + { + Assert.That(written[25], Is.EqualTo(10), "the trace state's length prefix"); + Assert.That(System.Text.Encoding.UTF8.GetString(written[26..36]), Is.EqualTo("vendor=abc")); + Assert.That(written[36], Is.EqualTo((byte)ActivityTraceFlags.Recorded)); + Assert.That(written, Has.Length.EqualTo(37), "nothing follows the flags"); + }); + } + + [Test] + public async Task WriteTraceContext_W3CActivityWithoutTraceState_WritesAnEmptyString() + { + using Activity activity = StartW3C(traceState: null); + + byte[] written = await WriteAsync(activity); + + Assert.Multiple(() => + { + Assert.That(written[25], Is.EqualTo(0), "an empty trace state is a zero length prefix"); + Assert.That(written, Has.Length.EqualTo(27)); + }); + } + + private static Activity StartW3C(string traceState) + { + var activity = new Activity("test"); + activity.SetIdFormat(ActivityIdFormat.W3C); + activity.SetParentId( + ActivityTraceId.CreateFromString(TraceIdHex), + ActivitySpanId.CreateFromString("1011121314151617"), + ActivityTraceFlags.Recorded); + if (traceState is not null) + { + activity.TraceStateString = traceState; + } + + activity.Start(); + return activity; + } + + private static async Task WriteAsync(Activity activity) + { + using var stream = new MemoryStream(); + using (var writer = new ClickHouseBinaryWriter(stream)) + { + ClientInfo.WriteTraceContext(writer, activity); + await writer.FlushAsync(None); + } + + return stream.ToArray(); + } +} diff --git a/ClickHouse.Driver.Tcp.Tests/Protocol/ServerPacketDecoderTests.cs b/ClickHouse.Driver.Tcp.Tests/Protocol/ServerPacketDecoderTests.cs index 8e09b69fa..bb3a5a9ba 100644 --- a/ClickHouse.Driver.Tcp.Tests/Protocol/ServerPacketDecoderTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Protocol/ServerPacketDecoderTests.cs @@ -25,7 +25,7 @@ public async Task Progress_AtCurrentTarget_ReadsAllGatedCounters() }); using var reader = ReaderOver(bytes); - Progress progress = await Progress.ReadAsync(reader, new NegotiatedProtocol(NegotiatedProtocol.ClientTcpProtocolVersion), None); + ClickHouseTcpProgress progress = await ClickHouseTcpProgress.ReadAsync(reader, new NegotiatedProtocol(NegotiatedProtocol.ClientTcpProtocolVersion), None); Assert.Multiple(() => { @@ -50,7 +50,7 @@ public async Task Progress_BelowWriteInfoGate_ReadsOnlyBaseCounters() using var reader = ReaderOver(bytes); // A server negotiating below 54420 sends no wrote_rows/wrote_bytes/elapsed_ns. - Progress progress = await Progress.ReadAsync(reader, new NegotiatedProtocol(54419), None); + ClickHouseTcpProgress progress = await ClickHouseTcpProgress.ReadAsync(reader, new NegotiatedProtocol(54419), None); Assert.Multiple(() => { @@ -74,7 +74,7 @@ public async Task ProfileInfo_RoundTrips() }); using var reader = ReaderOver(bytes); - ProfileInfo info = await ProfileInfo.ReadAsync(reader, None); + ClickHouseTcpProfileInfo info = await ClickHouseTcpProfileInfo.ReadAsync(reader, None); Assert.Multiple(() => { diff --git a/ClickHouse.Driver.Tcp.Tests/Utilities/CapturingLogger.cs b/ClickHouse.Driver.Tcp.Tests/Utilities/CapturingLogger.cs new file mode 100644 index 000000000..d64988cc5 --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Utilities/CapturingLogger.cs @@ -0,0 +1,148 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using Microsoft.Extensions.Logging; + +namespace ClickHouse.Driver.Tcp.Tests.Utilities; + +/// One captured log line, with the message already formatted. +internal sealed class LogEntry +{ + public LogLevel Level { get; init; } + + public EventId EventId { get; init; } + + public string Message { get; init; } + + public Exception Exception { get; init; } + + public override string ToString() => $"{Level} [{EventId.Id}] {Message}"; +} + +/// Records everything written to it, for a test to assert against. +internal sealed class CapturingLogger : ILogger +{ + private readonly List entries = []; + private readonly object gate = new(); + + /// The lowest level this logger reports as enabled. + public LogLevel MinimumLevel { get; set; } = LogLevel.Trace; + + /// A snapshot of what has been logged so far. + public IReadOnlyList Entries + { + get + { + lock (gate) + { + return entries.ToArray(); + } + } + } + + public IDisposable BeginScope(TState state) + where TState : notnull + => NullScope.Instance; + + public bool IsEnabled(LogLevel logLevel) => logLevel >= MinimumLevel && logLevel != LogLevel.None; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + if (!IsEnabled(logLevel)) + { + return; + } + + var entry = new LogEntry + { + Level = logLevel, + EventId = eventId, + Message = formatter(state, exception), + Exception = exception, + }; + + lock (gate) + { + entries.Add(entry); + } + } + + /// The entries with this event id. + /// The event id to match. + /// The matching entries, in order. + public IReadOnlyList WithEventId(int eventId) => Entries.Where(e => e.EventId.Id == eventId).ToArray(); + + private sealed class NullScope : IDisposable + { + public static readonly NullScope Instance = new(); + + public void Dispose() + { + } + } +} + +/// +/// Hands out a per category, so a test can assert both what was logged and which +/// category it went to. +/// +internal sealed class CapturingLoggerFactory : ILoggerFactory +{ + private readonly Dictionary loggers = new(StringComparer.Ordinal); + private readonly object gate = new(); + private LogLevel minimumLevel = LogLevel.Trace; + + /// The lowest level every logger, existing and future, reports as enabled. + public LogLevel MinimumLevel + { + get => minimumLevel; + set + { + lock (gate) + { + minimumLevel = value; + foreach (CapturingLogger logger in loggers.Values) + { + logger.MinimumLevel = value; + } + } + } + } + + /// The logger for a category, creating it if the client has not asked for it yet. + /// The category name. + /// The capturing logger for that category. + public CapturingLogger Logger(string categoryName) + { + lock (gate) + { + if (!loggers.TryGetValue(categoryName, out CapturingLogger logger)) + { + logger = new CapturingLogger { MinimumLevel = minimumLevel }; + loggers.Add(categoryName, logger); + } + + return logger; + } + } + + /// The categories the client has asked for a logger for. + public IReadOnlyCollection Categories + { + get + { + lock (gate) + { + return loggers.Keys.ToArray(); + } + } + } + + ILogger ILoggerFactory.CreateLogger(string categoryName) => Logger(categoryName); + + public void AddProvider(ILoggerProvider provider) => throw new NotSupportedException(); + + public void Dispose() + { + } +} diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs index 2323f9028..b2302600f 100644 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs @@ -1,15 +1,20 @@ using System; using System.Buffers; using System.Collections.Generic; +using System.Diagnostics; using System.Diagnostics.CodeAnalysis; using System.Runtime.CompilerServices; using System.Threading; using System.Threading.Tasks; using ClickHouse.Driver.Tcp.Client; +using ClickHouse.Driver.Tcp.Diagnostic; using ClickHouse.Driver.Tcp.Format; +using ClickHouse.Driver.Tcp.Logging; using ClickHouse.Driver.Tcp.Parameters; using ClickHouse.Driver.Tcp.Poco; +using ClickHouse.Driver.Tcp.Protocol; using ClickHouse.Driver.Tcp.Types; +using Microsoft.Extensions.Logging; namespace ClickHouse.Driver.Tcp; @@ -67,6 +72,7 @@ public sealed class ClickHouseTcpClient : IClickHouseTcpClient private static readonly ClickHouseTcpInsertOptions DefaultInsertOptions = new(); private readonly IConnectionSource source; + private readonly ILogger logger; /// Creates a client from options. /// The client configuration (endpoint, credentials, timeouts, client-level settings). @@ -77,6 +83,7 @@ public ClickHouseTcpClient(ClickHouseTcpClientOptions options) ArgumentNullException.ThrowIfNull(options); options.Validate(); Options = options.WithOwnedCustomSettings(); + logger = Options.LoggerFactory?.CreateLogger(ClickHouseTcpDiagnostics.ClientLogCategory); source = new ConnectionPool(Options); } @@ -105,6 +112,7 @@ internal ClickHouseTcpClient( this.source = source; ClickHouseTcpClientOptions resolved = options ?? new ClickHouseTcpClientOptions(); Options = optionsAreOwned ? resolved : resolved.WithOwnedCustomSettings(); + logger = Options.LoggerFactory?.CreateLogger(ClickHouseTcpDiagnostics.ClientLogCategory); } /// @@ -149,24 +157,86 @@ public async IAsyncEnumerable StreamAsync( IReadOnlyDictionary parameters = BuildParameters(sql, options); string queryId = options?.QueryId; - IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); + // Started before the rent, so the span covers waiting for a connection, and so the Query packet's + // trace-context field picks it up from Activity.Current. + ClientOperation operation = ClientOperation.Start(Options, logger, sql, queryId, options?.Callbacks); + IConnectionLease lease = null; + IAsyncEnumerator blocks = null; try { - // The connection's own enumerator owns each block's storage and, in its finally, returns the - // connection to Ready or terminates it. We pass the blocks straight through without disposing them. - await foreach (Block block in lease.Connection - .QueryAsync(sql, settings, parameters, queryId, handlers: null, cancellationToken) - .ConfigureAwait(false)) + try + { + lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); + + // The connection's own enumerator owns each block's storage and, in its finally, returns the + // connection to Ready or terminates it. We pass the blocks straight through without disposing them. + // Enumerated by hand rather than with `await foreach` because a yield cannot sit inside a try that + // has a catch, and a failed query whose span carries no error is the one thing a trace must not do. + blocks = lease.Connection + .QueryAsync(sql, settings, parameters, queryId, operation?.Handlers, cancellationToken) + .GetAsyncEnumerator(cancellationToken); + } + catch (Exception e) + { + operation?.Failed(e); + throw; + } + + while (true) { + Block block; + try + { + if (!await blocks.MoveNextAsync().ConfigureAwait(false)) + { + break; + } + + block = blocks.Current; + } + catch (Exception e) + { + operation?.Failed(e); + throw; + } + yield return block; } + + operation?.Succeeded(); } finally { - // Runs on natural completion, early break / enumerator disposal (which cascades disposal into the - // inner iterator so its finally runs first), and exceptions. Disposing the lease returns the - // connection to the source exactly once; the source reuses it if Ready or redials if terminated. - await lease.DisposeAsync().ConfigureAwait(false); + // Runs on natural completion, early break / enumerator disposal, and exceptions. Disposing the + // enumerator first settles the connection to Ready or terminated; disposing the lease then returns it + // to the source exactly once, which reuses it if Ready or redials if terminated. + // + // Nested, not three statements in a row: the enumerator's own disposal closes a socket and returns + // pooled buffers, none of which is guaranteed not to throw, and a throw there must not cost the pool + // the lease's permit for the rest of the client's life. + try + { + if (blocks is not null) + { + await blocks.DisposeAsync().ConfigureAwait(false); + } + } + finally + { + try + { + if (lease is not null) + { + await lease.DisposeAsync().ConfigureAwait(false); + } + } + finally + { + // Also the path an abandoned enumeration takes, where the span ends with no status at all: + // neither successful nor failed is the honest report of a result the caller stopped reading. + operation?.Dispose(); + } + } } } @@ -317,17 +387,27 @@ public async ValueTask InsertAsync( IReadOnlyDictionary settings = BuildSettings(options); IReadOnlyDictionary parameters = BuildParameters(sql, options); - await using IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); - await lease.Connection.InsertAsync( - sql, - columns, - settings, - parameters, - options?.QueryId, - ResolveMaxRowsPerBlock(options), - Options.MaxSendBufferBytes, - handlers: null, - cancellationToken).ConfigureAwait(false); + using ClientOperation operation = ClientOperation.Start(Options, logger, sql, options?.QueryId, options?.Callbacks); + try + { + await using IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); + await lease.Connection.InsertAsync( + sql, + columns, + settings, + parameters, + options?.QueryId, + ResolveMaxRowsPerBlock(options), + Options.MaxSendBufferBytes, + operation?.Handlers, + cancellationToken).ConfigureAwait(false); + operation?.Succeeded(); + } + catch (Exception e) + { + operation?.Failed(e); + throw; + } } /// @@ -354,18 +434,28 @@ public async ValueTask InsertRowsAsync( using var buffer = PocoRowBuffer.Create(rows, nameof(rows), cancellationToken); - await using IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); - await lease.Connection.InsertAsync( - sql, - buffer.Count, - schema => PocoTypes.WritePlanFor(schema).BuildColumns(buffer.Rows, buffer.Count), - settings, - parameters, - options?.QueryId, - ResolveMaxRowsPerBlock(options), - Options.MaxSendBufferBytes, - handlers: null, - cancellationToken).ConfigureAwait(false); + using ClientOperation operation = ClientOperation.Start(Options, logger, sql, options?.QueryId, options?.Callbacks); + try + { + await using IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); + await lease.Connection.InsertAsync( + sql, + buffer.Count, + schema => PocoTypes.WritePlanFor(schema).BuildColumns(buffer.Rows, buffer.Count), + settings, + parameters, + options?.QueryId, + ResolveMaxRowsPerBlock(options), + Options.MaxSendBufferBytes, + operation?.Handlers, + cancellationToken).ConfigureAwait(false); + operation?.Succeeded(); + } + catch (Exception e) + { + operation?.Failed(e); + throw; + } } /// @@ -382,18 +472,28 @@ public async ValueTask InsertRowsAsync( IReadOnlyDictionary parameters = BuildParameters(sql, options); using var buffer = PocoRowBuffer.Create(rows, nameof(rows), cancellationToken); - await using IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); - await lease.Connection.InsertAsync( - sql, - buffer.Count, - schema => UntypedRowColumns.Build(schema, buffer.Rows, buffer.Count), - settings, - parameters, - options?.QueryId, - ResolveMaxRowsPerBlock(options), - Options.MaxSendBufferBytes, - handlers: null, - cancellationToken).ConfigureAwait(false); + using ClientOperation operation = ClientOperation.Start(Options, logger, sql, options?.QueryId, options?.Callbacks); + try + { + await using IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); + await lease.Connection.InsertAsync( + sql, + buffer.Count, + schema => UntypedRowColumns.Build(schema, buffer.Rows, buffer.Count), + settings, + parameters, + options?.QueryId, + ResolveMaxRowsPerBlock(options), + Options.MaxSendBufferBytes, + operation?.Handlers, + cancellationToken).ConfigureAwait(false); + operation?.Succeeded(); + } + catch (Exception e) + { + operation?.Failed(e); + throw; + } } /// @@ -458,8 +558,18 @@ public async ValueTask OpenSessionAsync(CancellationToken /// A task that completes when the server answers. public async ValueTask PingAsync(CancellationToken cancellationToken = default) { - await using IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); - await lease.Connection.PingAsync(cancellationToken).ConfigureAwait(false); + using Activity activity = TcpActivity.StartPing(Options); + try + { + await using IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); + await lease.Connection.PingAsync(cancellationToken).ConfigureAwait(false); + activity?.SetSuccess(); + } + catch (Exception e) + { + activity?.SetError(e); + throw; + } } /// diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs index 7a73361d6..5f7147d23 100644 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs @@ -3,6 +3,7 @@ using System.Net.Security; using ClickHouse.Driver.Compression; using ClickHouse.Driver.Tcp.Protocol; +using Microsoft.Extensions.Logging; namespace ClickHouse.Driver.Tcp; @@ -12,11 +13,11 @@ namespace ClickHouse.Driver.Tcp; /// , or derive a variant of an existing instance with a with expression. /// /// -/// Being a record, two instances compare equal when every property does. and -/// are compared by reference, not by content: the first is an interface with no -/// value-equality contract, the second a delegate. Two options that hold equal-but-distinct dictionaries, or -/// equivalent-but-distinct lambdas, are not equal. Do not use these options as a cache or pool key; use a -/// purpose-built key type. +/// Being a record, two instances compare equal when every property does. , +/// , and are compared by +/// reference, not by content: the first three are interfaces with no value-equality contract, the last a +/// delegate. Two options that hold equal-but-distinct dictionaries, or equivalent-but-distinct lambdas, are +/// not equal. Do not use these options as a cache or pool key; use a purpose-built key type. /// public sealed record ClickHouseTcpClientOptions { @@ -29,6 +30,7 @@ public sealed record ClickHouseTcpClientOptions internal const int DefaultMinPoolSize = 0; internal const int DefaultMaxPoolSize = 20; internal const ClickHouseTcpPoolReusePolicy DefaultPoolReusePolicy = ClickHouseTcpPoolReusePolicy.Lifo; + internal const int DefaultStatementMaxLength = 300; /// /// The Compression connection-string value used when the key is absent. LZ4 is what @@ -285,6 +287,43 @@ public sealed record ClickHouseTcpClientOptions /// public IClickHouseCompressor Compressor { get; init; } = ResolveCompressor(DefaultCompression); + /// + /// Where the client gets its loggers, or null to log nothing. Cannot be set from a connection string. + /// + /// + /// + /// The client logs its own lifecycle — connects, handshakes, pool checkouts and retirements, operation + /// outcomes — under the ClickHouse.Driver.Tcp.* categories. It does not log what the + /// server reports: server log lines go to + /// , where the caller decides whether they are worth + /// logging. Nothing is formatted while the matching category and level are disabled. + /// + /// + /// At Debug the statement text is logged in full. That is deliberate — a driver log without the + /// statement is hard to use — but it is not the same policy as + /// , which keeps the statement out of traces unless asked. Enable + /// Debug on ClickHouse.Driver.Tcp.Client only where the statements may be recorded. + /// + /// + public ILoggerFactory LoggerFactory { get; init; } + + /// + /// Whether to put the statement text in the db.query.text span attribute. Defaults to false, because + /// a statement can carry data a trace is not meant to hold. + /// + public bool IncludeSqlInActivityTags { get; init; } + + /// + /// How much of the statement may leave the client as telemetry, in characters; longer text is truncated. + /// Defaults to 300. + /// + /// + /// It caps both channels — the db.query.text span attribute and the Debug log line — so zero + /// or less keeps the statement text out of telemetry altogether, whatever + /// says. + /// + public int StatementMaxLength { get; init; } = DefaultStatementMaxLength; + /// /// These options with replaced by a private snapshot, or this instance when there /// are none to copy. A client holds its options for its lifetime and merges the settings on every operation, so @@ -295,6 +334,22 @@ public sealed record ClickHouseTcpClientOptions /// The with expression carries every other property across, so a property added later needs no change /// here. Keep it that way: a hand-written copy is what silently drops a new property. /// + /// + /// The statement text as telemetry may carry it: truncated to , or empty + /// when that allows none. + /// + /// The statement. + /// The text to report, possibly empty, never null. + internal string StatementForTelemetry(string sql) + { + if (sql is null || StatementMaxLength <= 0) + { + return string.Empty; + } + + return sql.Length <= StatementMaxLength ? sql : sql[..StatementMaxLength]; + } + internal ClickHouseTcpClientOptions WithOwnedCustomSettings() => CustomSettings is null ? this diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileEvent.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileEvent.cs new file mode 100644 index 000000000..1b0ceb180 --- /dev/null +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileEvent.cs @@ -0,0 +1,67 @@ +using System; + +namespace ClickHouse.Driver.Tcp; + +/// +/// One server performance counter, streamed to the client while a query runs. The same counter arrives +/// repeatedly as the query progresses. +/// +/// +/// Every member is owned, so an event is safe to keep after the callback returns. +/// +public readonly record struct ClickHouseTcpProfileEvent +{ + /// Initializes a new instance of the struct. + /// When the server sampled the counter. + /// The server host the counter came from. + /// The OS thread the counter belongs to, or 0 for a query-wide total. + /// Whether is an increment or a reading. + /// The counter name. + /// The increment or the reading. + public ClickHouseTcpProfileEvent( + DateTimeOffset currentTime, + string hostName, + ulong threadId, + ClickHouseTcpProfileEventType type, + string name, + long value) + { + CurrentTime = currentTime; + HostName = hostName; + ThreadId = threadId; + Type = type; + Name = name; + Value = value; + } + + /// When the server sampled the counter, as a UTC instant. + public DateTimeOffset CurrentTime { get; } + + /// The server host the counter came from. + public string HostName { get; } + + /// The OS thread the counter belongs to, or 0 for a query-wide total. + public ulong ThreadId { get; } + + /// Whether is an increment to add up or a reading to take as it stands. + public ClickHouseTcpProfileEventType Type { get; } + + /// The counter name, e.g. Query or NetworkReceiveBytes. + public string Name { get; } + + /// The increment or the reading, per . + public long Value { get; } +} + +/// How to read the of a profile event. +public enum ClickHouseTcpProfileEventType +{ + /// The server sent a type outside the range it documents. + Unknown = 0, + + /// An increment: add it to the running total for this counter. + Increment = 1, + + /// A reading at a point in time: it replaces the previous one rather than adding to it. + Gauge = 2, +} diff --git a/ClickHouse.Driver.Tcp/Protocol/ProfileInfo.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileInfo.cs similarity index 73% rename from ClickHouse.Driver.Tcp/Protocol/ProfileInfo.cs rename to ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileInfo.cs index 8cdf22f67..180b7b190 100644 --- a/ClickHouse.Driver.Tcp/Protocol/ProfileInfo.cs +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileInfo.cs @@ -1,21 +1,23 @@ using System.Threading; using System.Threading.Tasks; +using ClickHouse.Driver.Tcp.Protocol; -namespace ClickHouse.Driver.Tcp.Protocol; +namespace ClickHouse.Driver.Tcp; /// -/// A decoded ProfileInfo packet: the once-per-query execution summary. +/// The once-per-query execution summary the server sends alongside the result. Unlike +/// these are totals, not increments. /// -internal readonly struct ProfileInfo +public readonly record struct ClickHouseTcpProfileInfo { - /// Initializes a new instance of the struct. + /// Initializes a new instance of the struct. /// Rows in the result. /// Blocks in the result. /// Bytes in the result. /// Whether a LIMIT was applied. /// Rows before the LIMIT. /// Whether is meaningful. - public ProfileInfo(ulong rows, ulong blocks, ulong bytes, bool appliedLimit, ulong rowsBeforeLimit, bool calculatedRowsBeforeLimit) + public ClickHouseTcpProfileInfo(ulong rows, ulong blocks, ulong bytes, bool appliedLimit, ulong rowsBeforeLimit, bool calculatedRowsBeforeLimit) { Rows = rows; Blocks = blocks; @@ -47,7 +49,7 @@ public ProfileInfo(ulong rows, ulong blocks, ulong bytes, bool appliedLimit, ulo /// The reader positioned at the packet body. /// A token to observe for cancellation. /// The decoded profile info. - public static async ValueTask ReadAsync(ClickHouseBinaryReader reader, CancellationToken cancellationToken) + internal static async ValueTask ReadAsync(ClickHouseBinaryReader reader, CancellationToken cancellationToken) { ulong rows = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); ulong blocks = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); @@ -56,6 +58,6 @@ public static async ValueTask ReadAsync(ClickHouseBinaryReader read ulong rowsBeforeLimit = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); bool calculatedRowsBeforeLimit = await reader.ReadBoolAsync(cancellationToken).ConfigureAwait(false); - return new ProfileInfo(rows, blocks, bytes, appliedLimit, rowsBeforeLimit, calculatedRowsBeforeLimit); + return new ClickHouseTcpProfileInfo(rows, blocks, bytes, appliedLimit, rowsBeforeLimit, calculatedRowsBeforeLimit); } } diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpProgress.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpProgress.cs new file mode 100644 index 000000000..c6263eb41 --- /dev/null +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpProgress.cs @@ -0,0 +1,98 @@ +using System.Threading; +using System.Threading.Tasks; +using ClickHouse.Driver.Tcp.Protocol; + +namespace ClickHouse.Driver.Tcp; + +/// +/// One decoded Progress packet, which the server sends repeatedly while a query runs. +/// +/// +/// Every counter is an increment, not a running total. A consumer that wants the totals so far has to add +/// the packets up — use or rather than keeping the last packet, which +/// only reports the most recent step. is an increment too: the server raises its estimate +/// as it learns how much data the query has to touch. +/// +public readonly record struct ClickHouseTcpProgress +{ + /// Initializes a new instance of the struct. + /// Rows read in this increment. + /// Bytes read in this increment. + /// The rise in the server's estimate of the rows to read. + /// Rows written in this increment (INSERT). + /// Bytes written in this increment (INSERT). + /// Server-side time in nanoseconds spent during this increment. + public ClickHouseTcpProgress(ulong rows, ulong bytes, ulong totalRows, ulong wroteRows, ulong wroteBytes, ulong elapsedNs) + { + Rows = rows; + Bytes = bytes; + TotalRows = totalRows; + WroteRows = wroteRows; + WroteBytes = wroteBytes; + ElapsedNs = elapsedNs; + } + + /// Rows read in this increment. + public ulong Rows { get; } + + /// Bytes read in this increment. + public ulong Bytes { get; } + + /// The rise in the server's estimate of the rows this query has to read. + public ulong TotalRows { get; } + + /// Rows written in this increment, for an INSERT. + public ulong WroteRows { get; } + + /// Bytes written in this increment, for an INSERT. + public ulong WroteBytes { get; } + + /// Server-side time in nanoseconds spent during this increment. + public ulong ElapsedNs { get; } + + /// Adds two increments field by field, giving the running total. + /// The total so far. + /// The increment to add. + /// The new total. + public static ClickHouseTcpProgress operator +(ClickHouseTcpProgress left, ClickHouseTcpProgress right) => new( + left.Rows + right.Rows, + left.Bytes + right.Bytes, + left.TotalRows + right.TotalRows, + left.WroteRows + right.WroteRows, + left.WroteBytes + right.WroteBytes, + left.ElapsedNs + right.ElapsedNs); + + /// Adds two increments field by field, giving the running total. + /// The total so far. + /// The increment to add. + /// The new total. + public static ClickHouseTcpProgress Add(ClickHouseTcpProgress left, ClickHouseTcpProgress right) => left + right; + + /// Reads a Progress packet body at the negotiated version. + /// The reader positioned at the packet body. + /// The negotiated protocol, gating the trailing counters. + /// A token to observe for cancellation. + /// The decoded progress. + internal static async ValueTask ReadAsync(ClickHouseBinaryReader reader, NegotiatedProtocol negotiated, CancellationToken cancellationToken) + { + ulong rows = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); + ulong bytes = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); + ulong totalRows = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); + + ulong wroteRows = 0; + ulong wroteBytes = 0; + if (negotiated.Supports(ProtocolFeature.ProgressWriteInfo)) + { + wroteRows = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); + wroteBytes = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); + } + + ulong elapsedNs = 0; + if (negotiated.Supports(ProtocolFeature.ProgressElapsedNs)) + { + elapsedNs = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); + } + + return new ClickHouseTcpProgress(rows, bytes, totalRows, wroteRows, wroteBytes, elapsedNs); + } +} diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs new file mode 100644 index 000000000..250c01ff7 --- /dev/null +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs @@ -0,0 +1,61 @@ +using System; +using ClickHouse.Driver.Tcp.Format; + +namespace ClickHouse.Driver.Tcp; + +/// +/// Optional callbacks for the metadata the server interleaves into a query or insert response: progress, +/// the execution summary, its own log lines, its performance counters, and the WITH TOTALS / extremes rows. +/// Set it on . +/// +/// +/// +/// Every member is optional, and setting one costs almost nothing: the packets arrive and are decoded either +/// way, to keep the connection aligned, and an unset callback only means the result is discarded instead of +/// handed over. What is not free is asking the server to send them at all — see +/// . +/// +/// +/// Callbacks run synchronously on the thread draining the response, in the order the packets arrive. +/// They sit on the read path between result blocks, so keep them fast; hand work off to a queue rather than +/// doing it here. A callback that throws propagates out of the operation and terminates the connection, so +/// never throw for control flow. +/// +/// +/// and borrow their block: it is valid for the call only, +/// and is released as soon as the callback returns. Copy out what must outlive it, and do not retain the block, +/// its columns, or their value spans. Every other callback receives owned values that are safe to keep. +/// +/// +public sealed class ClickHouseTcpQueryCallbacks +{ + /// + /// Called for each progress increment the server reports as the query runs. The counters are increments, not + /// running totals — see . + /// + public Action OnProgress { get; init; } + + /// Called once with the query's execution summary (result rows, blocks, bytes, whether a LIMIT applied). + public Action OnProfileInfo { get; init; } + + /// + /// Called once per line of the server's own log. The server sends these only when the query sets + /// send_logs_level (its default, fatal, is effectively silent), so setting this callback alone + /// produces nothing. + /// + public Action OnServerLog { get; init; } + + /// Called once per server performance counter sample. + public Action OnProfileEvent { get; init; } + + /// + /// Called with the borrowed WITH TOTALS block. Valid for the call only. + /// + public Action OnTotals { get; init; } + + /// + /// Called with the borrowed extremes block, whose two rows are the minimum and the maximum. The server sends + /// it only when the query sets the extremes setting. Valid for the call only. + /// + public Action OnExtremes { get; init; } +} diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryOptions.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryOptions.cs index 757fda17e..45548198a 100644 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryOptions.cs +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryOptions.cs @@ -60,4 +60,15 @@ public record ClickHouseTcpQueryOptions /// /// public ClickHouseTcpParameterCollection Parameters { get; init; } + + /// + /// Callbacks for the metadata the server interleaves into this operation's response — progress, the + /// execution summary, server log lines, performance counters, WITH TOTALS and extremes. Null means none, and + /// costs nothing. + /// + /// + /// The callbacks run synchronously on the thread draining the response, and one that throws terminates the + /// connection. See for the full contract. + /// + public ClickHouseTcpQueryCallbacks Callbacks { get; init; } } diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpServerLogRow.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpServerLogRow.cs new file mode 100644 index 000000000..84b1417ad --- /dev/null +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpServerLogRow.cs @@ -0,0 +1,98 @@ +using System; + +namespace ClickHouse.Driver.Tcp; + +/// +/// One row of the server's own log, streamed to the client while a query runs. The server sends these only when +/// the query asks it to, with the send_logs_level setting (its default, fatal, is effectively +/// silent). +/// +/// +/// Every member is owned, so a row is safe to keep after the callback returns. +/// +public readonly record struct ClickHouseTcpServerLogRow +{ + /// Initializes a new instance of the struct. + /// When the server wrote the line, to microsecond resolution. + /// The server host that wrote the line. + /// The id of the query the line belongs to. + /// The OS thread that wrote the line. + /// The severity. + /// The server-side logger name. + /// The message. + public ClickHouseTcpServerLogRow( + DateTimeOffset eventTime, + string hostName, + string queryId, + ulong threadId, + ClickHouseTcpServerLogLevel level, + string source, + string text) + { + EventTime = eventTime; + HostName = hostName; + QueryId = queryId; + ThreadId = threadId; + Level = level; + Source = source; + Text = text; + } + + /// When the server wrote the line, to microsecond resolution, as a UTC instant. + public DateTimeOffset EventTime { get; } + + /// The server host that wrote the line. + public string HostName { get; } + + /// The id of the query the line belongs to. + public string QueryId { get; } + + /// The OS thread that wrote the line. + public ulong ThreadId { get; } + + /// The severity. + public ClickHouseTcpServerLogLevel Level { get; } + + /// The server-side logger name, e.g. executeQuery. + public string Source { get; } + + /// The message. + public string Text { get; } +} + +/// +/// The severity of a . The values are the server's own log priorities, so +/// a lower number is more severe — the reverse of Microsoft.Extensions.Logging.LogLevel. +/// +public enum ClickHouseTcpServerLogLevel +{ + /// The server sent a priority outside the range it documents. + Unknown = 0, + + /// The process cannot continue. + Fatal = 1, + + /// A failure that needs attention now. + Critical = 2, + + /// A failure. + Error = 3, + + /// Something unexpected that did not fail the operation. + Warning = 4, + + /// A normal but significant event. + Notice = 5, + + /// Informational progress. + Information = 6, + + /// Detail for diagnosing a problem. + Debug = 7, + + /// The most detailed level the server emits by query. + Trace = 8, + + /// Test-only output. + Test = 9, +} diff --git a/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs b/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs index 570b79a88..b416976a4 100644 --- a/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs +++ b/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs @@ -3,7 +3,9 @@ using System.Globalization; using System.Threading; using System.Threading.Tasks; +using ClickHouse.Driver.Tcp.Logging; using ClickHouse.Driver.Tcp.Protocol; +using Microsoft.Extensions.Logging; namespace ClickHouse.Driver.Tcp.Client; @@ -50,6 +52,7 @@ internal sealed class ConnectionPool : IConnectionSource private readonly ClickHouseTcpClientOptions options; private readonly IConnectionFactory factory; + private readonly ILogger logger; private readonly TimeProvider time; private readonly SemaphoreSlim permits; private readonly ITimer sweeper; @@ -116,6 +119,7 @@ internal ConnectionPool(ClickHouseTcpClientOptions options, IConnectionFactory f this.options = options; this.factory = factory; this.time = time; + logger = options.LoggerFactory?.CreateLogger(ClickHouseTcpDiagnostics.PoolLogCategory); permits = new SemaphoreSlim(options.MaxPoolSize, options.MaxPoolSize); TimeSpan period = SweepInterval(options); @@ -164,10 +168,27 @@ public async ValueTask RentAsync(CancellationToken cancellatio // Disposal may have started while this caller waited for the permit. ThrowIfDisposed(); - PooledConnection connection = TakeReusableIdle() - ?? new PooledConnection(await DialAsync(cancellationToken).ConfigureAwait(false), time); + PooledConnection connection = TakeReusableIdle(); + bool reused = connection is not null; + if (!reused) + { + if (logger is not null) + { + PoolLog.Dialing(logger); + } + + connection = new PooledConnection(await DialAsync(cancellationToken).ConfigureAwait(false), time); + } connection.OnRented(); + + // Logged after OnRented, which is what makes UsageCount this operation's number rather than the + // previous one's. + if (reused && logger is not null) + { + PoolLog.Reused(logger, connection.UsageCount, connection.Age.TotalMilliseconds); + } + lock (gate) { // The slot gives way to the entry in `leased` under one lock, so the total this checkout @@ -254,7 +275,20 @@ private async Task TearDownAsync() // Nothing can re-enter the idle set after this: `Return` re-reads `disposed` under `gate`, and the // Interlocked.Exchange above happens before this lock is taken, so a returner either added before the // drain (and is closed by it) or observes the flag and closes its own connection. - CloseAll(TakeAllIdle()); + List closing = TakeAllIdle(); + int inFlight; + lock (gate) + { + inFlight = leased.Count; + } + + // Closed before the line is written: these connections are already out of the idle set, so nothing else + // can reach them, and a logger that threw first would leak every one of their sockets. + CloseAll(closing); + if (logger is not null) + { + PoolLog.Draining(logger, closing?.Count ?? 0, inFlight); + } // Wait for the operations still running to give their connections back, by acquiring every permit. Each one // finds the pool disposed and closes its connection rather than pooling it. Bounded by PoolTimeout for the @@ -361,8 +395,7 @@ private static TimeSpan ShortestActiveLimit(ClickHouseTcpClientOptions options) /// /// Runs a sweep and swallows anything it throws. This is what the timer calls. A timer callback runs on a /// thread-pool thread with no one to catch for it, so an escaping exception would end the process, which is too - /// high a price for a sweep that failed to close one socket. There is nothing to log to yet; observability - /// lands in Epic P. + /// high a price for a sweep that failed to close one socket. The logger is the only place it is reported. /// internal void SweepQuietly() { @@ -372,6 +405,19 @@ internal void SweepQuietly() } catch (Exception e) when (e is not OutOfMemoryException and not StackOverflowException) { + // Reporting the failure must not become one. This runs in a catch block, so anything thrown here + // propagates out of a timer callback with nobody to catch it, which is the very outcome this method + // exists to prevent — and a logger is caller code. + try + { + if (logger is not null) + { + PoolLog.SweepFailed(logger, e); + } + } + catch (Exception logFailure) when (logFailure is not OutOfMemoryException and not StackOverflowException) + { + } } } @@ -415,6 +461,11 @@ internal void Sweep() } } + if (reaped.Count != 0 && logger is not null) + { + PoolLog.Retired(logger, reaped.Count); + } + CloseAll(reaped); LastRefill = StartRefillIfBelowFloor(); } @@ -464,8 +515,8 @@ internal Task StartRefillIfBelowFloor() /// also reserves a slot against the checkouts and dials already in flight. /// /// - /// A dial that fails ends the round silently. Nobody is waiting on it, there is nothing to report it to until - /// Epic P, and the next sweep tries again, so a server that is down costs one failed connect per sweep rather + /// A dial that fails ends the round silently. Nobody is waiting on it, so the logger is the only place it is + /// reported, and the next sweep tries again — a server that is down costs one failed connect per sweep rather /// than a spin. /// /// @@ -528,7 +579,18 @@ private async Task RefillAsync() } catch (Exception e) when (e is not OutOfMemoryException and not StackOverflowException) { - // A failed dial, or disposal cancelling one. Either way the next sweep reassesses. + // A failed dial, or disposal cancelling one. Either way the next sweep reassesses. Disposal is not + // reported: cancelling a top-up is what disposal is meant to do. + try + { + if (logger is not null && Volatile.Read(ref disposed) == 0) + { + PoolLog.RefillFailed(logger, e); + } + } + catch (Exception logFailure) when (logFailure is not OutOfMemoryException and not StackOverflowException) + { + } } finally { @@ -726,6 +788,11 @@ private async ValueTask AcquirePermitAsync(CancellationToken cancellationToken) // Disposal takes every permit and keeps them, so it is a likelier cause than genuine exhaustion here. ThrowIfDisposed(); + if (logger is not null) + { + PoolLog.Exhausted(logger, options.MaxPoolSize, options.PoolTimeout.TotalSeconds); + } + throw new TimeoutException( string.Format( CultureInfo.InvariantCulture, @@ -772,6 +839,12 @@ private void Return(PooledConnection connection) if (!pooled) { + // Reusable but not pooled means disposal got there first, and the drain line already reports that. + if (!reusable && logger is not null) + { + PoolLog.Discarded(logger, connection.UsageCount); + } + connection.Close(); } } diff --git a/ClickHouse.Driver.Tcp/Client/IConnectionFactory.cs b/ClickHouse.Driver.Tcp/Client/IConnectionFactory.cs index 9c5e92e77..6e9599f3b 100644 --- a/ClickHouse.Driver.Tcp/Client/IConnectionFactory.cs +++ b/ClickHouse.Driver.Tcp/Client/IConnectionFactory.cs @@ -1,7 +1,11 @@ using System; +using System.Diagnostics; using System.Threading; using System.Threading.Tasks; +using ClickHouse.Driver.Tcp.Diagnostic; +using ClickHouse.Driver.Tcp.Logging; using ClickHouse.Driver.Tcp.Protocol; +using Microsoft.Extensions.Logging; namespace ClickHouse.Driver.Tcp.Client; @@ -31,6 +35,7 @@ internal sealed class TcpConnectionFactory : IConnectionFactory { private readonly ClickHouseTcpClientOptions options; private readonly TlsParameters tls; + private readonly ILogger logger; /// /// Initializes the factory over the client's validated options, resolving the TLS configuration once. A @@ -42,6 +47,7 @@ internal TcpConnectionFactory(ClickHouseTcpClientOptions options) { this.options = options; tls = BuildTlsParameters(options); + logger = options.LoggerFactory?.CreateLogger(ClickHouseTcpDiagnostics.ConnectionLogCategory); } /// @@ -49,18 +55,75 @@ public async ValueTask CreateAsync(CancellationToken ca { using var linked = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); linked.CancelAfter(options.DialTimeout); + + // One span over the socket connect, the TLS negotiation and the handshake, which is what a slow first + // operation is usually waiting on. + using Activity activity = TcpActivity.StartConnect(options); + long startedAt = Stopwatch.GetTimestamp(); + if (logger is not null) + { + ConnectionLog.Opening(logger, options.Host, options.ResolvedPort, options.Username, options.UseTls); + } + try { - return await ClickHouseTcpConnection.ConnectAsync( + ClickHouseTcpConnection connection = await ClickHouseTcpConnection.ConnectAsync( options.Host, options.ResolvedPort, options.ToHandshakeParameters(), tls, linked.Token, options.Compressor).ConfigureAwait(false); + + activity?.SetSuccess(); + if (logger is not null) + { + ServerHandshake server = connection.Server; + ConnectionLog.Opened( + logger, + server.ServerName, + server.VersionMajor, + server.VersionMinor, + server.VersionPatch, + Stopwatch.GetElapsedTime(startedAt).TotalMilliseconds, + server.Revision, + server.Timezone); + } + + return connection; } catch (OperationCanceledException) when (!cancellationToken.IsCancellationRequested && linked.IsCancellationRequested) { // The linked token, not the caller's, fired: the dial deadline elapsed. Surface it as a timeout so a // hung connect is distinguishable from a caller cancellation. The deadline covers the TLS handshake // too, which is one more round trip a wedged server can stall on. - throw new TimeoutException( + var timeout = new TimeoutException( $"Connecting to {options.Host}:{options.ResolvedPort} timed out after {options.DialTimeout.TotalSeconds:0.###}s (DialTimeout)."); + ReportFailure(activity, startedAt, timeout); + throw timeout; + } + catch (OperationCanceledException e) + { + // The pool dials on its shutdown token, so a client being disposed cancels any top-up in flight. + // That is disposal working, not a server that cannot be reached, and it is not worth a warning. + activity?.SetError(e); + if (logger is not null) + { + ConnectionLog.OpenCancelled(logger, options.Host, options.ResolvedPort, Stopwatch.GetElapsedTime(startedAt).TotalMilliseconds); + } + + throw; + } + catch (Exception e) + { + ReportFailure(activity, startedAt, e); + throw; + } + } + + // Marks the connect span failed and logs it. A dial the pool started in the background has no caller to + // report to, so without this line it fails invisibly. + private void ReportFailure(Activity activity, long startedAt, Exception exception) + { + activity?.SetError(exception); + if (logger is not null) + { + ConnectionLog.OpenFailed(logger, options.Host, options.ResolvedPort, Stopwatch.GetElapsedTime(startedAt).TotalMilliseconds, exception); } } diff --git a/ClickHouse.Driver.Tcp/Client/MetadataCallbackBridge.cs b/ClickHouse.Driver.Tcp/Client/MetadataCallbackBridge.cs new file mode 100644 index 000000000..f2cfc60e2 --- /dev/null +++ b/ClickHouse.Driver.Tcp/Client/MetadataCallbackBridge.cs @@ -0,0 +1,161 @@ +using System; +using System.Collections.Generic; +using ClickHouse.Driver.Tcp.Format; +using ClickHouse.Driver.Tcp.Protocol; +using ClickHouse.Driver.Tcp.Types; + +namespace ClickHouse.Driver.Tcp.Client; + +/// +/// Turns the public into the wire-shaped +/// the connection drains into, and projects the two fixed-schema metadata blocks +/// into owned rows on the way. +/// +/// +/// The projection is what keeps a borrowed block from reaching a caller who cannot know it is about to be +/// released. Log and ProfileEvents blocks have a schema the server fixes, so a row type is safe to publish; +/// Totals and Extremes carry the query's own result shape, so they stay blocks. +/// +internal static class MetadataCallbackBridge +{ + /// + /// Builds the handlers for one operation, or null when nothing at all is listening — which keeps the read + /// path's null check the whole cost of the feature for a caller who set no callbacks. + /// + /// The caller's callbacks, or null. + /// A client-internal progress observer to run before the caller's, or null. + /// A client-internal summary observer to run before the caller's, or null. + /// The handlers to drain into, or null. + public static MetadataHandlers Build( + ClickHouseTcpQueryCallbacks callbacks, + Action onProgress = null, + Action onProfileInfo = null) + { + Action serverLog = callbacks?.OnServerLog; + Action profileEvent = callbacks?.OnProfileEvent; + Action progress = Combine(onProgress, callbacks?.OnProgress); + Action profileInfo = Combine(onProfileInfo, callbacks?.OnProfileInfo); + Action totals = callbacks?.OnTotals; + Action extremes = callbacks?.OnExtremes; + + if (progress is null && profileInfo is null && serverLog is null && profileEvent is null && totals is null && extremes is null) + { + return null; + } + + return new MetadataHandlers + { + OnProgress = progress, + OnProfileInfo = profileInfo, + OnTotals = totals, + OnExtremes = extremes, + OnLog = serverLog is null ? null : block => ProjectServerLog(block, serverLog), + OnProfileEvents = profileEvent is null ? null : block => ProjectProfileEvents(block, profileEvent), + }; + } + + // The client's own observer runs first, so a caller's callback that throws cannot rob the client of the + // telemetry it already had in hand. + private static Action Combine(Action first, Action second) + { + if (first is null) + { + return second; + } + + return second is null ? first : first + second; + } + + private static void ProjectServerLog(Block block, Action callback) + { + const string Kind = "Log"; + + ReadOnlySpan eventTime = Column(block, Kind, "event_time").Values; + ReadOnlySpan microseconds = Column(block, Kind, "event_time_microseconds").Values; + ReadOnlySpan threadId = Column(block, Kind, "thread_id").Values; + ReadOnlySpan priority = Column(block, Kind, "priority").Values; + IColumn hostName = Column(block, Kind, "host_name"); + IColumn queryId = Column(block, Kind, "query_id"); + IColumn source = Column(block, Kind, "source"); + IColumn text = Column(block, Kind, "text"); + + for (int row = 0; row < block.RowCount; row++) + { + callback(new ClickHouseTcpServerLogRow( + Instant(eventTime[row], microseconds[row]), + hostName[row], + queryId[row], + threadId[row], + LogLevel(priority[row]), + source[row], + text[row])); + } + } + + private static void ProjectProfileEvents(Block block, Action callback) + { + const string Kind = "ProfileEvents"; + + ReadOnlySpan currentTime = Column(block, Kind, "current_time").Values; + ReadOnlySpan threadId = Column(block, Kind, "thread_id").Values; + ReadOnlySpan type = Column(block, Kind, "type").Values; + IColumn hostName = Column(block, Kind, "host_name"); + IColumn name = Column(block, Kind, "name"); + + // A counter is a signed count: a gauge can fall as well as rise. Every supported server sends Int64 + // (checked against 25.8, the oldest), so any other width is a protocol change to fail on rather than + // reinterpret. + ReadOnlySpan values = Column(block, Kind, "value").Values; + + for (int row = 0; row < block.RowCount; row++) + { + callback(new ClickHouseTcpProfileEvent( + Instant(currentTime[row], 0), + hostName[row], + threadId[row], + EventType(type[row]), + name[row], + values[row])); + } + } + + // The seconds column is a bare DateTime, so its value is a Unix instant with no timezone of its own. + private static DateTimeOffset Instant(uint unixSeconds, uint microseconds) + => DateTimeOffset.FromUnixTimeSeconds(unixSeconds).AddTicks(microseconds * TimeSpan.TicksPerMicrosecond); + + // An out-of-range value becomes Unknown rather than throwing: a server that grows a level must not break a + // caller who only wanted the message text. + private static ClickHouseTcpServerLogLevel LogLevel(sbyte priority) + => priority is >= (sbyte)ClickHouseTcpServerLogLevel.Fatal and <= (sbyte)ClickHouseTcpServerLogLevel.Test + ? (ClickHouseTcpServerLogLevel)priority + : ClickHouseTcpServerLogLevel.Unknown; + + private static ClickHouseTcpProfileEventType EventType(sbyte type) + => type is >= (sbyte)ClickHouseTcpProfileEventType.Increment and <= (sbyte)ClickHouseTcpProfileEventType.Gauge + ? (ClickHouseTcpProfileEventType)type + : ClickHouseTcpProfileEventType.Unknown; + + private static IColumn Column(Block block, string kind, string name) + { + IColumn column = Column(block, kind, name); + return column as IColumn + ?? throw new ClickHouseProtocolException( + $"{kind} column '{name}' has type '{column.TypeName}', which does not read as {typeof(T).Name}."); + } + + // Walks the columns rather than Block.ColumnNames, which would materialize and cache a string[] for every + // metadata block, and these arrive repeatedly through a query. + private static IColumn Column(Block block, string kind, string name) + { + IReadOnlyList columns = block.Columns; + for (int i = 0; i < columns.Count; i++) + { + if (string.Equals(columns[i].Name, name, StringComparison.Ordinal)) + { + return columns[i]; + } + } + + throw new ClickHouseProtocolException($"{kind} block has no column named '{name}'."); + } +} diff --git a/ClickHouse.Driver.Tcp/Diagnostic/ClickHouseTcpDiagnostics.cs b/ClickHouse.Driver.Tcp/Diagnostic/ClickHouseTcpDiagnostics.cs new file mode 100644 index 000000000..7c0cfa2b7 --- /dev/null +++ b/ClickHouse.Driver.Tcp/Diagnostic/ClickHouseTcpDiagnostics.cs @@ -0,0 +1,38 @@ +namespace ClickHouse.Driver.Tcp; + +/// +/// The names a tracing exporter or a logging filter needs to pick this client out. +/// +/// +/// +/// Sdk.CreateTracerProviderBuilder() +/// .AddSource(ClickHouseTcpDiagnostics.ActivitySourceName) +/// .AddConsoleExporter() +/// .Build(); +/// +/// +public static class ClickHouseTcpDiagnostics +{ + /// + /// The name the native-protocol client emits spans under. + /// It is separate from the HTTP transport's source, so either can be collected on its own. + /// + public const string ActivitySourceName = "ClickHouse.Driver.Tcp"; + + /// + /// The logger category for operations run through the client or a session: what ran, how long it took, and + /// how it ended. The statement text appears here at Debug. + /// + public const string ClientLogCategory = "ClickHouse.Driver.Tcp.Client"; + + /// + /// The logger category for opening a connection: the dial, the TLS negotiation, and the handshake result. + /// + public const string ConnectionLogCategory = "ClickHouse.Driver.Tcp.Connection"; + + /// + /// The logger category for the connection pool: checkouts, retirement, exhaustion, and the background work + /// no caller is awaiting — a failed top-up dial or sweep is reported nowhere else. + /// + public const string PoolLogCategory = "ClickHouse.Driver.Tcp.Pool"; +} diff --git a/ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs b/ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs new file mode 100644 index 000000000..e31e47969 --- /dev/null +++ b/ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs @@ -0,0 +1,149 @@ +using System; +using System.Diagnostics; +using ClickHouse.Driver.Tcp.Client; +using ClickHouse.Driver.Tcp.Logging; +using ClickHouse.Driver.Tcp.Protocol; +using Microsoft.Extensions.Logging; + +namespace ClickHouse.Driver.Tcp.Diagnostic; + +/// +/// Brackets one client operation with everything that watches it: its span, its log lines, and the metadata +/// handlers both are fed from. They are built together because the span's counters and the completion log line +/// come from the same Progress and ProfileInfo packets the caller's own callbacks do. +/// +/// +/// returns null when there is nothing to observe — no tracing listener, no logger factory, +/// and no caller callbacks — so every member is reached through operation?. and the +/// no-configuration path allocates nothing. +/// +internal sealed class ClientOperation : IDisposable +{ + private readonly Activity activity; + private readonly ILogger logger; + private readonly string operationName; + private readonly string queryId; + private readonly long startedAt; + private ClickHouseTcpProgress totals; + private bool ended; + + private ClientOperation(Activity activity, ILogger logger, string operationName, string queryId) + { + this.activity = activity; + this.logger = logger; + this.operationName = operationName; + this.queryId = queryId; + startedAt = Stopwatch.GetTimestamp(); + } + + /// The handlers the operation's response drains into, or null when nothing needs them. + public MetadataHandlers Handlers { get; private set; } + + /// Starts the span and the log line for a statement, and builds its handlers. + /// The client options the span's endpoint attributes come from. + /// The client-category logger, or null when none is configured. + /// The statement. + /// The caller's query id, or null to let the server assign one. + /// The caller's metadata callbacks, or null. + /// The operation, or null when nothing is observing it. + public static ClientOperation Start( + ClickHouseTcpClientOptions options, + ILogger logger, + string sql, + string queryId, + ClickHouseTcpQueryCallbacks callbacks) + { + // Tested before the statement is scanned: reading the leading keyword allocates, and an unconfigured + // client must not pay for it on every operation. + if (!TcpActivity.Source.HasListeners() && logger is null && callbacks is null) + { + return null; + } + + string operationName = TcpActivity.OperationName(sql); + Activity activity = TcpActivity.StartStatement(options, sql, operationName, queryId); + var operation = new ClientOperation(activity, logger, operationName ?? TcpActivity.UnknownOperation, queryId); + + // The counters feed both the span's attributes and the completion log line, so either one alone is reason + // enough to accumulate them. + operation.Handlers = MetadataCallbackBridge.Build( + callbacks, + activity is null && logger is null ? null : operation.Accumulate, + activity is null ? null : activity.SetProfileInfo); + + if (logger is not null) + { + // Capped by the same knob as the span attribute, so one setting governs how much statement text + // leaves the client whichever channel it leaves by. + ClientLog.StatementStarted(logger, operation.operationName, queryId, options.StatementForTelemetry(sql)); + } + + return operation; + } + + /// Records that the operation ran to completion. + public void Succeeded() + { + ended = true; + activity?.SetSuccess(); + + if (logger is null) + { + return; + } + + // An insert reports what it wrote and a query what it read, so the line carries whichever the server + // counted rather than a row of zeroes for the other. + if (totals.WroteRows != 0 || totals.WroteBytes != 0) + { + ClientLog.StatementWrote(logger, operationName, queryId, Elapsed(), totals.WroteRows, totals.WroteBytes); + } + else + { + ClientLog.StatementCompleted(logger, operationName, queryId, Elapsed(), totals.Rows, totals.Bytes); + } + } + + /// Records the exception that ended the operation. + /// The exception about to propagate. + public void Failed(Exception exception) + { + ended = true; + activity?.SetError(exception); + + if (logger is null) + { + return; + } + + // A caller cancelling is normal control flow, so it is not an error in the log — though it still ends the + // span as one, OpenTelemetry having no cancelled status. + if (exception is OperationCanceledException) + { + ClientLog.StatementCancelled(logger, operationName, queryId, Elapsed()); + } + else + { + ClientLog.StatementFailed(logger, operationName, queryId, Elapsed(), exception); + } + } + + /// Writes the accumulated counters and ends the span. + public void Dispose() + { + activity?.SetProgressTotals(totals); + activity?.Dispose(); + + // Neither succeeded nor failed means the caller stopped reading a result part-way. Worth a line, because + // it is also what leaves the connection to be discarded and redialed rather than reused. + if (!ended && logger is not null) + { + ClientLog.StatementAbandoned(logger, operationName, queryId, Elapsed()); + } + } + + private double Elapsed() => Stopwatch.GetElapsedTime(startedAt).TotalMilliseconds; + + // Progress packets carry increments, so the totals are their sum, not the last one seen. + private void Accumulate(ClickHouseTcpProgress increment) => totals += increment; +} diff --git a/ClickHouse.Driver.Tcp/Diagnostic/TcpActivity.cs b/ClickHouse.Driver.Tcp/Diagnostic/TcpActivity.cs new file mode 100644 index 000000000..3425707f5 --- /dev/null +++ b/ClickHouse.Driver.Tcp/Diagnostic/TcpActivity.cs @@ -0,0 +1,242 @@ +using System; +using System.Diagnostics; +using System.Globalization; +using System.Reflection; +using ClickHouse.Driver.Tcp.Protocol; + +namespace ClickHouse.Driver.Tcp.Diagnostic; + +/// +/// Starts and annotates the client spans. Every method tolerates a null , because +/// returns null when nothing is listening — so a +/// caller writes activity?.SetSuccess() and never branches on whether tracing is on. +/// +/// +/// The attribute names are the current OpenTelemetry database conventions +/// (db.system.name, db.namespace, db.query.text, server.address), not the older +/// db.system/db.statement/peer.service set the HTTP transport still emits. Two are outside +/// that set: db.user, which the conventions dropped without a replacement and the HTTP transport also +/// emits, and the db.clickhouse.* counters, which are shared with it. +/// +internal static class TcpActivity +{ + internal const string TagSystemName = "db.system.name"; + internal const string TagNamespace = "db.namespace"; + internal const string TagOperationName = "db.operation.name"; + internal const string TagQueryText = "db.query.text"; + internal const string TagUser = "db.user"; + internal const string TagServerAddress = "server.address"; + internal const string TagServerPort = "server.port"; + internal const string TagErrorType = "error.type"; + internal const string TagResponseStatusCode = "db.response.status_code"; + internal const string TagQueryId = "db.clickhouse.query_id"; + internal const string TagReadRows = "db.clickhouse.read_rows"; + internal const string TagReadBytes = "db.clickhouse.read_bytes"; + internal const string TagWrittenRows = "db.clickhouse.written_rows"; + internal const string TagWrittenBytes = "db.clickhouse.written_bytes"; + internal const string TagElapsedNs = "db.clickhouse.elapsed_ns"; + internal const string TagResultRows = "db.clickhouse.result_rows"; + internal const string TagResultBytes = "db.clickhouse.result_bytes"; + + /// Stands in for the operation name of a statement whose leading keyword could not be read. + internal const string UnknownOperation = "query"; + + private const string SystemName = "clickhouse"; + + // A statement whose leading keyword is longer than this is not a keyword, so no operation name is reported + // rather than putting an unbounded string into a low-cardinality attribute. + private const int MaxOperationNameLength = 16; + + internal static ActivitySource Source { get; } = CreateSource(); + + /// Starts the span for one SQL statement, naming it after the statement's leading keyword. + /// The client options the endpoint and database come from. + /// The statement, reported as db.query.text when that is enabled. + /// The statement's operation name from , or null. + /// The caller's query id, or null to let the server assign one. + /// The started span, or null when nothing is listening. + public static Activity StartStatement(ClickHouseTcpClientOptions options, string sql, string operation, string queryId) + { + Activity activity = Source.StartActivity(operation ?? UnknownOperation, ActivityKind.Client); + if (activity is null) + { + return null; + } + + if (!SetEndpointTags(activity, options)) + { + return activity; + } + + if (operation is not null) + { + activity.SetTag(TagOperationName, operation); + } + + // The join key to the server's own record of the same query, in system.query_log and + // system.opentelemetry_span_log. Only reported when the caller set one: a server-assigned id never + // reaches the client. + if (queryId is not null) + { + activity.SetTag(TagQueryId, queryId); + } + + if (options.IncludeSqlInActivityTags) + { + string text = options.StatementForTelemetry(sql); + if (text.Length != 0) + { + activity.SetTag(TagQueryText, text); + } + } + + return activity; + } + + /// Starts the span for a Ping. + /// The client options the endpoint comes from. + /// The started span, or null when nothing is listening. + public static Activity StartPing(ClickHouseTcpClientOptions options) + { + Activity activity = Source.StartActivity("ping", ActivityKind.Client); + SetEndpointTags(activity, options); + return activity; + } + + /// Starts the span covering a dial, the TLS negotiation and the handshake. + /// The client options the endpoint comes from. + /// The started span, or null when nothing is listening. + public static Activity StartConnect(ClickHouseTcpClientOptions options) + { + Activity activity = Source.StartActivity("connect", ActivityKind.Client); + SetEndpointTags(activity, options); + return activity; + } + + /// Records the accumulated progress counters for the operation. + /// The span, or null. + /// The sum of the operation's progress increments. + public static void SetProgressTotals(this Activity activity, ClickHouseTcpProgress totals) + { + if (activity is null || !activity.IsAllDataRequested) + { + return; + } + + activity.SetTag(TagReadRows, totals.Rows); + activity.SetTag(TagReadBytes, totals.Bytes); + activity.SetTag(TagElapsedNs, totals.ElapsedNs); + + // Only reported for an INSERT, and a zero tag on every SELECT would be noise. + if (totals.WroteRows != 0 || totals.WroteBytes != 0) + { + activity.SetTag(TagWrittenRows, totals.WroteRows); + activity.SetTag(TagWrittenBytes, totals.WroteBytes); + } + } + + /// Records the query's execution summary. + /// The span, or null. + /// The summary the server sent. + public static void SetProfileInfo(this Activity activity, ClickHouseTcpProfileInfo info) + { + if (activity is null || !activity.IsAllDataRequested) + { + return; + } + + activity.SetTag(TagResultRows, info.Rows); + activity.SetTag(TagResultBytes, info.Bytes); + } + + /// Marks the span as completed without error. + /// The span, or null. + public static void SetSuccess(this Activity activity) => activity?.SetStatus(ActivityStatusCode.Ok); + + /// Marks the span as failed and attaches the exception as an event. + /// The span, or null. + /// The exception that ended the operation. + public static void SetError(this Activity activity, Exception exception) + { + if (activity is null) + { + return; + } + + activity.SetStatus(ActivityStatusCode.Error, exception.Message); + + if (!activity.IsAllDataRequested) + { + return; + } + + activity.SetTag(TagErrorType, exception.GetType().FullName); + if (exception is ClickHouseServerException server) + { + activity.SetTag(TagResponseStatusCode, server.Code.ToString(CultureInfo.InvariantCulture)); + } + + activity.AddEvent(new ActivityEvent( + "exception", + tags: new ActivityTagsCollection + { + { "exception.type", exception.GetType().FullName }, + { "exception.message", exception.Message }, + { "exception.stacktrace", exception.ToString() }, + })); + } + + // Returns whether the span wants attributes at all, so a caller adding more of its own needs no second check. + private static bool SetEndpointTags(Activity activity, ClickHouseTcpClientOptions options) + { + if (activity is null || !activity.IsAllDataRequested) + { + return false; + } + + activity.SetTag(TagSystemName, SystemName); + activity.SetTag(TagServerAddress, options.Host); + activity.SetTag(TagServerPort, options.ResolvedPort); + activity.SetTag(TagNamespace, options.Database); + activity.SetTag(TagUser, options.Username); + return true; + } + + /// + /// The statement's leading keyword, uppercased — SELECT, INSERT, WITH. Null when the + /// statement does not start with a plain word, which keeps a generated or oddly-formatted statement out of + /// the span name and out of a low-cardinality attribute. + /// + /// The statement. + /// The operation name, or null when there is none to read. + public static string OperationName(string sql) + { + if (sql is null) + { + return null; + } + + int start = 0; + while (start < sql.Length && char.IsWhiteSpace(sql[start])) + { + start++; + } + + int end = start; + while (end < sql.Length && char.IsAsciiLetter(sql[end])) + { + end++; + } + + int length = end - start; + return length is > 0 and <= MaxOperationNameLength + ? sql[start..end].ToUpperInvariant() + : null; + } + + private static ActivitySource CreateSource() + { + string version = typeof(TcpActivity).Assembly.GetCustomAttribute()?.Version; + return new ActivitySource(ClickHouseTcpDiagnostics.ActivitySourceName, version); + } +} diff --git a/ClickHouse.Driver.Tcp/Logging/ClientLog.cs b/ClickHouse.Driver.Tcp/Logging/ClientLog.cs new file mode 100644 index 000000000..ebd3e546c --- /dev/null +++ b/ClickHouse.Driver.Tcp/Logging/ClientLog.cs @@ -0,0 +1,52 @@ +using System; +using Microsoft.Extensions.Logging; + +namespace ClickHouse.Driver.Tcp.Logging; + +/// +/// The messages written under . Source-generated, so a +/// disabled level formats nothing. +/// +/// +/// Every line carries QueryId, the key that joins it to the server's own record of the same query in +/// system.query_log. It is null unless the caller set +/// , a server-assigned id never being sent back. +/// +internal static partial class ClientLog +{ + [LoggerMessage( + EventId = 1000, + Level = LogLevel.Debug, + Message = "Running {Operation} (query id {QueryId}): {Sql}")] + public static partial void StatementStarted(ILogger logger, string operation, string queryId, string sql); + + [LoggerMessage( + EventId = 1001, + Level = LogLevel.Debug, + Message = "{Operation} (query id {QueryId}) completed in {ElapsedMs:0.###} ms, reading {ReadRows} rows / {ReadBytes} bytes")] + public static partial void StatementCompleted(ILogger logger, string operation, string queryId, double elapsedMs, ulong readRows, ulong readBytes); + + [LoggerMessage( + EventId = 1002, + Level = LogLevel.Error, + Message = "{Operation} (query id {QueryId}) failed after {ElapsedMs:0.###} ms")] + public static partial void StatementFailed(ILogger logger, string operation, string queryId, double elapsedMs, Exception exception); + + [LoggerMessage( + EventId = 1003, + Level = LogLevel.Debug, + Message = "{Operation} (query id {QueryId}) was abandoned after {ElapsedMs:0.###} ms with its result partly read")] + public static partial void StatementAbandoned(ILogger logger, string operation, string queryId, double elapsedMs); + + [LoggerMessage( + EventId = 1004, + Level = LogLevel.Debug, + Message = "{Operation} (query id {QueryId}) completed in {ElapsedMs:0.###} ms, writing {WrittenRows} rows / {WrittenBytes} bytes")] + public static partial void StatementWrote(ILogger logger, string operation, string queryId, double elapsedMs, ulong writtenRows, ulong writtenBytes); + + [LoggerMessage( + EventId = 1005, + Level = LogLevel.Debug, + Message = "{Operation} (query id {QueryId}) was cancelled after {ElapsedMs:0.###} ms")] + public static partial void StatementCancelled(ILogger logger, string operation, string queryId, double elapsedMs); +} diff --git a/ClickHouse.Driver.Tcp/Logging/ConnectionLog.cs b/ClickHouse.Driver.Tcp/Logging/ConnectionLog.cs new file mode 100644 index 000000000..192c8e2b8 --- /dev/null +++ b/ClickHouse.Driver.Tcp/Logging/ConnectionLog.cs @@ -0,0 +1,35 @@ +using System; +using Microsoft.Extensions.Logging; + +namespace ClickHouse.Driver.Tcp.Logging; + +/// +/// The messages written under . Source-generated, so a +/// disabled level formats nothing. +/// +internal static partial class ConnectionLog +{ + [LoggerMessage( + EventId = 2000, + Level = LogLevel.Debug, + Message = "Connecting to {Host}:{Port} as {Username} (TLS {Tls})")] + public static partial void Opening(ILogger logger, string host, int port, string username, bool tls); + + [LoggerMessage( + EventId = 2001, + Level = LogLevel.Debug, + Message = "Connected to {ServerName} {VersionMajor}.{VersionMinor}.{VersionPatch} in {ElapsedMs:0.###} ms: protocol revision {Revision}, server timezone {Timezone}")] + public static partial void Opened(ILogger logger, string serverName, int versionMajor, int versionMinor, int versionPatch, double elapsedMs, int revision, string timezone); + + [LoggerMessage( + EventId = 2002, + Level = LogLevel.Warning, + Message = "Connecting to {Host}:{Port} failed after {ElapsedMs:0.###} ms")] + public static partial void OpenFailed(ILogger logger, string host, int port, double elapsedMs, Exception exception); + + [LoggerMessage( + EventId = 2003, + Level = LogLevel.Debug, + Message = "Connecting to {Host}:{Port} was cancelled after {ElapsedMs:0.###} ms")] + public static partial void OpenCancelled(ILogger logger, string host, int port, double elapsedMs); +} diff --git a/ClickHouse.Driver.Tcp/Logging/PoolLog.cs b/ClickHouse.Driver.Tcp/Logging/PoolLog.cs new file mode 100644 index 000000000..7f3dc4a6d --- /dev/null +++ b/ClickHouse.Driver.Tcp/Logging/PoolLog.cs @@ -0,0 +1,64 @@ +using System; +using Microsoft.Extensions.Logging; + +namespace ClickHouse.Driver.Tcp.Logging; + +/// +/// The messages written under . Source-generated, so a disabled +/// level formats nothing. +/// +/// +/// Two of these report work no caller can see, because the pool deliberately swallows it: a background top-up +/// dial and a sweep both run on a timer with nobody awaiting them. Without a logger configured those failures +/// are invisible. +/// +internal static partial class PoolLog +{ + [LoggerMessage( + EventId = 3000, + Level = LogLevel.Trace, + Message = "Reusing a pooled connection, its {UsageCount} operation, open for {AgeMs:0} ms")] + public static partial void Reused(ILogger logger, int usageCount, double ageMs); + + [LoggerMessage( + EventId = 3001, + Level = LogLevel.Debug, + Message = "No idle connection to reuse; opening one")] + public static partial void Dialing(ILogger logger); + + [LoggerMessage( + EventId = 3002, + Level = LogLevel.Debug, + Message = "Closing a returned connection rather than pooling it: it is no longer reusable after {UsageCount} operations")] + public static partial void Discarded(ILogger logger, int usageCount); + + [LoggerMessage( + EventId = 3003, + Level = LogLevel.Debug, + Message = "Retired {Count} idle connections past MaxConnectionLifetime or IdleTimeout")] + public static partial void Retired(ILogger logger, int count); + + [LoggerMessage( + EventId = 3004, + Level = LogLevel.Warning, + Message = "All {MaxPoolSize} connections were in use and none became free within {TimeoutSeconds:0.###}s (PoolTimeout)")] + public static partial void Exhausted(ILogger logger, int maxPoolSize, double timeoutSeconds); + + [LoggerMessage( + EventId = 3005, + Level = LogLevel.Warning, + Message = "A background top-up towards MinPoolSize failed; the next sweep tries again")] + public static partial void RefillFailed(ILogger logger, Exception exception); + + [LoggerMessage( + EventId = 3006, + Level = LogLevel.Warning, + Message = "A pool sweep failed; the next one tries again")] + public static partial void SweepFailed(ILogger logger, Exception exception); + + [LoggerMessage( + EventId = 3007, + Level = LogLevel.Debug, + Message = "Draining the pool: closing {IdleCount} idle connections and waiting for {LeasedCount} in flight")] + public static partial void Draining(ILogger logger, int idleCount, int leasedCount); +} diff --git a/ClickHouse.Driver.Tcp/Protocol/ClickHouseTcpConnection.cs b/ClickHouse.Driver.Tcp/Protocol/ClickHouseTcpConnection.cs index aee03487f..63d34f419 100644 --- a/ClickHouse.Driver.Tcp/Protocol/ClickHouseTcpConnection.cs +++ b/ClickHouse.Driver.Tcp/Protocol/ClickHouseTcpConnection.cs @@ -1249,14 +1249,14 @@ private async ValueTask ConsumeMetadataAsync( case ServerPacketType.Progress: { - Progress progress = await Progress.ReadAsync(reader, negotiated, cancellationToken).ConfigureAwait(false); + ClickHouseTcpProgress progress = await ClickHouseTcpProgress.ReadAsync(reader, negotiated, cancellationToken).ConfigureAwait(false); handlers?.OnProgress?.Invoke(progress); break; } case ServerPacketType.ProfileInfo: { - ProfileInfo profileInfo = await ProfileInfo.ReadAsync(reader, cancellationToken).ConfigureAwait(false); + ClickHouseTcpProfileInfo profileInfo = await ClickHouseTcpProfileInfo.ReadAsync(reader, cancellationToken).ConfigureAwait(false); handlers?.OnProfileInfo?.Invoke(profileInfo); break; } diff --git a/ClickHouse.Driver.Tcp/Protocol/ClientInfo.cs b/ClickHouse.Driver.Tcp/Protocol/ClientInfo.cs index a8b1c981e..a2cb29209 100644 --- a/ClickHouse.Driver.Tcp/Protocol/ClientInfo.cs +++ b/ClickHouse.Driver.Tcp/Protocol/ClientInfo.cs @@ -1,12 +1,14 @@ using System; +using System.Diagnostics; namespace ClickHouse.Driver.Tcp.Protocol; /// /// Writes the ClientInfo block embedded in a Query packet (the TCP-interface branch). Identifies the query's /// origin and the client. Fields gate on the negotiated version; at the current ceiling every gate is active. -/// The client sends a plain initial query with no distributed context, no OpenTelemetry span, and no -/// parallel-replica coordination, so those fields are their zero/absent forms. +/// The client sends a plain initial query with no distributed context and no parallel-replica coordination, so +/// those fields are their zero/absent forms. The trace-context field carries the ambient +/// when there is one. /// internal static class ClientInfo { @@ -57,7 +59,7 @@ public static void Write(ClickHouseBinaryWriter writer, NegotiatedProtocol negot if (negotiated.Supports(ProtocolFeature.OpenTelemetry)) { - writer.WriteByte(0); // has_trace = 0 (no OpenTelemetry span) + WriteTraceContext(writer, Activity.Current); } if (negotiated.Supports(ProtocolFeature.ParallelReplicasClientInfo)) @@ -68,6 +70,42 @@ public static void Write(ClickHouseBinaryWriter writer, NegotiatedProtocol negot } } + /// + /// Writes the W3C trace context of , so the spans the server records for this + /// query (system.opentelemetry_span_log) hang off the caller's trace rather than starting their own. + /// Writes the absent form when there is no span, or when its id is not W3C — a hierarchical id has no + /// trace id to send. + /// + /// The writer to encode into. + /// The span to propagate, or null for none. + internal static void WriteTraceContext(ClickHouseBinaryWriter writer, Activity activity) + { + if (activity is null || activity.IdFormat != ActivityIdFormat.W3C) + { + writer.WriteByte(0); // has_trace = 0 + return; + } + + writer.WriteByte(1); // has_trace = 1 + + // trace_id is a UUID on the wire: two 8-byte halves, each written little-endian. A W3C trace id is 16 + // big-endian bytes, so each half is reversed. span_id is a plain little-endian UInt64, so it reverses + // whole. + Span id = stackalloc byte[16]; + activity.TraceId.CopyTo(id); + id[..8].Reverse(); + id[8..].Reverse(); + writer.WriteBytes(id); + + Span span = stackalloc byte[8]; + activity.SpanId.CopyTo(span); + span.Reverse(); + writer.WriteBytes(span); + + writer.WriteString(activity.TraceStateString ?? string.Empty); + writer.WriteByte((byte)activity.ActivityTraceFlags); + } + private static string TryGet(Func get) { try diff --git a/ClickHouse.Driver.Tcp/Protocol/MetadataHandlers.cs b/ClickHouse.Driver.Tcp/Protocol/MetadataHandlers.cs index ef3b2fa80..84f9f4f53 100644 --- a/ClickHouse.Driver.Tcp/Protocol/MetadataHandlers.cs +++ b/ClickHouse.Driver.Tcp/Protocol/MetadataHandlers.cs @@ -25,10 +25,10 @@ namespace ClickHouse.Driver.Tcp.Protocol; internal sealed class MetadataHandlers { /// Invoked for each Progress packet, which the server sends repeatedly as work advances. - public Action OnProgress { get; init; } + public Action OnProgress { get; init; } /// Invoked for the ProfileInfo summary (rows/blocks/bytes read, limit application). - public Action OnProfileInfo { get; init; } + public Action OnProfileInfo { get; init; } /// Invoked with the borrowed Totals block (the WITH TOTALS row). Valid only for the call. public Action OnTotals { get; init; } diff --git a/ClickHouse.Driver.Tcp/Protocol/Progress.cs b/ClickHouse.Driver.Tcp/Protocol/Progress.cs deleted file mode 100644 index 8c8c38b78..000000000 --- a/ClickHouse.Driver.Tcp/Protocol/Progress.cs +++ /dev/null @@ -1,74 +0,0 @@ -using System.Threading; -using System.Threading.Tasks; - -namespace ClickHouse.Driver.Tcp.Protocol; - -/// -/// A decoded Progress packet: cumulative counters the server emits as a query runs. Each packet is a delta; -/// callers accumulate. -/// -internal readonly struct Progress -{ - /// Initializes a new instance of the struct. - /// Rows read so far (delta). - /// Bytes read so far (delta). - /// Total rows to read, if known. - /// Rows written (INSERT), if applicable. - /// Bytes written (INSERT), if applicable. - /// Server-side elapsed time in nanoseconds. - public Progress(ulong rows, ulong bytes, ulong totalRows, ulong wroteRows, ulong wroteBytes, ulong elapsedNs) - { - Rows = rows; - Bytes = bytes; - TotalRows = totalRows; - WroteRows = wroteRows; - WroteBytes = wroteBytes; - ElapsedNs = elapsedNs; - } - - /// Rows read (delta). - public ulong Rows { get; } - - /// Bytes read (delta). - public ulong Bytes { get; } - - /// Total rows to read, if known. - public ulong TotalRows { get; } - - /// Rows written (delta), for INSERT. - public ulong WroteRows { get; } - - /// Bytes written (delta), for INSERT. - public ulong WroteBytes { get; } - - /// Server-side elapsed time in nanoseconds. - public ulong ElapsedNs { get; } - - /// Reads a Progress packet body at the negotiated version. - /// The reader positioned at the packet body. - /// The negotiated protocol, gating the trailing counters. - /// A token to observe for cancellation. - /// The decoded progress. - public static async ValueTask ReadAsync(ClickHouseBinaryReader reader, NegotiatedProtocol negotiated, CancellationToken cancellationToken) - { - ulong rows = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); - ulong bytes = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); - ulong totalRows = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); - - ulong wroteRows = 0; - ulong wroteBytes = 0; - if (negotiated.Supports(ProtocolFeature.ProgressWriteInfo)) - { - wroteRows = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); - wroteBytes = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); - } - - ulong elapsedNs = 0; - if (negotiated.Supports(ProtocolFeature.ProgressElapsedNs)) - { - elapsedNs = await reader.ReadVarUIntAsync(cancellationToken).ConfigureAwait(false); - } - - return new Progress(rows, bytes, totalRows, wroteRows, wroteBytes, elapsedNs); - } -} From edfe070609eef6179a31e81bbddf623dc34edd70 Mon Sep 17 00:00:00 2001 From: Alex Soffronow-Pagonidis Date: Tue, 25 Aug 2026 13:56:28 +0200 Subject: [PATCH 2/6] Report an insert's own row count, and keep a logger from breaking an operation An insert reported an empty read. The completion line and the span counters were chosen from the Progress write counters, so an insert logged "reading 0 rows / 0 bytes" and its span carried read_rows=0 and elapsed_ns=0. The server sends no Progress packet for rows a client streams to it, at any size, so that branch was never reached. The row count now comes from what the client sent, and a statement the server reported no counters for gets no counter attributes instead of zeroes. Build the loggers through DiagnosticLogger.Create, which wraps the caller's logger so it cannot throw into the driver. The log calls sit between the steps that hand a connection from one owner to the next, where an exception left a socket with nobody to close it. A caller callback still propagates: that is the caller's own code acting on their data, where failing the operation is a defensible answer. Co-Authored-By: Claude --- .../Client/ConnectionPoolLoggingTests.cs | 23 +++++ .../Diagnostic/ClientOperationTests.cs | 28 +++++- .../Diagnostic/DiagnosticLoggerTests.cs | 86 +++++++++++++++++++ .../Diagnostic/TcpActivityTests.cs | 48 +++++++++-- .../ClickHouseTcpCallbackIntegrationTests.cs | 4 +- .../ClickHouseTcpLoggingIntegrationTests.cs | 48 ++++++++++- .../Utilities/CapturingLogger.cs | 27 ++++++ .../Client/ClickHouseTcpClient.cs | 10 +-- .../Client/ClickHouseTcpClientOptions.cs | 7 +- .../Client/ConnectionPool.cs | 3 +- .../Client/IConnectionFactory.cs | 2 +- .../Diagnostic/ClientOperation.cs | 18 ++-- .../Diagnostic/DiagnosticLogger.cs | 79 +++++++++++++++++ .../Diagnostic/TcpActivity.cs | 29 ++++++- ClickHouse.Driver.Tcp/Logging/ClientLog.cs | 4 +- 15 files changed, 385 insertions(+), 31 deletions(-) create mode 100644 ClickHouse.Driver.Tcp.Tests/Diagnostic/DiagnosticLoggerTests.cs create mode 100644 ClickHouse.Driver.Tcp/Diagnostic/DiagnosticLogger.cs diff --git a/ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolLoggingTests.cs b/ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolLoggingTests.cs index 5d087f55c..e706fe35b 100644 --- a/ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolLoggingTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolLoggingTests.cs @@ -194,4 +194,27 @@ public async Task DisposeAsync_OpenPool_LogsTheDrain() LogEntry draining = Log.WithEventId(3007).Single(); Assert.That(draining.Message, Does.Contain("closing 1 idle")); } + + [Test] + public async Task RentAsync_ThrowingLogger_StillHandsOverTheConnection() + { + // The pool logs at the points a connection is between owners: taken out of the idle list but not yet + // leased, or out of the leased set but not yet closed. An exception from any of those calls would leave a + // socket with nobody left to close it, so a broken logger would read as the client leaking connections. + var connections = new FakeConnectionFactory(); + var pool = new ConnectionPool(Options() with { LoggerFactory = new ThrowingLoggerFactory() }, connections, new ControlledTimeProvider()); + + await using (IConnectionLease first = await pool.RentAsync(None)) + { + } + + await using (IConnectionLease reused = await pool.RentAsync(None)) + { + Assert.That(connections.CreateCount, Is.EqualTo(1), "the reuse path survived its log call"); + } + + await pool.DisposeAsync(); + + Assert.That(connections.Disposed, Is.True, "and teardown ran to the end"); + } } diff --git a/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs b/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs index 7e08144e2..df5e92230 100644 --- a/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs @@ -1,4 +1,5 @@ using System.Diagnostics; +using System.Linq; using ClickHouse.Driver.Tcp.Diagnostic; using ClickHouse.Driver.Tcp.Logging; using ClickHouse.Driver.Tcp.Tests.Utilities; @@ -59,12 +60,33 @@ public void Start_LoggerOnly_AccumulatesTheCountersTheCompletionLineNeeds() } [Test] - public void Succeeded_WriteCounters_ReportsWhatWasWrittenInsteadOfZeroRowsRead() + public void Succeeded_RowsSentAndNoProgressPacket_ReportsTheRowsSentInsteadOfZeroRowsRead() { + // The shape every insert takes. The server sends no Progress for the rows a client streams to it, so a + // line chosen from the Progress counters would report every insert as a read of nothing. using var factory = new CapturingLoggerFactory(); CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); using (ClientOperation operation = ClientOperation.Start(Options, logger, "INSERT INTO t VALUES", queryId: null, callbacks: null)) + { + operation.Succeeded(rowsSent: 5); + } + + Assert.Multiple(() => + { + Assert.That(logger.WithEventId(1004).Single().Message, Does.Contain("writing 5 rows")); + Assert.That(logger.WithEventId(1001), Is.Empty, "and not a read line of zeroes"); + }); + } + + [Test] + public void Succeeded_ServerReportedWriteCounters_ReportsThem() + { + // Reached by an INSERT ... SELECT, which the client runs as a statement and so sends no rows for. + using var factory = new CapturingLoggerFactory(); + CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); + + using (ClientOperation operation = ClientOperation.Start(Options, logger, "INSERT INTO t SELECT 1", queryId: null, callbacks: null)) { operation.Handlers.OnProgress(new ClickHouseTcpProgress(0, 0, 0, 5, 40, 1)); operation.Succeeded(); @@ -72,8 +94,8 @@ public void Succeeded_WriteCounters_ReportsWhatWasWrittenInsteadOfZeroRowsRead() Assert.Multiple(() => { - Assert.That(logger.WithEventId(1004), Is.Not.Empty, "an insert reports what it wrote"); - Assert.That(logger.WithEventId(1001), Is.Empty, "and not a read line of zeroes"); + Assert.That(logger.WithEventId(1004).Single().Message, Does.Contain("writing 5 rows")); + Assert.That(logger.WithEventId(1001), Is.Empty); }); } diff --git a/ClickHouse.Driver.Tcp.Tests/Diagnostic/DiagnosticLoggerTests.cs b/ClickHouse.Driver.Tcp.Tests/Diagnostic/DiagnosticLoggerTests.cs new file mode 100644 index 000000000..7f37fb328 --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Diagnostic/DiagnosticLoggerTests.cs @@ -0,0 +1,86 @@ +using System; +using ClickHouse.Driver.Tcp.Diagnostic; +using ClickHouse.Driver.Tcp.Tests.Utilities; +using Microsoft.Extensions.Logging; + +namespace ClickHouse.Driver.Tcp.Tests.Diagnostic; + +// The guard around a caller's logger. Its point is what happens at the sites the log calls sit between — a +// connection taken from the idle list but not yet leased, opened but not yet handed back — where an exception +// would leave a socket nobody owns. That consequence is covered where those sites are; this pins the boundary +// itself, which nothing else can observe. +[TestFixture] +public class DiagnosticLoggerTests +{ + private const string Category = "ClickHouse.Driver.Tcp.Tests"; + + [Test] + public void Create_NoFactory_ReturnsNull() + { + Assert.That(DiagnosticLogger.Create(null, Category), Is.Null, "no factory means no logger to call"); + } + + [Test] + public void Log_LoggerThrows_Swallows() + { + ILogger logger = DiagnosticLogger.Create(new ThrowingLoggerFactory(), Category); + + Assert.DoesNotThrow(() => logger.LogInformation("anything")); + } + + [Test] + public void IsEnabled_LoggerThrows_ReadsAsDisabled() + { + // Reported as off rather than on: the source-generated methods check it first, so a false here also keeps + // them from formatting a message for a logger that cannot take it. + ILogger logger = DiagnosticLogger.Create(new ThrowingLoggerFactory(), Category); + + Assert.That(logger.IsEnabled(LogLevel.Error), Is.False); + } + + [Test] + public void BeginScope_LoggerThrows_ReturnsNull() + { + ILogger logger = DiagnosticLogger.Create(new ThrowingLoggerFactory(), Category); + + Assert.That(logger.BeginScope("scope"), Is.Null); + } + + [Test] + public void Log_WorkingLogger_ReachesIt() + { + var factory = new RecordingLoggerFactory(); + ILogger logger = DiagnosticLogger.Create(factory, Category); + + logger.LogInformation("through the guard"); + + Assert.That(factory.Logger.Written, Is.EqualTo(1), "the guard forwards rather than replacing"); + } + + private sealed class RecordingLoggerFactory : ILoggerFactory + { + public RecordingLogger Logger { get; } = new(); + + public ILogger CreateLogger(string categoryName) => Logger; + + public void AddProvider(ILoggerProvider provider) + { + } + + public void Dispose() + { + } + + internal sealed class RecordingLogger : ILogger + { + public int Written { get; private set; } + + public IDisposable BeginScope(TState state) => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + => Written++; + } + } +} diff --git a/ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs b/ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs index 672549a96..bb5a3b9e4 100644 --- a/ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs @@ -146,11 +146,11 @@ public void StartStatement_NoQueryId_OmitsTheAttribute() } [Test] - public void SetProgressTotals_ReadCounters_SetsTheReadAttributesAndOmitsTheWriteOnes() + public void SetCounters_ReadCounters_SetsTheReadAttributesAndOmitsTheWriteOnes() { using (Activity activity = TcpActivity.StartStatement(Options, "SELECT 1", "SELECT", queryId: null)) { - activity.SetProgressTotals(new ClickHouseTcpProgress(rows: 12, bytes: 96, totalRows: 12, wroteRows: 0, wroteBytes: 0, elapsedNs: 5000)); + activity.SetCounters(new ClickHouseTcpProgress(rows: 12, bytes: 96, totalRows: 12, wroteRows: 0, wroteBytes: 0, elapsedNs: 5000), rowsSent: null); } Activity span = Single(); @@ -165,11 +165,12 @@ public void SetProgressTotals_ReadCounters_SetsTheReadAttributesAndOmitsTheWrite } [Test] - public void SetProgressTotals_WriteCounters_SetsTheWriteAttributes() + public void SetCounters_WriteCountersFromTheServer_SetsTheWriteAttributes() { - using (Activity activity = TcpActivity.StartStatement(Options, "INSERT INTO t VALUES", "INSERT", queryId: null)) + // Reached by an INSERT ... SELECT, the case the server does report write counters for. + using (Activity activity = TcpActivity.StartStatement(Options, "INSERT INTO t SELECT 1", "INSERT", queryId: null)) { - activity.SetProgressTotals(new ClickHouseTcpProgress(rows: 0, bytes: 0, totalRows: 0, wroteRows: 7, wroteBytes: 56, elapsedNs: 1)); + activity.SetCounters(new ClickHouseTcpProgress(rows: 9, bytes: 72, totalRows: 9, wroteRows: 7, wroteBytes: 56, elapsedNs: 1), rowsSent: null); } Activity span = Single(); @@ -180,6 +181,43 @@ public void SetProgressTotals_WriteCounters_SetsTheWriteAttributes() }); } + [Test] + public void SetCounters_NoProgressPacket_ReportsOnlyTheRowsTheClientSent() + { + // The shape every insert takes: the server counts nothing back to the client, so zero read counters would + // claim it reported reading nothing rather than reporting nothing at all. + using (Activity activity = TcpActivity.StartStatement(Options, "INSERT INTO t VALUES", "INSERT", queryId: null)) + { + activity.SetCounters(default, rowsSent: 3); + } + + Activity span = Single(); + Assert.Multiple(() => + { + Assert.That(span.GetTagItem("db.clickhouse.written_rows"), Is.EqualTo(3UL)); + Assert.That(span.GetTagItem("db.clickhouse.read_rows"), Is.Null); + Assert.That(span.GetTagItem("db.clickhouse.read_bytes"), Is.Null); + Assert.That(span.GetTagItem("db.clickhouse.elapsed_ns"), Is.Null, "a span claiming zero server time is worse than one claiming none"); + }); + } + + [Test] + public void SetCounters_ProgressWithoutWriteCounters_StillReportsTheRowsTheClientSent() + { + using (Activity activity = TcpActivity.StartStatement(Options, "INSERT INTO t VALUES", "INSERT", queryId: null)) + { + activity.SetCounters(new ClickHouseTcpProgress(rows: 0, bytes: 0, totalRows: 0, wroteRows: 0, wroteBytes: 0, elapsedNs: 4000), rowsSent: 3); + } + + Activity span = Single(); + Assert.Multiple(() => + { + Assert.That(span.GetTagItem("db.clickhouse.written_rows"), Is.EqualTo(3UL)); + Assert.That(span.GetTagItem("db.clickhouse.elapsed_ns"), Is.EqualTo(4000UL)); + Assert.That(span.GetTagItem("db.clickhouse.written_bytes"), Is.Null, "nothing reported it"); + }); + } + [Test] public void SetProfileInfo_Summary_SetsTheResultAttributes() { diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs index 659de3822..43f205e54 100644 --- a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs @@ -203,7 +203,7 @@ public async Task InsertAsync_Callbacks_ReachTheInsertAndReportTheRowsInserted() // callbacks reached the write path. Which counters appear is not asserted — the set differs by server // version — only that they decode. await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); - string table = $"tcp_callback_test_{Guid.NewGuid():N}"; + string table = UniqueTableName(); await client.ExecuteAsync($"CREATE TABLE {table} (id Int32) ENGINE = Memory", cancellationToken: None); try @@ -261,4 +261,6 @@ await DrainAsync( Assert.That(survived, Is.EqualTo(1)); } + + private static string UniqueTableName() => $"tcp_callback_test_{Guid.NewGuid():N}"; } diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs index 89606cb52..6c24db11d 100644 --- a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs @@ -114,7 +114,7 @@ public async Task StreamAsync_AbandonedMidResult_LogsThatItWasAbandoned() public async Task InsertAsync_WithALoggerFactory_LogsTheInsertAsItsOwnOperation() { await using ClickHouseTcpClient client = CreateClient(); - string table = $"tcp_logging_test_{Guid.NewGuid():N}"; + string table = UniqueTableName(); await client.ExecuteAsync($"CREATE TABLE {table} (id Int32) ENGINE = Memory", cancellationToken: None); try @@ -133,6 +133,52 @@ await client.InsertAsync( } } + [Test] + public async Task InsertAsync_WithALoggerFactory_ReportsTheRowsSentRatherThanAnEmptyRead() + { + // Against a real server, because the counters an insert has are not the ones a query has: the server sends + // no Progress packet for rows streamed to it, whatever the size, so a completion line taken from the + // Progress counters reports every insert as a read of nothing. + await using ClickHouseTcpClient client = CreateClient(); + string table = UniqueTableName(); + await client.ExecuteAsync($"CREATE TABLE {table} (id Int32) ENGINE = Memory", cancellationToken: None); + + try + { + await client.InsertAsync( + $"INSERT INTO {table} (id) VALUES", + new IColumn[] { PrimitiveColumn.FromValues("id", "Int32", [1, 2, 3]) }, + cancellationToken: None); + + Assert.Multiple(() => + { + Assert.That(ClientLogger.WithEventId(1004).Single().Message, Does.Contain("writing 3 rows")); + Assert.That( + ClientLogger.WithEventId(1001).Where(e => e.Message.Contains("INSERT", StringComparison.Ordinal)), + Is.Empty, + "an insert is not also reported as a completed read"); + }); + } + finally + { + await client.ExecuteAsync($"DROP TABLE IF EXISTS {table}", cancellationToken: None); + } + } + + [Test] + public async Task StreamAsync_ThrowingLogger_RunsTheStatementAnyway() + { + // A logger is infrastructure, so losing a log line beats losing the query. This is the opposite of the + // rule for a caller callback, which is documented to propagate and end the operation. + await using ClickHouseTcpClient client = new(TcpServerFixture.Options() with { LoggerFactory = new ThrowingLoggerFactory() }); + + List rows = await client.QueryAsync("SELECT 1", cancellationToken: None).ToListAsync(); + + Assert.That((byte)rows[0][0], Is.EqualTo((byte)1)); + } + + private static string UniqueTableName() => $"tcp_logging_test_{Guid.NewGuid():N}"; + [Test] public async Task StreamAsync_LoggerFactoryBelowDebug_LogsNothingForASuccessfulStatement() { diff --git a/ClickHouse.Driver.Tcp.Tests/Utilities/CapturingLogger.cs b/ClickHouse.Driver.Tcp.Tests/Utilities/CapturingLogger.cs index d64988cc5..75037f244 100644 --- a/ClickHouse.Driver.Tcp.Tests/Utilities/CapturingLogger.cs +++ b/ClickHouse.Driver.Tcp.Tests/Utilities/CapturingLogger.cs @@ -146,3 +146,30 @@ public void Dispose() { } } + +/// +/// A logger factory whose loggers throw from every member, for asserting that a broken logger cannot break the +/// operation it was reporting on. +/// +internal sealed class ThrowingLoggerFactory : ILoggerFactory +{ + public ILogger CreateLogger(string categoryName) => new ThrowingLogger(); + + public void AddProvider(ILoggerProvider provider) => throw new NotSupportedException(); + + public void Dispose() + { + } + + private sealed class ThrowingLogger : ILogger + { + public IDisposable BeginScope(TState state) + where TState : notnull + => throw new InvalidOperationException("from BeginScope"); + + public bool IsEnabled(LogLevel logLevel) => throw new InvalidOperationException("from IsEnabled"); + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + => throw new InvalidOperationException("from Log"); + } +} diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs index b2302600f..069d51c27 100644 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs @@ -83,7 +83,7 @@ public ClickHouseTcpClient(ClickHouseTcpClientOptions options) ArgumentNullException.ThrowIfNull(options); options.Validate(); Options = options.WithOwnedCustomSettings(); - logger = Options.LoggerFactory?.CreateLogger(ClickHouseTcpDiagnostics.ClientLogCategory); + logger = DiagnosticLogger.Create(Options.LoggerFactory, ClickHouseTcpDiagnostics.ClientLogCategory); source = new ConnectionPool(Options); } @@ -112,7 +112,7 @@ internal ClickHouseTcpClient( this.source = source; ClickHouseTcpClientOptions resolved = options ?? new ClickHouseTcpClientOptions(); Options = optionsAreOwned ? resolved : resolved.WithOwnedCustomSettings(); - logger = Options.LoggerFactory?.CreateLogger(ClickHouseTcpDiagnostics.ClientLogCategory); + logger = DiagnosticLogger.Create(Options.LoggerFactory, ClickHouseTcpDiagnostics.ClientLogCategory); } /// @@ -401,7 +401,7 @@ await lease.Connection.InsertAsync( Options.MaxSendBufferBytes, operation?.Handlers, cancellationToken).ConfigureAwait(false); - operation?.Succeeded(); + operation?.Succeeded(columns.Count == 0 ? 0UL : (ulong)columns[0].RowCount); } catch (Exception e) { @@ -449,7 +449,7 @@ await lease.Connection.InsertAsync( Options.MaxSendBufferBytes, operation?.Handlers, cancellationToken).ConfigureAwait(false); - operation?.Succeeded(); + operation?.Succeeded((ulong)buffer.Count); } catch (Exception e) { @@ -487,7 +487,7 @@ await lease.Connection.InsertAsync( Options.MaxSendBufferBytes, operation?.Handlers, cancellationToken).ConfigureAwait(false); - operation?.Succeeded(); + operation?.Succeeded((ulong)buffer.Count); } catch (Exception e) { diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs index 5f7147d23..f9042e938 100644 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs @@ -299,10 +299,11 @@ public sealed record ClickHouseTcpClientOptions /// logging. Nothing is formatted while the matching category and level are disabled. /// /// - /// At Debug the statement text is logged in full. That is deliberate — a driver log without the - /// statement is hard to use — but it is not the same policy as + /// At Debug the statement text is logged, up to characters. That is + /// deliberate — a driver log without the statement is hard to use — but it is not the same policy as /// , which keeps the statement out of traces unless asked. Enable - /// Debug on ClickHouse.Driver.Tcp.Client only where the statements may be recorded. + /// Debug on ClickHouse.Driver.Tcp.Client only where the statements may be recorded, or set + /// to zero to keep them out of both channels. /// /// public ILoggerFactory LoggerFactory { get; init; } diff --git a/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs b/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs index b416976a4..b9df7f480 100644 --- a/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs +++ b/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs @@ -3,6 +3,7 @@ using System.Globalization; using System.Threading; using System.Threading.Tasks; +using ClickHouse.Driver.Tcp.Diagnostic; using ClickHouse.Driver.Tcp.Logging; using ClickHouse.Driver.Tcp.Protocol; using Microsoft.Extensions.Logging; @@ -119,7 +120,7 @@ internal ConnectionPool(ClickHouseTcpClientOptions options, IConnectionFactory f this.options = options; this.factory = factory; this.time = time; - logger = options.LoggerFactory?.CreateLogger(ClickHouseTcpDiagnostics.PoolLogCategory); + logger = DiagnosticLogger.Create(options.LoggerFactory, ClickHouseTcpDiagnostics.PoolLogCategory); permits = new SemaphoreSlim(options.MaxPoolSize, options.MaxPoolSize); TimeSpan period = SweepInterval(options); diff --git a/ClickHouse.Driver.Tcp/Client/IConnectionFactory.cs b/ClickHouse.Driver.Tcp/Client/IConnectionFactory.cs index 6e9599f3b..835bcb6e3 100644 --- a/ClickHouse.Driver.Tcp/Client/IConnectionFactory.cs +++ b/ClickHouse.Driver.Tcp/Client/IConnectionFactory.cs @@ -47,7 +47,7 @@ internal TcpConnectionFactory(ClickHouseTcpClientOptions options) { this.options = options; tls = BuildTlsParameters(options); - logger = options.LoggerFactory?.CreateLogger(ClickHouseTcpDiagnostics.ConnectionLogCategory); + logger = DiagnosticLogger.Create(options.LoggerFactory, ClickHouseTcpDiagnostics.ConnectionLogCategory); } /// diff --git a/ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs b/ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs index e31e47969..0573e7aa4 100644 --- a/ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs +++ b/ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs @@ -25,6 +25,7 @@ internal sealed class ClientOperation : IDisposable private readonly string queryId; private readonly long startedAt; private ClickHouseTcpProgress totals; + private ulong? rowsSent; private bool ended; private ClientOperation(Activity activity, ILogger logger, string operationName, string queryId) @@ -82,9 +83,14 @@ public static ClientOperation Start( } /// Records that the operation ran to completion. - public void Succeeded() + /// + /// The rows the client sent, for an insert; null for a statement that only reads. The server sends no Progress + /// packet for rows a client streams to it, so this is the only count an insert has. + /// + public void Succeeded(ulong? rowsSent = null) { ended = true; + this.rowsSent = rowsSent; activity?.SetSuccess(); if (logger is null) @@ -92,11 +98,11 @@ public void Succeeded() return; } - // An insert reports what it wrote and a query what it read, so the line carries whichever the server - // counted rather than a row of zeroes for the other. - if (totals.WroteRows != 0 || totals.WroteBytes != 0) + // An insert reports the rows it wrote and a query the rows it read. Two messages rather than one, so + // neither has to carry a field of zeroes for the other. + if (rowsSent.HasValue || totals.WroteRows != 0) { - ClientLog.StatementWrote(logger, operationName, queryId, Elapsed(), totals.WroteRows, totals.WroteBytes); + ClientLog.StatementWrote(logger, operationName, queryId, Elapsed(), rowsSent ?? totals.WroteRows); } else { @@ -131,7 +137,7 @@ public void Failed(Exception exception) /// Writes the accumulated counters and ends the span. public void Dispose() { - activity?.SetProgressTotals(totals); + activity?.SetCounters(totals, rowsSent); activity?.Dispose(); // Neither succeeded nor failed means the caller stopped reading a result part-way. Worth a line, because diff --git a/ClickHouse.Driver.Tcp/Diagnostic/DiagnosticLogger.cs b/ClickHouse.Driver.Tcp/Diagnostic/DiagnosticLogger.cs new file mode 100644 index 000000000..7e0213d84 --- /dev/null +++ b/ClickHouse.Driver.Tcp/Diagnostic/DiagnosticLogger.cs @@ -0,0 +1,79 @@ +using System; +using Microsoft.Extensions.Logging; + +namespace ClickHouse.Driver.Tcp.Diagnostic; + +/// +/// Builds the client's loggers, wrapped so that a logger which throws cannot break the operation it was +/// reporting on. +/// +/// +/// +/// The guard matters because of where the log calls sit: between the steps that hand a connection from one owner +/// to the next — taken from the idle list but not yet leased, opened but not yet returned to the caller. An +/// exception out of any of them would leave a socket that no owner is left to close, so a broken logger would +/// surface as the client leaking connections. +/// +/// +/// A caller callback is deliberately not treated this way and still propagates: that is the caller's own code +/// acting on their own data, where failing the operation is a defensible answer. A logger is infrastructure, and +/// losing a log line is always better than losing the query. +/// +/// +internal static class DiagnosticLogger +{ + /// The logger for one category, guarded, or null when no factory is configured. + /// The caller's logger factory, or null to log nothing. + /// The category to log under. + /// The logger to pass to the log methods, or null. + public static ILogger Create(ILoggerFactory factory, string category) + { + // Not guarded: a factory that cannot build a logger fails at client construction, where the caller sees it. + ILogger inner = factory?.CreateLogger(category); + return inner is null ? null : new NoThrowLogger(inner); + } + + private sealed class NoThrowLogger : ILogger + { + private readonly ILogger inner; + + public NoThrowLogger(ILogger inner) => this.inner = inner; + + public IDisposable BeginScope(TState state) + { + try + { + return inner.BeginScope(state); + } + catch (Exception) + { + return null; + } + } + + public bool IsEnabled(LogLevel logLevel) + { + try + { + return inner.IsEnabled(logLevel); + } + catch (Exception) + { + // Read as "this level is off", so nothing is formatted for it either. + return false; + } + } + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + try + { + inner.Log(logLevel, eventId, state, exception, formatter); + } + catch (Exception) + { + // There is nowhere to report a logger that cannot log. + } + } + } +} diff --git a/ClickHouse.Driver.Tcp/Diagnostic/TcpActivity.cs b/ClickHouse.Driver.Tcp/Diagnostic/TcpActivity.cs index 3425707f5..1fc4ff31d 100644 --- a/ClickHouse.Driver.Tcp/Diagnostic/TcpActivity.cs +++ b/ClickHouse.Driver.Tcp/Diagnostic/TcpActivity.cs @@ -17,6 +17,10 @@ namespace ClickHouse.Driver.Tcp.Diagnostic; /// db.system/db.statement/peer.service set the HTTP transport still emits. Two are outside /// that set: db.user, which the conventions dropped without a replacement and the HTTP transport also /// emits, and the db.clickhouse.* counters, which are shared with it. +/// +/// The counters come from the server's Progress packets except for db.clickhouse.written_rows on an +/// insert, which is what the client sent: the server sends no Progress for rows streamed to it. +/// /// internal static class TcpActivity { @@ -113,26 +117,45 @@ public static Activity StartConnect(ClickHouseTcpClientOptions options) return activity; } - /// Records the accumulated progress counters for the operation. + /// Records the operation's row and byte counters. /// The span, or null. /// The sum of the operation's progress increments. - public static void SetProgressTotals(this Activity activity, ClickHouseTcpProgress totals) + /// The rows the client sent, for an insert; null for a statement that only reads. + public static void SetCounters(this Activity activity, ClickHouseTcpProgress totals, ulong? rowsSent) { if (activity is null || !activity.IsAllDataRequested) { return; } + // An insert gets no Progress packet at all: the server does not count the rows a client streams to it back + // to that client. Reporting the read counters as zero would then claim it read nothing and spent no time, + // when the truth is that it said nothing, so the only counter to set is the client's own row count. + if (totals == default) + { + if (rowsSent.HasValue) + { + activity.SetTag(TagWrittenRows, rowsSent.Value); + } + + return; + } + activity.SetTag(TagReadRows, totals.Rows); activity.SetTag(TagReadBytes, totals.Bytes); activity.SetTag(TagElapsedNs, totals.ElapsedNs); - // Only reported for an INSERT, and a zero tag on every SELECT would be noise. + // The statements the server does count writes for, an INSERT ... SELECT among them. A zero pair on every + // SELECT would be noise, so they are reported only once there is something to report. if (totals.WroteRows != 0 || totals.WroteBytes != 0) { activity.SetTag(TagWrittenRows, totals.WroteRows); activity.SetTag(TagWrittenBytes, totals.WroteBytes); } + else if (rowsSent.HasValue) + { + activity.SetTag(TagWrittenRows, rowsSent.Value); + } } /// Records the query's execution summary. diff --git a/ClickHouse.Driver.Tcp/Logging/ClientLog.cs b/ClickHouse.Driver.Tcp/Logging/ClientLog.cs index ebd3e546c..ce1288962 100644 --- a/ClickHouse.Driver.Tcp/Logging/ClientLog.cs +++ b/ClickHouse.Driver.Tcp/Logging/ClientLog.cs @@ -41,8 +41,8 @@ internal static partial class ClientLog [LoggerMessage( EventId = 1004, Level = LogLevel.Debug, - Message = "{Operation} (query id {QueryId}) completed in {ElapsedMs:0.###} ms, writing {WrittenRows} rows / {WrittenBytes} bytes")] - public static partial void StatementWrote(ILogger logger, string operation, string queryId, double elapsedMs, ulong writtenRows, ulong writtenBytes); + Message = "{Operation} (query id {QueryId}) completed in {ElapsedMs:0.###} ms, writing {WrittenRows} rows")] + public static partial void StatementWrote(ILogger logger, string operation, string queryId, double elapsedMs, ulong writtenRows); [LoggerMessage( EventId = 1005, From 8d0a137e76de56f63086884e597659c0c373b989 Mon Sep 17 00:00:00 2001 From: Alex Soffronow-Pagonidis Date: Tue, 25 Aug 2026 14:28:49 +0200 Subject: [PATCH 3/6] Prove the write counters against a server instead of a hand-fed packet MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The write branch of the completion line and the span counters were pinned only by unit tests that fed in a Progress packet of my own making, which is how the insert misreport survived: the shape those tests described was one the server never sends. Both branches now have integration coverage — an insert reports the rows the client sent, an INSERT ... SELECT reports the counters the server sent — and the unit tests they restate are gone. Co-Authored-By: Claude --- .../Diagnostic/ClientOperationTests.cs | 41 ------------- .../ClickHouseTcpLoggingIntegrationTests.cs | 23 +++++++ .../ClickHouseTcpTracingIntegrationTests.cs | 60 +++++++++++++++++++ 3 files changed, 83 insertions(+), 41 deletions(-) diff --git a/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs b/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs index df5e92230..fbc433a7d 100644 --- a/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs @@ -1,5 +1,4 @@ using System.Diagnostics; -using System.Linq; using ClickHouse.Driver.Tcp.Diagnostic; using ClickHouse.Driver.Tcp.Logging; using ClickHouse.Driver.Tcp.Tests.Utilities; @@ -59,46 +58,6 @@ public void Start_LoggerOnly_AccumulatesTheCountersTheCompletionLineNeeds() Assert.That(completed.Message, Does.Contain("reading 10 rows"), "the increments are summed, not overwritten"); } - [Test] - public void Succeeded_RowsSentAndNoProgressPacket_ReportsTheRowsSentInsteadOfZeroRowsRead() - { - // The shape every insert takes. The server sends no Progress for the rows a client streams to it, so a - // line chosen from the Progress counters would report every insert as a read of nothing. - using var factory = new CapturingLoggerFactory(); - CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); - - using (ClientOperation operation = ClientOperation.Start(Options, logger, "INSERT INTO t VALUES", queryId: null, callbacks: null)) - { - operation.Succeeded(rowsSent: 5); - } - - Assert.Multiple(() => - { - Assert.That(logger.WithEventId(1004).Single().Message, Does.Contain("writing 5 rows")); - Assert.That(logger.WithEventId(1001), Is.Empty, "and not a read line of zeroes"); - }); - } - - [Test] - public void Succeeded_ServerReportedWriteCounters_ReportsThem() - { - // Reached by an INSERT ... SELECT, which the client runs as a statement and so sends no rows for. - using var factory = new CapturingLoggerFactory(); - CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); - - using (ClientOperation operation = ClientOperation.Start(Options, logger, "INSERT INTO t SELECT 1", queryId: null, callbacks: null)) - { - operation.Handlers.OnProgress(new ClickHouseTcpProgress(0, 0, 0, 5, 40, 1)); - operation.Succeeded(); - } - - Assert.Multiple(() => - { - Assert.That(logger.WithEventId(1004).Single().Message, Does.Contain("writing 5 rows")); - Assert.That(logger.WithEventId(1001), Is.Empty); - }); - } - [Test] public void Dispose_NeitherSucceededNorFailed_ReportsTheOperationAbandoned() { diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs index 6c24db11d..0f0800f05 100644 --- a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs @@ -165,6 +165,29 @@ await client.InsertAsync( } } + [Test] + public async Task ExecuteAsync_InsertSelect_ReportsTheRowsTheServerCounted() + { + // The other half of the write line, and the half that does come from the server: an INSERT ... SELECT sends + // no rows from the client, and the server reports what it wrote in a Progress packet. Asserted against a + // real server because the counters an insert has are a server behaviour, not a client one. + await using ClickHouseTcpClient client = CreateClient(); + string table = UniqueTableName(); + await client.ExecuteAsync($"CREATE TABLE {table} (id UInt64) ENGINE = Memory", cancellationToken: None); + + try + { + await client.ExecuteAsync($"INSERT INTO {table} SELECT number FROM numbers(1000)", cancellationToken: None); + + LogEntry wrote = ClientLogger.WithEventId(1004).Single(); + Assert.That(wrote.Message, Does.Contain("writing 1000 rows")); + } + finally + { + await client.ExecuteAsync($"DROP TABLE IF EXISTS {table}", cancellationToken: None); + } + } + [Test] public async Task StreamAsync_ThrowingLogger_RunsTheStatementAnyway() { diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpTracingIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpTracingIntegrationTests.cs index 7ae524a6a..17808c212 100644 --- a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpTracingIntegrationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpTracingIntegrationTests.cs @@ -61,6 +61,64 @@ public async Task StreamAsync_WithAListener_ProducesOneSpanCarryingTheServerCoun }); } + [Test] + public async Task InsertAsync_WithAListener_ReportsTheRowsSentAndNoReadCounters() + { + // The server sends no Progress packet for rows a client streams to it, at any size, so an insert's span has + // only the count the client itself knows. Read counters of zero would claim the server reported reading + // nothing rather than reporting nothing at all, and a zero elapsed_ns would claim it took no time. + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + string table = UniqueTableName(); + await client.ExecuteAsync($"CREATE TABLE {table} (id Int32) ENGINE = Memory", cancellationToken: None); + + try + { + finished.Clear(); + await client.InsertAsync( + $"INSERT INTO {table} (id) VALUES", + new IColumn[] { PrimitiveColumn.FromValues("id", "Int32", [1, 2, 3]) }, + cancellationToken: None); + + Activity span = finished.Single(a => a.OperationName == "INSERT"); + Assert.Multiple(() => + { + Assert.That(span.GetTagItem("db.clickhouse.written_rows"), Is.EqualTo(3UL)); + Assert.That(span.GetTagItem("db.clickhouse.read_rows"), Is.Null); + Assert.That(span.GetTagItem("db.clickhouse.elapsed_ns"), Is.Null); + }); + } + finally + { + await client.ExecuteAsync($"DROP TABLE IF EXISTS {table}", cancellationToken: None); + } + } + + [Test] + public async Task ExecuteAsync_InsertSelect_ReportsTheCountersTheServerSent() + { + await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + string table = UniqueTableName(); + await client.ExecuteAsync($"CREATE TABLE {table} (id UInt64) ENGINE = Memory", cancellationToken: None); + + try + { + finished.Clear(); + await client.ExecuteAsync($"INSERT INTO {table} SELECT number FROM numbers(1000)", cancellationToken: None); + + Activity span = finished.Single(a => a.OperationName == "INSERT"); + Assert.Multiple(() => + { + Assert.That(span.GetTagItem("db.clickhouse.written_rows"), Is.EqualTo(1000UL)); + Assert.That(span.GetTagItem("db.clickhouse.written_bytes"), Is.Not.Null, "only the server reports these"); + Assert.That(span.GetTagItem("db.clickhouse.read_rows"), Is.EqualTo(1000UL), "the SELECT half is read as well as written"); + }); + } + finally + { + await client.ExecuteAsync($"DROP TABLE IF EXISTS {table}", cancellationToken: None); + } + } + [Test] public async Task StreamAsync_ServerRejectsTheStatement_MarksTheSpanFailedWithTheServerErrorCode() { @@ -183,6 +241,8 @@ public async Task StreamAsync_WithNoListener_SendsNoTraceContextAndStillRuns() }); } + private static string UniqueTableName() => $"tcp_tracing_test_{Guid.NewGuid():N}"; + private static async Task SpanLogExistsAsync(ClickHouseTcpClient client) { List rows = await client From 32df7038ed6be70ae788370bbc2ded72908c60be Mon Sep 17 00:00:00 2001 From: Alex Soffronow-Pagonidis Date: Thu, 27 Aug 2026 17:59:02 +0200 Subject: [PATCH 4/6] Hand metadata callbacks the block, and give Block by-name typed columns The metadata callbacks handed two of their blocks over as owned rows and the other two as borrowed blocks, on a rule about which schemas the server fixes that is invisible at the call site. Make every one of them lend the block, the same contract StreamAsync already has, so nothing is materialized that the caller did not ask for: the log projection built four strings per row and the profile-event projection two, for every row of every such block, whichever fields the caller went on to read. Blocks now carry the accessors that makes reading one practical: a by-name indexer, TryGetColumn, and Column by name or index, which report the block and its columns when a name is absent and the column's type when it cannot be read as T. The callback bridge had these as a private scan because Block offered no way to address a column by name. The client's own progress and profile-info observers no longer merge into the caller's callbacks. The connection takes both and invokes them in turn, its own first, so a caller callback that throws still cannot cost the client telemetry it already had. That drops the bridge, the wire-shaped handler type it translated into, and the projected row types, and lets ClientOperation stop taking callbacks at all: a caller who wants progress and no tracing starts no operation. The Log and ProfileEvents schemas move to the callback documentation, priority being a Poco severity where a lower number is more severe. The integration tests read those blocks by column name, so a server-side rename fails them. Co-Authored-By: Claude Opus 5 (1M context) --- .../Client/MetadataCallbackBridgeTests.cs | 249 ------------------ .../Diagnostic/ClientOperationTests.cs | 38 +-- .../Format/BlockColumnAccessorTests.cs | 144 ++++++++++ .../ClickHouseTcpCallbackIntegrationTests.cs | 129 ++++++--- ...seTcpConnectionMetadataIntegrationTests.cs | 16 +- .../ClickHouseTcpConnectionInsertTests.cs | 2 +- .../ClickHouseTcpConnectionQueryTests.cs | 16 +- .../Client/ClickHouseTcpClient.cs | 19 +- .../Client/ClickHouseTcpClientOptions.cs | 22 +- .../Client/ClickHouseTcpProfileEvent.cs | 67 ----- .../Client/ClickHouseTcpQueryCallbacks.cs | 82 ++++-- .../Client/ClickHouseTcpServerLogRow.cs | 98 ------- .../Client/MetadataCallbackBridge.cs | 161 ----------- .../Diagnostic/ClientOperation.cs | 28 +- ClickHouse.Driver.Tcp/Format/Block.cs | 82 ++++++ .../Protocol/ClickHouseTcpConnection.cs | 82 +++--- .../Protocol/MetadataHandlers.cs | 44 ---- 17 files changed, 505 insertions(+), 774 deletions(-) delete mode 100644 ClickHouse.Driver.Tcp.Tests/Client/MetadataCallbackBridgeTests.cs create mode 100644 ClickHouse.Driver.Tcp.Tests/Format/BlockColumnAccessorTests.cs delete mode 100644 ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileEvent.cs delete mode 100644 ClickHouse.Driver.Tcp/Client/ClickHouseTcpServerLogRow.cs delete mode 100644 ClickHouse.Driver.Tcp/Client/MetadataCallbackBridge.cs delete mode 100644 ClickHouse.Driver.Tcp/Protocol/MetadataHandlers.cs diff --git a/ClickHouse.Driver.Tcp.Tests/Client/MetadataCallbackBridgeTests.cs b/ClickHouse.Driver.Tcp.Tests/Client/MetadataCallbackBridgeTests.cs deleted file mode 100644 index 757d799ef..000000000 --- a/ClickHouse.Driver.Tcp.Tests/Client/MetadataCallbackBridgeTests.cs +++ /dev/null @@ -1,249 +0,0 @@ -using System; -using System.Collections.Generic; -using ClickHouse.Driver.Tcp.Client; -using ClickHouse.Driver.Tcp.Format; -using ClickHouse.Driver.Tcp.Protocol; -using ClickHouse.Driver.Tcp.Types; - -namespace ClickHouse.Driver.Tcp.Tests.Client; - -// What no server round-trip can reach: the null-when-nothing-is-listening contract, the ordering guarantee -// between the client's own observer and the caller's callback, and the schema error paths — a real server always -// sends the schema the projection expects, so only a hand-built block can drive them. The projection of a real -// server's blocks is covered by ClickHouseTcpCallbackIntegrationTests. -[TestFixture] -public class MetadataCallbackBridgeTests -{ - [Test] - public void Build_NothingSet_ReturnsNull() - { - // The read path's null check is then the whole cost of the feature for a caller who asked for nothing. - Assert.That(MetadataCallbackBridge.Build(null), Is.Null); - } - - [Test] - public void Build_EmptyCallbacksObject_ReturnsNull() - { - Assert.That(MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks()), Is.Null); - } - - [Test] - public void Build_OnlyAnInternalObserver_ReturnsHandlersForThatPacketAlone() - { - MetadataHandlers handlers = MetadataCallbackBridge.Build(null, onProgress: _ => { }); - - Assert.That(handlers, Is.Not.Null); - Assert.Multiple(() => - { - Assert.That(handlers.OnProgress, Is.Not.Null); - Assert.That(handlers.OnLog, Is.Null, "an unset callback leaves the packet discarded rather than decoded"); - Assert.That(handlers.OnProfileEvents, Is.Null); - Assert.That(handlers.OnTotals, Is.Null); - }); - } - - [Test] - public void Build_BothObservers_RunsTheClientsBeforeTheCallers() - { - // The documented ordering: a caller's callback that throws must not cost the client the telemetry it - // already had in hand. - var order = new List(); - MetadataHandlers handlers = MetadataCallbackBridge.Build( - new ClickHouseTcpQueryCallbacks { OnProgress = _ => order.Add("caller") }, - onProgress: _ => order.Add("client")); - - handlers.OnProgress(default); - - Assert.That(order, Is.EqualTo(new[] { "client", "caller" })); - } - - [Test] - public void Build_CallerCallbackThrows_TheClientObserverHasAlreadyRun() - { - var seen = new List(); - MetadataHandlers handlers = MetadataCallbackBridge.Build( - new ClickHouseTcpQueryCallbacks { OnProgress = _ => throw new InvalidOperationException("from the caller") }, - onProgress: seen.Add); - - Assert.Throws(() => handlers.OnProgress(new ClickHouseTcpProgress(3, 24, 3, 0, 0, 1))); - - Assert.That(seen, Has.Count.EqualTo(1), "the client's observer ran first, so its count survives the throw"); - Assert.That(seen[0].Rows, Is.EqualTo(3UL)); - } - - [Test] - public void OnLog_WellFormedBlock_ProjectsEveryRow() - { - var rows = new List(); - MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnServerLog = rows.Add }); - - using Block block = LogBlock(priority: 7); - handlers.OnLog(block); - - Assert.That(rows, Has.Count.EqualTo(1)); - Assert.Multiple(() => - { - // 1700000000 seconds plus 500000 microseconds, to the microsecond. - Assert.That(rows[0].EventTime, Is.EqualTo(DateTimeOffset.FromUnixTimeSeconds(1700000000).AddTicks(5000000))); - Assert.That(rows[0].HostName, Is.EqualTo("host-1")); - Assert.That(rows[0].QueryId, Is.EqualTo("query-1")); - Assert.That(rows[0].ThreadId, Is.EqualTo(4242UL)); - Assert.That(rows[0].Level, Is.EqualTo(ClickHouseTcpServerLogLevel.Debug)); - Assert.That(rows[0].Source, Is.EqualTo("executeQuery")); - Assert.That(rows[0].Text, Is.EqualTo("a message")); - }); - } - - [TestCase((sbyte)1, ClickHouseTcpServerLogLevel.Fatal)] - [TestCase((sbyte)8, ClickHouseTcpServerLogLevel.Trace)] - [TestCase((sbyte)9, ClickHouseTcpServerLogLevel.Test)] - [TestCase((sbyte)0, ClickHouseTcpServerLogLevel.Unknown)] - [TestCase((sbyte)10, ClickHouseTcpServerLogLevel.Unknown)] - [TestCase((sbyte)-1, ClickHouseTcpServerLogLevel.Unknown)] - public void OnLog_PriorityOutsideTheKnownRange_DegradesToUnknown(sbyte priority, ClickHouseTcpServerLogLevel expected) - { - // A server that grows a level must not break a caller who only wanted the message text, so an unmapped - // priority is reported rather than refused. No real server sends one, which is why this is a unit test. - var rows = new List(); - MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnServerLog = rows.Add }); - - using Block block = LogBlock(priority); - handlers.OnLog(block); - - Assert.That(rows[0].Level, Is.EqualTo(expected)); - } - - [Test] - public void OnLog_BlockMissingAColumn_ThrowsNamingIt() - { - MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnServerLog = _ => { } }); - - using var block = new Block( - string.Empty, - default, - 1, - new IColumn[] { PrimitiveColumn.FromValues("event_time", "DateTime", [1]) }, - null, - default); - - ClickHouseProtocolException thrown = Assert.Throws(() => handlers.OnLog(block)); - Assert.That(thrown.Message, Does.Contain("event_time_microseconds")); - } - - [Test] - public void OnLog_ColumnOfTheWrongType_ThrowsNamingTheTypeItGot() - { - MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnServerLog = _ => { } }); - - using Block block = LogBlock(priority: 7, threadIdColumn: new ArrayColumn("thread_id", "String", ["not a number"])); - - ClickHouseProtocolException thrown = Assert.Throws(() => handlers.OnLog(block)); - Assert.Multiple(() => - { - Assert.That(thrown.Message, Does.Contain("thread_id")); - Assert.That(thrown.Message, Does.Contain("String")); - }); - } - - [Test] - public void OnProfileEvents_ValueColumnOfAnotherWidth_ThrowsNamingIt() - { - // Every supported server sends Int64, so a different width means the packet is not the one this projects - // and reinterpreting it would report wrong numbers rather than an error. - MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnProfileEvent = _ => { } }); - - using Block block = ProfileEventsBlock(PrimitiveColumn.FromValues("value", "UInt64", [17])); - - ClickHouseProtocolException thrown = Assert.Throws(() => handlers.OnProfileEvents(block)); - Assert.Multiple(() => - { - Assert.That(thrown.Message, Does.Contain("value")); - Assert.That(thrown.Message, Does.Contain("UInt64")); - }); - } - - [Test] - public void OnProfileEvents_WellFormedBlock_ProjectsEveryField() - { - var events = new List(); - MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnProfileEvent = events.Add }); - - using Block block = ProfileEventsBlock(PrimitiveColumn.FromValues("value", "Int64", [99])); - handlers.OnProfileEvents(block); - - Assert.That(events, Has.Count.EqualTo(1)); - Assert.Multiple(() => - { - Assert.That(events[0].CurrentTime, Is.EqualTo(DateTimeOffset.FromUnixTimeSeconds(1700000000))); - Assert.That(events[0].HostName, Is.EqualTo("host-1")); - Assert.That(events[0].ThreadId, Is.EqualTo(4242UL)); - Assert.That(events[0].Type, Is.EqualTo(ClickHouseTcpProfileEventType.Increment)); - Assert.That(events[0].Name, Is.EqualTo("SelectedRows")); - Assert.That(events[0].Value, Is.EqualTo(99L)); - }); - } - - [TestCase((sbyte)2, ClickHouseTcpProfileEventType.Gauge)] - [TestCase((sbyte)0, ClickHouseTcpProfileEventType.Unknown)] - [TestCase((sbyte)3, ClickHouseTcpProfileEventType.Unknown)] - public void OnProfileEvents_TypeOutsideTheKnownRange_DegradesToUnknown(sbyte type, ClickHouseTcpProfileEventType expected) - { - var events = new List(); - MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnProfileEvent = events.Add }); - - using Block block = ProfileEventsBlock(PrimitiveColumn.FromValues("value", "Int64", [1]), type); - handlers.OnProfileEvents(block); - - Assert.That(events[0].Type, Is.EqualTo(expected)); - } - - [Test] - public void OnLog_ZeroRowBlock_InvokesNothing() - { - int calls = 0; - MetadataHandlers handlers = MetadataCallbackBridge.Build(new ClickHouseTcpQueryCallbacks { OnServerLog = _ => calls++ }); - - using Block block = LogBlock(priority: 7, rowCount: 0); - handlers.OnLog(block); - - Assert.That(calls, Is.Zero); - } - - // The server's fixed Log schema, in its documented order. - private static Block LogBlock(sbyte priority, IColumn threadIdColumn = null, int rowCount = 1) - => new( - string.Empty, - default, - rowCount, - new[] - { - PrimitiveColumn.FromValues("event_time", "DateTime", [1700000000]), - PrimitiveColumn.FromValues("event_time_microseconds", "UInt32", [500000]), - new ArrayColumn("host_name", "String", ["host-1"]), - new ArrayColumn("query_id", "String", ["query-1"]), - threadIdColumn ?? PrimitiveColumn.FromValues("thread_id", "UInt64", [4242]), - PrimitiveColumn.FromValues("priority", "Int8", [priority]), - new ArrayColumn("source", "String", ["executeQuery"]), - new ArrayColumn("text", "String", ["a message"]), - }, - null, - default); - - // The server's fixed ProfileEvents schema, in its documented order. - private static Block ProfileEventsBlock(IColumn valueColumn, sbyte type = 1) - => new( - string.Empty, - default, - 1, - new[] - { - new ArrayColumn("host_name", "String", ["host-1"]), - PrimitiveColumn.FromValues("current_time", "DateTime", [1700000000]), - PrimitiveColumn.FromValues("thread_id", "UInt64", [4242]), - PrimitiveColumn.FromValues("type", "Enum8('increment' = 1, 'gauge' = 2)", [type]), - new ArrayColumn("name", "String", ["SelectedRows"]), - valueColumn, - }, - null, - default); -} diff --git a/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs b/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs index fbc433a7d..76dabb3b4 100644 --- a/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs @@ -15,27 +15,9 @@ public class ClientOperationTests private static readonly ClickHouseTcpClientOptions Options = new(); [Test] - public void Start_NoListenerNoLoggerNoCallbacks_ReturnsNull() + public void Start_NoListenerAndNoLogger_ReturnsNull() { - Assert.That(ClientOperation.Start(Options, logger: null, "SELECT 1", queryId: null, callbacks: null), Is.Null); - } - - [Test] - public void Start_CallbacksOnly_BuildsAnOperationWithHandlersAndNoSpan() - { - using ClientOperation operation = ClientOperation.Start( - Options, - logger: null, - "SELECT 1", - queryId: null, - new ClickHouseTcpQueryCallbacks { OnProgress = _ => { } }); - - Assert.That(operation, Is.Not.Null); - Assert.Multiple(() => - { - Assert.That(operation.Handlers, Is.Not.Null); - Assert.That(Activity.Current, Is.Null, "no listener means no span, callbacks or not"); - }); + Assert.That(ClientOperation.Start(Options, logger: null, "SELECT 1", queryId: null), Is.Null); } [Test] @@ -46,11 +28,11 @@ public void Start_LoggerOnly_AccumulatesTheCountersTheCompletionLineNeeds() using var factory = new CapturingLoggerFactory(); CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); - using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", queryId: null, callbacks: null)) + using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", queryId: null)) { Assert.That(operation, Is.Not.Null); - operation.Handlers.OnProgress(new ClickHouseTcpProgress(4, 32, 4, 0, 0, 1)); - operation.Handlers.OnProgress(new ClickHouseTcpProgress(6, 48, 6, 0, 0, 1)); + operation.Telemetry.OnProgress(new ClickHouseTcpProgress(4, 32, 4, 0, 0, 1)); + operation.Telemetry.OnProgress(new ClickHouseTcpProgress(6, 48, 6, 0, 0, 1)); operation.Succeeded(); } @@ -64,7 +46,7 @@ public void Dispose_NeitherSucceededNorFailed_ReportsTheOperationAbandoned() using var factory = new CapturingLoggerFactory(); CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); - using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", queryId: null, callbacks: null)) + using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", queryId: null)) { } @@ -81,7 +63,7 @@ public void Start_QueryIdSet_PutsItOnTheLogLine() using var factory = new CapturingLoggerFactory(); CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); - using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", "my-query-id", callbacks: null)) + using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", "my-query-id")) { operation.Succeeded(); } @@ -102,7 +84,7 @@ public void Start_StatementLongerThanTheLimit_TruncatesItInTheLogLine() CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); ClickHouseTcpClientOptions options = Options with { StatementMaxLength = 6 }; - using (ClientOperation operation = ClientOperation.Start(options, logger, "SELECT 'a very long literal'", queryId: null, callbacks: null)) + using (ClientOperation operation = ClientOperation.Start(options, logger, "SELECT 'a very long literal'", queryId: null)) { } @@ -116,7 +98,7 @@ public void Start_ZeroStatementMaxLength_KeepsTheStatementOutOfTheLogEntirely() CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); ClickHouseTcpClientOptions options = Options with { StatementMaxLength = 0 }; - using (ClientOperation operation = ClientOperation.Start(options, logger, "SELECT 'secret'", queryId: null, callbacks: null)) + using (ClientOperation operation = ClientOperation.Start(options, logger, "SELECT 'secret'", queryId: null)) { } @@ -131,7 +113,7 @@ public void Failed_Cancellation_IsNotLoggedAsAnError() using var factory = new CapturingLoggerFactory(); CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); - using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", queryId: null, callbacks: null)) + using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", queryId: null)) { operation.Failed(new System.OperationCanceledException()); } diff --git a/ClickHouse.Driver.Tcp.Tests/Format/BlockColumnAccessorTests.cs b/ClickHouse.Driver.Tcp.Tests/Format/BlockColumnAccessorTests.cs new file mode 100644 index 000000000..1fc9684f2 --- /dev/null +++ b/ClickHouse.Driver.Tcp.Tests/Format/BlockColumnAccessorTests.cs @@ -0,0 +1,144 @@ +using System; +using ClickHouse.Driver.Tcp.Format; +using ClickHouse.Driver.Tcp.Types; + +namespace ClickHouse.Driver.Tcp.Tests.Format; + +// The by-name and typed column accessors. Hand-built blocks rather than a server round-trip: the point of these +// is the lookup and the failure messages, which a well-formed result never reaches. +[TestFixture] +public class BlockColumnAccessorTests +{ + [Test] + public void IndexerByName_ColumnPresent_ReturnsIt() + { + using Block block = TwoColumnBlock(); + + Assert.That(block["id"].Name, Is.EqualTo("id")); + Assert.That(block["label"].Name, Is.EqualTo("label")); + } + + [Test] + public void IndexerByName_ColumnAbsent_ThrowsListingTheColumnsItHas() + { + using Block block = TwoColumnBlock(); + + var e = Assert.Throws(() => _ = block["nope"]); + + Assert.Multiple(() => + { + Assert.That(e.Message, Does.Contain("'nope'"), "the name that was asked for"); + Assert.That(e.Message, Does.Contain("id").And.Contain("label"), "what the caller could have asked for"); + }); + } + + [Test] + public void IndexerByName_NamedBlock_NamesTheBlockInTheMessage() + { + using Block block = new("Log", default, 1, [Ids()], null, default); + + var e = Assert.Throws(() => _ = block["nope"]); + + Assert.That(e.Message, Does.Contain("Block 'Log'")); + } + + [Test] + public void IndexerByName_NullName_Throws() + { + using Block block = TwoColumnBlock(); + + Assert.Throws(() => _ = block[null]); + } + + [Test] + public void TryGetColumn_ColumnPresent_ReturnsTrueAndTheColumn() + { + using Block block = TwoColumnBlock(); + + Assert.That(block.TryGetColumn("label", out IColumn column), Is.True); + Assert.That(column.Name, Is.EqualTo("label")); + } + + [Test] + public void TryGetColumn_ColumnAbsent_ReturnsFalseAndNull() + { + using Block block = TwoColumnBlock(); + + Assert.That(block.TryGetColumn("nope", out IColumn column), Is.False); + Assert.That(column, Is.Null); + } + + [Test] + public void TryGetColumn_NameDifferingOnlyInCase_ReturnsFalse() + { + // ClickHouse column names are case-sensitive, so the match is ordinal. + using Block block = TwoColumnBlock(); + + Assert.That(block.TryGetColumn("ID", out _), Is.False); + } + + [Test] + public void ColumnByName_MatchingType_ReturnsTheTypedView() + { + using Block block = TwoColumnBlock(); + + IColumn ids = block.Column("id"); + + Assert.That(ids.Values.ToArray(), Is.EqualTo(new ulong[] { 7, 8 })); + } + + [Test] + public void ColumnByName_WrongType_ThrowsNamingTheTypeTheColumnHas() + { + using Block block = TwoColumnBlock(); + + var e = Assert.Throws(() => block.Column("id")); + + Assert.Multiple(() => + { + Assert.That(e.Message, Does.Contain("'id'")); + Assert.That(e.Message, Does.Contain("UInt64"), "the ClickHouse type it actually has"); + Assert.That(e.Message, Does.Contain("String"), "the CLR type that was asked for"); + }); + } + + [Test] + public void ColumnByName_ColumnAbsent_Throws() + { + using Block block = TwoColumnBlock(); + + Assert.Throws(() => block.Column("nope")); + } + + [Test] + public void ColumnByIndex_MatchingType_ReturnsTheTypedView() + { + using Block block = TwoColumnBlock(); + + Assert.That(block.Column(1).Values.ToArray(), Is.EqualTo(new[] { "a", "b" })); + } + + [Test] + public void ColumnByIndex_WrongType_Throws() + { + using Block block = TwoColumnBlock(); + + Assert.Throws(() => block.Column(1)); + } + + [TestCase(-1)] + [TestCase(2)] + public void ColumnByIndex_OutOfRange_Throws(int index) + { + using Block block = TwoColumnBlock(); + + Assert.Throws(() => block.Column(index)); + } + + private static Block TwoColumnBlock() + => new(string.Empty, default, 2, [Ids(), Labels()], null, default); + + private static IColumn Ids() => PrimitiveColumn.FromValues("id", "UInt64", [7UL, 8UL]); + + private static IColumn Labels() => new ArrayColumn("label", "String", ["a", "b"]); +} diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs index 43f205e54..e6f3dfc0e 100644 --- a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs @@ -9,8 +9,9 @@ namespace ClickHouse.Driver.Tcp.Tests.Integration; // The public callback surface, driven end to end through the client. The connection-level fan-out is covered by -// ClickHouseTcpConnectionMetadataIntegrationTests; what these add is the projection into owned rows and the fact -// that ClickHouseTcpQueryOptions.Callbacks reaches the read path at all. +// ClickHouseTcpConnectionMetadataIntegrationTests; what these add is that ClickHouseTcpQueryOptions.Callbacks +// reaches the read path at all, and that the Log and ProfileEvents blocks carry the schema the callback docs +// promise — a caller reads them by column name, so a rename on the server has to fail here. [TestFixture] [Category("Integration")] public class ClickHouseTcpCallbackIntegrationTests @@ -72,12 +73,19 @@ await DrainAsync( } [Test] - public async Task StreamAsync_OnServerLog_ProjectsTheServerRowsForThisQuery() + public async Task StreamAsync_OnLog_LendsBlocksCarryingTheDocumentedLogSchema() { await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); string queryId = Guid.NewGuid().ToString(); - var rows = new List(); + // Copied out inside the callback: the block is borrowed and released as soon as it returns. + var queryIds = new List(); + var texts = new List(); + var sources = new List(); + var priorities = new List(); + var threadIds = new List(); + var instants = new List(); + await DrainAsync( client, "SELECT sum(number) FROM numbers(100000)", @@ -85,64 +93,110 @@ await DrainAsync( { QueryId = queryId, Settings = new Dictionary { ["send_logs_level"] = "trace" }, - Callbacks = new ClickHouseTcpQueryCallbacks { OnServerLog = rows.Add }, + Callbacks = new ClickHouseTcpQueryCallbacks + { + OnLog = block => + { + ReadOnlySpan seconds = block.Column("event_time").Values; + ReadOnlySpan micros = block.Column("event_time_microseconds").Values; + ReadOnlySpan priority = block.Column("priority").Values; + ReadOnlySpan threadId = block.Column("thread_id").Values; + IColumn id = block.Column("query_id"); + IColumn source = block.Column("source"); + IColumn text = block.Column("text"); + + for (int row = 0; row < block.RowCount; row++) + { + queryIds.Add(id[row]); + texts.Add(text[row]); + sources.Add(source[row]); + priorities.Add(priority[row]); + threadIds.Add(threadId[row]); + instants.Add(DateTimeOffset.FromUnixTimeSeconds(seconds[row]) + .AddTicks(micros[row] * TimeSpan.TicksPerMicrosecond)); + } + }, + }, }); - Assert.That(rows, Is.Not.Empty, "the server streams trace-level log rows"); + Assert.That(texts, Is.Not.Empty, "the server streams trace-level log rows"); Assert.Multiple(() => { - Assert.That(rows.Select(r => r.QueryId), Is.All.EqualTo(queryId), "every row belongs to the query that asked for them"); - Assert.That(rows.Select(r => r.Text), Is.All.Not.Empty); - Assert.That(rows.Select(r => r.Level), Is.All.Not.EqualTo(ClickHouseTcpServerLogLevel.Unknown), "the priority column decodes to a known level"); - Assert.That(rows.Select(r => r.Source), Is.All.Not.Null); - Assert.That(rows.Select(r => r.HostName), Is.All.Not.Null); - Assert.That(rows.Select(r => r.EventTime), Is.All.GreaterThan(DateTimeOffset.UnixEpoch), "the two time columns combine into a real instant"); - Assert.That(rows.Any(r => r.ThreadId != 0), "at least one row names its thread"); + Assert.That(queryIds, Is.All.EqualTo(queryId), "every row belongs to the query that asked for them"); + Assert.That(texts, Is.All.Not.Empty); + Assert.That(sources, Is.All.Not.Null); + Assert.That(priorities, Is.All.InRange((sbyte)1, (sbyte)9), "a Poco severity, lower being more severe"); + Assert.That(threadIds.Any(id => id != 0), "at least one row names its thread"); + Assert.That(instants, Is.All.GreaterThan(DateTimeOffset.UnixEpoch), "the two time columns combine into a real instant"); }); } [Test] - public async Task StreamAsync_OnServerLog_WithoutSendLogsLevel_ReportsNothing() + public async Task StreamAsync_OnLog_WithoutSendLogsLevel_ReportsNothing() { // The callback alone changes nothing on the wire: the server's default log level is effectively silent, so // asking for server logs is a two-part act and this is the half the client does not do for you. await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); - var rows = new List(); + int blocks = 0; await DrainAsync( client, "SELECT sum(number) FROM numbers(100000)", new ClickHouseTcpQueryOptions { - Callbacks = new ClickHouseTcpQueryCallbacks { OnServerLog = rows.Add }, + Callbacks = new ClickHouseTcpQueryCallbacks { OnLog = _ => blocks++ }, }); - Assert.That(rows, Is.Empty); + Assert.That(blocks, Is.Zero); } [Test] - public async Task StreamAsync_OnProfileEvent_ProjectsNamedCounters() + public async Task StreamAsync_OnProfileEvents_LendsBlocksCarryingTheDocumentedCounterSchema() { await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); - var events = new List(); + var names = new List(); + var types = new List(); + var hosts = new List(); + var instants = new List(); + await DrainAsync( client, "SELECT sum(number) FROM numbers(100000)", new ClickHouseTcpQueryOptions { - Callbacks = new ClickHouseTcpQueryCallbacks { OnProfileEvent = events.Add }, + Callbacks = new ClickHouseTcpQueryCallbacks { OnProfileEvents = block => Collect(block) }, }); - Assert.That(events, Is.Not.Empty, "the server sends performance counters"); + Assert.That(names, Is.Not.Empty, "the server sends performance counters"); Assert.Multiple(() => { - Assert.That(events.Select(e => e.Name), Is.All.Not.Empty); - Assert.That(events.Select(e => e.Type), Is.All.Not.EqualTo(ClickHouseTcpProfileEventType.Unknown), "the type column decodes to a known kind"); - Assert.That(events.Select(e => e.CurrentTime), Is.All.GreaterThan(DateTimeOffset.UnixEpoch)); - Assert.That(events.Select(e => e.HostName), Is.All.Not.Null); - Assert.That(events.Any(e => e.Name == "SelectedRows"), "a counter every SELECT reports"); + Assert.That(names, Is.All.Not.Empty); + Assert.That(types, Is.All.InRange((sbyte)1, (sbyte)2), "1 increment, 2 gauge"); + Assert.That(hosts, Is.All.Not.Null); + Assert.That(instants, Is.All.GreaterThan(DateTimeOffset.UnixEpoch)); + Assert.That(names, Does.Contain("SelectedRows"), "a counter every SELECT reports"); }); + + void Collect(Block block) + { + ReadOnlySpan currentTime = block.Column("current_time").Values; + ReadOnlySpan type = block.Column("type").Values; + IColumn host = block.Column("host_name"); + IColumn name = block.Column("name"); + + // Bound as a span to pin the width the docs promise: a server sending another integer type throws. + ReadOnlySpan value = block.Column("value").Values; + + for (int row = 0; row < block.RowCount; row++) + { + names.Add(name[row]); + types.Add(type[row]); + hosts.Add(host[row]); + instants.Add(DateTimeOffset.FromUnixTimeSeconds(currentTime[row])); + _ = value[row]; + } + } } [Test] @@ -208,24 +262,37 @@ public async Task InsertAsync_Callbacks_ReachTheInsertAndReportTheRowsInserted() try { - var events = new List(); + var names = new List(); + var types = new List(); await client.InsertAsync( $"INSERT INTO {table} (id) VALUES", new IColumn[] { PrimitiveColumn.FromValues("id", "Int32", [1, 2, 3, 4, 5]) }, new ClickHouseTcpInsertOptions { - Callbacks = new ClickHouseTcpQueryCallbacks { OnProfileEvent = events.Add }, + Callbacks = new ClickHouseTcpQueryCallbacks + { + OnProfileEvents = block => + { + ReadOnlySpan type = block.Column("type").Values; + IColumn name = block.Column("name"); + for (int row = 0; row < block.RowCount; row++) + { + names.Add(name[row]); + types.Add(type[row]); + } + }, + }, }, None); List stored = await client.QueryAsync($"SELECT count() FROM {table}", cancellationToken: None).ToListAsync(); - Assert.That(events, Is.Not.Empty, "the insert path passes the callbacks through"); + Assert.That(names, Is.Not.Empty, "the insert path passes the callbacks through"); Assert.Multiple(() => { Assert.That((ulong)stored[0][0], Is.EqualTo(5UL), "observing the insert did not stop it inserting"); - Assert.That(events.Select(e => e.Name), Is.All.Not.Empty); - Assert.That(events.Select(e => e.Type), Is.All.Not.EqualTo(ClickHouseTcpProfileEventType.Unknown)); + Assert.That(names, Is.All.Not.Empty); + Assert.That(types, Is.All.InRange((sbyte)1, (sbyte)2)); }); } finally diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpConnectionMetadataIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpConnectionMetadataIntegrationTests.cs index 6c074b725..47975d804 100644 --- a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpConnectionMetadataIntegrationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpConnectionMetadataIntegrationTests.cs @@ -20,9 +20,9 @@ public class ClickHouseTcpConnectionMetadataIntegrationTests { private static readonly CancellationToken None = CancellationToken.None; - private static async Task DrainAsync(ClickHouseTcpConnection connection, string sql, MetadataHandlers handlers, IReadOnlyDictionary settings = null) + private static async Task DrainAsync(ClickHouseTcpConnection connection, string sql, ClickHouseTcpQueryCallbacks handlers, IReadOnlyDictionary settings = null) { - await foreach (Block block in connection.QueryAsync(sql, settings: settings, handlers: handlers, cancellationToken: None)) + await foreach (Block block in connection.QueryAsync(sql, settings: settings, callbacks: handlers, cancellationToken: None)) { _ = block.RowCount; } @@ -35,7 +35,7 @@ public async Task QueryAsync_ScanningManyRows_InvokesProgressWithRowsRead() int progressCount = 0; ulong maxRows = 0; - await DrainAsync(connection, "SELECT sum(number) FROM numbers(2000000)", new MetadataHandlers + await DrainAsync(connection, "SELECT sum(number) FROM numbers(2000000)", new ClickHouseTcpQueryCallbacks { OnProgress = p => { @@ -62,7 +62,7 @@ public async Task QueryAsync_AnyQuery_InvokesProfileInfo() int count = 0; ulong rows = 0; - await DrainAsync(connection, "SELECT number FROM numbers(10)", new MetadataHandlers + await DrainAsync(connection, "SELECT number FROM numbers(10)", new ClickHouseTcpQueryCallbacks { OnProfileInfo = info => { @@ -85,7 +85,7 @@ public async Task QueryAsync_AnyQuery_InvokesProfileEvents() await using var connection = await TcpServerFixture.ConnectAsync(None); int blocks = 0; - await DrainAsync(connection, "SELECT number FROM numbers(10)", new MetadataHandlers + await DrainAsync(connection, "SELECT number FROM numbers(10)", new ClickHouseTcpQueryCallbacks { OnProfileEvents = block => { @@ -114,7 +114,7 @@ public async Task QueryAsync_GroupByWithTotals_InvokesTotalsOnce() await DrainAsync( connection, "SELECT number % 3 AS k, count() AS c FROM numbers(100) GROUP BY k WITH TOTALS", - new MetadataHandlers + new ClickHouseTcpQueryCallbacks { OnTotals = block => { @@ -143,7 +143,7 @@ public async Task QueryAsync_ExtremesSetting_InvokesExtremesWithMinAndMax() await DrainAsync( connection, "SELECT number FROM numbers(10)", - new MetadataHandlers + new ClickHouseTcpQueryCallbacks { OnExtremes = block => { @@ -170,7 +170,7 @@ public async Task QueryAsync_TraceLogsSetting_InvokesLog() await DrainAsync( connection, "SELECT sum(number) FROM numbers(100000)", - new MetadataHandlers + new ClickHouseTcpQueryCallbacks { OnLog = block => logRows += block.RowCount, }, diff --git a/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionInsertTests.cs b/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionInsertTests.cs index e588410e1..c28d677d5 100644 --- a/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionInsertTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionInsertTests.cs @@ -68,7 +68,7 @@ await ProgressPacketAsync(), await connection.InsertAsync( "INSERT INTO t VALUES", Columns(UInt64Column(1, 2, 3)), - handlers: new MetadataHandlers { OnProgress = progresses.Add }, + callbacks: new ClickHouseTcpQueryCallbacks { OnProgress = progresses.Add }, cancellationToken: None); Assert.Multiple(() => diff --git a/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionQueryTests.cs b/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionQueryTests.cs index dc39dd24d..f93bcdf50 100644 --- a/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionQueryTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionQueryTests.cs @@ -272,7 +272,7 @@ await ProgressPacketAsync(), using var connection = await ConnectedAsync(script); var progresses = new List(); - await DrainAsync(connection, new MetadataHandlers { OnProgress = progresses.Add }); + await DrainAsync(connection, new ClickHouseTcpQueryCallbacks { OnProgress = progresses.Add }); Assert.Multiple(() => { @@ -295,7 +295,7 @@ await DataPacketAsync(new ulong[] { 5 }), using var connection = await ConnectedAsync(script); var captured = new List(); - await DrainAsync(connection, new MetadataHandlers { OnProfileInfo = captured.Add }); + await DrainAsync(connection, new ClickHouseTcpQueryCallbacks { OnProfileInfo = captured.Add }); Assert.Multiple(() => { @@ -318,7 +318,7 @@ await TotalsPacketAsync(new ulong[] { 99 }), var totals = new List(); // Copy out inside the call, since the block is released as soon as the handler returns. - await DrainAsync(connection, new MetadataHandlers + await DrainAsync(connection, new ClickHouseTcpQueryCallbacks { OnTotals = block => totals.Add(((IColumn)block[0]).Values.ToArray()), }); @@ -332,7 +332,7 @@ await TotalsPacketAsync(new ulong[] { 99 }), } [Test] - public async Task QueryAsync_AllMetadataHandlers_EachInvokedForItsPacket() + public async Task QueryAsync_AllMetadataCallbacks_EachInvokedForItsPacket() { byte[] script = Concat( await ServerHelloBytesAsync(54476), @@ -347,7 +347,7 @@ await DataPacketAsync(new ulong[] { 42 }), int extremes = 0; int log = 0; int profileEvents = 0; - await DrainAsync(connection, new MetadataHandlers + await DrainAsync(connection, new ClickHouseTcpQueryCallbacks { OnExtremes = _ => extremes++, OnLog = _ => log++, @@ -377,7 +377,7 @@ await DataPacketAsync(new ulong[] { 1 }), var boom = new InvalidOperationException("handler failed"); var thrown = Assert.ThrowsAsync(async () => - await DrainAsync(connection, new MetadataHandlers { OnProgress = _ => throw boom })); + await DrainAsync(connection, new ClickHouseTcpQueryCallbacks { OnProgress = _ => throw boom })); Assert.Multiple(() => { @@ -433,9 +433,9 @@ private static async Task DrainAsync(ClickHouseTcpConnection connection) } // Enumerates the response with metadata handlers attached, ignoring the row-bearing blocks themselves. - private static async Task DrainAsync(ClickHouseTcpConnection connection, MetadataHandlers handlers) + private static async Task DrainAsync(ClickHouseTcpConnection connection, ClickHouseTcpQueryCallbacks handlers) { - await foreach (Block block in connection.QueryAsync("SELECT 1", handlers: handlers, cancellationToken: None)) + await foreach (Block block in connection.QueryAsync("SELECT 1", callbacks: handlers, cancellationToken: None)) { _ = block; } diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs index 069d51c27..767c10ca0 100644 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs @@ -159,7 +159,7 @@ public async IAsyncEnumerable StreamAsync( // Started before the rent, so the span covers waiting for a connection, and so the Query packet's // trace-context field picks it up from Activity.Current. - ClientOperation operation = ClientOperation.Start(Options, logger, sql, queryId, options?.Callbacks); + ClientOperation operation = ClientOperation.Start(Options, logger, sql, queryId); IConnectionLease lease = null; IAsyncEnumerator blocks = null; try @@ -173,7 +173,7 @@ public async IAsyncEnumerable StreamAsync( // Enumerated by hand rather than with `await foreach` because a yield cannot sit inside a try that // has a catch, and a failed query whose span carries no error is the one thing a trace must not do. blocks = lease.Connection - .QueryAsync(sql, settings, parameters, queryId, operation?.Handlers, cancellationToken) + .QueryAsync(sql, settings, parameters, queryId, operation?.Telemetry, options?.Callbacks, cancellationToken) .GetAsyncEnumerator(cancellationToken); } catch (Exception e) @@ -387,7 +387,7 @@ public async ValueTask InsertAsync( IReadOnlyDictionary settings = BuildSettings(options); IReadOnlyDictionary parameters = BuildParameters(sql, options); - using ClientOperation operation = ClientOperation.Start(Options, logger, sql, options?.QueryId, options?.Callbacks); + using ClientOperation operation = ClientOperation.Start(Options, logger, sql, options?.QueryId); try { await using IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); @@ -399,7 +399,8 @@ await lease.Connection.InsertAsync( options?.QueryId, ResolveMaxRowsPerBlock(options), Options.MaxSendBufferBytes, - operation?.Handlers, + operation?.Telemetry, + options?.Callbacks, cancellationToken).ConfigureAwait(false); operation?.Succeeded(columns.Count == 0 ? 0UL : (ulong)columns[0].RowCount); } @@ -434,7 +435,7 @@ public async ValueTask InsertRowsAsync( using var buffer = PocoRowBuffer.Create(rows, nameof(rows), cancellationToken); - using ClientOperation operation = ClientOperation.Start(Options, logger, sql, options?.QueryId, options?.Callbacks); + using ClientOperation operation = ClientOperation.Start(Options, logger, sql, options?.QueryId); try { await using IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); @@ -447,7 +448,8 @@ await lease.Connection.InsertAsync( options?.QueryId, ResolveMaxRowsPerBlock(options), Options.MaxSendBufferBytes, - operation?.Handlers, + operation?.Telemetry, + options?.Callbacks, cancellationToken).ConfigureAwait(false); operation?.Succeeded((ulong)buffer.Count); } @@ -472,7 +474,7 @@ public async ValueTask InsertRowsAsync( IReadOnlyDictionary parameters = BuildParameters(sql, options); using var buffer = PocoRowBuffer.Create(rows, nameof(rows), cancellationToken); - using ClientOperation operation = ClientOperation.Start(Options, logger, sql, options?.QueryId, options?.Callbacks); + using ClientOperation operation = ClientOperation.Start(Options, logger, sql, options?.QueryId); try { await using IConnectionLease lease = await source.RentAsync(cancellationToken).ConfigureAwait(false); @@ -485,7 +487,8 @@ await lease.Connection.InsertAsync( options?.QueryId, ResolveMaxRowsPerBlock(options), Options.MaxSendBufferBytes, - operation?.Handlers, + operation?.Telemetry, + options?.Callbacks, cancellationToken).ConfigureAwait(false); operation?.Succeeded((ulong)buffer.Count); } diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs index f9042e938..870f89417 100644 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs @@ -295,7 +295,7 @@ public sealed record ClickHouseTcpClientOptions /// The client logs its own lifecycle — connects, handshakes, pool checkouts and retirements, operation /// outcomes — under the ClickHouse.Driver.Tcp.* categories. It does not log what the /// server reports: server log lines go to - /// , where the caller decides whether they are worth + /// , where the caller decides whether they are worth /// logging. Nothing is formatted while the matching category and level are disabled. /// /// @@ -325,16 +325,6 @@ public sealed record ClickHouseTcpClientOptions /// public int StatementMaxLength { get; init; } = DefaultStatementMaxLength; - /// - /// These options with replaced by a private snapshot, or this instance when there - /// are none to copy. A client holds its options for its lifetime and merges the settings on every operation, so - /// it must own them: keeping the caller's dictionary would let a later mutation of it fault or partially apply - /// mid-merge. Every other property is init-only and so cannot change after construction. - /// - /// - /// The with expression carries every other property across, so a property added later needs no change - /// here. Keep it that way: a hand-written copy is what silently drops a new property. - /// /// /// The statement text as telemetry may carry it: truncated to , or empty /// when that allows none. @@ -351,6 +341,16 @@ internal string StatementForTelemetry(string sql) return sql.Length <= StatementMaxLength ? sql : sql[..StatementMaxLength]; } + /// + /// These options with replaced by a private snapshot, or this instance when there + /// are none to copy. A client holds its options for its lifetime and merges the settings on every operation, so + /// it must own them: keeping the caller's dictionary would let a later mutation of it fault or partially apply + /// mid-merge. Every other property is init-only and so cannot change after construction. + /// + /// + /// The with expression carries every other property across, so a property added later needs no change + /// here. Keep it that way: a hand-written copy is what silently drops a new property. + /// internal ClickHouseTcpClientOptions WithOwnedCustomSettings() => CustomSettings is null ? this diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileEvent.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileEvent.cs deleted file mode 100644 index 1b0ceb180..000000000 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileEvent.cs +++ /dev/null @@ -1,67 +0,0 @@ -using System; - -namespace ClickHouse.Driver.Tcp; - -/// -/// One server performance counter, streamed to the client while a query runs. The same counter arrives -/// repeatedly as the query progresses. -/// -/// -/// Every member is owned, so an event is safe to keep after the callback returns. -/// -public readonly record struct ClickHouseTcpProfileEvent -{ - /// Initializes a new instance of the struct. - /// When the server sampled the counter. - /// The server host the counter came from. - /// The OS thread the counter belongs to, or 0 for a query-wide total. - /// Whether is an increment or a reading. - /// The counter name. - /// The increment or the reading. - public ClickHouseTcpProfileEvent( - DateTimeOffset currentTime, - string hostName, - ulong threadId, - ClickHouseTcpProfileEventType type, - string name, - long value) - { - CurrentTime = currentTime; - HostName = hostName; - ThreadId = threadId; - Type = type; - Name = name; - Value = value; - } - - /// When the server sampled the counter, as a UTC instant. - public DateTimeOffset CurrentTime { get; } - - /// The server host the counter came from. - public string HostName { get; } - - /// The OS thread the counter belongs to, or 0 for a query-wide total. - public ulong ThreadId { get; } - - /// Whether is an increment to add up or a reading to take as it stands. - public ClickHouseTcpProfileEventType Type { get; } - - /// The counter name, e.g. Query or NetworkReceiveBytes. - public string Name { get; } - - /// The increment or the reading, per . - public long Value { get; } -} - -/// How to read the of a profile event. -public enum ClickHouseTcpProfileEventType -{ - /// The server sent a type outside the range it documents. - Unknown = 0, - - /// An increment: add it to the running total for this counter. - Increment = 1, - - /// A reading at a point in time: it replaces the previous one rather than adding to it. - Gauge = 2, -} diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs index 250c01ff7..fa20c4028 100644 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs @@ -12,8 +12,7 @@ namespace ClickHouse.Driver.Tcp; /// /// Every member is optional, and setting one costs almost nothing: the packets arrive and are decoded either /// way, to keep the connection aligned, and an unset callback only means the result is discarded instead of -/// handed over. What is not free is asking the server to send them at all — see -/// . +/// handed over. What is not free is asking the server to send them at all — see . /// /// /// Callbacks run synchronously on the thread draining the response, in the order the packets arrive. @@ -22,9 +21,11 @@ namespace ClickHouse.Driver.Tcp; /// never throw for control flow. /// /// -/// and borrow their block: it is valid for the call only, -/// and is released as soon as the callback returns. Copy out what must outlive it, and do not retain the block, -/// its columns, or their value spans. Every other callback receives owned values that are safe to keep. +/// Every block is borrowed, on the same contract as +/// : it is valid for the call only, and is released as soon +/// as the callback returns. Copy out what must outlive it, and do not retain the block, its columns, or their +/// value spans. Nothing is materialized on your behalf, so a callback that reads two columns of one row pays +/// for two columns of one row. /// /// public sealed class ClickHouseTcpQueryCallbacks @@ -39,23 +40,74 @@ public sealed class ClickHouseTcpQueryCallbacks public Action OnProfileInfo { get; init; } /// - /// Called once per line of the server's own log. The server sends these only when the query sets - /// send_logs_level (its default, fatal, is effectively silent), so setting this callback alone - /// produces nothing. + /// Called with a borrowed block of the server's own log lines. The server sends these only when the query + /// sets send_logs_level (its default, fatal, is effectively silent), so setting this callback + /// alone produces nothing. /// - public Action OnServerLog { get; init; } - - /// Called once per server performance counter sample. - public Action OnProfileEvent { get; init; } + /// + /// The block's schema is fixed by the server: + /// + /// event_timeDateTime, read as — whole Unix seconds. + /// event_time_microsecondsUInt32 — the sub-second part, to be added to event_time. + /// host_nameString. + /// query_idString. + /// thread_idUInt64. + /// priorityInt8 — see the warning below. + /// sourceString — the server-side logger name, e.g. executeQuery. + /// textString — the message. + /// + /// + /// priority runs the opposite way to : a lower + /// number is more severe. It is a Poco severity — 1 fatal, 2 critical, 3 error, 4 warning, 5 notice, + /// 6 information, 7 debug, 8 trace, 9 test — so filter with <=, not >=. Treat a value + /// outside 1..9 as unknown rather than failing: the server may add a level. + /// + /// + /// + /// + /// OnLog = block => + /// { + /// ReadOnlySpan<sbyte> priority = block.Column<sbyte>("priority").Values; + /// IColumn<string> text = block.Column<string>("text"); + /// for (int row = 0; row < block.RowCount; row++) + /// { + /// if (priority[row] <= 4) // warning or worse + /// { + /// logger.LogWarning("{Message}", text[row]); + /// } + /// } + /// } + /// + /// + public Action OnLog { get; init; } /// - /// Called with the borrowed WITH TOTALS block. Valid for the call only. + /// Called with a borrowed block of the server's performance counters. The same counter arrives repeatedly as + /// the query progresses. /// + /// + /// The block's schema is fixed by the server: + /// + /// host_nameString. + /// current_timeDateTime, read as — whole Unix seconds. + /// thread_idUInt64 — 0 for a query-wide total. + /// typeInt8 — 1 an increment to add up, 2 a gauge reading that replaces the last. + /// nameString — the counter, e.g. SelectedRows. + /// valueInt64, and signed because a gauge can fall. + /// + /// + /// Reading name allocates a string per row, and the server reports many counters per block, so bind + /// only the columns you need and read name no more often than the filter requires. + /// + /// + public Action OnProfileEvents { get; init; } + + /// Called with the borrowed WITH TOTALS block, whose single row has the query's own result shape. public Action OnTotals { get; init; } /// - /// Called with the borrowed extremes block, whose two rows are the minimum and the maximum. The server sends - /// it only when the query sets the extremes setting. Valid for the call only. + /// Called with the borrowed extremes block, whose two rows are the minimum and the maximum in the query's own + /// result shape. The server sends it only when the query sets the extremes setting. /// public Action OnExtremes { get; init; } } diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpServerLogRow.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpServerLogRow.cs deleted file mode 100644 index 84b1417ad..000000000 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpServerLogRow.cs +++ /dev/null @@ -1,98 +0,0 @@ -using System; - -namespace ClickHouse.Driver.Tcp; - -/// -/// One row of the server's own log, streamed to the client while a query runs. The server sends these only when -/// the query asks it to, with the send_logs_level setting (its default, fatal, is effectively -/// silent). -/// -/// -/// Every member is owned, so a row is safe to keep after the callback returns. -/// -public readonly record struct ClickHouseTcpServerLogRow -{ - /// Initializes a new instance of the struct. - /// When the server wrote the line, to microsecond resolution. - /// The server host that wrote the line. - /// The id of the query the line belongs to. - /// The OS thread that wrote the line. - /// The severity. - /// The server-side logger name. - /// The message. - public ClickHouseTcpServerLogRow( - DateTimeOffset eventTime, - string hostName, - string queryId, - ulong threadId, - ClickHouseTcpServerLogLevel level, - string source, - string text) - { - EventTime = eventTime; - HostName = hostName; - QueryId = queryId; - ThreadId = threadId; - Level = level; - Source = source; - Text = text; - } - - /// When the server wrote the line, to microsecond resolution, as a UTC instant. - public DateTimeOffset EventTime { get; } - - /// The server host that wrote the line. - public string HostName { get; } - - /// The id of the query the line belongs to. - public string QueryId { get; } - - /// The OS thread that wrote the line. - public ulong ThreadId { get; } - - /// The severity. - public ClickHouseTcpServerLogLevel Level { get; } - - /// The server-side logger name, e.g. executeQuery. - public string Source { get; } - - /// The message. - public string Text { get; } -} - -/// -/// The severity of a . The values are the server's own log priorities, so -/// a lower number is more severe — the reverse of Microsoft.Extensions.Logging.LogLevel. -/// -public enum ClickHouseTcpServerLogLevel -{ - /// The server sent a priority outside the range it documents. - Unknown = 0, - - /// The process cannot continue. - Fatal = 1, - - /// A failure that needs attention now. - Critical = 2, - - /// A failure. - Error = 3, - - /// Something unexpected that did not fail the operation. - Warning = 4, - - /// A normal but significant event. - Notice = 5, - - /// Informational progress. - Information = 6, - - /// Detail for diagnosing a problem. - Debug = 7, - - /// The most detailed level the server emits by query. - Trace = 8, - - /// Test-only output. - Test = 9, -} diff --git a/ClickHouse.Driver.Tcp/Client/MetadataCallbackBridge.cs b/ClickHouse.Driver.Tcp/Client/MetadataCallbackBridge.cs deleted file mode 100644 index f2cfc60e2..000000000 --- a/ClickHouse.Driver.Tcp/Client/MetadataCallbackBridge.cs +++ /dev/null @@ -1,161 +0,0 @@ -using System; -using System.Collections.Generic; -using ClickHouse.Driver.Tcp.Format; -using ClickHouse.Driver.Tcp.Protocol; -using ClickHouse.Driver.Tcp.Types; - -namespace ClickHouse.Driver.Tcp.Client; - -/// -/// Turns the public into the wire-shaped -/// the connection drains into, and projects the two fixed-schema metadata blocks -/// into owned rows on the way. -/// -/// -/// The projection is what keeps a borrowed block from reaching a caller who cannot know it is about to be -/// released. Log and ProfileEvents blocks have a schema the server fixes, so a row type is safe to publish; -/// Totals and Extremes carry the query's own result shape, so they stay blocks. -/// -internal static class MetadataCallbackBridge -{ - /// - /// Builds the handlers for one operation, or null when nothing at all is listening — which keeps the read - /// path's null check the whole cost of the feature for a caller who set no callbacks. - /// - /// The caller's callbacks, or null. - /// A client-internal progress observer to run before the caller's, or null. - /// A client-internal summary observer to run before the caller's, or null. - /// The handlers to drain into, or null. - public static MetadataHandlers Build( - ClickHouseTcpQueryCallbacks callbacks, - Action onProgress = null, - Action onProfileInfo = null) - { - Action serverLog = callbacks?.OnServerLog; - Action profileEvent = callbacks?.OnProfileEvent; - Action progress = Combine(onProgress, callbacks?.OnProgress); - Action profileInfo = Combine(onProfileInfo, callbacks?.OnProfileInfo); - Action totals = callbacks?.OnTotals; - Action extremes = callbacks?.OnExtremes; - - if (progress is null && profileInfo is null && serverLog is null && profileEvent is null && totals is null && extremes is null) - { - return null; - } - - return new MetadataHandlers - { - OnProgress = progress, - OnProfileInfo = profileInfo, - OnTotals = totals, - OnExtremes = extremes, - OnLog = serverLog is null ? null : block => ProjectServerLog(block, serverLog), - OnProfileEvents = profileEvent is null ? null : block => ProjectProfileEvents(block, profileEvent), - }; - } - - // The client's own observer runs first, so a caller's callback that throws cannot rob the client of the - // telemetry it already had in hand. - private static Action Combine(Action first, Action second) - { - if (first is null) - { - return second; - } - - return second is null ? first : first + second; - } - - private static void ProjectServerLog(Block block, Action callback) - { - const string Kind = "Log"; - - ReadOnlySpan eventTime = Column(block, Kind, "event_time").Values; - ReadOnlySpan microseconds = Column(block, Kind, "event_time_microseconds").Values; - ReadOnlySpan threadId = Column(block, Kind, "thread_id").Values; - ReadOnlySpan priority = Column(block, Kind, "priority").Values; - IColumn hostName = Column(block, Kind, "host_name"); - IColumn queryId = Column(block, Kind, "query_id"); - IColumn source = Column(block, Kind, "source"); - IColumn text = Column(block, Kind, "text"); - - for (int row = 0; row < block.RowCount; row++) - { - callback(new ClickHouseTcpServerLogRow( - Instant(eventTime[row], microseconds[row]), - hostName[row], - queryId[row], - threadId[row], - LogLevel(priority[row]), - source[row], - text[row])); - } - } - - private static void ProjectProfileEvents(Block block, Action callback) - { - const string Kind = "ProfileEvents"; - - ReadOnlySpan currentTime = Column(block, Kind, "current_time").Values; - ReadOnlySpan threadId = Column(block, Kind, "thread_id").Values; - ReadOnlySpan type = Column(block, Kind, "type").Values; - IColumn hostName = Column(block, Kind, "host_name"); - IColumn name = Column(block, Kind, "name"); - - // A counter is a signed count: a gauge can fall as well as rise. Every supported server sends Int64 - // (checked against 25.8, the oldest), so any other width is a protocol change to fail on rather than - // reinterpret. - ReadOnlySpan values = Column(block, Kind, "value").Values; - - for (int row = 0; row < block.RowCount; row++) - { - callback(new ClickHouseTcpProfileEvent( - Instant(currentTime[row], 0), - hostName[row], - threadId[row], - EventType(type[row]), - name[row], - values[row])); - } - } - - // The seconds column is a bare DateTime, so its value is a Unix instant with no timezone of its own. - private static DateTimeOffset Instant(uint unixSeconds, uint microseconds) - => DateTimeOffset.FromUnixTimeSeconds(unixSeconds).AddTicks(microseconds * TimeSpan.TicksPerMicrosecond); - - // An out-of-range value becomes Unknown rather than throwing: a server that grows a level must not break a - // caller who only wanted the message text. - private static ClickHouseTcpServerLogLevel LogLevel(sbyte priority) - => priority is >= (sbyte)ClickHouseTcpServerLogLevel.Fatal and <= (sbyte)ClickHouseTcpServerLogLevel.Test - ? (ClickHouseTcpServerLogLevel)priority - : ClickHouseTcpServerLogLevel.Unknown; - - private static ClickHouseTcpProfileEventType EventType(sbyte type) - => type is >= (sbyte)ClickHouseTcpProfileEventType.Increment and <= (sbyte)ClickHouseTcpProfileEventType.Gauge - ? (ClickHouseTcpProfileEventType)type - : ClickHouseTcpProfileEventType.Unknown; - - private static IColumn Column(Block block, string kind, string name) - { - IColumn column = Column(block, kind, name); - return column as IColumn - ?? throw new ClickHouseProtocolException( - $"{kind} column '{name}' has type '{column.TypeName}', which does not read as {typeof(T).Name}."); - } - - // Walks the columns rather than Block.ColumnNames, which would materialize and cache a string[] for every - // metadata block, and these arrive repeatedly through a query. - private static IColumn Column(Block block, string kind, string name) - { - IReadOnlyList columns = block.Columns; - for (int i = 0; i < columns.Count; i++) - { - if (string.Equals(columns[i].Name, name, StringComparison.Ordinal)) - { - return columns[i]; - } - } - - throw new ClickHouseProtocolException($"{kind} block has no column named '{name}'."); - } -} diff --git a/ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs b/ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs index 0573e7aa4..81474243b 100644 --- a/ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs +++ b/ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs @@ -2,7 +2,6 @@ using System.Diagnostics; using ClickHouse.Driver.Tcp.Client; using ClickHouse.Driver.Tcp.Logging; -using ClickHouse.Driver.Tcp.Protocol; using Microsoft.Extensions.Logging; namespace ClickHouse.Driver.Tcp.Diagnostic; @@ -37,26 +36,29 @@ private ClientOperation(Activity activity, ILogger logger, string operationName, startedAt = Stopwatch.GetTimestamp(); } - /// The handlers the operation's response drains into, or null when nothing needs them. - public MetadataHandlers Handlers { get; private set; } + /// The client's own metadata observers, or null when nothing needs them. + public ClickHouseTcpQueryCallbacks Telemetry { get; private set; } /// Starts the span and the log line for a statement, and builds its handlers. /// The client options the span's endpoint attributes come from. /// The client-category logger, or null when none is configured. /// The statement. /// The caller's query id, or null to let the server assign one. - /// The caller's metadata callbacks, or null. /// The operation, or null when nothing is observing it. + /// + /// The caller's own callbacks are not this type's concern: the connection invokes them alongside + /// rather than through it, so a caller who wants progress and no tracing starts no + /// operation at all. + /// public static ClientOperation Start( ClickHouseTcpClientOptions options, ILogger logger, string sql, - string queryId, - ClickHouseTcpQueryCallbacks callbacks) + string queryId) { // Tested before the statement is scanned: reading the leading keyword allocates, and an unconfigured // client must not pay for it on every operation. - if (!TcpActivity.Source.HasListeners() && logger is null && callbacks is null) + if (!TcpActivity.Source.HasListeners() && logger is null) { return null; } @@ -66,11 +68,13 @@ public static ClientOperation Start( var operation = new ClientOperation(activity, logger, operationName ?? TcpActivity.UnknownOperation, queryId); // The counters feed both the span's attributes and the completion log line, so either one alone is reason - // enough to accumulate them. - operation.Handlers = MetadataCallbackBridge.Build( - callbacks, - activity is null && logger is null ? null : operation.Accumulate, - activity is null ? null : activity.SetProfileInfo); + // enough to accumulate them. These run before the caller's callbacks, so a caller callback that throws + // cannot rob the client of telemetry it already had. + operation.Telemetry = new ClickHouseTcpQueryCallbacks + { + OnProgress = operation.Accumulate, + OnProfileInfo = activity is null ? null : activity.SetProfileInfo, + }; if (logger is not null) { diff --git a/ClickHouse.Driver.Tcp/Format/Block.cs b/ClickHouse.Driver.Tcp/Format/Block.cs index df7e91d10..229e6cd23 100644 --- a/ClickHouse.Driver.Tcp/Format/Block.cs +++ b/ClickHouse.Driver.Tcp/Format/Block.cs @@ -95,6 +95,78 @@ public IReadOnlyList ColumnNames /// The column at that position. public IColumn this[int index] => Columns[index]; + /// The column called , matched ordinally. + /// + /// The lookup is a scan of , so bind a column once before a row loop rather than + /// addressing it per row. ClickHouse column names are case-sensitive, and so is this. + /// + /// The column name. + /// The column with that name. + /// is null. + /// The block has no column with that name. + public IColumn this[string name] + { + get + { + ArgumentNullException.ThrowIfNull(name); + return TryGetColumn(name, out IColumn column) ? column : throw NoSuchColumn(name); + } + } + + /// Finds the column called , matched ordinally. + /// The column name. + /// The column with that name, or null when there is none. + /// Whether the block has a column with that name. + /// is null. + public bool TryGetColumn(string name, out IColumn column) + { + ArgumentNullException.ThrowIfNull(name); + + // Scanned rather than looked up in a dictionary: building one would allocate per block, and a block is + // decoded, read and released. Callers bind their columns once, outside the row loop. + IReadOnlyList columns = Columns; + for (int i = 0; i < columns.Count; i++) + { + if (string.Equals(columns[i].Name, name, StringComparison.Ordinal)) + { + column = columns[i]; + return true; + } + } + + column = null; + return false; + } + + /// The column called , as the typed view its values read through. + /// Same scan and the same advice as : bind once, outside the row loop. + /// The CLR element type the column's values read as. + /// The column name. + /// The typed column. + /// is null. + /// The block has no column with that name. + /// The column's values cannot be read as . + public IColumn Column(string name) => Typed(this[name]); + + /// The column at , as the typed view its values read through. + /// The CLR element type the column's values read as. + /// The zero-based column index. + /// The typed column. + /// is not a column of this block. + /// The column's values cannot be read as . + public IColumn Column(int index) + { + if (index < 0 || index >= Columns.Count) + { + throw new ArgumentOutOfRangeException( + nameof(index), + index, + $"{Describe()} has {Columns.Count} columns."); + } + + return Typed(Columns[index]); + } + /// Releases the columns' storage (returning any pooled buffers). Idempotent. public void Dispose() { @@ -103,4 +175,14 @@ public void Dispose() column.Dispose(); } } + + private static IColumn Typed(IColumn column) + => column as IColumn + ?? throw new InvalidCastException( + $"Column '{column.Name}' has type '{column.TypeName}', whose values cannot be read as {typeof(T).Name}."); + + private ArgumentException NoSuchColumn(string name) + => new($"{Describe()} has no column named '{name}'. Its columns are: {string.Join(", ", ColumnNames)}.", nameof(name)); + + private string Describe() => string.IsNullOrEmpty(Name) ? "The block" : $"Block '{Name}'"; } diff --git a/ClickHouse.Driver.Tcp/Protocol/ClickHouseTcpConnection.cs b/ClickHouse.Driver.Tcp/Protocol/ClickHouseTcpConnection.cs index 63d34f419..1ae42ca1a 100644 --- a/ClickHouse.Driver.Tcp/Protocol/ClickHouseTcpConnection.cs +++ b/ClickHouse.Driver.Tcp/Protocol/ClickHouseTcpConnection.cs @@ -309,7 +309,7 @@ public async ValueTask PingAsync(CancellationToken cancellationToken) /// Runs a query and streams its result as a sequence of s. Sends the Query and the /// empty end-of-input marker, then drains the response, yielding each row-bearing Data block. The /// interleaved metadata packets (Progress, ProfileInfo, ProfileEvents, Log, TableColumns, Totals, - /// Extremes) are always consumed to keep the stream aligned; supply to + /// Extremes) are always consumed to keep the stream aligned; supply to /// observe them, otherwise their contents are discarded. /// /// @@ -338,7 +338,8 @@ public async ValueTask PingAsync(CancellationToken cancellationToken) /// Per-query settings as textual values, or null for none. /// Query parameter values in SQL representation, or null for none. /// The query id, or null to let the server assign one. - /// Optional callbacks for the interleaved metadata packets, or null to discard them. + /// The client's own metadata observers, run before the caller's, or null. + /// The caller's callbacks for the interleaved metadata packets, or null to discard them. /// A token to observe for cancellation. /// An async stream of the result's row-bearing blocks, each valid only for its own iteration. /// The connection is busy with another operation. @@ -351,7 +352,8 @@ internal async IAsyncEnumerable QueryAsync( IReadOnlyDictionary settings = null, IReadOnlyDictionary parameters = null, string queryId = null, - MetadataHandlers handlers = null, + ClickHouseTcpQueryCallbacks telemetry = null, + ClickHouseTcpQueryCallbacks callbacks = null, [EnumeratorCancellation] CancellationToken cancellationToken = default) { ArgumentNullException.ThrowIfNull(sql); @@ -431,8 +433,8 @@ internal async IAsyncEnumerable QueryAsync( else { // Everything else is interleaved metadata: consumed to stay stream-aligned, surfaced to the - // handlers when set. An unexpected packet throws from here. - await ConsumeMetadataAsync(packet, negotiated, readContext, handlers, cancellationToken).ConfigureAwait(false); + // callbacks when set. An unexpected packet throws from here. + await ConsumeMetadataAsync(packet, negotiated, readContext, telemetry, callbacks, cancellationToken).ConfigureAwait(false); } } } @@ -490,9 +492,10 @@ internal async IAsyncEnumerable QueryAsync( /// written — the write memory backstop bounding peak client memory during a large insert (a single column /// larger than the cap still buffers in full). Independent of the row-based block split. Defaults to /// . - /// Optional callbacks for the metadata the server interleaves into the insert - /// acknowledgement (notably for rows written and - /// ), or null to discard it. + /// The client's own metadata observers, run before the caller's, or null. + /// The caller's callbacks for the metadata the server interleaves into the insert + /// acknowledgement (notably for rows written and + /// ), or null to discard it. /// A token to observe for cancellation. /// A task that completes when the server acknowledges the insert with end-of-stream. /// or is null. @@ -512,11 +515,12 @@ internal ValueTask InsertAsync( string queryId = null, int? maxRowsPerBlock = DefaultMaxRowsPerBlock, int maxSendBufferBytes = BlockWriter.DefaultFlushThresholdBytes, - MetadataHandlers handlers = null, + ClickHouseTcpQueryCallbacks telemetry = null, + ClickHouseTcpQueryCallbacks callbacks = null, CancellationToken cancellationToken = default) { ValidateInsertArguments(sql, columns, maxRowsPerBlock, maxSendBufferBytes, out int rowCount); - return InsertCoreAsync(sql, columns, buildColumns: null, rowCount, settings, parameters, queryId, maxRowsPerBlock, maxSendBufferBytes, handlers, cancellationToken); + return InsertCoreAsync(sql, columns, buildColumns: null, rowCount, settings, parameters, queryId, maxRowsPerBlock, maxSendBufferBytes, telemetry, callbacks, cancellationToken); } /// @@ -535,7 +539,8 @@ internal ValueTask InsertAsync( string queryId = null, int? maxRowsPerBlock = DefaultMaxRowsPerBlock, int maxSendBufferBytes = BlockWriter.DefaultFlushThresholdBytes, - MetadataHandlers handlers = null, + ClickHouseTcpQueryCallbacks telemetry = null, + ClickHouseTcpQueryCallbacks callbacks = null, CancellationToken cancellationToken = default) { ArgumentNullException.ThrowIfNull(sql); @@ -546,7 +551,7 @@ internal ValueTask InsertAsync( } ValidateInsertGeometry(maxRowsPerBlock, maxSendBufferBytes); - return InsertCoreAsync(sql, columns: null, buildColumns, rowCount, settings, parameters, queryId, maxRowsPerBlock, maxSendBufferBytes, handlers, cancellationToken); + return InsertCoreAsync(sql, columns: null, buildColumns, rowCount, settings, parameters, queryId, maxRowsPerBlock, maxSendBufferBytes, telemetry, callbacks, cancellationToken); } /// @@ -562,7 +567,8 @@ private async ValueTask InsertCoreAsync( string queryId, int? maxRowsPerBlock, int maxSendBufferBytes, - MetadataHandlers handlers, + ClickHouseTcpQueryCallbacks telemetry, + ClickHouseTcpQueryCallbacks callbacks, CancellationToken cancellationToken) { // Bail on cancellation before claiming the connection, so a pre-cancelled call leaves it idle. @@ -586,7 +592,7 @@ private async ValueTask InsertCoreAsync( await writer.FlushAsync(cancellationToken).ConfigureAwait(false); // Drain metadata until the schema block (the first Data packet) or a terminal packet. - (Block schema, ClickHouseServerException error) = await ReadToNextDataBlockAsync(negotiated, readContext, handlers, cancellationToken).ConfigureAwait(false); + (Block schema, ClickHouseServerException error) = await ReadToNextDataBlockAsync(negotiated, readContext, telemetry, callbacks, cancellationToken).ConfigureAwait(false); if (schema is null) { if (error is null) @@ -637,7 +643,7 @@ private async ValueTask InsertCoreAsync( await StreamInsertRowsAsync(plan, rowCount, maxRowsPerBlock, maxSendBufferBytes, negotiated, cancellationToken).ConfigureAwait(false); // Rethrow any server error once the state is back to Ready. - pending = await DrainToEndOfStreamAsync(negotiated, readContext, handlers, cancellationToken).ConfigureAwait(false); + pending = await DrainToEndOfStreamAsync(negotiated, readContext, telemetry, callbacks, cancellationToken).ConfigureAwait(false); completed = true; } } @@ -777,18 +783,20 @@ await WriteDataBlockPacketAsync( /// /// The negotiated protocol. /// The codec-resolution context (timezone) for decoding blocks. - /// Optional metadata callbacks for the interleaved packets, or null to discard them. + /// The client's own metadata observers, run before the caller's, or null. + /// The caller's metadata callbacks for the interleaved packets, or null to discard them. /// A token to observe for cancellation. /// The parked server exception, or null if the stream ended cleanly. private async ValueTask DrainToEndOfStreamAsync( NegotiatedProtocol negotiated, ResolveContext context, - MetadataHandlers handlers, + ClickHouseTcpQueryCallbacks telemetry, + ClickHouseTcpQueryCallbacks callbacks, CancellationToken cancellationToken) { while (true) { - (Block block, ClickHouseServerException error) = await ReadToNextDataBlockAsync(negotiated, context, handlers, cancellationToken).ConfigureAwait(false); + (Block block, ClickHouseServerException error) = await ReadToNextDataBlockAsync(negotiated, context, telemetry, callbacks, cancellationToken).ConfigureAwait(false); if (block is null) { return error; @@ -1011,13 +1019,15 @@ private async ValueTask ReadMetadataBlockAsync( ServerPacketType packet, NegotiatedProtocol negotiated, ResolveContext context, - Action handler, + Action first, + Action second, CancellationToken cancellationToken) { Block block = await ReadBlockAsync(packet, negotiated, context, cancellationToken).ConfigureAwait(false); try { - handler?.Invoke(block); + first?.Invoke(block); + second?.Invoke(block); } finally { @@ -1180,13 +1190,15 @@ internal async ValueTask HandshakeAsync(ClientHandshakeParameters handshake, Can /// /// The negotiated protocol, for version-gated fields. /// The codec-resolution context (timezone) for decoding blocks. - /// Optional metadata callbacks for the interleaved packets, or null to discard them. + /// The client's own metadata observers, run before the caller's, or null. + /// The caller's metadata callbacks for the interleaved packets, or null to discard them. /// A token to observe for cancellation. /// The next Data block, or a null block plus the parked terminal exception (if any). private async ValueTask<(Block block, ClickHouseServerException error)> ReadToNextDataBlockAsync( NegotiatedProtocol negotiated, ResolveContext context, - MetadataHandlers handlers, + ClickHouseTcpQueryCallbacks telemetry, + ClickHouseTcpQueryCallbacks callbacks, CancellationToken cancellationToken) { while (true) @@ -1204,7 +1216,7 @@ internal async ValueTask HandshakeAsync(ClientHandshakeParameters handshake, Can return (await ReadBlockAsync(ServerPacketType.Data, negotiated, context, cancellationToken).ConfigureAwait(false), null); default: - await ConsumeMetadataAsync(packet, negotiated, context, handlers, cancellationToken).ConfigureAwait(false); + await ConsumeMetadataAsync(packet, negotiated, context, telemetry, callbacks, cancellationToken).ConfigureAwait(false); break; } } @@ -1212,52 +1224,56 @@ internal async ValueTask HandshakeAsync(ClientHandshakeParameters handshake, Can /// /// Consumes one interleaved metadata packet to keep the stream aligned, handing it to the matching callback - /// in when one is set and discarding it otherwise. Shared by the query and insert + /// to each set callback in turn, the client's own first, and discarding it otherwise. Shared by the query and insert /// response drains. Any packet type not valid mid-response at this protocol target is a violation. /// /// The packet type just read (never Data, Exception, or EndOfStream). /// The negotiated protocol, for version-gated fields. /// The codec-resolution context (timezone) for decoding block-bearing packets. - /// Optional metadata callbacks, or null to discard every packet. + /// The client's own metadata observers, run before the caller's, or null. + /// The caller's metadata callbacks, or null to discard every packet. /// A token to observe for cancellation. /// is not a valid interleaved packet. private async ValueTask ConsumeMetadataAsync( ServerPacketType packet, NegotiatedProtocol negotiated, ResolveContext context, - MetadataHandlers handlers, + ClickHouseTcpQueryCallbacks telemetry, + ClickHouseTcpQueryCallbacks callbacks, CancellationToken cancellationToken) { switch (packet) { - // Block-bearing packets lend the borrowed block to the handler for the call, then release it. + // Block-bearing packets lend the borrowed block to each set handler for the call, then release it. case ServerPacketType.Totals: - await ReadMetadataBlockAsync(ServerPacketType.Totals, negotiated, context, handlers?.OnTotals, cancellationToken).ConfigureAwait(false); + await ReadMetadataBlockAsync(ServerPacketType.Totals, negotiated, context, telemetry?.OnTotals, callbacks?.OnTotals, cancellationToken).ConfigureAwait(false); break; case ServerPacketType.Extremes: - await ReadMetadataBlockAsync(ServerPacketType.Extremes, negotiated, context, handlers?.OnExtremes, cancellationToken).ConfigureAwait(false); + await ReadMetadataBlockAsync(ServerPacketType.Extremes, negotiated, context, telemetry?.OnExtremes, callbacks?.OnExtremes, cancellationToken).ConfigureAwait(false); break; case ServerPacketType.ProfileEvents: - await ReadMetadataBlockAsync(ServerPacketType.ProfileEvents, negotiated, context, handlers?.OnProfileEvents, cancellationToken).ConfigureAwait(false); + await ReadMetadataBlockAsync(ServerPacketType.ProfileEvents, negotiated, context, telemetry?.OnProfileEvents, callbacks?.OnProfileEvents, cancellationToken).ConfigureAwait(false); break; case ServerPacketType.Log: - await ReadMetadataBlockAsync(ServerPacketType.Log, negotiated, context, handlers?.OnLog, cancellationToken).ConfigureAwait(false); + await ReadMetadataBlockAsync(ServerPacketType.Log, negotiated, context, telemetry?.OnLog, callbacks?.OnLog, cancellationToken).ConfigureAwait(false); break; case ServerPacketType.Progress: { ClickHouseTcpProgress progress = await ClickHouseTcpProgress.ReadAsync(reader, negotiated, cancellationToken).ConfigureAwait(false); - handlers?.OnProgress?.Invoke(progress); + telemetry?.OnProgress?.Invoke(progress); + callbacks?.OnProgress?.Invoke(progress); break; } case ServerPacketType.ProfileInfo: { ClickHouseTcpProfileInfo profileInfo = await ClickHouseTcpProfileInfo.ReadAsync(reader, cancellationToken).ConfigureAwait(false); - handlers?.OnProfileInfo?.Invoke(profileInfo); + telemetry?.OnProfileInfo?.Invoke(profileInfo); + callbacks?.OnProfileInfo?.Invoke(profileInfo); break; } diff --git a/ClickHouse.Driver.Tcp/Protocol/MetadataHandlers.cs b/ClickHouse.Driver.Tcp/Protocol/MetadataHandlers.cs deleted file mode 100644 index 84f9f4f53..000000000 --- a/ClickHouse.Driver.Tcp/Protocol/MetadataHandlers.cs +++ /dev/null @@ -1,44 +0,0 @@ -using System; -using ClickHouse.Driver.Tcp.Format; - -namespace ClickHouse.Driver.Tcp.Protocol; - -/// -/// Optional callbacks for the metadata packets the server interleaves into a query or insert response. Each -/// handler is optional; where one is null the corresponding packet is still consumed to keep the stream -/// aligned, but its contents are discarded. -/// -/// -/// Handlers run synchronously on the thread draining the response, in the order the packets arrive on the -/// wire. Keep them fast: they sit on the read path between blocks. A handler that throws propagates out of the -/// operation and terminates the connection, so a handler must not throw for control flow. -/// -/// -/// -/// Block-bearing handlers borrow. Blocks are valid only for the duration of the call; -/// the object is disposed and its storage is released as soon as the handler returns. -/// Copy out anything you need to keep, and do not retain the block, its columns, or their value spans. -/// The scalar handlers (, ) -/// receive owned, immutable values that are safe to retain. -/// -/// -internal sealed class MetadataHandlers -{ - /// Invoked for each Progress packet, which the server sends repeatedly as work advances. - public Action OnProgress { get; init; } - - /// Invoked for the ProfileInfo summary (rows/blocks/bytes read, limit application). - public Action OnProfileInfo { get; init; } - - /// Invoked with the borrowed Totals block (the WITH TOTALS row). Valid only for the call. - public Action OnTotals { get; init; } - - /// Invoked with the borrowed Extremes block (min/max rows). Valid only for the call. - public Action OnExtremes { get; init; } - - /// Invoked with a borrowed block of server log rows. Valid only for the call. - public Action OnLog { get; init; } - - /// Invoked with a borrowed block of profile-event metric rows. Valid only for the call. - public Action OnProfileEvents { get; init; } -} From 94a11fac9a989b11fa1f5cf8fb68858cb07548d7 Mon Sep 17 00:00:00 2001 From: Alex Soffronow-Pagonidis Date: Fri, 28 Aug 2026 11:02:18 +0200 Subject: [PATCH 5/6] Keep statement text out of telemetry by default StatementMaxLength now defaults to 5 rather than 300, so query text reaches a span attribute or a log line only when a caller raises it deliberately. Five rather than zero, because at zero IncludeSqlInActivityTags would produce no db.query.text at all and look broken; at five it produces a visibly truncated stub. Condense the ClickHouseTcpQueryCallbacks and LoggerFactory documentation. The Log and ProfileEvents column tables become one line each, and the LoggerFactory remarks lose the paragraph arguing that logging statement text is deliberate. Drop five unit tests whose every assertion is made again by an integration test against a real server, and collapse the six connection-level metadata tests into one parametrized test. That fixture now asserts only what the client-level one cannot: that each packet reaches its callback and leaves the connection reusable. The two assertions it alone made, the single Totals row and exactly one Extremes block, move to the callback fixture. Co-Authored-By: Claude Opus 5 (1M context) --- .../Client/ClickHouseTcpClientOptionsTests.cs | 2 + .../Diagnostic/ClientOperationTests.cs | 17 -- .../Diagnostic/TcpActivityTests.cs | 58 +---- .../ClickHouseTcpCallbackIntegrationTests.cs | 25 ++- ...seTcpConnectionMetadataIntegrationTests.cs | 203 +++++------------- .../ClickHouseTcpLoggingIntegrationTests.cs | 4 +- .../Client/ClickHouseTcpClientOptions.cs | 27 +-- .../Client/ClickHouseTcpQueryCallbacks.cs | 71 ++---- 8 files changed, 105 insertions(+), 302 deletions(-) diff --git a/ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpClientOptionsTests.cs b/ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpClientOptionsTests.cs index 78c13734c..f2de283e7 100644 --- a/ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpClientOptionsTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpClientOptionsTests.cs @@ -35,6 +35,8 @@ public void Defaults_WhenNotOverridden_MatchNativeProtocolConventions() Assert.That(options.MaxConnectionLifetime, Is.EqualTo(TimeSpan.FromMinutes(30))); Assert.That(options.IdleTimeout, Is.EqualTo(TimeSpan.FromMinutes(5))); Assert.That(options.PoolReusePolicy, Is.EqualTo(ClickHouseTcpPoolReusePolicy.Lifo)); + Assert.That(options.IncludeSqlInActivityTags, Is.False); + Assert.That(options.StatementMaxLength, Is.EqualTo(5), "a stub, so statement text has to be asked for"); }); } diff --git a/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs b/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs index 76dabb3b4..e352b0bc2 100644 --- a/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs @@ -40,23 +40,6 @@ public void Start_LoggerOnly_AccumulatesTheCountersTheCompletionLineNeeds() Assert.That(completed.Message, Does.Contain("reading 10 rows"), "the increments are summed, not overwritten"); } - [Test] - public void Dispose_NeitherSucceededNorFailed_ReportsTheOperationAbandoned() - { - using var factory = new CapturingLoggerFactory(); - CapturingLogger logger = factory.Logger(ClickHouseTcpDiagnostics.ClientLogCategory); - - using (ClientOperation operation = ClientOperation.Start(Options, logger, "SELECT 1", queryId: null)) - { - } - - Assert.Multiple(() => - { - Assert.That(logger.WithEventId(1003), Is.Not.Empty); - Assert.That(logger.WithEventId(1001), Is.Empty); - }); - } - [Test] public void Start_QueryIdSet_PutsItOnTheLogLine() { diff --git a/ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs b/ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs index bb5a3b9e4..17e6c66be 100644 --- a/ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs @@ -100,7 +100,7 @@ public void StartStatement_SqlNotIncluded_OmitsTheQueryText() [Test] public void StartStatement_SqlIncluded_SetsTheQueryText() { - ClickHouseTcpClientOptions options = Options with { IncludeSqlInActivityTags = true }; + ClickHouseTcpClientOptions options = Options with { IncludeSqlInActivityTags = true, StatementMaxLength = 100 }; TcpActivity.StartStatement(options, "SELECT 1", "SELECT", queryId: null)?.Dispose(); @@ -164,43 +164,6 @@ public void SetCounters_ReadCounters_SetsTheReadAttributesAndOmitsTheWriteOnes() }); } - [Test] - public void SetCounters_WriteCountersFromTheServer_SetsTheWriteAttributes() - { - // Reached by an INSERT ... SELECT, the case the server does report write counters for. - using (Activity activity = TcpActivity.StartStatement(Options, "INSERT INTO t SELECT 1", "INSERT", queryId: null)) - { - activity.SetCounters(new ClickHouseTcpProgress(rows: 9, bytes: 72, totalRows: 9, wroteRows: 7, wroteBytes: 56, elapsedNs: 1), rowsSent: null); - } - - Activity span = Single(); - Assert.Multiple(() => - { - Assert.That(span.GetTagItem("db.clickhouse.written_rows"), Is.EqualTo(7UL)); - Assert.That(span.GetTagItem("db.clickhouse.written_bytes"), Is.EqualTo(56UL)); - }); - } - - [Test] - public void SetCounters_NoProgressPacket_ReportsOnlyTheRowsTheClientSent() - { - // The shape every insert takes: the server counts nothing back to the client, so zero read counters would - // claim it reported reading nothing rather than reporting nothing at all. - using (Activity activity = TcpActivity.StartStatement(Options, "INSERT INTO t VALUES", "INSERT", queryId: null)) - { - activity.SetCounters(default, rowsSent: 3); - } - - Activity span = Single(); - Assert.Multiple(() => - { - Assert.That(span.GetTagItem("db.clickhouse.written_rows"), Is.EqualTo(3UL)); - Assert.That(span.GetTagItem("db.clickhouse.read_rows"), Is.Null); - Assert.That(span.GetTagItem("db.clickhouse.read_bytes"), Is.Null); - Assert.That(span.GetTagItem("db.clickhouse.elapsed_ns"), Is.Null, "a span claiming zero server time is worse than one claiming none"); - }); - } - [Test] public void SetCounters_ProgressWithoutWriteCounters_StillReportsTheRowsTheClientSent() { @@ -234,17 +197,6 @@ public void SetProfileInfo_Summary_SetsTheResultAttributes() }); } - [Test] - public void SetSuccess_Completed_SetsTheOkStatus() - { - using (Activity activity = TcpActivity.StartStatement(Options, "SELECT 1", "SELECT", queryId: null)) - { - activity.SetSuccess(); - } - - Assert.That(Single().Status, Is.EqualTo(ActivityStatusCode.Ok)); - } - [Test] public void SetError_ServerException_SetsTheErrorStatusAndTheServerErrorCode() { @@ -302,14 +254,6 @@ public void StartPing_WithAListener_NamesTheSpanPingAndSetsTheEndpoint() }); } - [Test] - public void StartConnect_WithAListener_NamesTheSpanConnect() - { - TcpActivity.StartConnect(Options)?.Dispose(); - - Assert.That(Single().OperationName, Is.EqualTo("connect")); - } - [Test] public void StartStatement_NoListener_ReturnsNull() { diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs index e6f3dfc0e..ca92f27a5 100644 --- a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs @@ -8,10 +8,11 @@ namespace ClickHouse.Driver.Tcp.Tests.Integration; -// The public callback surface, driven end to end through the client. The connection-level fan-out is covered by -// ClickHouseTcpConnectionMetadataIntegrationTests; what these add is that ClickHouseTcpQueryOptions.Callbacks -// reaches the read path at all, and that the Log and ProfileEvents blocks carry the schema the callback docs -// promise — a caller reads them by column name, so a rename on the server has to fail here. +// The public callback surface, driven end to end through the client: that ClickHouseTcpQueryOptions.Callbacks +// reaches the read path at all, what each packet carries, and that the Log and ProfileEvents blocks have the +// schema the callback docs promise — a caller reads those by column name, so a rename on the server has to fail +// here. ClickHouseTcpConnectionMetadataIntegrationTests covers the layer below, where a packet leaving the +// connection unusable would show. [TestFixture] [Category("Integration")] public class ClickHouseTcpCallbackIntegrationTests @@ -205,6 +206,7 @@ public async Task StreamAsync_OnTotals_LendsTheGrandTotalBlock() await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); int blocks = 0; + int rows = 0; ulong grandTotal = 0; await DrainAsync( client, @@ -216,6 +218,7 @@ await DrainAsync( OnTotals = block => { blocks++; + rows = block.RowCount; grandTotal = ((IColumn)block[1]).Values[0]; }, }, @@ -224,6 +227,7 @@ await DrainAsync( Assert.Multiple(() => { Assert.That(blocks, Is.EqualTo(1)); + Assert.That(rows, Is.EqualTo(1), "the single totals row"); Assert.That(grandTotal, Is.EqualTo(100UL)); }); } @@ -233,6 +237,7 @@ public async Task StreamAsync_OnExtremes_LendsTheMinimumAndMaximumBlock() { await using ClickHouseTcpClient client = TcpServerFixture.CreateClient(); + int blocks = 0; ulong[] extremes = null; await DrainAsync( client, @@ -242,11 +247,19 @@ await DrainAsync( Settings = new Dictionary { ["extremes"] = "1" }, Callbacks = new ClickHouseTcpQueryCallbacks { - OnExtremes = block => extremes = ((IColumn)block[0]).Values.ToArray(), + OnExtremes = block => + { + blocks++; + extremes = ((IColumn)block[0]).Values.ToArray(); + }, }, }); - Assert.That(extremes, Is.EqualTo(new ulong[] { 0, 9 })); + Assert.Multiple(() => + { + Assert.That(blocks, Is.EqualTo(1), "exactly one Extremes block"); + Assert.That(extremes, Is.EqualTo(new ulong[] { 0, 9 }), "the minimum then the maximum"); + }); } [Test] diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpConnectionMetadataIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpConnectionMetadataIntegrationTests.cs index 47975d804..6f08d8c89 100644 --- a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpConnectionMetadataIntegrationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpConnectionMetadataIntegrationTests.cs @@ -1,15 +1,17 @@ +using System; using System.Collections.Generic; using System.Threading; using System.Threading.Tasks; using ClickHouse.Driver.Tcp.Format; using ClickHouse.Driver.Tcp.Protocol; -using ClickHouse.Driver.Tcp.Types; namespace ClickHouse.Driver.Tcp.Tests.Integration; -// Drives each interleaved metadata packet from a real server and asserts its handler fires, validating the -// decoders against real server output rather than only hand-authored bytes. A yielded Block is borrowed, and so -// is a block handed to a block handler — everything needed is copied out inside the callback. +// Drives each interleaved metadata packet from a real server at the connection level, where the packet dispatcher +// sits, and asserts two things a fully-drained query does not: that the packet's callback fires, and that the +// connection is left reusable. A decoder consuming the wrong byte count can still let the query finish while +// leaving the connection unusable. What the packets carry, and the schema of the Log and ProfileEvents blocks, +// belongs to ClickHouseTcpCallbackIntegrationTests. // // Not covered here: TableColumns (the server sends it for external-table/defaults scenarios that a plain query // does not create, and the client discards it anyway) and PartUUIDs (needs part-level query deduplication on a @@ -20,166 +22,65 @@ public class ClickHouseTcpConnectionMetadataIntegrationTests { private static readonly CancellationToken None = CancellationToken.None; - private static async Task DrainAsync(ClickHouseTcpConnection connection, string sql, ClickHouseTcpQueryCallbacks handlers, IReadOnlyDictionary settings = null) + /// The metadata packets a plain query can be made to produce. + public enum MetadataPacket { - await foreach (Block block in connection.QueryAsync(sql, settings: settings, callbacks: handlers, cancellationToken: None)) - { - _ = block.RowCount; - } + Progress, + ProfileInfo, + ProfileEvents, + Totals, + Extremes, + Log, } - [Test] - public async Task QueryAsync_ScanningManyRows_InvokesProgressWithRowsRead() + [TestCase(MetadataPacket.Progress, "SELECT sum(number) FROM numbers(2000000)", null, null)] + [TestCase(MetadataPacket.ProfileInfo, "SELECT number FROM numbers(10)", null, null)] + [TestCase(MetadataPacket.ProfileEvents, "SELECT number FROM numbers(10)", null, null)] + [TestCase(MetadataPacket.Totals, "SELECT number % 3 AS k, count() AS c FROM numbers(100) GROUP BY k WITH TOTALS", null, null)] + [TestCase(MetadataPacket.Extremes, "SELECT number FROM numbers(10)", "extremes", "1")] + [TestCase(MetadataPacket.Log, "SELECT sum(number) FROM numbers(100000)", "send_logs_level", "trace")] + public async Task QueryAsync_MetadataPacket_InvokesItsCallbackAndLeavesTheConnectionReady( + MetadataPacket packet, + string sql, + string settingKey, + string settingValue) { - await using var connection = await TcpServerFixture.ConnectAsync(None); - - int progressCount = 0; - ulong maxRows = 0; - await DrainAsync(connection, "SELECT sum(number) FROM numbers(2000000)", new ClickHouseTcpQueryCallbacks - { - OnProgress = p => - { - progressCount++; - if (p.Rows > maxRows) - { - maxRows = p.Rows; - } - }, - }); + await using ClickHouseTcpConnection connection = await TcpServerFixture.ConnectAsync(None); - Assert.Multiple(() => + int invocations = 0; + ClickHouseTcpQueryCallbacks callbacks = packet switch { - Assert.That(progressCount, Is.GreaterThan(0), "at least one Progress packet"); - Assert.That(maxRows, Is.GreaterThan(0UL), "Progress reports rows read"); - Assert.That(connection.State, Is.EqualTo(TcpConnectionState.Ready)); - }); - } - - [Test] - public async Task QueryAsync_AnyQuery_InvokesProfileInfo() - { - await using var connection = await TcpServerFixture.ConnectAsync(None); - - int count = 0; - ulong rows = 0; - await DrainAsync(connection, "SELECT number FROM numbers(10)", new ClickHouseTcpQueryCallbacks + MetadataPacket.Progress => new ClickHouseTcpQueryCallbacks { OnProgress = _ => invocations++ }, + MetadataPacket.ProfileInfo => new ClickHouseTcpQueryCallbacks { OnProfileInfo = _ => invocations++ }, + MetadataPacket.ProfileEvents => new ClickHouseTcpQueryCallbacks { OnProfileEvents = WhenRows }, + MetadataPacket.Totals => new ClickHouseTcpQueryCallbacks { OnTotals = WhenRows }, + MetadataPacket.Extremes => new ClickHouseTcpQueryCallbacks { OnExtremes = WhenRows }, + MetadataPacket.Log => new ClickHouseTcpQueryCallbacks { OnLog = WhenRows }, + _ => throw new ArgumentOutOfRangeException(nameof(packet), packet, "unhandled packet"), + }; + + IReadOnlyDictionary settings = settingKey is null + ? null + : new Dictionary { [settingKey] = settingValue }; + + await foreach (Block block in connection.QueryAsync(sql, settings: settings, callbacks: callbacks, cancellationToken: None)) { - OnProfileInfo = info => - { - count++; - rows = info.Rows; - }, - }); - - Assert.Multiple(() => - { - Assert.That(count, Is.GreaterThan(0), "ProfileInfo summary is sent"); - Assert.That(rows, Is.EqualTo(10UL)); - Assert.That(connection.State, Is.EqualTo(TcpConnectionState.Ready)); - }); - } - - [Test] - public async Task QueryAsync_AnyQuery_InvokesProfileEvents() - { - await using var connection = await TcpServerFixture.ConnectAsync(None); - - int blocks = 0; - await DrainAsync(connection, "SELECT number FROM numbers(10)", new ClickHouseTcpQueryCallbacks - { - OnProfileEvents = block => - { - if (block.RowCount > 0) - { - blocks++; - } - }, - }); - - Assert.Multiple(() => - { - Assert.That(blocks, Is.GreaterThan(0), "the server sends a ProfileEvents block"); - Assert.That(connection.State, Is.EqualTo(TcpConnectionState.Ready)); - }); - } - - [Test] - public async Task QueryAsync_GroupByWithTotals_InvokesTotalsOnce() - { - await using var connection = await TcpServerFixture.ConnectAsync(None); - - int totalsCount = 0; - int totalsRows = 0; - ulong totalCount = 0; - await DrainAsync( - connection, - "SELECT number % 3 AS k, count() AS c FROM numbers(100) GROUP BY k WITH TOTALS", - new ClickHouseTcpQueryCallbacks - { - OnTotals = block => - { - totalsCount++; - totalsRows = block.RowCount; - totalCount = ((IColumn)block[1]).Values[0]; - }, - }); + _ = block.RowCount; + } Assert.Multiple(() => { - Assert.That(totalsCount, Is.EqualTo(1), "exactly one Totals block"); - Assert.That(totalsRows, Is.EqualTo(1), "the totals row"); - Assert.That(totalCount, Is.EqualTo(100UL), "the grand total count"); - Assert.That(connection.State, Is.EqualTo(TcpConnectionState.Ready)); + Assert.That(invocations, Is.GreaterThan(0), "the packet reached its callback"); + Assert.That(connection.State, Is.EqualTo(TcpConnectionState.Ready), "and was consumed whole, leaving the connection reusable"); }); - } - - [Test] - public async Task QueryAsync_ExtremesSetting_InvokesExtremesWithMinAndMax() - { - await using var connection = await TcpServerFixture.ConnectAsync(None); - int extremesCount = 0; - ulong[] rows = null; - await DrainAsync( - connection, - "SELECT number FROM numbers(10)", - new ClickHouseTcpQueryCallbacks - { - OnExtremes = block => - { - extremesCount++; - rows = ((IColumn)block[0]).Values.ToArray(); - }, - }, - settings: new Dictionary { ["extremes"] = "1" }); - - Assert.Multiple(() => + // A block-shaped packet counts only when it carries rows, an empty one proving nothing was decoded out of it. + void WhenRows(Block block) { - Assert.That(extremesCount, Is.EqualTo(1), "exactly one Extremes block"); - Assert.That(rows, Is.EqualTo(new ulong[] { 0, 9 }), "min then max"); - Assert.That(connection.State, Is.EqualTo(TcpConnectionState.Ready)); - }); - } - - [Test] - public async Task QueryAsync_TraceLogsSetting_InvokesLog() - { - await using var connection = await TcpServerFixture.ConnectAsync(None); - - int logRows = 0; - await DrainAsync( - connection, - "SELECT sum(number) FROM numbers(100000)", - new ClickHouseTcpQueryCallbacks + if (block.RowCount > 0) { - OnLog = block => logRows += block.RowCount, - }, - settings: new Dictionary { ["send_logs_level"] = "trace" }); - - Assert.Multiple(() => - { - Assert.That(logRows, Is.GreaterThan(0), "the server streams trace-level log rows"); - Assert.That(connection.State, Is.EqualTo(TcpConnectionState.Ready)); - }); + invocations++; + } + } } } diff --git a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs index 0f0800f05..98891f94b 100644 --- a/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs @@ -61,7 +61,9 @@ public async Task StreamAsync_WithALoggerFactory_LogsTheHandshakeResult() [Test] public async Task StreamAsync_WithALoggerFactory_LogsTheStatementAndItsCounters() { - await using ClickHouseTcpClient client = CreateClient(); + // The default cap allows a stub only, so reading the statement back out of the log has to lift it. + await using ClickHouseTcpClient client = + new(TcpServerFixture.Options() with { LoggerFactory = factory, StatementMaxLength = 100 }); await DrainAsync(client, "SELECT sum(number) FROM numbers(1000)"); diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs index 870f89417..7dc40f0d9 100644 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs @@ -30,7 +30,7 @@ public sealed record ClickHouseTcpClientOptions internal const int DefaultMinPoolSize = 0; internal const int DefaultMaxPoolSize = 20; internal const ClickHouseTcpPoolReusePolicy DefaultPoolReusePolicy = ClickHouseTcpPoolReusePolicy.Lifo; - internal const int DefaultStatementMaxLength = 300; + internal const int DefaultStatementMaxLength = 5; /// /// The Compression connection-string value used when the key is absent. LZ4 is what @@ -291,20 +291,11 @@ public sealed record ClickHouseTcpClientOptions /// Where the client gets its loggers, or null to log nothing. Cannot be set from a connection string. /// /// - /// /// The client logs its own lifecycle — connects, handshakes, pool checkouts and retirements, operation - /// outcomes — under the ClickHouse.Driver.Tcp.* categories. It does not log what the - /// server reports: server log lines go to - /// , where the caller decides whether they are worth - /// logging. Nothing is formatted while the matching category and level are disabled. - /// - /// - /// At Debug the statement text is logged, up to characters. That is - /// deliberate — a driver log without the statement is hard to use — but it is not the same policy as - /// , which keeps the statement out of traces unless asked. Enable - /// Debug on ClickHouse.Driver.Tcp.Client only where the statements may be recorded, or set - /// to zero to keep them out of both channels. - /// + /// outcomes — under the ClickHouse.Driver.Tcp.* categories, and formats nothing while the matching + /// category and level are disabled. It does not log what the server reports: server log lines + /// go to . Statement text on the Debug line is capped by + /// , which by default allows only a stub. /// public ILoggerFactory LoggerFactory { get; init; } @@ -316,12 +307,12 @@ public sealed record ClickHouseTcpClientOptions /// /// How much of the statement may leave the client as telemetry, in characters; longer text is truncated. - /// Defaults to 300. + /// Defaults to 5, a stub rather than a statement, so recording query text has to be asked for. /// /// - /// It caps both channels — the db.query.text span attribute and the Debug log line — so zero - /// or less keeps the statement text out of telemetry altogether, whatever - /// says. + /// It caps both channels — the db.query.text span attribute and the Debug log line — so raise + /// it to record statements, and set it to zero or less to keep them out even where + /// is on. /// public int StatementMaxLength { get; init; } = DefaultStatementMaxLength; diff --git a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs index fa20c4028..d192488b7 100644 --- a/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs +++ b/ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs @@ -10,22 +10,17 @@ namespace ClickHouse.Driver.Tcp; /// /// /// -/// Every member is optional, and setting one costs almost nothing: the packets arrive and are decoded either -/// way, to keep the connection aligned, and an unset callback only means the result is discarded instead of -/// handed over. What is not free is asking the server to send them at all — see . +/// Every member is optional, and an unset one costs nothing but the discarded result: the packets are decoded +/// either way, to keep the connection aligned. /// /// -/// Callbacks run synchronously on the thread draining the response, in the order the packets arrive. -/// They sit on the read path between result blocks, so keep them fast; hand work off to a queue rather than -/// doing it here. A callback that throws propagates out of the operation and terminates the connection, so -/// never throw for control flow. +/// Callbacks run synchronously on the thread draining the response, in packet order. Keep them fast, and +/// never throw: an exception propagates out of the operation and terminates the connection. /// /// /// Every block is borrowed, on the same contract as -/// : it is valid for the call only, and is released as soon -/// as the callback returns. Copy out what must outlive it, and do not retain the block, its columns, or their -/// value spans. Nothing is materialized on your behalf, so a callback that reads two columns of one row pays -/// for two columns of one row. +/// : it is released as soon as the callback returns, so copy +/// out what must outlive it and retain neither the block, its columns, nor their value spans. /// /// public sealed class ClickHouseTcpQueryCallbacks @@ -40,28 +35,15 @@ public sealed class ClickHouseTcpQueryCallbacks public Action OnProfileInfo { get; init; } /// - /// Called with a borrowed block of the server's own log lines. The server sends these only when the query - /// sets send_logs_level (its default, fatal, is effectively silent), so setting this callback - /// alone produces nothing. + /// Called with a borrowed block of the server's own log lines, whose columns are event_time, + /// event_time_microseconds, host_name, query_id, thread_id, priority, + /// source and text. The server sends them only when the query sets send_logs_level; + /// its default, fatal, is effectively silent. /// /// - /// The block's schema is fixed by the server: - /// - /// event_timeDateTime, read as — whole Unix seconds. - /// event_time_microsecondsUInt32 — the sub-second part, to be added to event_time. - /// host_nameString. - /// query_idString. - /// thread_idUInt64. - /// priorityInt8 — see the warning below. - /// sourceString — the server-side logger name, e.g. executeQuery. - /// textString — the message. - /// - /// - /// priority runs the opposite way to : a lower - /// number is more severe. It is a Poco severity — 1 fatal, 2 critical, 3 error, 4 warning, 5 notice, - /// 6 information, 7 debug, 8 trace, 9 test — so filter with <=, not >=. Treat a value - /// outside 1..9 as unknown rather than failing: the server may add a level. - /// + /// priority is an Int8 Poco severity, so a lower number is more severe — 1 fatal up to + /// 9 test. Filter with <=, and treat a value outside 1..9 as unknown. event_time is a + /// DateTime column read as whole Unix seconds. /// /// /// @@ -71,10 +53,7 @@ public sealed class ClickHouseTcpQueryCallbacks /// IColumn<string> text = block.Column<string>("text"); /// for (int row = 0; row < block.RowCount; row++) /// { - /// if (priority[row] <= 4) // warning or worse - /// { - /// logger.LogWarning("{Message}", text[row]); - /// } + /// if (priority[row] <= 4) logger.LogWarning("{Message}", text[row]); // warning or worse /// } /// } /// @@ -82,24 +61,12 @@ public sealed class ClickHouseTcpQueryCallbacks public Action OnLog { get; init; } /// - /// Called with a borrowed block of the server's performance counters. The same counter arrives repeatedly as - /// the query progresses. + /// Called with a borrowed block of the server's performance counters, whose columns are host_name, + /// current_time, thread_id (0 for a query-wide total), type (1 an increment to add up, + /// 2 a gauge reading that replaces the last), name and value (a signed , + /// because a gauge can fall). The same counter arrives repeatedly as the query progresses, and reading + /// name allocates a string per row. /// - /// - /// The block's schema is fixed by the server: - /// - /// host_nameString. - /// current_timeDateTime, read as — whole Unix seconds. - /// thread_idUInt64 — 0 for a query-wide total. - /// typeInt8 — 1 an increment to add up, 2 a gauge reading that replaces the last. - /// nameString — the counter, e.g. SelectedRows. - /// valueInt64, and signed because a gauge can fall. - /// - /// - /// Reading name allocates a string per row, and the server reports many counters per block, so bind - /// only the columns you need and read name no more often than the filter requires. - /// - /// public Action OnProfileEvents { get; init; } /// Called with the borrowed WITH TOTALS block, whose single row has the query's own result shape. From 202b10d651ab58e251a45cf62e89b476f04c8f9d Mon Sep 17 00:00:00 2001 From: Alex Soffronow-Pagonidis Date: Fri, 28 Aug 2026 13:24:52 +0200 Subject: [PATCH 6/6] Keep background pool dials out of the trace that built the client A timer captures the execution context when it is created and restores it for every callback, and Activity.Current rides in it. The sweep timer is built in the pool constructor, so a client built inside a traced request gave every later background MinPoolSize dial that request's span as the parent of its connect span, with its trace id, for as long as the client lived. The parent has ended by then, so the child sits outside its time bounds, and the captured context also pins that Activity and its parents for the life of the pool. Suppressing the capture at the timer covers the whole chain: the callback runs without a context, so the top-up it starts through Task.Run captures none either. Foreground dials are untouched and still nest under the operation that needed them. The test uses a real timer rather than ControlledTimeProvider, whose timer never fires and so captures nothing to inherit. Co-Authored-By: Claude Opus 5 (1M context) --- .../Client/ConnectionPoolTests.cs | 41 +++++++++++++++++++ .../Client/ConnectionPool.cs | 14 +++++-- 2 files changed, 52 insertions(+), 3 deletions(-) diff --git a/ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolTests.cs b/ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolTests.cs index 529e3ed55..778a15175 100644 --- a/ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolTests.cs +++ b/ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolTests.cs @@ -36,6 +36,47 @@ private static ClickHouseTcpClientOptions Options( PoolReusePolicy = reusePolicy, }; + [Test] + public async Task Sweep_PoolBuiltUnderAnAmbientActivity_DialsTheFloorWithoutInheritingIt() + { + // A real timer, not the controlled clock: this is about the execution context a timer captures when it is + // built, and ControlledTimeProvider hands back an inert timer that never fires. A pool is often built + // inside a traced request, and the sweep it starts outlives that request by the life of the client, so a + // background dial that inherited the request's span would hang every later connect off a finished trace. + var factory = new FakeConnectionFactory(); + var dialed = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + factory.BeforeCreate = _ => + { + dialed.TrySetResult(Activity.Current); + return Task.CompletedTask; + }; + + ClickHouseTcpClientOptions options = Options(maxPoolSize: 2, minPoolSize: 1) with + { + SweepInterval = TimeSpan.FromMilliseconds(20), + }; + + var source = new ActivitySource("ConnectionPoolTests.Ambient"); + using ActivityListener listener = new() + { + ShouldListenTo = candidate => candidate.Name == source.Name, + Sample = (ref ActivityCreationOptions _) => ActivitySamplingResult.AllData, + }; + ActivitySource.AddActivityListener(listener); + + ConnectionPool pool; + using (source.StartActivity("ambient")) + { + pool = new ConnectionPool(options, factory, TimeProvider.System); + } + + await using (pool) + { + Activity ambient = await dialed.Task.WaitAsync(TimeSpan.FromSeconds(30), None); + Assert.That(ambient, Is.Null, "the background dial runs with no ambient span to parent its connect to"); + } + } + [Test] public async Task RentAsync_FirstRent_OpensOneConnection() { diff --git a/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs b/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs index b9df7f480..52ead7491 100644 --- a/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs +++ b/ClickHouse.Driver.Tcp/Client/ConnectionPool.cs @@ -124,9 +124,17 @@ internal ConnectionPool(ClickHouseTcpClientOptions options, IConnectionFactory f permits = new SemaphoreSlim(options.MaxPoolSize, options.MaxPoolSize); TimeSpan period = SweepInterval(options); - sweeper = period == TimeSpan.Zero - ? null - : time.CreateTimer(static state => ((ConnectionPool)state).SweepQuietly(), this, period, period); + + // The timer captures the execution context here and restores it for every callback, so a pool built inside + // an ambient Activity would give each background dial's connect span that Activity as its parent — for the + // pool's whole life, long after the operation it belonged to ended. Suppressing the capture covers the + // whole sweep chain: the callback runs without one, so the top-up it starts captures nothing either. + using (ExecutionContext.SuppressFlow()) + { + sweeper = period == TimeSpan.Zero + ? null + : time.CreateTimer(static state => ((ConnectionPool)state).SweepQuietly(), this, period, period); + } } ///