Logs and debugging

“Job failed.” Now what?

Logs and debugging on YARN

Words you'll meet in this lesson

From our lab (Hadoop 3.5.0, one failed job)

Logs at three levels

Where every log lives

Architecture at a glance

The picture shows both kinds of logs and the path a container log takes after the job ends. Paths are the ones in our lab (Hadoop 3.5.0 Docker image).

The three files every container writes

Symptom → where to look (failures we met in this course)

Animated example: 2 AM, the payments report is late

From FAILED to the bad record, on our cluster

We run the revenue job from Lesson 8.1 on the messy file from Lesson 8.3. ItemRevenue skips lines with the wrong number of fields, but it has no check for a bad amount. The whole session is logs_lab.sh in “Run it on your PC”.

1. Read what the client says

   hadoop jar mr.jar ItemRevenue /user/hadoop/data/dirty_orders.csv /out/dbg

   Error: java.lang.NumberFormatException: For input string: "abc" Failed map tasks=10 Job job_1792655556966_0006 failed with state FAILED due to: Task failed task_1792655556966_0006_m_000001 Task Id : attempt_1792655556966_0006_m_000000_0, Status : FAILED Task Id : attempt_1792655556966_0006_m_000000_1, Status : FAILED Task Id : attempt_1792655556966_0006_m_000000_2, Status : FAILED
   Each failed attempt is retried (up to 4 per task). Ten failed attempts and one task that used up all its tries ended the job. The client prints only the first line of each error.

2. Ask the ResourceManager

   yarn application -status application_1792655556966_0006

   State : FINISHED Final-State : FAILED Tracking-URL : http://historyserver:19888/jobhistory/job/job_1792655556966_0006 Diagnostics : Task failed task_1792655556966_0006_m_000001 Job failed as tasks failed. failedMaps:1 failedReduces:0 killedMaps:0 killedReduces: 0
   State FINISHED but Final-State FAILED: YARN ran the application to its end; the application itself reports failure. The tracking URL now points to the JobHistory Server.

3. See which containers left logs

   yarn logs -applicationId application_1792655556966_0006 -show_application_log_info
   hdfs dfs -ls -R /tmp/logs/hadoop | grep application_1792655556966_0006

   Application State: Completed. Container: container_1792655556966_0006_01_000006 on worker1_36427 Container: container_1792655556966_0006_01_000010 on worker1_36427 Container: container_1792655556966_0006_01_000005 on worker2_40977 … 108540 /tmp/logs/hadoop/bucket-logs-tfile/0006/application_1792655556966_0006/worker1_36427 142851 /tmp/logs/hadoop/bucket-logs-tfile/0006/application_1792655556966_0006/worker2_40977
   Log aggregation packed all containers of this app from one node into one HDFS file. No need to log in to any worker.

4. Read the failed attempt's syslog

   yarn logs -applicationId application_1792655556966_0006 \
     -containerId container_1792655556966_0006_01_000002 -log_files syslog

   WARN [main] org.apache.hadoop.mapred.YarnChild: Exception running child : java.lang.NumberFormatException: For input string: "abc" at java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:67) at ItemRevenue$OrderMapper.map(ItemRevenue.java:27) at ItemRevenue$OrderMapper.map(ItemRevenue.java:18)
   Read the stack trace from the top and stop at the first line that is your code: ItemRevenue.java:27, the Integer.parseInt(f[2]) line.

5. Find the record

   hdfs dfs -cat /user/hadoop/data/dirty_orders.csv | grep -n -m3 ",abc$"

   1715:901714,chai,abc 6142:906141,chai,abc 6433:906432,chai,abc
   The exception message gave the bad value, so a search finds it. In a huge file, use the split range from the syslog to search only that part.

6. Check the ApplicationMaster's view

   yarn logs -applicationId application_1792655556966_0006 -am 1 -log_files syslog | grep -E "Job failed|JOB_FAILED|diagnostics"

   JobImpl: Job failed as tasks failed. failedMaps:1 failedReduces:0 killedMaps:0 killedRedu… JobHistoryEventHandler: In stop, writing event JOB_FAILED RMCommunicator: Setting job diagnostics to Task failed task_1792655556966_0006_m_000001
   The AM decided the job had failed, wrote the JOB_FAILED event for the JobHistory Server and sent the diagnostics we saw in step 2. If the AM itself crashes, this is the log to read.

7. Turn up the detail when you need it

   hadoop jar mr.jar ItemRevenue -D mapreduce.map.log.level=DEBUG /user/hadoop/data/canteen_orders.csv /out/lvl

   map.log.level=INFO: map container syslog has 82 lines map.log.level=DEBUG: map container syslog has 2134 lines
   26 times more lines from one small map task. DEBUG is useful for one run; left on for a production job, it fills disks and the HDFS log directory.

Following the logs of one failed job

Six steps through our lab's failed job: what you type, and where YARN gets the answer from.

Logs at work

Simplified; organisations differ in tools and policies. Scenario details are illustrative.

Find the first exception in a log

These are real lines from our failed job's client output and map syslog. The parser finds the failed attempts, the first exception, and the first stack frame that is our code rather than Java or Hadoop.

log = """Task Id : attempt_1792655556966_0006_m_000000_0, Status : FAILED
Error: java.lang.NumberFormatException: For input string: "abc"
Task Id : attempt_1792655556966_0006_m_000000_1, Status : FAILED
Task Id : attempt_1792655556966_0006_m_000000_2, Status : FAILED
WARN [main] org.apache.hadoop.mapred.YarnChild: Exception running child : java.lang.NumberFormatException: For input string: "abc"
\tat java.base/java.lang.NumberFormatException.forInputString(NumberFormatException.java:67)
\tat ItemRevenue$OrderMapper.map(ItemRevenue.java:27)
\tat ItemRevenue$OrderMapper.map(ItemRevenue.java:18)"""

FRAMEWORK = ("java.", "javax.", "org.apache.hadoop.", "sun.", "jdk.")
attempts, exception, user_frame = [], None, None
for line in log.splitlines():
    if line.startswith("Task Id :") and "FAILED" in line:
        attempts.append(line.split()[3].rstrip(","))
    if exception is None and "Exception" in line and ":" in line and not line.strip().startswith("at "):
        exception = line[line.find("java."):]
    s = line.strip()
    if s.startswith("at ") and user_frame is None:
        method = s[3:]
        if not method.startswith(FRAMEWORK):
            user_frame = method
print("failed attempts:", len(attempts), attempts[-1])
print("exception      :", exception)
print("your code      :", user_frame)

• FRAMEWORK = ("java.", "javax.", "org.apache.hadoop.", "sun.", "jdk.")Frames from Java and Hadoop tell you where the error surfaced; the first frame from your own classes tells you what to fix.
• if exception is None and "Exception" in line and ":" in line and not line.strip().startswith("at "):Read the FIRST exception. Later ones are often consequences (a task failing, then the job failing).
• if not method.startswith(FRAMEWORK):The first frame from our own code: class ItemRevenue$OrderMapper, method map, file ItemRevenue.java, line 27.

Run it on your PC: fail a job on purpose and debug it

Use the Module 8 lab cluster with log aggregation on (it is in the lab config: yarn.log-aggregation-enable=true). The script needs mr.jar from Lesson 8.1 and dirty_orders.csv from Lesson 8.3 in HDFS. Copy it into the namenode container and run it there; it takes about two minutes.

