ReplayHandler.java

/*
 * Licensed to the Apache Software Foundation (ASF) under one
 * or more contributor license agreements.  See the NOTICE file
 * distributed with this work for additional information
 * regarding copyright ownership.  The ASF licenses this file
 * to you under the Apache License, Version 2.0 (the
 * "License"); you may not use this file except in compliance
 * with the License.  You may obtain a copy of the License at
 *
 * http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing,
 * software distributed under the License is distributed on an
 * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
 * KIND, either express or implied.  See the License for the
 * specific language governing permissions and limitations
 * under the License.
 */
package org.apache.flume.channel.file;

import com.google.common.annotations.VisibleForTesting;
import com.google.common.base.Preconditions;
import com.google.common.collect.Lists;
import com.google.common.collect.Maps;
import com.google.common.collect.SetMultimap;
import com.google.common.collect.Sets;
import org.apache.commons.collections.MultiMap;
import org.apache.commons.collections.map.MultiValueMap;
import org.apache.flume.channel.file.encryption.KeyProvider;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import javax.annotation.Nullable;
import java.io.EOFException;
import java.io.File;
import java.io.IOException;
import java.util.Collection;
import java.util.Iterator;
import java.util.List;
import java.util.Map;
import java.util.PriorityQueue;
import java.util.Set;

/**
 * Processes a set of data logs, replaying said logs into the queue.
 */
class ReplayHandler {
  private static final Logger LOG = LoggerFactory
      .getLogger(ReplayHandler.class);
  private final FlumeEventQueue queue;
  private final long lastCheckpoint;
  private final Map<Integer, LogFile.SequentialReader> readers;
  private final PriorityQueue<LogRecord> logRecordBuffer;
  private final KeyProvider encryptionKeyProvider;
  private final boolean fsyncPerTransaction;
  /**
   * This data structure stores takes for which we found a commit in the log
   * files before we found a commit for the put. This can happen if the channel
   * is configured for multiple directories.
   *
   * Consider the following:
   *
   * logdir1, logdir2
   *
   * Put goes to logdir2 Commit of Put goes to logdir2 Take goes to logdir1
   * Commit of Take goes to logdir1
   *
   * When replaying we will start with log1 and find the take and commit before
   * finding the put and commit in logdir2.
   */
  private final List<Long> pendingTakes;
  int readCount = 0;
  int putCount = 0;
  int takeCount = 0;
  int rollbackCount = 0;
  int commitCount = 0;
  int skipCount = 0;

  @VisibleForTesting
  public int getReadCount() {
    return readCount;
  }
  @VisibleForTesting
  public int getPutCount() {
    return putCount;
  }
  @VisibleForTesting
  public int getTakeCount() {
    return takeCount;
  }
  @VisibleForTesting
  public int getCommitCount() {
    return commitCount;
  }

  @VisibleForTesting
  public int getRollbackCount() {
    return rollbackCount;
  }

  ReplayHandler(FlumeEventQueue queue,
                @Nullable KeyProvider encryptionKeyProvider,
                boolean fsyncPerTransaction) {
    this.queue = queue;
    this.lastCheckpoint = queue.getLogWriteOrderID();
    pendingTakes = Lists.newArrayList();
    readers = Maps.newHashMap();
    logRecordBuffer = new PriorityQueue<LogRecord>();
    this.encryptionKeyProvider = encryptionKeyProvider;
    this.fsyncPerTransaction = fsyncPerTransaction;
  }

