hadoop-common-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Nigel Daley (JIRA)" <j...@apache.org>
Subject [jira] Updated: (HADOOP-1022) SAXParseException causes test to run forever
Date Wed, 14 Feb 2007 23:43:07 GMT

     [ 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.


Mime
View raw message