kvcache-ai / kvcache-ai/Mooncake

[RFC]: Standardize Mooncake logging on spdlog with fmt-style APIs

Open
#3,550 4 comments 0 reactions 0 assignees View on GitHub
RFC
Dominant language
C++
Stars
6.6k
Forks
1.2k
Avg merge
3d 5h
Merged PRs (30d)
312

Description

## Changes proposed

## Summary

Mooncake currently has two logging paths:

- Mooncake-owned C++ code primarily uses glog and stream expressions such as `LOG(INFO) << "rank=" << rank`.
- `yalantinglibs/coro_rpc` uses easylog internally, with a separate format, configuration path, and runtime.

The result is inconsistent output, duplicated logging dependencies, and logging calls that are difficult to validate or optimize consistently.

This RFC proposes one logging model for Mooncake:

1. use spdlog as the only logging backend in the final state;
2. send normal log records through a bounded asynchronous queue;
3. use fmt-style, compile-time-checked message templates in Mooncake-owned code;
4. preserve the current human-readable glog line format by default;
5. retain required behaviors such as fatal logging, `errno`, debug/trace filtering, and rate limiting through a small format-style Mooncake API; and
6. remove glog and easylog after all built call sites, including the bundled `coro_rpc` path, have moved.

The intended result is easier to read at the call site and unchanged for an operator reading ordinary log lines.

## Why this needs an RFC

This is not a dependency-only replacement. The repository contains roughly:

- 301 files that directly include glog;
- 5,402 `LOG`/`PLOG` calls;
- 222 `VLOG` calls; and
- additional `CHECK`, fatal, and rate-limited logging sites.

The VLOG usage is broad enough to require an explicit migration, but its level model is shallow: 200 calls use `VLOG(1)`, 17 use `VLOG(2)`, and five dynamic calls are inside `ScopedVLogTimer`. All 90 current `ScopedVLogTimer` construction sites pass level 1. There are no Mooncake-owned `VLOG(3)` or higher calls.

A complete migration will touch several modules and substantially more than 500 lines. It also changes a foundational dependency and must define behavior at process boundaries shared by Store, Transfer Engine, Python extensions, and vendor runtimes.

This RFC overlaps with #3181, which currently proposes bundling glog 0.7.1 as a fixed foundational dependency. If both RFCs are accepted, #3181 should bundle the selected spdlog source instead of glog; Mooncake should not first establish a new long-term glog dependency and then remove it.

Issue #2574 also demonstrates that a process can already contain spdlog through hardware runtimes. Mooncake must therefore use project-owned logger names and must not assume that it owns every spdlog registry entry in the process.

## Goals

- One logging backend for all logs emitted by the final Mooncake build.
- Asynchronous logging for normal records, with a bounded record queue and defined ordering, saturation, shutdown, fatal, and `fork()` behavior.
- Human-readable output compatible with the current glog line format.
- Fmt-style message templates with compile-time checking where the format is a literal.
- Source file and line information on every Mooncake log record.
- Explicit behavior for fatal logs, `errno`, debug/trace filtering, rate limiting, file rotation, and flushing.
- No evaluation of expensive log arguments when the corresponding runtime level is disabled.
- A migration that keeps every intermediate commit buildable and testable.

## Non-goals

- Introducing structured or JSON logging in this change.
- Changing existing log message wording solely for style.
- Adding a general logging abstraction that supports multiple interchangeable backends.
- Rewriting yalantinglibs examples or tests that are not built by Mooncake.
- Preserving glog macros, glog-specific flags, or a permanent stream-style compatibility layer.

## Proposed user-facing format

The default output remains the format operators already see:

```text
I0820 15:03:30.321475 239489 rpc_service.cpp:269] Master Admin Metrics: ...
```

The fields remain:

1. one severity character (`I`, `W`, `E`, or `F`);
2. month and day;
3. local time with microseconds;
4. thread ID;
5. source basename and line; and
6. the message.

spdlog's pattern formatter provides the time, thread, and source fields. A small custom severity flag is required because spdlog calls the highest level `critical`, while the existing format uses `F` for fatal. Conceptually, the pattern is:

```text
%^%*%m%d %H:%M:%S.%f %5t %s:%#]%$ %v
```

`%*` is the Mooncake severity flag. Color is enabled only on an interactive console sink; file output contains no escape sequences.

Trace and debug remain distinct runtime filter levels, but the custom severity flag renders both as `I`. This matches glog, where enabled VLOG records are written with INFO severity, and avoids changing the operator-facing line format as part of the backend migration.

This proposal preserves the line format, not glog's severity-split file naming. File logging will use a stable base filename with numbered rotation. The exact filenames and rotation defaults will be documented with the implementation.

## Proposed call-site API

Mooncake-owned code uses format templates:

```cpp
// Before
LOG(INFO) << "registered segment " << name << " (" << size << " bytes)";

// After
MC_LOG_INFO("registered segment {} ({} bytes)", name, size);
```

The common operations are:

```cpp
MC_LOG_TRACE("selected rail {}", rail);
MC_LOG_DEBUG("request state: {}", state);
MC_LOG_INFO("registered {} bytes at {}", size, pointer);
MC_LOG_WARN("retrying peer {} after {} ms", peer, delay_ms);
MC_LOG_ERROR("transfer {} failed: {}", transfer_id, error);
MC_LOG_FATAL("invalid rank {} for group size {}", rank, group_size);
```

These are intentionally thin Mooncake macros over the central spdlog runtime, rather than a general backend-neutral interface. They provide three Mooncake-specific properties that direct `SPDLOG_*` calls do not provide consistently across this repository:

- a project-owned logger shared by Mooncake DSOs;
- a runtime-level guard before evaluating format arguments; and
- glog-compatible fatal behavior and source information.

The format template remains visible in full at the call site. The wrapper must not accept stream expressions.

### Special behaviors

Required glog behaviors use format-style helpers:

```cpp
MC_PLOG_ERROR("failed to open {}", path); // captures and appends errno
MC_LOG_EVERY_N_WARN(100, "queue is full: {}", queue_size);
MC_LOG_FIRST_N_WARN(3, "falling back to {}", fallback);
MC_CHECK(buffer != nullptr, "buffer for {} is null", object_key);

if (MC_LOG_DEBUG_ENABLED()) {
MC_LOG_DEBUG("allocator state: {}", BuildExpensiveAllocatorDump());
}
```

`MC_LOG_FATAL` and failed checks log a stack trace when the platform supports it, wait until all records queued before the fatal record have been written and the sinks have been flushed, and then abort. A normal asynchronous `flush()` request is not sufficient for this contract because it can return after merely enqueueing the flush operation. `PLOG` helpers capture `errno` before any formatting work and append both its text and numeric value. Fatal `PLOG` is supported for the existing call sites that require it.

Debug-only checks retain their current release-build behavior through `MC_DCHECK`; they are not silently promoted into always-on production checks.

Mooncake does not retain a numeric `MC_VLOG(n)` compatibility API. Existing calls migrate according to their actual use:

| Existing use | Replacement |
| --- | --- |
| `VLOG(1)` | `MC_LOG_DEBUG(...)` |
| `VLOG(2)` | `MC_LOG_TRACE(...)` |
| `VLOG_IS_ON(1)` | `MC_LOG_DEBUG_ENABLED()` |
| `ScopedVLogTimer` | `ScopedDebugLogTimer` |

`ScopedDebugLogTimer` has no numeric level parameter because every current caller passes 1. Tests that manipulate `FLAGS_v` or call `SetVLOGLevel` migrate to the Mooncake logger's debug/trace level controls. This removes glog's separate verbosity state and `vmodule` machinery instead of reproducing an unused compatibility surface.

### Custom types

Types that appear frequently in logs should define `fmt::formatter`. During migration, a type that only has `operator<<` may use `fmt::streamed(value)`, but that is a migration aid, not the desired final form for frequently logged types.

Dynamic format strings must be explicit through `fmt::runtime`. Literal format strings are the default so incorrect specifiers are rejected at compile time.

## Async logging and ownership

