One failed test, four Grid components, and no way to tell which log line is yours

A payments test throws NoSuchElementException on a button that has been on that page for two years. The suite is green on rerun. Someone opens the Grid logs, scrolls past tens of thousands of lines from the same two-minute window, greps for the test class name, and finds nothing, because the Grid has never heard of your test class. The investigation ends with the word "flaky" and the ticket is closed.

The information needed to close that ticket properly was there the whole time. What was missing was a join key. Your test report knows the test name and the exception. The Grid knows the session, the Node, the slot and the queue wait. Neither one knows the other's vocabulary, and the only field they appear to share is a timestamp, which on a Grid running dozens of concurrent sessions is not a key at all.

The mechanism: what each Grid component actually knows

Before you can join anything, be precise about which component holds which fact. The Selenium documentation describes the pieces this way.

The Router is the entry point of the Grid. It receives all external requests and forwards them to the correct component. For a new session request it forwards to the New Session Queue. For a request against an existing session it queries the Session Map to retrieve the Node ID and forwards the request directly to that Node.

The New Session Queue holds all new session requests in FIFO order, with configurable request timeout and retry interval.

The Distributor does two jobs. Nodes register with it by sending a registration event through the Event Bus, and it confirms the Node's existence over HTTP while tracking Node capabilities. Separately, it polls the New Session Queue for pending requests and finds a suitable Node where the session can be created.

The Session Map is a data store that keeps the relationship between the session id and the Node where the session is running.

The Node manages the slots for the browsers available on its machine, and executes commands without making evaluative decisions.

The Event Bus carries internal messages between Nodes, Distributor, New Session Queue and Session Map.

Read that list again with a debugging question in mind and something falls out. The session ID does not exist for the first part of a request's life. A request sits in the queue, gets matched by the Distributor, and only then does a session come into being and get recorded in the Session Map. Everything that happens before that point is invisible to session-based correlation. This is not a flaw in your logging, it is the shape of the system, and it decides which of two very different investigations you are about to run.

Once the session exists, though, one string ties everything together. Your Java code has it. The Session Map is keyed on it. The Router uses it to pick the Node. The GraphQL endpoint returns it. That string is the join key, and the entire job is making sure it gets written down on both sides.

The three-sided join

A usable correlation record has three sides, and most frameworks only build one.

Side one, the test side. Test identity, attempt number, build ID, the exception, and the session ID. This is yours to write and nobody else will write it for you.

Side two, the Grid side. Which Node ran the session, what the returned capabilities were, how long the session lasted, when it started. Available from the GraphQL endpoint while the session is live, and from component logs afterwards.

Side three, the request side. What you asked for, and how long it waited before anything happened. This is the side that matters when the session never started.

Build all three, keyed consistently, and the class of failure that starts with "we cannot tell what happened" mostly stops existing.

Capture the key on the test side

The rule is unglamorous: read the session ID exactly once, immediately after the driver is created, and write it somewhere durable before running a single command. Everything else follows from that.

package com.thetestingacademy.grid;

import java.io.IOException;
import java.io.UncheckedIOException;
import java.net.URL;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.StandardOpenOption;
import java.util.UUID;
import org.openqa.selenium.Capabilities;
import org.openqa.selenium.SessionNotCreatedException;
import org.openqa.selenium.chrome.ChromeOptions;
import org.openqa.selenium.remote.RemoteWebDriver;
import org.openqa.selenium.remote.SessionId;

public final class CorrelatedDriverFactory {

  private static final Path LOG = Path.of("target", "correlation.ndjson");

