You are viewing a plain text version of this content. The canonical link for it is here.
Posted to mapreduce-issues@hadoop.apache.org by "Allen Wittenauer (JIRA)" <ji...@apache.org> on 2014/07/17 18:51:04 UTC
[jira] [Resolved] (MAPREDUCE-167) SAXParseException causes test to
run forever
[ https://issues.apache.org/jira/browse/MAPREDUCE-167?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Allen Wittenauer resolved MAPREDUCE-167.
----------------------------------------
Resolution: Incomplete
I'm going to close this out as stale. I suspect this is no longer an issue.
> SAXParseException causes test to run forever
> --------------------------------------------
>
> Key: MAPREDUCE-167
> URL: https://issues.apache.org/jira/browse/MAPREDUCE-167
> Project: Hadoop Map/Reduce
> Issue Type: Bug
> Reporter: Nigel Daley
> Attachments: thread.dump.txt
>
>
> 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 was sent by Atlassian JIRA
(v6.2#6252)