Examples with RedoableOp com.zimbra.cs.redolog.op.RedoableOp used on opensource projects

Example 11 with RedoableOp

use of com.zimbra.cs.redolog.op.RedoableOp in project zm-mailbox by Zimbra.

the class RedoPlayer method runCrashRecovery.

/**
     *
     * @param redoLogMgr
     * @param postStartupRecoveryOps operations to recover/redo after startup
     *                               completes and clients are allowed to
     *                               connect
     * @return number of operations redone (regardless of their success)
     * @throws Exception
     */
public int runCrashRecovery(RedoLogManager redoLogMgr, List<RedoableOp> postStartupRecoveryOps) throws Exception {
    File redoLog = redoLogMgr.getLogFile();
    if (!redoLog.exists())
        return 0;
    long lookBackTstamp = Long.MAX_VALUE;
    long lookBackDuration = RedoConfig.redoLogCrashRecoveryLookbackSec() * 1000;
    if (lookBackDuration > 0) {
        // Guess the last op's timestamp.  Use the log file's last modified time.  Sanity check it by
        // going no earlier than the create time written in the log.  We can't rely on the last
        // op time field in the header because that is only accurate when the file was closed normally
        // but in crash recovery we're not dealing with a normally closed log.
        long logLastModTime = redoLog.lastModified();
        long logCreateTime = (new FileLogReader(redoLog)).getHeader().getCreateTime();
        long lastOpTstamp = Math.max(logLastModTime, logCreateTime);
        lookBackTstamp = lastOpTstamp - lookBackDuration;
    }
    // scanLog can truncate the current redo.log if it finds junk data at the end
    // from the previous crash.  Close log writer before scanning and reopen after
    // so we don't accidentally undo the truncation on the next write to the log.
    LogWriter logWriter = redoLogMgr.getLogWriter();
    logWriter.close();
    scanLog(redoLog, false, null, Long.MIN_VALUE, Long.MAX_VALUE, lookBackTstamp);
    logWriter.open();
    int numOps;
    synchronized (mOpsMapGuard) {
        numOps = mOpsMap.size();
    }
    if (numOps == 0) {
        ZimbraLog.redolog.info("No uncommitted transactions to redo");
        return 0;
    }
    synchronized (mOpsMapGuard) {
        Set entrySet = mOpsMap.entrySet();
        ZimbraLog.redolog.info("Redoing " + numOps + " uncommitted transactions");
        for (Iterator it = entrySet.iterator(); it.hasNext(); ) {
            Map.Entry entry = (Entry) it.next();
            RedoableOp op = (RedoableOp) entry.getValue();
            if (op == null)
                continue;
            if (op.deferCrashRecovery()) {
                ZimbraLog.redolog.info("Deferring crash recovery to after startup: " + op);
                postStartupRecoveryOps.add(op);
                continue;
            }
            if (ZimbraLog.redolog.isInfoEnabled())
                ZimbraLog.redolog.info("REDOING: " + op);
            boolean success = false;
            try {
                op.redo();
                success = true;
            } catch (Exception e) {
                ZimbraLog.redolog.error("Redo failed for [" + op + "]." + "  Backend state of affected item is indeterminate." + "  Marking operation as aborted and moving on.", e);
            } finally {
                if (success) {
                    CommitTxn commit = new CommitTxn(op);
                    redoLogMgr.logOnly(commit, true);
                } else {
                    AbortTxn abort = new AbortTxn(op);
                    redoLogMgr.logOnly(abort, true);
                }
            }
        }
        mOpsMap.clear();
    }
    return numOps;
}

Example 12 with RedoableOp

use of com.zimbra.cs.redolog.op.RedoableOp in project zm-mailbox by Zimbra.

the class RedoPlayer method processOp.

