Chapter 39 Logging (Part 2): Five Sinks, Rotation, and Async

Chapter Orientation

The previous chapter wrote every part of a custom Sink; this chapter assembles the whole machine: five built-in Sinks (console, file, text formatting, JSON formatting, async wrapping) cover the vast majority of output needs, all in a uniform configurator style (ConfigInit + customization + creation). The operations trio — rotation (xrtLogFileRotate), reopen (xrtLogFileReopen, recovering after external truncation), and statistics (xrtLogFileStats) — adapts the file Sinks to long runs. The async Sink is the hot path's key: the submitting thread only enqueues, a dedicated thread writes to disk — logging never slows the business down again.

39.1引入

Three hurdles when logging goes live. Hurdle one: logs must reach the collection pipeline as JSON (ELK/Loki eat structured data) — hand-writing JSON assembly in a custom Sink? Field escaping, time formats, nested error chains — pits everywhere. Hurdle two: log files grow without bound — the disk fills in three months; you need rotation by size, compressed archival, and the ability to resume writing after logrotate truncates externally. Hurdle three: at peak, tens of thousands of records per second, and the disk-write IO latency lands directly on request latency — logging becomes a performance tax.

The three hurdles map to three answer sets: the JSON Sink works out of the box (fields auto-collected into the object, error chains auto-expanded, millisecond timestamps); the file family's Rotate/Reopen/Stats (built-in rotation semantics + external-truncation recovery); and the async Sink moving disk writes off the submit path (queue buffering + a dedicated flushing thread). Their shared precondition is Chapter 38's foundation — every Sink implements the same write-function contract.

39.2概念

The five built-in Sinks in one table

The configurator style is uniform library-wide: ConfigInit fills defaults → change fields as needed → create in one step. The JSON Sink's output shape (visible in the json sample): top-level time (milliseconds)/level/logger/message plus a fields object collecting structured fields — names and types preserved as-is, zero parsing cost for the pipeline.

The file-operations trio

Rotation triggers come in a built-in policy (automatic by size) and manual firing (xrtLogFileRotate, the operations interface — time-based rotation is just cron calling it); xrtLogFilePath queries the current file path — after rotation the path changes, and monitoring needs to know where writing is happening now.

The async Sink: queue + dedicated thread

The truth of the submit path: with a synchronous file Sink, every record's IO latency (milliseconds) lands directly on the business call. The async Sink's structure: the submitting thread only does "format into the queue" (milliseconds; the lock-free queue's batch interface — Chapter 21's MPMC is exactly its foundation); a dedicated thread dequeues in batches and writes (amortized efficiency at batch size 32). The costs and disciplines: shutdown must Flush (xrtLogFlush — a clean exit means the queued records have reached disk; what you lose is the last few hundred milliseconds before a crash); queue capacity is the backpressure valve (when full, drop or block per policy — drop counts go into Stats; "a log flood sacrificing logs" is the correct trade).

Formatting reuse: TextWrite and field printf

The xrtLogTextWrite family lets a custom destination reuse the text formatting engine (your Sink only decides "write where"; formatting is the library's job); the xrtLogFieldsPrintf family printf-assembles field values (a convenience layer; Chapter 38's selection rule still applies). Validators (xrtLogTextConfigValidate / JsonConfigValidate / RecordValidate) stand guard at the config-loading gate — a wrong format string in config surfaces at startup, not as a runtime landmine.

39.3示例

Complete program: structured JSON output

From the repository sample examples/logging/json/main.c — fields auto-collected into the object, error chains expanded:

 */

#include <stdio.h>
#include <string.h>

#include <xrt.h>



/* 输出回调：每个 JSON 分片一段（本例直写 stdout）。 */
static bool exampleLogWrite(xbytesview Data, ptr pUserData)
{
	FILE* pFile = (FILE*)pUserData;

	return fwrite(Data.Data, 1u, Data.Size, pFile) == Data.Size;
}



