Lab H3: Debugging a Failed Query

Background

Lab H2 taught you to read a healthy DAG. This lab reads a broken one. Production Hive-on-Tez failures surface as one terse line in the Hive console — a "Vertex failed" message that is the tip of the failure, three or four hops away from the actual exception. The discipline you build here is a single sentence:

Diagnostics tell you WHERE; task logs tell you WHY.

The Hive console and the DAG/vertex diagnostics localise the failure to a vertex, a task, an attempt, and a container. They almost never contain the root-cause stack trace. That lives in the failed TaskAttempt's container log, which you retrieve with yarn logs. Confusing the two — trying to root-cause from diagnostics, or trying to localise from a task log — is the single most common time-sink in Hive-on-Tez debugging.

You will induce two real failures with different surfaces — a UDF that throws on specific input (a runtime, per-row failure) and a broken tez.lib.uris (a DAG-submit failure) — and walk each from console to root cause. Then you will build a decision tree for "which log do I open for this symptom." The counter and diagnostics machinery is documented in the counters & diagnostics deep-dive.

Why This Lab Matters for Contributors

A maintainer's most valuable and scarcest skill is turning a one-line console error into a root cause fast. The reporter pastes return code 2 from ...TezTask and nothing else; you must know, without asking, exactly which four commands retrieve the real exception. Contributors who have this reflex resolve issues in a sitting. Contributors who don't ask the reporter three rounds of follow-up questions and lose the thread.

The second, subtler skill is knowing which surface a failure appears on. A DAG-submit failure and a per-row runtime failure look nothing alike and live in different logs. Get the surface wrong and you spend an hour in the AM log for a bug whose stack trace was in a container log the whole time. This lab makes the mapping mechanical.

Prerequisites

• H1 and H2 complete.
• A Hive-on-Tez environment where you can reach yarn logs — i.e. Tez running against YARN, not local mode. (The container's embedded mode won't give you yarn logs; use a pseudo-distributed Hadoop+Tez+Hive, or MiniTezCluster from H5, for the log-retrieval steps.)
• ~/tez-src present for verifying diagnostic message shapes.
• The ability to ADD JAR and to edit tez.lib.uris.

The Failure Hop Sequence

flowchart TD
  H["Hive console<br/>'Vertex failed, vertexName=Map 1'"]
  H --> D["DAGStatus diagnostics<br/>which vertex, which task"]
  D --> V["Vertex diagnostics<br/>which TaskAttempt, which container"]
  V --> A["yarn logs → container log<br/>the actual stack trace"]
  A --> R["Root cause<br/>attribute Hive / Tez runtime / Tez AM / YARN"]

Every hop narrows location; only the last hop yields cause. The diagnostics you read in hops 1–3 are literally strings the Tez AM concatenated from nested failures — you will verify their exact shape below so you can parse them without guessing.

Step 1: Induce Failure A — a UDF That Throws

Register a UDF that throws on a specific input value, then run a query that feeds it that value. This is the canonical "wrong data on one row" production failure.

-- A minimal throwing UDF is fine; the point is the failure surface, not the UDF.
-- Use any UDF that raises on a=3, or simulate with a division:
SELECT t.a, (10 / (t.a - 3)) AS boom FROM t;   -- divide-by-zero when a = 3

The Hive console returns something shaped like this (synthesized from the real message templates you verify in Step 2 — do not treat the IDs as literal):

FAILED: Execution Error, return code 2 from org.apache.hadoop.hive.ql.exec.tez.TezTask.
Vertex failed, vertexName=Map 1, vertexId=vertex_..._1_00,
 diagnostics=[Task failed, taskId=task_..._1_00_000003,
  diagnostics=[TaskAttempt 0 failed, info=[
   Error: Failure while running task: ... ]]]

That nested Vertex failed → Task failed → TaskAttempt N failed structure is not arbitrary — it is three Tez diagnostic strings nested inside each other. Verify each template in the Tez source so you can parse any such message:

grep -n '"Vertex failed"' \
  ~/tez-src/tez-dag/src/main/java/org/apache/tez/dag/app/dag/impl/DAGImpl.java
grep -n '"Task failed"' \
  ~/tez-src/tez-dag/src/main/java/org/apache/tez/dag/app/dag/impl/VertexImpl.java
grep -n 'failed,"' \
  ~/tez-src/tez-dag/src/main/java/org/apache/tez/dag/app/dag/impl/TaskImpl.java

You will see DAGImpl.vertexFailed build "Vertex failed" + ", vertexName=" + ... + ", diagnostics=" + vertex.getDiagnostics(), VertexImpl.taskFailed build "Task failed" + ", taskId=" + ... + ", diagnostics=" + task.getDiagnostics(), and TaskImpl build "TaskAttempt " + id + " failed," + " info=" + attempt.getDiagnostics(). The nesting you see on the console is exactly this composition.

