View Javadoc

1   /**
2    * Licensed to the Apache Software Foundation (ASF) under one
3    * or more contributor license agreements.  See the NOTICE file
4    * distributed with this work for additional information
5    * regarding copyright ownership.  The ASF licenses this file
6    * to you under the Apache License, Version 2.0 (the
7    * "License"); you may not use this file except in compliance
8    * with the License.  You may obtain a copy of the License at
9    *
10   *     http://www.apache.org/licenses/LICENSE-2.0
11   *
12   * Unless required by applicable law or agreed to in writing, software
13   * distributed under the License is distributed on an "AS IS" BASIS,
14   * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15   * See the License for the specific language governing permissions and
16   * limitations under the License.
17   */
18  
19  package org.apache.hadoop.hbase.procedure2.store.wal;
20  
21  import java.io.IOException;
22  import java.io.FileNotFoundException;
23  import java.util.concurrent.atomic.AtomicBoolean;
24  import java.util.concurrent.atomic.AtomicLong;
25  import java.util.concurrent.atomic.AtomicReference;
26  import java.util.concurrent.locks.Condition;
27  import java.util.concurrent.locks.ReentrantLock;
28  import java.util.concurrent.LinkedTransferQueue;
29  import java.util.concurrent.CopyOnWriteArrayList;
30  import java.util.concurrent.TimeUnit;
31  import java.util.Arrays;
32  import java.util.ArrayList;
33  import java.util.Collections;
34  import java.util.HashSet;
35  import java.util.Iterator;
36  import java.util.LinkedList;
37  import java.util.Set;
38  
39  import org.apache.commons.logging.Log;
40  import org.apache.commons.logging.LogFactory;
41  import org.apache.hadoop.conf.Configuration;
42  import org.apache.hadoop.fs.FSDataOutputStream;
43  import org.apache.hadoop.fs.FileAlreadyExistsException;
44  import org.apache.hadoop.fs.FileStatus;
45  import org.apache.hadoop.fs.FileSystem;
46  import org.apache.hadoop.fs.Path;
47  import org.apache.hadoop.fs.PathFilter;
48  import org.apache.hadoop.hbase.classification.InterfaceAudience;
49  import org.apache.hadoop.hbase.classification.InterfaceStability;
50  import org.apache.hadoop.hbase.procedure2.Procedure;
51  import org.apache.hadoop.hbase.procedure2.store.ProcedureStore;
52  import org.apache.hadoop.hbase.procedure2.store.ProcedureStoreTracker;
53  import org.apache.hadoop.hbase.procedure2.util.ByteSlot;
54  import org.apache.hadoop.hbase.procedure2.util.StringUtils;
55  import org.apache.hadoop.hbase.protobuf.generated.ProcedureProtos.ProcedureWALHeader;
56  import org.apache.hadoop.hbase.util.Threads;
57  import org.apache.hadoop.ipc.RemoteException;
58  
59  import com.google.common.annotations.VisibleForTesting;
60  
61  /**
62   * WAL implementation of the ProcedureStore.
63   */
64  @InterfaceAudience.Private
65  @InterfaceStability.Evolving
66  public class WALProcedureStore implements ProcedureStore {
67    private static final Log LOG = LogFactory.getLog(WALProcedureStore.class);
68  
69    public interface LeaseRecovery {
70      void recoverFileLease(FileSystem fs, Path path) throws IOException;
71    }
72  
73    private static final String MAX_RETRIES_BEFORE_ROLL_CONF_KEY =
74      "hbase.procedure.store.wal.max.retries.before.roll";
75    private static final int DEFAULT_MAX_RETRIES_BEFORE_ROLL = 3;
76  
77    private static final String WAIT_BEFORE_ROLL_CONF_KEY =
78      "hbase.procedure.store.wal.wait.before.roll";
79    private static final int DEFAULT_WAIT_BEFORE_ROLL = 500;
80  
81    private static final String ROLL_RETRIES_CONF_KEY =
82      "hbase.procedure.store.wal.max.roll.retries";
83    private static final int DEFAULT_ROLL_RETRIES = 3;
84  
85    private static final String MAX_SYNC_FAILURE_ROLL_CONF_KEY =
86      "hbase.procedure.store.wal.sync.failure.roll.max";
87    private static final int DEFAULT_MAX_SYNC_FAILURE_ROLL = 3;
88  
89    private static final String PERIODIC_ROLL_CONF_KEY =
90      "hbase.procedure.store.wal.periodic.roll.msec";
91    private static final int DEFAULT_PERIODIC_ROLL = 60 * 60 * 1000; // 1h
92  
93    private static final String SYNC_WAIT_MSEC_CONF_KEY = "hbase.procedure.store.wal.sync.wait.msec";
94    private static final int DEFAULT_SYNC_WAIT_MSEC = 100;
95  
96    private static final String USE_HSYNC_CONF_KEY = "hbase.procedure.store.wal.use.hsync";
97    private static final boolean DEFAULT_USE_HSYNC = true;
98  
99    private static final String ROLL_THRESHOLD_CONF_KEY = "hbase.procedure.store.wal.roll.threshold";
100   private static final long DEFAULT_ROLL_THRESHOLD = 32 * 1024 * 1024; // 32M
101 
102   private final CopyOnWriteArrayList<ProcedureStoreListener> listeners =
103     new CopyOnWriteArrayList<ProcedureStoreListener>();
104 
105   private final LinkedList<ProcedureWALFile> logs = new LinkedList<ProcedureWALFile>();
106   private final ProcedureStoreTracker storeTracker = new ProcedureStoreTracker();
107   private final AtomicBoolean running = new AtomicBoolean(false);
108 
109   private final ReentrantLock lock = new ReentrantLock();
110   private final Condition waitCond = lock.newCondition();
111   private final Condition slotCond = lock.newCondition();
112   private final Condition syncCond = lock.newCondition();
113 
114   private final LeaseRecovery leaseRecovery;
115   private final Configuration conf;
116   private final FileSystem fs;
117   private final Path logDir;
118 
119   private final AtomicReference<Throwable> syncException = new AtomicReference<Throwable>();
120   private final AtomicBoolean loading = new AtomicBoolean(true);
121   private final AtomicBoolean inSync = new AtomicBoolean(false);
122   private final AtomicLong totalSynced = new AtomicLong(0);
123   private final AtomicLong lastRollTs = new AtomicLong(0);
124 
125   private LinkedTransferQueue<ByteSlot> slotsCache = null;
126   private Set<ProcedureWALFile> corruptedLogs = null;
127   private FSDataOutputStream stream = null;
128   private long flushLogId = 0;
129   private int slotIndex = 0;
130   private Thread syncThread;
131   private ByteSlot[] slots;
132 
133   private int maxRetriesBeforeRoll;
134   private int maxSyncFailureRoll;
135   private int waitBeforeRoll;
136   private int rollRetries;
137   private int periodicRollMsec;
138   private long rollThreshold;
139   private boolean useHsync;
140   private int syncWaitMsec;
141 
142   public WALProcedureStore(final Configuration conf, final FileSystem fs, final Path logDir,
143       final LeaseRecovery leaseRecovery) {
144     this.fs = fs;
145     this.conf = conf;
146     this.logDir = logDir;
147     this.leaseRecovery = leaseRecovery;
148   }
149 
150   @Override
151   public void start(int numSlots) throws IOException {
152     if (running.getAndSet(true)) {
153       return;
154     }
155 
156     // Init buffer slots
157     loading.set(true);
158     slots = new ByteSlot[numSlots];
159     slotsCache = new LinkedTransferQueue();
160     while (slotsCache.size() < numSlots) {
161       slotsCache.offer(new ByteSlot());
162     }
163 
164     // Tunings
165     maxRetriesBeforeRoll =
166       conf.getInt(MAX_RETRIES_BEFORE_ROLL_CONF_KEY, DEFAULT_MAX_RETRIES_BEFORE_ROLL);
167     maxSyncFailureRoll = conf.getInt(MAX_SYNC_FAILURE_ROLL_CONF_KEY, DEFAULT_MAX_SYNC_FAILURE_ROLL);
168     waitBeforeRoll = conf.getInt(WAIT_BEFORE_ROLL_CONF_KEY, DEFAULT_WAIT_BEFORE_ROLL);
169     rollRetries = conf.getInt(ROLL_RETRIES_CONF_KEY, DEFAULT_ROLL_RETRIES);
170     rollThreshold = conf.getLong(ROLL_THRESHOLD_CONF_KEY, DEFAULT_ROLL_THRESHOLD);
171     periodicRollMsec = conf.getInt(PERIODIC_ROLL_CONF_KEY, DEFAULT_PERIODIC_ROLL);
172     syncWaitMsec = conf.getInt(SYNC_WAIT_MSEC_CONF_KEY, DEFAULT_SYNC_WAIT_MSEC);
173     useHsync = conf.getBoolean(USE_HSYNC_CONF_KEY, DEFAULT_USE_HSYNC);
174 
175     // Init sync thread
176     syncThread = new Thread("WALProcedureStoreSyncThread") {
177       @Override
178       public void run() {
179         try {
180           syncLoop();
181         } catch (Throwable e) {
182           LOG.error("Got an exception from the sync-loop", e);
183           if (!isSyncAborted()) {
184             sendAbortProcessSignal();
185           }
186         }
187       }
188     };
189     syncThread.start();
190   }
191 
192   @Override
193   public void stop(boolean abort) {
194     if (!running.getAndSet(false)) {
195       return;
196     }
197 
198     LOG.info("Stopping the WAL Procedure Store");
199     sendStopSignal();
200 
201     if (!abort) {
202       try {
203         while (syncThread.isAlive()) {
204           sendStopSignal();
205           syncThread.join(250);
206         }
207       } catch (InterruptedException e) {
208         LOG.warn("join interrupted", e);
209         Thread.currentThread().interrupt();
210       }
211     }
212 
213     // Close the writer
214     closeStream();
215 
216     // Close the old logs
217     // they should be already closed, this is just in case the load fails
218     // and we call start() and then stop()
219     for (ProcedureWALFile log: logs) {
220       log.close();
221     }
222     logs.clear();
223   }
224 
225   private void sendStopSignal() {
226     if (lock.tryLock()) {
227       try {
228         waitCond.signalAll();
229         syncCond.signalAll();
230       } finally {
231         lock.unlock();
232       }
233     }
234   }
235 
236   @Override
237   public boolean isRunning() {
238     return running.get();
239   }
240 
241   @Override
242   public int getNumThreads() {
243     return slots == null ? 0 : slots.length;
244   }
245 
246   public ProcedureStoreTracker getStoreTracker() {
247     return storeTracker;
248   }
249 
250   public LinkedList<ProcedureWALFile> getActiveLogs() {
251     return logs;
252   }
253 
254   public Set<ProcedureWALFile> getCorruptedLogs() {
255     return corruptedLogs;
256   }
257 
258   @Override
259   public void registerListener(ProcedureStoreListener listener) {
260     this.listeners.add(listener);
261   }
262 
263   @Override
264   public boolean unregisterListener(ProcedureStoreListener listener) {
265     return this.listeners.remove(listener);
266   }
267 
268   @Override
269   public void recoverLease() throws IOException {
270     lock.lock();
271     try {
272       LOG.info("Starting WAL Procedure Store lease recovery");
273       FileStatus[] oldLogs = getLogFiles();
274       while (isRunning()) {
275         // Get Log-MaxID and recover lease on old logs
276         flushLogId = initOldLogs(oldLogs);
277 
278         // Create new state-log
279         if (!rollWriter(flushLogId + 1)) {
280           // someone else has already created this log
281           LOG.debug("someone else has already created log " + flushLogId);
282           continue;
283         }
284 
285         // We have the lease on the log
286         oldLogs = getLogFiles();
287         if (getMaxLogId(oldLogs) > flushLogId) {
288           if (LOG.isDebugEnabled()) {
289             LOG.debug("Someone else created new logs. Expected maxLogId < " + flushLogId);
290           }
291           logs.getLast().removeFile();
292           continue;
293         }
294 
295         LOG.info("Lease acquired for flushLogId: " + flushLogId);
296         break;
297       }
298     } finally {
299       lock.unlock();
300     }
301   }
302 
303   @Override
304   public Iterator<Procedure> load() throws IOException {
305     if (logs.isEmpty()) {
306       throw new RuntimeException("recoverLease() must be called before loading data");
307     }
308 
309     // Nothing to do, If we have only the current log.
310     if (logs.size() == 1) {
311       if (LOG.isDebugEnabled()) {
312         LOG.debug("No state logs to replay.");
313       }
314       loading.set(false);
315       return null;
316     }
317 
318     // Load the old logs
319     final ArrayList<ProcedureWALFile> toRemove = new ArrayList<ProcedureWALFile>();
320     Iterator<ProcedureWALFile> it = logs.descendingIterator();
321     it.next(); // Skip the current log
322     try {
323       return ProcedureWALFormat.load(it, storeTracker, new ProcedureWALFormat.Loader() {
324         @Override
325         public void removeLog(ProcedureWALFile log) {
326           toRemove.add(log);
327         }
328 
329         @Override
330         public void markCorruptedWAL(ProcedureWALFile log, IOException e) {
331           if (corruptedLogs == null) {
332             corruptedLogs = new HashSet<ProcedureWALFile>();
333           }
334           corruptedLogs.add(log);
335           // TODO: sideline corrupted log
336         }
337       });
338     } finally {
339       if (!toRemove.isEmpty()) {
340         for (ProcedureWALFile log: toRemove) {
341           removeLogFile(log);
342         }
343       }
344       loading.set(false);
345     }
346   }
347 
348   @Override
349   public void insert(final Procedure proc, final Procedure[] subprocs) {
350     if (LOG.isTraceEnabled()) {
351       LOG.trace("Insert " + proc + ", subproc=" + Arrays.toString(subprocs));
352     }
353 
354     ByteSlot slot = acquireSlot();
355     try {
356       // Serialize the insert
357       long[] subProcIds = null;
358       if (subprocs != null) {
359         ProcedureWALFormat.writeInsert(slot, proc, subprocs);
360         subProcIds = new long[subprocs.length];
361         for (int i = 0; i < subprocs.length; ++i) {
362           subProcIds[i] = subprocs[i].getProcId();
363         }
364       } else {
365         assert !proc.hasParent();
366         ProcedureWALFormat.writeInsert(slot, proc);
367       }
368 
369       // Push the transaction data and wait until it is persisted
370       pushData(PushType.INSERT, slot, proc.getProcId(), subProcIds);
371     } catch (IOException e) {
372       // We are not able to serialize the procedure.
373       // this is a code error, and we are not able to go on.
374       LOG.fatal("Unable to serialize one of the procedure: proc=" + proc +
375                 ", subprocs=" + Arrays.toString(subprocs), e);
376       throw new RuntimeException(e);
377     } finally {
378       releaseSlot(slot);
379     }
380   }
381 
382   @Override
383   public void update(final Procedure proc) {
384     if (LOG.isTraceEnabled()) {
385       LOG.trace("Update " + proc);
386     }
387 
388     ByteSlot slot = acquireSlot();
389     try {
390       // Serialize the update
391       ProcedureWALFormat.writeUpdate(slot, proc);
392 
393       // Push the transaction data and wait until it is persisted
394       pushData(PushType.UPDATE, slot, proc.getProcId(), null);
395     } catch (IOException e) {
396       // We are not able to serialize the procedure.
397       // this is a code error, and we are not able to go on.
398       LOG.fatal("Unable to serialize the procedure: " + proc, e);
399       throw new RuntimeException(e);
400     } finally {
401       releaseSlot(slot);
402     }
403   }
404 
405   @Override
406   public void delete(final long procId) {
407     if (LOG.isTraceEnabled()) {
408       LOG.trace("Delete " + procId);
409     }
410 
411     ByteSlot slot = acquireSlot();
412     try {
413       // Serialize the delete
414       ProcedureWALFormat.writeDelete(slot, procId);
415 
416       // Push the transaction data and wait until it is persisted
417       pushData(PushType.DELETE, slot, procId, null);
418     } catch (IOException e) {
419       // We are not able to serialize the procedure.
420       // this is a code error, and we are not able to go on.
421       LOG.fatal("Unable to serialize the procedure: " + procId, e);
422       throw new RuntimeException(e);
423     } finally {
424       releaseSlot(slot);
425     }
426   }
427 
428   private ByteSlot acquireSlot() {
429     ByteSlot slot = slotsCache.poll();
430     return slot != null ? slot : new ByteSlot();
431   }
432 
433   private void releaseSlot(final ByteSlot slot) {
434     slot.reset();
435     slotsCache.offer(slot);
436   }
437 
438   private enum PushType { INSERT, UPDATE, DELETE };
439 
440   private long pushData(final PushType type, final ByteSlot slot,
441       final long procId, final long[] subProcIds) {
442     if (!isRunning()) {
443       throw new RuntimeException("the store must be running before inserting data");
444     }
445     if (logs.isEmpty()) {
446       throw new RuntimeException("recoverLease() must be called before inserting data");
447     }
448 
449     long logId = -1;
450     lock.lock();
451     try {
452       // Wait for the sync to be completed
453       while (true) {
454         if (!isRunning()) {
455           throw new RuntimeException("store no longer running");
456         } else if (isSyncAborted()) {
457           throw new RuntimeException("sync aborted", syncException.get());
458         } else if (inSync.get()) {
459           syncCond.await();
460         } else if (slotIndex == slots.length) {
461           slotCond.signal();
462           syncCond.await();
463         } else {
464           break;
465         }
466       }
467 
468       updateStoreTracker(type, procId, subProcIds);
469       slots[slotIndex++] = slot;
470       logId = flushLogId;
471 
472       // Notify that there is new data
473       if (slotIndex == 1) {
474         waitCond.signal();
475       }
476 
477       // Notify that the slots are full
478       if (slotIndex == slots.length) {
479         waitCond.signal();
480         slotCond.signal();
481       }
482 
483       syncCond.await();
484     } catch (InterruptedException e) {
485       Thread.currentThread().interrupt();
486       sendAbortProcessSignal();
487       throw new RuntimeException(e);
488     } finally {
489       lock.unlock();
490       if (isSyncAborted()) {
491         throw new RuntimeException("sync aborted", syncException.get());
492       }
493     }
494     return logId;
495   }
496 
497   private void updateStoreTracker(final PushType type,
498       final long procId, final long[] subProcIds) {
499     switch (type) {
500       case INSERT:
501         if (subProcIds == null) {
502           storeTracker.insert(procId);
503         } else {
504           storeTracker.insert(procId, subProcIds);
505         }
506         break;
507       case UPDATE:
508         storeTracker.update(procId);
509         break;
510       case DELETE:
511         storeTracker.delete(procId);
512         break;
513       default:
514         throw new RuntimeException("invalid push type " + type);
515     }
516   }
517 
518   private boolean isSyncAborted() {
519     return syncException.get() != null;
520   }
521 
522   private void syncLoop() throws Throwable {
523     inSync.set(false);
524     lock.lock();
525     try {
526       while (isRunning()) {
527         try {
528           // Wait until new data is available
529           if (slotIndex == 0) {
530             if (!loading.get()) {
531               periodicRoll();
532             }
533 
534             if (LOG.isTraceEnabled()) {
535               float rollTsSec = getMillisFromLastRoll() / 1000.0f;
536               LOG.trace(String.format("Waiting for data. flushed=%s (%s/sec)",
537                         StringUtils.humanSize(totalSynced.get()),
538                         StringUtils.humanSize(totalSynced.get() / rollTsSec)));
539             }
540 
541             waitCond.await(getMillisToNextPeriodicRoll(), TimeUnit.MILLISECONDS);
542             if (slotIndex == 0) {
543               // no data.. probably a stop() or a periodic roll
544               continue;
545             }
546           }
547 
548           // Wait SYNC_WAIT_MSEC or the signal of "slots full" before flushing
549           long syncWaitSt = System.currentTimeMillis();
550           if (slotIndex != slots.length) {
551             slotCond.await(syncWaitMsec, TimeUnit.MILLISECONDS);
552           }
553           long syncWaitMs = System.currentTimeMillis() - syncWaitSt;
554           if (LOG.isTraceEnabled() && (syncWaitMs > 10 || slotIndex < slots.length)) {
555             float rollSec = getMillisFromLastRoll() / 1000.0f;
556             LOG.trace(String.format("Sync wait %s, slotIndex=%s , totalSynced=%s (%s/sec)",
557                       StringUtils.humanTimeDiff(syncWaitMs), slotIndex,
558                       StringUtils.humanSize(totalSynced.get()),
559                       StringUtils.humanSize(totalSynced.get() / rollSec)));
560           }
561 
562           inSync.set(true);
563           totalSynced.addAndGet(syncSlots());
564           slotIndex = 0;
565           inSync.set(false);
566         } catch (InterruptedException e) {
567           Thread.currentThread().interrupt();
568           sendAbortProcessSignal();
569           syncException.compareAndSet(null, e);
570           throw e;
571         } catch (Throwable t) {
572           syncException.compareAndSet(null, t);
573           throw t;
574         } finally {
575           syncCond.signalAll();
576         }
577       }
578     } finally {
579       lock.unlock();
580     }
581   }
582 
583   private long syncSlots() throws Throwable {
584     int retry = 0;
585     int logRolled = 0;
586     long totalSynced = 0;
587     do {
588       try {
589         totalSynced = syncSlots(stream, slots, 0, slotIndex);
590         break;
591       } catch (Throwable e) {
592         if (++retry >= maxRetriesBeforeRoll) {
593           if (logRolled >= maxSyncFailureRoll) {
594             LOG.error("Sync slots after log roll failed, abort.", e);
595             sendAbortProcessSignal();
596             throw e;
597           }
598 
599           if (!rollWriterOrDie()) {
600             throw e;
601           }
602 
603           logRolled++;
604           retry = 0;
605         }
606       }
607     } while (running.get());
608     return totalSynced;
609   }
610 
611   protected long syncSlots(FSDataOutputStream stream, ByteSlot[] slots, int offset, int count)
612       throws IOException {
613     long totalSynced = 0;
614     for (int i = 0; i < count; ++i) {
615       ByteSlot data = slots[offset + i];
616       data.writeTo(stream);
617       totalSynced += data.size();
618     }
619 
620     if (useHsync) {
621       stream.hsync();
622     } else {
623       stream.hflush();
624     }
625     sendPostSyncSignal();
626 
627     if (LOG.isTraceEnabled()) {
628       LOG.trace("Sync slots=" + count + '/' + slots.length +
629                 ", flushed=" + StringUtils.humanSize(totalSynced));
630     }
631     return totalSynced;
632   }
633 
634   protected void sendPostSyncSignal() {
635     if (!this.listeners.isEmpty()) {
636       for (ProcedureStoreListener listener : this.listeners) {
637         listener.postSync();
638       }
639     }
640   }
641 
642   private void sendAbortProcessSignal() {
643     if (!this.listeners.isEmpty()) {
644       for (ProcedureStoreListener listener : this.listeners) {
645         listener.abortProcess();
646       }
647     }
648   }
649 
650   private boolean rollWriterOrDie() {
651     for (int i = 1; i <= rollRetries; ++i) {
652       try {
653         if (rollWriter()) {
654           return true;
655         }
656       } catch (IOException e) {
657         LOG.warn("Unable to roll the log, attempt=" + i, e);
658         Threads.sleepWithoutInterrupt(waitBeforeRoll);
659       }
660     }
661     LOG.fatal("Unable to roll the log");
662     sendAbortProcessSignal();
663     throw new RuntimeException("unable to roll the log");
664   }
665 
666   private boolean tryRollWriter() {
667     try {
668       return rollWriter();
669     } catch (IOException e) {
670       LOG.warn("Unable to roll the log", e);
671       return false;
672     }
673   }
674 
675   private long getMillisToNextPeriodicRoll() {
676     if (lastRollTs.get() > 0 && periodicRollMsec > 0) {
677       return periodicRollMsec - getMillisFromLastRoll();
678     }
679     return Long.MAX_VALUE;
680   }
681 
682   private long getMillisFromLastRoll() {
683     return (System.currentTimeMillis() - lastRollTs.get());
684   }
685 
686   @VisibleForTesting
687   protected void periodicRollForTesting() throws IOException {
688     lock.lock();
689     try {
690       periodicRoll();
691     } finally {
692       lock.unlock();
693     }
694   }
695 
696   @VisibleForTesting
697   protected boolean rollWriterForTesting() throws IOException {
698     lock.lock();
699     try {
700       return rollWriter();
701     } finally {
702       lock.unlock();
703     }
704   }
705 
706   private void periodicRoll() throws IOException {
707     if (storeTracker.isEmpty()) {
708       if (LOG.isTraceEnabled()) {
709         LOG.trace("no active procedures");
710       }
711       tryRollWriter();
712       removeAllLogs(flushLogId - 1);
713     } else {
714       if (storeTracker.isUpdated()) {
715         if (LOG.isTraceEnabled()) {
716           LOG.trace("all the active procedures are in the latest log");
717         }
718         removeAllLogs(flushLogId - 1);
719       }
720 
721       // if the log size has exceeded the roll threshold
722       // or the periodic roll timeout is expired, try to roll the wal.
723       if (totalSynced.get() > rollThreshold || getMillisToNextPeriodicRoll() <= 0) {
724         tryRollWriter();
725       }
726 
727       removeInactiveLogs();
728     }
729   }
730 
731   private boolean rollWriter() throws IOException {
732     // Create new state-log
733     if (!rollWriter(flushLogId + 1)) {
734       LOG.warn("someone else has already created log " + flushLogId);
735       return false;
736     }
737 
738     // We have the lease on the log,
739     // but we should check if someone else has created new files
740     if (getMaxLogId(getLogFiles()) > flushLogId) {
741       LOG.warn("Someone else created new logs. Expected maxLogId < " + flushLogId);
742       logs.getLast().removeFile();
743       return false;
744     }
745 
746     // We have the lease on the log
747     return true;
748   }
749 
750   private boolean rollWriter(final long logId) throws IOException {
751     assert logId > flushLogId : "logId=" + logId + " flushLogId=" + flushLogId;
752     assert lock.isHeldByCurrentThread() : "expected to be the lock owner. " + lock.isLocked();
753 
754     ProcedureWALHeader header = ProcedureWALHeader.newBuilder()
755       .setVersion(ProcedureWALFormat.HEADER_VERSION)
756       .setType(ProcedureWALFormat.LOG_TYPE_STREAM)
757       .setMinProcId(storeTracker.getMinProcId())
758       .setLogId(logId)
759       .build();
760 
761     FSDataOutputStream newStream = null;
762     Path newLogFile = null;
763     long startPos = -1;
764     newLogFile = getLogFilePath(logId);
765     try {
766       newStream = fs.create(newLogFile, false);
767     } catch (FileAlreadyExistsException e) {
768       LOG.error("Log file with id=" + logId + " already exists", e);
769       return false;
770     } catch (RemoteException re) {
771       LOG.warn("failed to create log file with id=" + logId, re);
772       return false;
773     }
774     try {
775       ProcedureWALFormat.writeHeader(newStream, header);
776       startPos = newStream.getPos();
777     } catch (IOException ioe) {
778       LOG.warn("Encountered exception writing header", ioe);
779       newStream.close();
780       return false;
781     }
782 
783     closeStream();
784 
785     storeTracker.resetUpdates();
786     stream = newStream;
787     flushLogId = logId;
788     totalSynced.set(0);
789     lastRollTs.set(System.currentTimeMillis());
790     logs.add(new ProcedureWALFile(fs, newLogFile, header, startPos));
791 
792     if (LOG.isDebugEnabled()) {
793       LOG.debug("Roll new state log: " + logId);
794     }
795     return true;
796   }
797 
798   private void closeStream() {
799     try {
800       if (stream != null) {
801         try {
802           ProcedureWALFile log = logs.getLast();
803           log.setProcIds(storeTracker.getUpdatedMinProcId(), storeTracker.getUpdatedMaxProcId());
804           ProcedureWALFormat.writeTrailer(stream, storeTracker);
805         } catch (IOException e) {
806           LOG.warn("Unable to write the trailer: " + e.getMessage());
807         }
808         stream.close();
809       }
810     } catch (IOException e) {
811       LOG.error("Unable to close the stream", e);
812     } finally {
813       stream = null;
814     }
815   }
816 
817   // ==========================================================================
818   //  Log Files cleaner helpers
819   // ==========================================================================
820   private void removeInactiveLogs() {
821     // Verify if the ProcId of the first oldest is still active. if not remove the file.
822     while (logs.size() > 1) {
823       ProcedureWALFile log = logs.getFirst();
824       if (storeTracker.isTracking(log.getMinProcId(), log.getMaxProcId())) {
825         break;
826       }
827       removeLogFile(log);
828     }
829   }
830 
831   private void removeAllLogs(long lastLogId) {
832     if (logs.size() <= 1) return;
833 
834     if (LOG.isDebugEnabled()) {
835       LOG.debug("Remove all state logs with ID less than " + lastLogId);
836     }
837     while (logs.size() > 1) {
838       ProcedureWALFile log = logs.getFirst();
839       if (lastLogId < log.getLogId()) {
840         break;
841       }
842       removeLogFile(log);
843     }
844   }
845 
846   private boolean removeLogFile(final ProcedureWALFile log) {
847     try {
848       if (LOG.isDebugEnabled()) {
849         LOG.debug("Remove log: " + log);
850       }
851       log.removeFile();
852       logs.remove(log);
853       LOG.info("Remove log: " + log);
854       LOG.info("Removed logs: " + logs);
855       if (logs.size() == 0) { LOG.error("Expected at least one log"); }
856       assert logs.size() > 0 : "expected at least one log";
857     } catch (IOException e) {
858       LOG.error("Unable to remove log: " + log, e);
859       return false;
860     }
861     return true;
862   }
863 
864   // ==========================================================================
865   //  FileSystem Log Files helpers
866   // ==========================================================================
867   public Path getLogDir() {
868     return this.logDir;
869   }
870 
871   public FileSystem getFileSystem() {
872     return this.fs;
873   }
874 
875   protected Path getLogFilePath(final long logId) throws IOException {
876     return new Path(logDir, String.format("state-%020d.log", logId));
877   }
878 
879   private static long getLogIdFromName(final String name) {
880     int end = name.lastIndexOf(".log");
881     int start = name.lastIndexOf('-') + 1;
882     while (start < end) {
883       if (name.charAt(start) != '0')
884         break;
885       start++;
886     }
887     return Long.parseLong(name.substring(start, end));
888   }
889 
890   private FileStatus[] getLogFiles() throws IOException {
891     try {
892       return fs.listStatus(logDir, new PathFilter() {
893         @Override
894         public boolean accept(Path path) {
895           String name = path.getName();
896           return name.startsWith("state-") && name.endsWith(".log");
897         }
898       });
899     } catch (FileNotFoundException e) {
900       LOG.warn("Log directory not found: " + e.getMessage());
901       return null;
902     }
903   }
904 
905   private long getMaxLogId(final FileStatus[] logFiles) {
906     long maxLogId = 0;
907     if (logFiles != null && logFiles.length > 0) {
908       for (int i = 0; i < logFiles.length; ++i) {
909         maxLogId = Math.max(maxLogId, getLogIdFromName(logFiles[i].getPath().getName()));
910       }
911     }
912     return maxLogId;
913   }
914 
915   /**
916    * @return Max-LogID of the specified log file set
917    */
918   private long initOldLogs(final FileStatus[] logFiles) throws IOException {
919     this.logs.clear();
920 
921     long maxLogId = 0;
922     if (logFiles != null && logFiles.length > 0) {
923       for (int i = 0; i < logFiles.length; ++i) {
924         final Path logPath = logFiles[i].getPath();
925         leaseRecovery.recoverFileLease(fs, logPath);
926         maxLogId = Math.max(maxLogId, getLogIdFromName(logPath.getName()));
927 
928         ProcedureWALFile log = initOldLog(logFiles[i]);
929         if (log != null) {
930           this.logs.add(log);
931         }
932       }
933       Collections.sort(this.logs);
934       initTrackerFromOldLogs();
935     }
936     return maxLogId;
937   }
938 
939   private void initTrackerFromOldLogs() {
940     // TODO: Load the most recent tracker available
941     if (!logs.isEmpty()) {
942       ProcedureWALFile log = logs.getLast();
943       try {
944         log.readTracker(storeTracker);
945       } catch (IOException e) {
946         LOG.warn("Unable to read tracker for " + log + " - " + e.getMessage());
947         // try the next one...
948         storeTracker.clear();
949         storeTracker.setPartialFlag(true);
950       }
951     }
952   }
953 
954   private ProcedureWALFile initOldLog(final FileStatus logFile) throws IOException {
955     ProcedureWALFile log = new ProcedureWALFile(fs, logFile);
956     if (logFile.getLen() == 0) {
957       LOG.warn("Remove uninitialized log: " + logFile);
958       log.removeFile();
959       return null;
960     }
961     if (LOG.isDebugEnabled()) {
962       LOG.debug("Opening state-log: " + logFile);
963     }
964     try {
965       log.open();
966     } catch (ProcedureWALFormat.InvalidWALDataException e) {
967       LOG.warn("Remove uninitialized log: " + logFile, e);
968       log.removeFile();
969       return null;
970     } catch (IOException e) {
971       String msg = "Unable to read state log: " + logFile;
972       LOG.error(msg, e);
973       throw new IOException(msg, e);
974     }
975 
976     if (log.isCompacted()) {
977       try {
978         log.readTrailer();
979       } catch (IOException e) {
980         LOG.warn("Unfinished compacted log: " + logFile, e);
981         log.removeFile();
982         return null;
983       }
984     }
985     return log;
986   }
987 }