BootstrapApplierThread.java

/**
 *
 */
package com.linkedin.databus.bootstrap.producer;

/*
 *
 * Copyright 2013 LinkedIn Corp. All rights reserved
 *
 * Licensed 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.
 *
 */

import java.sql.Connection;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.util.Formatter;
import java.util.Random;

import org.apache.log4j.Logger;

import com.linkedin.databus.bootstrap.api.BootstrapProducerStatus;
import com.linkedin.databus.bootstrap.common.BootstrapConn;
import com.linkedin.databus.bootstrap.common.BootstrapDBMetaDataDAO;
import com.linkedin.databus.bootstrap.common.BootstrapProducerStatsCollector;
import com.linkedin.databus.bootstrap.common.BootstrapReadOnlyConfig;
import com.linkedin.databus.bootstrap.monitoring.producer.mbean.DbusBootstrapProducerStatsMBean;
import com.linkedin.databus.core.DatabusThreadBase;
import com.linkedin.databus.core.util.RateMonitor;
import com.linkedin.databus.core.util.RngUtils;
import com.linkedin.databus2.core.BackoffTimer;
import com.linkedin.databus2.core.container.request.BootstrapDatabaseTooOldException;
import com.linkedin.databus2.util.DBHelper;

public class BootstrapApplierThread extends DatabusThreadBase
{

  public static final String MODULE = BootstrapApplierThread.class.getName();
  public static final Logger LOG = Logger.getLogger(MODULE);

  private static final int MAX_EVENT_WAIT_TIME = 1000;
  private static final int INITIAL_EVENT_WAIT_TIME = 5;
  private static final int DEFAULT_LOG_SAMPLING_PERCENTAGE = 2;
  private static final int DEFAULT_MINSCN_TIMEOUT_SEC = 10;

  private static Random _sSampler = new Random();

  private BootstrapDBMetaDataDAO _bootstrapDao;
  private final String _source;
  private PreparedStatement _tabScnStmt;
  private PreparedStatement _getScnStmt;
  private final BootstrapReadOnlyConfig _config;
  private sourcePositions _sourcePositions = null;

  // Log Specific
  private String _lastLogLine = "";
  private int _lastLogLineRepeatCount = 0;
  private static final String APPLIER_STATE_LINE_FORMAT = "Applier state : %d %d %d %d";
  private static final int MAX_SKIPPED_LOG_LINES = 1000;

  /* Stats Specific */
  private BootstrapProducerStatsCollector _statsCollector = null;
  private final RateMonitor _srcRm;
  private final RateMonitor _totalRm;
  private final BackoffTimer _retryTimer;
  private long _minScn = -1L;
  private boolean _isRunning = false;

  /**
   * @param config
   *
   */
  public BootstrapApplierThread(String name, String source,
      BootstrapReadOnlyConfig config)
  {
    this(name, source, config, null);
  }

  public BootstrapApplierThread(String name, String source,
      BootstrapReadOnlyConfig config,
      BootstrapProducerStatsCollector statsCollector)
  {
    super(name);
    _source = source;
    _bootstrapDao = null;
    _config = config;
    _retryTimer = new BackoffTimer(name + "RetryTimer", config.getRetryConfig());
    _statsCollector = statsCollector;
    _srcRm = new RateMonitor(name + "ProducerSourceRateMonitor");
    _totalRm = new RateMonitor(name + "ProducerTotalRateMonitor");

  }

  @Override
  public String toString()
  {
    return "BootstrapApplierThread [_source=" + _source + ", _config="
        + _config + ", _sourcePositions=" + _sourcePositions + "]";
  }

  @Override
  public synchronized void start()
  {
    super.start();
  }