  public static RemoteWebDriver create(String gridUrl, String testId, int attempt) {
    // A key that exists BEFORE the request leaves the client. This survives
    // the case where no session is ever created.
    String correlationId = UUID.randomUUID().toString();

    ChromeOptions options = new ChromeOptions();
    // Metadata is attached by prefixing a capability with "se:". The Grid UI
    // shows se:name in place of the raw session id; other se: values are
    // visible on the session and through GraphQL.
    options.setCapability("se:name", testId + " #" + attempt);
    options.setCapability("se:correlationId", correlationId);
    options.setCapability("se:buildId", System.getenv().getOrDefault("BUILD_ID", "local"));

    long requestedAt = System.currentTimeMillis();
    RemoteWebDriver driver;
    try {
      driver = new RemoteWebDriver(new URL(gridUrl), options);
    } catch (SessionNotCreatedException e) {
      // No session id will ever exist for this attempt. Record the request
      // side anyway, or this failure becomes uninvestigable.
      append(json(
          "correlationId", correlationId,
          "sessionId", "",
          "testId", testId,
          "attempt", String.valueOf(attempt),
          "outcome", "NO_SESSION",
          "waitedMillis", String.valueOf(System.currentTimeMillis() - requestedAt),
          "error", e.getClass().getName()));
      throw e;
    } catch (java.net.MalformedURLException e) {
      throw new IllegalArgumentException("Bad grid url: " + gridUrl, e);
    }

    SessionId sessionId = driver.getSessionId();
    if (sessionId == null) {
      // The API declares this nullable. Treat it as a hard error here rather
      // than letting an empty key poison every downstream join.
      driver.quit();
      throw new IllegalStateException("Null session id for " + testId + " #" + attempt);
    }

    Capabilities returned = driver.getCapabilities();
    append(json(
        "correlationId", correlationId,
        "sessionId", sessionId.toString(),
        "testId", testId,
        "attempt", String.valueOf(attempt),
        "outcome", "SESSION_CREATED",
        "waitedMillis", String.valueOf(System.currentTimeMillis() - requestedAt),
        "requestedBrowser", options.getBrowserName(),
        "returnedBrowser", returned.getBrowserName(),
        "returnedVersion", returned.getBrowserVersion(),
        "gridUrl", gridUrl));

    return driver;
  }

  private static String json(String... kv) {
    StringBuilder sb = new StringBuilder("{");
    for (int i = 0; i < kv.length; i += 2) {
      if (i > 0) sb.append(',');
      sb.append('"').append(kv[i]).append("\":\"")
        .append(kv[i + 1] == null ? "" : kv[i + 1].replace("\"", "\\\""))
        .append('"');
    }
    return sb.append('}').toString();
  }

  private static synchronized void append(String line) {
    try {
      Files.createDirectories(LOG.getParent());
      Files.writeString(LOG, line + System.lineSeparator(),
          StandardOpenOption.CREATE, StandardOpenOption.APPEND);
    } catch (IOException e) {
      throw new UncheckedIOException("Could not write correlation record", e);
    }
  }
}

Four things in that factory earn their place.

requestedBrowser and returnedBrowser as separate fields. What you asked for and what you got are different facts and they are allowed to differ. Recording only one of them destroys the ability to answer "did the Distributor match a slot I did not expect", which turns out to be a surprisingly common root cause.

waitedMillis on both paths. Session creation wall time is your only client-side view of queue pressure. It costs one subtraction.

A record written on the failure path. The SessionNotCreatedException branch is the whole reason the correlation ID exists. Without it, the failures you most need to explain are the ones with no evidence.

Newline-delimited JSON, appended. Not a database, not a service. One file, one line per attempt, greppable, uploadable as a CI artifact, and trivially mergeable across shards.

Query the Grid side

With the key in hand, the Grid is queryable. The GraphQL endpoint is documented at /graphql on the Router (or on a Standalone), and it takes a POST with a JSON body containing a query field.

GRID=http://localhost:4444
SID=$(jq -r 'select(.testId=="checkout.appliesDiscount") | .sessionId' \
        target/correlation.ndjson | tail -1)

# 1. Which Node ran this session, and what did it actually get?
curl -s -X POST -H 'Content-Type: application/json' \
  --data "{\"query\":\"{ session (id: \\\"${SID}\\\") { id, capabilities, startTime, uri, nodeId, nodeUri } }\"}" \
  "${GRID}/graphql" | jq '.data.session'

# 2. Everything currently running, with the node it landed on and how long
#    it has been alive. Useful while a hang is still in progress.
curl -s -X POST -H 'Content-Type: application/json' \
  --data '{"query":"{ sessionsInfo { sessions { id, capabilities, startTime, nodeId, nodeUri, sessionDurationMillis } } }"}' \
  "${GRID}/graphql" | jq '.data.sessionsInfo.sessions'

