0001: /*
0002:
0003: Derby - Class org.apache.derby.impl.store.raw.log.FileLogger
0004:
0005: Licensed to the Apache Software Foundation (ASF) under one or more
0006: contributor license agreements. See the NOTICE file distributed with
0007: this work for additional information regarding copyright ownership.
0008: The ASF licenses this file to you under the Apache License, Version 2.0
0009: (the "License"); you may not use this file except in compliance with
0010: the License. You may obtain a copy of the License at
0011:
0012: http://www.apache.org/licenses/LICENSE-2.0
0013:
0014: Unless required by applicable law or agreed to in writing, software
0015: distributed under the License is distributed on an "AS IS" BASIS,
0016: WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
0017: See the License for the specific language governing permissions and
0018: limitations under the License.
0019:
0020: */
0021:
0022: package org.apache.derby.impl.store.raw.log;
0023:
0024: import org.apache.derby.iapi.reference.SQLState;
0025: import org.apache.derby.iapi.reference.MessageId;
0026:
0027: import org.apache.derby.impl.store.raw.log.LogCounter;
0028: import org.apache.derby.impl.store.raw.log.LogRecord;
0029: import org.apache.derby.impl.store.raw.log.StreamLogScan;
0030:
0031: import org.apache.derby.iapi.store.access.TransactionController;
0032:
0033: import org.apache.derby.iapi.store.raw.RawStoreFactory;
0034:
0035: import org.apache.derby.iapi.store.raw.log.LogInstant;
0036: import org.apache.derby.iapi.store.raw.log.Logger;
0037: import org.apache.derby.iapi.store.raw.log.LogScan;
0038:
0039: import org.apache.derby.iapi.store.raw.xact.RawTransaction;
0040: import org.apache.derby.iapi.store.raw.xact.TransactionFactory;
0041: import org.apache.derby.iapi.store.raw.xact.TransactionId;
0042:
0043: import org.apache.derby.iapi.store.raw.Compensation;
0044: import org.apache.derby.iapi.store.raw.ContainerHandle;
0045: import org.apache.derby.iapi.store.raw.LockingPolicy;
0046: import org.apache.derby.iapi.store.raw.Loggable;
0047: import org.apache.derby.iapi.store.raw.Page;
0048: import org.apache.derby.iapi.store.raw.RePreparable;
0049: import org.apache.derby.iapi.store.raw.Undoable;
0050:
0051: import org.apache.derby.iapi.services.io.FormatIdOutputStream;
0052:
0053: import org.apache.derby.iapi.services.sanity.SanityManager;
0054:
0055: import org.apache.derby.iapi.error.StandardException;
0056: import org.apache.derby.iapi.services.i18n.MessageService;
0057:
0058: import org.apache.derby.iapi.services.io.ArrayInputStream;
0059: import org.apache.derby.iapi.services.io.ArrayOutputStream;
0060: import org.apache.derby.iapi.util.ByteArray;
0061: import org.apache.derby.iapi.services.io.DynamicByteArrayOutputStream;
0062:
0063: import org.apache.derby.iapi.services.io.LimitObjectInput;
0064: import java.io.IOException;
0065:
0066: import org.apache.derby.impl.store.raw.data.InitPageOperation;
0067:
0068: /**
0069: Write log records to a log file as a stream
0070: (ie. log records added to the end of the file, no concept of pages).
0071: <P>
0072: The format of a log record that is not a compensation operation is
0073: <PRE>
0074: @format_id no formatId, format is implied by the log file format and the
0075: log record content.
0076: @purpose the log record and optional data
0077: @upgrade
0078: @disk_layout
0079: Log Record
0080: (see org.apache.derby.impl.store.raw.log.LogRecord)
0081: length(int) length of optional data
0082: optionalData(byte[length]) optional data written by the log record
0083: @end_format
0084: </PRE> <HR WIDTH="100%">
0085:
0086: <P> The form of a log record that is a compensation operation is
0087: <PRE>
0088: @format_id no formatId, format is implied by the log file format and the
0089: log record content.
0090: @purpose undo a previous log record
0091: @upgrade
0092: @disk_layout
0093: Log Record that contains the compenstation operation
0094: (see org.apache.derby.impl.store.raw.log.LogRecord)
0095: undoInstant(long) the log instant of the operation that is to be rolled back
0096: The undo instant is logically part of the LogRecord but is written
0097: by the logger because it is used and controlled by the rollback
0098: code but not by the log operation.
0099: There is no optional data in a compensation operation, all data
0100: necessary for the rollback must be stored in the operation being
0101: undone.
0102: @end_format
0103: </PRE>
0104:
0105: <BR>
0106:
0107: <P>Multithreading considerations:<BR>
0108: Logger must be MT-safe. Each RawTransaction has its own private
0109: FileLogger object. Each logger has a logOutputBuffer and a log input
0110: buffer which are used to read and write to the log. Since multiple
0111: threads can be in the same transaction, fileLogger must be synchronized.
0112:
0113: @see LogRecord
0114: */
0115:
0116: public class FileLogger implements Logger {
0117:
0118: private LogRecord logRecord;
0119:
0120: protected byte[] encryptionBuffer;
0121: private DynamicByteArrayOutputStream logOutputBuffer;
0122: private FormatIdOutputStream logicalOut;
0123:
0124: private ArrayInputStream logIn;
0125:
0126: private LogToFile logFactory; // actually writes the log records.
0127:
0128: /**
0129: Make a new Logger with its own log record buffers
0130: MT - not needed for constructor
0131: */
0132: public FileLogger(LogToFile logFactory) {
0133:
0134: this .logFactory = logFactory;
0135: logOutputBuffer = new DynamicByteArrayOutputStream(1024); // init size 1K
0136: logicalOut = new FormatIdOutputStream(logOutputBuffer);
0137:
0138: // logIn and logOutputBuffer must share the same buffer because they
0139: // combined to form an IO stream to access the same log record.
0140: //
0141: // Before each use of logIn, you must reset logIn's data to the
0142: // byte array you want to read from.
0143: //
0144: // To log a record, set logIn's data to point to logOutputBuffer's
0145: // byte array when you know you have everything you need in the output
0146: // buffer, then set limit on logIn and send it to the log operation's
0147: // doMe.
0148: //
0149: // Keep in mind the dynamic nature of the logOutputBuffer which means
0150: // it could switch buffer from underneath the logOutputBuffer on every
0151: // write.
0152: logIn = new ArrayInputStream();
0153:
0154: logRecord = new LogRecord();
0155:
0156: }
0157:
0158: /**
0159: Close the logger.
0160: MT - caller provide synchronization
0161: (RESOLVE: not called by anyone ??)
0162: */
0163: public void close() throws IOException {
0164: if (logOutputBuffer != null) {
0165: logOutputBuffer.close();
0166: logOutputBuffer = null;
0167: }
0168:
0169: logIn = null;
0170: logFactory = null;
0171:
0172: logicalOut = null;
0173:
0174: logRecord = null;
0175: }
0176:
0177: /*
0178: ** Methods of Logger
0179: */
0180:
0181: /**
0182: Writes out a log record to the log stream, and call its doMe method to
0183: apply the change to the rawStore.
0184: <BR>Any optional data the doMe method need is first written to the log
0185: stream using operation.writeOptionalData, then whatever is written to
0186: the log stream is passed back to the operation for the doMe method.
0187:
0188: <P>MT - there could be multiple threads running in the same raw
0189: transactions and they can be calling the same logger to log different
0190: log operations. This whole method is synchronized to make sure log
0191: records are logged one at a time.
0192:
0193: @param xact the transaction logging the change
0194: @param operation the log operation
0195: @return the instant in the log that can be used to identify the log
0196: record
0197:
0198: @exception StandardException Cloudscape Standard error policy
0199: */
0200: public synchronized LogInstant logAndDo(RawTransaction xact,
0201: Loggable operation) throws StandardException {
0202: boolean isLogPrepared = false;
0203:
0204: boolean inUserCode = false;
0205: byte[] preparedLog;
0206:
0207: try {
0208:
0209: logOutputBuffer.reset();
0210:
0211: // always use the short Id, only the BeginXact log record contains
0212: // the XactId (long form)
0213: TransactionId transactionId = xact.getId();
0214:
0215: // write out the log header with the operation embedded
0216: // this is by definition not a compensation log record,
0217: // those are called thru the logAndUndo interface
0218: logRecord.setValue(transactionId, operation);
0219:
0220: inUserCode = true;
0221: logicalOut.writeObject(logRecord);
0222: inUserCode = false;
0223:
0224: int optionalDataLength = 0;
0225: int optionalDataOffset = 0;
0226: int completeLength = 0;
0227:
0228: ByteArray preparedLogArray = operation.getPreparedLog();
0229: if (preparedLogArray != null) {
0230:
0231: preparedLog = preparedLogArray.getArray();
0232: optionalDataLength = preparedLogArray.getLength();
0233: optionalDataOffset = preparedLogArray.getOffset();
0234:
0235: // There is a race condition if the operation is a begin tran in
0236: // that between the time the beginXact log record is written to
0237: // disk and the time the transaction object is updated in the
0238: // beginXact.doMe method, other log records may be written.
0239: // This will render the transaction table in an inconsistent state
0240: // since it may think a later transaction is the earliest
0241: // transaction or it may think that there is no active transactions
0242: // where there is a bunch of them sitting on the log.
0243: //
0244: // Similarly, there is a race condition for endXact, i.e.,
0245: // 1) endXact is written to the log,
0246: // 2) checkpoint gets that (committed) transaction as the
0247: // firstUpdateTransaction
0248: // 3) the transaction calls postComplete, nulling out itself
0249: // 4) checkpoint tries to access a closed transaction object
0250: //
0251: // The solution is to sync between the time a begin tran or end
0252: // tran log record is sent to the log stream and its doMe method is
0253: // called to update the transaction table and in memory state
0254: //
0255: // We only need to serialized the begin and end Xact log records
0256: // because once a transaction has been started and in the
0257: // transaction table, its order and transaction state does not
0258: // change.
0259: //
0260: // Use the logFactory as the sync object so that a checkpoint can
0261: // take its snap shot of the undoLWM before or after a transaction
0262: // is started, but not in the middle. (see LogToFile.checkpoint)
0263: //
0264:
0265: // now set the input limit to be the optional data.
0266: // This limits amount of data availiable to logIn that doMe can
0267: // use
0268: logIn.setData(preparedLog);
0269: logIn.setPosition(optionalDataOffset);
0270: logIn.setLimit(optionalDataLength);
0271:
0272: if (SanityManager.DEBUG) {
0273: if ((optionalDataLength) != logIn.available())
0274: SanityManager
0275: .THROWASSERT(" stream not set correctly "
0276: + optionalDataLength
0277: + " != "
0278: + logIn.available());
0279: }
0280:
0281: } else {
0282: preparedLog = null;
0283: optionalDataLength = 0;
0284: }
0285:
0286: logicalOut.writeInt(optionalDataLength);
0287: completeLength = logOutputBuffer.getPosition()
0288: + optionalDataLength;
0289:
0290: LogInstant logInstant = null;
0291: int encryptedLength = 0; // in case of encryption, we need to pad
0292:
0293: try {
0294: if (logFactory.databaseEncrypted()) {
0295: // we must pad the encryption data to be multiple of block
0296: // size, which is logFactory.getEncryptionBlockSize()
0297: encryptedLength = completeLength;
0298: if ((encryptedLength % logFactory
0299: .getEncryptionBlockSize()) != 0)
0300: encryptedLength = encryptedLength
0301: + logFactory.getEncryptionBlockSize()
0302: - (encryptedLength % logFactory
0303: .getEncryptionBlockSize());
0304:
0305: if (encryptionBuffer == null
0306: || encryptionBuffer.length < encryptedLength)
0307: encryptionBuffer = new byte[encryptedLength];
0308:
0309: System.arraycopy(logOutputBuffer.getByteArray(), 0,
0310: encryptionBuffer, 0, completeLength
0311: - optionalDataLength);
0312:
0313: if (optionalDataLength > 0)
0314: System.arraycopy(preparedLog,
0315: optionalDataOffset, encryptionBuffer,
0316: completeLength - optionalDataLength,
0317: optionalDataLength);
0318:
0319: // do not bother to clear out the padding area
0320: int len = logFactory.encrypt(encryptionBuffer, 0,
0321: encryptedLength, encryptionBuffer, 0);
0322:
0323: if (SanityManager.DEBUG)
0324: SanityManager
0325: .ASSERT(len == encryptedLength,
0326: "encrypted log buffer length != log buffer len");
0327: }
0328:
0329: if ((operation.group() & (Loggable.FIRST | Loggable.LAST)) != 0) {
0330: synchronized (logFactory) {
0331: long instant = 0;
0332:
0333: if (logFactory.databaseEncrypted()) {
0334: // encryption has completely drained both the the
0335: // logOuputBuffer array and the preparedLog array
0336: instant = logFactory.appendLogRecord(
0337: encryptionBuffer, 0,
0338: encryptedLength, null, -1, 0);
0339: } else {
0340: instant = logFactory.appendLogRecord(
0341: logOutputBuffer.getByteArray(), 0,
0342: completeLength, preparedLog,
0343: optionalDataOffset,
0344: optionalDataLength);
0345: }
0346: logInstant = new LogCounter(instant);
0347:
0348: operation.doMe(xact, logInstant, logIn);
0349: }
0350: } else {
0351: long instant = 0;
0352:
0353: if (logFactory.databaseEncrypted()) {
0354: // encryption has completely drained both the the
0355: // logOuputBuffer array and the preparedLog array
0356: instant = logFactory.appendLogRecord(
0357: encryptionBuffer, 0, encryptedLength,
0358: null, -1, 0);
0359: } else {
0360: instant = logFactory.appendLogRecord(
0361: logOutputBuffer.getByteArray(), 0,
0362: completeLength, preparedLog,
0363: optionalDataOffset, optionalDataLength);
0364: }
0365:
0366: logInstant = new LogCounter(instant);
0367:
0368: operation.doMe(xact, logInstant, logIn);
0369: }
0370:
0371: } catch (StandardException se) {
0372: throw logFactory.markCorrupt(StandardException
0373: .newException(SQLState.LOG_DO_ME_FAIL, se,
0374: operation));
0375: } catch (IOException ioe) {
0376: throw logFactory.markCorrupt(StandardException
0377: .newException(SQLState.LOG_DO_ME_FAIL, ioe,
0378: operation));
0379: } finally {
0380: logIn.clearLimit();
0381: }
0382:
0383: if (SanityManager.DEBUG) {
0384: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0385: SanityManager.DEBUG(LogToFile.DBG_FLAG,
0386: "Write log record: tranId="
0387: + transactionId.toString()
0388: + " instant: "
0389: + logInstant.toString()
0390: + " length: " + completeLength
0391: + "\n" + operation + "\n");
0392: }
0393: }
0394: return logInstant;
0395: }
0396:
0397: catch (IOException ioe) {
0398: // error writing to the log buffer
0399: if (inUserCode) {
0400: throw StandardException.newException(
0401: SQLState.LOG_WRITE_LOG_RECORD, ioe, operation);
0402: } else {
0403: throw StandardException.newException(
0404: SQLState.LOG_BUFFER_FULL, ioe, operation);
0405: }
0406: }
0407:
0408: }
0409:
0410: /**
0411: Writes out a compensation log record to the log stream, and call its
0412: doMe method to undo the change of a previous log operation.
0413:
0414: <P>MT - Not needed. A transaction must be single threaded thru undo, each
0415: RawTransaction has its own logger, therefore no need to synchronize.
0416: The RawTransaction must handle synchronizing with multiple threads
0417: during rollback.
0418:
0419: @param xact the transaction logging the change
0420: @param compensation the compensation log operation
0421: @param undoInstant the log instant of the operation that is to be
0422: rolled back
0423: @param in optional data input for the compenastion doMe method
0424:
0425: @return the instant in the log that can be used to identify the log
0426: record
0427:
0428: @exception StandardException Cloudscape Standard error policy
0429: */
0430: public LogInstant logAndUndo(RawTransaction xact,
0431: Compensation compensation, LogInstant undoInstant,
0432: LimitObjectInput in) throws StandardException {
0433: boolean inUserCode = false;
0434:
0435: try {
0436: logOutputBuffer.reset();
0437:
0438: TransactionId transactionId = xact.getId();
0439:
0440: // write out the log header with the operation embedded
0441: logRecord.setValue(transactionId, compensation);
0442:
0443: inUserCode = true;
0444: logicalOut.writeObject(logRecord);
0445: inUserCode = false;
0446:
0447: // write out the undoInstant
0448: logicalOut.writeLong(((LogCounter) undoInstant)
0449: .getValueAsLong());
0450:
0451: // in this implemetaion, there is no optional data for the
0452: // compensation operation. Optional data for the rollback comes
0453: // from the undoable operation - and is passed into this call.
0454: int completeLength = logOutputBuffer.getPosition();
0455: long instant = 0;
0456:
0457: if (logFactory.databaseEncrypted()) {
0458: // we must pad the encryption data to be multiple of block
0459: // size, which is logFactory.getEncryptionBlockSize()
0460: int encryptedLength = completeLength;
0461: if ((encryptedLength % logFactory
0462: .getEncryptionBlockSize()) != 0)
0463: encryptedLength = encryptedLength
0464: + logFactory.getEncryptionBlockSize()
0465: - (encryptedLength % logFactory
0466: .getEncryptionBlockSize());
0467:
0468: if (encryptionBuffer == null
0469: || encryptionBuffer.length < encryptedLength)
0470: encryptionBuffer = new byte[encryptedLength];
0471:
0472: System.arraycopy(logOutputBuffer.getByteArray(), 0,
0473: encryptionBuffer, 0, completeLength);
0474:
0475: // do not bother to clear out the padding area
0476: int len = logFactory.encrypt(encryptionBuffer, 0,
0477: encryptedLength, encryptionBuffer, 0);
0478:
0479: if (SanityManager.DEBUG)
0480: SanityManager
0481: .ASSERT(len == encryptedLength,
0482: "encrypted log buffer length != log buffer len");
0483:
0484: instant = logFactory.appendLogRecord(encryptionBuffer,
0485: 0, encryptedLength, null, 0, 0);
0486: } else {
0487: instant = logFactory.appendLogRecord(logOutputBuffer
0488: .getByteArray(), 0, completeLength, null, 0, 0);
0489: }
0490:
0491: LogInstant logInstant = new LogCounter(instant);
0492:
0493: if (SanityManager.DEBUG) {
0494: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0495: SanityManager.DEBUG(LogToFile.DBG_FLAG,
0496: "Write CLR: Xact: "
0497: + transactionId.toString()
0498: + "clrinstant: "
0499: + logInstant.toString()
0500: + " undoinstant " + undoInstant
0501: + "\n");
0502: }
0503: }
0504:
0505: try {
0506: // in and dataLength contains optional data that was written
0507: // to the log during a previous call to logAndDo.
0508: compensation.doMe(xact, logInstant, in);
0509: } catch (StandardException se) {
0510: throw logFactory.markCorrupt(StandardException
0511: .newException(SQLState.LOG_DO_ME_FAIL, se,
0512: compensation));
0513: } catch (IOException ioe) {
0514: throw logFactory.markCorrupt(StandardException
0515: .newException(SQLState.LOG_DO_ME_FAIL, ioe,
0516: compensation));
0517: }
0518:
0519: return logInstant;
0520:
0521: } catch (IOException ioe) {
0522: if (inUserCode) {
0523: throw StandardException.newException(
0524: SQLState.LOG_WRITE_LOG_RECORD, ioe,
0525: compensation);
0526: } else {
0527: throw StandardException.newException(
0528: SQLState.LOG_BUFFER_FULL, ioe, compensation);
0529: }
0530: }
0531: }
0532:
0533: /**
0534: Flush the log up to the given log instant.
0535:
0536: <P>MT - not needed, wrapper method
0537:
0538: @exception StandardException cannot sync log file
0539: */
0540: public void flush(LogInstant where) throws StandardException {
0541: if (SanityManager.DEBUG) {
0542: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0543: SanityManager.DEBUG(LogToFile.DBG_FLAG, "Flush log to "
0544: + where.toString());
0545: }
0546: }
0547:
0548: logFactory.flush(where);
0549: }
0550:
0551: /**
0552: Flush all outstanding log to disk.
0553:
0554: <P>MT - not needed, wrapper method
0555:
0556: @exception StandardException cannot sync log file
0557: */
0558: public void flushAll() throws StandardException {
0559: logFactory.flushAll();
0560: }
0561:
0562: /**
0563: * During recovery re-prepare a transaction.
0564: * <p>
0565: * After redo() and undo(), this routine is called on all outstanding
0566: * in-doubt (prepared) transactions. This routine re-acquires all
0567: * logical write locks for operations in the xact, and then modifies
0568: * the transaction table entry to make the transaction look as if it
0569: * had just been prepared following startup after recovery.
0570: * <p>
0571: *
0572: * @param t is the transaction performing the re-prepare
0573: * @param prepareId is the transaction ID to be re-prepared
0574: * @param prepareStopAt is where the log instant (inclusive) where the
0575: * re-prepare should stop.
0576: * @param prepareStartAt is the log instant (inclusive) where re-prepare
0577: * should begin, this is normally the log instant
0578: * of the last log record of the transaction that
0579: * is to be re-prepare. If null, then re-prepare
0580: * starts from the end of the log.
0581: *
0582: * @exception StandardException Standard exception policy.
0583: **/
0584: public void reprepare(RawTransaction t, TransactionId prepareId,
0585: LogInstant prepareStopAt, LogInstant prepareStartAt)
0586: throws StandardException {
0587:
0588: if (SanityManager.DEBUG) {
0589: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0590: if (prepareStartAt != null) {
0591: SanityManager
0592: .DEBUG(
0593: LogToFile.DBG_FLAG,
0594: "----------------------------------------------------\n"
0595: + "\nBegin of RePrepare : "
0596: + prepareId.toString()
0597: + "start at "
0598: + prepareStartAt.toString()
0599: + " stop at "
0600: + prepareStopAt.toString()
0601: + "\n----------------------------------------------------\n");
0602: } else {
0603: SanityManager
0604: .DEBUG(
0605: LogToFile.DBG_FLAG,
0606: "----------------------------------------------------\n"
0607: + "\nBegin of Reprepare: "
0608: + prepareId.toString()
0609: + "start at end of log stop at "
0610: + prepareStopAt.toString()
0611: + "\n----------------------------------------------------\n");
0612: }
0613: }
0614: }
0615:
0616: // statistics
0617: int clrskipped = 0;
0618: int logrecordseen = 0;
0619:
0620: RePreparable lop = null;
0621:
0622: // stream to read the log record - initial size 4096, scanLog needs
0623: // to resize if the log record is larger than that.
0624: ArrayInputStream rawInput = null;
0625:
0626: try {
0627: StreamLogScan scanLog;
0628:
0629: if (prepareStartAt == null) {
0630: // don't know where to start, scan from end of log
0631: scanLog = (StreamLogScan) logFactory
0632: .openBackwardsScan(prepareStopAt);
0633: } else {
0634: if (prepareStartAt.lessThan(prepareStopAt)) {
0635: // nothing to prepare!
0636: return;
0637: }
0638:
0639: scanLog = (StreamLogScan) logFactory.openBackwardsScan(
0640: ((LogCounter) prepareStartAt).getValueAsLong(),
0641: prepareStopAt);
0642: }
0643:
0644: if (SanityManager.DEBUG)
0645: SanityManager.ASSERT(scanLog != null,
0646: "cannot open log for prepare");
0647:
0648: rawInput = new ArrayInputStream(new byte[4096]);
0649:
0650: LogRecord record;
0651:
0652: while ((record = scanLog.getNextRecord(rawInput, prepareId,
0653: 0)) != null) {
0654: if (SanityManager.DEBUG) {
0655: SanityManager
0656: .ASSERT(record.getTransactionId().equals(
0657: prepareId),
0658: "getNextRecord return unqualified log rec for prepare");
0659: }
0660:
0661: logrecordseen++;
0662:
0663: if (record.isCLR()) {
0664: clrskipped++;
0665:
0666: // the loggable is still in the input stream, get rid of it
0667: record.skipLoggable();
0668:
0669: // read the prepareInstant
0670: long prepareInstant = rawInput.readLong();
0671:
0672: if (SanityManager.DEBUG) {
0673: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0674: SanityManager
0675: .DEBUG(
0676: LogToFile.DBG_FLAG,
0677: "Skipping over CLRs, reset scan to "
0678: + LogCounter
0679: .toDebugString(prepareInstant));
0680: }
0681: }
0682:
0683: scanLog
0684: .resetPosition(new LogCounter(
0685: prepareInstant));
0686: // scanLog now positioned at the beginning of the log
0687: // record that was rolled back by this CLR.
0688: // The scan is a backward one so getNextRecord will skip
0689: // over the record that was rolled back and go to the one
0690: // previous to it
0691:
0692: continue;
0693: }
0694:
0695: if (record.requiresPrepareLocks()) {
0696: lop = record.getRePreparable();
0697: } else {
0698: continue;
0699: }
0700:
0701: if (lop != null) {
0702: // Reget locks based on log record. reclaim all locks with
0703: // a serializable locking policy, since we are only
0704: // reclaiming write locks, isolation level does not matter
0705: // much.
0706:
0707: lop
0708: .reclaimPrepareLocks(
0709: t,
0710: t
0711: .newLockingPolicy(
0712: LockingPolicy.MODE_RECORD,
0713: TransactionController.ISOLATION_REPEATABLE_READ,
0714: true));
0715:
0716: if (SanityManager.DEBUG) {
0717: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0718: SanityManager.DEBUG(LogToFile.DBG_FLAG,
0719: "Reprepare log record at instant "
0720: + scanLog.getInstant()
0721: + " : " + lop);
0722: }
0723: }
0724:
0725: }
0726: }
0727:
0728: } catch (ClassNotFoundException cnfe) {
0729: throw logFactory.markCorrupt(StandardException
0730: .newException(SQLState.LOG_CORRUPTED, cnfe));
0731: } catch (IOException ioe) {
0732: throw logFactory.markCorrupt(StandardException
0733: .newException(SQLState.LOG_READ_LOG_FOR_UNDO, ioe));
0734: } catch (StandardException se) {
0735: throw logFactory.markCorrupt(StandardException
0736: .newException(SQLState.LOG_UNDO_FAILED, se,
0737: prepareId, lop, (Object) null));
0738: } finally {
0739: if (rawInput != null) {
0740: try {
0741: rawInput.close();
0742: } catch (IOException ioe) {
0743: throw logFactory.markCorrupt(StandardException
0744: .newException(
0745: SQLState.LOG_READ_LOG_FOR_UNDO,
0746: ioe, prepareId));
0747: }
0748: }
0749: }
0750:
0751: if (SanityManager.DEBUG) {
0752: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0753: SanityManager.DEBUG(LogToFile.DBG_FLAG,
0754: "Finish prepare" + ", clr skipped = "
0755: + clrskipped + ", record seen = "
0756: + logrecordseen + "\n");
0757: }
0758: }
0759:
0760: if (SanityManager.DEBUG) {
0761: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0762: SanityManager
0763: .DEBUG(
0764: LogToFile.DBG_FLAG,
0765: "----------------------------------------------------\n"
0766: + "End of recovery rePrepare\n"
0767: + ", clr skipped = "
0768: + clrskipped
0769: + ", record seen = "
0770: + logrecordseen
0771: + "\n----------------------------------------------------\n");
0772: }
0773: }
0774: }
0775:
0776: /**
0777: Undo a part of or the entire transaction. Begin rolling back the log
0778: record at undoStartAt and stopping at (inclusive) the log record at
0779: undoStopAt.
0780:
0781: <P>MT - Not needed. A transaction must be single threaded thru undo,
0782: each RawTransaction has its own logger, therefore no need to
0783: synchronize. The RawTransaction must handle synchronizing with
0784: multiple threads during rollback.
0785:
0786: @param t the transaction that needs to be rolled back
0787: @param undoId the transaction ID
0788: @param undoStopAt the last log record that should be rolled back
0789: @param undoStartAt the first log record that should be rolled back
0790:
0791: @exception StandardException Standard Cloudscape error policy
0792:
0793: @see Logger#undo
0794: */
0795: public void undo(RawTransaction t, TransactionId undoId,
0796: LogInstant undoStopAt, LogInstant undoStartAt)
0797: throws StandardException {
0798:
0799: if (SanityManager.DEBUG) {
0800: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0801: if (undoStartAt != null) {
0802: SanityManager.DEBUG(LogToFile.DBG_FLAG,
0803: "\nUndo transaction: " + undoId.toString()
0804: + "start at "
0805: + undoStartAt.toString()
0806: + " stop at "
0807: + undoStopAt.toString());
0808: } else {
0809: SanityManager.DEBUG(LogToFile.DBG_FLAG,
0810: "\nUndo transaction: " + undoId.toString()
0811: + "start at end of log stop at "
0812: + undoStopAt.toString());
0813: }
0814: }
0815: }
0816:
0817: // statistics
0818: int clrgenerated = 0;
0819: int clrskipped = 0;
0820: int logrecordseen = 0;
0821:
0822: StreamLogScan scanLog;
0823: Compensation compensation = null;
0824: Undoable lop = null;
0825:
0826: // stream to read the log record - initial size 4096, scanLog needs
0827: // to resize if the log record is larget than that.
0828: ArrayInputStream rawInput = null;
0829:
0830: try {
0831: if (undoStartAt == null) {
0832: // don't know where to start, rollback from end of log
0833:
0834: scanLog = (StreamLogScan) logFactory
0835: .openBackwardsScan(undoStopAt);
0836: } else {
0837: if (undoStartAt.lessThan(undoStopAt)) {
0838: // nothing to undo!
0839: return;
0840: }
0841:
0842: long undoStartInstant = ((LogCounter) undoStartAt)
0843: .getValueAsLong();
0844:
0845: scanLog = (StreamLogScan) logFactory.openBackwardsScan(
0846: undoStartInstant, undoStopAt);
0847: }
0848:
0849: if (SanityManager.DEBUG)
0850: SanityManager.ASSERT(scanLog != null,
0851: "cannot open log for undo");
0852:
0853: rawInput = new ArrayInputStream(new byte[4096]);
0854:
0855: LogRecord record;
0856:
0857: while ((record = scanLog.getNextRecord(rawInput, undoId, 0)) != null) {
0858: if (SanityManager.DEBUG) {
0859: SanityManager
0860: .ASSERT(record.getTransactionId().equals(
0861: undoId),
0862: "getNextRecord return unqualified log record for undo");
0863: }
0864:
0865: logrecordseen++;
0866:
0867: if (record.isCLR()) {
0868: clrskipped++;
0869:
0870: // the loggable is still in the input stream, get rid of it
0871: record.skipLoggable();
0872:
0873: // read the undoInstant
0874: long undoInstant = rawInput.readLong();
0875:
0876: if (SanityManager.DEBUG) {
0877: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0878: SanityManager
0879: .DEBUG(
0880: LogToFile.DBG_FLAG,
0881: "Skipping over CLRs, reset scan to "
0882: + LogCounter
0883: .toDebugString(undoInstant));
0884: }
0885: }
0886:
0887: scanLog.resetPosition(new LogCounter(undoInstant));
0888:
0889: // scanLog now positioned at the beginning of the log
0890: // record that was rolled back by this CLR.
0891: // The scan is a backward one so getNextRecord will skip
0892: // over the record that was rolled back and go to the one
0893: // previous to it
0894:
0895: continue;
0896: }
0897:
0898: lop = record.getUndoable();
0899:
0900: if (lop != null) {
0901: int optionalDataLength = rawInput.readInt();
0902: int savePosition = rawInput.getPosition();
0903: rawInput.setLimit(savePosition, optionalDataLength);
0904:
0905: compensation = lop.generateUndo(t, rawInput);
0906:
0907: if (SanityManager.DEBUG) {
0908: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0909: SanityManager
0910: .DEBUG(
0911: LogToFile.DBG_FLAG,
0912: "Rollback log record at instant "
0913: + LogCounter
0914: .toDebugString(scanLog
0915: .getInstant())
0916: + " : " + lop);
0917: }
0918: }
0919:
0920: clrgenerated++;
0921:
0922: if (compensation != null) {
0923: // generateUndo may have read stuff off the
0924: // stream, reset it for the undo operation.
0925: rawInput.setLimit(savePosition,
0926: optionalDataLength);
0927:
0928: // log the compensation op that rolls back the
0929: // operation at this instant
0930: t.logAndUndo(compensation, new LogCounter(
0931: scanLog.getInstant()), rawInput);
0932:
0933: compensation.releaseResource(t);
0934: compensation = null;
0935: }
0936:
0937: // if compensation is null, log operation is redo only
0938: }
0939: // if this is not an undoable operation, continue with next log
0940: // record
0941: }
0942: } catch (ClassNotFoundException cnfe) {
0943: throw logFactory.markCorrupt(StandardException
0944: .newException(SQLState.LOG_CORRUPTED, cnfe));
0945: } catch (IOException ioe) {
0946: throw logFactory.markCorrupt(StandardException
0947: .newException(SQLState.LOG_READ_LOG_FOR_UNDO, ioe));
0948: } catch (StandardException se) {
0949: // TODO (4327) - exceptions caught here are nested in the exception
0950: // below but for some reason the nested exceptions are not logged
0951: // or reported in any way.
0952:
0953: throw logFactory.markCorrupt(StandardException
0954: .newException(SQLState.LOG_UNDO_FAILED, se, undoId,
0955: lop, compensation));
0956: } finally {
0957: if (compensation != null) {
0958: // errored out
0959: compensation.releaseResource(t);
0960: }
0961:
0962: if (rawInput != null) {
0963: try {
0964: rawInput.close();
0965: } catch (IOException ioe) {
0966: throw logFactory.markCorrupt(StandardException
0967: .newException(
0968: SQLState.LOG_READ_LOG_FOR_UNDO,
0969: ioe, undoId));
0970: }
0971: }
0972: }
0973:
0974: if (SanityManager.DEBUG) {
0975: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
0976: SanityManager.DEBUG(LogToFile.DBG_FLAG, "Finish undo"
0977: + ", clr generated = " + clrgenerated
0978: + ", clr skipped = " + clrskipped
0979: + ", record seen = " + logrecordseen + "\n");
0980: }
0981: }
0982: }
0983:
0984: /**
0985: Recovery Redo loop.
0986:
0987: <P> The log stream is scanned from the beginning (or
0988: from the undo low water mark of a checkpoint) forward until the end.
0989: The purpose of the redo pass is to repeat history, i.e, to repeat
0990: exactly the same set of changes the rawStore went thru right before it
0991: stopped. With each log record that is encountered in the redo pass:
0992: <OL>
0993: <LI>if it isFirst(), then the transaction factory is called upon to
0994: create a new transaction object.
0995: <LI>if it needsRedo(), its doMe() is called (if it is a compensation
0996: operation, then the undoable operation needs to be created first
0997: before the doMe is called).
0998: <LI>if it isComplete(), then the transaction object is closed.
0999: </OL>
1000:
1001: <P> MT - caller provides synchronization
1002:
1003: @param transFactory - the transaction factory
1004: @param redoLWM - if checkpoint seen, starting from this point
1005: on, apply redo if necessary
1006:
1007: @return the log instant of the next log record (or the instant just
1008: after the last log record). This is used to determine where the log
1009: truly ends
1010:
1011: @exception StandardException Standard Cloudscape error policy
1012: @exception IOException error reading log file
1013: @exception ClassNotFoundException log file corrupted
1014:
1015: @see LogToFile#recover
1016: */
1017: protected long redo(RawTransaction recoveryTransaction,
1018: TransactionFactory transFactory, StreamLogScan redoScan,
1019: long redoLWM, long ttabInstant) throws IOException,
1020: StandardException, ClassNotFoundException {
1021: // begin debug info
1022: if (SanityManager.DEBUG) {
1023: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
1024: SanityManager.DEBUG(LogToFile.DBG_FLAG,
1025: "In recovery redo, redoLWM = " + redoLWM);
1026: }
1027: }
1028:
1029: int scanCount = 0;
1030: int redoCount = 0;
1031: int prepareCount = 0;
1032: int clrCount = 0;
1033: int btranCount = 0;
1034: int etranCount = 0;
1035:
1036: // end debug info
1037:
1038: TransactionId tranId = null;
1039:
1040: // the current log instant
1041: long instant = LogCounter.INVALID_LOG_INSTANT;
1042:
1043: //////////////////////////////////////////////////////////////////////
1044: // During redo time, the byte array in the logOutputBuffer is not used.
1045: // Use it to read the log record - if it is not big enough, scan
1046: // will resize it. We could create a brand new log input stream that
1047: // has nothing to do with logIn or logOutputBuffer but that seem like
1048: // a waste of memory.
1049: //////////////////////////////////////////////////////////////////////
1050: logIn.setData(logOutputBuffer.getByteArray());
1051:
1052: // use this scan to reconstitute operation to be undone
1053: // when we see a CLR in the redo scan
1054: StreamLogScan undoScan = null;
1055: Loggable op = null;
1056: long logEnd = 0; // we need to determine the log's true end
1057:
1058: try {
1059:
1060: // scan the log forward in redo pass and go to the end
1061: LogRecord record;
1062: while ((record = redoScan.getNextRecord(logIn, null, 0)) != null) {
1063: scanCount++;
1064: long undoInstant = 0;
1065:
1066: // last known good instant
1067: instant = redoScan.getInstant();
1068:
1069: // last known good log end
1070: logEnd = redoScan.getLogRecordEnd();
1071:
1072: // NOTE NOTE -- be very careful about the undoInstant, it is
1073: // read off the input stream in this debug section.
1074: // if we change the log format we will need to change the way
1075: // the undo instant is gotten. Also, once it is read off, it
1076: // should not be read from the stream any more
1077: // NOTE NOTE
1078: if (SanityManager.DEBUG) {
1079: if (SanityManager.DEBUG_ON(LogToFile.DUMP_LOG_ONLY)
1080: || SanityManager
1081: .DEBUG_ON(LogToFile.DBG_FLAG))
1082:
1083: {
1084: if (SanityManager
1085: .DEBUG_ON(LogToFile.DUMP_LOG_ONLY))
1086: SanityManager.DEBUG_SET(LogToFile.DBG_FLAG);
1087:
1088: op = record.getLoggable();
1089: tranId = record.getTransactionId();
1090: if (record.isCLR()) {
1091: // !!!!!!! this moves the file pointer
1092: undoInstant = logIn.readLong();
1093:
1094: SanityManager
1095: .DEBUG(
1096: LogToFile.DBG_FLAG,
1097: "scanned "
1098: + tranId
1099: + " : "
1100: + op
1101: + " instant = "
1102: + LogCounter
1103: .toDebugString(instant)
1104: + " undoInstant : "
1105: + LogCounter
1106: .toDebugString(undoInstant));
1107: } else {
1108: SanityManager
1109: .DEBUG(
1110: LogToFile.DBG_FLAG,
1111: "scanned "
1112: + tranId
1113: + " : "
1114: + op
1115: + " instant = "
1116: + LogCounter
1117: .toDebugString(instant)
1118: + " logEnd = "
1119: + LogCounter
1120: .toDebugString(logEnd)
1121: + " logIn at "
1122: + logIn
1123: .getPosition()
1124: + " available "
1125: + logIn.available());
1126: }
1127:
1128: // we only want to dump the log, don't touch it
1129: if (SanityManager
1130: .DEBUG_ON(LogToFile.DUMP_LOG_ONLY))
1131: continue;
1132: }
1133: }
1134:
1135: // if the redo scan is between the undoLWM and redoLWM, we only
1136: // need to redo begin and end tran. Everything else has
1137: // already been flushed by checkpoint
1138: if (redoLWM != LogCounter.INVALID_LOG_INSTANT
1139: && instant < redoLWM) {
1140: if (!(record.isFirst() || record.isComplete() || record
1141: .isPrepare())) {
1142: continue;
1143: }
1144: }
1145:
1146: // get the transaction
1147: tranId = record.getTransactionId();
1148:
1149: // if this transaction is known to the transaction factory, make
1150: // the recoveryTransaction assume its identitiy and properties
1151: // otherwise, make it known to the transaction factory
1152: if (!transFactory.findTransaction(tranId,
1153: recoveryTransaction)) {
1154: // transaction not found
1155:
1156: if (redoLWM != LogCounter.INVALID_LOG_INSTANT
1157: && instant < redoLWM
1158: && (record.isPrepare() || record
1159: .isComplete())) {
1160: // What is happening here is that a transaction that
1161: // started before the undoLWM has commited by the time
1162: // the checkpoint undoLWM was taken. Hence, we only
1163: // see the tail end of its log record and its endXact
1164: // record.
1165: //
1166: // NOTE:
1167: // Since we didn't see its beginXact, we cannot do the
1168: // endXact's doMe either. Also if the endXact, is
1169: // actually just a prepare, we don't need to do
1170: // anything as the transaction will commit or abort
1171: // prior to point we are recovering to.
1172: // If it is deemed necessary to do the endXact's doMe,
1173: // then we should start the transaction right here.
1174: // For now, just completely ignore this transaction
1175: //
1176: etranCount++;
1177:
1178: continue;
1179: }
1180:
1181: if ((ttabInstant == LogCounter.INVALID_LOG_INSTANT)
1182: && !record.isFirst()) {
1183: throw StandardException
1184: .newException(
1185: SQLState.LOG_UNEXPECTED_RECOVERY_PROBLEM,
1186: MessageService
1187: .getTextMessage(
1188: MessageId.LOG_RECORD_NOT_FIRST,
1189: tranId));
1190:
1191: }
1192:
1193: if (SanityManager.DEBUG) {
1194: // if we dumped the transaction table but see a non
1195: // BeginXact record after the transaction table dump
1196: // instant, error.
1197: if (ttabInstant != LogCounter.INVALID_LOG_INSTANT) {
1198: if (instant > ttabInstant
1199: && !record.isFirst()) {
1200: SanityManager
1201: .THROWASSERT("log record is Not first but transaction "
1202: + "is not in transaction table (2) : "
1203: + tranId);
1204: }
1205:
1206: // If we dump the transaction table and the table
1207: // does not have the transaction, and we see this
1208: // beginXact before the ttab instant, we could have
1209: // igored it because we "know" that we should see
1210: // the endXact before the ttab instant also.
1211: // Leave it in just in case.
1212: }
1213: }
1214: btranCount++;
1215:
1216: // the long transaction ID is embedded in the beginXact log
1217: // record. The short ID is stored in the log record.
1218: recoveryTransaction.setTransactionId(record
1219: .getLoggable(), tranId);
1220:
1221: } else {
1222: // recoveryTransaction found
1223:
1224: if ((ttabInstant == LogCounter.INVALID_LOG_INSTANT)
1225: && record.isFirst()) {
1226: throw StandardException
1227: .newException(
1228: SQLState.LOG_UNEXPECTED_RECOVERY_PROBLEM,
1229: MessageService
1230: .getTextMessage(
1231: MessageId.LOG_RECORD_FIRST,
1232: tranId));
1233:
1234: }
1235:
1236: if (SanityManager.DEBUG) {
1237: if (ttabInstant != LogCounter.INVALID_LOG_INSTANT
1238: && instant > ttabInstant
1239: && record.isFirst()) {
1240: SanityManager
1241: .THROWASSERT("log record is first but transaction is "
1242: + "already in transaction table (3): "
1243: + tranId);
1244: }
1245:
1246: if (record.isPrepare())
1247: prepareCount++;
1248: }
1249:
1250: // if we have a transaction table dumped with the
1251: // checkpoint log record, then during the redo scan we may
1252: // see the beginXact of a transaction which is already in
1253: // the transaction table, just ignore it if it is after the
1254: // redoLWM but before the transaction table instant. We
1255: // still need to redo any database changes but since the
1256: // transaction is already recorded in the transaction
1257: // table, ignore it.
1258: //
1259: if (record.isFirst()) {
1260: btranCount++;
1261: continue;
1262: }
1263: }
1264:
1265: op = record.getLoggable();
1266:
1267: if (SanityManager.DEBUG) {
1268: if (!record.isCLR()) {
1269: if (logIn.available() < 4) {
1270: SanityManager
1271: .THROWASSERT("not enough bytes read in : "
1272: + logIn.available()
1273: + " for "
1274: + op
1275: + " instant "
1276: + LogCounter
1277: .toDebugString(instant));
1278: }
1279: }
1280: }
1281:
1282: if (SanityManager.DEBUG) {
1283: SanityManager
1284: .ASSERT(!recoveryTransaction
1285: .handlesPostTerminationWork(),
1286: "recovery transaction handles post termination work");
1287: }
1288:
1289: if (op.needsRedo(recoveryTransaction)) {
1290: redoCount++;
1291:
1292: if (record.isCLR()) {
1293: clrCount++;
1294:
1295: // the log operation is not complete, the operation to
1296: // undo is stashed away at the undoInstant.
1297: // Reconstitute that first.
1298:
1299: if (SanityManager.DEBUG)
1300: SanityManager
1301: .ASSERT(op instanceof Compensation);
1302:
1303: // this value may be set by sanity xxxx
1304: if (undoInstant == 0)
1305: undoInstant = logIn.readLong();
1306:
1307: if (undoScan == null) {
1308: undoScan = (StreamLogScan) logFactory
1309: .openForwardsScan(undoInstant,
1310: (LogInstant) null);
1311: } else {
1312: undoScan.resetPosition(new LogCounter(
1313: undoInstant));
1314: }
1315:
1316: // undoScan now positioned at the beginning of the log
1317: // record was rolled back by this CLR.
1318: // The scan is a forward one so getNextRecord will get
1319: // the log record that needs to be rolled back.
1320:
1321: // reuse the buffer in logIn and logIn since CLR
1322: // has no optional data and has no use for them anymore
1323: logIn.clearLimit();
1324: LogRecord undoRecord = undoScan.getNextRecord(
1325: logIn, null, 0);
1326:
1327: Undoable undoOp = undoRecord.getUndoable();
1328:
1329: if (SanityManager.DEBUG) {
1330: SanityManager
1331: .DEBUG(
1332: LogToFile.DBG_FLAG,
1333: "Redoing CLR: undoInstant = "
1334: + LogCounter
1335: .toDebugString(undoInstant)
1336: + " clrinstant = "
1337: + LogCounter
1338: .toDebugString(instant));
1339:
1340: SanityManager.ASSERT(undoRecord
1341: .getTransactionId().equals(tranId));
1342:
1343: SanityManager.ASSERT(undoOp != null);
1344: }
1345:
1346: ((Compensation) op).setUndoOp(undoOp);
1347: }
1348:
1349: // at this point, logIn points to the optional
1350: // data of the loggable that is to be redone or to be
1351: // rolled back
1352:
1353: if (SanityManager.DEBUG) {
1354: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
1355: SanityManager
1356: .DEBUG(
1357: LogToFile.DBG_FLAG,
1358: "redoing "
1359: + op
1360: + " instant = "
1361: + LogCounter
1362: .toDebugString(instant));
1363: }
1364: }
1365:
1366: int dataLength = logIn.readInt();
1367: logIn.setLimit(logIn.getPosition(), dataLength);
1368:
1369: // even though the log has already been written, we need to
1370: // tie the page to the log stream so that if redo failed
1371: // for some reasons, the log factory's corruption will stop
1372: // the corrupt page from flushing to disk.
1373:
1374: op.doMe(recoveryTransaction,
1375: new LogCounter(instant), logIn);
1376:
1377: op.releaseResource(recoveryTransaction);
1378:
1379: op = null;
1380: }
1381:
1382: // RESOLVE: to speed up undo, may want to update the
1383: // LastLogInstant in the transaction table.
1384: // Right now, undo always start from the end of the log.
1385:
1386: // one last thing, if this is the last log record of the
1387: // transaction, then commit the transaction and clean up
1388: //
1389: // 'commit' even though the transaction maybe a rollback
1390: // because we already did all the rollback work when redoing
1391: // the CLRs. Commit will only flush the log if this session
1392: // has written any transaction, so in this case, it is a noop.
1393: if (record.isComplete()) {
1394: etranCount++;
1395:
1396: if (SanityManager.DEBUG)
1397: SanityManager
1398: .ASSERT(!recoveryTransaction
1399: .handlesPostTerminationWork(),
1400: "recovery xact handles post termination work");
1401:
1402: recoveryTransaction.commit();
1403: }
1404: } // while redoScan.getNextRecord() != null
1405:
1406: // If the scan ended in an empty file, update logEnd to reflect that
1407: // in order to avoid to continue logging to an older file
1408: long end = redoScan.getLogRecordEnd();
1409: if (end != LogCounter.INVALID_LOG_INSTANT
1410: && (LogCounter.getLogFileNumber(logEnd) < LogCounter
1411: .getLogFileNumber(end))) {
1412: logEnd = end;
1413: }
1414: } catch (StandardException se) {
1415: throw StandardException.newException(
1416: SQLState.LOG_REDO_FAILED, se, op);
1417: } finally {
1418: // close all the io streams
1419: redoScan.close();
1420: redoScan = null;
1421:
1422: if (undoScan != null) {
1423: undoScan.close();
1424: undoScan = null;
1425: }
1426:
1427: if (op != null)
1428: op.releaseResource(recoveryTransaction);
1429:
1430: }
1431:
1432: if (SanityManager.DEBUG) {
1433: if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) {
1434: SanityManager
1435: .DEBUG(
1436: LogToFile.DBG_FLAG,
1437: "----------------------------------------------------\n"
1438: + "End of recovery redo\n"
1439: + "Scanned = "
1440: + scanCount
1441: + " log records"
1442: + ", redid = "
1443: + redoCount
1444: + " ( clr = "
1445: + clrCount
1446: + " )"
1447: + " begintran = "
1448: + btranCount
1449: + " endtran = "
1450: + etranCount
1451: + " preparetran = "
1452: + prepareCount
1453: + "\n log ends at "
1454: + LogCounter
1455: .toDebugString(logEnd)
1456: + "\n----------------------------------------------------\n");
1457: }
1458: }
1459:
1460: if (SanityManager.DEBUG) {
1461: // make sure logEnd and instant is consistent
1462: if (instant != LogCounter.INVALID_LOG_INSTANT) {
1463: SanityManager
1464: .ASSERT(LogCounter.getLogFileNumber(instant) < LogCounter
1465: .getLogFileNumber(logEnd)
1466: || (LogCounter
1467: .getLogFileNumber(instant) == LogCounter
1468: .getLogFileNumber(logEnd) && LogCounter
1469: .getLogFilePosition(instant) <= LogCounter
1470: .getLogFilePosition(logEnd)));
1471: } else {
1472: SanityManager
1473: .ASSERT(logEnd == LogCounter.INVALID_LOG_INSTANT);
1474: }
1475: }
1476:
1477: // logEnd is the last good log record position in the log
1478: return logEnd;
1479: }
1480:
1481: /**
1482: Read the next log record from the scan.
1483:
1484: <P>MT - caller must provide synchronization (right now, it is only
1485: called in recovery to find the checkpoint log record. When this method
1486: is called by a more general audience, MT must be revisited).
1487:
1488: @param scan an opened log scan
1489: @param size estimated size of the log record
1490:
1491: @return the log operation that is the next in the scan, or null if no
1492: more log operation in the log scan
1493:
1494: @exception IOException Error reading the log file
1495: @exception StandardException Standard Cloudscape error policy
1496: @exception ClassNotFoundException log corrupted
1497: */
1498: protected Loggable readLogRecord(StreamLogScan scan, int size)
1499: throws IOException, StandardException,
1500: ClassNotFoundException {
1501: Loggable lop = null;
1502:
1503: ArrayInputStream logInputBuffer = new ArrayInputStream(
1504: new byte[size]);
1505:
1506: LogRecord record = scan.getNextRecord(logInputBuffer, null, 0);
1507: if (record != null)
1508: lop = record.getLoggable();
1509: return lop;
1510: }
1511:
1512: }
|