  @Override
  public void run()
  {
    _isRunning = true;

    try
    {
      _sourcePositions = new sourcePositions(_source);
      _sourcePositions.init();
      if (null != _statsCollector)
      {
        DbusBootstrapProducerStatsMBean stats = _statsCollector
            .getSourceStats(_source);
        stats.registerBatch(0, 0, -1, _sourcePositions.getApplyId(),
            _sourcePositions.getLogPos());
      }
    } catch (Exception e)
    {
      if (null != _statsCollector)
        _statsCollector.getTotalStats().registerSQLException();
      LOG.error("Error occurred in initializing source position", e);
      return;
    }

    int sleepTime = INITIAL_EVENT_WAIT_TIME;
    int totalRowsApplied = 0;
    while (_isRunning && !isShutdownRequested())
    {
      try
      {
        if (isPauseRequested())
        {
          LOG.info("Pause requested for applier. Pausing !!");
          signalPause();
          LOG.info("Pausing. Waiting for resume command");
          awaitUnPauseRequest();
          LOG.info("Resume requested for applier. Resuming !!");
          signalResumed();
          LOG.info("Applier resumed !!");
        }

        _totalRm.start();
        Connection conn = getConnection();
        try
        {
          totalRowsApplied += applyLog(_source);
          if (LOG.isDebugEnabled())
          {
            LOG.debug("Number of rows applier so far = " + totalRowsApplied + " for source = " + _source);
          }
        } catch (Exception e)
        {
          if (null != _statsCollector)
          {
            _statsCollector.getTotalStats().registerSQLException();
            _statsCollector.getSourceStats(_source).registerSQLException();
          }

          LOG.error("apply error:", e);
          throw e;
        }
        try
        {
          DBHelper.commit(conn);
        } catch (SQLException s)
        {
          DBHelper.rollback(conn);
          throw s;
        }
        _totalRm.stop();
        if (null != _statsCollector)
          _statsCollector.getTotalStats().registerBatch(
              _totalRm.getDuration() / 1000000L, totalRowsApplied, -1, -1, -1);

        if (0 == totalRowsApplied)
        {
          // sleep for sometime when no events found
          Thread.sleep(sleepTime);

          // increase sleep time for next round if no events are found
          sleepTime = Math.min(sleepTime * 10, MAX_EVENT_WAIT_TIME);
        }
        else
        { // reset to initial sleep time
          sleepTime = INITIAL_EVENT_WAIT_TIME;
          totalRowsApplied = 0;
        }
      } catch (Exception e)
      {
        LOG.error("Error occured in bootstrap applier", e);
        if (null != _statsCollector)
        {
          _statsCollector.getTotalStats().registerSQLException();
        }

        if (e instanceof SQLException)
        {
          if (!reset(true))
          {
            LOG.fatal(
                "Unable to reset Bootstrap DB connections. Stopping Applier Thread !!",
                e);
            _isRunning = false;
          }
        }
      }
    }

    reset(false);

    doShutdownNotify();
  }

  public boolean isRunning()
  {
    return _isRunning;
  }

  private void closeApplyStatements() throws SQLException
  {
    _sourcePositions.close();
  }

  private int applyLog(String source) throws BootstrapDatabaseTooOldException,
      SQLException
  {
    PreparedStatement stmt = null;

    sourcePositions pos = _sourcePositions;
    applyBatch batch = pos.getNextApplyBatch();
    int rowsToApply = batch.getTorid() - batch.getFromrid();

    try
    {
      _srcRm.start();
      if (rowsToApply > 0)
      {
        // Apply log to the table to move it up to logScn
        stmt = pos.getApplyStmt();
        stmt.setInt(1, batch.getFromrid());
        stmt.setInt(2, batch.getTorid());
        stmt.executeUpdate();

        boolean log = (RngUtils.randomPositiveInt(_sSampler) % 100) < DEFAULT_LOG_SAMPLING_PERCENTAGE;
        if (log)
          LOG.info("Applied Log " + batch + " for " + source);
      }

      // we need to save state regardless if any rows are returned because
      // we could be switching logs.
      pos.save();
    } catch (SQLException e)
    {
      LOG.error("Error occured during apply log", e);
      throw e;
    } finally
    {
      _srcRm.stop();
      if (null != _statsCollector)
      {
        DbusBootstrapProducerStatsMBean stats = _statsCollector
            .getSourceStats(source);
        stats.registerBatch(_srcRm.getDuration() / 1000000L, rowsToApply,
            pos.getApplyWindowSCN(), pos.getApplyId(), pos.getLogPos());
      }
    }
    return rowsToApply;
  }

