Examples with FileLogReader com.zimbra.cs.redolog.logger.FileLogReader used on opensource projects

Example 1 with FileLogReader

use of com.zimbra.cs.redolog.logger.FileLogReader in project zm-mailbox by Zimbra.

the class RedoLogVerify method scanLog.

public boolean scanLog(File logfile) throws IOException {
    boolean good = false;
    FileLogReader logReader = new FileLogReader(logfile, false);
    logReader.open();
    if (!mParams.quiet) {
        FileHeader header = logReader.getHeader();
        mOut.println("HEADER");
        mOut.println("------");
        mOut.print(header);
        mOut.println("------");
    }
    boolean hasMailboxIdsFilter = !mParams.mboxIds.isEmpty();
    RedoableOp op = null;
    long lastPosition = 0;
    long lastOpStartOffset = 0;
    try {
        while ((op = logReader.getNextOp()) != null) {
            lastOpStartOffset = logReader.getLastOpStartOffset();
            lastPosition = logReader.position();
            if (hasMailboxIdsFilter) {
                int mboxId = op.getMailboxId();
                if (op instanceof StoreIncomingBlob) {
                    List<Integer> list = ((StoreIncomingBlob) op).getMailboxIdList();
                    if (list != null) {
                        boolean match = false;
                        for (Integer mid : list) {
                            if (mParams.mboxIds.contains(mid)) {
                                match = true;
                                break;
                            }
                        }
                        if (!match)
                            continue;
                    }
                // If list==null, it's a store incoming blob op targeted at unknown set of mailboxes.
                // It applies to our filtered mailboxes.
                } else if (!mParams.mboxIds.contains(mboxId)) {
                    continue;
                }
            }
            if (!mParams.quiet) {
                printOp(mOut, op, mParams.hideOffset, lastOpStartOffset, lastPosition - lastOpStartOffset);
                if (mParams.showBlob) {
                    InputStream dataStream = op.getAdditionalDataStream();
                    if (dataStream != null) {
                        mOut.println("<START OF BLOB>");
                        ByteUtil.copy(dataStream, true, mOut, false);
                        mOut.println();
                        mOut.println("<END OF BLOB>");
                    }
                }
            }
        }
        good = true;
    } catch (IOException e) {
        // The IOException could be a real I/O problem or it could mean
        // there was a server crash previously and there were half-written
        // log entries.
        mOut.println();
        mOut.printf("Error while parsing data starting at offset 0x%08x", lastPosition);
        mOut.println();
        long size = logReader.getSize();
        long diff = size - lastPosition;
        mOut.printf("%d bytes remaining in the file", diff);
        mOut.println();
        mOut.println();
        if (op != null) {
            mOut.println("Last suceessfully parsed redo op:");
            printOp(mOut, op, false, lastOpStartOffset, lastPosition - lastOpStartOffset);
            mOut.println();
        }
        // hexdump data around the bad bytes
        int bytesPerLine = 16;
        int linesBefore = 10;
        int linesAfter = 10;
        long startPos = Math.max(lastPosition - (lastPosition % bytesPerLine) - linesBefore * bytesPerLine, 0);
        int count = (int) Math.min((linesBefore + linesAfter + 1) * bytesPerLine, lastPosition - startPos + diff);
        RandomAccessFile raf = null;
        try {
            raf = new RandomAccessFile(logfile, "r");
            raf.seek(startPos);
            byte[] buf = new byte[count];
            raf.read(buf, 0, count);
            mOut.printf("Data near error offset %08x:", lastPosition);
            mOut.println();
            hexdump(mOut, buf, 0, count, startPos, lastPosition);
            mOut.println();
        } catch (IOException eh) {
            mOut.println("Error opening log file " + logfile.getAbsolutePath() + " for hexdump");
            eh.printStackTrace(mOut);
        } finally {
            if (raf != null)
                raf.close();
        }
        throw e;
    } finally {
        logReader.close();
    }
    return good;
}

Example 2 with FileLogReader

use of com.zimbra.cs.redolog.logger.FileLogReader in project zm-mailbox by Zimbra.

the class RedoLogManager method getChangedMailboxesSince.

/**
     * Returns the set of mailboxes that had any committed changes since a
     * particular CommitId in the past, by scanning redologs.  Also returns
     * the last CommitId seen during the scanning process.
     * @param cid
     * @return can be null if server is shutting down
     * @throws IOException
     * @throws MailServiceException
     */
