View Javadoc

1   /*
2    *
3    * Licensed to the Apache Software Foundation (ASF) under one
4    * or more contributor license agreements.  See the NOTICE file
5    * distributed with this work for additional information
6    * regarding copyright ownership.  The ASF licenses this file
7    * to you under the Apache License, Version 2.0 (the
8    * "License"); you may not use this file except in compliance
9    * with the License.  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  package org.apache.hadoop.hbase.replication.regionserver;
20  
21  import java.io.EOFException;
22  import java.io.FileNotFoundException;
23  import java.io.IOException;
24  import java.util.ArrayList;
25  import java.util.Comparator;
26  import java.util.List;
27  import java.util.UUID;
28  import java.util.concurrent.PriorityBlockingQueue;
29  import java.util.concurrent.TimeUnit;
30  
31  import org.apache.commons.lang.StringUtils;
32  import org.apache.commons.logging.Log;
33  import org.apache.commons.logging.LogFactory;
34  import org.apache.hadoop.hbase.classification.InterfaceAudience;
35  import org.apache.hadoop.conf.Configuration;
36  import org.apache.hadoop.fs.FileStatus;
37  import org.apache.hadoop.fs.FileSystem;
38  import org.apache.hadoop.fs.Path;
39  import org.apache.hadoop.hbase.Cell;
40  import org.apache.hadoop.hbase.CellUtil;
41  import org.apache.hadoop.hbase.HBaseConfiguration;
42  import org.apache.hadoop.hbase.HConstants;
43  import org.apache.hadoop.hbase.Stoppable;
44  import org.apache.hadoop.hbase.wal.DefaultWALProvider;
45  import org.apache.hadoop.hbase.wal.WAL;
46  import org.apache.hadoop.hbase.wal.WALKey;
47  import org.apache.hadoop.hbase.regionserver.wal.WALEdit;
48  import org.apache.hadoop.hbase.replication.ChainWALEntryFilter;
49  import org.apache.hadoop.hbase.replication.ReplicationEndpoint;
50  import org.apache.hadoop.hbase.replication.ReplicationException;
51  import org.apache.hadoop.hbase.replication.ReplicationPeers;
52  import org.apache.hadoop.hbase.replication.ReplicationQueueInfo;
53  import org.apache.hadoop.hbase.replication.ReplicationQueues;
54  import org.apache.hadoop.hbase.replication.SystemTableWALEntryFilter;
55  import org.apache.hadoop.hbase.replication.WALEntryFilter;
56  import org.apache.hadoop.hbase.util.EnvironmentEdgeManager;
57  import org.apache.hadoop.hbase.util.FSUtils;
58  import org.apache.hadoop.hbase.util.Threads;
59  
60  import com.google.common.collect.Lists;
61  import com.google.common.util.concurrent.ListenableFuture;
62  import com.google.common.util.concurrent.Service;
63  
64  /**
65   * Class that handles the source of a replication stream.
66   * Currently does not handle more than 1 slave
67   * For each slave cluster it selects a random number of peers
68   * using a replication ratio. For example, if replication ration = 0.1
69   * and slave cluster has 100 region servers, 10 will be selected.
70   * <p/>
71   * A stream is considered down when we cannot contact a region server on the
72   * peer cluster for more than 55 seconds by default.
73   * <p/>
74   *
75   */
76  @InterfaceAudience.Private
77  public class ReplicationSource extends Thread
78      implements ReplicationSourceInterface {
79  
80    public static final Log LOG = LogFactory.getLog(ReplicationSource.class);
81    // Queue of logs to process
82    private PriorityBlockingQueue<Path> queue;
83    private ReplicationQueues replicationQueues;
84    private ReplicationPeers replicationPeers;
85  
86    private Configuration conf;
87    private ReplicationQueueInfo replicationQueueInfo;
88    // id of the peer cluster this source replicates to
89    private String peerId;
90    // The manager of all sources to which we ping back our progress
91    private ReplicationSourceManager manager;
92    // Should we stop everything?
93    private Stoppable stopper;
94    // How long should we sleep for each retry
95    private long sleepForRetries;
96    // Max size in bytes of entriesArray
97    private long replicationQueueSizeCapacity;
98    // Max number of entries in entriesArray
99    private int replicationQueueNbCapacity;
100   // Our reader for the current log. open/close handled by repLogReader
101   private WAL.Reader reader;
102   // Last position in the log that we sent to ZooKeeper
103   private long lastLoggedPosition = -1;
104   // Path of the current log
105   private volatile Path currentPath;
106   private FileSystem fs;
107   // id of this cluster
108   private UUID clusterId;
109   // id of the other cluster
110   private UUID peerClusterId;
111   // total number of edits we replicated
112   private long totalReplicatedEdits = 0;
113   // total number of edits we replicated
114   private long totalReplicatedOperations = 0;
115   // The znode we currently play with
116   private String peerClusterZnode;
117   // Maximum number of retries before taking bold actions
118   private int maxRetriesMultiplier;
119   // Current number of operations (Put/Delete) that we need to replicate
120   private int currentNbOperations = 0;
121   // Current size of data we need to replicate
122   private int currentSize = 0;
123   // Indicates if this particular source is running
124   private volatile boolean running = true;
125   // Metrics for this source
126   private MetricsSource metrics;
127   // Handle on the log reader helper
128   private ReplicationWALReaderManager repLogReader;
129   //WARN threshold for the number of queued logs, defaults to 2
130   private int logQueueWarnThreshold;
131   // ReplicationEndpoint which will handle the actual replication
132   private ReplicationEndpoint replicationEndpoint;
133   // A filter (or a chain of filters) for the WAL entries.
134   private WALEntryFilter walEntryFilter;
135   // throttler
136   private ReplicationThrottler throttler;
137 
138   /**
139    * Instantiation method used by region servers
140    *
141    * @param conf configuration to use
142    * @param fs file system to use
143    * @param manager replication manager to ping to
144    * @param stopper     the atomic boolean to use to stop the regionserver
145    * @param peerClusterZnode the name of our znode
146    * @param clusterId unique UUID for the cluster
147    * @param replicationEndpoint the replication endpoint implementation
148    * @param metrics metrics for replication source
149    * @throws IOException
150    */
151   @Override
152   public void init(final Configuration conf, final FileSystem fs,
153       final ReplicationSourceManager manager, final ReplicationQueues replicationQueues,
154       final ReplicationPeers replicationPeers, final Stoppable stopper,
155       final String peerClusterZnode, final UUID clusterId, ReplicationEndpoint replicationEndpoint,
156       final MetricsSource metrics)
157           throws IOException {
158     this.stopper = stopper;
159     this.conf = HBaseConfiguration.create(conf);
160     decorateConf();
161     this.replicationQueueSizeCapacity =
162         this.conf.getLong("replication.source.size.capacity", 1024*1024*64);
163     this.replicationQueueNbCapacity =
164         this.conf.getInt("replication.source.nb.capacity", 25000);
165     this.sleepForRetries =
166         this.conf.getLong("replication.source.sleepforretries", 1000);    // 1 second
167     this.maxRetriesMultiplier =
168         this.conf.getInt("replication.source.maxretriesmultiplier", 300); // 5 minutes @ 1 sec per
169     this.queue =
170         new PriorityBlockingQueue<Path>(
171             this.conf.getInt("hbase.regionserver.maxlogs", 32),
172             new LogsComparator());
173     long bandwidth = this.conf.getLong("replication.source.per.peer.node.bandwidth", 0);
174     this.throttler = new ReplicationThrottler((double)bandwidth/10.0);
175     this.replicationQueues = replicationQueues;
176     this.replicationPeers = replicationPeers;
177     this.manager = manager;
178     this.fs = fs;
179     this.metrics = metrics;
180     this.repLogReader = new ReplicationWALReaderManager(this.fs, this.conf);
181     this.clusterId = clusterId;
182 
183     this.peerClusterZnode = peerClusterZnode;
184     this.replicationQueueInfo = new ReplicationQueueInfo(peerClusterZnode);
185     // ReplicationQueueInfo parses the peerId out of the znode for us
186     this.peerId = this.replicationQueueInfo.getPeerId();
187     this.logQueueWarnThreshold = this.conf.getInt("replication.source.log.queue.warn", 2);
188     this.replicationEndpoint = replicationEndpoint;
189   }
190 
191   private void decorateConf() {
192     String replicationCodec = this.conf.get(HConstants.REPLICATION_CODEC_CONF_KEY);
193     if (StringUtils.isNotEmpty(replicationCodec)) {
194       this.conf.set(HConstants.RPC_CODEC_CONF_KEY, replicationCodec);
195     }
196   }
197 
198   @Override
199   public void enqueueLog(Path log) {
200     this.queue.put(log);
201     int queueSize = queue.size();
202     this.metrics.setSizeOfLogQueue(queueSize);
203     // This will log a warning for each new log that gets created above the warn threshold
204     if (queueSize > this.logQueueWarnThreshold) {
205       LOG.warn("Queue size: " + queueSize +
206         " exceeds value of replication.source.log.queue.warn: " + logQueueWarnThreshold);
207     }
208   }
209 
210   private void uninitialize() {
211     LOG.debug("Source exiting " + this.peerId);
212     metrics.clear();
213     if (replicationEndpoint.state() == Service.State.STARTING
214         || replicationEndpoint.state() == Service.State.RUNNING) {
215       replicationEndpoint.stopAndWait();
216     }
217   }
218 
219   @Override
220   public void run() {
221     // We were stopped while looping to connect to sinks, just abort
222     if (!this.isActive()) {
223       uninitialize();
224       return;
225     }
226 
227     try {
228       // start the endpoint, connect to the cluster
229       Service.State state = replicationEndpoint.start().get();
230       if (state != Service.State.RUNNING) {
231         LOG.warn("ReplicationEndpoint was not started. Exiting");
232         uninitialize();
233         return;
234       }
235     } catch (Exception ex) {
236       LOG.warn("Error starting ReplicationEndpoint, exiting", ex);
237       throw new RuntimeException(ex);
238     }
239 
240     // get the WALEntryFilter from ReplicationEndpoint and add it to default filters
241     ArrayList<WALEntryFilter> filters = Lists.newArrayList(
242       (WALEntryFilter)new SystemTableWALEntryFilter());
243     WALEntryFilter filterFromEndpoint = this.replicationEndpoint.getWALEntryfilter();
244     if (filterFromEndpoint != null) {
245       filters.add(filterFromEndpoint);
246     }
247     this.walEntryFilter = new ChainWALEntryFilter(filters);
248 
249     int sleepMultiplier = 1;
250     // delay this until we are in an asynchronous thread
251     while (this.isActive() && this.peerClusterId == null) {
252       this.peerClusterId = replicationEndpoint.getPeerUUID();
253       if (this.isActive() && this.peerClusterId == null) {
254         if (sleepForRetries("Cannot contact the peer's zk ensemble", sleepMultiplier)) {
255           sleepMultiplier++;
256         }
257       }
258     }
259     // We were stopped while looping to contact peer's zk ensemble, just abort
260     if (!this.isActive()) {
261       uninitialize();
262       return;
263     }
264 
265     // resetting to 1 to reuse later
266     sleepMultiplier = 1;
267 
268     // In rare case, zookeeper setting may be messed up. That leads to the incorrect
269     // peerClusterId value, which is the same as the source clusterId
270     if (clusterId.equals(peerClusterId) && !replicationEndpoint.canReplicateToSameCluster()) {
271       this.terminate("ClusterId " + clusterId + " is replicating to itself: peerClusterId "
272           + peerClusterId + " which is not allowed by ReplicationEndpoint:"
273           + replicationEndpoint.getClass().getName(), null, false);
274     }
275     LOG.info("Replicating "+clusterId + " -> " + peerClusterId);
276 
277     // If this is recovered, the queue is already full and the first log
278     // normally has a position (unless the RS failed between 2 logs)
279     if (this.replicationQueueInfo.isQueueRecovered()) {
280       try {
281         this.repLogReader.setPosition(this.replicationQueues.getLogPosition(this.peerClusterZnode,
282           this.queue.peek().getName()));
283         if (LOG.isTraceEnabled()) {
284           LOG.trace("Recovered queue started with log " + this.queue.peek() +
285               " at position " + this.repLogReader.getPosition());
286         }
287       } catch (ReplicationException e) {
288         this.terminate("Couldn't get the position of this recovered queue " +
289             this.peerClusterZnode, e);
290       }
291     }
292     // Loop until we close down
293     while (isActive()) {
294       // Sleep until replication is enabled again
295       if (!isPeerEnabled()) {
296         if (sleepForRetries("Replication is disabled", sleepMultiplier)) {
297           sleepMultiplier++;
298         }
299         continue;
300       }
301       Path oldPath = getCurrentPath(); //note that in the current scenario,
302                                        //oldPath will be null when a log roll
303                                        //happens.
304       // Get a new path
305       boolean hasCurrentPath = getNextPath();
306       if (getCurrentPath() != null && oldPath == null) {
307         sleepMultiplier = 1; //reset the sleepMultiplier on a path change
308       }
309       if (!hasCurrentPath) {
310         if (sleepForRetries("No log to process", sleepMultiplier)) {
311           sleepMultiplier++;
312         }
313         continue;
314       }
315       boolean currentWALisBeingWrittenTo = false;
316       //For WAL files we own (rather than recovered), take a snapshot of whether the
317       //current WAL file (this.currentPath) is in use (for writing) NOW!
318       //Since the new WAL paths are enqueued only after the prev WAL file
319       //is 'closed', presence of an element in the queue means that
320       //the previous WAL file was closed, else the file is in use (currentPath)
321       //We take the snapshot now so that we are protected against races
322       //where a new file gets enqueued while the current file is being processed
323       //(and where we just finished reading the current file).
324       if (!this.replicationQueueInfo.isQueueRecovered() && queue.size() == 0) {
325         currentWALisBeingWrittenTo = true;
326       }
327       // Open a reader on it
328       if (!openReader(sleepMultiplier)) {
329         // Reset the sleep multiplier, else it'd be reused for the next file
330         sleepMultiplier = 1;
331         continue;
332       }
333 
334       // If we got a null reader but didn't continue, then sleep and continue
335       if (this.reader == null) {
336         if (sleepForRetries("Unable to open a reader", sleepMultiplier)) {
337           sleepMultiplier++;
338         }
339         continue;
340       }
341 
342       boolean gotIOE = false;
343       currentNbOperations = 0;
344       List<WAL.Entry> entries = new ArrayList<WAL.Entry>(1);
345       currentSize = 0;
346       try {
347         if (readAllEntriesToReplicateOrNextFile(currentWALisBeingWrittenTo, entries)) {
348           continue;
349         }
350       } catch (IOException ioe) {
351         LOG.warn(this.peerClusterZnode + " Got: ", ioe);
352         gotIOE = true;
353         if (ioe.getCause() instanceof EOFException) {
354 
355           boolean considerDumping = false;
356           if (this.replicationQueueInfo.isQueueRecovered()) {
357             try {
358               FileStatus stat = this.fs.getFileStatus(this.currentPath);
359               if (stat.getLen() == 0) {
360                 LOG.warn(this.peerClusterZnode + " Got EOF and the file was empty");
361               }
362               considerDumping = true;
363             } catch (IOException e) {
364               LOG.warn(this.peerClusterZnode + " Got while getting file size: ", e);
365             }
366           }
367 
368           if (considerDumping &&
369               sleepMultiplier == this.maxRetriesMultiplier &&
370               processEndOfFile()) {
371             continue;
372           }
373         }
374       } finally {
375         try {
376           this.reader = null;
377           this.repLogReader.closeReader();
378         } catch (IOException e) {
379           gotIOE = true;
380           LOG.warn("Unable to finalize the tailing of a file", e);
381         }
382       }
383 
384       // If we didn't get anything to replicate, or if we hit a IOE,
385       // wait a bit and retry.
386       // But if we need to stop, don't bother sleeping
387       if (this.isActive() && (gotIOE || entries.isEmpty())) {
388         if (this.lastLoggedPosition != this.repLogReader.getPosition()) {
389           this.manager.logPositionAndCleanOldLogs(this.currentPath,
390               this.peerClusterZnode, this.repLogReader.getPosition(),
391               this.replicationQueueInfo.isQueueRecovered(), currentWALisBeingWrittenTo);
392           this.lastLoggedPosition = this.repLogReader.getPosition();
393         }
394         // Reset the sleep multiplier if nothing has actually gone wrong
395         if (!gotIOE) {
396           sleepMultiplier = 1;
397           // if there was nothing to ship and it's not an error
398           // set "ageOfLastShippedOp" to <now> to indicate that we're current
399           this.metrics.setAgeOfLastShippedOp(EnvironmentEdgeManager.currentTime());
400         }
401         if (sleepForRetries("Nothing to replicate", sleepMultiplier)) {
402           sleepMultiplier++;
403         }
404         continue;
405       }
406       sleepMultiplier = 1;
407       shipEdits(currentWALisBeingWrittenTo, entries);
408     }
409     uninitialize();
410   }
411 
412   /**
413    * Read all the entries from the current log files and retain those
414    * that need to be replicated. Else, process the end of the current file.
415    * @param currentWALisBeingWrittenTo is the current WAL being written to
416    * @param entries resulting entries to be replicated
417    * @return true if we got nothing and went to the next file, false if we got
418    * entries
419    * @throws IOException
420    */
421   protected boolean readAllEntriesToReplicateOrNextFile(boolean currentWALisBeingWrittenTo,
422       List<WAL.Entry> entries) throws IOException {
423     long seenEntries = 0;
424     if (LOG.isTraceEnabled()) {
425       LOG.trace("Seeking in " + this.currentPath + " at position "
426           + this.repLogReader.getPosition());
427     }
428     this.repLogReader.seek();
429     long positionBeforeRead = this.repLogReader.getPosition();
430     WAL.Entry entry =
431         this.repLogReader.readNextAndSetPosition();
432     while (entry != null) {
433       this.metrics.incrLogEditsRead();
434       seenEntries++;
435 
436       // don't replicate if the log entries have already been consumed by the cluster
437       if (replicationEndpoint.canReplicateToSameCluster()
438           || !entry.getKey().getClusterIds().contains(peerClusterId)) {
439         // Remove all KVs that should not be replicated
440         entry = walEntryFilter.filter(entry);
441         WALEdit edit = null;
442         WALKey logKey = null;
443         if (entry != null) {
444           edit = entry.getEdit();
445           logKey = entry.getKey();
446         }
447 
448         if (edit != null && edit.size() != 0) {
449           //Mark that the current cluster has the change
450           logKey.addClusterId(clusterId);
451           currentNbOperations += countDistinctRowKeys(edit);
452           entries.add(entry);
453           currentSize += entry.getEdit().heapSize();
454         } else {
455           this.metrics.incrLogEditsFiltered();
456         }
457       }
458       // Stop if too many entries or too big
459       if (currentSize >= this.replicationQueueSizeCapacity ||
460           entries.size() >= this.replicationQueueNbCapacity) {
461         break;
462       }
463       try {
464         entry = this.repLogReader.readNextAndSetPosition();
465       } catch (IOException ie) {
466         LOG.debug("Break on IOE: " + ie.getMessage());
467         break;
468       }
469     }
470     metrics.incrLogReadInBytes(this.repLogReader.getPosition() - positionBeforeRead);
471     if (currentWALisBeingWrittenTo) {
472       return false;
473     }
474     // If we didn't get anything and the queue has an object, it means we
475     // hit the end of the file for sure
476     return seenEntries == 0 && processEndOfFile();
477   }
478 
479   /**
480    * Poll for the next path
481    * @return true if a path was obtained, false if not
482    */
483   protected boolean getNextPath() {
484     try {
485       if (this.currentPath == null) {
486         this.currentPath = queue.poll(this.sleepForRetries, TimeUnit.MILLISECONDS);
487         this.metrics.setSizeOfLogQueue(queue.size());
488         if (this.currentPath != null) {
489           this.manager.cleanOldLogs(this.currentPath.getName(),
490               this.peerId,
491               this.replicationQueueInfo.isQueueRecovered());
492           if (LOG.isTraceEnabled()) {
493             LOG.trace("New log: " + this.currentPath);
494           }
495         }
496       }
497     } catch (InterruptedException e) {
498       LOG.warn("Interrupted while reading edits", e);
499     }
500     return this.currentPath != null;
501   }
502 
503   /**
504    * Open a reader on the current path
505    *
506    * @param sleepMultiplier by how many times the default sleeping time is augmented
507    * @return true if we should continue with that file, false if we are over with it
508    */
509   protected boolean openReader(int sleepMultiplier) {
510     try {
511       try {
512         if (LOG.isTraceEnabled()) {
513           LOG.trace("Opening log " + this.currentPath);
514         }
515         this.reader = repLogReader.openReader(this.currentPath);
516       } catch (FileNotFoundException fnfe) {
517         if (this.replicationQueueInfo.isQueueRecovered()) {
518           // We didn't find the log in the archive directory, look if it still
519           // exists in the dead RS folder (there could be a chain of failures
520           // to look at)
521           List<String> deadRegionServers = this.replicationQueueInfo.getDeadRegionServers();
522           LOG.info("NB dead servers : " + deadRegionServers.size());
523           final Path rootDir = FSUtils.getRootDir(this.conf);
524           for (String curDeadServerName : deadRegionServers) {
525             final Path deadRsDirectory = new Path(rootDir,
526                 DefaultWALProvider.getWALDirectoryName(curDeadServerName));
527             Path[] locs = new Path[] {
528                 new Path(deadRsDirectory, currentPath.getName()),
529                 new Path(deadRsDirectory.suffix(DefaultWALProvider.SPLITTING_EXT),
530                                           currentPath.getName()),
531             };
532             for (Path possibleLogLocation : locs) {
533               LOG.info("Possible location " + possibleLogLocation.toUri().toString());
534               if (this.manager.getFs().exists(possibleLogLocation)) {
535                 // We found the right new location
536                 LOG.info("Log " + this.currentPath + " still exists at " +
537                     possibleLogLocation);
538                 // Breaking here will make us sleep since reader is null
539                 // TODO why don't we need to set currentPath and call openReader here?
540                 return true;
541               }
542             }
543           }
544           // In the case of disaster/recovery, HMaster may be shutdown/crashed before flush data
545           // from .logs to .oldlogs. Loop into .logs folders and check whether a match exists
546           if (stopper instanceof ReplicationSyncUp.DummyServer) {
547             // N.B. the ReplicationSyncUp tool sets the manager.getLogDir to the root of the wal
548             //      area rather than to the wal area for a particular region server.
549             FileStatus[] rss = fs.listStatus(manager.getLogDir());
550             for (FileStatus rs : rss) {
551               Path p = rs.getPath();
552               FileStatus[] logs = fs.listStatus(p);
553               for (FileStatus log : logs) {
554                 p = new Path(p, log.getPath().getName());
555                 if (p.getName().equals(currentPath.getName())) {
556                   currentPath = p;
557                   LOG.info("Log " + currentPath.getName() + " found at " + currentPath);
558                   // Open the log at the new location
559                   this.openReader(sleepMultiplier);
560                   return true;
561                 }
562               }
563             }
564           }
565 
566           // TODO What happens if the log was missing from every single location?
567           // Although we need to check a couple of times as the log could have
568           // been moved by the master between the checks
569           // It can also happen if a recovered queue wasn't properly cleaned,
570           // such that the znode pointing to a log exists but the log was
571           // deleted a long time ago.
572           // For the moment, we'll throw the IO and processEndOfFile
573           throw new IOException("File from recovered queue is " +
574               "nowhere to be found", fnfe);
575         } else {
576           // If the log was archived, continue reading from there
577           Path archivedLogLocation =
578               new Path(manager.getOldLogDir(), currentPath.getName());
579           if (this.manager.getFs().exists(archivedLogLocation)) {
580             currentPath = archivedLogLocation;
581             LOG.info("Log " + this.currentPath + " was moved to " +
582                 archivedLogLocation);
583             // Open the log at the new location
584             this.openReader(sleepMultiplier);
585 
586           }
587           // TODO What happens the log is missing in both places?
588         }
589       }
590     } catch (IOException ioe) {
591       if (ioe instanceof EOFException && isCurrentLogEmpty()) return true;
592       LOG.warn(this.peerClusterZnode + " Got: ", ioe);
593       this.reader = null;
594       if (ioe.getCause() instanceof NullPointerException) {
595         // Workaround for race condition in HDFS-4380
596         // which throws a NPE if we open a file before any data node has the most recent block
597         // Just sleep and retry. Will require re-reading compressed WALs for compressionContext.
598         LOG.warn("Got NPE opening reader, will retry.");
599       } else if (sleepMultiplier == this.maxRetriesMultiplier) {
600         // TODO Need a better way to determine if a file is really gone but
601         // TODO without scanning all logs dir
602         LOG.warn("Waited too long for this file, considering dumping");
603         return !processEndOfFile();
604       }
605     }
606     return true;
607   }
608 
609   /*
610    * Checks whether the current log file is empty, and it is not a recovered queue. This is to
611    * handle scenario when in an idle cluster, there is no entry in the current log and we keep on
612    * trying to read the log file and get EOFException. In case of a recovered queue the last log
613    * file may be empty, and we don't want to retry that.
614    */
615   private boolean isCurrentLogEmpty() {
616     return (this.repLogReader.getPosition() == 0 &&
617         !this.replicationQueueInfo.isQueueRecovered() && queue.size() == 0);
618   }
619 
620   /**
621    * Do the sleeping logic
622    * @param msg Why we sleep
623    * @param sleepMultiplier by how many times the default sleeping time is augmented
624    * @return True if <code>sleepMultiplier</code> is &lt; <code>maxRetriesMultiplier</code>
625    */
626   protected boolean sleepForRetries(String msg, int sleepMultiplier) {
627     try {
628       if (LOG.isTraceEnabled()) {
629         LOG.trace(msg + ", sleeping " + sleepForRetries + " times " + sleepMultiplier);
630       }
631       Thread.sleep(this.sleepForRetries * sleepMultiplier);
632     } catch (InterruptedException e) {
633       LOG.debug("Interrupted while sleeping between retries");
634       Thread.currentThread().interrupt();
635     }
636     return sleepMultiplier < maxRetriesMultiplier;
637   }
638 
639   /**
640    * Count the number of different row keys in the given edit because of
641    * mini-batching. We assume that there's at least one Cell in the WALEdit.
642    * @param edit edit to count row keys from
643    * @return number of different row keys
644    */
645   private int countDistinctRowKeys(WALEdit edit) {
646     List<Cell> cells = edit.getCells();
647     int distinctRowKeys = 1;
648     Cell lastCell = cells.get(0);
649     for (int i = 0; i < edit.size(); i++) {
650       if (!CellUtil.matchingRow(cells.get(i), lastCell)) {
651         distinctRowKeys++;
652       }
653       lastCell = cells.get(i);
654     }
655     return distinctRowKeys;
656   }
657 
658   /**
659    * Do the shipping logic
660    * @param currentWALisBeingWrittenTo was the current WAL being (seemingly)
661    * written to when this method was called
662    */
663   protected void shipEdits(boolean currentWALisBeingWrittenTo, List<WAL.Entry> entries) {
664     int sleepMultiplier = 0;
665     if (entries.isEmpty()) {
666       LOG.warn("Was given 0 edits to ship");
667       return;
668     }
669     while (this.isActive()) {
670       try {
671         if (this.throttler.isEnabled()) {
672           long sleepTicks = this.throttler.getNextSleepInterval(currentSize);
673           if (sleepTicks > 0) {
674             try {
675               if (LOG.isTraceEnabled()) {
676                 LOG.trace("To sleep " + sleepTicks + "ms for throttling control");
677               }
678               Thread.sleep(sleepTicks);
679             } catch (InterruptedException e) {
680               LOG.debug("Interrupted while sleeping for throttling control");
681               Thread.currentThread().interrupt();
682               // current thread might be interrupted to terminate
683               // directly go back to while() for confirm this
684               continue;
685             }
686             // reset throttler's cycle start tick when sleep for throttling occurs
687             this.throttler.resetStartTick();
688           }
689         }
690         // create replicateContext here, so the entries can be GC'd upon return from this call stack
691         ReplicationEndpoint.ReplicateContext replicateContext = new ReplicationEndpoint.ReplicateContext();
692         replicateContext.setEntries(entries).setSize(currentSize);
693 
694         long startTimeNs = System.nanoTime();
695         // send the edits to the endpoint. Will block until the edits are shipped and acknowledged
696         boolean replicated = replicationEndpoint.replicate(replicateContext);
697         long endTimeNs = System.nanoTime();
698 
699         if (!replicated) {
700           continue;
701         } else {
702           sleepMultiplier = Math.max(sleepMultiplier-1, 0);
703         }
704 
705         if (this.lastLoggedPosition != this.repLogReader.getPosition()) {
706           this.manager.logPositionAndCleanOldLogs(this.currentPath,
707               this.peerClusterZnode, this.repLogReader.getPosition(),
708               this.replicationQueueInfo.isQueueRecovered(), currentWALisBeingWrittenTo);
709           this.lastLoggedPosition = this.repLogReader.getPosition();
710         }
711         if (this.throttler.isEnabled()) {
712           this.throttler.addPushSize(currentSize);
713         }
714         this.totalReplicatedEdits += entries.size();
715         this.totalReplicatedOperations += currentNbOperations;
716         this.metrics.shipBatch(this.currentNbOperations, this.currentSize/1024);
717         this.metrics.setAgeOfLastShippedOp(entries.get(entries.size()-1).getKey().getWriteTime());
718         if (LOG.isTraceEnabled()) {
719           LOG.trace("Replicated " + this.totalReplicatedEdits + " entries in total, or "
720               + this.totalReplicatedOperations + " operations in " +
721               ((endTimeNs - startTimeNs)/1000000) + " ms");
722         }
723         break;
724       } catch (Exception ex) {
725         LOG.warn(replicationEndpoint.getClass().getName() + " threw unknown exception:" +
726             org.apache.hadoop.util.StringUtils.stringifyException(ex));
727         if (sleepForRetries("ReplicationEndpoint threw exception", sleepMultiplier)) {
728           sleepMultiplier++;
729         }
730       }
731     }
732   }
733 
734   /**
735    * check whether the peer is enabled or not
736    *
737    * @return true if the peer is enabled, otherwise false
738    */
739   protected boolean isPeerEnabled() {
740     return this.replicationPeers.getStatusOfPeer(this.peerId);
741   }
742 
743   /**
744    * If the queue isn't empty, switch to the next one
745    * Else if this is a recovered queue, it means we're done!
746    * Else we'll just continue to try reading the log file
747    * @return true if we're done with the current file, false if we should
748    * continue trying to read from it
749    */
750   @edu.umd.cs.findbugs.annotations.SuppressWarnings(value="DE_MIGHT_IGNORE",
751       justification="Yeah, this is how it works")
752   protected boolean processEndOfFile() {
753     if (this.queue.size() != 0) {
754       if (LOG.isTraceEnabled()) {
755         String filesize = "N/A";
756         try {
757           FileStatus stat = this.fs.getFileStatus(this.currentPath);
758           filesize = stat.getLen()+"";
759         } catch (IOException ex) {}
760         LOG.trace("Reached the end of a log, stats: " + getStats() +
761             ", and the length of the file is " + filesize);
762       }
763       this.currentPath = null;
764       this.repLogReader.finishCurrentFile();
765       this.reader = null;
766       return true;
767     } else if (this.replicationQueueInfo.isQueueRecovered()) {
768       this.manager.closeRecoveredQueue(this);
769       LOG.info("Finished recovering the queue with the following stats " + getStats());
770       this.running = false;
771       return true;
772     }
773     return false;
774   }
775 
776   @Override
777   public void startup() {
778     String n = Thread.currentThread().getName();
779     Thread.UncaughtExceptionHandler handler =
780         new Thread.UncaughtExceptionHandler() {
781           @Override
782           public void uncaughtException(final Thread t, final Throwable e) {
783             LOG.error("Unexpected exception in ReplicationSource," +
784               " currentPath=" + currentPath, e);
785           }
786         };
787     Threads.setDaemonThreadRunning(
788         this, n + ".replicationSource," +
789         this.peerClusterZnode, handler);
790   }
791 
792   @Override
793   public void terminate(String reason) {
794     terminate(reason, null);
795   }
796 
797   @Override
798   public void terminate(String reason, Exception cause) {
799     terminate(reason, cause, true);
800   }
801 
802   public void terminate(String reason, Exception cause, boolean join) {
803     if (cause == null) {
804       LOG.info("Closing source "
805           + this.peerClusterZnode + " because: " + reason);
806 
807     } else {
808       LOG.error("Closing source " + this.peerClusterZnode
809           + " because an error occurred: " + reason, cause);
810     }
811     this.running = false;
812     this.interrupt();
813     ListenableFuture<Service.State> future = null;
814     if (this.replicationEndpoint != null) {
815       future = this.replicationEndpoint.stop();
816     }
817     if (join) {
818       Threads.shutdown(this, this.sleepForRetries);
819       if (future != null) {
820         try {
821           future.get();
822         } catch (Exception e) {
823           LOG.warn("Got exception:" + e);
824         }
825       }
826     }
827   }
828 
829   @Override
830   public String getPeerClusterZnode() {
831     return this.peerClusterZnode;
832   }
833 
834   @Override
835   public String getPeerClusterId() {
836     return this.peerId;
837   }
838 
839   @Override
840   public Path getCurrentPath() {
841     return this.currentPath;
842   }
843 
844   private boolean isActive() {
845     return !this.stopper.isStopped() && this.running && !isInterrupted();
846   }
847 
848   /**
849    * Comparator used to compare logs together based on their start time
850    */
851   public static class LogsComparator implements Comparator<Path> {
852 
853     @Override
854     public int compare(Path o1, Path o2) {
855       return Long.valueOf(getTS(o1)).compareTo(getTS(o2));
856     }
857 
858     /**
859      * Split a path to get the start time
860      * For example: 10.20.20.171%3A60020.1277499063250
861      * @param p path to split
862      * @return start time
863      */
864     private long getTS(Path p) {
865       String[] parts = p.getName().split("\\.");
866       return Long.parseLong(parts[parts.length-1]);
867     }
868   }
869 
870   @Override
871   public String getStats() {
872     long position = this.repLogReader.getPosition();
873     return "Total replicated edits: " + totalReplicatedEdits +
874       ", currently replicating from: " + this.currentPath +
875       " at position: " + position;
876   }
877 
878   /**
879    * Get Replication Source Metrics
880    * @return sourceMetrics
881    */
882   public MetricsSource getSourceMetrics() {
883     return this.metrics;
884   }
885 }