  private long getWindowScnforSource(int srcid, int applyLogId, int tabRid)
      throws SQLException
  {
    ResultSet rs = null;
    long windowScn = 0;
    PreparedStatement stmt = null;

    try
    {
      if (0 == tabRid)
      { // get the maxscn of the prior table
        stmt = getMaxWindowScnStatement();
        stmt.setInt(1, srcid);
        stmt.setInt(2, Math.max(0, applyLogId - 1));
      }
      else
      {
        stmt = getWindowScnStatement(applyLogId, srcid);
        stmt.setInt(1, tabRid);
      }

      rs = stmt.executeQuery();
      if (rs.next())
      {
        windowScn = rs.getLong(1);
      }
    } catch (SQLException e)
    {
      LOG.error("Error ocurred during getWindowScnforSource", e);
      throw e;
    } finally
    {
      if (null != rs)
      {
        rs.close();
        rs = null;
      }
      if (null != stmt)
      {
        stmt.close();
        stmt = null;
      }
    }
    return windowScn;
  }

  private void setTabPosition(int srcid, int logid, int tabRid, long windowScn)
      throws SQLException
  {
    PreparedStatement stmt = getTabPositionUpdateStmt();

    stmt.setInt(1, logid);
    stmt.setInt(2, tabRid);
    stmt.setLong(3, windowScn);
    stmt.setInt(4, srcid);

    stmt.executeUpdate();

    StringBuilder logLineBuilder = new StringBuilder(1024);
    Formatter logFormatter = new Formatter(logLineBuilder);
    logFormatter.format(APPLIER_STATE_LINE_FORMAT, srcid, logid, tabRid,
        windowScn);

    log(srcid, logFormatter);
  }

  private PreparedStatement getMaxWindowScnStatement() throws SQLException
  {
    Connection conn = null;
    PreparedStatement windowScnStmt = null;
    try
    {
      conn = getConnection();
      StringBuilder sql = new StringBuilder();

      sql.append("select maxwindowscn from bootstrap_loginfo where srcid = ? and logid = ?");
      windowScnStmt = conn.prepareStatement(sql.toString());
    } catch (SQLException e)
    {
      DBHelper.close(windowScnStmt);
      LOG.error("error occurred during getWindowScnStatement", e);
      throw e;
    }

    return windowScnStmt;
  }

  private PreparedStatement getWindowScnStatement(int applyLogId, int srcid)
      throws SQLException
  {
    Connection conn = null;
    PreparedStatement windowScnStmt = null;
    try
    {
      conn = getConnection();
      StringBuilder sql = new StringBuilder();

      sql.append("select windowscn from ");
      sql.append(getLogTableName(applyLogId, srcid));
      sql.append(" where id = ?");
      windowScnStmt = conn.prepareStatement(sql.toString());
    } catch (SQLException e)
    {
      DBHelper.close(windowScnStmt);
      LOG.error("error occurred during getWindowScnStatement", e);
      throw e;
    }

    return windowScnStmt;
  }

  private PreparedStatement getTabPositionUpdateStmt() throws SQLException
  {
    if (_tabScnStmt != null)
    {
      return _tabScnStmt;
    }

    Connection conn = null;

    try
    {
      conn = getConnection();
      StringBuilder sql = new StringBuilder();

      sql.append("update bootstrap_applier_state set logid = ?, rid = ? , windowscn = ?  where srcid = ?");
      _tabScnStmt = conn.prepareStatement(sql.toString());
    } catch (SQLException e)
    {
      LOG.error("Error ocurred in getTabPositionUpdateStmt", e);
      _tabScnStmt.close();
      conn.close();
      return null;
    }

    return _tabScnStmt;
  }

  private PreparedStatement getPositionsStmt() throws SQLException
  {
    if (_getScnStmt != null)
    {
      return _getScnStmt;
    }

    Connection conn = null;

    try
    {
      conn = getConnection();
      StringBuilder sql = new StringBuilder();

      sql.append("select p.logid, p.rid, a.logid, a.rid, l.maxrid, l.maxwindowscn ");
      sql.append("from bootstrap_sources s, bootstrap_producer_state p, bootstrap_applier_state a, bootstrap_loginfo l ");
      sql.append("where p.srcid = s.id and a.srcid = s.id and l.srcid = s.id and l.logid = a.logid and s.src = ?");

      _getScnStmt = conn.prepareStatement(sql.toString());
    } catch (Exception e)
    {
      LOG.error("Error occured in getPositionsstatement", e);
      _getScnStmt.close();
      conn.close();
      return null;
    }

    return _getScnStmt;
  }