int main(void)
{
	xlogjsonconfig Config;
	xlogfield Fields[2];
	xlogrecord Record;

	/* 手工组装完整记录：时间、级别、来源、消息、两个结构化字段。 */
	memset(&Record, 0, sizeof(Record));
	Fields[0] = xrtLogFieldUInt(XRT_STR_LITERAL("request_id"), 42u);
	Fields[1] = xrtLogFieldBool(XRT_STR_LITERAL("cached"), false);
	Record.Time = xrtNow();
	Record.Level = XLOG_INFO;
	Record.Logger = XRT_STR_LITERAL("http");
	Record.Message = XRT_STR_LITERAL("request completed");
	Record.Fields = Fields;
	Record.FieldCount = 2u;

	/* 默认配置全字段输出；分片经回调直达目标。 */
	if (
		!xrtLogJsonConfigInit(&Config) ||
		!xrtLogJsonWrite(
			&Record,
			&Config,
			exampleLogWrite,
			stdout,
			NULL
		)
	) {
		fprintf(stderr, "log JSON failed: %s\n", xrtErrorMessage(xrtGetError()));
		return 1;
	}
	return 0;
}

What just happened. (1) One LogFields submission (integer field 42, boolean field false) — the JSON Sink automatically collects them into the fields object: fields delivered typed and intact (42 is a number, not "42"; false is a boolean), zero parsing cost for the pipeline. (2) time is Unix milliseconds (Chapter 3's xtime measure) — machine-sortable, human-formattable; the format choice belongs to the consumer. (3) message and fields are separate in the output — the human-facing message and the machine-searchable fields each in their place; that is the very meaning of "structured logging". Contrast Chapter 38's text Sink (which ignored fields and printed only the message): hang both Sinks on one Logger — text to the console, JSON to the pipeline — dual-format in parallel is precisely this model's value.

Complete program: the async Sink

From examples/logging/async/main.c — zero blocking on the submit thread, a dedicated thread flushing to disk:

 */

#include <xrt.h>

#include <stdio.h>
#include <string.h>



/* 目标 Sink：直接输出原始消息（异步层不关心格式）。 */
static xlogresult exampleLogAsyncWrite(
	const xlogrecord* pRecord,
	ptr pUserData
)
{
	FILE* pFile = (FILE*)pUserData;

	if (
		fwrite(
			pRecord->Message.Data,
			1u,
			pRecord->Message.Size,
			pFile
		) != pRecord->Message.Size ||
		fputc('\n', pFile) == EOF
	) {
		return XLOG_RESULT_ERROR;
	}
	return XLOG_RESULT_WRITTEN;
}



/* 目标 Flush：由异步栅栏在工作线程上按序调用。 */
static bool exampleLogAsyncFlush(ptr pUserData)
{
	return fflush((FILE*)pUserData) == 0;
}



int main(void)
{
	xlogsinkconfig TargetConfig;
	xlogasyncconfig AsyncConfig;
	xlogrecord Record;
	xlogsink* pTarget;
	xlogsink* pAsync;

	/* 先造同步目标 Sink（stdout 直写）。 */
	memset(&TargetConfig, 0, sizeof(TargetConfig));
	TargetConfig.Name = XRT_STR_LITERAL("stdout");
	TargetConfig.Level = XLOG_TRACE;
	TargetConfig.Write = exampleLogAsyncWrite;
	TargetConfig.Flush = exampleLogAsyncFlush;
	TargetConfig.UserData = stdout;
	pTarget = xrtLogSinkCreate(&TargetConfig);
	if ( pTarget == NULL ) {
		return 1;
	}

	/* 配置背压参数后包装：Async 持有目标引用，本地引用可释放。 */
	if ( !xrtLogAsyncConfigInit(&AsyncConfig) ) {
		xrtLogSinkFree(pTarget);
		return 2;
	}
	AsyncConfig.Capacity = 256u;
	AsyncConfig.ByteLimit = 2u * 1024u * 1024u;
	pAsync = xrtLogAsync(pTarget, &AsyncConfig);
	xrtLogSinkFree(pTarget);
	if ( pAsync == NULL ) {
		return 3;
	}

	/* 提交 = 入队即返回；业务线程不等待写盘。 */
	memset(&Record, 0, sizeof(Record));
	Record.Level = XLOG_INFO;
	Record.Message = XRT_STR_LITERAL("asynchronous sink ready");
	if ( xrtLogSinkSubmit(pAsync, &Record) != XLOG_RESULT_WRITTEN ) {
		xrtLogSinkFree(pAsync);
		return 4;
	}

	/* 栅栏冲刷：返回即保证该条已真实写出。 */
	if ( !xrtLogSinkFlush(pAsync) ) {
		xrtLogSinkFree(pAsync);
		return 5;
	}
	xrtLogSinkFree(pAsync);
	return 0;
}

What just happened. (1) The async Sink wraps a real destination (a file) — to the Logger it is an ordinary Sink; the submission interface is unchanged. (2) The main thread's submissions only enqueue (asynchronous sink ready prints immediately — submission was not blocked by disk writes); the dedicated thread consumes in batches in the background. (3) The shutdown path's Flush: queue drained, file handle closed — a clean exit. The sink_tour sample is left as the full-form reading of the operations interfaces: it walks the Ref/Name/Level/SetLevel/Count/Stats/Detach family and the file-specific family (Path/Rotate/Reopen/Stats) end to end — nine oks for nine interface groups.

39.4契约

• Uniform configurators: ConfigInit → customize → create; validators guard the config gate.
• JSON shape: time in milliseconds / level / logger / message + the fields object — fields typed, time machine-ordered.
• Rotation semantics: Rotate renames to archive and opens a new file; automatic by size plus manual triggers; Path queries the current path.
• Truncation recovery: Reopen reopens after an external move/truncate — built-in support for logrotate cooperation.
• Async discipline: Flush at shutdown; queue capacity is the backpressure valve, drop counts go into Stats; submission in milliseconds, flushing amortized in batches.
• Formatting reuse: custom destinations use the TextWrite family; machine-bound fields still go LogFields.

From examples to engineering: three Sink-assembly patterns

Development environment: one console Sink (text format, DEBUG threshold) — instantly readable in the terminal, five-minute assembly. Production standard: a JSON file Sink (INFO threshold, rotation by size) + an async wrapper (queue backpressure) + a console ERROR Sink (the stderr alert channel in container environments) — three Sinks, each at its post, assembled once. Collection pipeline: JSON format straight to stdout (container stdout collection) or rotating files plus a Filebeat-class agent — the format is already uniform at the Sink layer, zero adaptation in the pipeline. The three patterns share a shape: assembly code concentrates in the startup function (Chapter 38's discipline), configuration comes from a Chapter 32 JSON config file (Sink type, path, level — all configurable) — "the logging system's own log config" is the standard exercise in config-driven assembly.

An operations view: logs are a data stream

Treating logging as "printing" is the development view; in production it is a data stream — with a source (business code), a pipeline (Sinks and queues), a destination (files/collection systems), a capacity (disk and queue), and a lifecycle (rotation and archival). Make operations decisions with the data-stream lens: capacity planning reads Stats' write rate × retention period; flood protection relies on the queue's drop policy plus dynamic level lowering (SetLevel adjusts at runtime); failure recovery rehearses Reopen (drill the external truncation); quality monitoring reconciles "submitted vs written" (async drops within tolerance). This view also explains why Chapter 36's pipeline thinking applies again — the logging system is itself a "record → format → queue → disk" pipeline, and the assembly skills you learned in Volume 4 go on duty here directly.

Common Mistakes

/* shutdown */
xrtLogSinkFree(pAsyncSink);   /* freed directly - queue contents dropped */

/* shutdown: flush the queue first, then free */
xrtLogFlush(pLogger);          /* or the async Sink's dedicated Flush interface */
xrtLogSinkFree(pAsyncSink);

void handle_request(void)
{
	xlogsink* pSink = create_file_sink("app.log");   /* one per request */
	xrtLogAttach(gLog, pSink);
	xrtLog(gLog, XLOG_INFO, ...);
	xrtLogSinkFree(pSink);                            /* build, tear down, build again */
}

/* assemble once at startup, reuse globally (Chapter 38's "concentrated assembly" discipline) */
static xlogsink* gFileSink;
void init_logging(void) { gFileSink = create_file_sink("app.log"); xrtLogAttach(gLog, gFileSink); }
void handle_request(void) { xrtLog(gLog, XLOG_INFO, ...); }   /* submit only, never assemble */

Programming Exercises

Summary