public Pair<Set<Integer>, CommitId> getChangedMailboxesSince(CommitId cid) throws IOException, MailServiceException {
    Set<Integer> mailboxes = new HashSet<Integer>();
    // Grab a read lock to prevent rollover.
    ReadLock readLock = mRWLock.readLock();
    try {
        readLock.lockInterruptibly();
    } catch (InterruptedException e) {
        synchronized (mShuttingDownGuard) {
            if (!mShuttingDown)
                ZimbraLog.redolog.error("InterruptedException during redo log scan for CommitId", e);
            else
                ZimbraLog.redolog.debug("Redo log scan for CommitId interrupted for shutdown");
        }
        return null;
    }
    File linkDir = null;
    File[] logs;
    try {
        try {
            long seq = cid.getRedoSeq();
            File[] archived = getArchivedLogsFromSequence(seq);
            if (archived != null) {
                logs = new File[archived.length + 1];
                System.arraycopy(archived, 0, logs, 0, archived.length);
                logs[archived.length] = mLogFile;
            } else {
                logs = new File[] { mLogFile };
            }
            // Make sure the first log has the sequence in cid.
            FileLogReader firstLog = new FileLogReader(logs[0]);
            if (firstLog.getHeader().getSequence() != seq) {
                // Most likely, the CommitId is too old.
                throw MailServiceException.INVALID_COMMIT_ID(cid.toString());
            }
            // Create a temp directory and make hard links to all redologs.
            // This prevents the logs from disappearing while being scanned.
            String dirName = "tmp-scan-" + System.currentTimeMillis();
            linkDir = new File(mLogFile.getParentFile(), dirName);
            if (linkDir.exists()) {
                int suffix = 1;
                while (linkDir.exists()) {
                    linkDir = new File(mLogFile.getParentFile(), dirName + "-" + suffix);
                }
            }
            if (!linkDir.mkdir())
                throw new IOException("Unable to create temp dir " + linkDir.getAbsolutePath());
            for (int i = 0; i < logs.length; i++) {
                File src = logs[i];
                File dest = new File(linkDir, logs[i].getName());
                IO.link(src.getAbsolutePath(), dest.getAbsolutePath());
                logs[i] = dest;
            }
        } finally {
            // We can let rollover happen now.
            readLock.unlock();
        }
        // Scan redologs to get list with IDs of mailboxes that have
        // committed changes since the given commit id.
        long lastSeq = -1;
        CommitTxn lastCommitTxn = null;
        boolean foundMarker = false;
        for (File logfile : logs) {
            FileLogReader logReader = new FileLogReader(logfile);
            logReader.open();
            lastSeq = logReader.getHeader().getSequence();
            try {
                RedoableOp op = null;
                while ((op = logReader.getNextOp()) != null) {
                    if (ZimbraLog.redolog.isDebugEnabled())
                        ZimbraLog.redolog.debug("Read: " + op);
                    if (!(op instanceof CommitTxn))
                        continue;
                    lastCommitTxn = (CommitTxn) op;
                    if (foundMarker) {
                        int mboxId = op.getMailboxId();
                        if (mboxId > 0)
                            mailboxes.add(mboxId);
                    } else {
                        if (cid.matches(lastCommitTxn))
                            foundMarker = true;
                    }
                }
            } catch (IOException e) {
                ZimbraLog.redolog.warn("IOException while reading redolog file", e);
            } finally {
                logReader.close();
            }
        }
        if (!foundMarker) {
            // Most likely, the CommitId is too old.
            throw MailServiceException.INVALID_COMMIT_ID(cid.toString());
        }
        CommitId lastCommitId = new CommitId(lastSeq, lastCommitTxn);
        return new Pair<Set<Integer>, CommitId>(mailboxes, lastCommitId);
    } finally {
        if (linkDir != null) {
            // Clean up the temp dir with links.
            try {
                if (linkDir.exists())
                    FileUtil.deleteDir(linkDir);
            } catch (IOException e) {
                ZimbraLog.redolog.warn("Unable to delete temporary directory " + linkDir.getAbsolutePath(), e);
            }
        }
    }
}

Example 3 with FileLogReader

use of com.zimbra.cs.redolog.logger.FileLogReader in project zm-mailbox by Zimbra.

the class RedoPlayer method scanLog.

