Uploaded image for project: 'Hadoop Map/Reduce'
  1. Hadoop Map/Reduce
  2. MAPREDUCE-167

SAXParseException causes test to run forever

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Incomplete
    • None
    • None
    • None
    • None

    Description

      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)

      Attachments

        1. thread.dump.txt
          42 kB
          Nigel Daley

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. HADOOP-1036 task gets lost during assignment

          • Critical - Crashes, loss of data, severe memory leak.
          • Closed

          Activity

            People

              Unassigned Unassigned
              nidaley Nigel Daley
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: