Senior Application Developer

loc: Maynooth, ON K0L 2S0tel: 613-553-0960email: rgsamways@gmail.com
Robin Samways

Farpost · Data Ingestion

$ The Bug That Silently Ate 2,706 Records

I was loading 31,152 real civic addresses into a MongoDB collection, in batches, for performance — one round-trip per record was too slow against the dataset size. Each building gets a human-readable slug (e.g. 136-spence-rd-carl-civic), generated by checking the database for anything already using that slug and appending -2, -3, etc. on a collision.

That check has a blind spot: it only sees what's already committed to the database. Two addresses distinguished only by a house-number suffix — 136A Spence Rd and 136B Spence Rd — landed in the same unflushed batch. Neither was in the database yet, so both passed the uniqueness check and were assigned the identical slug. The second one failed at insert time with a duplicate-key error — which looked exactly like the expected, harmless case of re-running the pipeline against data it had already loaded. My error handling treated every duplicate-key error the same way: swallow it and move on. 2,706 real addresses quietly vanished before anyone noticed.

async def _generate_building_slug(record: dict, assigned_slugs: set[str]) -> str:
    """assigned_slugs tracks every slug handed out so far *this run*, checked in
    addition to the DB. Without it, two records sharing house_no+rd_name+municipality
    (distinguished only by house_suf/rd_dir/unit — e.g. 136A vs 136B Spence Rd) that
    land in the same unflushed batch both pass the `await Building.find_one` check
    (neither is in the DB yet) and get assigned the same base slug; the second then
    fails at flush time with a duplicate-key error on the slug index, which looked
    identical to an expected re-run duplicate and was silently swallowed — silently
    dropping 2,706 real records on the first live run before this fix."""
    base = _slugify_component(
        f"{record['house_no']}-{record['house_suf']}-{record['rd_dir']}-{record['rd_name']}-"
        f"{record['unit']}-{record['municipality_code']}-civic",
    ) or "civic-building"
    slug = base
    counter = 2
    while slug in assigned_slugs or await Building.find_one({"slug": slug}):
        slug = f"{base}-{counter}"
        counter += 1
    assigned_slugs.add(slug)
    return slug
except BulkWriteError as e:
    write_errors = e.details.get("writeErrors", [])
    non_id_duplicates = [
        err for err in write_errors
        if err.get("code") != 11000 or "index: _id_" not in err.get("errmsg", "")
    ]
    if non_id_duplicates:
        raise  # a real bug, not idempotency — must not be swallowed
    inserted = e.details.get("nInserted", batch_size - len(write_errors))

The fix

The fix has two parts: (1) track every slug already handed out during this run, in memory, not just what's already in the database — closing the race between unflushed records in the same batch. (2) Stop treating every duplicate-key error the same way — only a duplicate on the _id index is the expected, harmless "already ingested this" case. A duplicate on any other index, like slug, is a real data-loss bug wearing the same error code as a harmless one, and now raises instead of vanishing silently.

Why this matters

The dangerous part of this bug wasn't the collision itself — it's that the failure mode was indistinguishable from correct behavior at a glance. "Duplicate key error, skip it" is right 99% of the time in an idempotent pipeline. Catching the 1% required actually reasoning about which index the duplicate was on, not just the error code. Caught this during verification before it shipped, by checking the actual record count against the expected one rather than trusting a clean exit code.

Feedback on this page