consensus log pollution: Block Display dumps full GTxnBytes/payload during PFN catchup recovery #817

Summary / 摘要

Priority: P2 (ops / observability) — not chain safety, but blocks production RCA during mainnet PFN catchup.

While catching up a mainnet Public Full Node, consensus_log/vfn.log becomes nearly unreadable because recovery INFO logs expand full block payloads into multi-hundred-line Vec<u8> Debug dumps (GTxnBytes one byte per line).

在 mainnet PFN catchup 时，consensus_log/vfn.log 因 recovery 路径把完整 block payload 用 {:?} 打成数百行纯数字（GTxnBytes 默认 Debug）而几乎无法检索 / 排障。

Environment / 环境

Measured impact / 实测影响

• Last 20MB of vfn.log: ~957k lines total, ~891k pure-numeric lines (~93.1%) matching ^\s+\d+,?\s*$
• Longest pure-numeric streak sampled in last 80MB: 449 consecutive lines (one GTxnBytes expansion)
• Practical effects:
  • grep Timeout|ERROR|epoch is unusable without heavy filtering
  • Log rotation burns disk during catchup
  • Ops / RCA during catchup is painful

Problem / 问题

Hot INFO paths format consensus objects with Rust default Debug, which recursively dumps:

1. Full Payload / SignedTransaction / GTxnBytes(Vec<u8>) → one byte per indented line ( 2,)
2. Full ValidatorSet including validator_network_addresses: [1, 68, 4, 2, …] byte vectors

This is especially bad during block recovery because the recover log fires once per recovered block.

Root cause / 根因

Primary — recover block + Display for Block

Log site (aptos-core/consensus/src/block_storage/block_store.rs ~L643):

info!("recover block {}, txn_size: {}", p_block.block(), txns.len());

• Fires once per recovered block during catchup recovery (high volume).
• Uses {} → Display for Block.

Format path (aptos-core/consensus/consensus-types/src/block.rs impl Display for Block):

write!(
    f,
    "[id: {}, author: {}, epoch: {}, round: {:02}, parent_id: {}, timestamp: {}, block_number: {:?}, payload: {:?}]",
    ...
    self.payload(),  // FULL Debug of Payload
)

payload: {:?} expands roughly:

InQuorumStore(ProofWithData { proofs: [...], status: Mutex(Some(Cached([SignedTransaction { raw_txn: RawTransaction { payload: GTxnBytes([ byte, byte, ... ]) } }]))) })

GTxnBytes(Vec<u8>) / nested byte fields use Rust default Debug → one byte per line with indentation.

Secondary — ValidatorSet epoch log (same class)

crates/block-buffer-manager/src/block_buffer_manager.rs ~L883–887:

info!(
    "block number {} get validator set from new epoch {} event {:?}",
    block_num, new_epoch, validator_set
);

Full ValidatorSet Debug includes network address byte arrays (observed at epoch 966→967 boundary on the same node).

Production log samples / 生产日志样例

Sanitized structure only (long hex truncated). Full local samples available on the investigation host under /tmp/vfn-log-sample/.

Sample A — recover line that opens SignedTransaction / GTxnBytes

2026-08-14T15:41:31.991402Z [consensus-38] INFO
  aptos-core/consensus/src/block_storage/block_store.rs:643
  recover block [id: 301056b1, author: 0x2a970925…, epoch: 966, round: 24450,
  parent_id: 288e2f2d, timestamp: 1786131693036381, block_number: Some(30320920),
  payload: Some(InQuorumStore(ProofWithData { proofs: [ProofOfStore { info: BatchInfo {
    … digest: HashValue(bec9aa05…), num_txns: 1, num_bytes: 696 }, multi_signature: … }, …],
  status: Mutex(Mutex { data: Some(Cached([SignedTransaction {
    { raw_txn: RawTransaction {
      sender: 0000000000000000000000006136b50c…,
      sequence_number: 53,
      payload: GTxnBytes(
          [
              2,
              249,
              1,
              189,
              …

Sample B — pure-numeric streak (no timestamp; pollutes greps)

            2,
            249,
            1,
            189,
            131,
            1,
            240,
            …
            0,
            170,
            61,
            208,

(~449 lines in one streak, then returns to gext: GravityExtension { … }, txn_size: 1)

Proposed fix / 修复建议

Scope is surgical log formatting only — do not rewrite the whole logging framework.

1. Block Display/Debug must NOT dump full payload bytes/txns

Summary only, e.g.:

• id (short), author short, epoch, round, parent_id short, block_number
• payload kind, proof_count / batch_count, optional digest prefixes
• txn_size already logged separately on the recover line

Prefer changing Display for Block (used by recover log) and audit other INFO uses of {} / {:?} on Block.

2. Recover log

Either:

• Use a compact formatter (not full Display), or
• Downgrade to DEBUG / rate-limit during recovery

3. ValidatorSet epoch log

Print epoch + validator count + short account/consensus keys — not full network address byte vectors via {:?}.

4. Bytes policy (hot INFO paths)

Any Vec<u8> on hot INFO paths → len=N or truncated hex 0xabcd…(N bytes), never default Debug multi-line.

Acceptance criteria / 验收标准

• Synthetic or catchup: after fix, sample ~20MB of consensus log during recovery → pure-numeric line ratio ≈ 0% (^\s+\d+,?\s*$)
• Single log line length bounded (soft target < 2–4KB)
• Still enough fields to debug recovery progress: block_number, round, epoch, txn_size
• ValidatorSet epoch transition logs no longer dump full network-address byte arrays
• No unrelated logging-framework rewrite

Out of scope / 非范围

• Rewriting the global logging framework
• Changing recovery correctness / consensus semantics
• Log shipping / retention product features (disk burn is a symptom of the dump)

References / 代码锚点