DEV Community: Paolo

That Username Is Taken. How Did the Form Know Before I Finished Typing?

Paolo — Thu, 01 Oct 2026 09:27:15 +0000

Start typing a username on a sign-up form and, before you've even reached the last letter, a little message shows up underneath telling you it's taken. Change a letter or add a number and it flips to available, as if the site had been waiting for you.

I got curious about how that works on a site with millions of accounts, maybe billions. I'd seen it listed as a common system design interview question, so before reading anything I tried to answer it on my own, and my first idea went in the wrong direction. Figuring out what the form is really asking took me from the database index that does most of the work to a data structure I'm only now getting my head around.

Where I started: ruling names out letter by letter

My first idea was to narrow the list as I typed. "m" rules out almost nothing, "ma" a bit more, "map" more still, and by the last letter only the exact name is left to check. It looked efficient, because each keystroke would build on the work of the one before.

That is the answer to a different question. Narrowing by prefix is how autocomplete works: show me everything that starts with these letters. The sign-up form asks something much smaller. Does this exact string exist, yes or no?

The intermediate answers don't help with that. Almost every short prefix matches a huge number of taken names, so knowing that "ma" has matches tells me nothing about "maple". The only result the user cares about is the one for the complete string, and as it turns out, the form shouldn't even ask about the partial ones.

Finding one name among billions

The lookup itself turned out to be the easy part. Put a unique index on the username column and the database keeps the names sorted in a B-tree. Each node of the tree is a page on disk, and depending on the page size and the length of the keys, it holds a few hundred of them, each pointing to another page one level down. To find a name, the database reads the root, picks the branch where the name would sort, and repeats until it lands on the name or on the spot where it would be.

Because every page fans out to hundreds more, the tree is very wide and very short. With 300 keys per node, four levels already cover 300⁴, about 8 billion entries. With 200 per node you need a fifth. For a table of two billion users, that means four or five hops from the root to the answer.

In practice it's cheaper still. Every lookup reads the top levels, so they stay in memory, and a single check costs at most a couple of page reads that aren't already cached. That's fast enough to run every time the user pauses.

One detail matters later: the index should be on a normalized form of the name, something like lower(username), so that "Maple" and "maple" collide instead of becoming two accounts.

The same index also settles what happens when two people submit the same free name at the same moment. Both INSERT statements reach the database, the index lets exactly one of them through, and the other fails with a duplicate-key error that the application can turn into "sorry, that name was just taken". It also means the green "available" under the field is only a hint, because the answer that counts is the one the INSERT gets.

The instant part happens in the browser

The "before you finish typing" part is mostly frontend work. If the form sent a request on every keystroke, typing "maple" would fire five requests, four of them about names nobody wants. So the form waits for a short pause, cancels whatever request is still in flight, and ignores any answer that arrives late.

const input = document.querySelector('#username');
const status = document.querySelector('#username-status');
let timer, controller, latest = 0;

input.addEventListener('input', () => {
  clearTimeout(timer);
  timer = setTimeout(check, 300);
});

async function check() {
  controller?.abort();
  controller = new AbortController();
  const id = ++latest;
  try {
    const url = `/api/usernames/${encodeURIComponent(input.value)}/available`;
    const res = await fetch(url, { signal: controller.signal });
    const { available } = await res.json();
    if (id === latest) status.textContent = available ? 'Available' : 'Taken';
  } catch (e) {
    if (e.name !== 'AbortError') status.textContent = '';
  }
}

Two details are easy to miss. Aborting a fetch only tells the browser to stop waiting, and the server may still run the query. And the latest counter is there because an old response can slip through if it had already arrived when the abort happened. Without it, the label could briefly show the verdict on "map" while the user is looking at "maple".

The Bloom filter, which I'm learning right now

This is the part I'm still studying, and the one that struck me most.

A Bloom filter is an array of bits, all zero at the start, plus a few hash functions. To add a name, you hash it with each function and switch on the bits at those positions. To check a name, you hash it the same way and look: if any of those bits is off, the name was never added.

A toy version makes it concrete. Take 10 bits and two hash functions, and suppose (the values are made up) that they send "sunny" to bits 2 and 7, and "rocket" to bits 4 and 9. After adding both names, bits 2, 4, 7 and 9 are on.

Now check "pixel", which hashes to 3 and 7. Bit 3 is off, so "pixel" is definitely free. Then check "comet", which hashes to 2 and 9. Both bits are on, so the filter says it might be taken, even though nobody registered it. Bit 2 came from "sunny" and bit 9 from "rocket". That's a false positive.

A zero means the name was never added, guaranteed. A one only means somebody set that bit, and it may have been somebody else. So a Bloom filter can be wrong when it says "maybe", but it's never wrong when it says "no": there are no false negatives.

Its size depends on the error rate you accept. The optimal number of bits per name is -ln(p) / (ln 2)², which for a 1% false-positive rate comes to about 9.6 bits, with 7 hash functions. For two billion names that's around 19 billion bits, roughly 2.4 GB. A 10-character name stored as plain ASCII takes 80 bits on its own, so the filter is about an eighth of the bare list of names, and its size doesn't grow with their length.

I wouldn't write one myself, since there are solid implementations for most languages. What I wanted to understand was what it actually speeds up. A Bloom filter is fast at saying no. When it says maybe, the form still has to ask the database, because the maybe could be a false positive. So the filter only saves work on names that are free.

And think about who's typing. Someone picking a username tries the obvious names first, like their own name or a word they like, and those are exactly the names most likely to be taken already. For them the filter says maybe, the database gets queried anyway, and I've added a 2.4 GB structure that has to stay in sync with the table. It can't even forget a name when an account is deleted, because switching a bit off could erase a bit that another name relies on.

Where it does fit is the opposite case: suggesting alternatives when a name is taken. Generated candidates are mostly free, so the usual answer is no, and that's exactly where a Bloom filter could earn its memory.

One thing I haven't settled

"admin" written with a Cyrillic а (U+0430) is a different string from "admin" with a Latin a (U+0061). The index sees two different names while a person sees the same one, so whoever registers the lookalike can pass for the original.

Unicode Technical Standard #39 describes a "skeleton" for exactly this: it maps each character to a prototype of the characters it can be mistaken for, so two names that look alike end up with the same skeleton, and a unique index on the skeleton would catch them. The blunt alternative is to accept only lowercase a to z, digits and a couple of symbols, and most of the problem never shows up.

I don't know yet which one I'd pick. The skeleton leaves room for people whose names aren't written in Latin letters, while the short whitelist is much harder to get wrong.

Why it's still worth knowing

Most of us will never write a B-tree or a Bloom filter for production. The database already has the first, and a library has the second. What's worth having is a sense of what each one costs: a B-tree gives an exact answer in a handful of page reads, while a Bloom filter gives a cheap no and a maybe that still needs checking, for about 10 bits a name. That's enough to choose between them for the right reasons, and to notice when the clever option doesn't help.

Have you ever put a Bloom filter in front of a database and seen it actually pay off? I'd like to hear where it did.

Your Search Query Is a Program: Composing Role-Based SQL With the Strategy Pattern

Paolo — Sat, 26 Sep 2026 18:19:15 +0000

Every business application has this screen somewhere: a table of records, filter boxes above it, and a user who may only see part of the data. The first query is a SELECT with a WHERE on the user's office. Filters arrive one at a time, then a role that sees two offices, then an auditor who sees everything once approved. Eventually the query is a two-hundred-line method nobody wants to touch.