/**
     * Scans a redo log file.  An op that is neither committed nor aborted is
     * added to mOpsMap.  These are the ops that need to be reattempted during
     * crash recovery.  If redoCommitted is true, an op is reattempted as soon
     * as its COMMIT entry is encountered.  This case is for replaying the logs
     * during mailbox restore.
     * @param logfile
     * @param redoCommitted
     * @param mboxIDsMap If not null, restrict replay of log entries to
     *                   mailboxes whose IDs are given by the key set of the
     *                   map.  Replay is done against mailboxes whose IDs are
     *                   given by the value set of the map.  Thus, it is
     *                   possible to replay operations from one mailbox in
     *                   a different mailbox.
     * @param startTime  Only process ops whose prepare time is at or later than
     *                   this time.
     * @param endTime    Only process ops whose commit time is before (but not
     *                   at) this time.
     * @param ignoreCommitsAtOrAfter Ops that were committed at or after this timestamp are ignored.
     *                               They will not be replayed even when redoCommitted=true.  They will
     *                               be considered uncommitted, and thus will become eligible for replay
     *                               during crash recovery.  For uses other than crash recovery, pass
     *                               Long.MAX_VALUE to not ignore any committed ops.
     * @throws IOException
     */
private void scanLog(File logfile, boolean redoCommitted, Map<Integer, Integer> mboxIDsMap, long startTime, long endTime, long ignoreCommitsAtOrAfter) throws IOException, ServiceException {
    FileLogReader logReader = new FileLogReader(logfile, mWritable);
    logReader.open();
    long lastPosition = 0;
    // Read all ops in redo log, discarding those with commit/abort entries.
    try {
        RedoableOp op = null;
        while ((op = logReader.getNextOp()) != null) {
            lastPosition = logReader.position();
            if (ZimbraLog.redolog.isDebugEnabled())
                ZimbraLog.redolog.debug("Read: " + op);
            processOp(op, redoCommitted, mboxIDsMap, startTime, endTime, ignoreCommitsAtOrAfter);
        }
    } catch (IOException e) {
        // The IOException could be a real I/O problem or it could mean
        // there was a server crash previously and there were half-written
        // log entries.  We can't really tell which case it is, so just
        // assume the second case and truncate the file after the last
        // successfully read item.
        ZimbraLog.redolog.warn("IOException while reading redolog file", e);
        long size = logReader.getSize();
        if (lastPosition < size) {
            long diff = size - lastPosition;
            String msg = "There were " + diff + " bytes of junk data at the end of " + logfile.getAbsolutePath() + ".";
            if (mWritable) {
                ZimbraLog.redolog.warn(msg + "  File will be truncated to " + lastPosition + " bytes.");
                logReader.truncate(lastPosition);
            } else
                ZimbraLog.redolog.warn(msg);
        }
    } finally {
        logReader.close();
    }
}

Example 4 with FileLogReader

use of com.zimbra.cs.redolog.logger.FileLogReader 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 5 with FileLogReader

use of com.zimbra.cs.redolog.logger.FileLogReader in project zm-mailbox by Zimbra.

the class PlaybackUtil method initParams.

