Stage 3 — Error Messages and Exception Context

What this stage teaches

Stage 3 is the first stage where you change behaviour visible to operators in a production postmortem. Nothing here is algorithmically hard. The difficulty is discipline: an error path is code nobody runs until the worst possible moment, so the bar for "done" is whether an on-call engineer, staring at a single AM log at 3am, can identify the failing DAG, vertex, task, and root cause without opening a second file. You learn:

• The CONTEXT rule for tez-dag: every error raised, logged, or rethrown inside the AppMaster should carry the DAG ID, and the vertex/task/attempt ID wherever the call site has them in scope.
• How to chain causes correctly: throw new TezException(msg, cause) instead of throw new TezException(msg) — losing cause throws away the stack trace that actually explains the failure.
• How to add caller identity to an action log, so "who killed my DAG?" has an answer.
• How the runtime library reports fetch failures, and why the original exception must survive all the way up to the AM.

These patches are 2–200 lines, often single-method changes on error paths. They are the ideal first merged contribution: low blast radius, high operator value, and reviewers can reason about them completely.

Prerequisite: Stage 2, plus the diagnostics deep dive: counters & diagnostics and, for the AM error surface, DAG AppMaster. Read those first — this stage assumes you know where diagnostics strings flow.

Finding Stage 3 issues today

Real JQL for issues.apache.org/jira (project TEZ). The Tez project uses text search heavily because component labels are inconsistent:

project = TEZ AND resolution = Unresolved
  AND (summary ~ "error message" OR summary ~ "diagnostic"
       OR summary ~ "misleading" OR summary ~ "improve message"
       OR summary ~ "swallow" OR summary ~ "NPE" )
ORDER BY updated DESC

A second sweep — find your own candidates by grep in the checkout at /Users/s0x/src/oss-repos/tez:

cd /Users/s0x/src/oss-repos/tez
# throw sites that build a message with no identifier in it
grep -rn 'throw new .*Exception("' tez-dag/src/main/java \
  | grep -vi "ID\|Id\|getName\|%s\|format" | head -30

# catch sites that drop the cause (canonical bug shape)
grep -rn "catch (.*Exception" tez-dag/src/main/java -A 3 \
  | grep -B1 "throw new" | grep -v ", e)\|, cause)\|, ie)" | head -30

The second grep is fuzzy; you will get false positives. But every true positive is a Stage 3 patch, and the pattern is exactly what the real fixes below removed.

The CONTEXT rule for tez-dag

Every error inside the AppMaster should carry enough state to identify which DAG instance on which application attempt threw it. The minimum fields, in priority order:

1. TezDAGID
2. TezVertexID — if in a vertex context
3. TezTaskID — if in a task context
4. TezTaskAttemptID — if in an attempt context
5. The container ID — for container-management errors

Each ID's toString() returns the canonical form. They live on every relevant impl object:

grep -n "getDAGID\|getVertexId\|getTaskID\|getID" \
  tez-dag/src/main/java/org/apache/tez/dag/app/dag/impl/VertexImpl.java | head

If you are editing a method on VertexImpl, getVertexId() and the DAG ID are in scope. If you don't include them, the patch is incomplete.

The subsystem knowledge you need

Two mechanisms carry context in Tez, and you must know which is already active before you add anything:

• NDC (Nested Diagnostic Context). The dispatcher wraps transition callbacks in CallableWithNdc, which pushes the relevant ID onto log4j's diagnostic stack for the duration of the call. If the log pattern includes %X{...}, the ID is already in every line — adding it inline is redundant and reviewers reject it. Check first:

  cd /Users/s0x/src/oss-repos/tez
  find . -name CallableWithNdc.java
  grep -rn "class CallableWithNdc" tez-common/src/main/java
  

• The diagnostics string on the entity. Errors that must survive to the user (not just the log) are stored as a diagnostic on the DAG/vertex/task — this is what the UI and DAGStatus surface. TEZ-3246 below improves exactly this. Read counters & diagnostics for how these strings flow from the entity to the client.

The rule of thumb: log-only context can lean on NDC; user-facing context must be put on the diagnostics string explicitly. Know which one you're touching.

Case study A — TEZ-3246: "who killed my DAG?"

This is the model Stage 3 fix. Read it:

cd /Users/s0x/src/oss-repos/tez
git show b63d7faf5   # TEZ-3246. Improve diagnostics when DAG killed by user