Our argument is that this query was never a string. A search with optional filters and role-based visibility is application logic, and one of its invariants is a security boundary. Built by appending text, it gets the testability and review process of a text file. Built from small units that contribute fragments to a builder that enforces the rules, it gets treated like the rest of the code. The pattern is Strategy, used twice: one family of strategies decides what a user may see, the other what the user asked for, and neither writes the whole query.

The companion repository is search-query-composition-demo: both versions of the search on the same schema, tested against a real SQL Server through Testcontainers, so you need Docker.

Versions used: Spring Boot 4.1.1, Spring Framework 7.0.9, Flyway 12.4.0, Testcontainers 2.0.5, Microsoft JDBC Driver for SQL Server 13.4.0, SQL Server 2025 (mcr.microsoft.com/mssql/server:2025-CU9-ubuntu-24.04), Java 21. No JPA: Spring JDBC, NamedParameterJdbcTemplate and records.

The domain

A document platform for an organization with a national office, regional offices, and local offices under each region, modelled in org_unit with a parent_id. The exception is the chartered units, local offices that report straight to the national office: a regional supervisor sees one only while holding an explicit, dated delegation for it.

Documents belong to a unit and have a type, a status (DRAFT, SUBMITTED, APPROVED, ARCHIVED), an author, dates, attachments and tags. Five roles decide visibility:

Role	Visibility
`LOCAL_OFFICER`	their own unit
`REGIONAL_SUPERVISOR`	their region and its local offices, plus chartered units with an active delegation
`NATIONAL_ADMIN`	everything, including the author's email
`AUDITOR`	every unit, only `APPROVED` or `ARCHIVED`
`DELEGATE`	only the units they hold an active delegation for

On top of that come ten optional filters (region, unit, type, status, date range, attachments, author, title, tag, overdue), several of which need joins.

The version that grows naturally

The legacy package has the search you get by adding one requirement at a time: one method, a StringBuilder that starts with SELECT DISTINCT and every join any filter might need, then one if per role and one per filter, with catch-all predicates for the simple filters. For a local officer it sends this (abridged):

SELECT DISTINCT d.id, d.title, d.status, d.created_at, author.email AS author_email
FROM document d
JOIN org_unit unit ON unit.id = d.org_unit_id
JOIN app_user author ON author.id = d.author_id
LEFT JOIN attachment a ON a.document_id = d.id
LEFT JOIN document_tag dt ON dt.document_id = d.id
LEFT JOIN tag t ON t.id = dt.tag_id
WHERE 1 = 1
AND d.org_unit_id = :userUnitId
AND (:regionId IS NULL OR unit.id = :regionId OR unit.parent_id = :regionId)
AND (:author IS NULL OR author.username = :author)
ORDER BY d.created_at DESC, d.id

It works: apart from two quirks covered below, the repository's tests show it returns the same rows as the composed version. The problems are structural.

The rules are not addressable. "A supervisor sees chartered units only with an active delegation" is a real business rule, and here it is five sql.append calls inside an else if. There is nothing to call, reuse or test in isolation. When a count query or an export needs the same visibility, the only option is to copy those lines, and the copies drift.

Catch-alls fight the plan cache. SQL Server caches one plan per statement text, and this text never changes, so every combination of filters shares one plan: compiled for the values of the first call, and required to be valid whenever any parameter is NULL, which pushes the optimizer towards scans. OPTION (RECOMPILE) trades that for a compilation on every execution; Erland Sommarskog's Dynamic Search Conditions in T-SQL covers the options in depth. SQL Server 2025 adds Optional Parameter Plan Optimization, which caches plan variants by NULL state, and how it copes with ten optional predicates is something to measure, not assume.

Data is fetched, then hidden. The author's email is selected for every role and set to null in the row mapper unless the user is an admin. It leaves the database for users who may not see it, with one if in a lambda between it and the response.

Two smaller things: the LEFT JOINs multiply rows and DISTINCT hides that instead of avoiding it, and the mapper reads the nullable reviewer id with rs.getLong, which returns 0 for NULL.

Why one query per role does not fix it

Splitting the method by role gives each role clean SQL, but the search varies along two independent axes: visibility depends on who asks, filtering on what they asked. A query per role removes the first axis by multiplying the second. Five roles means five copies of the tag filter, and every fix to a filter is five fixes.

It also hides the security boundary. In each query the visibility predicate sits inline among the filters, and a reviewer reading a diff cannot tell whether a changed line affects what the user asked for or what the user may see.

Fragments that compose

The composed version keeps the axes apart. A visibility scope decides what a user may see: one per role, exactly one per search, never optional. A filter contributor decides what the user asked for: one per filter, each deciding whether it applies. Both add fragments (predicates, joins, CTEs, columns, parameters) to a builder, and neither sees the whole query.

public interface VisibilityScope {

    Role role();

    void restrict(SearchQuery query, SearchContext context);
}

public interface FilterContributor {

    boolean appliesTo(SearchContext context);

    void contribute(SearchQuery query, SearchContext context);
}

SearchContext is a record of the user, the criteria and today's date, resolved once per search for a reason that comes up in the security section. The supervisor scope is where the chartered exception lives, and the only place it lives:

@Component
public class RegionalSupervisorScope implements VisibilityScope {

    private static final Cte SUPERVISED_UNIT = new Cte("supervised_unit", """
            SELECT u.id AS unit_id
            FROM org_unit u
            WHERE u.id = :userUnitId OR u.parent_id = :userUnitId
            UNION
            SELECT dl.org_unit_id
            FROM delegation dl
            JOIN org_unit cu ON cu.id = dl.org_unit_id
            WHERE dl.delegate_user_id = :userId
              AND cu.chartered = 1
              AND dl.valid_from <= :today
              AND (dl.valid_to IS NULL OR dl.valid_to >= :today)
            """);

    @Override
    public Role role() {
        return Role.REGIONAL_SUPERVISOR;
    }

    @Override
    public void restrict(SearchQuery query, SearchContext context) {
        query.with(SUPERVISED_UNIT)
                .restrictVisibility("d.org_unit_id IN (SELECT unit_id FROM supervised_unit)")
                .param("userUnitId", context.user().unitId())
                .param("userId", context.user().id())
                .param("today", context.today());
    }
}

When the rule changes, this is the one class to open. The national admin scope calls query.visibleToAll(), which adds no predicate but records that a scope decided; the builder refuses a query where none did. That scope also adds the email column, so for every other role it is never selected.

A filter looks the same from outside:

@Component
public class RegionFilter implements FilterContributor {

    @Override
    public boolean appliesTo(SearchContext context) {
        return context.criteria().regionId() != null;
    }

    @Override
    public void contribute(SearchQuery query, SearchContext context) {
        query.join(Joins.UNIT)
                .where("unit.id = :regionId OR unit.parent_id = :regionId")
                .param("regionId", context.criteria().regionId());
    }
}

Keep an eye on the OR in that predicate; it comes back in the security section.

Every contributor declares the joins it depends on, even ones the base query already has. Shared joins are constants with a key, like new Join("unit", "JOIN org_unit unit ON unit.id = d.org_unit_id"); the builder adds each key once and throws if a key arrives with different SQL.

A VisibilityScopeRegistry collects the scopes into a map by role, so two scopes for one role fail at startup. A role with no scope throws NoVisibilityScopeException at search time, and nothing reads a missing scope as "no restriction".