# 3. Is the Grid actually able to take work right now? Queue depth is the
#    number that separates "your test is broken" from "your Grid is full".
curl -s -X POST -H 'Content-Type: application/json' \
  --data '{"query":"{ grid { uri, maxSession, sessionCount, sessionQueueSize } }"}' \
  "${GRID}/graphql" | jq '.data.grid'

# 4. What is sitting in the queue, unmatched?
curl -s -X POST -H 'Content-Type: application/json' \
  --data '{"query":"{ sessionsInfo { sessionQueueRequests } }"}' \
  "${GRID}/graphql" | jq -r '.data.sessionsInfo.sessionQueueRequests[]'

# 5. What capabilities do the Nodes claim to offer? If your request does not
#    match any stereotype, it will queue until it times out.
curl -s -X POST -H 'Content-Type: application/json' \
  --data '{"query":"{ nodesInfo { nodes { id, uri, status, stereotypes } } }"}' \
  "${GRID}/graphql" | jq '.data.nodesInfo.nodes'

Query one is the money shot: it takes a session ID from your own record and returns the Node URI. That single hop is what turns "some Node somewhere" into "this container, go read its log".

Queries three, four and five are the request-side view, and they only mean anything while the Grid is in the state you care about. Snapshot them on failure, from CI, into the artifact bundle. A queue depth read the next morning tells you nothing.

Wire the logging flags so the component side exists at all

The Grid's own log output is configured by a small set of flags. The documented descriptions are worth quoting because they are more restrictive than people assume:

• --log-level, with the note that the default logging level is INFO.
• --log, a file to write out logs, with a reminder to keep the path compatible with the operating system.
• --structured-logs, described simply as "Use structured logs".
• --http-logs, described as "Enable http logging", with the explicit caveat that tracing should be enabled to log http logs.
• --tracing, "Enable trace collection".

That caveat on --http-logs is the one that catches people. Turning on HTTP logging by itself and getting nothing useful is not a bug; the documentation says tracing is expected alongside it.

For a distributed Grid, the components and their flags are documented individually. Here is a compose file that turns on file logging for each one so there is something to grep later.

# docker-compose.yml
# Env var names vary between docker-selenium image versions. Check the
# README for the tag you pin before copying this into a real environment.
services:
  event-bus:
    image: selenium/event-bus:4.41.0
    ports: ["4442:4442", "4443:4443", "5557:5557"]

  session-map:
    image: selenium/sessions:4.41.0
    depends_on: [event-bus]
    environment:
      SE_EVENT_BUS_HOST: event-bus
      SE_EVENT_BUS_PUBLISH_PORT: "4442"
      SE_EVENT_BUS_SUBSCRIBE_PORT: "4443"
      SE_OPTS: "--log-level FINE --log /opt/logs/sessions.log"
    volumes: ["./grid-logs:/opt/logs"]

  session-queue:
    image: selenium/session-queue:4.41.0
    environment:
      SE_OPTS: "--log-level FINE --log /opt/logs/sessionqueue.log --session-request-timeout 120"
    volumes: ["./grid-logs:/opt/logs"]

  distributor:
    image: selenium/distributor:4.41.0
    depends_on: [event-bus, session-map, session-queue]
    environment:
      SE_EVENT_BUS_HOST: event-bus
      SE_EVENT_BUS_PUBLISH_PORT: "4442"
      SE_EVENT_BUS_SUBSCRIBE_PORT: "4443"
      SE_SESSIONS_MAP_HOST: session-map
      SE_SESSION_QUEUE_HOST: session-queue
      SE_OPTS: "--log-level FINE --log /opt/logs/distributor.log"
    volumes: ["./grid-logs:/opt/logs"]

  router:
    image: selenium/router:4.41.0
    depends_on: [distributor]
    ports: ["4444:4444"]
    environment:
      SE_DISTRIBUTOR_HOST: distributor
      SE_SESSIONS_MAP_HOST: session-map
      SE_SESSION_QUEUE_HOST: session-queue
      SE_OPTS: "--log-level FINE --log /opt/logs/router.log"
    volumes: ["./grid-logs:/opt/logs"]

  chrome:
    image: selenium/node-chrome:4.41.0
    depends_on: [event-bus]
    shm_size: 2gb
    environment:
      SE_EVENT_BUS_HOST: event-bus
      SE_EVENT_BUS_PUBLISH_PORT: "4442"
      SE_EVENT_BUS_SUBSCRIBE_PORT: "4443"
      SE_OPTS: "--log-level FINE --log /opt/logs/node-chrome.log"
    volumes: ["./grid-logs:/opt/logs"]

