Skip to content

[Bug]: Follow mode (-F) silently drops same-timestamp lines from a single source #1501

Description

@fhill2

Bug Description

Summary

In --follow (-F) mode, hl can silently drop log lines when multiple lines written to the same file carry an identical timestamp (i.e. they parse to the same (sec, nsec)). Lines are lost with no error or warning, making follow-mode output unreliable whenever a logger emits several entries sharing the exact same timestamp.

Within a sync-interval window, only the last same-key line survives; earlier ones at that key are dropped. Across sync interval windows, each log line is emitted separately, making this difficult to debug.

When it happens

All of the following must be true:

  1. hl is running in follow mode (-F).
  2. One input file receives multiple lines whose parsed timestamps are exactly equal (same (sec, nsec), at any resolution the timestamp happens to be expressed in).
  3. Those lines are appended in separate write() calls that arrive as separate filesystem events within one --sync-interval-ms window (default 100 ms).

Note: running hl -F log1.log log2.log against files that already contain same-timestamp lines does NOT reproduce this bug.

Why it happens

The merge window is a BTreeMap, and BTreeMap::insert silently overwrites an existing key. Because every same-timestamp line shares the identical key (ts, input, 0, 0), when new lines are added they overwrite the existing value instead of creating a new entry.

same file + identical timestamp + one line per write/event, all within one --sync-interval-ms window ⇒ only the last line survives

Verified on current master: the test fails as shown above.

Steps to Reproduce

I can't reproduce it with a filesystem-based test because the bug depends on filesystem event timing, so I'm including a unit test that bypasses the filesystem entirely and feeds merge_segments two same-source segments with block: 0, an identical ts, and offset 0 directly. This recreates the colliding key (ts, input, 0, 0) on every run:

#[test]
fn test_merge_segments_same_source_same_ts_keeps_both_lines() {
    // This feeds two same-source/same-block(=0)/same-ts/same-offset(=0)
    // segments directly to merge_segments, deterministically reproducing the
    // collision with no fs-event/timing dependency.
    let app = App::new(options());
    let badges = test_badges(2);
    let (txo, rxo) = channel::bounded(10);

    let buf1 = b"  line-one".to_vec();
    let index1 = TimestampIndex {
        block: 0,
        lines: vec![TimestampIndexLine {
            location: 0..buf1.len(),
            ts: ts(100, 0),
        }],
    };

    let buf2 = b"  line-two".to_vec();
    let index2 = TimestampIndex {
        block: 0, // same source, SAME block (mimics fs-event reset)
        lines: vec![TimestampIndexLine {
            location: 0..buf2.len(), // SAME offset (first record of a fresh buffer)
            ts: ts(100, 0),          // SAME timestamp
        }],
    };

    txo.send((0, buf1, index1)).unwrap();
    txo.send((0, buf2, index2)).unwrap();
    drop(txo);

    let mut output = Vec::new();
    app.merge_segments(&badges, rxo, &mut output, 1).unwrap();

    let result = String::from_utf8(output).unwrap();
    assert_eq!(result, "SSline-one\nSSline-two\n");
}

My current workaround is to set timestamp resolution to nanoseconds to avoid duplicates in the map and it works well, but would be great to have no dropped log lines at any timestamp resolution.

Expected Behavior

I expect both lines to be preserved
"SSline-one\nSSline-two\n"

Actual Behavior

actual — line-one was dropped
"SSline-two\n"

Environment Details

  • hl version: 0.36.3
  • OS: OSX
  • Terminal: kitty
  • Shell: bash

Logs or Error Messages

Additional Context

No response

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions