SAXParseException causes test to run forever
--------------------------------------------
Key: HADOOP-1022
URL: https://issues.apache.org/jira/browse/HADOOP-1022
Project: Hadoop
Issue Type: Bug
Components: mapred
Affects Versions: 0.11.1
Reporter: Nigel Daley
Occassionally, while running TestMiniMRClasspath, I get a SAXParseException
that causes the test to run forever. Two questions I have:
1) what is the underlying cause of the SAXParseException?
2) does the JobTracker realize that a task got lost?
Here's the pertinent test trace:
[junit] 2007-02-13 19:26:56,058 INFO mapred.JobClient
(JobClient.java:runJob(400)) - Running job: job_0001
[junit] 2007-02-13 19:26:57,062 INFO mapred.JobClient
(JobClient.java:runJob(417)) - map 0% reduce 0%
[junit] 2007-02-13 19:27:05,258 INFO mapred.JobInProgress
(JobInProgress.java:findNewTask(421)) - Choosing cached task tip_0001_m_000000
[junit] 2007-02-13 19:27:05,259 INFO mapred.JobTracker
(JobTracker.java:createTaskEntry(690)) - Adding task 'task_0001_m_000000_0' to
tip tip_0001_m_000000, for tracker 'tracker_ucdev15.yst.corp.yahoo.com:50067'
[junit] 2007-02-13 19:27:05,260 INFO mapred.JobInProgress
(JobInProgress.java:findNewTask(421)) - Choosing cached task tip_0001_m_000001
[junit] 2007-02-13 19:27:05,261 INFO mapred.JobTracker
(JobTracker.java:createTaskEntry(690)) - Adding task 'task_0001_m_000001_0' to
tip tip_0001_m_000001, for tracker 'tracker_ucdev15.yst.corp.yahoo.com:50063'
[junit] 2007-02-13 19:27:05,262 INFO mapred.TaskTracker
(TaskTracker.java:startNewTask(822)) - LaunchTaskAction: task_0001_m_000000_0
[junit] 2007-02-13 19:27:05,262 INFO mapred.JobInProgress
(JobInProgress.java:findNewTask(421)) - Choosing cached task tip_0001_m_000002
[junit] 2007-02-13 19:27:05,263 INFO mapred.JobTracker
(JobTracker.java:createTaskEntry(690)) - Adding task 'task_0001_m_000002_0' to
tip tip_0001_m_000002, for tracker 'tracker_ucdev15.yst.corp.yahoo.com:50066'
[junit] 2007-02-13 19:27:05,263 INFO mapred.TaskTracker
(TaskTracker.java:startNewTask(822)) - LaunchTaskAction: task_0001_m_000001_0
[junit] 2007-02-13 19:27:05,267 INFO mapred.TaskTracker
(TaskTracker.java:startNewTask(822)) - LaunchTaskAction: task_0001_m_000002_0
[junit] 2007-02-13 19:27:05,270 INFO mapred.JobInProgress
(JobInProgress.java:findNewTask(453)) - Choosing normal task tip_0001_r_000000
[junit] 2007-02-13 19:27:05,270 INFO mapred.JobTracker
(JobTracker.java:createTaskEntry(690)) - Adding task 'task_0001_r_000000_0' to
tip tip_0001_r_000000, for tracker 'tracker_ucdev15.yst.corp.yahoo.com:50062'
[junit] 2007-02-13 19:27:05,271 INFO mapred.TaskTracker
(TaskTracker.java:startNewTask(822)) - LaunchTaskAction: task_0001_r_000000_0
[junit] 2007-02-13 19:27:05,285 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_-4805938806139473507 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,289 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_-4805938806139473507 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,292 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_-4805938806139473507 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,295 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_-4805938806139473507 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,312 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_3019208026182045172 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,312 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_3019208026182045172 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,352 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_-1390246588917827761 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,355 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_-1390246588917827761 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,367 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_4739954315939188869 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,368 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_3019208026182045172 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,367 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_4739954315939188869 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,416 FATAL conf.Configuration
(Configuration.java:loadResource(552)) - error parsing conf file:
org.xml.sax.SAXParseException: Premature end of file.
[junit] 2007-02-13 19:27:05,417 ERROR mapred.TaskTracker
(TaskTracker.java:offerService(535)) - Caught exception:
java.lang.RuntimeException: org.xml.sax.SAXParseException: Premature end of
file.
[junit] at
org.apache.hadoop.conf.Configuration.loadResource(Configuration.java:553)
[junit] at
org.apache.hadoop.conf.Configuration.loadResources(Configuration.java:472)
[junit] at
org.apache.hadoop.conf.Configuration.getProps(Configuration.java:453)
[junit] at
org.apache.hadoop.conf.Configuration.get(Configuration.java:201)
[junit] at org.apache.hadoop.mapred.JobConf.getJar(JobConf.java:112)
[junit] at
org.apache.hadoop.mapred.TaskTracker.localizeJob(TaskTracker.java:332)
[junit] at
org.apache.hadoop.mapred.TaskTracker.startNewTask(TaskTracker.java:835)
[junit] at
org.apache.hadoop.mapred.TaskTracker.offerService(TaskTracker.java:509)
[junit] at
org.apache.hadoop.mapred.TaskTracker.run(TaskTracker.java:864)
[junit] at
org.apache.hadoop.mapred.MiniMRCluster$TaskTrackerRunner.run(MiniMRCluster.java:130)
[junit] at java.lang.Thread.run(Thread.java:595)
[junit] Caused by: org.xml.sax.SAXParseException: Premature end of file.
[junit] at
com.sun.org.apache.xerces.internal.parsers.DOMParser.parse(DOMParser.java:264)
[junit] at
com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.parse(DocumentBuilderImpl.java:292)
[junit] at
javax.xml.parsers.DocumentBuilder.parse(DocumentBuilder.java:98)
[junit] at
org.apache.hadoop.conf.Configuration.loadResource(Configuration.java:510)
[junit] ... 10 more
[junit] [Fatal Error] :-1:-1: Premature end of file.
[junit] 2007-02-13 19:27:05,423 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_3019208026182045172 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,444 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_-1390246588917827761 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,453 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_4739954315939188869 to
/66.228.166.95
[junit] 2007-02-13 19:27:05,638 INFO dfs.DistributedFileSystem
(InMemoryFileSystem.java:initialize(69)) - Initialized InMemoryFileSystem:
ramfs://mapoutput8574467 of size (in bytes): 78643200
[junit] 2007-02-13 19:27:05,639 INFO mapred.TaskRunner
(ReduceTaskRunner.java:<init>(380)) - task_0001_r_000000_0 Created an
InMemoryFileSystem, uri: ramfs://mapoutput8574467
[junit] 2007-02-13 19:27:05,733 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(446)) - task_0001_r_000000_0 Need 3 map output(s)
[junit] 2007-02-13 19:27:05,733 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(450)) - task_0001_r_000000_0 Need 3 map output
location(s)
[junit] 2007-02-13 19:27:05,735 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(461)) - task_0001_r_000000_0 Got 0 map outputs
from jobtracker
[junit] 2007-02-13 19:27:05,735 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(476)) - task_0001_r_000000_0 Got 0 known map
output location(s); scheduling...
[junit] 2007-02-13 19:27:05,736 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(505)) - task_0001_r_000000_0 Scheduled 0 of 0
known outputs (0 slow hosts and 0 dup hosts)
[junit] 2007-02-13 19:27:05,736 INFO mapred.TaskRunner
(ReduceTaskRunner.java:run(162)) - task_0001_r_000000_0 Started thread: Map
output copy reporter for task task_0001_r_000000_0
[junit] 2007-02-13 19:27:06,741 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.0% reduce >
copy >
[junit] 2007-02-13 19:27:06,957 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_2428305120985131059 to
/66.228.166.95
[junit] 2007-02-13 19:27:06,959 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_6899441376756315813 to
/66.228.166.95
[junit] 2007-02-13 19:27:07,216 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_m_000002_0 0.0%
hdfs://localhost:65314/testing/ext/input/part-0:20+10
[junit] 2007-02-13 19:27:07,218 INFO mapred.TaskTracker
(TaskTracker.java:reportDone(1062)) - Task task_0001_m_000002_0 is done.
[junit] 2007-02-13 19:27:07,267 INFO mapred.JobInProgress
(JobInProgress.java:completedTask(496)) - Task 'task_0001_m_000002_0' has
completed tip_0001_m_000002 successfully.
[junit] 2007-02-13 19:27:07,267 INFO mapred.TaskInProgress
(TaskInProgress.java:completedTask(379)) - Task 'task_0001_m_000002_0' has
completed.
[junit] 2007-02-13 19:27:07,470 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_2428305120985131059 to
/66.228.166.95
[junit] 2007-02-13 19:27:07,503 INFO dfs.DataNode
(DataNode.java:readBlock(719)) - Served block blk_6899441376756315813 to
/66.228.166.95
[junit] 2007-02-13 19:27:07,744 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.0% reduce >
copy >
[junit] 2007-02-13 19:27:07,805 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_m_000000_0 1.0%
hdfs://localhost:65314/testing/ext/input/part-0:0+10
[junit] 2007-02-13 19:27:07,807 INFO mapred.TaskTracker
(TaskTracker.java:reportDone(1062)) - Task task_0001_m_000000_0 is done.
[junit] 2007-02-13 19:27:07,817 INFO mapred.JobInProgress
(JobInProgress.java:completedTask(496)) - Task 'task_0001_m_000000_0' has
completed tip_0001_m_000000 successfully.
[junit] 2007-02-13 19:27:07,818 INFO mapred.TaskInProgress
(TaskInProgress.java:completedTask(379)) - Task 'task_0001_m_000000_0' has
completed.
[junit] 2007-02-13 19:27:08,111 INFO mapred.JobClient
(JobClient.java:runJob(417)) - map 66% reduce 0%
[junit] 2007-02-13 19:27:08,746 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.0% reduce >
copy >
[junit] 2007-02-13 19:27:09,748 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.0% reduce >
copy >
[junit] 2007-02-13 19:27:10,736 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(446)) - task_0001_r_000000_0 Need 3 map output(s)
[junit] 2007-02-13 19:27:10,737 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(450)) - task_0001_r_000000_0 Need 3 map output
location(s)
[junit] 2007-02-13 19:27:10,738 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(461)) - task_0001_r_000000_0 Got 2 map outputs
from jobtracker
[junit] 2007-02-13 19:27:10,738 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(476)) - task_0001_r_000000_0 Got 2 known map
output location(s); scheduling...
[junit] 2007-02-13 19:27:10,738 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(505)) - task_0001_r_000000_0 Scheduled 1 of 2
known outputs (0 slow hosts and 1 dup hosts)
[junit] 2007-02-13 19:27:10,738 INFO mapred.TaskRunner
(ReduceTaskRunner.java:copyOutput(278)) - task_0001_r_000000_0 Copying
task_0001_m_000000_0 output from ucdev15.yst.corp.yahoo.com.
[junit] 2007-02-13 19:27:10,750 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.0% reduce >
copy >
[junit] 2007-02-13 19:27:10,756 INFO mapred.TaskRunner
(ReduceTaskRunner.java:copyOutput(304)) - task_0001_r_000000_0 done copying
task_0001_m_000000_0 output from ucdev15.yst.corp.yahoo.com.
[junit] 2007-02-13 19:27:10,757 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(446)) - task_0001_r_000000_0 Need 2 map output(s)
[junit] 2007-02-13 19:27:10,757 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(450)) - task_0001_r_000000_0 Need 1 map output
location(s)
[junit] 2007-02-13 19:27:11,752 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.11111112%
reduce > copy (1 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:12,755 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.11111112%
reduce > copy (1 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:13,757 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.11111112%
reduce > copy (1 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:14,760 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.11111112%
reduce > copy (1 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:15,738 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(461)) - task_0001_r_000000_0 Got 0 map outputs
from jobtracker
[junit] 2007-02-13 19:27:15,739 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(476)) - task_0001_r_000000_0 Got 1 known map
output location(s); scheduling...
[junit] 2007-02-13 19:27:15,739 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(505)) - task_0001_r_000000_0 Scheduled 1 of 1
known outputs (0 slow hosts and 0 dup hosts)
[junit] 2007-02-13 19:27:15,739 INFO mapred.TaskRunner
(ReduceTaskRunner.java:copyOutput(278)) - task_0001_r_000000_0 Copying
task_0001_m_000002_0 output from ucdev15.yst.corp.yahoo.com.
[junit] 2007-02-13 19:27:15,753 INFO mapred.TaskRunner
(ReduceTaskRunner.java:copyOutput(304)) - task_0001_r_000000_0 done copying
task_0001_m_000002_0 output from ucdev15.yst.corp.yahoo.com.
[junit] 2007-02-13 19:27:15,754 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(446)) - task_0001_r_000000_0 Need 1 map output(s)
[junit] 2007-02-13 19:27:15,754 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(450)) - task_0001_r_000000_0 Need 1 map output
location(s)
[junit] 2007-02-13 19:27:15,762 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.22222224%
reduce > copy (2 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:16,145 INFO mapred.JobClient
(JobClient.java:runJob(417)) - map 66% reduce 11%
[junit] 2007-02-13 19:27:16,764 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.22222224%
reduce > copy (2 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:17,766 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.22222224%
reduce > copy (2 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:18,768 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.22222224%
reduce > copy (2 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:19,770 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.22222224%
reduce > copy (2 of 3 at 0.00 MB/s) >
And then this log snippet is repeated forever:
[junit] 2007-02-13 19:27:20,740 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(461)) - task_0001_r_000000_0 Got 0 map outputs
from jobtracker
[junit] 2007-02-13 19:27:20,740 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(476)) - task_0001_r_000000_0 Got 0 known map
output location(s); scheduling...
[junit] 2007-02-13 19:27:20,740 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(505)) - task_0001_r_000000_0 Scheduled 0 of 0
known outputs (0 slow hosts and 0 dup hosts)
[junit] 2007-02-13 19:27:20,772 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.22222224%
reduce > copy (2 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:21,775 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.22222224%
reduce > copy (2 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:22,777 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.22222224%
reduce > copy (2 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:23,779 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.22222224%
reduce > copy (2 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:24,781 INFO mapred.TaskTracker
(TaskTracker.java:reportProgress(1013)) - task_0001_r_000000_0 0.22222224%
reduce > copy (2 of 3 at 0.00 MB/s) >
[junit] 2007-02-13 19:27:25,742 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(446)) - task_0001_r_000000_0 Need 1 map output(s)
[junit] 2007-02-13 19:27:25,742 INFO mapred.TaskRunner
(ReduceTaskRunner.java:prepare(450)) - task_0001_r_000000_0 Need 1 map output
location(s)
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