  /*
   * Reset the Bootstrap Connection and in memory state of Applier
   */
  private boolean reset(boolean recreate)
  {
    boolean success = false;

    _retryTimer.reset();
    while (!success)
    {
      try
      {
        _bootstrapDao.getBootstrapConn().close();

        DBHelper.close(_getScnStmt);
        _getScnStmt = null;

        DBHelper.close(_tabScnStmt);
        _tabScnStmt = null;

        closeApplyStatements();

        // Close the Source Positions
        _sourcePositions.close();

        if (recreate)
        {
          getConnection();
          _bootstrapDao.getBootstrapConn().executeDummyBootstrapDBQuery();

          // Init the SourcePositions from DB
          _sourcePositions.init();
        }

        success = true;
      } catch (SQLException sqlEx)
      {
        LOG.error("Unable to reset DBConnections in Applier", sqlEx);
        success = false;

        if (null != _statsCollector)
        {
          _statsCollector.getTotalStats().registerSQLException();
        }

        if (_retryTimer.getRemainingRetriesNum() <= 0)
        {
          LOG.fatal("Applier Thread reached max retries trying to reset the MySQL Connections. Stopping !!");
          break;
        }

        _retryTimer.backoffAndSleep();
      }
    }
    return success;
  }

  private Connection getConnection() throws SQLException
  {
    Connection conn = null;
    BootstrapConn bsConn = null;
    if (_bootstrapDao == null)
    {
      bsConn = new BootstrapConn();
      try
      {
        final boolean autoCommit = false;
        bsConn.initBootstrapConn(autoCommit,
            java.sql.Connection.TRANSACTION_READ_COMMITTED,
            _config.getBootstrapDBUsername(), _config.getBootstrapDBPassword(),
            _config.getBootstrapDBHostname(), _config.getBootstrapDBName());
        _bootstrapDao = new BootstrapDBMetaDataDAO(bsConn,
            _config.getBootstrapDBHostname(), _config.getBootstrapDBUsername(),
            _config.getBootstrapDBPassword(), _config.getBootstrapDBName(),
            autoCommit);
      } catch (SQLException e)
      {
        LOG.fatal("Unable to get Bootstrap DB Connection", e);
        throw e;
      } catch (Exception ex)
      {
        LOG.fatal("Unable to get Bootstrap DB Connection", ex);
        return null;
      }
    }

    try
    {
      conn = _bootstrapDao.getBootstrapConn().getDBConn();
    } catch (SQLException sqlEx)
    {
      LOG.fatal("NOT able to get Bootstrap DB Connection", sqlEx);
      throw sqlEx;
    }

    return conn;
  }

  private String getLogTableName(int applyLogId, int srcid) throws SQLException
  {
    return getBootstrapConn().getLogTableName(applyLogId, srcid);
  }

  private String getSrcTableName(int srcid) throws SQLException,
      BootstrapDatabaseTooOldException
  {
    return getBootstrapConn().getSrcTableName(srcid);
  }

  private BootstrapConn getBootstrapConn()
  {
    return _bootstrapDao.getBootstrapConn();
  }

  static class applyBatch
  {
    private final int _logid;
    private final int _fromrid;
    private final int _torid;

    applyBatch(int logid, int fromrid, int torid)
    {
      _logid = logid;
      _fromrid = fromrid;
      _torid = torid;
    }

    public int getLogId()
    {
      return _logid;
    }

    public int getFromrid()
    {
      return _fromrid;
    }

    public int getTorid()
    {
      return _torid;
    }

    @Override
    public String toString()
    {
      return "LogId: " + _logid + " From: " + _fromrid + "  To: " + _torid;
    }
  }