The bug. When a client kills a DAG or shuts down the AM, the AM logged a generic constant and passed that same constant as the diagnostic string stored on the DAG:

LOG.info("Sending client kill to dag: " + dagIdStr);
dagAppMaster.tryKillDAG(dag, "Kill Dag request received from client");

For a multi-tenant Hive session AM serving dozens of users, "Kill Dag request received from client" is useless. Which client? An operator investigating a mysteriously-killed query had no way to attribute the kill.

How it was found. Operator report: DAGs dying with a diagnostic that names no actor. The git show diff is the whole story — Eric Badger added a getClientInfo() helper that reads the caller's UGI and remote address off the RPC Server:

private String getClientInfo() throws TezException {
  UserGroupInformation callerUGI;
  try {
    callerUGI = UserGroupInformation.getCurrentUser();
  } catch (IOException ie) {
    LOG.info("Error getting UGI ", ie);
    throw new TezException(ie);
  }
  String message = callerUGI.toString();
  if (null != Server.getRemoteAddress()) {
    message += " at " + Server.getRemoteAddress();
  }
  return message;
}

Then both tryKillDAG and the shutdown path build a message that names the actor and pass that as the diagnostic:

String message = "Sending client kill from " + getClientInfo() + " to dag " + dagIdStr;
LOG.info(message);
dagAppMaster.tryKillDAG(dag, message);

What the test did. Note what it does not do — it never asserts on the exact string. It uses Mockito contains(...):

verify(mockDagAM, times(1)).tryKillDAG(eventCaptor.capture(),
    contains("Sending client kill from"));
...
verify(mockDagAM).shutdownTezAM(contains("Received message to shutdown AM from"));

The three lessons.

1. The diagnostic string is data, not just a log line — it is stored on the DAG and surfaced to the user. Improving it improves every downstream tool.
2. Caller identity (UGI + remote address) is the highest-value context you can add to any user-initiated action. Learn where UserGroupInformation.getCurrentUser() and Server.getRemoteAddress() live.
3. Assert with contains, never equals. A reviewer will reject an exact-string assertion because it breaks the next time someone rephrases the message.

Case study B — TEZ-1836: turn a config error into an actionable one

git show 665801c6d   # better error messages when io.sort.mb / spill percent are misconfigured

The bug. The sorters validated tez.runtime.io.sort.mb and tez.runtime.sort.spill.percent with opaque checks. PipelinedSorter and DefaultSorter each hand-rolled a bitmask test and threw messages like:

if ((sortmb & 0x7FF) != sortmb) {
  throw new IOException("Invalid \"" + TEZ_RUNTIME_IO_SORT_MB + "\": " + sortmb);
}

(sortmb & 0x7FF) != sortmb is a clever way to test "≤ 2047", but the message "Invalid io.sort.mb: 4096" doesn't tell the operator what the valid range is.

The fix. Vasanth Kumar RJ consolidated the validation into ExternalSorter (the shared base) using Preconditions.checkArgument with a message that states the constraint:

Preconditions.checkArgument(initialMemRequestMb > 0 && initialMemRequestMb <= 2047,
    TezRuntimeConfiguration.TEZ_RUNTIME_IO_SORT_MB
        + " should be larger than 0 and less than or equal to 2047");

The duplicated, cryptic checks in the two subclasses were deleted. One validation, one clear message, one place to maintain.

What the test did. TestOnFileSortedOutput.testSortBufferSize / testSortSpillPercent set the config to an illegal value (2048, then 0; 0.0f then 1.1f), call initialize(), expect the exception, and assert the message names the config key:

catch (IllegalArgumentException e) {
  assertTrue(e.getMessage().contains(TezRuntimeConfiguration.TEZ_RUNTIME_IO_SORT_MB));
}

Note the exception type changed from IOException to IllegalArgumentException — that is what Preconditions.checkArgument throws. That is acceptable here because these are argument validation failures, not I/O failures. The lesson: pick the exception type that describes the category of the error, and let the test assert on the key name (stable) rather than the full sentence (churny).

Case study C — TEZ-4336: never swallow the original fetch exception

git show 6863a2d99   # ShuffleScheduler should try to report the original exception

The bug. When shuffle becomes "unhealthy" (too many fetch failures), the ShuffleScheduler reported failure to the AM by constructing a fresh IOException with only its own summary string:

exceptionReporter.reportException(new IOException(errorMsg));

