[
https://issues.apache.org/jira/browse/HADOOP-1022?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Nigel Daley updated HADOOP-1022:
--------------------------------
Attachment: thread.dump.txt
The attached file is the (long) thread dump of the running test.
> 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
> 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 is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
