raftstore: use readable format for leader lease in logs (tikv#1722)

src/raftstore/store/peer.rs

@@ -41,7 +41,7 @@ use raftstore::store::worker::apply::ExecResult;
 
 use util::worker::{Worker, Scheduler};
 use raftstore::store::worker::{ApplyTask, ApplyRes};
-use util::{clocktime, Either, HashMap, HashSet};
+use util::{clocktime, Either, HashMap, HashSet, strftimespec};
 
 use pd::INVALID_ID;
 
@@ -596,11 +596,11 @@ impl Peer {
                     // It is recommended to update the lease expiring time right after
                     // this peer becomes leader because it's more convenient to do it here and
                     // it has no impact on the correctness.
-                    self.leader_lease_expired_time =
-                        Some(Either::Left(self.next_lease_expired_time(clocktime::raw_now())));
+                    let next_expired_time = self.next_lease_expired_time(clocktime::raw_now());
+                    self.leader_lease_expired_time = Some(Either::Left(next_expired_time));
                     debug!("{} becomes leader and lease expired time is {:?}",
                            self.tag,
-                           self.leader_lease_expired_time);
+                           strftimespec(next_expired_time));
                     self.heartbeat_pd(worker)
                 }
                 StateRole::Follower => {
@@ -851,8 +851,8 @@ impl Peer {
             if current_expired_time < next_expired_time {
                 debug!("{} update leader lease expired time from {:?} to {:?}",
                        self.tag,
-                       current_expired_time,
-                       next_expired_time);
+                       strftimespec(current_expired_time),
+                       strftimespec(next_expired_time));
                 self.leader_lease_expired_time = Some(Either::Left(next_expired_time));
             }
         } else if self.is_leader() {
@@ -862,7 +862,7 @@ impl Peer {
             let next_expired_time = self.next_lease_expired_time(propose_time);
             debug!("{} update leader lease expired time from None to {:?}",
                    self.tag,
-                   self.leader_lease_expired_time);
+                   strftimespec(next_expired_time));
             self.leader_lease_expired_time = Some(Either::Left(next_expired_time));
         }
     }
@@ -1035,7 +1035,7 @@ impl Peer {
 
             debug!("{} leader lease expired time {:?} is outdated",
                    self.tag,
-                   self.leader_lease_expired_time);
+                   strftimespec(safe_expired_time));
             // Reset leader lease expiring time.
             self.leader_lease_expired_time = None;
         }

src/util/mod.rs

@@ -17,6 +17,7 @@ use std::io;
 use std::{slice, thread};
 use std::net::{ToSocketAddrs, TcpStream, SocketAddr};
 use std::time::{Duration, Instant};
+use time::{self, Timespec};
 use std::collections::hash_map::Entry;
 use std::sync::{RwLock, RwLockReadGuard, RwLockWriteGuard};
 
@@ -308,6 +309,14 @@ pub fn duration_to_nanos(d: Duration) -> u64 {
     d.as_secs() * 1_000_000_000 + nanos
 }
 
+// Returns the formatted string for a specified time in local timezone.
+pub fn strftimespec(t: Timespec) -> String {
+    let tm = time::at(t);
+    let mut s = time::strftime("%Y/%m/%d %H:%M:%S", &tm).unwrap();
+    s += &format!(".{:03}", t.nsec / 1_000_000);
+    s
+}
+
 pub fn get_tag_from_thread_name() -> Option<String> {
     thread::current().name().and_then(|name| name.split("::").skip(1).last()).map(From::from)
 }
@@ -465,6 +474,7 @@ mod tests {
     use std::rc::Rc;
     use std::{f64, cmp};
     use std::sync::atomic::{AtomicBool, Ordering};
+    use time;
     use super::*;
 
     #[test]
@@ -525,6 +535,17 @@ mod tests {
         }
     }
 
+    #[test]
+    fn test_strftimespec() {
+        let s = "2016/08/30 15:40:07".to_owned();
+        let mut tm = time::strptime(&s, "%Y/%m/%d %H:%M:%S").unwrap();
+        // `tm` is of UTC timezone. Set the timezone of `tm` to be local timezone,
+        // so that we get a `tm` of local timezone.
+        let ltm = tm.to_local();
+        tm.tm_utcoff = ltm.tm_utcoff;
+        assert_eq!(strftimespec(tm.to_timespec()), s + ".000");
+    }
+
     #[test]
     fn test_defer() {
         let should_panic = Rc::new(AtomicBool::new(true));