# logs_lab.sh: a job fails on bad data. Find out why, using only YARN's logs and tools.
# Run inside the namenode container (in /tmp/mr). ItemRevenue (Lesson 8.1) has no check for a bad amount.
cd /tmp/mr
hdfs dfs -rm -r -f -skipTrash /out/dbg > /dev/null 2>&1
echo "== 1. the client only says it failed"
hadoop jar mr.jar ItemRevenue /user/hadoop/data/dirty_orders.csv /out/dbg > /tmp/dbg.log 2>&1
grep -E "Task Id|^Error|failed with state|Failed map tasks" /tmp/dbg.log | sed -E 's/^[0-9-]+ [0-9:]+ INFO  //' | sort -u | head -6 | cut -c1-160
app=$(grep -o "application_[0-9_]*" /tmp/dbg.log | head -1)
echo "== 2. what the ResourceManager remembers"
yarn application -status $app 2>/dev/null | grep -E "State|Final-State|Diagnostics" -A1 | grep -v "^--" | sed 's/^\s*//' | head -6
echo "== 3. aggregated logs: which containers left logs?"
sleep 8
yarn logs -applicationId $app -show_application_log_info 2>/dev/null | grep -E "Container|Application State" | head -8
echo "-- they live in HDFS now:"
hdfs dfs -ls -R /tmp/logs/hadoop 2>/dev/null | grep $app | awk '{print $5, $8}' | head -3
echo "== 4. the failed attempt's syslog: the real exception with a line number"
c=$(yarn logs -applicationId $app -show_application_log_info 2>/dev/null | grep -o "container_[0-9_]*_000002" | head -1)
yarn logs -applicationId $app -containerId $c -log_files syslog 2>/dev/null | grep -E -A4 "^java.lang|Exception" | grep -E "Exception|at ItemRevenue|at org.apache.hadoop.mapred.MapTask.run" | head -4 | cut -c1-160
echo "== 5. which line of input? (search the data for the bad value)"
hdfs dfs -cat /user/hadoop/data/dirty_orders.csv | grep -n -m3 ",abc$" 2>/dev/null
echo "== 6. the ApplicationMaster's own log (-am 1)"
yarn logs -applicationId $app -am 1 -log_files syslog 2>/dev/null | grep -E "Task failed|failedMaps|JOB_FAILED|Job failed" | sed -E 's/^[0-9-]+ [0-9:,]+ //' | head -3 | cut -c1-170
echo "== 7. more detail: the same job with DEBUG logging in the map tasks"
for lvl in INFO DEBUG; do
  hdfs dfs -rm -r -f -skipTrash /out/lvl > /dev/null 2>&1
  hadoop jar mr.jar ItemRevenue -D mapreduce.map.log.level=$lvl /user/hadoop/data/canteen_orders.csv /out/lvl > /tmp/lvl.log 2>&1
  a=$(grep -o "application_[0-9_]*" /tmp/lvl.log | head -1); sleep 8
  m=$(yarn logs -applicationId $a -show_application_log_info 2>/dev/null | grep -o "container_[0-9_]*_000002" | head -1)
  echo "map.log.level=$lvl: map container syslog has $(yarn logs -applicationId $a -containerId $m -log_files syslog 2>/dev/null | wc -l) lines"
done

# In the mr-lab folder:
#   docker cp logs_lab.sh lab8-namenode-1:/tmp/mr/
#   docker exec lab8-namenode-1 bash /tmp/mr/logs_lab.sh

