1 | /* |
2 | |
3 | Derby - Class org.apache.derby.impl.store.raw.log.Scan |
4 | |
5 | Copyright 1997, 2004 The Apache Software Foundation or its licensors, as applicable. |
6 | |
7 | Licensed under the Apache License, Version 2.0 (the "License"); |
8 | you may not use this file except in compliance with the License. |
9 | You may obtain a copy of the License at |
10 | |
11 | http://www.apache.org/licenses/LICENSE-2.0 |
12 | |
13 | Unless required by applicable law or agreed to in writing, software |
14 | distributed under the License is distributed on an "AS IS" BASIS, |
15 | WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
16 | See the License for the specific language governing permissions and |
17 | limitations under the License. |
18 | |
19 | */ |
20 | |
21 | package org.apache.derby.impl.store.raw.log; |
22 | |
23 | import org.apache.derby.iapi.reference.SQLState; |
24 | |
25 | import org.apache.derby.iapi.services.io.ArrayInputStream; |
26 | |
27 | import org.apache.derby.iapi.services.sanity.SanityManager; |
28 | |
29 | import org.apache.derby.iapi.error.StandardException; |
30 | |
31 | import org.apache.derby.iapi.store.raw.log.LogInstant; |
32 | |
33 | import org.apache.derby.iapi.store.raw.xact.TransactionId; |
34 | |
35 | import org.apache.derby.impl.store.raw.log.LogCounter; |
36 | import org.apache.derby.impl.store.raw.log.LogRecord; |
37 | import org.apache.derby.impl.store.raw.log.StreamLogScan; |
38 | |
39 | import org.apache.derby.io.StorageRandomAccessFile; |
40 | |
41 | import java.io.IOException; |
42 | import org.apache.derby.iapi.store.raw.Loggable; |
43 | |
44 | /** |
45 | |
46 | Scan the the log which is implemented by a series of log files.n |
47 | This log scan knows how to move across log file if it is positioned at |
48 | the boundary of a log file and needs to getNextRecord. |
49 | |
50 | <PRE> |
51 | 4 bytes - length of user data, i.e. N |
52 | 8 bytes - long representing log instant |
53 | N bytes of supplied data |
54 | 4 bytes - length of user data, i.e. N |
55 | </PRE> |
56 | |
57 | */ |
58 | |
59 | public class Scan implements StreamLogScan { |
60 | |
61 | // value for scanDirection |
62 | public static final byte FORWARD = 1; |
63 | public static final byte BACKWARD = 2; |
64 | public static final byte BACKWARD_FROM_LOG_END = 4; |
65 | |
66 | private StorageRandomAccessFile scan; // an output stream to the log file |
67 | private LogToFile logFactory; // log factory knows how to to skip |
68 | // from log file to log file |
69 | |
70 | private long currentLogFileNumber; // the log file the scan is currently on |
71 | |
72 | private long currentLogFileLength; // the size of the current log file |
73 | // used only for FORWARD scan to determine when |
74 | // to switch the next log file |
75 | |
76 | private long knownGoodLogEnd; // For FORWARD scan only |
77 | // during recovery, we need to determine the end |
78 | // of the log. Everytime a complete log record |
79 | // is read in, knownGoodLogEnd is set to the |
80 | // log instant of the next log record if it is |
81 | // on the same log file. |
82 | // |
83 | // only valid afer a successfull getNextRecord |
84 | // on a FOWARD scan. |
85 | |
86 | |
87 | private long currentInstant; // the log instant the scan is |
88 | // currently on - only valid after a |
89 | // successful getNextRecord |
90 | |
91 | private long stopAt; // scan until we find a log record whose |
92 | // log instance < stopAt if we scan BACKWARD |
93 | // log instance > stopAt if we scan FORWARD |
94 | // log instance >= stopAt if we scan FORWARD_FLUSHED |
95 | |
96 | |
97 | private byte scanDirection; // BACKWARD or FORWARD |
98 | |
99 | private boolean fuzzyLogEnd = false; //get sets to true during forward scan |
100 | //for recovery, if there were |
101 | //partial writes at the end of the log before crash; |
102 | //during forward scan for recovery. |
103 | |
104 | |
105 | /** |
106 | For backward scan, we expect a scan positioned at the end of the next log record. |
107 | For forward scan, we expect a scan positioned at the beginning of the next log record. |
108 | |
109 | For forward flushed scan, we expect stopAt to be the instant for the |
110 | first not-flushed log record. Like any forward scan, we expect a scan |
111 | positioned at the beginning of the next log record. |
112 | |
113 | @exception StandardException Standard Cloudscape error policy |
114 | @exception IOException cannot access the log at the new position. |
115 | */ |
116 | public Scan(LogToFile logFactory, long startAt, LogInstant stopAt, byte direction) |
117 | throws IOException, StandardException |
118 | { |
119 | if (SanityManager.DEBUG) |
120 | SanityManager.ASSERT(startAt != LogCounter.INVALID_LOG_INSTANT, |
121 | "cannot start scan on an invalid log instant"); |
122 | |
123 | this.logFactory = logFactory; |
124 | currentLogFileNumber = LogCounter.getLogFileNumber(startAt); |
125 | currentLogFileLength = -1; |
126 | knownGoodLogEnd = LogCounter.INVALID_LOG_INSTANT;// set at getNextRecord for FORWARD scan |
127 | currentInstant = LogCounter.INVALID_LOG_INSTANT; // set at getNextRecord |
128 | if (stopAt != null) |
129 | this.stopAt = ((LogCounter) stopAt).getValueAsLong(); |
130 | else |
131 | this.stopAt = LogCounter.INVALID_LOG_INSTANT; |
132 | |
133 | switch(direction) |
134 | { |
135 | case FORWARD: |
136 | scan = logFactory.getLogFileAtPosition(startAt); |
137 | scanDirection = FORWARD; |
138 | |
139 | if (SanityManager.DEBUG) |
140 | if (scan == null) |
141 | SanityManager.THROWASSERT( |
142 | "scan null at " + LogCounter.toDebugString(startAt)); |
143 | |
144 | // NOTE: just get the length of the file without syncing. |
145 | // this only works because the only place forward scan is used |
146 | // right now is on recovery redo and nothing is being added to |
147 | // the current log file. When the forward scan is used for some |
148 | // other purpose, need to sync access to the end of the log |
149 | currentLogFileLength = scan.length(); |
150 | break; |
151 | |
152 | case BACKWARD: |
153 | // startAt is at the front of the log record, for backward |
154 | // scan we need to be positioned at the end of the log record |
155 | scan = logFactory.getLogFileAtPosition(startAt); |
156 | int logsize = scan.readInt(); |
157 | |
158 | // skip forward over the log record and all the overhead, but remember |
159 | // we just read an int off the overhead |
160 | scan.seek(scan.getFilePointer() + logsize + LogToFile.LOG_RECORD_OVERHEAD - 4); |
161 | scanDirection = BACKWARD; |
162 | break; |
163 | |
164 | case BACKWARD_FROM_LOG_END: |
165 | // startAt is at the end of the log, no need to skip the log record |
166 | scan = logFactory.getLogFileAtPosition(startAt); |
167 | scanDirection = BACKWARD; |
168 | break; |
169 | |
170 | } |
171 | } |
172 | |
173 | /* |
174 | ** Methods of StreamLogScan |
175 | */ |
176 | |
177 | /** |
178 | Read the next log record. |
179 | Switching log to a previous log file if necessary, |
180 | Resize the input stream byte array if necessary. |
181 | @see StreamLogScan#getNextRecord |
182 | |
183 | @return the next LogRecord, or null if the end of the |
184 | scan has been reached. |
185 | |
186 | @exception StandardException Standard Cloudscape error policy |
187 | */ |
188 | public LogRecord getNextRecord(ArrayInputStream input, |
189 | TransactionId tranId, |
190 | int groupmask) |
191 | throws StandardException |
192 | { |
193 | if (scan == null) |
194 | return null; |
195 | |
196 | if (SanityManager.DEBUG) |
197 | SanityManager.ASSERT(scanDirection != 0, "scan has been secretly closed!"); |
198 | |
199 | LogRecord lr = null; |
200 | try |
201 | { |
202 | if (scanDirection == BACKWARD) |
203 | lr = getNextRecordBackward(input, tranId, groupmask); |
204 | else if (scanDirection == FORWARD) |
205 | lr = getNextRecordForward(input, tranId, groupmask); |
206 | |
207 | return lr; |
208 | |
209 | } |
210 | catch (IOException ioe) |
211 | { |
212 | if (SanityManager.DEBUG) |
213 | ioe.printStackTrace(); |
214 | |
215 | throw logFactory.markCorrupt( |
216 | StandardException.newException(SQLState.LOG_CORRUPTED, ioe)); |
217 | } |
218 | catch (ClassNotFoundException cnfe) |
219 | { |
220 | if (SanityManager.DEBUG) |
221 | cnfe.printStackTrace(); |
222 | |
223 | throw logFactory.markCorrupt( |
224 | StandardException.newException(SQLState.LOG_CORRUPTED, cnfe)); |
225 | } |
226 | finally |
227 | { |
228 | if (lr == null) |
229 | close(); // no more log record, close the scan |
230 | } |
231 | |
232 | } |
233 | |
234 | /** |
235 | Read the previous log record. |
236 | Switching log to a previous log file if necessary, |
237 | Resize the input stream byte array if necessary. |
238 | @see StreamLogScan#getNextRecord |
239 | |
240 | Side effects include: |
241 | on a successful read, setting currentInstant. |
242 | on a log file switch, setting currentLogFileNumber. |
243 | |
244 | @return the previous LogRecord, or null if the end of the |
245 | scan has been reached. |
246 | */ |
247 | private LogRecord getNextRecordBackward(ArrayInputStream input, |
248 | TransactionId tranId, |
249 | int groupmask) |
250 | throws StandardException, IOException, ClassNotFoundException |
251 | { |
252 | if (SanityManager.DEBUG) |
253 | SanityManager.ASSERT(scanDirection == BACKWARD, "can only called by backward scan"); |
254 | |
255 | // scan is positioned just past the last byte of the record, or |
256 | // right at the beginning of the file (end of the file header) |
257 | // may need to switch log file |
258 | |
259 | boolean candidate; |
260 | // if we have filtering, peek at the group and/or the transaction id, |
261 | // do them in one read rather than 2 reads. |
262 | int peekAmount = LogRecord.formatOverhead() + LogRecord.maxGroupStoredSize(); |
263 | if (tranId != null) |
264 | peekAmount += LogRecord.maxTransactionIdStoredSize(tranId); |
265 | |
266 | int readAmount; // the number of bytes actually read |
267 | |
268 | LogRecord lr; |
269 | long curpos = scan.getFilePointer(); |
270 | |
271 | do |
272 | { |
273 | // this log record is a candidate unless proven otherwise |
274 | candidate = true; |
275 | lr = null; |
276 | readAmount = -1; |
277 | |
278 | if (curpos == LogToFile.LOG_FILE_HEADER_SIZE) |
279 | { |
280 | // don't go thru the trouble of switching log file if we |
281 | // will have gone past stopAt |
282 | if (stopAt != LogCounter.INVALID_LOG_INSTANT && |
283 | LogCounter.getLogFileNumber(stopAt) == currentLogFileNumber) |
284 | { |
285 | if (SanityManager.DEBUG) |
286 | { |
287 | if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) |
288 | { |
289 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
290 | "stopping at " + currentLogFileNumber); |
291 | } |
292 | } |
293 | |
294 | return null; // no more log record |
295 | } |
296 | |
297 | // figure out where the last log record is in the previous |
298 | // log file |
299 | scan.seek(LogToFile.LOG_FILE_HEADER_PREVIOUS_LOG_INSTANT_OFFSET); |
300 | long previousLogInstant = scan.readLong(); |
301 | scan.close(); |
302 | |
303 | if (SanityManager.DEBUG) |
304 | { |
305 | SanityManager.ASSERT(previousLogInstant != LogCounter.INVALID_LOG_INSTANT, |
306 | "scanning backward beyond the first log file"); |
307 | if (currentLogFileNumber != |
308 | LogCounter.getLogFileNumber(previousLogInstant) + 1) |
309 | SanityManager.THROWASSERT( |
310 | "scanning backward but get incorrect log file number " + |
311 | "expected " + (currentLogFileNumber -1) + |
312 | "get " + |
313 | LogCounter.getLogFileNumber(previousLogInstant)); |
314 | |
315 | SanityManager.ASSERT(LogCounter.getLogFilePosition(previousLogInstant) > |
316 | LogToFile.LOG_FILE_HEADER_SIZE, |
317 | "scanning backward encounter completely empty log file"); |
318 | |
319 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
320 | "scanning backwards from log file " + |
321 | currentLogFileNumber + ", switch to (" + |
322 | LogCounter.getLogFileNumber(previousLogInstant) + "," + |
323 | LogCounter.getLogFilePosition(previousLogInstant) + ")" |
324 | ); |
325 | } |
326 | |
327 | // log file switch, set this.currentLogFileNumber |
328 | currentLogFileNumber = LogCounter.getLogFileNumber(previousLogInstant); |
329 | |
330 | scan = logFactory.getLogFileAtPosition(previousLogInstant); |
331 | |
332 | // scan is located right past the last byte of the last log |
333 | // record in the previous log file. currentLogFileNumber is |
334 | // set. We asserted that the scan is not located right at the |
335 | // end of the file header, in other words, there is at least |
336 | // one log record in this log file. |
337 | curpos = scan.getFilePointer(); |
338 | |
339 | // if the log file happens to be empty skip and proceed. |
340 | // ideally this case should never occur because log switch is |
341 | // not suppose to happen on an empty log file. |
342 | // But it is safer to put following check incase if it ever |
343 | // happens to avoid any recovery issues. |
344 | if (curpos == LogToFile.LOG_FILE_HEADER_SIZE) |
345 | continue; |
346 | } |
347 | |
348 | scan.seek(curpos - 4); |
349 | int recordLength = scan.readInt(); // get the length after the log record |
350 | |
351 | // calculate where this log record started. |
352 | // include the eight bytes for the long log instant at the front |
353 | // the four bytes of length in the front and the four bytes we just read |
354 | long recordStartPosition = curpos - recordLength - |
355 | LogToFile.LOG_RECORD_OVERHEAD; |
356 | |
357 | if (SanityManager.DEBUG) |
358 | { |
359 | if (recordStartPosition < LogToFile.LOG_FILE_HEADER_SIZE) |
360 | SanityManager.THROWASSERT( |
361 | "next position " + recordStartPosition + |
362 | " recordLength " + recordLength + |
363 | " current file position " + scan.getFilePointer()); |
364 | |
365 | scan.seek(recordStartPosition); |
366 | |
367 | // read the length before the log record and check it against the |
368 | // length after the log record |
369 | int checkLength = scan.readInt(); |
370 | |
371 | if (checkLength != recordLength) |
372 | { |
373 | long inst = LogCounter.makeLogInstantAsLong(currentLogFileNumber, recordStartPosition); |
374 | |
375 | throw logFactory.markCorrupt( |
376 | StandardException.newException( |
377 | SQLState.LOG_RECORD_CORRUPTED, |
378 | new Long(checkLength), |
379 | new Long(recordLength), |
380 | new Long(inst), |
381 | new Long(currentLogFileNumber))); |
382 | } |
383 | } |
384 | else |
385 | { |
386 | // skip over the length in insane |
387 | scan.seek(recordStartPosition+4); |
388 | } |
389 | |
390 | // scan is positioned just before the log instant |
391 | // read the current log instant - this is the currentInstant if we have not |
392 | // exceeded the scan limit |
393 | currentInstant = scan.readLong(); |
394 | |
395 | if (SanityManager.DEBUG) |
396 | { |
397 | // sanity check the current instant against the scan position |
398 | if (LogCounter.getLogFileNumber(currentInstant) != |
399 | currentLogFileNumber || |
400 | LogCounter.getLogFilePosition(currentInstant) != |
401 | recordStartPosition) |
402 | SanityManager.THROWASSERT( |
403 | "Wrong LogInstant on log record " + |
404 | LogCounter.toDebugString(currentInstant) + |
405 | " version real position (" + |
406 | currentLogFileNumber + "," + |
407 | recordStartPosition + ")"); |
408 | } |
409 | |
410 | |
411 | // if stopAt == INVALID_LOG_INSTANT, no stop instant, read till |
412 | // nothing more can be read. Else check scan limit |
413 | if (currentInstant < stopAt && stopAt != LogCounter.INVALID_LOG_INSTANT) |
414 | { |
415 | currentInstant = LogCounter.INVALID_LOG_INSTANT; |
416 | return null; // we went past the stopAt |
417 | } |
418 | |
419 | |
420 | byte[] data = input.getData(); |
421 | |
422 | if (data.length < recordLength) |
423 | { |
424 | // make a new array of sufficient size and reset the arrary |
425 | // in the input stream |
426 | data = new byte[recordLength]; |
427 | input.setData(data); |
428 | } |
429 | |
430 | // If the log is encrypted, we must do the filtering after reading |
431 | // and decrypting the record. |
432 | if (logFactory.databaseEncrypted()) |
433 | { |
434 | scan.readFully(data, 0, recordLength); |
435 | int len = logFactory.decrypt(data, 0, recordLength, data, 0); |
436 | if (SanityManager.DEBUG) |
437 | SanityManager.ASSERT(len == recordLength); |
438 | input.setLimit(0, recordLength); |
439 | } |
440 | else // no need to decrypt, only get the group and tid if we filter |
441 | { |
442 | if (groupmask == 0 && tranId == null) |
443 | { |
444 | // no filter, get the whole thing |
445 | scan.readFully(data, 0, recordLength); |
446 | input.setLimit(0, recordLength); |
447 | } |
448 | else |
449 | { |
450 | // Read only enough so that group and the tran id is in |
451 | // the data buffer. Group is stored as compressed int |
452 | // and tran id is stored as who knows what. read min |
453 | // of peekAmount or recordLength |
454 | readAmount = (recordLength > peekAmount) ? |
455 | peekAmount : recordLength; |
456 | |
457 | // in the data buffer, we now have enough to peek |
458 | scan.readFully(data, 0, readAmount); |
459 | input.setLimit(0, readAmount); |
460 | } |
461 | } |
462 | |
463 | lr = (LogRecord) input.readObject(); |
464 | |
465 | // skip the checksum log records, there is no need to look at them |
466 | // during backward scans. They are used only in forwardscan during recovery. |
467 | if(lr.isChecksum()) |
468 | { |
469 | candidate = false; |
470 | }else if (groupmask != 0 || tranId != null) |
471 | { |
472 | |
473 | // skip the checksum log records |
474 | if(lr.isChecksum()) |
475 | candidate = false; |
476 | |
477 | if (candidate && groupmask != 0 && (groupmask & lr.group()) == 0) |
478 | candidate = false; // no match, throw this log record out |
479 | |
480 | if (candidate && tranId != null) |
481 | { |
482 | TransactionId tid = lr.getTransactionId(); |
483 | if (!tid.equals(tranId)) // nomatch |
484 | candidate = false; // throw this log record out |
485 | } |
486 | |
487 | // if this log record is not filtered out, we need to read |
488 | // in the rest of the log record to the input buffer. |
489 | // Except if it is an encrypted database, in which case the |
490 | // entire log record have already be read in for |
491 | // decryption. |
492 | if (candidate && !logFactory.databaseEncrypted()) |
493 | { |
494 | // read the rest of the log into the buffer |
495 | if (SanityManager.DEBUG) |
496 | SanityManager.ASSERT(readAmount > 0); |
497 | |
498 | if (readAmount < recordLength) |
499 | { |
500 | // Need to remember where we are because the log |
501 | // record may have read part of it off the input |
502 | // stream already and that position is lost when we |
503 | // set limit again. |
504 | int inputPosition = input.getPosition(); |
505 | |
506 | scan.readFully(data, readAmount, |
507 | recordLength-readAmount); |
508 | |
509 | input.setLimit(0, recordLength); |
510 | input.setPosition(inputPosition); |
511 | } |
512 | } |
513 | } |
514 | |
515 | // go back to the start of the log record so that the next time |
516 | // this method is called, it is positioned right past the last byte |
517 | // of the record. |
518 | curpos = recordStartPosition; |
519 | scan.seek(curpos); |
520 | |
521 | } while (candidate == false); |
522 | |
523 | return lr; |
524 | |
525 | } |
526 | |
527 | /** |
528 | Read the next log record. |
529 | Switching log to a previous log file if necessary, |
530 | Resize the input stream byte array if necessary. |
531 | @see StreamLogScan#getNextRecord |
532 | |
533 | Side effects include: |
534 | on a successful read, setting currentInstant, knownGoodLogEnd |
535 | on a log file switch, setting currentLogFileNumber, currentLogFileLength. |
536 | on detecting a fuzzy log end that needs clearing, it will call |
537 | logFactory to clear the fuzzy log end. |
538 | |
539 | @return the next LogRecord, or null if the end of the |
540 | scan has been reached. |
541 | */ |
542 | private LogRecord getNextRecordForward(ArrayInputStream input, |
543 | TransactionId tranId, |
544 | int groupmask) |
545 | throws StandardException, IOException, ClassNotFoundException |
546 | { |
547 | if (SanityManager.DEBUG) |
548 | SanityManager.ASSERT(scanDirection == FORWARD, "can only called by forward scan"); |
549 | |
550 | // NOTE: |
551 | // |
552 | // if forward scan, scan is positioned at the first byte of the |
553 | // next record, or the end of file - note the the 'end of file' |
554 | // is defined at the time the scan is initialized. If we are |
555 | // on the current log file, it may well have grown by now... |
556 | // |
557 | // This is not a problem in reality because the only forward |
558 | // scan on the log now is recovery redo and the log does not |
559 | // grow. If in the future, a foward scan of the log is used |
560 | // for some other reasons, need to keep this in mind. |
561 | // |
562 | |
563 | // first we need to make sure the entire log record is on the |
564 | // log, or else this is a fuzzy log end. |
565 | |
566 | // RESOLVE: can get this from knownGoodLogEnd if this is not the first |
567 | // time getNext is called. Probably just as fast to call |
568 | // scan.getFilePointer though... |
569 | long recordStartPosition = scan.getFilePointer(); |
570 | |
571 | boolean candidate; |
572 | |
573 | // if we have filtering, peek at the group and/or the transaction id, |
574 | // do them in one read rather than 2 reads. |
575 | int peekAmount = LogRecord.formatOverhead() + LogRecord.maxGroupStoredSize(); |
576 | if (tranId != null) |
577 | peekAmount += LogRecord.maxTransactionIdStoredSize(tranId); |
578 | |
579 | int readAmount; // the number of bytes actually read |
580 | |
581 | LogRecord lr; |
582 | |
583 | do |
584 | { |
585 | // this log record is a candidate unless proven otherwise |
586 | candidate = true; |
587 | lr = null; |
588 | readAmount = -1; |
589 | |
590 | // if we are not right at the end but this position + 4 is at |
591 | // or exceeds the end, we know we don't have a complete log |
592 | // record. This is the log file and chalk it up as the fuzzy |
593 | // end. |
594 | if (recordStartPosition + 4 > currentLogFileLength) |
595 | { |
596 | // since there is no end of log file marker, we are at the |
597 | // end of the log. |
598 | if (SanityManager.DEBUG) |
599 | { |
600 | if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) |
601 | { |
602 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
603 | "detected fuzzy log end on log file " + |
604 | currentLogFileNumber + |
605 | " record start position " + recordStartPosition + |
606 | " file length " + currentLogFileLength); |
607 | } |
608 | } |
609 | |
610 | //if recordStartPosition == currentLogFileLength |
611 | //there is NO fuzz, it just a properly ended log |
612 | //without the end marker. |
613 | if(recordStartPosition != currentLogFileLength) |
614 | fuzzyLogEnd = true ; |
615 | |
616 | // don't bother to write the end of log file marker because |
617 | // if it is not overwritten by the next log record then |
618 | // the next time the database is recovered it will come |
619 | // back right here |
620 | return null; |
621 | } |
622 | |
623 | // read in the length before the log record |
624 | int recordLength = scan.readInt(); |
625 | |
626 | while (recordLength == 0 || recordStartPosition + recordLength + |
627 | LogToFile.LOG_RECORD_OVERHEAD > currentLogFileLength) |
628 | { |
629 | // if recordLength is zero or the log record goes beyond the |
630 | // current file, then we have detected the end of a log file. |
631 | // |
632 | // If recordLength == 0 then we know that this log file has either |
633 | // been properly switched or it had a 1/2 written log record which |
634 | // was subsequently cleared by clearFuzzyEnd. |
635 | // |
636 | // If recordLength != 0 but log record goes beyond the current log |
637 | // file, we have detected a fuzzy end. This is the last log file |
638 | // since we will clear it by clearFuzzyEnd. |
639 | |
640 | if (recordLength != 0) // this is a fuzzy log end |
641 | { |
642 | if (SanityManager.DEBUG) |
643 | { |
644 | if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) |
645 | { |
646 | SanityManager.DEBUG( |
647 | LogToFile.DBG_FLAG, |
648 | "detected fuzzy log end on log file " + |
649 | currentLogFileNumber + |
650 | " record start position " + |
651 | recordStartPosition + |
652 | " file length " + currentLogFileLength + |
653 | " recordLength=" + recordLength ); |
654 | } |
655 | } |
656 | |
657 | fuzzyLogEnd = true; |
658 | scan.close(); |
659 | scan = null; |
660 | |
661 | return null; |
662 | } |
663 | |
664 | // recordLength == 0 |
665 | |
666 | if (SanityManager.DEBUG) |
667 | { |
668 | if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) |
669 | { |
670 | if (recordStartPosition + 4 == currentLogFileLength) |
671 | { |
672 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
673 | "detected proper log end on log file " + |
674 | currentLogFileNumber); |
675 | } |
676 | else |
677 | { |
678 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
679 | "detected zapped log end on log file " + |
680 | currentLogFileNumber + |
681 | " end marker at " + |
682 | recordStartPosition + |
683 | " real end at " + currentLogFileLength); |
684 | } |
685 | } |
686 | } |
687 | |
688 | // don't go thru the trouble of switching log file if we |
689 | // have will have gone past stopAt if we want to stop here |
690 | if (stopAt != LogCounter.INVALID_LOG_INSTANT && |
691 | LogCounter.getLogFileNumber(stopAt) == currentLogFileNumber) |
692 | { |
693 | return null; |
694 | } |
695 | |
696 | // |
697 | // we have a log end marker and we don't want to stop yet, switch |
698 | // log file |
699 | // |
700 | scan.close(); |
701 | |
702 | // set this.currentLogFileNumber |
703 | scan = logFactory.getLogFileAtBeginning(++currentLogFileNumber); |
704 | if (scan == null) // we have seen the last log file |
705 | { |
706 | return null; |
707 | } |
708 | |
709 | // scan is position just past the log header |
710 | recordStartPosition = scan.getFilePointer(); |
711 | |
712 | // Verify that the header of the new log file refers |
713 | // to the end of the log record of the previous file |
714 | // (Rest of header has been verified by getLogFileAtBeginning) |
715 | scan.seek(LogToFile |
716 | .LOG_FILE_HEADER_PREVIOUS_LOG_INSTANT_OFFSET); |
717 | long previousLogInstant = scan.readLong(); |
718 | if (previousLogInstant != knownGoodLogEnd) { |
719 | // If there is a mismatch, something is wrong and |
720 | // we return null to stop the scan. The same |
721 | // behavior occurs when getLogFileAtBeginning |
722 | // detects an error in the other fields of the header. |
723 | if (SanityManager.DEBUG) { |
724 | if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) { |
725 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
726 | "log file " |
727 | + currentLogFileNumber |
728 | + ": previous log record: " |
729 | + previousLogInstant |
730 | + " known previous log record: " |
731 | + knownGoodLogEnd); |
732 | } |
733 | } |
734 | return null; |
735 | } |
736 | |
737 | |
738 | scan.seek(recordStartPosition); |
739 | |
740 | if (SanityManager.DEBUG) |
741 | { |
742 | if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) |
743 | { |
744 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
745 | "switched to next log file " + |
746 | currentLogFileNumber); |
747 | } |
748 | } |
749 | |
750 | // Advance knownGoodLogEnd to make sure that if this |
751 | // log file is the last log file and empty, logging |
752 | // continues in this file, not the old file. |
753 | knownGoodLogEnd = LogCounter.makeLogInstantAsLong |
754 | (currentLogFileNumber, recordStartPosition); |
755 | |
756 | // set this.currentLogFileLength |
757 | currentLogFileLength = scan.length(); |
758 | |
759 | if (recordStartPosition+4 >= currentLogFileLength) // empty log file |
760 | { |
761 | if (SanityManager.DEBUG) |
762 | { |
763 | if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) |
764 | { |
765 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
766 | "log file " + currentLogFileNumber + |
767 | " is empty"); |
768 | } |
769 | } |
770 | |
771 | return null; |
772 | } |
773 | |
774 | // we have successfully switched to the next log file. |
775 | // scan is positioned just before the next log record |
776 | // see if this one is written in entirety |
777 | recordLength = scan.readInt(); |
778 | } |
779 | |
780 | // we know the entire log record is on this log file |
781 | |
782 | // read the current log instant |
783 | currentInstant = scan.readLong(); |
784 | |
785 | /*check if the current instant happens is less than the last one. |
786 | *This can happen if system crashed before writing the log instant |
787 | *completely. If the instant is partially written it will be less |
788 | *than the last one and should be the last record that was suppose to |
789 | *get written. Currentlt preallocated files are filled with zeros, |
790 | *this should hold good. |
791 | *Note: In case of Non-preallocated files earlier check with log |
792 | * file lengths should have found the end. But in prellocated files, log file |
793 | *length is not sufficiant to find the log end. This check |
794 | *is must to find the end in preallocated log files. |
795 | */ |
796 | if(currentInstant < knownGoodLogEnd) |
797 | { |
798 | fuzzyLogEnd = true ; |
799 | return null; |
800 | } |
801 | |
802 | // sanity check it |
803 | if (SanityManager.DEBUG) |
804 | { |
805 | if (LogCounter.getLogFileNumber(currentInstant) != |
806 | currentLogFileNumber || |
807 | LogCounter.getLogFilePosition(currentInstant) != |
808 | recordStartPosition) |
809 | SanityManager.THROWASSERT( |
810 | "Wrong LogInstant on log record " + |
811 | LogCounter.toDebugString(currentInstant) + |
812 | " version real position (" + |
813 | currentLogFileNumber + "," + |
814 | recordStartPosition + ")"); |
815 | } |
816 | |
817 | |
818 | // if stopAt == INVALID_LOG_INSTANT, no stop instant, read till |
819 | // nothing more can be read. Else check scan limit |
820 | if (stopAt != LogCounter.INVALID_LOG_INSTANT && currentInstant > stopAt) |
821 | { |
822 | currentInstant = LogCounter.INVALID_LOG_INSTANT; |
823 | return null; // we went past the stopAt |
824 | } |
825 | |
826 | // read in the log record |
827 | byte[] data = input.getData(); |
828 | |
829 | if (data.length < recordLength) |
830 | { |
831 | // make a new array of sufficient size and reset the arrary |
832 | // in the input stream |
833 | data = new byte[recordLength]; |
834 | input.setData(data); |
835 | } |
836 | |
837 | // If the log is encrypted, we must do the filtering after |
838 | // reading and decryptiong the record. |
839 | |
840 | if (logFactory.databaseEncrypted()) |
841 | { |
842 | scan.readFully(data, 0, recordLength); |
843 | int len = logFactory.decrypt(data, 0, recordLength, data, 0); |
844 | if (SanityManager.DEBUG) |
845 | SanityManager.ASSERT(len == recordLength); |
846 | |
847 | input.setLimit(0, len); |
848 | } |
849 | else // no need to decrypt, only get the group and tid if we filter |
850 | { |
851 | if (groupmask == 0 && tranId == null) |
852 | { |
853 | // no filter, get the whole thing |
854 | scan.readFully(data, 0, recordLength); |
855 | input.setLimit(0, recordLength); |
856 | } |
857 | else |
858 | { |
859 | // Read only enough so that group and the tran id is in |
860 | // the data buffer. Group is stored as compressed int |
861 | // and tran id is stored as who knows what. read min |
862 | // of peekAmount or recordLength |
863 | readAmount = (recordLength > peekAmount) ? |
864 | peekAmount : recordLength; |
865 | |
866 | // in the data buffer, we now have enough to peek |
867 | scan.readFully(data, 0, readAmount); |
868 | input.setLimit(0, readAmount); |
869 | } |
870 | } |
871 | |
872 | lr = (LogRecord) input.readObject(); |
873 | if (groupmask != 0 || tranId != null) |
874 | { |
875 | if (groupmask != 0 && (groupmask & lr.group()) == 0) |
876 | candidate = false; // no match, throw this log record out |
877 | |
878 | if (candidate && tranId != null) |
879 | { |
880 | TransactionId tid = lr.getTransactionId(); |
881 | if (!tid.equals(tranId)) // nomatch |
882 | candidate = false; // throw this log record out |
883 | } |
884 | |
885 | // if this log record is not filtered out, we need to read |
886 | // in the rest of the log record to the input buffer. |
887 | // Except if it is an encrypted database, in which case the |
888 | // entire log record have already be read in for |
889 | // decryption. |
890 | if (candidate && !logFactory.databaseEncrypted()) |
891 | { |
892 | // read the rest of the log into the buffer |
893 | if (SanityManager.DEBUG) |
894 | SanityManager.ASSERT(readAmount > 0); |
895 | |
896 | if (readAmount < recordLength) |
897 | { |
898 | // Need to remember where we are because the log |
899 | // record may have read part of it off the input |
900 | // stream already and that position is lost when we |
901 | // set limit again. |
902 | int inputPosition = input.getPosition(); |
903 | |
904 | scan.readFully(data, readAmount, |
905 | recordLength-readAmount); |
906 | |
907 | input.setLimit(0, recordLength); |
908 | input.setPosition(inputPosition); |
909 | } |
910 | } |
911 | } |
912 | |
913 | /*check if the logrecord length written before and after the |
914 | *log record are equal, if not the end of of the log is reached. |
915 | *This can happen if system crashed before writing the length field |
916 | *in the end of the records completely. If the length is partially |
917 | *written or not written at all it will not match with length written |
918 | *in the beginning of the log record. Currentlt preallocated files |
919 | *are filled with zeros, log record length can never be zero; |
920 | *if the lengths are not matching, end of the properly written log |
921 | *is reached. |
922 | *Note: In case of Non-preallocated files earlier fuzzy case check with log |
923 | * file lengths should have found the end. But in prellocated files, log file |
924 | *length is not sufficiant to find the log end. This check |
925 | *is must to find the end in preallocated log files. |
926 | */ |
927 | // read the length after the log record and check it against the |
928 | // length before the log record, make sure we go to the correct |
929 | // place for skipped log record. |
930 | if (!candidate) |
931 | scan.seek(recordStartPosition - 4); |
932 | int checkLength = scan.readInt(); |
933 | if (checkLength != recordLength && checkLength < recordLength) |
934 | { |
935 | |
936 | |
937 | //lengh written in the end of the log record should be always |
938 | //less then the length written in the beginning if the log |
939 | //record was half written before the crash. |
940 | if(checkLength < recordLength) |
941 | { |
942 | fuzzyLogEnd = true ; |
943 | return null; |
944 | }else |
945 | { |
946 | |
947 | //If checklength > recordLength then it can be not be a partial write |
948 | //probablly it is corrupted for some reason , this should never |
949 | //happen throw error in debug mode. In non debug case , let's |
950 | //hope it's only is wrong and system can proceed. |
951 | |
952 | if (SanityManager.DEBUG) |
953 | { |
954 | throw logFactory.markCorrupt |
955 | (StandardException.newException( |
956 | SQLState.LOG_RECORD_CORRUPTED, |
957 | new Long(checkLength), |
958 | new Long(recordLength), |
959 | new Long(currentInstant), |
960 | new Long(currentLogFileNumber))); |
961 | |
962 | } |
963 | |
964 | //In non debug case, do nothing , let's hope it's only |
965 | //length part that is incorrect and system can proceed. |
966 | } |
967 | |
968 | } |
969 | |
970 | // next record start position is right after this record |
971 | recordStartPosition += recordLength + LogToFile.LOG_RECORD_OVERHEAD; |
972 | knownGoodLogEnd = LogCounter.makeLogInstantAsLong |
973 | (currentLogFileNumber, recordStartPosition); |
974 | |
975 | |
976 | if (SanityManager.DEBUG) |
977 | { |
978 | if (recordStartPosition != scan.getFilePointer()) |
979 | SanityManager.THROWASSERT( |
980 | "calculated end " + recordStartPosition + |
981 | " != real end " + scan.getFilePointer()); |
982 | } |
983 | else |
984 | { |
985 | // seek to the start of the next log record |
986 | scan.seek(recordStartPosition); |
987 | } |
988 | |
989 | // the scan is now positioned just past this log record and right |
990 | // at the beginning of the next log record |
991 | |
992 | |
993 | /** if the current log record is a checksum log record then |
994 | * using the information available in this record validate |
995 | * that data in the log file by matching the checksum in |
996 | * checksum log record and by recalculating the checksum for the |
997 | * specified length of the data in the log file. cheksum values |
998 | * should match unless the right was incomplete before the crash. |
999 | */ |
1000 | if(lr.isChecksum()) |
1001 | { |
1002 | // checksum log record should not be returned to the logger recovery redo |
1003 | // routines, it is just used to identify the incomplete log writes. |
1004 | |
1005 | candidate = false; |
1006 | Loggable op = lr.getLoggable(); |
1007 | if (SanityManager.DEBUG) |
1008 | { |
1009 | if (SanityManager.DEBUG_ON(LogToFile.DUMP_LOG_ONLY) || |
1010 | SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) |
1011 | |
1012 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
1013 | "scanned " + "Null" + " : " + op + |
1014 | " instant = " + |
1015 | LogCounter.toDebugString(currentInstant) + |
1016 | " logEnd = " + LogCounter.toDebugString(knownGoodLogEnd)); |
1017 | } |
1018 | |
1019 | ChecksumOperation clop = (ChecksumOperation) op; |
1020 | int ckDataLength = clop.getDataLength(); |
1021 | // resize the buffer to be size of checksum data length if required. |
1022 | if (data.length < ckDataLength) |
1023 | { |
1024 | // make a new array of sufficient size and reset the arrary |
1025 | // in the input stream |
1026 | data = new byte[ckDataLength]; |
1027 | input.setData(data); |
1028 | input.setLimit(0, ckDataLength); |
1029 | } |
1030 | |
1031 | boolean validChecksum = false; |
1032 | // check if the expected number of bytes by the checksum log |
1033 | // record actually exist in the file and then verify if checksum |
1034 | // is valid to identify any incomplete out of order writes. |
1035 | if((recordStartPosition + ckDataLength) <= currentLogFileLength) |
1036 | { |
1037 | // read the data into the buffer |
1038 | scan.readFully(data, 0, ckDataLength); |
1039 | // verify the checksum |
1040 | if(clop.isChecksumValid(data, 0 , ckDataLength)) |
1041 | validChecksum = true; |
1042 | } |
1043 | |
1044 | |
1045 | if(!validChecksum) |
1046 | { |
1047 | // declare that the end of the transaction log is fuzzy, checksum is invalid |
1048 | // only when the writes are incomplete; this can happen |
1049 | // only when writes at the end of the log were partially |
1050 | // written before the crash. |
1051 | |
1052 | if (SanityManager.DEBUG) |
1053 | { |
1054 | if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) |
1055 | { |
1056 | SanityManager.DEBUG( |
1057 | LogToFile.DBG_FLAG, |
1058 | "detected fuzzy log end on log file while doing checksum checks " + |
1059 | currentLogFileNumber + |
1060 | " checksum record start position " + recordStartPosition + |
1061 | " file length " + currentLogFileLength + |
1062 | " checksumDataLength=" + ckDataLength); |
1063 | } |
1064 | |
1065 | } |
1066 | |
1067 | fuzzyLogEnd = true; |
1068 | scan.close(); |
1069 | scan = null; |
1070 | return null; |
1071 | } |
1072 | |
1073 | // reset the scan to the start of the next log record |
1074 | scan.seek(recordStartPosition); |
1075 | } |
1076 | |
1077 | |
1078 | } while (candidate == false) ; |
1079 | |
1080 | return lr; |
1081 | } |
1082 | |
1083 | |
1084 | /** |
1085 | Reset the scan to the given LogInstant. |
1086 | |
1087 | @param instant the position to reset to |
1088 | @exception IOException scan cannot access the log at the new position. |
1089 | @exception StandardException cloudscape standard error policy |
1090 | */ |
1091 | |
1092 | public void resetPosition(LogInstant instant) |
1093 | throws IOException, StandardException |
1094 | { |
1095 | if (SanityManager.DEBUG) |
1096 | SanityManager.ASSERT(instant != null); |
1097 | |
1098 | long instant_long = ((LogCounter)instant).getValueAsLong(); |
1099 | |
1100 | if ((instant_long == LogCounter.INVALID_LOG_INSTANT) || |
1101 | (stopAt != LogCounter.INVALID_LOG_INSTANT && |
1102 | (scanDirection == FORWARD && instant_long > stopAt) || |
1103 | (scanDirection == FORWARD && instant_long < stopAt))) |
1104 | { |
1105 | close(); |
1106 | |
1107 | throw StandardException.newException( |
1108 | SQLState.LOG_RESET_BEYOND_SCAN_LIMIT, |
1109 | instant, new LogCounter(stopAt)); |
1110 | } |
1111 | else |
1112 | { |
1113 | long fnum = ((LogCounter)instant).getLogFileNumber(); |
1114 | |
1115 | if (fnum != currentLogFileNumber) |
1116 | { |
1117 | if (SanityManager.DEBUG) |
1118 | { |
1119 | if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) |
1120 | { |
1121 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
1122 | "Scan " + scanDirection + |
1123 | " resetting to " + instant + |
1124 | " need to switch log from " + |
1125 | currentLogFileNumber + " to " + fnum); |
1126 | } |
1127 | } |
1128 | |
1129 | scan.close(); |
1130 | scan = logFactory.getLogFileAtPosition(instant_long); |
1131 | |
1132 | currentLogFileNumber= fnum; |
1133 | |
1134 | if (scanDirection == FORWARD) |
1135 | { |
1136 | // NOTE: |
1137 | // |
1138 | // just get the length of the file without syncing. |
1139 | // this only works because the only place forward scan is used |
1140 | // right now is on recovery redo and nothing is being added to |
1141 | // the current log file. When the forward scan is used for some |
1142 | // other purpose, need to sync access to the end of the log |
1143 | // |
1144 | currentLogFileLength = scan.length(); |
1145 | } |
1146 | } |
1147 | else |
1148 | |
1149 | { |
1150 | long fpos = ((LogCounter)instant).getLogFilePosition(); |
1151 | scan.seek(fpos); |
1152 | |
1153 | // |
1154 | //RESOLVE: Can this be optimized? Does it belong here. |
1155 | currentLogFileLength = scan.length(); |
1156 | |
1157 | if (SanityManager.DEBUG) |
1158 | { |
1159 | if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) |
1160 | { |
1161 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
1162 | "Scan reset to " + instant); |
1163 | } |
1164 | } |
1165 | } |
1166 | |
1167 | |
1168 | currentInstant = instant_long; |
1169 | |
1170 | //scan is being reset, it is possibly that, scan is doing a random |
1171 | //access of the log file. set the knownGoodLogEnd to the instant |
1172 | //scan is being reset to. |
1173 | //Note: reset gets called with undo forward scan for CLR processing during |
1174 | //recovery, if this value is not reset checks to find the end of log |
1175 | //getNextRecordForward() will fail because undoscan scans log file |
1176 | //back & forth to redo CLR's. |
1177 | knownGoodLogEnd = currentInstant; |
1178 | |
1179 | if (SanityManager.DEBUG) |
1180 | { |
1181 | if (SanityManager.DEBUG_ON(LogToFile.DBG_FLAG)) |
1182 | { |
1183 | SanityManager.DEBUG(LogToFile.DBG_FLAG, |
1184 | "Scan.getInstant reset to " + currentInstant + |
1185 | LogCounter.toDebugString(currentInstant)); |
1186 | } |
1187 | } |
1188 | } |
1189 | } |
1190 | |
1191 | /** |
1192 | Return the log instant (as an integer) the scan is currently on - this is the log |
1193 | instant of the log record that was returned by getNextRecord. |
1194 | */ |
1195 | public long getInstant() |
1196 | { |
1197 | return currentInstant; |
1198 | } |
1199 | |
1200 | /** |
1201 | Return the log instant at the end of the log record on the current |
1202 | LogFile in the form of a log instant. |
1203 | After the scan has been closed, the end of the last log record will be |
1204 | returned except when the scan ended in an empty log file. In that |
1205 | case, the start of this empty log file will be returned. (This is |
1206 | done to make sure new log records are inserted into the newest log |
1207 | file.) |
1208 | */ |
1209 | public long getLogRecordEnd() |
1210 | { |
1211 | return knownGoodLogEnd; |
1212 | } |
1213 | |
1214 | /** |
1215 | returns true if there is partially writen log records before the crash |
1216 | in the last log file. Partiall wrires are identified during forward |
1217 | redo scans for log recovery. |
1218 | */ |
1219 | public boolean isLogEndFuzzy() |
1220 | { |
1221 | return fuzzyLogEnd; |
1222 | } |
1223 | |
1224 | /** |
1225 | Return the log instant the scan is currently on - this is the log |
1226 | instant of the log record that was returned by getNextRecord. |
1227 | */ |
1228 | public LogInstant getLogInstant() |
1229 | { |
1230 | if (currentInstant == LogCounter.INVALID_LOG_INSTANT) |
1231 | return null; |
1232 | else |
1233 | return new LogCounter(currentInstant); |
1234 | } |
1235 | |
1236 | /** |
1237 | Close the scan. |
1238 | */ |
1239 | public void close() |
1240 | { |
1241 | if (scan != null) |
1242 | { |
1243 | try |
1244 | { |
1245 | scan.close(); |
1246 | } |
1247 | catch (IOException ioe) |
1248 | {} |
1249 | |
1250 | scan = null; |
1251 | } |
1252 | |
1253 | logFactory = null; |
1254 | currentLogFileNumber = -1; |
1255 | currentLogFileLength = -1; |
1256 | // Do not reset knownGoodLogEnd, it needs to be available after the |
1257 | // scan has closed. |
1258 | currentInstant = LogCounter.INVALID_LOG_INSTANT; |
1259 | stopAt = LogCounter.INVALID_LOG_INSTANT; |
1260 | scanDirection = 0; |
1261 | } |
1262 | |
1263 | } |