The errorMsg is a synthetic health summary. The actual exception that caused the fetch to fail — a ConnectException, a ChecksumException, whatever the Fetcher hit — was thrown away. The operator saw "shuffle is unhealthy" but never the reason.

The fix. Laszlo Bodor threaded the real cause through. He added a cause field and a fluent withCause(...) to InputAttemptFetchFailure:

public InputAttemptFetchFailure withCause(Throwable throwable) {
  this.cause = throwable;
  return this;
}

FetcherOrderedGrouped now attaches the caught exception at the failure site:

scheduler.copyFailed(InputAttemptFetchFailure.fromAttempt(left).withCause(ie),
    host, connectSucceeded, !connectSucceeded);

and the scheduler chains it into the reported exception:

exceptionReporter.reportException(new IOException(errorMsg, fetchFailure.getCause()));

Same errorMsg, but now the two-argument IOException constructor preserves the whole causal chain. The AM diagnostics — and the user's error — finally name the underlying network/disk failure.

The lesson. This is the CONTEXT rule applied across a subsystem boundary. The "error message" isn't a string you write; it's a cause chain you must not break. When a low layer catches an exception and a high layer reports it, the object that travels between them (InputAttemptFetchFailure here) must carry the cause. This same carrier is reused by a later deadlock fix (TEZ-4334, dissected in Stage 6) — so understanding it now pays twice.

Tip: TEZ-4308 (git show 5eeccf0e3) is a one-line sibling — it added a missing space in a ShuffleScheduler error message so two words stopped running together. Trivial, but it merged, and it is a legitimate first PR. Do not be too proud to fix a message that reads hostFailures=3reducerStalled.

Case study D — TEZ-4357: name the resource, not just the failure

git show cafa4b37d   # Report url to logs in case of fetcher connection failure

The bug. When a Fetcher failed to connect, the warning named the hosts but not the URL it was actually trying to reach — so an operator debugging a shuffle failure couldn't tell which shuffle-handler endpoint (partition, keep-alive, SSL) was involved.

The fix. Laszlo Bodor hoisted the baseURI out of the try block so it is in scope in the catch, and added it to the log — plus a greppable FETCH_FAILURE: tag and a switch from String.format to SLF4J {} placeholders (lazy, cheaper):

StringBuilder baseURI = null;
try {
  baseURI = ShuffleUtils.constructBaseURIForShuffleHandler(host, port, ...);
  ...
} catch (...) {
  LOG.warn("FETCH_FAILURE: Fetch Failure while connecting from {} to: {}:{}, attempt: {}, url: {}"
      + " Informing ShuffleManager", localHostname, host, port, firstAttempt, baseURI, e);

Two lessons. First, a variable you want to log in a catch must be declared before the try — a common oversight that silently drops the most useful field. Second, a consistent, greppable prefix (FETCH_FAILURE:) turns a log into a queryable dataset; operators grep for it across thousands of container logs. Both are cheap habits with outsized operational payoff.

The contribution playbook for this class

1. Grep for the shape, not the ticket. The two greps above find swallowed causes and ID-less throws faster than JIRA search does.
2. Read the surrounding 20 lines to learn what identifiers are in scope. If getVertexId()/getDAGID() are reachable, they belong in the message.
3. Chain the cause. Every rethrow uses the two-argument constructor. If the object crosses a subsystem boundary, give it a withCause-style carrier.
4. Log and throw only when the callers might swallow. TEZ-3246 logs the same message it stores as a diagnostic — belt and braces.
5. Test with contains/Matchers.contains on the stable token (a config key, an ID prefix like "dag_", a fixed phrase), never on the full sentence.
6. Run the targeted suite.

cd /Users/s0x/src/oss-repos/tez
mvn -pl tez-dag test -Dtest=TestDAGClientHandler -q
mvn -pl tez-runtime-library test -Dtest=TestOnFileSortedOutput -q

Common mistakes

Exit criteria — when you're ready for the next stage

• You have shipped at least one error-context patch: one in tez-dag and one in tez-runtime-library, each carrying the relevant IDs or a chained cause.
• A reviewer accepted your contains-based test without comment.
• You can find three more candidate error sites in five minutes of grepping — and you can point at TEZ-3246, TEZ-1836, and TEZ-4336 as the templates for the three shapes (caller identity, actionable validation, preserved cause).
• You have read DAGClientHandler and ExternalSorter around the fixed sites and did not feel lost.

Stage 4 takes you inside the state machines themselves.