Normal non-fatal records use `spdlog::async_logger` with a bounded queue and one worker to preserve output order. Queue saturation uses the non-blocking `overrun_oldest` policy so logging cannot apply backpressure to transfer threads. Overwritten records are counted and reported after the queue recovers instead of being lost silently. Queue capacity and periodic flush intervals are implementation choices validated by benchmarks rather than public configuration in the first version.

Fatal logs, failed checks, and normal shutdown must wait until accepted records have been processed and sinks have flushed. Mooncake's production `fork()` paths must reinitialize the async logging runtime in the child before normal logging resumes; signal handlers and `_exit()` paths do not attempt to drain it.

Mooncake consumes pinned header-only spdlog sources and does not add a `libspdlog.so` dependency. Logger construction, the async thread pool, sinks, and shutdown state live once in the existing Common-owned runtime, while Store, Transfer Engine, Python extensions, and plugins call the exported Mooncake API instead of spdlog globals. This boundary is required because header-only spdlog registries are [not shared between a program and its shared libraries](https://github.com/gabime/spdlog/wiki/How-to-use-spdlog-in-DLLs).

Mooncake-owned logger names use the `mooncake.` prefix and do not replace unrelated registry entries. Call-site formatting and the central implementation use one pinned fmt configuration so independently versioned fmt ABIs are not mixed.

## Removing easylog from the coro_rpc path

Mooncake-owned easylog configuration calls are straightforward to remove, but `coro_rpc` currently contains stream-style `ELOG_*` calls in vendored headers. Silencing easylog or forwarding its already-formatted strings to spdlog would leave two logging implementations and would not satisfy this RFC.

The final migration therefore requires a yalantinglibs change for the `coro_rpc` code built by Mooncake:

1. convert those built call sites to a backend hook that accepts fmt-style arguments;
2. provide Mooncake's `mooncake.rpc` spdlog implementation of that hook; and
3. update the vendored yalantinglibs revision after the same change is proposed upstream.

Mooncake does not rewrite unrelated yalantinglibs examples and tests. Until the yalantinglibs change lands, easylog remains temporarily present and the final dependency-removal phase cannot be declared complete.

## Configuration changes

Project-owned settings remain project-owned:

- `MC_LOG_LEVEL` controls Mooncake's default logger;
- `MC_LOG_DIR` controls Transfer Engine file logging;
- `--log_dir` controls the Store executable's file logging; and
- `MC_RPC_LOG_LEVEL` controls the `mooncake.rpc` logger.

The easylog-specific `MC_YLT_LOG_LEVEL` name is removed rather than retained as an alias. Undocumented glog flags such as `--logtostderr` and `--stop_logging_if_full_disk`, as well as `--v` and `--vmodule`, are also removed. `MC_LOG_LEVEL=debug` and `MC_LOG_LEVEL=trace` select the two migrated verbose levels. Rotation settings, if needed, will be explicit Mooncake settings rather than compatibility definitions for the complete glog flag surface.

## Migration sequence

The implementation should land as a reviewable series, not one repository-wide mechanical patch:

1. **Logging foundation:** add the pinned dependency, `mooncake_logging`, the glog-compatible formatter, async queue and lifecycle hooks, sinks, special helpers, and unit tests. glog remains linked while no call sites have moved.
2. **Transfer Engine and Common:** migrate calls and configuration, add formatters for common transport and status types, and validate standalone TE builds.
3. **Store:** migrate Store libraries, executables, tests, and benchmarks; replace glog log-capture tests with spdlog sinks.
4. **Integration, EP, and PG:** migrate extension and process-group targets and validate Python loading with Store and Transfer Engine in one process.
5. **coro_rpc:** land or vendor the accepted yalantinglibs fmt-style logging hook and route it to `mooncake.rpc`.
6. **Removal:** delete glog/easylog configuration and links, update dependency installation scripts and documentation, and verify no built Mooncake path retains either backend.

Each phase must build and pass its relevant tests before the next phase starts. No phase introduces a second permanent compatibility API.

## Validation

### Behavior

- Golden tests cover the visible prefix for trace, debug, info, warning, error, and fatal records, including the `I` prefix used by trace and debug.
- Death tests verify fatal/check flush-and-abort behavior.
- A fatal record is present after abrupt termination, and every record enqueued before it remains ordered ahead of it.
- `PLOG` tests verify that the original `errno` value is captured.
- Runtime-disabled logs do not evaluate expensive arguments.
- Rate-limited and first-N logs behave deterministically under concurrency.
- Console color never appears in file output.
- File rotation and flush behavior are covered without timing-dependent tests.
- Queue-saturation tests verify that normal producers do not block, the newest records remain available, and the exact overwritten-record count is exposed and reported after recovery.
- Shutdown tests verify that the queue drains before logging state is destroyed.
- Fork tests verify that the parent resumes and the child can reinitialize its logger without deadlock, duplicate registration, or inherited stale sinks.

### Integration

- Representative Common, Transfer Engine, Store, Integration, EP, and PG targets build.
- Python can load Store and Transfer Engine in one process without duplicate logger registration or divergent levels.
- A representative MACA-enabled loading path is checked against the logger-name collision described in #2574 when that toolchain is available.
- Go and Rust bindings link without reproducing an ad hoc list of glog or fmt libraries.

### Removal checks

- No Mooncake-owned source includes `glog/logging.h` or uses `LOG`, `PLOG`, `VLOG`, or glog `CHECK` macros.
- No built `coro_rpc` path emits through easylog.
- Default build artifacts have no glog dependency.
- Installation scripts and active documentation no longer install or describe glog.

### Performance

Before removing glog, microbenchmarks compare:

- enabled logging to a null sink;
- runtime-disabled logging with cheap arguments;
- runtime-disabled logging with an expensive guarded argument; and
- multi-threaded enqueue latency and worker throughput through the asynchronous console-disabled file path;
- producer latency and overwrite accounting when the bounded queue is saturated; and
- drain latency during fatal handling and normal shutdown.

The migration must not regress disabled-log argument evaluation. Any meaningful enabled-log throughput or binary-size regression must be reported with the PR rather than hidden by changing benchmark parameters.

## Trade-offs

### Benefits

- Complete message templates are visible at the call site.
- Literal format strings receive compile-time type checking.
- Formatting avoids iostream state and is generally more efficient.
- One formatter and sink policy produces consistent operator-facing output.
- Producers normally avoid sink I/O latency while one worker preserves record order for human readers.
- The final build removes two logging implementations.

### Costs

- The migration is large and cannot be safely automated without review.
- Frequently logged custom types need fmt formatters.
- Format templates can become hard to read if too much state is packed into one record; migration reviews should prefer named local values over dense inline expressions.
- The yalantinglibs work is an external coordination dependency.
- Maintaining the exact line prefix requires a small custom severity formatter.
- The bounded queue consumes preallocated queue storage and one background thread. During sustained saturation it preserves service progress by overwriting old records, which can remove useful diagnostic history even though the loss is counted and reported.
- Fatal, shutdown, and `fork()` paths require explicit queue lifecycle logic and stronger tests than a synchronous logger.

## Questions for consensus

1. Is preserving the current log *line* format sufficient, while moving from glog severity files to stable spdlog rotating filenames?
2. Is the proposed upstream-first yalantinglibs logging hook acceptable as a completion dependency for removing easylog?

### Before submitting a new issue...

- [x] Make sure you already searched for relevant issues and read the [documentation](https://kvcache-ai.github.io/Mooncake/)

Contributor guide

Open the contributing guide

Research direction

Start by reviewing the existing glog call sites and the Common-owned logging runtime, then inspect logging in Store, Transfer Engine, Python extensions, plugins, and the vendored yalantinglibs coro_rpc path. The work is complete when Mooncake uses the spdlog-based API and tests cover formatting, levels, async behavior, fatal handling, fork and shutdown behavior, while glog and easylog are removed after the upstream coro_rpc change lands.

Written by the indexing model from the issue text.

Assessment

Tech stack
cpp
Domain
infrastructure
Issue type
Refactor
Difficulty
5/5
Estimated time
Over a week
Activity status
Active
Clarity
Mostly clear
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.