private final void processOp(RedoableOp op, boolean redoCommitted, Map<Integer, Integer> mboxIDsMap, long startTime, long endTime, long ignoreCommitsAtOrAfter) throws ServiceException {
    if (op.isStartMarker()) {
        synchronized (mOpsMapGuard) {
            mOpsMap.put(op.getTransactionId(), op);
            if (mHasOrphanOps) {
                RedoableOp x = mOrphanOps.remove(op.getTransactionId());
                if (x != null)
                    ZimbraLog.redolog.error("Detected out-of-order insertion of change record for orphans commit/abort: change=" + op + ", orphan=" + x);
            }
        }
    } else {
        // those listed in the checkpoint.
        if (op instanceof Checkpoint) {
            Checkpoint ckpt = (Checkpoint) op;
            Set txns = ckpt.getActiveTxns();
            if (txns.size() > 0) {
                synchronized (mOpsMapGuard) {
                    if (mOpsMap.size() != txns.size()) {
                        // Unexpected discrepancy
                        if (ZimbraLog.redolog.isDebugEnabled()) {
                            StringBuffer sb1 = new StringBuffer("Current Uncommitted Ops: ");
                            StringBuffer sb2 = new StringBuffer("Checkpoint Uncommitted Ops: ");
                            int i = 0;
                            for (Iterator it = mOpsMap.keySet().iterator(); it.hasNext(); i++) {
                                TransactionId id = (TransactionId) it.next();
                                if (i > 0)
                                    sb1.append(", ");
                                sb1.append(id);
                            }
                            i = 0;
                            for (Iterator it = txns.iterator(); it.hasNext(); i++) {
                                TransactionId id = (TransactionId) it.next();
                                if (i > 0)
                                    sb2.append(", ");
                                sb2.append(id);
                            }
                            ZimbraLog.redolog.info("Checkpoint discrepancy: # current uncommitted ops = " + mOpsMap.size() + ", # checkpoint uncommitted ops = " + txns.size() + "\nMAP DUMP:\n" + sb1.toString() + "\n" + sb2.toString());
                        }
                    }
                }
            } else {
                synchronized (mOpsMapGuard) {
                    if (mOpsMap.size() != 0) {
                        // Unexpected discrepancy
                        if (ZimbraLog.redolog.isDebugEnabled()) {
                            StringBuffer sb1 = new StringBuffer("Current Uncommitted Ops: ");
                            int i = 0;
                            for (Iterator it = mOpsMap.keySet().iterator(); it.hasNext(); i++) {
                                TransactionId id = (TransactionId) it.next();
                                if (i > 0)
                                    sb1.append(", ");
                                sb1.append(id);
                            }
                            ZimbraLog.redolog.info("Checkpoint discrepancy: # current uncommitted ops = " + mOpsMap.size() + " instead of 0\nMAP DUMP:\n" + sb1.toString());
                        }
                    }
                }
            }
        } else if (op.isEndMarker()) {
            // Ignore if op is a commit and its timestamp is at or after ignoreCommitsAtOrAfter.
            // In other words, don't ignore if op is a rollback OR its timestamp is before ignoreCommitsAtOrAfter.
            boolean isCommitOp = op instanceof CommitTxn;
            long opTstamp = op.getTimestamp();
            if (!isCommitOp || opTstamp < ignoreCommitsAtOrAfter) {
                // Encountered COMMIT or ABORT.  Discard the
                // corresponding op from map, and optionally execute the committed op.
                RedoableOp prepareOp;
                synchronized (mOpsMapGuard) {
                    prepareOp = (RedoableOp) mOpsMap.remove(op.getTransactionId());
                    if (prepareOp == null) {
                        mHasOrphanOps = true;
                        ZimbraLog.redolog.error("Commit/abort record encountered before corresponding change record (" + op + ")");
                        TransactionId tid = op.getTransactionId();
                        RedoableOp x = (RedoableOp) mOrphanOps.get(tid);
                        if (x != null)
                            ZimbraLog.redolog.error("Op [" + op + "] is already in orphans map: value=" + x);
                        mOrphanOps.put(tid, op);
                    }
                }
                if (redoCommitted && prepareOp != null && isCommitOp && (startTime == -1 || prepareOp.getTimestamp() >= startTime) && opTstamp < endTime) {
                    boolean allowRedo = false;
                    if (mboxIDsMap == null) {
                        // Caller doesn't care which mailbox(es) the op is for.
                        allowRedo = true;
                    } else {
                        int opMailboxId = prepareOp.getMailboxId();
                        if (prepareOp instanceof StoreIncomingBlob) {
                            assert (opMailboxId == RedoableOp.MAILBOX_ID_ALL);
                            // special case for StoreIncomingBlob op that has
                            // a list of mailbox IDs.
                            StoreIncomingBlob storeOp = (StoreIncomingBlob) prepareOp;
                            List<Integer> list = storeOp.getMailboxIdList();
                            if (list != null) {
                                Set<Integer> opMboxIds = new HashSet<Integer>(list);
                                for (Map.Entry<Integer, Integer> entry : mboxIDsMap.entrySet()) {
                                    if (opMboxIds.contains(entry.getKey())) {
                                        allowRedo = true;
                                        // Replace the mailbox ID list in the op.  We're
                                        // replaying it only for the target mailbox ID we're
                                        // interested in.
                                        List<Integer> newList = new ArrayList<Integer>(mboxIDsMap.values());
                                        storeOp.setMailboxIdList(newList);
                                        break;
                                    }
                                }
                            } else {
                                // Prior to redolog version 1.0 StoreIncomingBlob
                                // didn't keep track of mailbox list.  Always recreate
                                // the blob since we don't know which mailboxes will
                                // need it.
                                allowRedo = true;
                            }
                        } else if (opMailboxId == RedoableOp.MAILBOX_ID_ALL) {
                            // This case should be checked after StoreIncomingBlob
                            // case because StoreIncomingBlob has mailbox ID of
                            // MAILBOX_ID_ALL.
                            allowRedo = true;
                        } else {
                            for (Map.Entry<Integer, Integer> entry : mboxIDsMap.entrySet()) {
                                if (opMailboxId == entry.getKey().intValue()) {
                                    if (entry.getValue() != null) {
                                        // restore to a different mailbox
                                        prepareOp.setMailboxId(entry.getValue().intValue());
                                    }
                                    allowRedo = true;
                                    break;
                                }
                            }
                        }
                    }
                    if (allowRedo) {
                        if (mSkipDeleteOps && prepareOp.isDeleteOp()) {
                            ZimbraLog.redolog.info("Skipping delete op: " + prepareOp.toString());
                        } else {
                            try {
                                if (ZimbraLog.redolog.isDebugEnabled())
                                    ZimbraLog.redolog.debug("Redoing: " + prepareOp.toString());
                                prepareOp.setUnloggedReplay(mUnloggedReplay);
                                playOp(prepareOp);
                            } catch (Exception e) {
                                if (!ignoreReplayErrors())
                                    throw ServiceException.FAILURE("Error executing redoOp", e);
                                else
                                    ZimbraLog.redolog.warn("Ignoring error during redo log replay: " + e.getMessage(), e);
                            }
                        }
                    }
                }
            }
        }
    }
}