Step 2: Parse the Console Message

Extract the identifiers. The format is stable across every Hive-on-Tez failure, so learn the fields once.

This is the WHERE. You now know the failure is in Map 1, task 000003, attempt 0, container 000007. You do not yet know WHY — the console diagnostic is truncated and wrapped. For that, open the container log.

Step 3: Get the AM Log (context) and the Container Log (cause)

The Tez AM is a YARN container (always the app's first container, _01_000001). Its log holds vertex/task state transitions and the aggregated diagnostics — useful context, rarely the full trace.

yarn logs -applicationId application_1718..._4321 \
  -containerId container_e123_..._01_000001 > ~/tez-notes/hive-h3a-amlog.txt
grep -n "task_.*_000003\|FAILED\|Diagnostics" ~/tez-notes/hive-h3a-amlog.txt | head

The container that actually ran the failing attempt (_000007 here) holds the full stdout/stderr of the Tez task runtime (LogicalIOProcessorRuntimeTask) — the real exception:

yarn logs -applicationId application_1718..._4321 \
  -containerId container_e123_..._000007 > ~/tez-notes/hive-h3a-container.txt
grep -n -B2 -A25 "ERROR\|Caused by\|Exception" ~/tez-notes/hive-h3a-container.txt | head -80

The container log shape for Failure A (synthesized from the real Hive/Tez runtime class names — verify the classes with the greps below):

[ERROR] LogicalIOProcessorRuntimeTask - Failed to execute task
java.lang.RuntimeException: org.apache.hadoop.hive.ql.metadata.HiveException:
  Hive Runtime Error while processing row {"a":3,"b":"q"}
        at org.apache.hadoop.hive.ql.exec.tez.MapRecordSource.processRow(MapRecordSource.java)
        at org.apache.hadoop.hive.ql.exec.tez.MapRecordProcessor.run(MapRecordProcessor.java)
        at org.apache.hadoop.hive.ql.exec.tez.TezProcessor.run(TezProcessor.java)
        at org.apache.tez.runtime.LogicalIOProcessorRuntimeTask.run(LogicalIOProcessorRuntimeTask.java)
        at org.apache.tez.runtime.task.TaskRunner2Callable$1.run(TaskRunner2Callable.java)
Caused by: java.lang.ArithmeticException: / by zero
        at ...

Verify every class named is real and lives where the trace claims:

grep -rln "class MapRecordSource\|class MapRecordProcessor" ~/hive-src/ql/src/java/
grep -rln "class LogicalIOProcessorRuntimeTask" ~/tez-src/tez-runtime-internals/src/main/java/
grep -rln "class TaskRunner2Callable" ~/tez-src/tez-runtime-internals/src/main/java/

{"a":3,"b":"q"} is the gift: the Hive runtime tags the failure with the row that broke it. The Caused by: chain walks from Hive's wrapping HiveException down to the JVM-level ArithmeticException. That is the WHY.

Step 4: Attribute Failure A

Apply the rule from H4 (previewed): the top frame in code you can change names the owner.

1. Skip java.lang.RuntimeException (JVM wrapper).
2. First actionable frame: org.apache.hadoop.hive.ql.exec.tez.MapRecordSource — Hive Tez integration, map side.
3. Caused by: ArithmeticException: / by zero — the root: the query's own arithmetic on data. Not a framework bug at all; the query divides by zero when a=3.

Attribution: user query (bad arithmetic), surfaced correctly by Hive's MapRecordSource, run correctly by Tez. Tez's job here was to provide a clean stack trace tagged with the container and task — which it did. No JIRA. The fix is the query (or a CASE WHEN a=3).

The lesson is the discipline, not this trivial cause: diagnostics said Map 1, task 3, container 7; only the container log said divide by zero on row {a:3}.

Step 5: Induce Failure B — Broken tez.lib.uris (a Different Surface)

Now break DAG submission rather than row processing. Point tez.lib.uris at a path that has no tez tarball:

SET tez.lib.uris=hdfs:///nonexistent/tez.tar.gz;
SELECT t.a, COUNT(*) FROM t GROUP BY t.a;

Verify the key is real first:

grep -n "TEZ_LIB_URIS " \
  ~/tez-src/tez-api/src/main/java/org/apache/tez/dag/api/TezConfiguration.java
# public static final String TEZ_LIB_URIS = TEZ_PREFIX + "lib.uris";

This fails at a completely different surface. Instead of "Vertex failed" (which requires a running DAG), you get a failure to even start the AM or localize its resources — often at the TezTask/session level in the HS2 log, before any container runs:

FAILED: Execution Error, return code 1 from org.apache.hadoop.hive.ql.exec.tez.TezTask.
Application application_... failed 2 times ... AM Container ... exited ...
 File does not exist: hdfs:/nonexistent/tez.tar.gz

There is often no container log to fetch because no task container ever launched. The evidence is in the HS2 log and the AM launch failure, not in a TaskAttempt log. This is the crucial contrast: two failures, two surfaces.

Step 6: The "Which Log?" Decision Tree

Build and keep this. Given a symptom, it tells you which of the three logs (HS2, AM, container) to open first.

flowchart TD
  S[Symptom on Hive console]
  S --> Q1{Did the DAG start running?<br/>i.e. was there a 'Vertex failed'?}
  Q1 -->|No: 'Application failed',<br/>missing file, AM won't start| HS2[Open HS2 log + AM launch diagnostics<br/>usually config/env: tez.lib.uris, queue, ACL]
  Q1 -->|Yes: a vertex/task failed| Q2{Is the cause about<br/>orchestration or a row?}
  Q2 -->|AM-side: OOM in DAGAppMaster,<br/>scheduling, state machine| AM[Open the AM log<br/>container _01_000001]
  Q2 -->|Task-side: exception<br/>processing data| Q3{Do you have the<br/>failing container ID?}
  Q3 -->|Yes| C[yarn logs -containerId that container<br/>the real stack trace]
  Q3 -->|No| AM2[AM log first to find<br/>the failing container ID, then C]

Step 7: A Third Surface — Shuffle Failure (Tez Runtime)

For completeness, the third common shape: a shuffle fetch failure, which is a Tez runtime library surface, not Hive and not submit-time. Container log top of stack (synthesized; verify the class):

java.io.IOException: Failed to fetch shuffle data
        at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.ShuffleScheduler.copyFailed(ShuffleScheduler.java)
        at org.apache.tez.runtime.library.common.shuffle.orderedgrouped.Fetcher.copyFromHost(Fetcher.java)
Caused by: java.net.ConnectException: Connection refused

grep -rln "class ShuffleScheduler" ~/tez-src/tez-runtime-library/src/main/java/
grep -n "shuffle.fetch.failures.limit\|shuffle.connect.timeout" \
  ~/tez-src/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/api/TezRuntimeConfiguration.java

Top actionable frame is org.apache.tez.runtime.library.* → Tez runtime library. The Caused by: ConnectException says the upstream container is gone — so the next hop is that upstream container's log. Whether this is infra (a node died) or a Tez bug (the fetcher gave up too early) depends on tez.runtime.shuffle.fetch.failures.limit and the retry behavior — you attribute it rigorously in H4 and reproduce it deterministically in H5.

Deliverables

• For Failure A: the console message, the parsed-identifier table, the AM-log fragment showing the task transition to FAILED, and the container-log fragment with the full Caused by: chain.
• For Failure B: the console message and the HS2/AM evidence, plus one sentence on why there is no task container log.
• The completed "which log?" decision tree, saved.
• The A-vs-B surface-contrast table, in your own words.
• Verified grep output proving the three diagnostic message templates (Vertex failed, Task failed, TaskAttempt N failed) are real.

Troubleshooting

Stretch Goals

1. Break it at three surfaces on purpose. Reproduce Failure A (runtime), Failure B (submit), and a shuffle failure, and for each name the log you opened first and why.
2. Time the diagnostic walk. From console error to root-cause trace, time yourself. Under ten minutes is the committer standard; write down what slowed you.
3. Trace the diagnostic accumulation. Follow addDiagnostic in DAGImpl to getDiagnostics() and see how the nested string you parsed on the console was built. This is the exact code path you improve in H6.
4. Find the row. In Failure A, confirm the {"a":...} tag in the container log points at the row that broke, and explain which Hive class attaches it.

Validation / Self-check

1. State the one-sentence discipline of this lab, and give the concrete example: what did diagnostics tell you and what did the task log tell you for Failure A?
2. Name the three nested diagnostic templates and the Tez class that emits each. Where on the console do you see them composed?
3. Which YARN container is always the AM, and what does its log contain that a task container's log does not?
4. Failure B produced no task container log. Why? Where is the cause instead?
5. Given "Vertex failed ... while processing row {...}", which log do you open, and given "Application ... failed: File does not exist", which log do you open?
6. A shuffle ConnectException appears in a container log. What is the next hop, and which config value decides whether this is a Tez bug or infrastructure?
7. Walk the Caused by: chain rule: how do you pick the frame that names the owner?

You can now walk any Hive-on-Tez failure from console tip to root cause and know which log holds the answer. Next, Lab H4: Bug Attribution makes the "who owns it" judgment rigorous with real, cross-layer JIRAs.