  class sourcePositions
  {
    private int _srcid;
    private int _tabrid;
    private int _logrid;
    private int _applylogid;
    private int _producelogid;
    private int _logmaxrid;
    private long _logwindowscn;
    private PreparedStatement _applyStmt;
    private long _lastlogmaxscn;

    private final String _source;

    sourcePositions(String source) throws Exception
    {
      _source = source;
      init();
    }

    public void init() throws SQLException
    {
      try
      {
        getConnection();

        BootstrapDBMetaDataDAO.SourceStatusInfo srcIdStatus = _bootstrapDao
            .getSrcIdStatusFromDB(_source, false);
        _srcid = srcIdStatus.getSrcId();

        if (_config.isBootstrapDBStateCheck())
        {
          // TO allow test framework to listen to relay directly,DBStateCheck
          // flag is used
          if (!BootstrapProducerStatus.isReadyForConsumption(srcIdStatus
              .getStatus()))
            throw new BootstrapDatabaseTooOldException(
                "Bootstrap DB not ready to read events from relay, Status :"
                    + srcIdStatus);
        }

        refresh();
        _applyStmt = createApplyStatement();
        // initialize minScnmap with current minScn value
        // bootstrap applier is started after bootstrap producer initialization;
        // the minScn of sources will be initialized appropriately
        _minScn = _bootstrapDao
            .getMinScnOfSnapshots(srcIdStatus.getSrcId());
      } catch (BootstrapDatabaseTooOldException e)
      {
        throw new RuntimeException(e);
      }
    }

    public void close()
    {
      DBHelper.close(_applyStmt);
      _applyStmt = null;
    }

    void refresh() throws SQLException
    {
      ResultSet rs = null;
      try
      {
        PreparedStatement stmt = getPositionsStmt();
        stmt.setString(1, _source);
        rs = stmt.executeQuery();
        if (rs.next())
        {
          _producelogid = rs.getInt(1);
          _logrid = rs.getInt(2);
          _applylogid = rs.getInt(3);
          _tabrid = rs.getInt(4);
          _logmaxrid = rs.getInt(5);
          long currentLogMaxScn = rs.getLong(6);

          if (currentLogMaxScn > 0)
          {
            if (_lastlogmaxscn > currentLogMaxScn)
            {
              throw new RuntimeException("_lastlogmaxscn=" + _lastlogmaxscn
                  + " currentLogMaxScn=" + currentLogMaxScn + " applylogid="
                  + _applylogid + " producerlogid=" + _producelogid
                  + " tabrid=" + _tabrid + " logrid=" + _logrid + " logmaxrid="
                  + _logmaxrid);
            }
            _lastlogmaxscn = currentLogMaxScn;
          }
        }
        rs.close();
      } catch (SQLException e)
      {
        LOG.error("Error occured during refresh of sourcePositions", e);
        if (null != rs)
        {
          rs.close();
          rs = null;
        }
        throw e;
      }
    }

    @Override
    public String toString()
    {
      return "SrcId: " + _srcid + " ProducerLogId: " + _producelogid
          + " Logrid: " + _logrid + " ApplyLogId: " + _applylogid + " Tabrid: "
          + _tabrid + " LogMaxrid: " + _logmaxrid;
    }

    void save() throws SQLException
    {
      LOG.debug("Saving state " + this);

      // if tabrid is 0, we need to get max window scn from the last log table;
      // otherwise, we get the window scn of the row corresponding to _tabrid;
      // except for the initial case where nothing is inserted, (applylogid - 1)
      // will
      // be -1 and 0 shall be used in this case.
      _logwindowscn = getWindowScnforSource(_srcid, _applylogid, _tabrid);
      setTabPosition(_srcid, _applylogid, _tabrid, _logwindowscn);
      // check if minscn has been set already
      // this happens once! or when minScn table is reinitialized;
      if (_minScn == BootstrapDBMetaDataDAO.DEFAULT_WINDOWSCN)
      {
        // WARN: could be a long running query; if _tabrid is high;
        long newMinScn = _bootstrapDao.isSeeded(_srcid) ? 0 : _bootstrapDao
            .getMinWindowScnFromSnapshot(_srcid, _tabrid,
                DEFAULT_MINSCN_TIMEOUT_SEC);
        // Avoid unnecessary updates and safety check: never re-initialize it
        // due to return value of negative scn
        if ((_minScn != newMinScn)
            && (newMinScn != BootstrapDBMetaDataDAO.DEFAULT_WINDOWSCN))
        {
          LOG.info("Applier setting minScn=" + newMinScn);
          // Note: Assume that rows never actually have scn=0. Since this table
          // has rows with newMinScn, the minScn is updated to 1 less.
          // The bootstrap snapshot query will serve all rows with scn greater
          // than minScn.
          if (newMinScn != 0)
          {
            newMinScn--;
          }
          _bootstrapDao.updateMinScnOfSnapshot(_srcid, newMinScn);
          _minScn = newMinScn;
        }
      }
    }