# attempts.sh JOB_ID : every task attempt of a finished job (node, time, state), from the JobHistory REST API
J=$1; ID=${J#job_}
for kind in m r; do
  for t in $(curl -s http://historyserver:19888/ws/v1/history/mapreduce/jobs/$J/tasks | grep -o "task_${ID}_${kind}_[0-9]*" | sort -u); do
    curl -s http://historyserver:19888/ws/v1/history/mapreduce/jobs/$J/tasks/$t/attempts | python3 -c '
import sys, json
t = json.load(sys.stdin)["taskAttempts"]["taskAttempt"]
for a in (t if isinstance(t, list) else [t]):
    node = a["nodeHttpAddress"].split(":")[0]
    print("%-40s %-9s %-8s %5.1f s  %s" % (a["id"], a["state"], node, a["elapsedTime"] / 1000, a.get("diagnostics", "")[:70]))'
  done
done

# Inside the namenode container:
#   bash attempts.sh job_<your failed job id>

Reading a stack trace from the top

A stack trace lists the calls that were active when the exception happened, newest first. Skip the library frames until you reach your own code.

Worked examples: real problems, solved and traced in memory

Four debugging problems from different domains: a stack trace, log retention, finding a bad record in a big file, and choosing a log level.

4 stack frames

open: SaleMapper.java:41 | error: Index 5 out of bounds for length 5

120 GB/day · replication 3 · 10 TB

360 GB raw per day -> keep 28 days -> retain-seconds = 2419200

start 268,435,456 · length 134,217,728 · 1.2 TB

part-0412.csv: bytes 268,435,456 to 402,653,184 (128 MB)
that is 0.010% of the input

2,000 maps · 82 vs 2,134 lines

whole job at DEBUG : 4,268,000 lines
one split at DEBUG : 2,134 lines (plus the normal run at INFO: 164,000)

Check yourself

Quick revision

Interview and viva questions

Practice problems

Debugging exercises using the real outputs from our failed job and earlier lessons.

10 failed · 4 per task

6 failed attempts belonged to other tasks (they were still retrying when the job stopped)

print(10 - 4, "failed attempts belonged to other tasks (they were still retrying when the job stopped)")

108,540 and 142,851 bytes

251,391 bytes for one small failed job

print(f"{108540 + 142851:,} bytes for one small failed job")

82 vs 2,134 lines

26.0 times

print(round(2134 / 82, 1), "times")

Processing split: hdfs://namenode/user/hadoop/data/dirty_orders.csv:2097152+2097152

dirty_orders.csv 2097152 4194303

line = "Processing split: hdfs://namenode/user/hadoop/data/dirty_orders.csv:2097152+2097152"
path, rng = line.split(": ")[1].rsplit(":", 1)
start, length = map(int, rng.split("+"))
print(path.split("/")[-1], start, start + length - 1)

5 lines

3 901714,chai,abc
4 1004,samosa,-18

lines = ["1001,chai,15", "1002,dosa,45", "901714,chai,abc", "1004,samosa,-18", "1005,poha,25"]
for n, l in enumerate(lines, 1):
    amount = l.split(",")[2]
    if not amount.isdigit() or int(amount) <= 0:
        print(n, l)

5 diagnostics

4 NumberFormatException: abc
1 Java heap space

diags = ["NumberFormatException: abc", "NumberFormatException: abc", "Java heap space",
         "NumberFormatException: abc", "NumberFormatException: abc"]
from collections import Counter
for msg, n in Counter(diags).most_common():
    print(n, msg)

06:00 deadline · 2.5 h rerun · 40 min vs 2 h

yarn logs         latest failure 02:50
worker by worker  latest failure 01:30

from datetime import datetime, timedelta
deadline = datetime(2026, 10, 22, 6, 0)
for name, debug in [("yarn logs", 40), ("worker by worker", 120)]:
    print(f"{name:17} latest failure {(deadline - timedelta(minutes=150 + debug)):%H:%M}")

180 GB/day · 12 TB budget

replication 3: 22 days, yarn.log-aggregation.retain-seconds=1900800
replication 2: 34 days, yarn.log-aggregation.retain-seconds=2937600

per_day_gb, budget_tb = 180, 12
for rep in (3, 2):
    days = int(budget_tb * 1024 // (per_day_gb * rep))
    print(f"replication {rep}: {days} days, yarn.log-aggregation.retain-seconds={days * 86400}")

Real-world scenario questions (asked in company interviews)

Debugging questions test whether you have actually run jobs on a cluster. Interviewers want an order of steps, not guesses.