Switch safekeeper from log to tracing logging.

Add context to wal acceptor and wal sender threads showing timeline id and
unique id differentiating them.

walkeeper/Cargo.toml

@@ -16,7 +16,7 @@ routerify = "2"
 fs2 = "0.4.3"
 lazy_static = "1.4.0"
 serde_json = "1"
-log = "0.4.14"
+tracing = "0.1.27"
 clap = "2.33.0"
 daemonize = "0.4.1"
 rust-s3 = { version = "0.27.0-rc4", features = ["no-verify-ssl"] }

walkeeper/src/bin/safekeeper.rs

@@ -5,9 +5,9 @@ use anyhow::Result;
 use clap::{App, Arg};
 use const_format::formatcp;
 use daemonize::Daemonize;
-use log::*;
 use std::path::{Path, PathBuf};
 use std::thread;
+use tracing::*;
 use walkeeper::defaults::{DEFAULT_HTTP_LISTEN_ADDR, DEFAULT_PG_LISTEN_ADDR};
 use walkeeper::http;
 use walkeeper::s3_offload;

walkeeper/src/json_ctrl.rs

@@ -9,8 +9,8 @@
 use anyhow::{anyhow, Result};
 use bytes::{BufMut, Bytes, BytesMut};
 use crc32c::crc32c_append;
-use log::*;
 use serde::{Deserialize, Serialize};
+use tracing::*;
 
 use crate::safekeeper::{AcceptorProposerMessage, AppendResponse};
 use crate::safekeeper::{

walkeeper/src/receive_wal.rs

@@ -5,8 +5,8 @@
 use anyhow::{bail, Context, Result};
 use bytes::Bytes;
 use bytes::BytesMut;
-use log::*;
 use postgres::{Client, Config, NoTls};
+use tracing::*;
 
 use std::net::SocketAddr;
 use std::thread;
@@ -116,6 +116,8 @@ impl<'pg> ReceiveWalConn<'pg> {
 
     /// Receive WAL from wal_proposer
     pub fn run(&mut self, swh: &mut SendWalHandler) -> Result<()> {
+        let _enter = info_span!("WAL acceptor", timeline = %swh.timelineid.unwrap()).entered();
+
         // Notify the libpq client that it's allowed to send `CopyData` messages
         self.pg_backend
             .write_message(&BeMessage::CopyBothResponse)?;

walkeeper/src/replication.rs

@@ -5,7 +5,6 @@ use crate::send_wal::SendWalHandler;
 use crate::timeline::{ReplicaState, Timeline, TimelineTools};
 use anyhow::{anyhow, Context, Result};
 use bytes::Bytes;
-use log::*;
 use postgres_ffi::xlog_utils::{
     get_current_timestamp, TimestampTz, XLogFileName, MAX_SEND_SIZE, PG_TLI,
 };
@@ -20,6 +19,7 @@ use std::sync::Arc;
 use std::thread::sleep;
 use std::time::Duration;
 use std::{str, thread};
+use tracing::*;
 use zenith_utils::bin_ser::BeSer;
 use zenith_utils::lsn::Lsn;
 use zenith_utils::postgres_backend::PostgresBackend;
@@ -177,6 +177,8 @@ impl ReplicationConn {
         pgb: &mut PostgresBackend,
         cmd: &Bytes,
     ) -> Result<()> {
+        let _enter = info_span!("WAL sender", timeline = %swh.timelineid.unwrap()).entered();
+
         // spawn the background thread which receives HotStandbyFeedback messages.
         let bg_timeline = Arc::clone(swh.timeline.get());
         let bg_stream_in = self.stream_in.take().unwrap();

walkeeper/src/s3_offload.rs

@@ -3,7 +3,6 @@
 //
 
 use anyhow::Result;
-use log::*;
 use postgres_ffi::xlog_utils::*;
 use s3::bucket::Bucket;
 use s3::creds::Credentials;
@@ -16,6 +15,7 @@ use std::path::Path;
 use std::time::SystemTime;
 use tokio::runtime;
 use tokio::time::sleep;
+use tracing::*;
 use walkdir::WalkDir;
 
 use crate::SafeKeeperConf;

walkeeper/src/safekeeper.rs

@@ -8,13 +8,13 @@ use bytes::Buf;
 use bytes::BufMut;
 use bytes::Bytes;
 use bytes::BytesMut;
-use log::*;
 use pageserver::waldecoder::WalStreamDecoder;
 use postgres_ffi::xlog_utils::TimeLineID;
 use serde::{Deserialize, Serialize};
 use std::cmp::min;
 use std::fmt;
 use std::io::Read;
+use tracing::*;
 
 use lazy_static::lazy_static;
 

walkeeper/src/timeline.rs

@@ -5,7 +5,6 @@ use anyhow::{anyhow, bail, ensure, Context, Result};
 use byteorder::{LittleEndian, ReadBytesExt, WriteBytesExt};
 use fs2::FileExt;
 use lazy_static::lazy_static;
-use log::*;
 use postgres_ffi::xlog_utils::{find_end_of_wal, PG_TLI};
 use std::cmp::{max, min};
 use std::collections::HashMap;
@@ -14,6 +13,7 @@ use std::io::{Read, Seek, SeekFrom, Write};
 use std::path::PathBuf;
 use std::sync::{Arc, Condvar, Mutex};
 use std::time::Duration;
+use tracing::*;
 use zenith_metrics::{register_histogram_vec, Histogram, HistogramVec, DISK_WRITE_SECONDS_BUCKETS};
 use zenith_utils::bin_ser::LeSer;
 use zenith_utils::lsn::Lsn;

walkeeper/src/upgrade.rs

@@ -3,8 +3,8 @@ use crate::safekeeper::{
     AcceptorState, PgUuid, SafeKeeperState, ServerInfo, Term, TermHistory, TermSwitchEntry,
 };
 use anyhow::{bail, Result};
-use log::*;
 use serde::{Deserialize, Serialize};
+use tracing::*;
 use zenith_utils::{bin_ser::LeSer, lsn::Lsn};
 
 /// Persistent consensus state of the acceptor.

walkeeper/src/wal_service.rs

@@ -3,9 +3,10 @@
 //!   receive WAL from wal_proposer and send it to WAL receivers
 //!
 use anyhow::Result;
-use log::*;
+use regex::Regex;
 use std::net::{TcpListener, TcpStream};
 use std::thread;
+use tracing::*;
 
 use crate::send_wal::SendWalHandler;
 use crate::SafeKeeperConf;
@@ -33,9 +34,19 @@ pub fn thread_main(conf: SafeKeeperConf, listener: TcpListener) -> Result<()> {
     }
 }
 
+// Get unique thread id (Rust internal), with ThreadId removed for shorter printing
+fn get_tid() -> u64 {
+    let tids = format!("{:?}", thread::current().id());
+    let r = Regex::new(r"ThreadId\((\d+)\)").unwrap();
+    let caps = r.captures(&tids).unwrap();
+    caps.get(1).unwrap().as_str().parse().unwrap()
+}
+
 /// This is run by `thread_main` above, inside a background thread.
 ///
 fn handle_socket(socket: TcpStream, conf: SafeKeeperConf) -> Result<()> {
+    let _enter = info_span!("", tid = ?get_tid()).entered();
+
     socket.set_nodelay(true)?;
 
     let mut conn_handler = SendWalHandler::new(conf);