  /**
   * Replay logic from Flume1.2 which can be activated if the v2 logic
   * is failing on ol logs for some reason.
   */
  @Deprecated
  void replayLogv1(List<File> logs) throws Exception {
    int total = 0;
    int count = 0;
    MultiMap transactionMap = new MultiValueMap();
    //Read inflight puts to see if they were committed
    SetMultimap<Long, Long> inflightPuts = queue.deserializeInflightPuts();
    for (Long txnID : inflightPuts.keySet()) {
      Set<Long> eventPointers = inflightPuts.get(txnID);
      for (Long eventPointer : eventPointers) {
        transactionMap.put(txnID, FlumeEventPointer.fromLong(eventPointer));
      }
    }

    SetMultimap<Long, Long> inflightTakes = queue.deserializeInflightTakes();
    LOG.info("Starting replay of " + logs);
    for (File log : logs) {
      LOG.info("Replaying " + log);
      LogFile.SequentialReader reader = null;
      try {
        reader = LogFileFactory.getSequentialReader(log,
          encryptionKeyProvider, fsyncPerTransaction);
        reader.skipToLastCheckpointPosition(queue.getLogWriteOrderID());
        LogRecord entry;
        FlumeEventPointer ptr;
        // for puts the fileId is the fileID of the file they exist in
        // for takes the fileId and offset are pointers to a put
        int fileId = reader.getLogFileID();

        while ((entry = reader.next()) != null) {
          int offset = entry.getOffset();
          TransactionEventRecord record = entry.getEvent();
          short type = record.getRecordType();
          long trans = record.getTransactionID();
          readCount++;
          if (record.getLogWriteOrderID() > lastCheckpoint) {
            if (type == TransactionEventRecord.Type.PUT.get()) {
              putCount++;
              ptr = new FlumeEventPointer(fileId, offset);
              transactionMap.put(trans, ptr);
            } else if (type == TransactionEventRecord.Type.TAKE.get()) {
              takeCount++;
              Take take = (Take) record;
              ptr = new FlumeEventPointer(take.getFileID(), take.getOffset());
              transactionMap.put(trans, ptr);
            } else if (type == TransactionEventRecord.Type.ROLLBACK.get()) {
              rollbackCount++;
              transactionMap.remove(trans);
            } else if (type == TransactionEventRecord.Type.COMMIT.get()) {
              commitCount++;
              @SuppressWarnings("unchecked")
              Collection<FlumeEventPointer> pointers =
                  (Collection<FlumeEventPointer>) transactionMap.remove(trans);
              if (((Commit) record).getType() == TransactionEventRecord.Type.TAKE.get()) {
                if (inflightTakes.containsKey(trans)) {
                  if (pointers == null) {
                    pointers = Sets.newHashSet();
                  }
                  Set<Long> takes = inflightTakes.removeAll(trans);
                  Iterator<Long> it = takes.iterator();
                  while (it.hasNext()) {
                    Long take = it.next();
                    pointers.add(FlumeEventPointer.fromLong(take));
                  }
                }
              }
              if (pointers != null && pointers.size() > 0) {
                processCommit(((Commit) record).getType(), pointers);
                count += pointers.size();
              }
            } else {
              Preconditions.checkArgument(false,
                                          "Unknown record type: " + Integer.toHexString(type));
            }

          } else {
            skipCount++;
          }
        }
        LOG.info("Replayed " + count + " from " + log);
        if (LOG.isDebugEnabled()) {
          LOG.debug("read: " + readCount + ", put: " + putCount + ", take: "
              + takeCount + ", rollback: " + rollbackCount + ", commit: "
              + commitCount + ", skipp: " + skipCount);
        }
      } catch (EOFException e) {
        LOG.warn("Hit EOF on " + log);
      } finally {
        total += count;
        count = 0;
        if (reader != null) {
          reader.close();
        }
      }
    }
    //re-insert the events in the take map,
    //since the takes were not committed.
    int uncommittedTakes = 0;
    for (Long inflightTxnId : inflightTakes.keySet()) {
      Set<Long> inflightUncommittedTakes =
              inflightTakes.get(inflightTxnId);
      for (Long inflightUncommittedTake : inflightUncommittedTakes) {
        queue.addHead(FlumeEventPointer.fromLong(inflightUncommittedTake));
        uncommittedTakes++;
      }
    }
    inflightTakes.clear();
    count += uncommittedTakes;
    int pendingTakesSize = pendingTakes.size();
    if (pendingTakesSize > 0) {
      String msg = "Pending takes " + pendingTakesSize
          + " exist after the end of replay";
      if (LOG.isDebugEnabled()) {
        for (Long pointer : pendingTakes) {
          LOG.debug("Pending take " + FlumeEventPointer.fromLong(pointer));
        }
      } else {
        LOG.error(msg + ". Duplicate messages will exist in destination.");
      }
    }
    LOG.info("Replayed " + total);
  }
  /**
   * Replay logs in order records were written
   * @param logs
   * @throws IOException
   */
  void replayLog(List<File> logs) throws Exception {
    int count = 0;
    MultiMap transactionMap = new MultiValueMap();
    // seed both with the highest known sequence of either the tnxid or woid
    long transactionIDSeed = lastCheckpoint, writeOrderIDSeed = lastCheckpoint;
    LOG.info("Starting replay of " + logs);
    //Load the inflight puts into the transaction map to see if they were
    //committed in one of the logs.
    SetMultimap<Long, Long> inflightPuts = queue.deserializeInflightPuts();
    for (Long txnID : inflightPuts.keySet()) {
      Set<Long> eventPointers = inflightPuts.get(txnID);
      for (Long eventPointer : eventPointers) {
        transactionMap.put(txnID, FlumeEventPointer.fromLong(eventPointer));
      }
    }
    SetMultimap<Long, Long> inflightTakes = queue.deserializeInflightTakes();
    try {
      for (File log : logs) {
        LOG.info("Replaying " + log);
        try {
          LogFile.SequentialReader reader =
              LogFileFactory.getSequentialReader(log, encryptionKeyProvider, fsyncPerTransaction);
          reader.skipToLastCheckpointPosition(queue.getLogWriteOrderID());
          Preconditions.checkState(!readers.containsKey(reader.getLogFileID()),
              "Readers " + readers + " already contains "
                  + reader.getLogFileID());
          readers.put(reader.getLogFileID(), reader);
          LogRecord logRecord = reader.next();
          if (logRecord == null) {
            readers.remove(reader.getLogFileID());
            reader.close();
          } else {
            logRecordBuffer.add(logRecord);
          }
        } catch (EOFException e) {
          LOG.warn("Ignoring " + log + " due to EOF", e);
        }
      }
      LogRecord entry = null;
      FlumeEventPointer ptr = null;
      while ((entry = next()) != null) {
        // for puts the fileId is the fileID of the file they exist in
        // for takes the fileId and offset are pointers to a put
        int fileId = entry.getFileID();
        int offset = entry.getOffset();
        TransactionEventRecord record = entry.getEvent();
        short type = record.getRecordType();
        long trans = record.getTransactionID();
        transactionIDSeed = Math.max(transactionIDSeed, trans);
        writeOrderIDSeed = Math.max(writeOrderIDSeed,
            record.getLogWriteOrderID());
        readCount++;
        if (readCount % 10000 == 0 && readCount > 0) {
          LOG.info("read: " + readCount + ", put: " + putCount + ", take: "
              + takeCount + ", rollback: " + rollbackCount + ", commit: "
              + commitCount + ", skip: " + skipCount + ", eventCount:" + count);
        }
        if (record.getLogWriteOrderID() > lastCheckpoint) {
          if (type == TransactionEventRecord.Type.PUT.get()) {
            putCount++;
            ptr = new FlumeEventPointer(fileId, offset);
            transactionMap.put(trans, ptr);
          } else if (type == TransactionEventRecord.Type.TAKE.get()) {
            takeCount++;
            Take take = (Take) record;
            ptr = new FlumeEventPointer(take.getFileID(), take.getOffset());
            transactionMap.put(trans, ptr);
          } else if (type == TransactionEventRecord.Type.ROLLBACK.get()) {
            rollbackCount++;
            transactionMap.remove(trans);
          } else if (type == TransactionEventRecord.Type.COMMIT.get()) {
            commitCount++;
            @SuppressWarnings("unchecked")
            Collection<FlumeEventPointer> pointers =
                (Collection<FlumeEventPointer>) transactionMap.remove(trans);
            if (((Commit) record).getType()
                    == TransactionEventRecord.Type.TAKE.get()) {
              if (inflightTakes.containsKey(trans)) {
                if (pointers == null) {
                  pointers = Sets.newHashSet();
                }
                Set<Long> takes = inflightTakes.removeAll(trans);
                Iterator<Long> it = takes.iterator();
                while (it.hasNext()) {
                  Long take = it.next();
                  pointers.add(FlumeEventPointer.fromLong(take));
                }
              }
            }
            if (pointers != null && pointers.size() > 0) {
              processCommit(((Commit) record).getType(), pointers);
              count += pointers.size();
            }
          } else {
            Preconditions.checkArgument(false, "Unknown record type: "
                + Integer.toHexString(type));
          }
        } else {
          skipCount++;
        }
      }
      LOG.info("read: " + readCount + ", put: " + putCount + ", take: "
          + takeCount + ", rollback: " + rollbackCount + ", commit: "
          + commitCount + ", skip: " + skipCount + ", eventCount:" + count);
      queue.replayComplete();
    } finally {
      TransactionIDOracle.setSeed(transactionIDSeed);
      WriteOrderOracle.setSeed(writeOrderIDSeed);
      for (LogFile.SequentialReader reader : readers.values()) {
        if (reader != null) {
          reader.close();
        }
      }
    }
    //re-insert the events in the take map,
    //since the takes were not committed.
    int uncommittedTakes = 0;
    for (Long inflightTxnId : inflightTakes.keySet()) {
      Set<Long> inflightUncommittedTakes =
              inflightTakes.get(inflightTxnId);
      for (Long inflightUncommittedTake : inflightUncommittedTakes) {
        queue.addHead(FlumeEventPointer.fromLong(inflightUncommittedTake));
        uncommittedTakes++;
      }
    }
    inflightTakes.clear();
    count += uncommittedTakes;
    int pendingTakesSize = pendingTakes.size();
    if (pendingTakesSize > 0) {
      LOG.info("Pending takes " + pendingTakesSize + " exist after the" +
          " end of replay. Duplicate messages will exist in" +
          " destination.");
    }
  }
  private LogRecord next() throws IOException, CorruptEventException {
    LogRecord resultLogRecord = logRecordBuffer.poll();
    if (resultLogRecord != null) {
      // there is more log records to read
      LogFile.SequentialReader reader = readers.get(resultLogRecord.getFileID());
      LogRecord nextLogRecord;
      if ((nextLogRecord = reader.next()) != null) {
        logRecordBuffer.add(nextLogRecord);
      }
    }
    return resultLogRecord;
  }
  private void processCommit(short type, Collection<FlumeEventPointer> pointers) {
    if (type == TransactionEventRecord.Type.PUT.get()) {
      for (FlumeEventPointer pointer : pointers) {
        if (!queue.addTail(pointer)) {
          throw new IllegalStateException("Unable to add "
              + pointer + ". Queue depth = " + queue.getSize()
              + ", Capacity = " + queue.getCapacity());
        }
        if (pendingTakes.remove(pointer.toLong())) {
          Preconditions.checkState(queue.remove(pointer),
              "Take was pending and pointer was successfully added to the"
                  + " queue but could not be removed: " + pointer);
        }
      }
    } else if (type == TransactionEventRecord.Type.TAKE.get()) {
      for (FlumeEventPointer pointer : pointers) {
        boolean removed = queue.remove(pointer);
        if (!removed) {
          pendingTakes.add(pointer.toLong());
        }
      }
    } else {
      Preconditions.checkArgument(false,
          "Unknown record type: " + Integer.toHexString(type));
    }
  }

}