If you are running the jars directly instead, the component commands are documented on the getting-started page and take the same logging flags. The distributed shape is worth internalising because it tells you which log file to open for which question:

V=4.41.0
BUS=10.0.0.11

java -jar selenium-server-${V}.jar event-bus \
  --publish-events tcp://${BUS}:4442 --subscribe-events tcp://${BUS}:4443 --port 5557

java -jar selenium-server-${V}.jar sessionqueue \
  --port 5559 --log /var/log/selenium/sessionqueue.log --log-level FINE

java -jar selenium-server-${V}.jar sessions \
  --publish-events tcp://${BUS}:4442 --subscribe-events tcp://${BUS}:4443 \
  --port 5556 --log /var/log/selenium/sessions.log --log-level FINE

java -jar selenium-server-${V}.jar distributor \
  --publish-events tcp://${BUS}:4442 --subscribe-events tcp://${BUS}:4443 \
  --sessions http://10.0.0.12:5556 --sessionqueue http://10.0.0.13:5559 \
  --port 5553 --bind-bus false --log /var/log/selenium/distributor.log --log-level FINE

java -jar selenium-server-${V}.jar router \
  --sessions http://10.0.0.12:5556 --distributor http://10.0.0.14:5553 \
  --sessionqueue http://10.0.0.13:5559 --port 4444 \
  --log /var/log/selenium/router.log --log-level FINE

java -jar selenium-server-${V}.jar node \
  --publish-events tcp://${BUS}:4442 --subscribe-events tcp://${BUS}:4443 \
  --log /var/log/selenium/node.log --log-level FINE

A note on --structured-logs: the documentation tells you it exists and not what shape it produces, and the shape has changed between versions. Do not copy a jq filter from a blog post (including this one) and assume the field names. Run one session, look at one line, and then pin your queries. A filter that works regardless of field names is worth having in the meantime:

SID="8f21c0d3b7a94e18b1c0aa77e0f4c221"

# Version-independent: match the raw id anywhere in the record.
grep -F "${SID}" grid-logs/*.log | sed 's/^/  /'

# If the output is JSON lines, this finds every record mentioning the id
# without caring which field it lives in.
cat grid-logs/*.log \
  | jq -c --arg sid "${SID}" 'select(tostring | contains($sid))' 2>/dev/null

# Ordering across components is the actual signal. Which file mentions the
# session first, and which one mentions it last?
grep -lF "${SID}" grid-logs/*.log

That last command answers a question people spend hours on. If the Node log never mentions the ID, the session did not reach a Node the way you think it did. If the Router log mentions it long after the Node does, you are looking at a routing or Session Map problem rather than a browser problem.

Worked example one: the element that was never going to be there

The NoSuchElementException from the opening. Here is what the join produced.

The correlation record for the failing attempt gave a session ID and a waitedMillis in the low hundreds, so the queue was not the issue. The single-session GraphQL query returned a nodeUri pointing at one specific container and a sessionDurationMillis far shorter than the test's own runtime. That mismatch is the finding: the session ended before the test did. The test then kept issuing commands against a session that no longer existed, and the failure surfaced as the first command that needed an element.

Grepping that Node's log for the session ID showed the ID appearing and then stopping mid-test, with nothing after it. The Node had been recycled. The look-alike explanation, a genuinely missing button, was ruled out by the fact that the same locator worked on the retry against a different Node URI, and by the returned capabilities being identical on both attempts.

The fix had nothing to do with waits or locators. It was a Node lifecycle setting. Notice how much of that reasoning depended on a single field, nodeUri, that the test report had no way of knowing.

Worked example two: no session ID, because no session

The second investigation starts differently. A CI job fails with SessionNotCreatedException and no session ID exists anywhere, so every technique above is unavailable.

This is where the request side earns its keep. The correlation record still exists, because the factory wrote one on the exception path, and it carries the correlation ID, the requested capabilities and the wait time. Now go to the queue.

GRID=http://localhost:4444

# What was still queued at the moment of failure? Capture this from CI,
# on the failure path, or it is gone.
curl -s -X POST -H 'Content-Type: application/json' \
  --data '{"query":"{ sessionsInfo { sessionQueueRequests } }"}' \
  "${GRID}/graphql" | jq -r '.data.sessionsInfo.sessionQueueRequests[]' \
  > artifacts/queue-at-failure.json

# What could the Grid have matched? Compare your requested capabilities
# against the stereotypes the Nodes actually advertise.
curl -s -X POST -H 'Content-Type: application/json' \
  --data '{"query":"{ nodesInfo { nodes { id, uri, status, stereotypes } } }"}' \
  "${GRID}/graphql" | jq '.data.nodesInfo.nodes' \
  > artifacts/stereotypes-at-failure.json

# The two-line summary that classifies the failure.
jq -r '"queued requests: " + (length|tostring)' artifacts/queue-at-failure.json
jq -r '"nodes UP: " + ([.[] | select(.status=="UP")] | length | tostring)' \
  artifacts/stereotypes-at-failure.json

Three outcomes, three different owners:

• Queue depth high, Nodes UP, no free slots. Capacity. Nothing is wrong with your test. This is where dynamic Node provisioning belongs in the conversation.
• Queue depth high, Nodes UP, slots free. Matching. Your requested capabilities do not satisfy any advertised stereotype, so the Distributor never matches the request and it sits until --session-request-timeout expires. Diff your request against the stereotypes field character by character; it is usually a platformName or a browserVersion string.
• Nodes not UP, or absent. Registration. Nodes register through the Event Bus, so this is an Event Bus reachability or Node startup problem, and the Distributor log is the place to look.

None of these are visible from the test report. All three are visible in two GraphQL calls that cost nothing to add.

How to tell it is a correlation problem and not a look-alike

Three failures wear this costume. The evidence that separates them is specific.

It is genuinely a product defect. Signature: the test's own assertion failed on visible application state, and the session was healthy the whole time. Check sessionDurationMillis against your test's own elapsed time, and check that the returned capabilities match the request. If the session outlived the test and the capabilities match, the Grid did its job and you should stop reading Grid logs.

It is a client-side lifecycle bug. Signature: your correlation file has two records with the same session ID, or a record whose session ID is empty, or more records than sessions the Grid ever created. That is a framework problem and no amount of Grid logging will explain it. Fix the capture layer first, because a broken capture layer makes every subsequent conclusion untrustworthy.

It is clock skew masquerading as causality. Signature: your timeline says the Node logged something before the Router received the request. That is not time travel, that is two hosts disagreeing about the time. This is precisely why timestamp joins fail and why the session ID is the key. When you do need ordering across components, order by the sequence of appearances of the session ID rather than by wall-clock time, or invest in proper trace correlation where the span hierarchy carries the ordering for you.

What this costs

Latency: two extra map reads and one file append per session. Against a session creation that takes hundreds of milliseconds, this does not register. The GraphQL queries are the expensive part and they only run on failure.

Storage: one line per attempt. A suite with a few thousand sessions produces a file measured in low megabytes. Grid component logs at FINE are the real cost here, and they are substantial. Do not run FINE permanently on a busy production Grid; run it in CI, or turn it on when you are investigating.

Complexity: one factory, one file, two queries. The design is deliberately boring. The hard part is not the code, it is making every driver-creation path in the framework go through the one factory. If you have three ways to build a driver, correlation will be silently incomplete until all three are converted.

Privacy: a real cost people forget. Correlation records and Grid logs both end up as CI artifacts. Capabilities can contain vendor credentials, and se: metadata contains whatever you put in it. Never put a token in an se: capability, and strip capability blobs before uploading if your Grid is a vendor endpoint. Artifact retention should be short.

Coverage: it tells you where, not why. Knowing the session ran on node-chrome-7 and lasted eleven seconds does not fix anything by itself. It shortens the search from "the whole Grid" to "one container", which is worth a great deal and is not the same as a root cause.

Rollout path

1. Ship the factory in shadow mode. Write correlation records, change nothing else, upload the file as an artifact. One week of records costs nothing and gives you a baseline.
2. Add se:name to the requested capabilities. Immediate, visible payoff: the Grid UI stops showing opaque session IDs and starts showing your test names. This is the change that gets the rest of the work approved.
3. Turn on --log for each component with a path you can collect. Leave the level at the default until you have a reason to raise it.
4. Add the two failure-path GraphQL snapshots to CI. Queue state and Node stereotypes, captured on failure only, written into the artifact bundle.
5. Only now, raise the log level or enable tracing. By this point you know which questions you cannot answer, so you can turn on the specific thing that answers them instead of turning on everything.
6. Write the join into your reporting. A failure row that links straight to the Node URI and the session record removes the manual step entirely, and that is when people actually start using it.

If you have not yet consolidated driver creation, do that before step one. A single session factory is the precondition for all of this, not an optional refinement.

Trade-offs worth arguing about

Session ID versus a synthetic correlation ID. The session ID joins to the Grid; the synthetic ID exists earlier and survives a failed creation. Neither alone covers the whole request lifetime. Carrying both costs one extra field and closes the gap, which is why the factory above does exactly that.

Structured logs versus plain logs. Structured output is far better for automated analysis and far worse for a human skimming a terminal during an incident. The output shape is also version-dependent, which means your parsing is a maintenance obligation. If nobody is going to write the parser, plain logs plus grep -F will serve you better than structured logs nobody queries.

GraphQL polling versus tracing. Polling the endpoint is trivial to add, needs no extra infrastructure, and only sees the present moment. Tracing gives you the full causal path across components, and costs you a backend to run and maintain. Start with polling. Move to tracing when you have a specific question that polling has failed to answer more than once.

Grid logs versus browser logs. They answer different questions and teams frequently collect the wrong one. Grid logs explain routing, queuing, slot assignment and session lifetime. Browser logs explain what the page did. A NoSuchElementException that turned out to be a recycled Node needed Grid logs; the same exception caused by a JavaScript error needs browser logs. Collect both and label them clearly, or people will read the wrong file and reach a confident wrong answer.

When not to do this

You run Standalone locally with one session at a time. There is no ambiguity to resolve. Your log has one session in it. Adding correlation machinery to a single-session local run is pure overhead, and it will not teach you anything the terminal is not already telling you.

You use a vendor Grid and have no access to component logs. Half the join does not exist. Vendors expose their own session identifier and their own dashboard, and correlating to those is worthwhile, but the Grid-component reasoning here does not apply. Capture the vendor's session ID and their build ID and use their tooling; do not build a pipeline for logs you cannot read.

Your failures are not infrastructure failures. Run the check first. If sessionDurationMillis comfortably exceeds your test runtime on every failure and returned capabilities always match the request, the Grid is not your problem and correlation will not find one for you. Spending a sprint on observability to discover your locators are bad is an expensive way to learn that.

Nobody is on call for the Grid. Correlation produces findings that need an owner. If the answer to "which Node ran this" is going to be met with a shrug because there is no team responsible for Nodes, the tooling will be built and then ignored. Sort out ownership first; it is the cheaper fix and it is the one that makes the tooling pay off.

You would have to log capabilities from a vendor endpoint into a public artifact. Vendor capability blobs frequently carry credentials. If your redaction story is "we will remember to strip it", do not enable it. Build the redaction, verify it on one run, and then enable it.

Practise it

Next time a test is called flaky in your standup, ask for exactly three fields before anyone reruns it: the session ID, the Node URI, and the session duration. If the team cannot produce them, that is the gap, and it is a smaller piece of work than it looks.

Then run the discriminator on a real failure. Did the session outlive the test? Do the returned capabilities match what you asked for? Does the Node log mention the session ID at all? Three answers, three different owners, and none of them require a rerun.

You can rehearse the same reasoning under time pressure in the QABattle arena. Pick a Grid scenario, commit to which component you would open first, and name the single field that would prove you picked the wrong one.