private static Params initParams(CommandLine cl) throws ServiceException, IOException {
    Params params = new Params();
    params.help = cl.hasOption(OPT_HELP);
    if (params.help)
        return params;
    params.stopOnError = cl.hasOption(OPT_STOP_ON_ERROR);
    if (cl.hasOption(OPT_FROM_TIME)) {
        String timeStr = cl.getOptionValue(OPT_FROM_TIME);
        Date time = SoapCLI.parseDatetime(timeStr);
        if (time != null) {
            params.fromTime = time.getTime();
            SimpleDateFormat f = new SimpleDateFormat(SoapCLI.CANONICAL_DATETIME_FORMAT);
            String tstamp = f.format(time);
            System.out.printf("Using from-time of %s\n", tstamp);
        } else {
            System.err.printf("Invalid timestamp \"%s\" specified for --%s option\n", timeStr, OPT_FROM_TIME);
            System.err.println();
            System.err.print(SoapCLI.getAllowedDatetimeFormatsHelp());
            System.exit(1);
        }
    }
    if (cl.hasOption(OPT_FROM_SEQ)) {
        params.fromSeq = Long.parseLong(cl.getOptionValue(OPT_FROM_SEQ));
        System.out.printf("Using from-sequence of %d\n", params.fromSeq);
    }
    if (cl.hasOption(OPT_TO_TIME)) {
        String timeStr = cl.getOptionValue(OPT_TO_TIME);
        Date time = SoapCLI.parseDatetime(timeStr);
        if (time != null) {
            params.toTime = time.getTime();
            SimpleDateFormat f = new SimpleDateFormat(SoapCLI.CANONICAL_DATETIME_FORMAT);
            String tstamp = f.format(time);
            System.out.printf("Using to-time of %s\n", tstamp);
        } else {
            System.err.printf("Invalid timestamp \"%s\" specified for --%s option\n", timeStr, OPT_TO_TIME);
            System.err.println();
            System.err.print(SoapCLI.getAllowedDatetimeFormatsHelp());
            System.exit(1);
        }
    }
    if (cl.hasOption(OPT_TO_SEQ)) {
        params.toSeq = Long.parseLong(cl.getOptionValue(OPT_TO_SEQ));
        System.out.printf("Using to-sequence of %d\n", params.toSeq);
    }
    if (params.fromSeq > params.toSeq) {
        System.err.println("Error: fromSeq greater than toSeq");
        System.exit(1);
    }
    if (params.fromTime > params.toTime) {
        System.err.println("Error: fromTime later than toTime");
        System.exit(1);
    }
    if (cl.hasOption(OPT_MAILBOX_ID)) {
        params.mboxId = Integer.parseInt(cl.getOptionValue(OPT_MAILBOX_ID));
        System.out.printf("Replaying operations for mailbox %d only\n", params.mboxId);
    } else {
        System.out.println("Replaying operations for all mailboxes");
    }
    if (cl.hasOption(OPT_THREADS))
        params.threads = Integer.parseInt(cl.getOptionValue(OPT_THREADS));
    System.out.printf("Using %d redo player threads\n", params.threads);
    if (cl.hasOption(OPT_QUEUE_CAPACITY))
        params.queueCapacity = Integer.parseInt(cl.getOptionValue(OPT_QUEUE_CAPACITY));
    System.out.printf("Using %d as queue capacity for each redo player thread\n", params.queueCapacity);
    List<File> logList = new ArrayList<File>();
    if (cl.hasOption(OPT_LOGFILES)) {
        String[] fnames = cl.getOptionValues(OPT_LOGFILES);
        params.logfiles = new File[fnames.length];
        for (int i = 0; i < fnames.length; i++) {
            File f = new File(fnames[i]);
            if (f.exists())
                logList.add(f);
            else
                throw new FileNotFoundException("No such file: " + f.getAbsolutePath());
        }
    } else {
        // By default, use /opt/zimbra/redolog/archive/*, then /opt/zimbra/redolog/redo.log,
        // ordered by log sequence.
        Provisioning prov = Provisioning.getInstance();
        Server server = prov.getLocalServer();
        String archiveDirPath = Config.getPathRelativeToZimbraHome(server.getAttr(Provisioning.A_zimbraRedoLogArchiveDir, "redolog/archive")).getAbsolutePath();
        String redoLogPath = Config.getPathRelativeToZimbraHome(server.getAttr(Provisioning.A_zimbraRedoLogLogPath, "redolog/redo.log")).getAbsolutePath();
        File archiveDir = new File(archiveDirPath);
        if (archiveDir.exists()) {
            File[] archiveLogs = RolloverManager.getArchiveLogs(archiveDir, params.fromSeq, params.toSeq);
            for (File f : archiveLogs) {
                logList.add(f);
            }
        }
        File redoLog = new File(redoLogPath);
        if (redoLog.exists()) {
            FileLogReader logReader = new FileLogReader(redoLog);
            long seq = logReader.getHeader().getSequence();
            if (params.fromSeq <= seq && seq <= params.toSeq)
                logList.add(redoLog);
        }
    }
    // Filter out logs based on from/to times.
    for (Iterator<File> iter = logList.iterator(); iter.hasNext(); ) {
        File f = iter.next();
        FileHeader hdr = (new FileLogReader(f)).getHeader();
        if (hdr.getFirstOpTstamp() > params.toTime || (hdr.getLastOpTstamp() < params.fromTime && !hdr.getOpen())) {
            // log is outside the time range
            iter.remove();
            System.out.printf("Redolog %s has no operation in the requested time range\n", f.getName());
        }
    }
    params.logfiles = new File[logList.size()];
    params.logfiles = logList.toArray(params.logfiles);
    System.out.printf("%d redolog files to play back\n", params.logfiles.length);
    return params;
}