Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 1.5.0
    • Component/s: None
    • Labels:
      None
    • Environment:

      MacOSX, Hadoop 1.0.3, zookeeper 3.3.3

      Description

      I shut my machine down with Accumulo, Zookeeper, and HDFS running. When I restarted it, Accumulo failed to recover its write ahead log because it was zero length. I wondered if this was because I shutdown HDFS so I tried the following on my single node Accumulo instance.

      • start HDFS and zookeeper
      • init & start Accumulo
      • created a table and insert some data
      • pkill -f java
      • restart everything
      • Accumulo fails to start because walog is zero length

      Saw excpetions like the following

      06 18:58:44,581 [log.SortedLogRecovery] INFO : Looking at mutations from /accumulo/recovery/def72721-5c64-4755-87cc-2e8cfc3002b7 for !0;!0<<
      06 18:58:44,590 [tabletserver.TabletServer] WARN : exception trying to assign tablet !0;!0<< /root_tablet
      java.lang.RuntimeException: java.io.IOException: java.lang.RuntimeException: Unable to read log entries
              at org.apache.accumulo.server.tabletserver.Tablet.<init>(Tablet.java:1458)
              at org.apache.accumulo.server.tabletserver.Tablet.<init>(Tablet.java:1295)
              at org.apache.accumulo.server.tabletserver.Tablet.<init>(Tablet.java:1134)
              at org.apache.accumulo.server.tabletserver.Tablet.<init>(Tablet.java:1121)
              at org.apache.accumulo.server.tabletserver.TabletServer$AssignmentHandler.run(TabletServer.java:2477)
              at org.apache.accumulo.core.util.LoggingRunnable.run(LoggingRunnable.java:34)
              at java.lang.Thread.run(Thread.java:680)
      Caused by: java.io.IOException: java.lang.RuntimeException: Unable to read log entries
              at org.apache.accumulo.server.tabletserver.log.TabletServerLogger.recover(TabletServerLogger.java:428)
              at org.apache.accumulo.server.tabletserver.TabletServer.recover(TabletServer.java:3206)
              at org.apache.accumulo.server.tabletserver.Tablet.<init>(Tablet.java:1426)
              ... 6 more
      Caused by: java.lang.RuntimeException: Unable to read log entries
              at org.apache.accumulo.server.tabletserver.log.SortedLogRecovery.findLastStartToFinish(SortedLogRecovery.java:125)
              at org.apache.accumulo.server.tabletserver.log.SortedLogRecovery.recover(SortedLogRecovery.java:89)
              at org.apache.accumulo.server.tabletserver.log.TabletServerLogger.recover(TabletServerLogger.java:426)
              ... 8 more
      
      

      When trying to run LogReader on the files, it prints nothing.

      $ ./bin/accumulo org.apache.accumulo.server.logger.LogReader /accumulo/recovery/def72721-5c64-4755-87cc-2e8cfc3002b7
      06 19:04:37,147 [util.NativeCodeLoader] WARN : Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
      $ ./bin/accumulo org.apache.accumulo.server.logger.LogReader /accumulo/wal/127.0.0.1+40200/def72721-5c64-4755-87cc-2e8cfc3002b7
      $ 
      

        Activity

        Hide
        Josh Elser added a comment -

        Interesting, I added some messages in TabletServer to dump those variables on my instance: 'dfs.durable.sync'=false and 'dfs.support.append'=true. I have neither set in my config files.

        Cloudera's site (https://ccp.cloudera.com/display/CDHDOC/Incompatible+Changes) states that starting in CDH3u4 dfs.support.append is true by default. Given that I'm on CDH3u3, apparently that's a little off or I stumbled upon tlipcon's magic pixie dust

        Show
        Josh Elser added a comment - Interesting, I added some messages in TabletServer to dump those variables on my instance: 'dfs.durable.sync'=false and 'dfs.support.append'=true. I have neither set in my config files. Cloudera's site ( https://ccp.cloudera.com/display/CDHDOC/Incompatible+Changes ) states that starting in CDH3u4 dfs.support.append is true by default. Given that I'm on CDH3u3, apparently that's a little off or I stumbled upon tlipcon's magic pixie dust
        Hide
        Keith Turner added a comment -

        John V and I were discussing this, one possibility is that a tserver will only start if dfs.durable.sync OR dfs.support.append is set to true. This is kinda screwy because at some point the property dfs.support.append (which defaults to false) will go away and the property dfs.durable.sync will appear (which defaults to true). However, I do not think there is a way to determine what a property defaults to in HAdoop, because this is just hardcoded into code that uses the prop. So a user would need to explicitly set dfs.durable.sync to true in their config even though this is the default. See HADOOP-8365.

        Show
        Keith Turner added a comment - John V and I were discussing this, one possibility is that a tserver will only start if dfs.durable.sync OR dfs.support.append is set to true. This is kinda screwy because at some point the property dfs.support.append (which defaults to false) will go away and the property dfs.durable.sync will appear (which defaults to true). However, I do not think there is a way to determine what a property defaults to in HAdoop, because this is just hardcoded into code that uses the prop. So a user would need to explicitly set dfs.durable.sync to true in their config even though this is the default. See HADOOP-8365 .
        Hide
        Keith Turner added a comment -
        Show
        Keith Turner added a comment - see HADOOP-8230
        Hide
        Keith Turner added a comment -

        I was doing some research looking for HDFS issues, turns out I just need to set dfs.support.append to true in hdfs-site.xml. After doing this, the previous two scenarios that failed to recover now work. This needs to be documented in the README. Since the consequences of not setting this property are so severe, maybe tablet servers and the master should refuse to start unless it is set to true.

        The property seems kinda screwy. It enables append which is broken, but also enables sync.

        Show
        Keith Turner added a comment - I was doing some research looking for HDFS issues, turns out I just need to set dfs.support.append to true in hdfs-site.xml. After doing this, the previous two scenarios that failed to recover now work. This needs to be documented in the README. Since the consequences of not setting this property are so severe, maybe tablet servers and the master should refuse to start unless it is set to true. The property seems kinda screwy. It enables append which is broken, but also enables sync.
        Hide
        Keith Turner added a comment -

        Did the following experiment killing the namenode. In this case recovery succeeds.

        • start HDFS and zookeeper
        • init & start Accumulo
        • created a table and insert some data
        • kill name node
        • kill all accumulo processes
        • restart namenode
        • restart accumulo
        • recovery succeeds
        Show
        Keith Turner added a comment - Did the following experiment killing the namenode. In this case recovery succeeds. start HDFS and zookeeper init & start Accumulo created a table and insert some data kill name node kill all accumulo processes restart namenode restart accumulo recovery succeeds
        Hide
        Keith Turner added a comment - - edited

        I tried another experiment. Instead of killing all java processes on my single node instance, I did the following.

        • start HDFS and zookeeper
        • init & start Accumulo
        • created a table and insert some data
        • kill data node
        • kill all accumulo processes
        • restart datanode
        • restart accumulo
        • recovery fails

        Under this scenario recovery fails differently. The following is from the tablet server logs, I get an NPE in hdfs client code.

        14 16:26:17,253 [log.LogSorter] INFO : Zookeeper references 1 recoveries, attempting locks14 16:26:17,254 [log.LogSorter] DEBUG: Attempting to lock b67eb806-6ef1-4ecc-b739-a4ee90e08086
        14 16:26:17,262 [log.LogSorter] INFO : got lock for b67eb806-6ef1-4ecc-b739-a4ee90e08086
        14 16:26:17,264 [log.LogSorter] INFO : Copying /accumulo/wal/127.0.0.1+40200/b67eb806-6ef1-4ecc-b739-a4ee90e08086 to /accumulo/recovery/b67eb806-6ef1-4ecc-b739-a4ee90e08086
        14 16:26:17,300 [log.LogSorter] ERROR: Unexpected error
        java.lang.NullPointerException
                at org.apache.hadoop.hdfs.DFSClient$DFSInputStream.updateBlockInfo(DFSClient.java:1885)
                at org.apache.hadoop.hdfs.DFSClient$DFSInputStream.openInfo(DFSClient.java:1858)        at org.apache.hadoop.hdfs.DFSClient$DFSInputStream.<init>(DFSClient.java:1834)
                at org.apache.hadoop.hdfs.DFSClient.open(DFSClient.java:578)        at org.apache.hadoop.hdfs.DistributedFileSystem.open(DistributedFileSystem.java:154)
                at org.apache.hadoop.fs.FileSystem.open(FileSystem.java:427)
                at org.apache.accumulo.server.tabletserver.log.LogSorter.startSort(LogSorter.java:295)
                at org.apache.accumulo.server.tabletserver.log.LogSorter.attemptRecoveries(LogSorter.java:266)
                at org.apache.accumulo.server.tabletserver.log.LogSorter.access$200(LogSorter.java:60)
                at org.apache.accumulo.server.tabletserver.log.LogSorter$1.process(LogSorter.java:204)
                at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:530)        at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:506)
        
        

        An update, if I kill accumulo after this and restart HDFS, then I am back to the first problem of a zero length walog file.

        Show
        Keith Turner added a comment - - edited I tried another experiment. Instead of killing all java processes on my single node instance, I did the following. start HDFS and zookeeper init & start Accumulo created a table and insert some data kill data node kill all accumulo processes restart datanode restart accumulo recovery fails Under this scenario recovery fails differently. The following is from the tablet server logs, I get an NPE in hdfs client code. 14 16:26:17,253 [log.LogSorter] INFO : Zookeeper references 1 recoveries, attempting locks14 16:26:17,254 [log.LogSorter] DEBUG: Attempting to lock b67eb806-6ef1-4ecc-b739-a4ee90e08086 14 16:26:17,262 [log.LogSorter] INFO : got lock for b67eb806-6ef1-4ecc-b739-a4ee90e08086 14 16:26:17,264 [log.LogSorter] INFO : Copying /accumulo/wal/127.0.0.1+40200/b67eb806-6ef1-4ecc-b739-a4ee90e08086 to /accumulo/recovery/b67eb806-6ef1-4ecc-b739-a4ee90e08086 14 16:26:17,300 [log.LogSorter] ERROR: Unexpected error java.lang.NullPointerException at org.apache.hadoop.hdfs.DFSClient$DFSInputStream.updateBlockInfo(DFSClient.java:1885) at org.apache.hadoop.hdfs.DFSClient$DFSInputStream.openInfo(DFSClient.java:1858) at org.apache.hadoop.hdfs.DFSClient$DFSInputStream.<init>(DFSClient.java:1834) at org.apache.hadoop.hdfs.DFSClient.open(DFSClient.java:578) at org.apache.hadoop.hdfs.DistributedFileSystem.open(DistributedFileSystem.java:154) at org.apache.hadoop.fs.FileSystem.open(FileSystem.java:427) at org.apache.accumulo.server.tabletserver.log.LogSorter.startSort(LogSorter.java:295) at org.apache.accumulo.server.tabletserver.log.LogSorter.attemptRecoveries(LogSorter.java:266) at org.apache.accumulo.server.tabletserver.log.LogSorter.access$200(LogSorter.java:60) at org.apache.accumulo.server.tabletserver.log.LogSorter$1.process(LogSorter.java:204) at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:530) at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:506) An update, if I kill accumulo after this and restart HDFS, then I am back to the first problem of a zero length walog file.
        Hide
        Keith Turner added a comment -

        The hdfs write ahead log is new in trunk. This does not affect 1.4.

        Show
        Keith Turner added a comment - The hdfs write ahead log is new in trunk. This does not affect 1.4.

          People

          • Assignee:
            Keith Turner
            Reporter:
            Keith Turner
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development