TCP P: observability — metadata callbacks, OpenTelemetry tracing and ILogger

[alex-clickhouse]

Stacked on tcp/epic-k5-qbit (#579). Implements Epic P — observability for the native/TCP client: the metadata the server already decodes becomes a public surface, spans get emitted and propagated, and the client gets its own logger.

Three parts, one per commit-worth of concern, plus the decisions behind them.

1. Metadata callbacks

Every metadata packet the server interleaves was already decoded and handed to an internal MetadataHandlers — which no code under Client/ ever referenced, so the dispatch target was unconditionally null at runtime. This connects it.

ClickHouseTcpQueryOptions.Callbacks takes a ClickHouseTcpQueryCallbacks:

await foreach (Block block in client.StreamAsync(sql, new ClickHouseTcpQueryOptions
{
    Callbacks = new ClickHouseTcpQueryCallbacks
    {
        OnProgress = p => total += p,
        OnProfileInfo = info => Console.WriteLine(info.Rows),
        OnServerLog = row => Console.WriteLine($"{row.Level}: {row.Text}"),
    },
}))

Plain callbacks rather than events or IProgress<T>: an event on a shared client cannot be scoped to one query, and IProgress<T> posts to a captured context, which would move the work off the read path and lose the ordering the wire gives it.

Progress/ProfileInfo move out of Protocol as public ClickHouseTcpProgress / ClickHouseTcpProfileInfo record structs.

The Progress counters are increments, not running totals. That is the wire's contract and it is the easiest thing in this API to get wrong, so the type carries operator + rather than leaving every caller to discover it; an integration test sums the increments over numbers(2000000) and requires exactly 2_000_000, which a running-total reading could not produce.

Log and ProfileEvents project into owned row structs (ClickHouseTcpServerLogRow, ClickHouseTcpProfileEvent). Those two packets have a schema the server fixes, so a row type is safe to publish — and it means 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, so they stay borrowed blocks, on the same contract StreamAsync already has.

Server log lines are not bridged into ILogger. Re-emitting what the server says through our logger is the caller's decision, not the client's. Worth knowing: nothing the client does turns them on either — the server's send_logs_level default is effectively silent, so setting only the callback yields nothing, and a test pins that so the surprise is documented rather than discovered.

2. Tracing, and trace context on the wire

ClickHouseTcpDiagnostics.ActivitySourceName is "ClickHouse.Driver.Tcp", separate from the HTTP transport's source so either can be collected alone. Spans at StreamAsync (so QueryAsync/QueryAsync<T>/ExecuteAsync all get one), each InsertAsync, PingAsync, and the dial.

Attributes are the current stable OpenTelemetry database conventions — db.system.name, db.namespace, db.query.text, db.operation.name, server.address, server.port, error.type, db.response.status_code (the server's own error code) — not the deprecated db.system/db.statement/peer.service set the HTTP transport still emits. That is a deliberate inconsistency inside one package: this surface is new and [Experimental], so it seemed the wrong moment to adopt names upstream has already retired. db.clickhouse.* counters are shared with HTTP. db.user is kept for parity even though the conventions dropped it, and the code says so.

ClientInfo's OpenTelemetry field is no longer a hardcoded has_trace = 0. With an ambient W3C Activity it carries the trace id, span id, trace state and flags, so the server's own system.opentelemetry_span_log rows hang off the caller's trace. The HTTP transport does not do this — it relies on HttpClient injecting W3C headers, and a raw socket has no equivalent free ride.

The encoding is the part to review carefully. trace_id is a ClickHouse UUID — two 8-byte halves, each little-endian — so each half of the big-endian W3C id is reversed; span_id is a plain little-endian UInt64, so it reverses whole. Verified against clickhouse-go's swap64/swap64 in lib/proto/query.go.

A byte-order mistake here is invisible to a round trip: we would send bytes the server reads as a different trace, and nothing on our side would notice. So the proof is asymmetric — ClickHouseTcpTracingIntegrationTests runs a query under a recorded span, then requires the server to have written a row to system.opentelemetry_span_log against the trace id the client sent. Getting the swap wrong yields a different, self-consistent trace id and zero rows.

Gotcha found the hard way: system.opentelemetry_span_log is created on demand, the first time the server records a span. Probing for it before the query silently skipped the test.

3. Logging

ClickHouseTcpClientOptions.LoggerFactory, categories exposed as ClickHouseTcpDiagnostics.{Client,Connection,Pool}LogCategory, and source-generated [LoggerMessage] partials under Logging/ so a disabled level formats nothing.

The two events that most needed this are the ones the pool deliberately swallows. A background top-up dial and a sweep both run on a timer with nobody awaiting them — the pool's own comments said as much, reserving the work for this epic — so without a logger either failure was invisible. ConnectionPoolLoggingTests covers both, and they are reachable no other way.

Every statement line carries QueryId, the key that joins client-side telemetry to system.query_log; it is only reported when the caller set one, a server-assigned id never coming back. StatementMaxLength caps the statement text in both channels, so one setting governs how much SQL leaves the client whichever way it leaves, and 0 keeps it out of telemetry entirely.

What emits what

Spans

Three shapes, all ActivityKind.Client. Every one carries db.system.name, server.address, server.port, db.namespace and db.user.

Span name	Raised by	Covers
the statement's leading keyword — SELECT, INSERT, WITH … (or query when unreadable)	StreamAsync, and so also QueryAsync, QueryAsync<T> and ExecuteAsync, which all funnel through it; plus each of the three InsertAsync overloads	renting a connection, the whole statement, and draining the response
ping	PingAsync	the round trip
connect	the pool's dial, in TcpConnectionFactory	socket connect + TLS negotiation + handshake

Statement spans add db.operation.name (when the leading keyword is readable), db.clickhouse.query_id (when the caller set one) and db.query.text (only with IncludeSqlInActivityTags, truncated to StatementMaxLength).

Statement spans are annotated as the response arrives: db.clickhouse.read_rows / read_bytes / elapsed_ns from the summed Progress increments, and result_rows / result_bytes from ProfileInfo. written_rows is the rows the client sent, because the server sends no Progress at all for rows streamed to it; written_bytes appears only for the statements it does count writes for, an INSERT ... SELECT among them. A statement the server sent no Progress for gets none of these rather than a set of zeroes.

Status is Ok on completion and Error on failure — the latter adding error.type, an exception event, and db.response.status_code carrying the server's own error code when the failure came from the server. An enumeration the caller abandons part-way is left Unset: neither outcome is an honest claim about a result nobody finished reading.

A session's operations produce the same spans, a session being this client over a pinned connection.

Log lines

ClickHouse.Driver.Tcp.Client — one line per operation, each carrying Operation and QueryId:

Id	Level	When
1000	Debug	statement starting (with the statement text, capped by StatementMaxLength)
1001	Debug	completed, with rows and bytes read
1004	Debug	completed, with the rows written — an insert reports this instead of 1001
1002	Error	failed, with the exception
1005	Debug	cancelled by the caller — deliberately not an Error, cancellation being control flow
1003	Debug	abandoned with its result partly read, which is also why its connection gets discarded rather than reused

ClickHouse.Driver.Tcp.Connection:

Id	Level	When
2000	Debug	dialling, naming host, port, user and whether TLS is on
2001	Debug	connected, with the server version, negotiated protocol revision and server timezone
2002	Warning	the dial or handshake failed
2003	Debug	the dial was cancelled — what a client disposal racing a background top-up looks like, so not a warning

ClickHouse.Driver.Tcp.Pool:

Id	Level	When
3000	Trace	reusing an idle connection, with its operation count and age
3001	Debug	no idle connection to reuse, so opening one
3002	Debug	a returned connection closed rather than pooled, no longer being reusable
3003	Debug	a sweep retired idle connections past MaxConnectionLifetime or IdleTimeout
3004	Warning	the pool was exhausted for PoolTimeout — logged just before the TimeoutException
3005	Warning	a background top-up dial failed
3006	Warning	a pool sweep failed
3007	Debug	draining on disposal, with the idle and in-flight counts

3005 and 3006 are the two the pool deliberately swallows — both run on a timer with nobody awaiting them, so a logger is the only place either is reported at all.

Notes for review

• StreamAsync is enumerated by hand rather than with await foreach. 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 — that asymmetry already exists in the HTTP driver's PostStreamAsync, which records nothing for a transport failure. The disposals in the finally are nested, not sequential: Terminate() swallows nothing, so a throw while disposing the enumerator would otherwise skip lease.DisposeAsync() and cost the pool a permit for the client's life.
• ClientInfo.Write reads ambient Activity.Current rather than taking it as a parameter. That is the standard instrumentation idiom and needs no plumbing through three layers, but it does make the Query packet's bytes a function of hidden state — worth a second opinion.
• The no-configuration path allocates nothing. ClientOperation.Start checks Source.HasListeners() before scanning the statement for its leading keyword, because that scan allocates a substring and a ToUpperInvariant. A unit test pins the null return.
• The ProfileEvents value column is read as Int64 only. The protocol notes say the width varies by version, but 25.8 — our floor — was measured sending Int64, so a second path would have been dead code.
• No docs/ change: the TCP client has no public-docs presence at all, so documenting this means introducing the whole client, which is R1/R4's job. Filed as P8.
• No changelog fragment, per the convention for this epic stack.
• N11b is untouched and still open (a server error during Query-packet read poisons the pooled connection). P5's hook is the span; that bug is the pool's.

Tests

• Unit — byte-exact trace context (ClientInfoTraceContextTests), span attribute names and gating (TcpActivityTests), the callback projection's error paths and its degrade-to-Unknown behaviour over hand-built blocks (MetadataCallbackBridgeTests), the zero-cost contract (ClientOperationTests), pool logging over connections that need no server (ConnectionPoolLoggingTests).
• Integration — every callback driven through ClickHouseTcpClient, the Progress-increment sum, span status on success/failure/abandonment, and the trace-propagation round trip.

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.

🤖 Generated with Claude Code

[Copilot]

Pull request overview

Adds observability to the native TCP client, including metadata callbacks, OpenTelemetry propagation, and structured logging.

Changes:

• Exposes progress, profile, server-log, totals, and extremes callbacks.
• Adds client, connection, pool tracing and logging.
• Adds extensive unit and integration coverage.

Reviewed changes

Copilot reviewed 35 out of 35 changed files in this pull request and generated 6 comments.

Show a summary per file

File	Description
ClickHouse.Driver.Tcp/Protocol/Progress.cs	Removes internal progress model.
ClickHouse.Driver.Tcp/Protocol/MetadataHandlers.cs	Uses public metadata models.
ClickHouse.Driver.Tcp/Protocol/ClientInfo.cs	Propagates W3C trace context.
ClickHouse.Driver.Tcp/Protocol/ClickHouseTcpConnection.cs	Decodes public progress/profile types.
ClickHouse.Driver.Tcp/Logging/PoolLog.cs	Defines pool log events.
ClickHouse.Driver.Tcp/Logging/ConnectionLog.cs	Defines connection log events.
ClickHouse.Driver.Tcp/Logging/ClientLog.cs	Defines operation log events.
ClickHouse.Driver.Tcp/Diagnostic/TcpActivity.cs	Implements TCP tracing attributes.
ClickHouse.Driver.Tcp/Diagnostic/ClientOperation.cs	Coordinates tracing, logging, and callbacks.
ClickHouse.Driver.Tcp/Diagnostic/ClickHouseTcpDiagnostics.cs	Exposes diagnostic source/category names.
ClickHouse.Driver.Tcp/Client/MetadataCallbackBridge.cs	Projects metadata packets into callback values.
ClickHouse.Driver.Tcp/Client/IConnectionFactory.cs	Instruments connection establishment.
ClickHouse.Driver.Tcp/Client/ConnectionPool.cs	Adds pool lifecycle logging.
ClickHouse.Driver.Tcp/Client/ClickHouseTcpServerLogRow.cs	Adds public server-log model.
ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryOptions.cs	Adds per-query callbacks.
ClickHouse.Driver.Tcp/Client/ClickHouseTcpQueryCallbacks.cs	Defines callback API.
ClickHouse.Driver.Tcp/Client/ClickHouseTcpProgress.cs	Adds public progress accumulator.
ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileInfo.cs	Publishes profile summaries.
ClickHouse.Driver.Tcp/Client/ClickHouseTcpProfileEvent.cs	Adds public profile-event model.
ClickHouse.Driver.Tcp/Client/ClickHouseTcpClientOptions.cs	Adds logging and telemetry options.
ClickHouse.Driver.Tcp/Client/ClickHouseTcpClient.cs	Instruments query, insert, and ping operations.
ClickHouse.Driver.Tcp.Tests/Utilities/CapturingLogger.cs	Adds test logging utilities.
ClickHouse.Driver.Tcp.Tests/Protocol/ServerPacketDecoderTests.cs	Updates metadata decoding tests.
ClickHouse.Driver.Tcp.Tests/Protocol/ClientInfoTraceContextTests.cs	Tests trace-context encoding.
ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionQueryTests.cs	Updates query metadata tests.
ClickHouse.Driver.Tcp.Tests/Protocol/ClickHouseTcpConnectionInsertTests.cs	Updates insert metadata tests.
ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpTracingIntegrationTests.cs	Tests tracing and propagation.
ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpLoggingIntegrationTests.cs	Tests operation and connection logs.
ClickHouse.Driver.Tcp.Tests/Integration/ClickHouseTcpCallbackIntegrationTests.cs	Tests callbacks end to end.
ClickHouse.Driver.Tcp.Tests/Diagnostic/TcpActivityTests.cs	Tests span attributes and status.
ClickHouse.Driver.Tcp.Tests/Diagnostic/ClientOperationTests.cs	Tests operation instrumentation.
ClickHouse.Driver.Tcp.Tests/Client/MetadataCallbackBridgeTests.cs	Tests metadata projection.
ClickHouse.Driver.Tcp.Tests/Client/ConnectionPoolLoggingTests.cs	Tests pool log events.
ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpProgressTests.cs	Tests progress accumulation.
ClickHouse.Driver.Tcp.Tests/Client/ClickHouseTcpClientOptionsTests.cs	Tests option copying.

Suppressed comments (3)

ClickHouse.Driver.Tcp/Client/ConnectionPool.cs:472

• Log only after closing the reaped connections. A caller-provided logger can throw here; the finally then clears reaped, so the removed idle connections are lost without ever being closed. This is the same close-before-log safeguard already used by pool teardown.

            if (reaped.Count != 0 && logger is not null)
            {
                PoolLog.Retired(logger, reaped.Count);
            }

            CloseAll(reaped);

ClickHouse.Driver.Tcp/Client/ConnectionPool.cs:282

• This log call can abort teardown before the pool waits for/aborts leased connections and disposes the factory. A throwing logger therefore turns diagnostics into incomplete resource cleanup. Defer this message until teardown is complete or guard it so cleanup always continues.

            PoolLog.Draining(logger, closing?.Count ?? 0, inFlight);

ClickHouse.Driver.Tcp/Client/ConnectionPool.cs:782

• Close the discarded connection before logging it. If the caller-provided logger throws here, the connection has already been removed from leased; the permit is released by finally, but the socket is lost and never closed.

            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();
            }

---

💡 Configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.

📢 Thoughts on this report? Let us know!

[cursor]

Cursor Bugbot has reviewed your changes using high effort and found 1 potential issue.

^{❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, have a team admin enable autofix in the Cursor dashboard.}

^{Reviewed by Cursor Bugbot for commit a9a9734. Configure here.}