DocumentQueryComposer puts it together; the registry, the List<FilterContributor> injected by Spring and a Clock come in through its constructor:

public SqlQuery compose(SearchUser user, SearchCriteria criteria) {
    VisibilityScope scope = scopes.scopeFor(user.role());
    SearchContext context = new SearchContext(user, criteria, LocalDate.now(clock));

    SearchQuery query = SearchQuery.from("document d")
            .join(Joins.UNIT)
            .join(Joins.DOCUMENT_TYPE)
            .join(Joins.AUTHOR)
            .select("d.id", "d.reference", "d.title", "d.status",
                    "unit.code AS unit_code", "doc_type.code AS document_type", "author.username AS author",
                    "d.reviewer_id", "d.created_at", "d.due_date");

    scope.restrict(query, context);
    for (FilterContributor filter : filters) {
        if (filter.appliesTo(context)) {
            filter.contribute(query, context);
        }
    }

    return query.orderBy(criteria.sortField(), criteria.sortDirection())
            .orderBy(SortField.ID, SortDirection.ASC)
            .build();
}

Adding a filter means adding a class, and order does not matter because every fragment ends up as one more ANDed condition in its own parentheses. Each combination of filters also produces a different statement text, so SQL Server caches a plan per combination actually used, with only the predicates that are really there.

The builder

The full SearchQuery also handles CTEs, joins and ordering. These two methods carry the rules the next section depends on:

public SearchQuery param(String name, Object value) {
    requireIdentifier(name);
    if (value == null) {
        throw new QueryCompositionException("Parameter :" + name + " has no value");
    }
    Object existing = parameters.putIfAbsent(name, value);
    if (existing != null && !Objects.equals(existing, value)) {
        throw new QueryCompositionException(
                "Parameter :" + name + " is already bound to " + existing + ", refusing " + value);
    }
    return this;
}

public SqlQuery build() {
    if (!visibilityDecided) {
        throw new QueryCompositionException("No visibility scope was applied to this query");
    }
    StringBuilder sql = new StringBuilder();
    // WITH, SELECT, FROM and JOIN clauses omitted

    List<String> conditions = Stream.concat(visibilityPredicates.stream(), predicates.stream())
            // An OR inside one fragment must never escape into the AND chain around it
            .map(predicate -> "(" + predicate.strip() + ")")
            .toList();
    if (!conditions.isEmpty()) {
        sql.append("WHERE ").append(String.join("\n  AND ", conditions)).append('\n');
    }
    // ORDER BY omitted
    return new SqlQuery(sql.toString().strip(), Map.copyOf(parameters));
}

Security is a property of the composition

Nobody can review every combination of fragments written by different people, so the builder has to make the unsafe combinations impossible to build.

Values are parameters

Every value goes through param(...) and reaches SQL Server as a bound parameter. The builder cannot prove that nobody concatenated a value, and Java has no safe SQL templating (String Templates were previewed in JDK 21 and 22, then withdrawn). What it can do is reject any fragment containing ', ;, -- or /*. Without quotes there is nowhere to put a string literal, so even the auditor's fixed statuses travel as parameters. It is a tripwire, not a proof, and it keeps every piece of data a fragment touches visible in the param calls under it.

Identifiers are a whitelist

Column names cannot be bound, and SQL Server rejects a variable in ORDER BY outright. SortField maps the names the UI may send to real columns:

public enum SortField {
    CREATED_AT("createdAt", "d.created_at"),
    TITLE("title", "d.title");
    // other constants, fields, constructor and fromLogicalName omitted
}

The builder's only sort method is orderBy(SortField field, SortDirection direction), with no String overload to misuse.

The AND/OR precedence leak

This is the bug the design is built around, and it gets past both code review and most test suites.

The region filter's predicate, unit.id = :regionId OR unit.parent_id = :regionId, is correct. So is the local officer's d.org_unit_id = :userUnitId. Concatenated the way a string builder does it:

WHERE d.org_unit_id = :userUnitId AND unit.id = :regionId OR unit.parent_id = :regionId

AND binds tighter than OR, as * binds tighter than +, so the database reads:

WHERE (d.org_unit_id = :userUnitId AND unit.id = :regionId)
   OR unit.parent_id = :regionId

The second branch has no visibility predicate at all: any document in any local office under the requested region matches, whoever asks. In the demo data, a local officer from the north who filters on the south region receives every document of the south's local office. PrecedenceLeakTest runs those two concatenated strings against SQL Server and asserts the leaked rows, then runs the same fragments through the builder and gets nothing back.

It survives review because each fragment is correct on its own; the bug is in the space between them, which nobody wrote. It survives testing because the natural test checks that the right documents come back. Filtering on their own region, the northern officer does get all of their documents, plus those of the other northern office (the test has that case too). Only a test that asserts absence catches it, and the authorization matrix below does exactly that.

The legacy method gets this right almost by accident, since a catch-all only works inside parentheses. The leak arrives the day someone tidies it into if (regionId != null) sql.append("AND unit.id = :regionId OR unit.parent_id = :regionId "), which reads like an improvement.

The builder's defence is the commented line in build(): every predicate is wrapped in parentheses, visibility first. Contributors cannot forget it or opt out, and the worst a stray OR can do is return the wrong subset of what the user could see anyway.

Parameter names collide

Contributors are written independently, so two of them will eventually pick the same parameter name. Sometimes that is right: the supervisor scope and the overdue filter both bind :today. Sometimes it is a hole. Had the local officer scope bound its unit as :unitId, the natural name, the unit filter's :unitId would silently replace it in a plain map, and the visibility predicate would check the unit the user asked for instead of the one they belong to. param accepts a second binding only if it equals the first, and SearchQueryTest has that exact case. Naming the scope's parameter userUnitId makes collisions rarer; the rule catches the rest.

The same rule is why today lives in SearchContext. If the scope and the overdue filter each called LocalDate.now(clock), the two calls could straddle midnight, the builder would reject the second binding, and the search would fail. Resolving the date once per search removes the race.

Fail closed

The legacy method has branches for local officer, supervisor, auditor and delegate. The admin has none, because "everything" is what you get when no branch adds a predicate, and that is also what any new role gets. The repository has a sixth role, EXTERNAL_REVIEWER, with no scope yet: FailClosedTest shows the legacy search returning all 21 documents to it and the composed one throwing NoVisibilityScopeException.

The composed version fails closed twice. The registry throws for a role without a scope, and build() throws if no scope called restrictVisibility or visibleToAll, so a buggy restrict does not produce an unrestricted query either. Seeing everything has to be written down.

LIKE has its own syntax