    public int getTabPos()
    {
      return _tabrid;
    }

    public int getLogPos()
    {
      return _logrid;
    }

    public int getSrcId()
    {
      return _srcid;
    }

    public int getApplyId()
    {
      return _applylogid;
    }

    public long getApplyWindowSCN()
    {
      return _logwindowscn;
    }

    public PreparedStatement getApplyStmt()
        throws BootstrapDatabaseTooOldException, SQLException
    {
      if (null != _applyStmt)
        return _applyStmt;
      _applyStmt = createApplyStatement();
      return _applyStmt;
    }

    public applyBatch getNextApplyBatch() throws SQLException
    {
      int _torid = _tabrid;

      // If we are applying the same log file that is currently being produced,
      // read upto
      // next 1000 rows
      if (_applylogid == _producelogid)
      {
        // If we have caught up for this source, refresh the state
        if (_tabrid == _logrid)
        {
          refresh();
        }
        else
        {
          _torid = Math.min(_logrid, _tabrid + 1000);
        }
      }
      else
      {
        if (_logmaxrid == 0)
        {
          refresh();
        }

        // If we have finished reading this log, we can move to the next
        if (_tabrid == _logmaxrid)
        {
          _applylogid++;
          _torid = 0;
          _tabrid = 0;
          _logmaxrid = 0;
          // remove the apply statement so a new statement can be created to
          // moves rows from new log table to tab table.
          DBHelper.close(_applyStmt);
          _applyStmt = null;
        }
        else
        {
          _torid = Math.min(_logmaxrid, _tabrid + 1000);
        }
      }

      applyBatch nextBatch = new applyBatch(_applylogid, _tabrid, _torid);
      _tabrid = _torid;
      return nextBatch;
    }

    private PreparedStatement createApplyStatement() throws SQLException,
        BootstrapDatabaseTooOldException
    {
      Connection conn = getConnection();
      PreparedStatement applyStmt = null;
      StringBuilder sql = new StringBuilder();
      sql.append("insert into ");
      sql.append(getSrcTableName(_srcid));
      sql.append(" (scn, srckey, val) ");
      sql.append("select windowscn, srckey, val from ");
      sql.append(getLogTableName(_applylogid, _srcid) + " B ");
      sql.append(" where B.id > ? and B.id <= ?");
      sql.append(" on duplicate key update scn = B.windowscn, srckey=B.srckey, val=B.val");
      applyStmt = conn.prepareStatement(sql.toString());

      LOG.info("Created apply statement: " + sql.toString());

      return applyStmt;
    }
  }

  private void log(int srcid, Formatter logLine)
  {
    logLine.flush();
    String newLogLine = logLine.toString();

    boolean skipLog = true;
    final int saveLastLogLineRepeat = _lastLogLineRepeatCount;

    String lastLogLine = _lastLogLine;

    if (newLogLine.equals(lastLogLine)
        && _lastLogLineRepeatCount < MAX_SKIPPED_LOG_LINES)
    {
      ++_lastLogLineRepeatCount;
    }
    else
    {
      skipLog = false;
      lastLogLine = newLogLine;
      _lastLogLineRepeatCount = 0;
    }


    if (!skipLog)
    {
      _lastLogLine = lastLogLine;
      LOG.info("skipLog = false, last line repeated: " + saveLastLogLineRepeat);
      LOG.info("newLogLine = " + newLogLine);
    }
  }
}