Example 13 with RedoableOp

use of com.zimbra.cs.redolog.op.RedoableOp in project zm-mailbox by Zimbra.

the class FileLogReader method getNextOp.

public synchronized RedoableOp getNextOp() throws IOException {
    long pos = mRAF.getFilePointer();
    if (pos == mFileSizeAtOpen) {
        // EOF reached.
        return null;
    }
    boolean first = true;
    long currPos = pos;
    while (true) {
        try {
            RedoableOp op = RedoableOp.deserializeOp(mIN);
            mLastOpStartOffset = currPos;
            if (!first) {
                String msg = String.format("Skipped bad bytes in redolog %s; resuming at offset 0x%08x after skipping %d bytes", mFile.getAbsolutePath(), currPos, currPos - pos);
                ZimbraLog.redolog.warn(msg);
            }
            return op;
        } catch (IOException e) {
            if (e instanceof EOFException)
                throw e;
            if (first) {
                String msg = String.format("Error while parsing redolog %s, offset=0x%08x; bad bytes will be skipped", mFile.getAbsolutePath(), pos);
                ZimbraLog.redolog.warn(msg, e);
            }
        }
        first = false;
        // Skip over bad bytes by looking for the next occurrence of "ZMREDO" redo op marker.
        mRAF.seek(currPos + 1);
        if (searchInRAF(RedoableOp.REDO_MAGIC.getBytes())) {
            currPos = mRAF.getFilePointer();
        } else {
            String msg = String.format("Found %d junk bytes from offset 0x%08x to end of file, in redolog %s", mFileSizeAtOpen - pos, pos, mFile.getAbsolutePath());
            throw new IOException(msg);
        }
    }
}

Example 14 with RedoableOp

use of com.zimbra.cs.redolog.op.RedoableOp in project zm-mailbox by Zimbra.

the class FileLogWriter method rollover.

@SuppressWarnings("unchecked")
@Override
public synchronized File rollover(LinkedHashMap activeOps) throws IOException {
    RolloverManager romgr = mRedoLogMgr.getRolloverManager();
    long lastSeq = getSequence();
    // Close current log, so it's impossible for its content to change.
    noStat(true);
    close();
    romgr.incrementSequence();
    String currentPath = mFile.getAbsolutePath();
    // Open a temporary logger.
    File tempLogfile = new File(mFile.getParentFile(), romgr.getTempFilename(lastSeq + 1));
    FileLogWriter tempLogger = new FileLogWriter(mRedoLogMgr, tempLogfile, 0);
    tempLogger.open();
    tempLogger.noStat(true);
    // Rewrite change entries for all active operations, maintaining
    // their order of occurrence.  (LinkedHashMap ensures ordering.)
    Set opsSet = activeOps.entrySet();
    for (Iterator it = opsSet.iterator(); it.hasNext(); ) {
        Map.Entry entry = (Map.Entry) it.next();
        RedoableOp op = (RedoableOp) entry.getValue();
        tempLogger.log(op, op.getInputStream(), false);
    }
    tempLogger.close();
    // Rename the current log to rolled-over name.
    File rolloverFile = romgr.getRolloverFile(lastSeq);
    if (RedoConfig.redoLogDeleteOnRollover()) {
        // indexing-only log files after rollover.
        if (!mFile.delete())
            throw new IOException("Unable to delete current redo log " + mFile.getAbsolutePath());
    } else {
        File destDir = rolloverFile.getParentFile();
        if (destDir != null && !destDir.exists())
            destDir.mkdirs();
        if (!mFile.renameTo(rolloverFile))
            throw new IOException("Unable to rename current redo log to " + rolloverFile.getAbsolutePath());
    }
    // Rename the temporary logger to current logfile name.
    String tempPath = tempLogfile.getAbsolutePath();
    mFile = new File(currentPath);
    if (!tempLogfile.renameTo(mFile))
        throw new IOException("Unable to rename " + tempPath + " to " + currentPath);
    // Reopen current log.
    open();
    noStat(false);
    return rolloverFile;
}