A bound parameter protects the SQL, not the pattern. In the legacy version, 100% also matches "Budget review for 100 days", and since [ opens a character class on SQL Server, [DRAFT] matches every title containing one of those letters: all 21 documents in the demo. LikePattern brackets the three special characters, the SQL Server idiom:

static String escape(String text) {
    StringBuilder escaped = new StringBuilder(text.length());
    for (char c : text.toCharArray()) {
        // SQL Server reads [ as the start of a character class, so it is a wildcard too
        if (c == '%' || c == '_' || c == '[') {
            escaped.append('[').append(c).append(']');
        } else {
            escaped.append(c);
        }
    }
    return escaped.toString();
}

Testing it

The whole visibility policy fits in a table, so the main test is one: each row a document, each column a user, each cell whether that user sees it.

private static final String MATRIX = """
        reference  officer.n1  super.north  super.south  auditor  delegate.one
        N1-001     Y           Y            .            .        .
        S1-002     .           .            Y            Y        Y
        CA-001     .           Y            .            Y        .
        CB-001     .           .            .            .        Y
        """;

The full matrix has 21 documents and 7 users, run against both implementations for 294 cases. The . cells matter as much as the Y ones, because they assert that something is not returned.

Characterization tests run the legacy and the composed search on 20 combinations of criteria for every user and require the same rows in the same order. They are how the two legacy quirks above, the 0 reviewer and the unescaped LIKE, were found, and each became a named test rather than a looser comparison. Testing SQL you inherited without tests is the subject of a follow-up article.

Trade-offs and alternatives

Spring Data Specifications and the Criteria API. A Specification is the same idea as a filter contributor, and since Criteria predicates are objects combined into a tree, the precedence leak cannot happen there, a real advantage over any string-based builder, this one included. We did not use them because they need JPA entities, and because the visibility rules want CTEs (and screens like this soon want window functions), which standard JPA Criteria lacks and Hibernate 6 offers only through its own extensions. The SQL is also generated rather than written, which matters when this query's plan is what you are tuning.

jOOQ. Starting from zero, this is what we would evaluate first. Conditions combine into an AST, so parentheses are rendered for you; generated code makes the schema itself the sort whitelist; CTEs, window functions and the SQL Server dialect are all there. The costs are a code generation step and, for SQL Server, a commercial license, since the open source edition covers only open source databases. Most of this design carries over to it unchanged.

Row-Level Security. SQL Server can attach a filter predicate to document through a security policy, so every query gets it, ad-hoc reports included, with the user's identity set through sp_set_session_context on every connection checkout. The predicate is invisible in the application's SQL and harder to test, and Microsoft documents side-channel attacks against it, so we see it as a second line of defence.

A closure table. u.id = :userUnitId OR u.parent_id = :userUnitId works only because the hierarchy has exactly three levels. With a fourth, an org_unit_closure(ancestor_id, descendant_id, depth) table, or a recursive CTE, turns "everything under this unit" into one indexed lookup, and the chartered exception stays in its one scope.

When this is too much. One role, three filters, an internal tool used by five people: write the query, parenthesize it, test it and move on. The same goes for reports that look like searches but are fixed queries. The design earns its cost when visibility has more than two cases, filters keep arriving, and a leak would be an incident rather than a bug report.

Closing

The search keeps growing because it is where the rules about who may see what meet the user's question about what they want to see. Written as one string, both kinds of rule end up in the same StringBuilder, and the security boundary is only as good as the last person who appended to it.

Treated as a program, the query has parts with names: the supervisor rule is a class you can open, and the region filter cannot leak because the builder owns its parentheses. Every fragment is still plain SQL you can paste into a console. It just stops being the place where the rules live.

The Row Says 'system': Spring Data JPA Auditing Outside the HTTP Request

Paolo — Wed, 23 Sep 2026 18:49:03 +0000

Every table in our platform has the same four columns at the end: created_by, created_at, updated_by, updated_at. Spring Data JPA fills them in for you with four annotations and one @EnableJpaAuditing. That part takes five minutes.

Then you look at the data a month later and find rows that say system, and you cannot tell which ones deserved it. Some of them really were written by a scheduled job. Some were written by a queue consumer on behalf of a real person whose identity got lost on the way. A few were written by a user whose session had not been set up yet. All three look identical in the audit trail, which makes the audit trail useless for exactly the question it exists to answer.

What follows is what happens after those first five minutes: where the auditor's identity comes from, what to return when there is no logged-in user, what to actually put in that column, and how to package all of it in a library that a dozen services can share without any of them breaking at startup. The setup is deliberately not Spring Security. Our services keep the logged-in user in a session-scoped bean of their own, and the auditor reads from there. If you use SecurityContextHolder, the interesting parts still apply, because the problem is not where the identity is stored. The problem is that on a scheduler thread there is no identity to read.

Everything is in a companion repository: auditor-aware-demo. It is a single Spring Boot module on an in-memory H2 database, with two test classes that cover the two situations described below, so mvn test is all you need.

Versions used: Spring Boot 3.5.16, Spring Data JPA 3.5.13, Hibernate 6.6.53.Final, H2 2.3.232, Java 21. Boot 3.5.x is out of OSS support since July 2026; everything here runs unchanged on 4.x.

The problem

Here is the shape of the system: several Spring Boot services, each with its own database, all of them persisting through JPA. A user logs in once, and from then on every row that user writes should carry their id.

Some rows, though, are not written by a user at all:

a nightly job that archives stale records;
a consumer that picks a command off a queue and executes it;
an @Async method that was started inside a request and finishes after the request is gone.

Spring Data has one hook for all of this, AuditorAware<T>, and it has one method: Optional<T> getCurrentAuditor(). Most of this article is about what that method should return, and what it should never do.

The basic setup

The entity side first, because it does not change.

@MappedSuperclass
@EntityListeners(AuditingEntityListener.class)
public abstract class AuditableEntity {

    @CreatedBy
    @Column(name = "created_by", updatable = false)
    private String createdBy;

    @CreatedDate
    @Column(name = "created_at", updatable = false)
    private Instant createdAt;

    @LastModifiedBy
    @Column(name = "updated_by")
    private String updatedBy;

    @LastModifiedDate
    @Column(name = "updated_at")
    private Instant updatedAt;

    // getters only
}

Three things about this class are deliberate choices rather than the defaults you would end up with by accident.

No setters. These fields are written by AuditingEntityListener and by nobody else. If application code can call setCreatedBy, sooner or later it will, usually in a "migration" or an "import" that somebody wrote in a hurry. The updatable = false on the two created_* columns is the same idea one layer down: even if an entity is loaded, modified and merged back, those two columns are not part of the UPDATE.

No equals/hashCode. Do not generate them over these fields. All four change the moment the entity is persisted, so an entity in a HashSet before save() is a different object after it. With Lombok that means @Getter on this class, not @Data.

Instant, not LocalDateTime. The audit trail is going to be read across services that may not share a timezone. Instant is unambiguous, and Spring Data converts it without configuration.

Every entity in every service extends this:

@Entity
@Table(name = "note")
public class Note extends AuditableEntity {
    @Id @GeneratedValue(strategy = GenerationType.IDENTITY)
    private Long id;
    private String text;
    private boolean archived;
    // ...
}

Then turn auditing on:

@Configuration
@EnableJpaAuditing
public class JpaAuditingConfig {
}

That is the entire configuration; the auditor is a @Component implementing AuditorAware<String>, shown in the next section. Many examples add auditorAwareRef = "auditorAware" and an explicit @Bean. The attribute is optional: without it, Spring Data autowires the AuditingHandler by type, and one AuditorAware bean in the context is enough. Why it has to be exactly one comes up when the configuration moves into a library.

One behaviour to know before the first test: on insert, Spring Data fills in all four columns, not just the created_* pair. @LastModifiedBy and @LastModifiedDate are set on creation too, so a freshly inserted row has updated_by == created_by and updated_at == created_at. If your reporting logic treats a null updated_at as "never modified", it is wrong for every row you insert, not just the ones that were later modified. @EnableJpaAuditing(modifyOnCreate = false) turns this off.

Where the identity comes from

Our services keep the logged-in user in a session-scoped bean:

@Component
@SessionScope
public class CurrentUser implements Serializable {
    private String userId;
    // getter, setter
}

One instance per HTTP session, populated at login. How that bean gets populated, and why it is session-scoped at all, is a topic for another article. What matters here is one property of it: the auditor is a singleton, and what it receives is a proxy. Every call on that proxy is routed to the session of the current request thread. On a thread that is not serving a request, there is no session to route to, and the call throws:

org.springframework.beans.factory.support.ScopeNotActiveException:
  Error creating bean with name 'scopedTarget.currentUser':
  Scope 'session' is not active for the current thread; ...
Caused by: java.lang.IllegalStateException: No thread-bound request found:
  Are you referring to request attributes outside of an actual web request,
  or processing a request outside of the originally receiving thread? ...

So the auditor has to know, before touching the session, whether there is a request at all. RequestContextHolder answers that question:

@Component
public class CurrentUserAuditorAware implements AuditorAware<String> {

    public static final String ANONYMOUS = "anonymous";
    public static final String USER_PREFIX = "user:";

    private final CurrentUser currentUser;

    public CurrentUserAuditorAware(CurrentUser currentUser) {
        this.currentUser = currentUser;
    }

    @Override
    public Optional<String> getCurrentAuditor() {
        Optional<String> explicit = AuditorContext.current();
        if (explicit.isPresent()) {
            return explicit;
        }

        // No request bound to this thread: a scheduled job, a queue consumer, a test.
        // Touching the session-scoped bean here would throw, so we do not.
        if (RequestContextHolder.getRequestAttributes() == null) {
            return Optional.of(Auditors.SYSTEM); // "system", a constant of the shared library
        }

        return Optional.of(Optional.ofNullable(currentUser.getUserId())
                .map(id -> USER_PREFIX + id)
                .orElse(ANONYMOUS));
    }
}

The last statement is the happy path: a request, a session, a user in it. The values are namespaced (user:42, not 42) so that a user, a job and a consumer can never be mistaken for one another; the full argument is in What goes in the column.

The RequestContextHolder guard is what prevents the exception above. There is a version of this class that checks currentUser == null instead; it shows up in a lot of codebases and it is dead code. The proxy is injected at startup and is never null; what can be missing on a given thread is the request that the proxy needs in order to reach a session.

The distinction between anonymous and system is deliberate. A request with nobody logged in and no request at all are different situations, and when you are staring at a row three months later, knowing which one produced it is worth a lot more than the two extra constants cost.

The first three lines, the explicit auditor, are the subject of the next section.

When there is no user

system is a correct answer to "who wrote this row" when a job did it. It is a poor answer when the row was written by a consumer executing a command that a specific person put on a queue thirty seconds earlier. And it is a wrong answer when an @Async method, started inside a request by a logged-in user, finishes its work on a pool thread where RequestContextHolder is empty. All three cases hit the same return Optional.of(Auditors.SYSTEM), and the audit trail cannot tell them apart.

The fix is to stop treating the auditor as something that has to be discovered from ambient state, and let the code that actually knows who is acting say so:

public final class AuditorContext {

    private static final ThreadLocal<String> CURRENT = new ThreadLocal<>();

    public static void runAs(String auditor, Runnable action) {
        callAs(auditor, () -> { action.run(); return null; });
    }

    public static <T> T callAs(String auditor, Supplier<T> action) {
        String previous = CURRENT.get();
        CURRENT.set(auditor);
        try {
            return action.get();
        } finally {
            if (previous == null) CURRENT.remove(); else CURRENT.set(previous);
        }
    }

    public static Optional<String> current() {
        return Optional.ofNullable(CURRENT.get());
    }
}

A thread-local with a try/finally around it, nothing more. The previous bookkeeping makes it safe to nest, which matters the first time a job calls a service method that has its own runAs. On Java 25 you would reach for ScopedValue instead; the shape of the API is the same.

The auditor checks this first, before looking at any request. An explicit statement of who is acting beats an inference from ambient state.

Now the three cases become three different rows.

The scheduled job names itself:

@Component
public class NightlyArchiveJob {

    public static final String AUDITOR = "job:nightly-archive";
    private static final Duration RETENTION = Duration.ofDays(30);

    private final NoteService noteService;

    public NightlyArchiveJob(NoteService noteService) {
        this.noteService = noteService;
    }

    @Scheduled(cron = "0 0 3 * * *", zone = "UTC")
    public void run() {
        archiveCreatedBefore(Instant.now().minus(RETENTION));
    }

    public int archiveCreatedBefore(Instant cutoff) {
        return AuditorContext.callAs(AUDITOR, () -> noteService.archiveEachCreatedBefore(cutoff));
    }
}

archiveEachCreatedBefore does what the name says: it loads the stale notes and flips them one at a time, so each row goes through the auditing listener and gets updated_by = job:nightly-archive. That is a row you can act on directly, whereas a row that says system sends you to the logs to find out which process wrote it.

A side note on the zone attribute, since it is the kind of thing that only bites in production: a cron expression runs in the JVM's default time zone unless you say otherwise. In a container that is usually UTC; on the laptop where you tested it, it is not. Spelling it out costs nothing and removes a whole category of "why did the job run at 4" questions. The cutoff itself is an Instant, so the comparison has no time zone to get wrong.

The queue consumer carries the originating user through. The producer knew who asked for this; it is a header on the message, or a field in the payload. The consumer's only job is not to lose it:

@Component
public class NoteCommandConsumer {

    public static final String AUDITOR = "consumer:note-commands";

    // requestedBy is already namespaced upstream (e.g. "user:42")
    public record NoteCommand(String text, String requestedBy) {
    }

    private final NoteService noteService;

    public NoteCommandConsumer(NoteService noteService) {
        this.noteService = noteService;
    }

    public Note onMessage(NoteCommand command) {
        String auditor = command.requestedBy() != null ? command.requestedBy() : AUDITOR;
        return AuditorContext.callAs(auditor, () -> noteService.create(command.text()));
    }
}

When the message has no origin, the consumer falls back to its own name (consumer:note-commands) rather than to system, so the row still says something specific about where it came from.

One caveat that has to be stated: requestedBy is a value the producer controls. This only works if the producer is trusted, which in practice means the queue is internal and the message was authenticated on the way in. An auditor taken from an unauthenticated payload is a spoofable audit trail.

The value also arrives already namespaced, because normalising an identity into user:42 belongs at the boundary where it enters the system, not in every consumer that happens to handle it.

The @Async method is the same problem in a different costume. Thread-locals do not cross thread boundaries, and that applies equally to RequestContextHolder, to SecurityContextHolder and to our own AuditorContext. Capture the auditor before the hop and re-establish it on the other side, either by hand (String who = ...; executor.submit(() -> AuditorContext.runAs(who, ...))) or with a TaskDecorator on the executor that does it for every task. We will not go further into that here. The point is that once the auditor is a value you can hold in a variable, propagating it becomes a solved problem, which it never was while the identity stayed buried in a session proxy.

The test that lied to us

The two test classes in the repo are split on purpose: one goes through MockMvc with a real session, the other has no request at all. The second one is where the system branch gets exercised.

Our first version of it was a plain @SpringBootTest calling the service directly. The row came back anonymous.

Not system. anonymous. Which means the auditor found a request bound to the test thread, found no user on it, and gave the right answer for what it saw. Where did the request come from?

From Spring itself. When a test's context is a WebApplicationContext (the default for @SpringBootTest in a web project), ServletTestExecutionListener binds a MockHttpServletRequest to the test thread before every test method. The intent is that code depending on RequestContextHolder works in tests without MockMvc. The side effect is that a test meant to simulate "no request" is not simulating it at all, and the branch you wrote the test for never runs.

The fix is one attribute:

@SpringBootTest(webEnvironment = SpringBootTest.WebEnvironment.NONE)
class AuditingOutsideRequestTest { ... }

With no web layer in the context, the listener does not run and nothing gets bound to the thread. That is also what a batch worker's context looks like, and it is the situation this test is meant to cover.

What goes in the column

The values so far have been strings like user:42 and job:nightly-archive. That is a decision, and one that is hard to undo once a few million rows carry it.

The temptation is to store the user's primary key. It is what you have at hand and what the rest of the schema uses, and AuditorAware<Long> makes it look like the intended choice. Then the first scheduled job runs and you need a value for it. If the column is a BIGINT, you invent one: 0, -1, a "system user" row. If the column is a VARCHAR that happens to always contain digits, you write system into it, and somewhere downstream a frontend or a report does Long.parseLong(createdBy) and falls over, though not immediately: it happens weeks later, on the one screen that happens to list rows a job touched.

The rule we landed on is boring: one column, one kind of value, and never mix kinds. Two ways to honour it.

Everything is a user. The column is a foreign key to the users table, and every non-human actor is a real row in it: a technical user for each job, and likewise for each consumer and each integration that writes rows. job:nightly-archive becomes user 10001, with a display name, and the frontend resolves it like any other user without special cases. This is the cleanest option if you already have a users table in every service and you can afford to seed it with the technical accounts. It is also the one where AuditorAware<Long> is the accurate type.

Everything is a string, and the string says what it is. The column is text, the values are user:42, job:nightly-archive, consumer:note-commands, system, anonymous, and no code anywhere is allowed to parse a number out of it. The namespace is the guard: nobody looks at user:42 and thinks it is an integer. This is what the demo does, because it needs no users table and it works across services that do not share one.

What you should not do is the thing that happens by default: a string column that contains a number for people and a word for everyone else. That is a Long with a lie in it, and every consumer of the column has to know about the lie.

Whichever you pick, store a stable identifier rather than a display name, because names change over time, they get corrected, and sometimes they get anonymised, and none of that should propagate into an audit trail.

Sharing it across microservices

Everything above lives in one service. We have a dozen, and they all need the same four columns and the same AuditableEntity, governed by the same rules. The natural move is a shared library, and the natural mistake is to put AuditableEntity in the library and leave each service to write its own configuration.

What the library should own:

AuditableEntity
Auditors, the values the library itself knows about (system)
AuditorContext
the @EnableJpaAuditing itself
a default AuditorAware for services that have no notion of a user

What each service should own: its AuditorAware, if it has something better than the default to say. That is the whole contract.

In Spring Boot terms, the library ships an auto-configuration:

@AutoConfiguration
@EnableJpaAuditing
public class AuditingAutoConfiguration {

    @Bean
    @ConditionalOnMissingBean(AuditorAware.class)
    public AuditorAware<String> systemAuditorAware() {
        return () -> Optional.of(AuditorContext.current().orElse(Auditors.SYSTEM));
    }
}

registered in META-INF/spring/org.springframework.boot.autoconfigure.AutoConfiguration.imports:

com.example.auditdemo.audit.AuditingAutoConfiguration

A web-facing service keeps its CurrentUserAuditorAware as a @Component and deletes its JpaAuditingConfig; the @EnableJpaAuditing now lives in the library. Auto-configurations are evaluated after the service's own beans, so @ConditionalOnMissingBean sees the service's bean and the default steps aside. A batch worker with no session does not need to declare anything: it gets the default, and its rows say whatever AuditorContext was told, or system when it was told nothing. No service ever writes @EnableJpaAuditing.

That last sentence is a rule, and Spring enforces it at startup. @EnableJpaAuditing registers its infrastructure beans by fixed name, and Boot has refused to silently override bean definitions since 2.1. A service that keeps its old configuration alongside the library's auto-configuration does not start:

BeanDefinitionOverrideException: Invalid bean definition with name 'jpaAuditingHandler'
  defined in null: Cannot register bean definition [...] for bean 'jpaAuditingHandler'
  since there is already [...] bound.

defined in null is the tell, because it means the bean was registered by an annotation's registrar rather than by a class you can open in the IDE. When you see this one, the search term is @EnableJpaAuditing, and the answer is that it is declared twice.

The same exception shows up in a second disguise. If an AuditorAware implementation is annotated @Component("auditorAware") and a configuration class has a @Bean method called auditorAware returning it (a common combination, because the @Bean version gets added when someone reads about auditorAwareRef and nobody removes the @Component), the two definitions collide on the name, and one of them has to go; the @Component on its own is enough.

The demo repository is a single module, but the audit package in it is wired exactly this way, imports file included, so you can see the mechanism working without a second pom.xml.

Pitfalls

The null column

getCurrentAuditor() returns an Optional for a reason: Optional.empty() means "unknown", and Spring Data leaves the column untouched. On insert, that means NULL.

Whether that is acceptable is a schema question. With created_by NOT NULL, an empty auditor turns into a constraint violation at flush time, several stack frames away from the auditor and with a message about the table rather than about the cause. We went with a sentinel (system) instead of empty() for that reason, and because a NULL in an audit column is one more thing that "cannot happen" that will happen.

Two related traps. Returning null instead of an Optional fails immediately with Auditor must not be null, which is at least loud. And a user object that exists but has a null id (a half-initialised session) will produce the string "null" if you build the value with String.valueOf. Check that the id is present as well as the object before building the value.

Bulk queries

This one is not a bug so much as a property of how JPA works, and it seems to catch everyone once. The nightly job above archives one entity at a time. Here is the same operation written as a bulk update instead:

@Modifying
@Query("update Note n set n.archived = true where n.archived = false and n.createdAt < :before")
int bulkArchiveCreatedBefore(@Param("before") Instant before);

A JPQL or native UPDATE goes straight to the database. No entity is loaded, no @PreUpdate fires, and the audit columns keep whatever they had. Run the job this way and it produces rows that say nothing about it: the test in the repo shows the archived flag flipping while updated_by and updated_at do not move. deleteAllInBatch and every native query are the same story.

Your options, in the order we usually pick them: load the entities and modify them one by one, as the job does (correct, slow past a few thousand rows); set the audit columns explicitly in the query (set n.archived = true, n.updatedBy = :who, n.updatedAt = :now), which works but duplicates the auditor logic in every bulk query; or accept that bulk operations are unaudited at the row level and log them as one event at the job level. The wrong option is not deciding, which is what happens by default.

Listeners that do nothing

@EntityListeners(AuditingEntityListener.class) on AuditableEntity is what makes any of this happen, and it is inherited by every subclass, so you write it once. But the listener is only a hook. It delegates to an AuditingHandler that @EnableJpaAuditing creates and injects, which works because Boot hands Hibernate a Spring-aware bean container, so the listener Hibernate instantiates is actually a Spring bean.

Take @EnableJpaAuditing away and nothing fails. The listener still runs, but it finds no handler and simply returns, so every audit column on every row is NULL and there is not a single log line to say why. We reproduced it in the demo by excluding the auto-configuration: createdBy=null createdAt=null, test green.

This is the failure mode to expect in a new service that pulled in the library but is missing something. The checklist, in order: is the listener on the entity or its superclass? Is @EnableJpaAuditing present, exactly once? Is there exactly one AuditorAware bean? The first two fail silently; the third fails at startup, which is a mercy.

What this does not cover

Row-level audit columns tell you who last touched a row. They do not tell you what it looked like before, and they cannot be trusted to record every touch, as the bulk-query section shows. A real audit log is a separate concern: Hibernate Envers, a history table maintained by triggers, or change data capture off the transaction log. The four columns are the cheap first layer, and they are worth having precisely because they are cheap.

What they are not worth having is half-configured. An auditor that returns system from every path it does not understand will pass every test you write on a request thread, and then spend a year writing system into rows that a specific person, or a specific job, was responsible for. The fix is not more fallback logic. It is making the code that knows who is acting say so, and making the fallback the exception it was supposed to be.

Where OpenTelemetry Stops: the missing 44ms in a Spring Boot trace

Paolo — Fri, 31 Jul 2026 12:19:47 +0000

A POST /orders in this demo takes 178 milliseconds. The OpenTelemetry Java agent, attached with a single JVM flag and no code changes, will tell you that 127 of those went to a downstream service and 6 to the database. It will not tell you anything about the remaining 44.

That gap is where auto-instrumentation ends and your own code begins. This article locates that boundary precisely, then crosses it: with distributed tracing across two Spring Boot services with zero code changes, then with the minimum instrumentation needed to make the missing 44 milliseconds visible.

Everything is in a companion repository: spring-boot-otel-demo. If you have Docker installed you can clone it and have a live trace in front of you in about two minutes.

Versions used: OpenTelemetry Java agent 2.30.0, opentelemetry-instrumentation-annotations 2.30.0, Spring Boot 3.5.16, Java 21, otel/opentelemetry-collector-contrib:0.157.0, jaegertracing/all-in-one:1.76.0, postgres:18-alpine. This ecosystem moves fast. Check the current OpenTelemetry Java documentation before copying any version number.

The repository has two branches on purpose. master is the agent-only state described in Step 1: no OpenTelemetry dependency in either service. manual-spans is the annotated version from Step 2. Clone, run master first, then switch branches to see the difference.

The problem

Here is a request that touches two services and a database.

POST /orders arrives at order-service. The service validates the request, calculates pricing, calls inventory-service over HTTP to check stock, persists the order to PostgreSQL, and returns a response.

It takes around 180 milliseconds. Sometimes it takes 900. Where does the time go?

The usual answer is to open the logs of both services, filter by timestamp, and reconstruct the sequence by hand. That works with two services. It does not work with eight, and it does not work at all when two requests overlap in the same window.

Traces, spans, and the one header that matters

A trace is one request through your whole system. A span is one unit of work inside it: an HTTP handler, a database query, a method call. Spans nest: each has a parent, and the trace is a tree.

Every span in a trace carries the same trace id. That is what lets a UI stitch together work that happened in different processes, on different machines.

The mechanism for carrying that id across a service boundary is a single HTTP header, traceparent, defined by the W3C Trace Context specification. order-service sends it, inventory-service reads it, and the second service knows it belongs to a trace that started somewhere else.

Here is the setup we are building:

Note the shape. The two services never talk to Jaeger. They talk to an OpenTelemetry Collector, and the Collector decides where the data goes. We will come back to why that matters.

Step 1: tracing with zero code changes

The OpenTelemetry Java agent attaches to the JVM and rewrites bytecode at class-loading time. It recognises Spring MVC, JDBC, Hibernate and HTTP clients, and creates spans for them without the application knowing.

Download the agent jar in your Dockerfile, then start the service with:

ENTRYPOINT ["java", "-javaagent:/app/opentelemetry-javaagent.jar", "-jar", "/app/app.jar"]

Configure it with environment variables in docker-compose.yml:

environment:
  OTEL_SERVICE_NAME: order-service
  OTEL_EXPORTER_OTLP_ENDPOINT: http://otel-collector:4317
  OTEL_EXPORTER_OTLP_PROTOCOL: grpc
  OTEL_TRACES_EXPORTER: otlp

The protocol line is load-bearing, not decoration. Port 4317 is the gRPC port and the Collector in this repo opens a gRPC receiver only. Defaults for this variable have varied across SDKs and versions, so set it explicitly: if the agent picks http/protobuf and sends it to 4317, every export fails and no traces reach Jaeger.

The failure is at least loud. The agent logs it to the service's own stdout on every export cycle, naming both the exporter and the endpoint:

[otel.javaagent] ... ERROR io.opentelemetry.exporter.otlp.internal.HttpExporter
- Failed to export spans. The request could not be executed.
java.net.SocketException: Connection reset

If Jaeger is empty, docker compose logs order-service is the first place to look. The word HttpExporter against a port you configured for gRPC is the whole diagnosis.

That is the entire integration. No dependency in pom.xml, no configuration class, no SDK.

Bring the stack up and send a request:

curl -X POST http://localhost:8080/orders \
  -H "Content-Type: application/json" \
  -d '{"customerId":"CUST-001","sku":"SKU-1000","quantity":5}'

Then open Jaeger at http://localhost:16686, select order-service, and click Find Traces:

One thing before you read anything into the numbers: let the JVM warm up. The first request through a fresh service can be three times slower than the steady state, and the shape of that first trace is misleading. Send the request ten times and look at the last one.

What you got for free

Read that waterfall carefully, because there is more in it than it first appears.

The trace crosses the service boundary. inventory-service GET /inventory/{sku} is nested inside the client span of order-service. Two JVMs, two containers, one trace. Nobody wrote code to make that happen. The agent injected traceparent on the way out and read it on the way in.

The persistence layer is broken down for you. OrderRepository.save at 5.93ms contains Session.persist at 1.36ms, the actual INSERT at 496µs, and Transaction.commit at 3.37ms.

That last pair is worth sitting with. The INSERT is under half a millisecond. The commit costs nearly seven times as much. Most of the time spent persisting this order is not the query. It is everything around it. You would never learn that from a log line, and it is the kind of detail that changes how you think about transaction boundaries under load.

Self time versus total time. The client span for the inventory call is 127.37ms, while the server span inside inventory-service is 123.69ms. The difference is real client-side and network overhead. When hunting a bottleneck, the number you want is not the widest bar, but the bar that is wide and does not have equally wide children. A service that takes two seconds is not guilty if 1.9 of them are spent waiting for someone else.

Where the agent stops

Now look at the start of the trace:

The root span starts at zero. The first child span starts around 44 milliseconds later. Nothing at all is recorded in between.

That gap is your business logic. In this service it is request validation followed by a pricing calculation: plain Java, no I/O. The DTO mapping that happens after persistence is invisible for the same reason, though at well under a millisecond it does not leave a hole you can see.

And that is exactly why the agent cannot see them. Auto-instrumentation works by recognising libraries: a servlet container, a JDBC driver, an HTTP client. It has no way to know that computePricing is a meaningful unit of work in your domain. From the agent's point of view, the time between two library calls is just time.

This is the honest limit of "zero code changes". The agent gives you the skeleton of the request for free. The flesh is your problem.

Step 2: naming your own work

Add one dependency to order-service:

<properties>
  <!-- Must match the agent version pinned in the Dockerfile -->
  <opentelemetry-instrumentation.version>2.30.0</opentelemetry-instrumentation.version>
</properties>

<dependency>
  <groupId>io.opentelemetry.instrumentation</groupId>
  <artifactId>opentelemetry-instrumentation-annotations</artifactId>
  <version>${opentelemetry-instrumentation.version}</version>
</dependency>

Keep that version aligned with the agent jar you download in the Dockerfile. A mismatch between the two is the most common reason @WithSpan spans silently fail to appear. The build succeeds, the service starts, and the spans simply are not there.

Then annotate the methods that matter. @WithSpan creates a span for the method, correctly parented to whatever span is active. @SpanAttribute attaches a method parameter to that span as a searchable field:

@WithSpan("calculate-pricing")
private PricingBreakdown computePricing(@SpanAttribute("order.sku") String sku,
                                        @SpanAttribute("order.quantity") int quantity) {
    // both helpers are plain in-memory work: a price list scan and a discount tier walk
    BigDecimal basePrice = lookupBasePrice(sku);
    BigDecimal discountRate = resolveVolumeDiscountRate(quantity);

    BigDecimal subtotalAfterDiscount = BigDecimal.ZERO;
    BigDecimal taxAmount = BigDecimal.ZERO;
    int remainingUnits = quantity;

    while (remainingUnits > 0) {
        int unitsInLine = Math.min(LINE_SIZE, remainingUnits);
        BigDecimal lineSubtotal = applyPerUnitRules(basePrice, unitsInLine);

        BigDecimal lineDiscount = lineSubtotal.multiply(discountRate).setScale(2, RoundingMode.HALF_UP);
        BigDecimal lineAfterDiscount = lineSubtotal.subtract(lineDiscount);
        BigDecimal lineTax = lineAfterDiscount.multiply(TAX_RATE).setScale(2, RoundingMode.HALF_UP);

        subtotalAfterDiscount = subtotalAfterDiscount.add(lineAfterDiscount);
        taxAmount = taxAmount.add(lineTax);
        remainingUnits -= unitsInLine;
    }

    BigDecimal totalPrice = subtotalAfterDiscount.add(taxAmount).setScale(2, RoundingMode.HALF_UP);
    return new PricingBreakdown(basePrice, discountRate, taxAmount, totalPrice);
}

No I/O, no sleeps, no database. Pure CPU work, which is exactly the point. This is the kind of method the agent cannot see.

One disclosure, since the numbers have to add up: the loop you see here is cheap at quantity = 5. The weight sits in lookupBasePrice, which builds and linearly scans a price catalog of roughly 950,000 entries, once per call rather than once per unit. That is deliberately absurd. In a real service it would be a cached lookup and the span would measure microseconds. The point of this article is the shape of the trace, not the size of the number, and a gap of forty milliseconds is easier to see in a screenshot than a gap of forty microseconds.

Two things worth knowing before scattering these around.

It works on private methods, but only because the agent is rewriting bytecode. This is not a Spring proxy, so there is no self-invocation problem to worry about. A private method called from within the same class still gets its span. If one fails to appear, check the version alignment above first, then try widening the method's visibility.

Extract before you annotate. A span is only useful if it wraps one coherent thing. If your pricing logic sits inline in the middle of a 200-line service method, annotating that method tells you nothing you did not already know.

Switch to the manual-spans branch, rebuild, send the same request, and the gap is gone:

validate-order-request at 32µs. calculate-pricing at 38.68ms, most of the 44ms gap from before, now with a name. check-inventory and persist-order wrap the library spans they own, and map-response closes the request at 20µs.

Note that a few milliseconds are still unaccounted for. That residue is not a failure of instrumentation: some of what sits between two spans is request deserialisation, framework dispatch and other work that is not yours to name. You are never going to close the gap completely, and chasing the last microsecond is how you end up with a trace so noisy that nobody reads it.

The totals: 178.06ms without manual spans, 184.86ms with them. Do not read that difference as the cost of instrumentation. Two annotations cannot cost seven milliseconds. The runtime overhead of a span is a context push and a timestamp, measured in fractions of a microsecond. What you are looking at is JVM noise: a minor GC, a scheduling hiccup, network jitter between two containers. Run the same request twenty times and you will see a wider spread than this with no code change at all.

There is one real cost worth naming: annotating a small private method can prevent the JIT from inlining it, so a hot, tight method may genuinely run slower once instrumented. That is an argument for instrumenting meaningful units of work rather than every method you can reach. It is not an argument against instrumenting at all. In an I/O bound service like this one, where a single HTTP call accounts for 70% of the request, it is invisible.

Attributes are where this gets useful

Click on the calculate-pricing span:

The span carries order.sku = SKU-1000 and order.quantity = 5, the actual values from the request. It also carries code.function = computePricing and code.namespace = com.example.orderservice.order.OrderService, added automatically.

This is the difference between something took 38ms and OrderService.computePricing took 38ms for SKU-1000 at quantity 5. Once those attributes are on the span you can search on them: every pricing calculation above a threshold, filtered by SKU. That is a question you cannot ask a log file without writing a parser first.

Two cautions. Whatever you put in an attribute ends up in your observability backend, so keep personal data and secrets out of them. And be careful about where that attribute travels: order.sku is harmless on a span, because traces are sampled and stored as individual records. Put the same field on a metric and you have created one time series per SKU. High-cardinality labels are the classic way to take down a Prometheus instance, and the mistake is easy to make once you start instrumenting by habit rather than by intent.

Why the Collector is in the picture

You may have noticed the agent could have pointed straight at Jaeger. In development it can. There are three reasons not to do that anywhere else.

Batching and retries belong in a separate process, not in the request path of your application. The Collector can enrich, filter and drop data centrally rather than in every service. And most importantly:

exporters:
  otlp:
    endpoint: jaeger:4317
    tls:
      insecure: true

Changing your observability backend means editing that block. It does not mean touching, rebuilding or redeploying a single service. Your applications emit OTLP, an open protocol, and where it lands is a deployment detail.

If you have ever had to argue an architecture decision on vendor lock-in grounds, this is an unusually clean example: the instrumentation is standard, the wire protocol is standard, and the vendor-specific part is one block in one file.

For completeness: OTLP travels over gRPC on port 4317 and over HTTP/protobuf on 4318. The specification says the default should be http/protobuf unless an SDK has good reason to pick gRPC (backward compatibility, typically), so what you actually get depends on your SDK and version. Pin it explicitly, as in the compose file above. gRPC is generally the right choice for agent-to-collector traffic, which is high volume and continuous. Switch to HTTP if you have proxies or load balancers in between that are unhappy with long-lived HTTP/2 connections, which is common enough in enterprise networks.

What this does not cover

Tracing every request is affordable on a laptop but not in production, so sampling strategy is the decision waiting on the other side of this setup. Traces are also only one of three signals: metrics and logs travel the same pipeline, and correlating existing Log4j2 output with trace ids is arguably the highest-value thing to do after this. Asynchronous boundaries deserve their own article: put a message on a queue and the context does not propagate on its own, so the trace breaks silently at exactly that point.

The boundary described here, though, does not move. Auto-instrumentation maps the parts of your system that are made of libraries. Everything that is genuinely yours (the logic you were actually hired to write) stays invisible until you name it.

Naming it costs one dependency and a handful of annotations.