Skip to content

Id fields are logged via Debug, emitting Id { raw: 854, _marker: PhantomData<...> } instead of 854 #475

Description

@20001020ycx

Bug

Id<TypeMarker> derives Debug, so any tracing call site that formats it with the ? sigil
emits the whole struct — including the zero-information _marker: PhantomData<...> field — into
the log record:

"job_id":"Id { raw: 854, _marker: PhantomData<spider_core::types::id::JobIdMarker> }"

Expected:

"job_id":854

This is more than verbosity. Because different call sites format the same logical field
differently, one field name carries three mutually incompatible JSON types in a single log
stream
, which makes it impossible to query or aggregate on.

The three shapes

Measured on a live 4-worker deployment with JSON-formatted tracing output. Counts are a
point-in-time snapshot of the retained container logs taken while the cluster was running, so the
absolute numbers drift upward; the ratios are the point.

field "Id { raw: N, _marker: … }" (Debug) "N" (Display, string) N (number)
em_id 7,463 5,963 13,418
job_id 5,090 2,523 918
rg_id 16 — 8
execution_manager_id 16 — —
scheduler_id — 5,954 —

So job_id is a Debug-formatted struct string, a decimal string, and a JSON number, depending
on which line emitted it.

Root cause

components/spider-core/src/types/id.rs:29 derives Debug:

#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
pub struct Id<TypeMarker: Debug + PartialEq + Eq> {
    raw: u64,
    _marker: PhantomData<TypeMarker>,
}

The derived Debug prints every field, including _marker. That field is zero-sized and its type
is already implied by the log field's name, so it tells a reader nothing.

The two other formatting impls in the same file already do the right thing:

// id.rs:102
impl<TypeMarker: Debug + PartialEq + Eq> Display for Id<TypeMarker> {
    fn fmt(&self, formatter: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
        Display::fmt(&self.get(), formatter)
    }
}

// id.rs:108
impl<TypeMarker: Debug + PartialEq + Eq> Serialize for Id<TypeMarker> {
    fn serialize<SerializerImpl: Serializer>(
        &self,
        serializer: SerializerImpl,
    ) -> Result<SerializerImpl::Ok, SerializerImpl::Error> {
        self.get().serialize(serializer)
    }
}

Debug is the only impl that leaks the marker.

The call sites disagree with each other

Two components have opposite conventions:

file _id = ? (Debug) _id = % (Display)
components/spider-storage/src/state/service.rs 27 0
components/spider-scheduler/src/service.rs 0 19
// spider-storage/src/state/service.rs:168  ->  "Id { raw: 854, _marker: PhantomData<…> }"
job_id = ?job_id,

// spider-scheduler/src/service.rs:99        ->  "854"  (a string, not a number)
em_id = %em_id,

Note that % is an improvement but still does not reach the target: tracing's DisplayValue is
recorded through record_debug/record_str, so a JSON subscriber writes "854" — a quoted
string — not the number 854. All 5,954 scheduler_id occurrences in the sample above are
"scheduler_id":"N", confirming this.

Downstream impact

We ingest these logs into a log-search system. A user searching for the job they care about with
job_id: 854 gets zero hits from the storage component, because the value stored there is an
85-character string. Getting complete results today means knowing all three encodings and OR-ing a
substring match against them. Any dashboard that groups by job_id splits one job across three
buckets.

There is also a size cost: "job_id":854 is 12 bytes and the Debug form is 85 bytes — 73 bytes
of overhead per occurrence
(97 bytes for em_id, whose marker name is longer). In the snapshot
above that is several MB of pure PhantomData text per retention window on a small 4-worker
cluster.

Suggested fix

Fixing this in spider-core/src/types/id.rs means no call site can get it wrong, which seems
preferable to auditing sigils across the repo.

1. Record the field as a u64 (yields exactly "job_id":854).

tracing picks the JSON type from which Visit method is called, so record_u64 is the only
route to an unquoted number:

impl<TypeMarker: Debug + PartialEq + Eq> tracing::field::Value for Id<TypeMarker> {
    fn record(&self, field: &tracing::field::Field, visitor: &mut dyn tracing::field::Visit) {
        visitor.record_u64(field, self.get());
    }
}

Call sites then drop the sigil entirely — job_id = job_id — and every one of them, present and
future, emits a number.

Trade-off: spider-core currently has no tracing dependency (per
components/spider-core/Cargo.toml), so this would add one. If that is unacceptable, the same
output can be had at call sites with job_id = job_id.get(), at the cost of being unenforceable.

2. Independently, stop Debug from leaking PhantomData.

Whether or not (1) is adopted, a hand-written Debug removes the failure mode permanently:

impl<TypeMarker: Debug + PartialEq + Eq> fmt::Debug for Id<TypeMarker> {
    fn fmt(&self, formatter: &mut fmt::Formatter<'_>) -> fmt::Result {
        Debug::fmt(&self.get(), formatter)
    }
}

If you would rather keep Debug visually distinct from a bare integer,
formatter.debug_tuple("Id").field(&self.raw).finish() gives Id(854) — still free of
PhantomData, though it does not satisfy "integer only".

3. Unify the call sites once the type behaves correctly, so ? / % / .get() are no longer
mixed for the same field name.

Happy to open a PR for whichever option you prefer.

Spider version

0.2.0-rc.0 (deployed via CLP Helm chart 0.4.1-dev.8, CLP 0.13.1-dev). Source inspected at
y-scope/spider@main on 2026-09-10.

Environment

  • Kubernetes cluster, Linux 5.15.0, Spider deployed as the CLP chart's subchart
  • 4 spider-worker replicas, 1 spider-scheduler, 1 spider-storage
  • tracing configured with a JSON formatting layer writing to stdout; container logs collected by
    Fluentd and ingested into CLP for search

Reproduction steps

  1. Run Spider with a JSON tracing subscriber at info level or above.

  2. Submit any job, so that both the storage and scheduler components log about it.

  3. Inspect the storage component's Job registered in DB. / Job started. records
    (components/spider-storage/src/state/service.rs:168, :185). The job_id field is the
    string Id { raw: 854, _marker: PhantomData<spider_core::types::id::JobIdMarker> }.

  4. Inspect the scheduler's Task dispatched to execution manager. record
    (components/spider-scheduler/src/service.rs:99). The same class of value appears as the
    quoted string "854".

  5. Grep the combined stream for one field name to see all three encodings coexist:

    grep -ho '"job_id":[^,}]*' *.log | sed 's/[0-9]\+/N/g' | sort | uniq -c | sort -rn
    5090 "job_id":"Id { raw: N
    2523 "job_id":"N"
     918 "job_id":N
    

A minimal reproduction needs no cluster — any tracing::info!(job_id = ?some_id, "…") where
some_id: Id<JobIdMarker> shows the same output.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

bugSomething isn't working

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions