Merge remote-tracking branch 'origin/main' into netstat-logs

This change causes writer halves of a TLS stream to always flush after a
portion of bytes has been written by `std::io::copy`. Furthermore, some
cosmetic and minor functional changes are made to facilitate debug.

.circleci/config.yml

@@ -7,7 +7,7 @@ executors:
   zenith-build-executor:
     resource_class: xlarge
     docker:
-      - image: cimg/rust:1.52.1
+      - image: cimg/rust:1.55.0
 
 jobs:
   check-codestyle:
@@ -110,7 +110,7 @@ jobs:
             # Require an exact match. While an out of date cache might speed up the build,
             # there's no way to clean out old packages, so the cache grows every time something
             # changes.
-            - v03-rust-cache-deps-<< parameters.build_type >>-{{ checksum "Cargo.lock" }}
+            - v04-rust-cache-deps-<< parameters.build_type >>-{{ checksum "Cargo.lock" }}
 
         # Build the rust code, including test binaries
       - run:
@@ -128,7 +128,7 @@ jobs:
 
       - save_cache:
           name: Save rust cache
-          key: v03-rust-cache-deps-<< parameters.build_type >>-{{ checksum "Cargo.lock" }}
+          key: v04-rust-cache-deps-<< parameters.build_type >>-{{ checksum "Cargo.lock" }}
           paths:
             - ~/.cargo/registry
             - ~/.cargo/git
@@ -182,6 +182,21 @@ jobs:
           paths:
             - "*"
 
+  check-python:
+    executor: python/default
+    steps:
+      - checkout
+      - run:
+          name: Install pipenv & deps
+          working_directory: test_runner
+          command: |
+            pip install pipenv
+            pipenv install --dev
+      - run:
+          name: Run yapf to ensure code format
+          working_directory: test_runner
+          command: pipenv run yapf --recursive --diff .
+
   run-pytest:
     #description: "Run pytest"
     executor: python/default
@@ -241,17 +256,21 @@ jobs:
             if << parameters.run_in_parallel >>; then
               EXTRA_PARAMS="-n4 $EXTRA_PARAMS"
             fi;
+            ./netstat-script.sh &
+            NS_PID=$!
             # Run the tests.
             #
             # The junit.xml file allows CircleCI to display more fine-grained test information
             # in its "Tests" tab in the results page.
-            # -s prevents pytest from capturing output, which helps to see
-            # what's going on if the test hangs
             # --verbose prints name of each test (helpful when there are
             # multiple tests in one file)
             # -rA prints summary in the end
             # -n4 uses four processes to run tests via pytest-xdist
-            pipenv run pytest --junitxml=$TEST_OUTPUT/junit.xml --tb=short -s --verbose -rA $TEST_SELECTION $EXTRA_PARAMS
+            # -s is not used to prevent pytest from capturing output, because tests are running
+            # in parallel and logs are mixed between different tests
+            pipenv run pytest --junitxml=$TEST_OUTPUT/junit.xml --tb=short --verbose -rA $TEST_SELECTION $EXTRA_PARAMS
+            kill $NS_PID
+            awk '/===/ {if (count) print count; print; count=0; next} {count++} END {print count}' $TEST_OUTPUT/netstat.stdout > $TEST_OUTPUT/netstat_stats.stdout
       - run:
           # CircleCI artifacts are preserved one file at a time, so skipping
           # this step isn't a good idea. If you want to extract the
@@ -325,8 +344,7 @@ jobs:
                 \"inputs\": {
                   \"ci_job_name\": \"zenith-remote-ci\",
                   \"commit_hash\": \"$CIRCLE_SHA1\",
-                  \"remote_repo\": \"$LOCAL_REPO\",
-                  \"zenith_image_branch\": \"$CIRCLE_BRANCH\"
+                  \"remote_repo\": \"$LOCAL_REPO\"
                 }
               }"
 
@@ -334,6 +352,7 @@ workflows:
   build_and_test:
     jobs:
       - check-codestyle
+      - check-python
       - build-postgres:
           name: build-postgres-<< matrix.build_type >>
           matrix:

Cargo.lock

@@ -2326,6 +2326,7 @@ dependencies = [
  "fs2",
  "hex",
  "humantime",
+ "hyper",
  "lazy_static",
  "log",
  "pageserver",
@@ -2333,6 +2334,7 @@ dependencies = [
  "postgres-protocol",
  "postgres_ffi",
  "regex",
+ "routerify",
  "rust-s3",
  "serde",
  "serde_json",

Dockerfile

@@ -38,8 +38,6 @@ RUN apt-get update && apt-get -yq install libreadline-dev libseccomp-dev openssl
 
 COPY --from=build /zenith/target/release/pageserver /usr/local/bin
 COPY --from=build /zenith/target/release/safekeeper /usr/local/bin
-# TODO: temporary alias for compatibility, see https://github.com/zenithdb/zenith/pull/740
-RUN ln -s /usr/local/bin/safekeeper /usr/local/bin/wal_acceptor
 COPY --from=build /zenith/target/release/proxy /usr/local/bin
 COPY --from=pg-build /zenith/tmp_install postgres_install
 COPY docker-entrypoint.sh /docker-entrypoint.sh

Dockerfile.alpine

@@ -82,8 +82,6 @@ RUN apk add --update openssl build-base libseccomp-dev
 RUN apk --no-cache --update --repository https://dl-cdn.alpinelinux.org/alpine/edge/testing add rocksdb
 COPY --from=build /zenith/target/release/pageserver /usr/local/bin
 COPY --from=build /zenith/target/release/safekeeper /usr/local/bin
-# TODO: temporary alias for compatibility, see https://github.com/zenithdb/zenith/pull/740
-RUN ln -s /usr/local/bin/safekeeper /usr/local/bin/wal_acceptor
 COPY --from=build /zenith/target/release/proxy /usr/local/bin
 COPY --from=pg-build /zenith/tmp_install /usr/local
 COPY docker-entrypoint.sh /docker-entrypoint.sh

README.md

@@ -28,7 +28,7 @@ apt install build-essential libtool libreadline-dev zlib1g-dev flex bison libsec
 libssl-dev clang pkg-config libpq-dev
 ```
 
-[Rust] 1.52 or later is also required.
+[Rust] 1.55 or later is also required.
 
 To run the `psql` client, install the `postgresql-client` package or modify `PATH` and `LD_LIBRARY_PATH` to include `tmp_install/bin` and `tmp_install/lib`, respectively.
 

control_plane/src/compute.rs

@@ -84,25 +84,53 @@ impl ComputeControlPlane {
         }
     }
 
+    // FIXME: see also parse_point_in_time in branches.rs.
+    fn parse_point_in_time(
+        &self,
+        tenantid: ZTenantId,
+        s: &str,
+    ) -> Result<(ZTimelineId, Option<Lsn>)> {
+        let mut strings = s.split('@');
+        let name = strings.next().unwrap();
+
+        let lsn: Option<Lsn>;
+        if let Some(lsnstr) = strings.next() {
+            lsn = Some(
+                Lsn::from_str(lsnstr)
+                    .with_context(|| "invalid LSN in point-in-time specification")?,
+            );
+        } else {
+            lsn = None
+        }
+
+        // Resolve the timeline ID, given the human-readable branch name
+        let timeline_id = self
+            .pageserver
+            .branch_get_by_name(&tenantid, name)?
+            .timeline_id;
+
+        Ok((timeline_id, lsn))
+    }
+
     pub fn new_node(
         &mut self,
         tenantid: ZTenantId,
-        branch_name: &str,
+        name: &str,
+        timeline_spec: &str,
         port: Option<u16>,
     ) -> Result<Arc<PostgresNode>> {
-        let timeline_id = self
-            .pageserver
-            .branch_get_by_name(&tenantid, branch_name)?
-            .timeline_id;
+        // Resolve the human-readable timeline spec into timeline ID and LSN
+        let (timelineid, lsn) = self.parse_point_in_time(tenantid, timeline_spec)?;
 
         let port = port.unwrap_or_else(|| self.get_port());
         let node = Arc::new(PostgresNode {
-            name: branch_name.to_owned(),
+            name: name.to_owned(),
             address: SocketAddr::new("127.0.0.1".parse().unwrap(), port),
             env: self.env.clone(),
             pageserver: Arc::clone(&self.pageserver),
             is_test: false,
-            timelineid: timeline_id,
+            timelineid,
+            lsn,
             tenantid,
             uses_wal_proposer: false,
         });
@@ -127,6 +155,7 @@ pub struct PostgresNode {
     pageserver: Arc<PageServerNode>,
     is_test: bool,
     pub timelineid: ZTimelineId,
+    pub lsn: Option<Lsn>, // if it's a read-only node. None for primary
     pub tenantid: ZTenantId,
     uses_wal_proposer: bool,
 }
@@ -161,9 +190,12 @@ impl PostgresNode {
         let port: u16 = conf.parse_field("port", &context)?;
         let timelineid: ZTimelineId = conf.parse_field("zenith.zenith_timeline", &context)?;
         let tenantid: ZTenantId = conf.parse_field("zenith.zenith_tenant", &context)?;
-
         let uses_wal_proposer = conf.get("wal_acceptors").is_some();
 
+        // parse recovery_target_lsn, if any
+        let recovery_target_lsn: Option<Lsn> =
+            conf.parse_field_optional("recovery_target_lsn", &context)?;
+
         // ok now
         Ok(PostgresNode {
             address: SocketAddr::new("127.0.0.1".parse().unwrap(), port),
@@ -172,6 +204,7 @@ impl PostgresNode {
             pageserver: Arc::clone(pageserver),
             is_test: false,
             timelineid,
+            lsn: recovery_target_lsn,
             tenantid,
             uses_wal_proposer,
         })
@@ -233,7 +266,7 @@ impl PostgresNode {
         // Read the archive directly from the `CopyOutReader`
         tar::Archive::new(copyreader)
             .unpack(&self.pgdata())
-            .with_context(|| "extracting page backup failed")?;
+            .with_context(|| "extracting base backup failed")?;
 
         Ok(())
     }
@@ -301,6 +334,9 @@ impl PostgresNode {
         conf.append("zenith.page_server_connstring", &pageserver_connstr);
         conf.append("zenith.zenith_tenant", &self.tenantid.to_string());
         conf.append("zenith.zenith_timeline", &self.timelineid.to_string());
+        if let Some(lsn) = self.lsn {
+            conf.append("recovery_target_lsn", &lsn.to_string());
+        }
         conf.append_line("");
 
         // Configure the node to stream WAL directly to the pageserver
@@ -314,7 +350,9 @@ impl PostgresNode {
     }
 
     fn load_basebackup(&self) -> Result<()> {
-        let lsn = if self.uses_wal_proposer {
+        let backup_lsn = if let Some(lsn) = self.lsn {
+            Some(lsn)
+        } else if self.uses_wal_proposer {
             // LSN 0 means that it is bootstrap and we need to download just
             // latest data from the pageserver. That is a bit clumsy but whole bootstrap
             // procedure evolves quite actively right now, so let's think about it again
@@ -329,7 +367,7 @@ impl PostgresNode {
             None
         };
 
-        self.do_basebackup(lsn)?;
+        self.do_basebackup(backup_lsn)?;
 
         Ok(())
     }
@@ -406,6 +444,10 @@ impl PostgresNode {
         // 3. Load basebackup
         self.load_basebackup()?;
 
+        if self.lsn.is_some() {
+            File::create(self.pgdata().join("standby.signal"))?;
+        }
+
         // 4. Finally start the compute node postgres
         println!("Starting postgres node at '{}'", self.connstr());
         self.pg_ctl(&["start"], auth_token)

control_plane/src/postgresql_conf.rs

@@ -83,6 +83,22 @@ impl PostgresConf {
             .with_context(|| format!("could not parse '{}' option {}", field_name, context))
     }
 
+    pub fn parse_field_optional<T>(&self, field_name: &str, context: &str) -> Result<Option<T>>
+    where
+        T: FromStr,
+        <T as FromStr>::Err: std::error::Error + Send + Sync + 'static,
+    {
+        if let Some(val) = self.get(field_name) {
+            let result = val
+                .parse::<T>()
+                .with_context(|| format!("could not parse '{}' option {}", field_name, context))?;
+
+            Ok(Some(result))
+        } else {
+            Ok(None)
+        }
+    }
+
     ///
     /// Note: if you call this multiple times for the same option, the config
     /// file will a line for each call. It would be nice to have a function

docker-entrypoint.sh

@@ -7,7 +7,7 @@ if [ "$1" = 'pageserver' ]; then
         pageserver --init -D /data --postgres-distrib /usr/local
     fi
     echo "Staring pageserver at 0.0.0.0:6400"
-    pageserver -l 0.0.0.0:6400 -D /data
+    pageserver -l 0.0.0.0:6400 --listen-http 0.0.0.0:9898 -D /data
 else
     "$@"
 fi

pageserver/src/basebackup.rs

@@ -13,6 +13,7 @@
 use anyhow::Result;
 use bytes::{BufMut, BytesMut};
 use log::*;
+use std::fmt::Write as FmtWrite;
 use std::io;
 use std::io::Write;
 use std::sync::Arc;
@@ -83,7 +84,7 @@ impl<'a> Basebackup<'a> {
 
         info!(
             "taking basebackup lsn={}, prev_lsn={}",
-            backup_prev, backup_lsn
+            backup_lsn, backup_prev
         );
 
         Ok(Basebackup {
@@ -248,13 +249,7 @@ impl<'a> Basebackup<'a> {
         let mut pg_control = ControlFileData::decode(&pg_control_bytes)?;
         let mut checkpoint = CheckPoint::decode(&checkpoint_bytes)?;
 
-        // Generate new pg_control and WAL needed for bootstrap
-        let checkpoint_segno = self.lsn.segment_number(pg_constants::WAL_SEGMENT_SIZE);
-        let checkpoint_lsn = XLogSegNoOffsetToRecPtr(
-            checkpoint_segno,
-            XLOG_SIZE_OF_XLOG_LONG_PHD as u32,
-            pg_constants::WAL_SEGMENT_SIZE,
-        );
+        // Generate new pg_control needed for bootstrap
         checkpoint.redo = normalize_lsn(self.lsn, pg_constants::WAL_SEGMENT_SIZE).0;
 
         //reset some fields we don't want to preserve
@@ -263,19 +258,24 @@ impl<'a> Basebackup<'a> {
         checkpoint.oldestActiveXid = 0;
 
         //save new values in pg_control
-        pg_control.checkPoint = checkpoint_lsn;
+        pg_control.checkPoint = 0;
         pg_control.checkPointCopy = checkpoint;
         pg_control.state = pg_constants::DB_SHUTDOWNED;
 
         // add zenith.signal file
-        let xl_prev = if self.prev_record_lsn == Lsn(0) {
-            0xBAD0 // magic value to indicate that we don't know prev_lsn
+        let mut zenith_signal = String::new();
+        if self.prev_record_lsn == Lsn(0) {
+            if self.lsn == self.timeline.get_ancestor_lsn() {
+                write!(zenith_signal, "PREV LSN: none")?;
+            } else {
+                write!(zenith_signal, "PREV LSN: invalid")?;
+            }
         } else {
-            self.prev_record_lsn.0
-        };
+            write!(zenith_signal, "PREV LSN: {}", self.prev_record_lsn)?;
+        }
         self.ar.append(
-            &new_tar_header("zenith.signal", 8)?,
-            &xl_prev.to_le_bytes()[..],
+            &new_tar_header("zenith.signal", zenith_signal.len() as u64)?,
+            zenith_signal.as_bytes(),
         )?;
 
         //send pg_control
@@ -284,14 +284,15 @@ impl<'a> Basebackup<'a> {
         self.ar.append(&header, &pg_control_bytes[..])?;
 
         //send wal segment
+        let segno = self.lsn.segment_number(pg_constants::WAL_SEGMENT_SIZE);
         let wal_file_name = XLogFileName(
             1, // FIXME: always use Postgres timeline 1
-            checkpoint_segno,
+            segno,
             pg_constants::WAL_SEGMENT_SIZE,
         );
         let wal_file_path = format!("pg_wal/{}", wal_file_name);
         let header = new_tar_header(&wal_file_path, pg_constants::WAL_SEGMENT_SIZE as u64)?;
-        let wal_seg = generate_wal_segment(&pg_control);
+        let wal_seg = generate_wal_segment(segno, pg_control.system_identifier);
         assert!(wal_seg.len() == pg_constants::WAL_SEGMENT_SIZE);
         self.ar.append(&header, &wal_seg[..])?;
         Ok(())

pageserver/src/bin/pageserver.rs

@@ -2,7 +2,6 @@
 // Main entry point for the Page Server executable
 //
 
-use pageserver::defaults::*;
 use serde::{Deserialize, Serialize};
 use std::{
     env,
@@ -28,13 +27,8 @@ use clap::{App, Arg, ArgMatches};
 use daemonize::Daemonize;
 
 use pageserver::{
-    branches,
-    defaults::{
-        DEFAULT_HTTP_LISTEN_ADDR, DEFAULT_PG_LISTEN_ADDR,
-        DEFAULT_RELISH_STORAGE_MAX_CONCURRENT_SYNC_LIMITS,
-    },
-    http, page_service, relish_storage, tenant_mgr, PageServerConf, RelishStorageConfig,
-    RelishStorageKind, S3Config, LOG_FILE_NAME,
+    branches, defaults::*, http, page_service, relish_storage, tenant_mgr, PageServerConf,
+    RelishStorageConfig, RelishStorageKind, S3Config, LOG_FILE_NAME,
 };
 use zenith_utils::http::endpoint;
 use zenith_utils::postgres_backend;
@@ -42,7 +36,7 @@ use zenith_utils::postgres_backend;
 use const_format::formatcp;
 
 /// String arguments that can be declared via CLI or config file
-#[derive(Serialize, Deserialize)]
+#[derive(Serialize, Deserialize, PartialEq, Eq, Clone)]
 struct CfgFileParams {
     listen_pg_addr: Option<String>,
     listen_http_addr: Option<String>,
@@ -53,12 +47,21 @@ struct CfgFileParams {
     pg_distrib_dir: Option<String>,
     auth_validation_public_key_path: Option<String>,
     auth_type: Option<String>,
-    // see https://github.com/alexcrichton/toml-rs/blob/6c162e6562c3e432bf04c82a3d1d789d80761a86/examples/enum_external.rs for enum deserialisation examples
-    relish_storage: Option<RelishStorage>,
     relish_storage_max_concurrent_sync: Option<String>,
+    /////////////////////////////////
+    //// Don't put `Option<String>` and other "simple" values below.
+    ////
+    /// `Option<RelishStorage>` is a <a href='https://toml.io/en/v1.0.0#table'>table</a> in TOML.
+    /// Values in TOML cannot be defined after tables (other tables can),
+    /// and [`toml`] crate serializes all fields in the order of their appearance.
+    ////////////////////////////////
+    relish_storage: Option<RelishStorage>,
 }
 
-#[derive(Serialize, Deserialize, Clone)]
+#[derive(Serialize, Deserialize, PartialEq, Eq, Clone)]
+// Without this attribute, enums with values won't be serialized by the `toml` library (but can be deserialized nonetheless!).
+// See https://github.com/alexcrichton/toml-rs/blob/6c162e6562c3e432bf04c82a3d1d789d80761a86/examples/enum_external.rs for the examples
+#[serde(untagged)]
 enum RelishStorage {
     Local {
         local_path: String,
@@ -552,7 +555,7 @@ fn start_pageserver(conf: &'static PageServerConf) -> Result<()> {
                 info!("Got SIGQUIT. Terminate pageserver in immediate shutdown mode");
                 exit(111);
             }
-            SIGTERM => {
+            SIGINT | SIGTERM => {
                 info!("Got SIGINT/SIGTERM. Terminate gracefully in fast shutdown mode");
                 // Terminate postgres backends
                 postgres_backend::set_pgbackend_shutdown_requested();
@@ -577,11 +580,142 @@ fn start_pageserver(conf: &'static PageServerConf) -> Result<()> {
                 info!("Pageserver shut down successfully completed");
                 exit(0);
             }
-            _ => {
-                debug!("Unknown signal.");
+            unknown_signal => {
+                debug!("Unknown signal {}", unknown_signal);
             }
         }
     }
 
     Ok(())
 }
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    #[test]
+    fn page_server_conf_toml_serde() {
+        let params = CfgFileParams {
+            listen_pg_addr: Some("listen_pg_addr_VALUE".to_string()),
+            listen_http_addr: Some("listen_http_addr_VALUE".to_string()),
+            checkpoint_distance: Some("checkpoint_distance_VALUE".to_string()),
+            checkpoint_period: Some("checkpoint_period_VALUE".to_string()),
+            gc_horizon: Some("gc_horizon_VALUE".to_string()),
+            gc_period: Some("gc_period_VALUE".to_string()),
+            pg_distrib_dir: Some("pg_distrib_dir_VALUE".to_string()),
+            auth_validation_public_key_path: Some(
+                "auth_validation_public_key_path_VALUE".to_string(),
+            ),
+            auth_type: Some("auth_type_VALUE".to_string()),
+            relish_storage: Some(RelishStorage::Local {
+                local_path: "relish_storage_local_VALUE".to_string(),
+            }),
+            relish_storage_max_concurrent_sync: Some(
+                "relish_storage_max_concurrent_sync_VALUE".to_string(),
+            ),
+        };
+
+        let toml_string = toml::to_string(&params).expect("Failed to serialize correct config");
+        let toml_pretty_string =
+            toml::to_string_pretty(&params).expect("Failed to serialize correct config");
+        assert_eq!(
+            r#"listen_pg_addr = 'listen_pg_addr_VALUE'
+listen_http_addr = 'listen_http_addr_VALUE'
+checkpoint_distance = 'checkpoint_distance_VALUE'
+checkpoint_period = 'checkpoint_period_VALUE'
+gc_horizon = 'gc_horizon_VALUE'
+gc_period = 'gc_period_VALUE'
+pg_distrib_dir = 'pg_distrib_dir_VALUE'
+auth_validation_public_key_path = 'auth_validation_public_key_path_VALUE'
+auth_type = 'auth_type_VALUE'
+relish_storage_max_concurrent_sync = 'relish_storage_max_concurrent_sync_VALUE'
+
+[relish_storage]
+local_path = 'relish_storage_local_VALUE'
+"#,
+            toml_pretty_string
+        );
+
+        let params_from_serialized: CfgFileParams = toml::from_str(&toml_string)
+            .expect("Failed to deserialize the serialization result of the config");
+        let params_from_serialized_pretty: CfgFileParams = toml::from_str(&toml_pretty_string)
+            .expect("Failed to deserialize the prettified serialization result of the config");
+        assert!(
+            params_from_serialized == params,
+            "Expected the same config in the end of config -> serialize -> deserialize chain"
+        );
+        assert!(
+            params_from_serialized_pretty == params,
+            "Expected the same config in the end of config -> serialize pretty -> deserialize chain"
+        );
+    }
+
+    #[test]
+    fn credentials_omitted_during_serialization() {
+        let params = CfgFileParams {
+            listen_pg_addr: Some("listen_pg_addr_VALUE".to_string()),
+            listen_http_addr: Some("listen_http_addr_VALUE".to_string()),
+            checkpoint_distance: Some("checkpoint_distance_VALUE".to_string()),
+            checkpoint_period: Some("checkpoint_period_VALUE".to_string()),
+            gc_horizon: Some("gc_horizon_VALUE".to_string()),
+            gc_period: Some("gc_period_VALUE".to_string()),
+            pg_distrib_dir: Some("pg_distrib_dir_VALUE".to_string()),
+            auth_validation_public_key_path: Some(
+                "auth_validation_public_key_path_VALUE".to_string(),
+            ),
+            auth_type: Some("auth_type_VALUE".to_string()),
+            relish_storage: Some(RelishStorage::AwsS3 {
+                bucket_name: "bucket_name_VALUE".to_string(),
+                bucket_region: "bucket_region_VALUE".to_string(),
+                access_key_id: Some("access_key_id_VALUE".to_string()),
+                secret_access_key: Some("secret_access_key_VALUE".to_string()),
+            }),
+            relish_storage_max_concurrent_sync: Some(
+                "relish_storage_max_concurrent_sync_VALUE".to_string(),
+            ),
+        };
+
+        let toml_string = toml::to_string(&params).expect("Failed to serialize correct config");
+        let toml_pretty_string =
+            toml::to_string_pretty(&params).expect("Failed to serialize correct config");
+        assert_eq!(
+            r#"listen_pg_addr = 'listen_pg_addr_VALUE'
+listen_http_addr = 'listen_http_addr_VALUE'
+checkpoint_distance = 'checkpoint_distance_VALUE'
+checkpoint_period = 'checkpoint_period_VALUE'
+gc_horizon = 'gc_horizon_VALUE'
+gc_period = 'gc_period_VALUE'
+pg_distrib_dir = 'pg_distrib_dir_VALUE'
+auth_validation_public_key_path = 'auth_validation_public_key_path_VALUE'
+auth_type = 'auth_type_VALUE'
+relish_storage_max_concurrent_sync = 'relish_storage_max_concurrent_sync_VALUE'
+
+[relish_storage]
+bucket_name = 'bucket_name_VALUE'
+bucket_region = 'bucket_region_VALUE'
+"#,
+            toml_pretty_string
+        );
+
+        let params_from_serialized: CfgFileParams = toml::from_str(&toml_string)
+            .expect("Failed to deserialize the serialization result of the config");
+        let params_from_serialized_pretty: CfgFileParams = toml::from_str(&toml_pretty_string)
+            .expect("Failed to deserialize the prettified serialization result of the config");
+
+        let mut expected_params = params;
+        expected_params.relish_storage = Some(RelishStorage::AwsS3 {
+            bucket_name: "bucket_name_VALUE".to_string(),
+            bucket_region: "bucket_region_VALUE".to_string(),
+            access_key_id: None,
+            secret_access_key: None,
+        });
+        assert!(
+            params_from_serialized == expected_params,
+            "Expected the config without credentials in the end of a 'config -> serialize -> deserialize' chain"
+        );
+        assert!(
+            params_from_serialized_pretty == expected_params,
+            "Expected the config without credentials in the end of a 'config -> serialize pretty -> deserialize' chain"
+        );
+    }
+}

pageserver/src/branches.rs

@@ -183,6 +183,9 @@ fn run_initdb(conf: &'static PageServerConf, initdbpath: &Path) -> Result<()> {
         .args(&["-D", initdbpath.to_str().unwrap()])
         .args(&["-U", &conf.superuser])
         .arg("--no-instructions")
+        // This is only used for a temporary installation that is deleted shortly after,
+        // so no need to fsync it
+        .arg("--no-sync")
         .env_clear()
         .env("LD_LIBRARY_PATH", conf.pg_lib_dir().to_str().unwrap())
         .env("DYLD_LIBRARY_PATH", conf.pg_lib_dir().to_str().unwrap())

pageserver/src/http/routes.rs

@@ -1,4 +1,3 @@
-use std::str::FromStr;
 use std::sync::Arc;
 
 use anyhow::Result;
@@ -16,6 +15,8 @@ use zenith_utils::http::{
     endpoint,
     error::HttpErrorBody,
     json::{json_request, json_response},
+    request::get_request_param,
+    request::parse_request_param,
 };
 
 use super::models::BranchCreateRequest;
@@ -57,33 +58,6 @@ fn get_config(request: &Request<Body>) -> &'static PageServerConf {
     get_state(request).conf
 }
 
-fn get_request_param<'a>(
-    request: &'a Request<Body>,
-    param_name: &str,
-) -> Result<&'a str, ApiError> {
-    match request.param(param_name) {
-        Some(arg) => Ok(arg),
-        None => {
-            return Err(ApiError::BadRequest(format!(
-                "no {} specified in path param",
-                param_name
-            )))
-        }
-    }
-}
-
-fn parse_request_param<T: FromStr>(
-    request: &Request<Body>,
-    param_name: &str,
-) -> Result<T, ApiError> {
-    match get_request_param(request, param_name)?.parse() {
-        Ok(v) => Ok(v),
-        Err(_) => Err(ApiError::BadRequest(
-            "failed to parse tenant id".to_string(),
-        )),
-    }
-}
-
 // healthcheck handler
 async fn status_handler(_: Request<Body>) -> Result<Response<Body>, ApiError> {
     Ok(Response::builder()

pageserver/src/layered_repository.rs

@@ -678,6 +678,10 @@ pub struct LayeredTimeline {
 
 /// Public interface functions
 impl Timeline for LayeredTimeline {
+    fn get_ancestor_lsn(&self) -> Lsn {
+        self.ancestor_lsn
+    }
+
     /// Wait until WAL has been received up to the given LSN.
     fn wait_lsn(&self, lsn: Lsn) -> Result<()> {
         // This should never be called from the WAL receiver thread, because that could lead
@@ -1340,50 +1344,54 @@ impl LayeredTimeline {
             timeline_dir.sync_all()?;
         }
 
-        // Save the metadata, with updated 'disk_consistent_lsn', to a
-        // file in the timeline dir. After crash, we will restart WAL
-        // streaming and processing from that point.
+        // If we were able to advance 'disk_consistent_lsn', save it the metadata file.
+        // After crash, we will restart WAL streaming and processing from that point.
+        let old_disk_consistent_lsn = self.disk_consistent_lsn.load();
+        if disk_consistent_lsn != old_disk_consistent_lsn {
+            assert!(disk_consistent_lsn > old_disk_consistent_lsn);
 
-        // We can only save a valid 'prev_record_lsn' value on disk if we
-        // flushed *all* in-memory changes to disk. We only track
-        // 'prev_record_lsn' in memory for the latest processed record, so we
-        // don't remember what the correct value that corresponds to some old
-        // LSN is. But if we flush everything, then the value corresponding
-        // current 'last_record_lsn' is correct and we can store it on disk.
-        let ondisk_prev_record_lsn = if disk_consistent_lsn == last_record_lsn {
-            Some(prev_record_lsn)
-        } else {
-            None
-        };
+            // We can only save a valid 'prev_record_lsn' value on disk if we
+            // flushed *all* in-memory changes to disk. We only track
+            // 'prev_record_lsn' in memory for the latest processed record, so we
+            // don't remember what the correct value that corresponds to some old
+            // LSN is. But if we flush everything, then the value corresponding
+            // current 'last_record_lsn' is correct and we can store it on disk.
+            let ondisk_prev_record_lsn = if disk_consistent_lsn == last_record_lsn {
+                Some(prev_record_lsn)
+            } else {
+                None
+            };
 
-        let ancestor_timelineid = self.ancestor_timeline.as_ref().map(|x| x.timelineid);
+            let ancestor_timelineid = self.ancestor_timeline.as_ref().map(|x| x.timelineid);
 
-        let metadata = TimelineMetadata {
-            disk_consistent_lsn,
-            prev_record_lsn: ondisk_prev_record_lsn,
-            ancestor_timeline: ancestor_timelineid,
-            ancestor_lsn: self.ancestor_lsn,
-        };
-        LayeredRepository::save_metadata(
-            self.conf,
-            self.timelineid,
-            self.tenantid,
-            &metadata,
-            false,
-        )?;
-        if self.upload_relishes {
-            schedule_timeline_upload(())
-            // schedule_timeline_upload(
-            //     self.tenantid,
-            //     self.timelineid,
-            //     layer_uploads,
-            //     disk_consistent_lsn,
-            // });
+            let metadata = TimelineMetadata {
+                disk_consistent_lsn,
+                prev_record_lsn: ondisk_prev_record_lsn,
+                ancestor_timeline: ancestor_timelineid,
+                ancestor_lsn: self.ancestor_lsn,
+            };
+            LayeredRepository::save_metadata(
+                self.conf,
+                self.timelineid,
+                self.tenantid,
+                &metadata,
+                false,
+            )?;
+
+            // Also update the in-memory copy
+            self.disk_consistent_lsn.store(disk_consistent_lsn);
+
+            if self.upload_relishes {
+                schedule_timeline_upload(())
+                // schedule_timeline_upload(
+                //     self.tenantid,
+                //     self.timelineid,
+                //     layer_uploads,
+                //     disk_consistent_lsn,
+                // });
+            }
         }
 
-        // Also update the in-memory copy
-        self.disk_consistent_lsn.store(disk_consistent_lsn);
-
         Ok(())
     }
 
@@ -1695,7 +1703,7 @@ impl LayeredTimeline {
             //
             // If we don't have a base image, then the oldest WAL record better initialize
             // the page
-            if data.page_img.is_none() && !data.records.first().unwrap().will_init {
+            if data.page_img.is_none() && !data.records.first().unwrap().1.will_init {
                 // FIXME: this ought to be an error?
                 warn!(
                     "Base image for page {}/{} at {} not found, but got {} WAL records",
@@ -1773,7 +1781,7 @@ impl Deref for LayeredTimelineWriter<'_> {
 }
 
 impl<'a> TimelineWriter for LayeredTimelineWriter<'a> {
-    fn put_wal_record(&self, rel: RelishTag, blknum: u32, rec: WALRecord) -> Result<()> {
+    fn put_wal_record(&self, lsn: Lsn, rel: RelishTag, blknum: u32, rec: WALRecord) -> Result<()> {
         if !rel.is_blocky() && blknum != 0 {
             bail!(
                 "invalid request for block {} for non-blocky relish {}",
@@ -1781,11 +1789,11 @@ impl<'a> TimelineWriter for LayeredTimelineWriter<'a> {
                 rel
             );
         }
-        ensure!(rec.lsn.is_aligned(), "unaligned record LSN");
+        ensure!(lsn.is_aligned(), "unaligned record LSN");
 
         let seg = SegmentTag::from_blknum(rel, blknum);
-        let layer = self.tl.get_layer_for_write(seg, rec.lsn)?;
-        let delta_size = layer.put_wal_record(blknum, rec);
+        let layer = self.tl.get_layer_for_write(seg, lsn)?;
+        let delta_size = layer.put_wal_record(lsn, blknum, rec);
         self.tl
             .increase_current_logical_size(delta_size * BLCKSZ as u32);
         Ok(())

pageserver/src/layered_repository/delta_layer.rs

@@ -198,7 +198,7 @@ impl Layer for DeltaLayer {
                 .slice_range((Included(&minkey), Included(&maxkey)))
                 .iter()
                 .rev();
-            for ((_blknum, _lsn), blob_range) in iter {
+            for ((_blknum, pv_lsn), blob_range) in iter {
                 let pv = PageVersion::des(&read_blob(&page_version_reader, blob_range)?)?;
 
                 if let Some(img) = pv.page_image {
@@ -208,7 +208,7 @@ impl Layer for DeltaLayer {
                     break;
                 } else if let Some(rec) = pv.record {
                     let will_init = rec.will_init;
-                    reconstruct_data.records.push(rec);
+                    reconstruct_data.records.push((*pv_lsn, rec));
                     if will_init {
                         // This WAL record initializes the page, so no need to go further back
                         need_image = false;

pageserver/src/layered_repository/inmemory_layer.rs

@@ -160,13 +160,13 @@ impl Layer for InMemoryLayer {
                 .get_block_lsn_range(blknum, ..=lsn)
                 .iter()
                 .rev();
-            for (_entry_lsn, entry) in iter {
+            for (entry_lsn, entry) in iter {
                 if let Some(img) = &entry.page_image {
                     reconstruct_data.page_img = Some(img.clone());
                     need_image = false;
                     break;
                 } else if let Some(rec) = &entry.record {
-                    reconstruct_data.records.push(rec.clone());
+                    reconstruct_data.records.push((*entry_lsn, rec.clone()));
                     if rec.will_init {
                         // This WAL record initializes the page, so no need to go further back
                         need_image = false;
@@ -337,10 +337,10 @@ impl InMemoryLayer {
     // Write operations
 
     /// Remember new page version, as a WAL record over previous version
-    pub fn put_wal_record(&self, blknum: u32, rec: WALRecord) -> u32 {
+    pub fn put_wal_record(&self, lsn: Lsn, blknum: u32, rec: WALRecord) -> u32 {
         self.put_page_version(
             blknum,
-            rec.lsn,
+            lsn,
             PageVersion {
                 page_image: None,
                 record: Some(rec),

pageserver/src/layered_repository/storage_layer.rs

@@ -78,7 +78,7 @@ pub struct PageVersion {
 /// 'records' contains the records to apply over the base image.
 ///
 pub struct PageReconstructData {
-    pub records: Vec<WALRecord>,
+    pub records: Vec<(Lsn, WALRecord)>,
     pub page_img: Option<Bytes>,
 }
 

pageserver/src/relish_storage.rs

@@ -55,15 +55,21 @@ pub trait RelishStorage: Send + Sync {
 
     async fn list_relishes(&self) -> anyhow::Result<Vec<Self::RelishStoragePath>>;
 
-    async fn download_relish(
+    async fn download_relish<W: 'static + std::io::Write + Send>(
         &self,
         from: &Self::RelishStoragePath,
-        to: &Path,
-    ) -> anyhow::Result<()>;
+        // rust_s3 `get_object_stream` method requires `std::io::BufWriter` for some reason, not the async counterpart
+        // that forces us to consume and return the writer to satisfy the blocking operation async wrapper requirements
+        to: std::io::BufWriter<W>,
+    ) -> anyhow::Result<std::io::BufWriter<W>>;
 
     async fn delete_relish(&self, path: &Self::RelishStoragePath) -> anyhow::Result<()>;
 
-    async fn upload_relish(&self, from: &Path, to: &Self::RelishStoragePath) -> anyhow::Result<()>;
+    async fn upload_relish<R: tokio::io::AsyncRead + std::marker::Unpin + Send>(
+        &self,
+        from: &mut tokio::io::BufReader<R>,
+        to: &Self::RelishStoragePath,
+    ) -> anyhow::Result<()>;
 }
 
 fn strip_workspace_prefix<'a>(

pageserver/src/relish_storage/local_fs.rs

@@ -9,11 +9,13 @@
 
 use std::{
     future::Future,
+    io::Write,
     path::{Path, PathBuf},
     pin::Pin,
 };
 
 use anyhow::{bail, Context};
+use tokio::{fs, io};
 
 use super::{strip_workspace_prefix, RelishStorage};
 
@@ -64,16 +66,33 @@ impl RelishStorage for LocalFs {
         Ok(get_all_files(&self.root).await?.into_iter().collect())
     }
 
-    async fn download_relish(
+    async fn download_relish<W: 'static + std::io::Write + Send>(
         &self,
         from: &Self::RelishStoragePath,
-        to: &Path,
-    ) -> anyhow::Result<()> {
+        mut to: std::io::BufWriter<W>,
+    ) -> anyhow::Result<std::io::BufWriter<W>> {
         let file_path = self.resolve_in_storage(from)?;
         if file_path.exists() && file_path.is_file() {
-            create_target_directory(to).await?;
-            tokio::fs::copy(file_path, to).await?;
-            Ok(())
+            let updated_buffer = tokio::task::spawn_blocking(move || {
+                let mut source = std::io::BufReader::new(
+                    std::fs::OpenOptions::new()
+                        .read(true)
+                        .open(&file_path)
+                        .with_context(|| {
+                            format!(
+                                "Failed to open source file '{}' to use in the download",
+                                file_path.display()
+                            )
+                        })?,
+                );
+                std::io::copy(&mut source, &mut to)
+                    .context("Failed to download the relish file")?;
+                to.flush().context("Failed to flush the download buffer")?;
+                Ok::<_, anyhow::Error>(to)
+            })
+            .await
+            .context("Failed to spawn a blocking task")??;
+            Ok(updated_buffer)
         } else {
             bail!(
                 "File '{}' either does not exist or is not a file",
@@ -94,18 +113,30 @@ impl RelishStorage for LocalFs {
         }
     }
 
-    async fn upload_relish(&self, from: &Path, to: &Self::RelishStoragePath) -> anyhow::Result<()> {
+    async fn upload_relish<R: io::AsyncRead + std::marker::Unpin + Send>(
+        &self,
+        from: &mut io::BufReader<R>,
+        to: &Self::RelishStoragePath,
+    ) -> anyhow::Result<()> {
         let target_file_path = self.resolve_in_storage(to)?;
         create_target_directory(&target_file_path).await?;
+        let mut destination = io::BufWriter::new(
+            fs::OpenOptions::new()
+                .write(true)
+                .create(true)
+                .open(&target_file_path)
+                .await
+                .with_context(|| {
+                    format!(
+                        "Failed to open target fs destination at '{}'",
+                        target_file_path.display()
+                    )
+                })?,
+        );
 
-        tokio::fs::copy(&from, &target_file_path)
+        io::copy_buf(from, &mut destination)
             .await
-            .with_context(|| {
-                format!(
-                    "Failed to upload relish '{}' to local storage",
-                    from.display(),
-                )
-            })?;
+            .context("Failed to upload relish to local storage")?;
         Ok(())
     }
 }

pageserver/src/relish_storage/rust_s3.rs

@@ -1,5 +1,6 @@
 //! A wrapper around AWS S3 client library `rust_s3` to be used a relish storage.
 
+use std::io::Write;
 use std::path::Path;
 
 use anyhow::Context;
@@ -83,18 +84,14 @@ impl RelishStorage for RustS3 {
             .collect())
     }
 
-    async fn download_relish(
+    async fn download_relish<W: 'static + std::io::Write + Send>(
         &self,
         from: &Self::RelishStoragePath,
-        to: &Path,
-    ) -> anyhow::Result<()> {
-        let mut target_file = std::fs::OpenOptions::new()
-            .write(true)
-            .open(to)
-            .with_context(|| format!("Failed to open target s3 destination at {}", to.display()))?;
+        mut to: std::io::BufWriter<W>,
+    ) -> anyhow::Result<std::io::BufWriter<W>> {
         let code = self
             .bucket
-            .get_object_stream(from.key(), &mut target_file)
+            .get_object_stream(from.key(), &mut to)
             .await
             .with_context(|| format!("Failed to download s3 object with key {}", from.key()))?;
         if code != 200 {
@@ -103,7 +100,12 @@ impl RelishStorage for RustS3 {
                 code
             ))
         } else {
-            Ok(())
+            tokio::task::spawn_blocking(move || {
+                to.flush().context("Failed to fluch the downoad buffer")?;
+                Ok::<_, anyhow::Error>(to)
+            })
+            .await
+            .context("Failed to joim the download buffer flush task")?
         }
     }
 
@@ -113,9 +115,9 @@ impl RelishStorage for RustS3 {
             .delete_object(path.key())
             .await
             .with_context(|| format!("Failed to delete s3 object with key {}", path.key()))?;
-        if code != 200 {
+        if code != 204 {
             Err(anyhow::format_err!(
-                "Received non-200 exit code during deleting object with key '{}', code: {}",
+                "Received non-204 exit code during deleting object with key '{}', code: {}",
                 path.key(),
                 code
             ))
@@ -124,12 +126,14 @@ impl RelishStorage for RustS3 {
         }
     }
 
-    async fn upload_relish(&self, from: &Path, to: &Self::RelishStoragePath) -> anyhow::Result<()> {
-        let mut local_file = tokio::fs::OpenOptions::new().read(true).open(from).await?;
-
+    async fn upload_relish<R: tokio::io::AsyncRead + std::marker::Unpin + Send>(
+        &self,
+        from: &mut tokio::io::BufReader<R>,
+        to: &Self::RelishStoragePath,
+    ) -> anyhow::Result<()> {
         let code = self
             .bucket
-            .put_object_stream(&mut local_file, to.key())
+            .put_object_stream(from, to.key())
             .await
             .with_context(|| format!("Failed to create s3 object with key {}", to.key()))?;
         if code != 200 {

pageserver/src/repository.rs

@@ -119,6 +119,9 @@ pub trait Timeline: Send + Sync {
     /// Get a list of all existing non-relational objects
     fn list_nonrels(&self, lsn: Lsn) -> Result<HashSet<RelishTag>>;
 
+    /// Get the LSN where this branch was created
+    fn get_ancestor_lsn(&self) -> Lsn;
+
     //------------------------------------------------------------------------------
     // Public PUT functions, to update the repository with new page versions.
     //
@@ -162,7 +165,7 @@ pub trait TimelineWriter: Deref<Target = dyn Timeline> {
     ///
     /// This will implicitly extend the relation, if the page is beyond the
     /// current end-of-file.
-    fn put_wal_record(&self, tag: RelishTag, blknum: u32, rec: WALRecord) -> Result<()>;
+    fn put_wal_record(&self, lsn: Lsn, tag: RelishTag, blknum: u32, rec: WALRecord) -> Result<()>;
 
     /// Like put_wal_record, but with ready-made image of the page.
     fn put_page_image(&self, tag: RelishTag, blknum: u32, lsn: Lsn, img: Bytes) -> Result<()>;
@@ -182,7 +185,6 @@ pub trait TimelineWriter: Deref<Target = dyn Timeline> {
 
 #[derive(Debug, Clone, Serialize, Deserialize, PartialEq, Eq)]
 pub struct WALRecord {
-    pub lsn: Lsn, // LSN at the *end* of the record
     pub will_init: bool,
     pub rec: Bytes,
     // Remember the offset of main_data in rec,
@@ -193,22 +195,19 @@ pub struct WALRecord {
 
 impl WALRecord {
     pub fn pack(&self, buf: &mut BytesMut) {
-        buf.put_u64(self.lsn.0);
         buf.put_u8(self.will_init as u8);
         buf.put_u32(self.main_data_offset);
         buf.put_u32(self.rec.len() as u32);
         buf.put_slice(&self.rec[..]);
     }
     pub fn unpack(buf: &mut Bytes) -> WALRecord {
-        let lsn = Lsn::from(buf.get_u64());
         let will_init = buf.get_u8() != 0;
         let main_data_offset = buf.get_u32();
-        let mut dst = vec![0u8; buf.get_u32() as usize];
-        buf.copy_to_slice(&mut dst);
+        let rec_len = buf.get_u32() as usize;
+        let rec = buf.split_to(rec_len);
         WALRecord {
-            lsn,
             will_init,
-            rec: Bytes::from(dst),
+            rec,
             main_data_offset,
         }
     }
@@ -832,7 +831,7 @@ mod tests {
             blknum: u32,
             lsn: Lsn,
             base_img: Option<Bytes>,
-            records: Vec<WALRecord>,
+            records: Vec<(Lsn, WALRecord)>,
         ) -> Result<Bytes, WalRedoError> {
             let s = format!(
                 "redo for {} blk {} to get to {}, with {} and {} records",

pageserver/src/restore_local_repo.rs

@@ -7,10 +7,10 @@ use postgres_ffi::nonrelfile_utils::slru_may_delete_clogsegment;
 use std::cmp::min;
 use std::fs;
 use std::fs::File;
-use std::io::Read;
-use std::path::Path;
+use std::io::{Read, Seek, SeekFrom};
+use std::path::{Path, PathBuf};
 
-use anyhow::{bail, Result};
+use anyhow::{anyhow, bail, Result};
 use bytes::{Buf, Bytes};
 use tracing::*;
 
@@ -37,6 +37,8 @@ pub fn import_timeline_from_postgres_datadir(
     writer: &dyn TimelineWriter,
     lsn: Lsn,
 ) -> Result<()> {
+    let mut pg_control: Option<ControlFileData> = None;
+
     // Scan 'global'
     for direntry in fs::read_dir(path.join("global"))? {
         let direntry = direntry?;
@@ -44,7 +46,7 @@ pub fn import_timeline_from_postgres_datadir(
             None => continue,
 
             Some("pg_control") => {
-                import_control_file(writer, lsn, &direntry.path())?;
+                pg_control = Some(import_control_file(writer, lsn, &direntry.path())?);
             }
             Some("pg_filenode.map") => import_nonrel_file(
                 writer,
@@ -127,6 +129,18 @@ pub fn import_timeline_from_postgres_datadir(
 
     writer.advance_last_record_lsn(lsn);
 
+    // Import WAL. This is needed even when starting from a shutdown checkpoint, because
+    // this reads the checkpoint record itself, advancing the tip of the timeline to
+    // *after* the checkpoint record. And crucially, it initializes the 'prev_lsn'
+    let pg_control = pg_control.ok_or_else(|| anyhow!("pg_control file not found"))?;
+    import_wal(
+        &path.join("pg_wal"),
+        writer,
+        Lsn(pg_control.checkPointCopy.redo),
+        lsn,
+        &mut pg_control.checkPointCopy.clone(),
+    )?;
+
     Ok(())
 }
 
@@ -212,7 +226,11 @@ fn import_nonrel_file(
 ///
 /// The control file is imported as is, but we also extract the checkpoint record
 /// from it and store it separated.
-fn import_control_file(timeline: &dyn TimelineWriter, lsn: Lsn, path: &Path) -> Result<()> {
+fn import_control_file(
+    timeline: &dyn TimelineWriter,
+    lsn: Lsn,
+    path: &Path,
+) -> Result<ControlFileData> {
     let mut file = File::open(path)?;
     let mut buffer = Vec::new();
     // read the whole file
@@ -233,7 +251,7 @@ fn import_control_file(timeline: &dyn TimelineWriter, lsn: Lsn, path: &Path) ->
     let checkpoint_bytes = pg_control.checkPointCopy.encode();
     timeline.put_page_image(RelishTag::Checkpoint, 0, lsn, checkpoint_bytes)?;
 
-    Ok(())
+    Ok(pg_control)
 }
 
 ///
@@ -285,6 +303,104 @@ fn import_slru_file(
     Ok(())
 }
 
+/// Scan PostgreSQL WAL files in given directory and load all records between
+/// 'startpoint' and 'endpoint' into the repository.
+fn import_wal(
+    walpath: &Path,
+    timeline: &dyn TimelineWriter,
+    startpoint: Lsn,
+    endpoint: Lsn,
+    checkpoint: &mut CheckPoint,
+) -> Result<()> {
+    let mut waldecoder = WalStreamDecoder::new(startpoint);
+
+    let mut segno = startpoint.segment_number(pg_constants::WAL_SEGMENT_SIZE);
+    let mut offset = startpoint.segment_offset(pg_constants::WAL_SEGMENT_SIZE);
+    let mut last_lsn = startpoint;
+
+    while last_lsn <= endpoint {
+        // FIXME: assume postgresql tli 1 for now
+        let filename = XLogFileName(1, segno, pg_constants::WAL_SEGMENT_SIZE);
+        let mut buf = Vec::new();
+
+        // Read local file
+        let mut path = walpath.join(&filename);
+
+        // It could be as .partial
+        if !PathBuf::from(&path).exists() {
+            path = walpath.join(filename + ".partial");
+        }
+
+        // Slurp the WAL file
+        let mut file = File::open(&path)?;
+
+        if offset > 0 {
+            file.seek(SeekFrom::Start(offset as u64))?;
+        }
+
+        let nread = file.read_to_end(&mut buf)?;
+        if nread != pg_constants::WAL_SEGMENT_SIZE - offset as usize {
+            // Maybe allow this for .partial files?
+            error!("read only {} bytes from WAL file", nread);
+        }
+
+        waldecoder.feed_bytes(&buf);
+
+        let mut nrecords = 0;
+        while last_lsn <= endpoint {
+            if let Some((lsn, recdata)) = waldecoder.poll_decode()? {
+                let mut checkpoint_modified = false;
+
+                let decoded = decode_wal_record(recdata.clone());
+                save_decoded_record(
+                    checkpoint,
+                    &mut checkpoint_modified,
+                    timeline,
+                    &decoded,
+                    recdata,
+                    lsn,
+                )?;
+                last_lsn = lsn;
+
+                if checkpoint_modified {
+                    let checkpoint_bytes = checkpoint.encode();
+                    timeline.put_page_image(
+                        RelishTag::Checkpoint,
+                        0,
+                        last_lsn,
+                        checkpoint_bytes,
+                    )?;
+                }
+
+                // Now that this record has been fully handled, including updating the
+                // checkpoint data, let the repository know that it is up-to-date to this LSN
+                timeline.advance_last_record_lsn(last_lsn);
+                nrecords += 1;
+
+                trace!("imported record at {} (end {})", lsn, endpoint);
+            }
+        }
+
+        debug!("imported {} records up to {}", nrecords, last_lsn);
+
+        segno += 1;
+        offset = 0;
+    }
+
+    if last_lsn != startpoint {
+        debug!(
+            "reached end of WAL at {}, updating checkpoint info",
+            last_lsn
+        );
+
+        timeline.advance_last_record_lsn(last_lsn);
+    } else {
+        info!("no WAL to import at {}", last_lsn);
+    }
+
+    Ok(())
+}
+
 ///
 /// Helper function to parse a WAL record and call the Timeline's PUT functions for all the
 /// relations/pages that the record affects.
@@ -312,13 +428,12 @@ pub fn save_decoded_record(
         });
 
         let rec = WALRecord {
-            lsn,
             will_init: blk.will_init || blk.apply_image,
             rec: recdata.clone(),
             main_data_offset: decoded.main_data_offset as u32,
         };
 
-        timeline.put_wal_record(tag, blk.blkno, rec)?;
+        timeline.put_wal_record(lsn, tag, blk.blkno, rec)?;
     }
 
     let mut buf = decoded.record.clone();
@@ -656,12 +771,12 @@ fn save_xact_record(
     let segno = pageno / pg_constants::SLRU_PAGES_PER_SEGMENT;
     let rpageno = pageno % pg_constants::SLRU_PAGES_PER_SEGMENT;
     let rec = WALRecord {
-        lsn,
         will_init: false,
         rec: decoded.record.clone(),
         main_data_offset: decoded.main_data_offset as u32,
     };
     timeline.put_wal_record(
+        lsn,
         RelishTag::Slru {
             slru: SlruKind::Clog,
             segno,
@@ -677,6 +792,7 @@ fn save_xact_record(
             let segno = pageno / pg_constants::SLRU_PAGES_PER_SEGMENT;
             let rpageno = pageno % pg_constants::SLRU_PAGES_PER_SEGMENT;
             timeline.put_wal_record(
+                lsn,
                 RelishTag::Slru {
                     slru: SlruKind::Clog,
                     segno,
@@ -771,7 +887,6 @@ fn save_multixact_create_record(
     decoded: &DecodedWALRecord,
 ) -> Result<()> {
     let rec = WALRecord {
-        lsn,
         will_init: false,
         rec: decoded.record.clone(),
         main_data_offset: decoded.main_data_offset as u32,
@@ -780,6 +895,7 @@ fn save_multixact_create_record(
     let segno = pageno / pg_constants::SLRU_PAGES_PER_SEGMENT;
     let rpageno = pageno % pg_constants::SLRU_PAGES_PER_SEGMENT;
     timeline.put_wal_record(
+        lsn,
         RelishTag::Slru {
             slru: SlruKind::MultiXactOffsets,
             segno,
@@ -799,6 +915,7 @@ fn save_multixact_create_record(
         let segno = pageno / pg_constants::SLRU_PAGES_PER_SEGMENT;
         let rpageno = pageno % pg_constants::SLRU_PAGES_PER_SEGMENT;
         timeline.put_wal_record(
+            lsn,
             RelishTag::Slru {
                 slru: SlruKind::MultiXactMembers,
                 segno,

pageserver/src/tenant_mgr.rs

@@ -9,8 +9,8 @@ use crate::PageServerConf;
 use anyhow::{anyhow, bail, Context, Result};
 use lazy_static::lazy_static;
 use log::{debug, info};
-use std::collections::hash_map::Entry;
 use std::collections::HashMap;
+use std::fmt;
 use std::fs;
 use std::str::FromStr;
 use std::sync::atomic::{AtomicBool, Ordering};
@@ -19,13 +19,47 @@ use std::thread::JoinHandle;
 use zenith_utils::zid::{ZTenantId, ZTimelineId};
 
 lazy_static! {
-    static ref REPOSITORY: Mutex<HashMap<ZTenantId, Arc<dyn Repository>>> =
-        Mutex::new(HashMap::new());
+    static ref TENANTS: Mutex<HashMap<ZTenantId, Tenant>> = Mutex::new(HashMap::new());
 }
 
-fn access_repository() -> MutexGuard<'static, HashMap<ZTenantId, Arc<dyn Repository>>> {
-    REPOSITORY.lock().unwrap()
+struct Tenant {
+    state: TenantState,
+    repo: Option<Arc<dyn Repository>>,
 }
+
+#[derive(Debug)]
+enum TenantState {
+    // This tenant only exists in cloud storage. It cannot be accessed.
+    CloudOnly,
+    // This tenant exists in cloud storage, and we are currently downloading it to local disk.
+    // It cannot be accessed yet, not until it's been fully downloaded to local disk.
+    Downloading,
+    // All data for this tenant is complete on local disk, but we haven't loaded the Repository,
+    // Timeline and Layer structs into memory yet, so it cannot be accessed yet.
+    //Ready,
+    // This tenant exists on local disk, and the layer map has been loaded into memory.
+    // The local disk might have some newer files that don't exist in cloud storage yet.
+    Active,
+    // This tenant exists on local disk, and the layer map has been loaded into memory.
+    // The local disk might have some newer files that don't exist in cloud storage yet.
+    // The tenant cannot be accessed anymore for any reason, but graceful shutdown.
+    //Stopping,
+}
+
+impl fmt::Display for TenantState {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        match self {
+            TenantState::CloudOnly => f.write_str("CloudOnly"),
+            TenantState::Downloading => f.write_str("Downloading"),
+            TenantState::Active => f.write_str("Active"),
+        }
+    }
+}
+
+fn access_tenants() -> MutexGuard<'static, HashMap<ZTenantId, Tenant>> {
+    TENANTS.lock().unwrap()
+}
+
 struct TenantHandleEntry {
     checkpointer_handle: Option<JoinHandle<()>>,
     gc_handle: Option<JoinHandle<()>>,
@@ -41,17 +75,25 @@ lazy_static! {
 static SHUTDOWN_REQUESTED: AtomicBool = AtomicBool::new(false);
 
 pub fn init(conf: &'static PageServerConf) {
-    let mut m = access_repository();
     for dir_entry in fs::read_dir(conf.tenants_path()).unwrap() {
         let tenantid =
             ZTenantId::from_str(dir_entry.unwrap().file_name().to_str().unwrap()).unwrap();
-        let repo = init_repo(conf, tenantid);
+
+        {
+            let mut m = access_tenants();
+            let tenant = Tenant {
+                state: TenantState::CloudOnly,
+                repo: None,
+            };
+            m.insert(tenantid, tenant);
+        }
+
+        init_repo(conf, tenantid);
         info!("initialized storage for tenant: {}", &tenantid);
-        m.insert(tenantid, repo);
     }
 }
 
-fn init_repo(conf: &'static PageServerConf, tenant_id: ZTenantId) -> Arc<LayeredRepository> {
+fn init_repo(conf: &'static PageServerConf, tenant_id: ZTenantId) {
     // Set up a WAL redo manager, for applying WAL records.
     let walredo_mgr = PostgresRedoManager::new(conf, tenant_id);
 
@@ -74,7 +116,10 @@ fn init_repo(conf: &'static PageServerConf, tenant_id: ZTenantId) -> Arc<Layered
 
     handles.insert(tenant_id, h);
 
-    repo
+    let mut m = access_tenants();
+    let tenant = m.get_mut(&tenant_id).unwrap();
+    tenant.repo = Some(repo);
+    tenant.state = TenantState::Active;
 }
 
 // TODO kb Currently unused function, will later be used when the relish storage downloads a new layer.
@@ -89,15 +134,23 @@ pub fn register_relish_download(
         tenant_id,
         timeline_id
     );
-    match access_repository().entry(tenant_id) {
-        Entry::Occupied(o) => init_timeline(o.get().as_ref(), timeline_id),
-        Entry::Vacant(v) => {
-            log::info!("New repo initialized");
-            let new_repo = init_repo(conf, tenant_id);
-            init_timeline(new_repo.as_ref(), timeline_id);
-            v.insert(new_repo);
+
+    {
+        let mut m = access_tenants();
+        let mut tenant = m.get_mut(&tenant_id).unwrap();
+        tenant.state = TenantState::Downloading;
+        match &tenant.repo {
+            Some(repo) => init_timeline(repo.as_ref(), timeline_id),
+            None => {
+                log::info!("Initialize new repo");
+            }
         }
     }
+
+    // init repo updates Tenant state
+    init_repo(conf, tenant_id);
+    let new_repo = get_repository_for_tenant(tenant_id).unwrap();
+    init_timeline(new_repo.as_ref(), timeline_id);
 }
 
 fn init_timeline(repo: &dyn Repository, timeline_id: ZTimelineId) {
@@ -125,8 +178,8 @@ pub fn stop_tenant_threads(tenantid: ZTenantId) {
 pub fn shutdown_all_tenants() -> Result<()> {
     SHUTDOWN_REQUESTED.swap(true, Ordering::Relaxed);
 
-    let tenants = list_tenants()?;
-    for tenantid in tenants {
+    let tenantids = list_tenantids()?;
+    for tenantid in tenantids {
         stop_tenant_threads(tenantid);
         let repo = get_repository_for_tenant(tenantid)?;
         debug!("shutdown tenant {}", tenantid);
@@ -140,25 +193,40 @@ pub fn create_repository_for_tenant(
     conf: &'static PageServerConf,
     tenantid: ZTenantId,
 ) -> Result<()> {
-    let mut m = access_repository();
-
-    // First check that the tenant doesn't exist already
-    if m.get(&tenantid).is_some() {
-        bail!("tenant {} already exists", tenantid);
+    {
+        let mut m = access_tenants();
+        // First check that the tenant doesn't exist already
+        if m.get(&tenantid).is_some() {
+            bail!("tenant {} already exists", tenantid);
+        }
+        let tenant = Tenant {
+            state: TenantState::CloudOnly,
+            repo: None,
+        };
+        m.insert(tenantid, tenant);
     }
+
     let wal_redo_manager = Arc::new(PostgresRedoManager::new(conf, tenantid));
     let repo = branches::create_repo(conf, tenantid, wal_redo_manager)?;
 
-    m.insert(tenantid, repo);
+    let mut m = access_tenants();
+    let tenant = m.get_mut(&tenantid).unwrap();
+    tenant.repo = Some(repo);
+    tenant.state = TenantState::Active;
 
     Ok(())
 }
 
 pub fn get_repository_for_tenant(tenantid: ZTenantId) -> Result<Arc<dyn Repository>> {
-    access_repository()
+    let m = access_tenants();
+    let tenant = m
         .get(&tenantid)
-        .map(Arc::clone)
-        .ok_or_else(|| anyhow!("repository not found for tenant name {}", tenantid))
+        .ok_or_else(|| anyhow!("Tenant not found for tenant {}", tenantid));
+
+    match &tenant.unwrap().repo {
+        Some(repo) => Ok(Arc::clone(repo)),
+        None => anyhow::bail!("Repository for tenant {} is not yet valid", tenantid),
+    }
 }
 
 pub fn get_timeline_for_tenant(
@@ -170,12 +238,11 @@ pub fn get_timeline_for_tenant(
         .with_context(|| format!("cannot fetch timeline {}", timelineid))
 }
 
-fn list_tenants() -> Result<Vec<ZTenantId>> {
-    let o = &mut REPOSITORY.lock().unwrap();
-
-    o.iter()
-        .map(|tenant| {
-            let (tenantid, _) = tenant;
+fn list_tenantids() -> Result<Vec<ZTenantId>> {
+    let m = access_tenants();
+    m.iter()
+        .map(|v| {
+            let (tenantid, _) = v;
             Ok(*tenantid)
         })
         .collect()

pageserver/src/waldecoder.rs

@@ -72,6 +72,10 @@ impl WalStreamDecoder {
     ///     Err(WalDecodeError): an error occured while decoding, meaning the input was invalid.
     ///
     pub fn poll_decode(&mut self) -> Result<Option<(Lsn, Bytes)>, WalDecodeError> {
+        let recordbuf;
+
+        // Run state machine that validates page headers, and reassembles records
+        // that cross page boundaries.
         loop {
             // parse and verify page boundaries as we go
             if self.lsn.segment_offset(pg_constants::WAL_SEGMENT_SIZE) == 0 {
@@ -120,29 +124,41 @@ impl WalStreamDecoder {
                 self.lsn += self.padlen as u64;
                 self.padlen = 0;
             } else if self.contlen == 0 {
-                // need to have at least the xl_tot_len field
+                assert!(self.recordbuf.is_empty());
 
+                // need to have at least the xl_tot_len field
                 if self.inputbuf.remaining() < 4 {
                     return Ok(None);
                 }
 
-                // read xl_tot_len FIXME: assumes little-endian
+                // peek xl_tot_len at the beginning of the record.
+                // FIXME: assumes little-endian
                 self.startlsn = self.lsn;
-                let xl_tot_len = self.inputbuf.get_u32_le();
+                let xl_tot_len = (&self.inputbuf[0..4]).get_u32_le();
                 if (xl_tot_len as usize) < XLOG_SIZE_OF_XLOG_RECORD {
                     return Err(WalDecodeError {
                         msg: format!("invalid xl_tot_len {}", xl_tot_len),
                         lsn: self.lsn,
                     });
                 }
-                self.lsn += 4;
 
-                self.recordbuf.clear();
-                self.recordbuf.reserve(xl_tot_len as usize);
-                self.recordbuf.put_u32_le(xl_tot_len);
-
-                self.contlen = xl_tot_len - 4;
-                continue;
+                // Fast path for the common case that the whole record fits on the page.
+                let pageleft = self.lsn.remaining_in_block() as u32;
+                if self.inputbuf.remaining() >= xl_tot_len as usize && xl_tot_len <= pageleft {
+                    // Take the record from the 'inputbuf', and validate it.
+                    recordbuf = self.inputbuf.copy_to_bytes(xl_tot_len as usize);
+                    self.lsn += xl_tot_len as u64;
+                    break;
+                } else {
+                    // Need to assemble the record from pieces. Remember the size of the
+                    // record, and loop back. On next iteration, we will reach the 'else'
+                    // branch below, and copy the part of the record that was on this page
+                    // to 'recordbuf'.  Subsequent iterations will skip page headers, and
+                    // append the continuations from the next pages to 'recordbuf'.
+                    self.recordbuf.reserve(xl_tot_len as usize);
+                    self.contlen = xl_tot_len;
+                    continue;
+                }
             } else {
                 // we're continuing a record, possibly from previous page.
                 let pageleft = self.lsn.remaining_in_block() as u32;
@@ -159,47 +175,42 @@ impl WalStreamDecoder {
                 self.contlen -= n as u32;
 
                 if self.contlen == 0 {
-                    let recordbuf = std::mem::replace(&mut self.recordbuf, BytesMut::new());
-
-                    let recordbuf = recordbuf.freeze();
-                    let mut buf = recordbuf.clone();
-
-                    let xlogrec = XLogRecord::from_bytes(&mut buf);
-
-                    // XLOG_SWITCH records are special. If we see one, we need to skip
-                    // to the next WAL segment.
-                    if xlogrec.is_xlog_switch_record() {
-                        trace!("saw xlog switch record at {}", self.lsn);
-                        self.padlen =
-                            self.lsn.calc_padding(pg_constants::WAL_SEGMENT_SIZE as u64) as u32;
-                    } else {
-                        // Pad to an 8-byte boundary
-                        self.padlen = self.lsn.calc_padding(8u32) as u32;
-                    }
-
-                    let mut crc = crc32c_append(0, &recordbuf[XLOG_RECORD_CRC_OFFS + 4..]);
-                    crc = crc32c_append(crc, &recordbuf[0..XLOG_RECORD_CRC_OFFS]);
-                    if crc != xlogrec.xl_crc {
-                        return Err(WalDecodeError {
-                            msg: "WAL record crc mismatch".into(),
-                            lsn: self.lsn,
-                        });
-                    }
-
-                    // Always align resulting LSN on 0x8 boundary -- that is important for getPage()
-                    // and WalReceiver integration. Since this code is used both for WalReceiver and
-                    // initial WAL import let's force alignment right here.
-                    let result = (self.lsn.align(), recordbuf);
-                    return Ok(Some(result));
+                    // The record is now complete.
+                    recordbuf = std::mem::replace(&mut self.recordbuf, BytesMut::new()).freeze();
+                    break;
                 }
                 continue;
             }
         }
-        // check record boundaries
 
-        // deal with continuation records
+        // We now have a record in the 'recordbuf' local variable.
+        let xlogrec = XLogRecord::from_slice(&recordbuf[0..XLOG_SIZE_OF_XLOG_RECORD]);
 
-        // deal with xlog_switch records
+        let mut crc = 0;
+        crc = crc32c_append(crc, &recordbuf[XLOG_RECORD_CRC_OFFS + 4..]);
+        crc = crc32c_append(crc, &recordbuf[0..XLOG_RECORD_CRC_OFFS]);
+        if crc != xlogrec.xl_crc {
+            return Err(WalDecodeError {
+                msg: "WAL record crc mismatch".into(),
+                lsn: self.lsn,
+            });
+        }
+
+        // XLOG_SWITCH records are special. If we see one, we need to skip
+        // to the next WAL segment.
+        if xlogrec.is_xlog_switch_record() {
+            trace!("saw xlog switch record at {}", self.lsn);
+            self.padlen = self.lsn.calc_padding(pg_constants::WAL_SEGMENT_SIZE as u64) as u32;
+        } else {
+            // Pad to an 8-byte boundary
+            self.padlen = self.lsn.calc_padding(8u32) as u32;
+        }
+
+        // Always align resulting LSN on 0x8 boundary -- that is important for getPage()
+        // and WalReceiver integration. Since this code is used both for WalReceiver and
+        // initial WAL import let's force alignment right here.
+        let result = (self.lsn.align(), recordbuf);
+        Ok(Some(result))
     }
 }
 

pageserver/src/walredo.rs

@@ -82,7 +82,7 @@ pub trait WalRedoManager: Send + Sync {
         blknum: u32,
         lsn: Lsn,
         base_img: Option<Bytes>,
-        records: Vec<WALRecord>,
+        records: Vec<(Lsn, WALRecord)>,
     ) -> Result<Bytes, WalRedoError>;
 }
 
@@ -99,7 +99,7 @@ impl crate::walredo::WalRedoManager for DummyRedoManager {
         _blknum: u32,
         _lsn: Lsn,
         _base_img: Option<Bytes>,
-        _records: Vec<WALRecord>,
+        _records: Vec<(Lsn, WALRecord)>,
     ) -> Result<Bytes, WalRedoError> {
         Err(WalRedoError::InvalidState)
     }
@@ -150,7 +150,7 @@ struct WalRedoRequest {
     lsn: Lsn,
 
     base_img: Option<Bytes>,
-    records: Vec<WALRecord>,
+    records: Vec<(Lsn, WALRecord)>,
 }
 
 /// An error happened in WAL redo
@@ -179,7 +179,7 @@ impl WalRedoManager for PostgresRedoManager {
         blknum: u32,
         lsn: Lsn,
         base_img: Option<Bytes>,
-        records: Vec<WALRecord>,
+        records: Vec<(Lsn, WALRecord)>,
     ) -> Result<Bytes, WalRedoError> {
         let start_time;
         let lock_time;
@@ -277,7 +277,7 @@ impl PostgresRedoManager {
                 page.extend_from_slice(&ZERO_PAGE);
             }
             // Apply all collected WAL records
-            for record in records {
+            for (_lsn, record) in records {
                 let mut buf = record.rec.clone();
 
                 WAL_REDO_RECORD_COUNTER.inc();
@@ -544,7 +544,7 @@ impl PostgresRedoProcess {
         &mut self,
         tag: BufferTag,
         base_img: Option<Bytes>,
-        records: &[WALRecord],
+        records: &[(Lsn, WALRecord)],
     ) -> Result<Bytes, std::io::Error> {
         let stdout = &mut self.stdout;
         // Buffer the writes to avoid a lot of small syscalls.
@@ -570,11 +570,11 @@ impl PostgresRedoProcess {
             }
 
             // Send WAL records.
-            for rec in records.iter() {
+            for (lsn, rec) in records.iter() {
                 WAL_REDO_RECORD_COUNTER.inc();
 
                 stdin
-                    .write_all(&build_apply_record_msg(rec.lsn, &rec.rec))
+                    .write_all(&build_apply_record_msg(*lsn, &rec.rec))
                     .await?;
 
                 //debug!("sent WAL record to wal redo postgres process ({:X}/{:X}",

postgres_ffi/src/xlog_utils.rs

@@ -9,7 +9,6 @@
 
 use crate::pg_constants;
 use crate::CheckPoint;
-use crate::ControlFileData;
 use crate::FullTransactionId;
 use crate::XLogLongPageHeaderData;
 use crate::XLogPageHeaderData;
@@ -18,8 +17,8 @@ use crate::XLOG_PAGE_MAGIC;
 
 use anyhow::{bail, Result};
 use byteorder::{ByteOrder, LittleEndian};
+use bytes::BytesMut;
 use bytes::{Buf, Bytes};
-use bytes::{BufMut, BytesMut};
 use crc32c::*;
 use log::*;
 use std::cmp::max;
@@ -329,7 +328,12 @@ pub fn main() {
 }
 
 impl XLogRecord {
-    pub fn from_bytes(buf: &mut Bytes) -> XLogRecord {
+    pub fn from_slice(buf: &[u8]) -> XLogRecord {
+        use zenith_utils::bin_ser::LeSer;
+        XLogRecord::des(buf).unwrap()
+    }
+
+    pub fn from_bytes<B: Buf>(buf: &mut B) -> XLogRecord {
         use zenith_utils::bin_ser::LeSer;
         XLogRecord::des_from(&mut buf.reader()).unwrap()
     }
@@ -405,27 +409,25 @@ impl CheckPoint {
 }
 
 //
-// Generate new WAL segment with single XLOG_CHECKPOINT_SHUTDOWN record.
+// Generate new, empty WAL segment.
 // We need this segment to start compute node.
-// In order to minimize changes in Postgres core, we prefer to
-// provide WAL segment from which is can extract checkpoint record in standard way,
-// rather then implement some alternative mechanism.
 //
-pub fn generate_wal_segment(pg_control: &ControlFileData) -> Bytes {
+pub fn generate_wal_segment(segno: u64, system_id: u64) -> Bytes {
     let mut seg_buf = BytesMut::with_capacity(pg_constants::WAL_SEGMENT_SIZE as usize);
 
+    let pageaddr = XLogSegNoOffsetToRecPtr(segno, 0, pg_constants::WAL_SEGMENT_SIZE);
     let hdr = XLogLongPageHeaderData {
         std: {
             XLogPageHeaderData {
                 xlp_magic: XLOG_PAGE_MAGIC as u16,
                 xlp_info: pg_constants::XLP_LONG_HEADER,
                 xlp_tli: 1, // FIXME: always use Postgres timeline 1
-                xlp_pageaddr: pg_control.checkPoint - XLOG_SIZE_OF_XLOG_LONG_PHD as u64,
+                xlp_pageaddr: pageaddr,
                 xlp_rem_len: 0,
                 ..Default::default() // Put 0 in padding fields.
             }
         },
-        xlp_sysid: pg_control.system_identifier,
+        xlp_sysid: system_id,
         xlp_seg_size: pg_constants::WAL_SEGMENT_SIZE as u32,
         xlp_xlog_blcksz: XLOG_BLCKSZ as u32,
     };
@@ -433,36 +435,6 @@ pub fn generate_wal_segment(pg_control: &ControlFileData) -> Bytes {
     let hdr_bytes = hdr.encode();
     seg_buf.extend_from_slice(&hdr_bytes);
 
-    let rec_hdr = XLogRecord {
-        xl_tot_len: (XLOG_SIZE_OF_XLOG_RECORD
-            + SIZE_OF_XLOG_RECORD_DATA_HEADER_SHORT
-            + SIZEOF_CHECKPOINT) as u32,
-        xl_xid: 0, //0 is for InvalidTransactionId
-        xl_prev: 0,
-        xl_info: pg_constants::XLOG_CHECKPOINT_SHUTDOWN,
-        xl_rmid: pg_constants::RM_XLOG_ID,
-        xl_crc: 0,
-        ..Default::default() // Put 0 in padding fields.
-    };
-
-    let mut rec_shord_hdr_bytes = BytesMut::new();
-    rec_shord_hdr_bytes.put_u8(pg_constants::XLR_BLOCK_ID_DATA_SHORT);
-    rec_shord_hdr_bytes.put_u8(SIZEOF_CHECKPOINT as u8);
-
-    let rec_bytes = rec_hdr.encode();
-    let checkpoint_bytes = pg_control.checkPointCopy.encode();
-
-    //calculate record checksum
-    let mut crc = 0;
-    crc = crc32c_append(crc, &rec_shord_hdr_bytes[..]);
-    crc = crc32c_append(crc, &checkpoint_bytes[..]);
-    crc = crc32c_append(crc, &rec_bytes[0..XLOG_RECORD_CRC_OFFS]);
-
-    seg_buf.extend_from_slice(&rec_bytes[0..XLOG_RECORD_CRC_OFFS]);
-    seg_buf.put_u32_le(crc);
-    seg_buf.extend_from_slice(&rec_shord_hdr_bytes);
-    seg_buf.extend_from_slice(&checkpoint_bytes);
-
     //zero out the rest of the file
     seg_buf.resize(pg_constants::WAL_SEGMENT_SIZE, 0);
     seg_buf.freeze()

proxy/src/cplane_api.rs

@@ -12,7 +12,7 @@ pub struct DatabaseInfo {
     pub port: u16,
     pub dbname: String,
     pub user: String,
-    pub password: String,
+    pub password: Option<String>,
 }
 
 impl DatabaseInfo {
@@ -24,12 +24,23 @@ impl DatabaseInfo {
             .next()
             .ok_or_else(|| anyhow::Error::msg("cannot resolve at least one SocketAddr"))
     }
+}
 
-    pub fn conn_string(&self) -> String {
-        format!(
-            "dbname={} user={} password={}",
-            self.dbname, self.user, self.password
-        )
+impl From<DatabaseInfo> for tokio_postgres::Config {
+    fn from(db_info: DatabaseInfo) -> Self {
+        let mut config = tokio_postgres::Config::new();
+
+        config
+            .host(&db_info.host)
+            .port(db_info.port)
+            .dbname(&db_info.dbname)
+            .user(&db_info.user);
+
+        if let Some(password) = db_info.password {
+            config.password(password);
+        }
+
+        config
     }
 }
 

proxy/src/main.rs

@@ -145,18 +145,18 @@ fn main() -> anyhow::Result<()> {
     println!("Starting mgmt on {}", state.conf.mgmt_address);
     let mgmt_listener = TcpListener::bind(state.conf.mgmt_address)?;
 
-    let threads = vec![
+    let threads = [
         // Spawn a thread to listen for connections. It will spawn further threads
         // for each connection.
         thread::Builder::new()
-            .name("Proxy thread".into())
+            .name("Listener thread".into())
             .spawn(move || proxy::thread_main(state, pageserver_listener))?,
         thread::Builder::new()
             .name("Mgmt thread".into())
             .spawn(move || mgmt::thread_main(state, mgmt_listener))?,
     ];
 
-    for t in threads.into_iter() {
+    for t in threads {
         t.join().unwrap()?;
     }
 

proxy/src/proxy.rs

@@ -6,7 +6,6 @@ use anyhow::bail;
 use tokio_postgres::NoTls;
 
 use rand::Rng;
-use std::io::Write;
 use std::{io, sync::mpsc::channel, thread};
 use zenith_utils::postgres_backend::Stream;
 use zenith_utils::postgres_backend::{PostgresBackend, ProtoState};
@@ -28,11 +27,13 @@ pub fn thread_main(
         println!("accepted connection from {}", peer_addr);
         socket.set_nodelay(true).unwrap();
 
-        thread::spawn(move || {
-            if let Err(err) = proxy_conn_main(state, socket) {
-                println!("error: {}", err);
-            }
-        });
+        thread::Builder::new()
+            .name("Proxy thread".into())
+            .spawn(move || {
+                if let Err(err) = proxy_conn_main(state, socket) {
+                    println!("error: {}", err);
+                }
+            })?;
     }
 }
 
@@ -158,6 +159,7 @@ impl ProxyConnection {
     fn handle_existing_user(&mut self) -> anyhow::Result<DatabaseInfo> {
         // ask password
         rand::thread_rng().fill(&mut self.md5_salt);
+
         self.pgb
             .write_message(&BeMessage::AuthenticationMD5Password(&self.md5_salt))?;
         self.pgb.state = ProtoState::Authentication; // XXX
@@ -250,51 +252,68 @@ databases without opening the browser.
 /// Create a TCP connection to a postgres database, authenticate with it, and receive the ReadyForQuery message
 async fn connect_to_db(db_info: DatabaseInfo) -> anyhow::Result<tokio::net::TcpStream> {
     let mut socket = tokio::net::TcpStream::connect(db_info.socket_addr()?).await?;
-    let config = db_info.conn_string().parse::<tokio_postgres::Config>()?;
+    let config = tokio_postgres::Config::from(db_info);
     let _ = config.connect_raw(&mut socket, NoTls).await?;
     Ok(socket)
 }
 
 /// Concurrently proxy both directions of the client and server connections
 fn proxy(
-    client_read: ReadStream,
-    client_write: WriteStream,
-    server_read: ReadStream,
-    server_write: WriteStream,
+    (client_read, client_write): (ReadStream, WriteStream),
+    (server_read, server_write): (ReadStream, WriteStream),
 ) -> anyhow::Result<()> {
-    fn do_proxy(mut reader: ReadStream, mut writer: WriteStream) -> io::Result<()> {
-        std::io::copy(&mut reader, &mut writer)?;
-        writer.flush()?;
-        writer.shutdown(std::net::Shutdown::Both)
+    fn do_proxy(mut reader: impl io::Read, mut writer: WriteStream) -> io::Result<u64> {
+        /// FlushWriter will make sure that every message is sent as soon as possible
+        struct FlushWriter<W>(W);
+
+        impl<W: io::Write> io::Write for FlushWriter<W> {
+            fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
+                // `std::io::copy` is guaranteed to exit if we return an error,
+                // so we can afford to lose `res` in case `flush` fails
+                let res = self.0.write(buf);
+                if res.is_ok() {
+                    self.0.flush()?;
+                }
+                res
+            }
+
+            fn flush(&mut self) -> io::Result<()> {
+                self.0.flush()
+            }
+        }
+
+        let res = std::io::copy(&mut reader, &mut FlushWriter(&mut writer));
+        writer.shutdown(std::net::Shutdown::Both)?;
+        res
     }
 
     let client_to_server_jh = thread::spawn(move || do_proxy(client_read, server_write));
 
-    let res1 = do_proxy(server_read, client_write);
-    let res2 = client_to_server_jh.join().unwrap();
-    res1?;
-    res2?;
+    do_proxy(server_read, client_write)?;
+    client_to_server_jh.join().unwrap()?;
 
     Ok(())
 }
 
 /// Proxy a client connection to a postgres database
 fn proxy_pass(pgb: PostgresBackend, db_info: DatabaseInfo) -> anyhow::Result<()> {
-    let runtime = tokio::runtime::Builder::new_current_thread()
-        .enable_all()
-        .build()?;
-    let db_stream = runtime.block_on(connect_to_db(db_info))?;
-    let db_stream = db_stream.into_std()?;
-    db_stream.set_nonblocking(false)?;
+    let db_stream = {
+        // We'll get rid of this once migration to async is complete
+        let runtime = tokio::runtime::Builder::new_current_thread()
+            .enable_all()
+            .build()?;
 
-    let db_stream = zenith_utils::sock_split::BidiStream::from_tcp(db_stream);
-    let (db_read, db_write) = db_stream.split();
+        let stream = runtime.block_on(connect_to_db(db_info))?.into_std()?;
+        stream.set_nonblocking(false)?;
+        stream
+    };
 
-    let stream = match pgb.into_stream() {
+    let db = zenith_utils::sock_split::BidiStream::from_tcp(db_stream);
+
+    let client = match pgb.into_stream() {
         Stream::Bidirectional(bidi_stream) => bidi_stream,
         _ => bail!("invalid stream"),
     };
 
-    let (client_read, client_write) = stream.split();
-    proxy(client_read, client_write, db_read, db_write)
+    proxy(client.split(), db.split())
 }

test_runner/Pipfile

@@ -11,11 +11,14 @@ pyjwt = {extras = ["crypto"], version = "*"}
 requests = "*"
 pytest-xdist = "*"
 asyncpg = "*"
+cached-property = "*"
 
 [dev-packages]
-yapf = "*"
 flake8 = "*"
 mypy = "*"
+# Behavior may change slightly between versions. These are run continuously,
+# so we pin exact versions to avoid suprising breaks. Update if comfortable.
+yapf = "==0.31.0"
 
 [requires]
 # we need at least 3.6, but pipenv doesn't allow to say this directly

test_runner/Pipfile.lock

@@ -1,7 +1,7 @@
 {
     "_meta": {
         "hash": {
-            "sha256": "3cdc048691824d0b93912b6b78a0aa01dc98f278212c1badb0cc2edbd2103c3a"
+            "sha256": "3645ae8d2dcf55bd2a54963c44cfeedf577f3b289d1077365214a80a7f36e643"
         },
         "pipfile-spec": 6,
         "requires": {
@@ -43,94 +43,108 @@
             "markers": "python_version >= '2.7' and python_version not in '3.0, 3.1, 3.2, 3.3, 3.4'",
             "version": "==21.2.0"
         },
+        "cached-property": {
+            "hashes": [
+                "sha256:9fa5755838eecbb2d234c3aa390bd80fbd3ac6b6869109bfc1b499f7bd89a130",
+                "sha256:df4f613cf7ad9a588cc381aaf4a512d26265ecebd5eb9e1ba12f1319eb85a6a0"
+            ],
+            "index": "pypi",
+            "version": "==1.5.2"
+        },
         "certifi": {
             "hashes": [
-                "sha256:2bbf76fd432960138b3ef6dda3dde0544f27cbf8546c458e60baf371917ba9ee",
-                "sha256:50b1e4f8446b06f41be7dd6338db18e0990601dce795c2b1686458aa7e8fa7d8"
+                "sha256:78884e7c1d4b00ce3cea67b44566851c4343c120abd683433ce934a68ea58872",
+                "sha256:d62a0163eb4c2344ac042ab2bdf75399a71a2d8c7d47eac2e2ee91b9d6339569"
             ],
-            "version": "==2021.5.30"
+            "version": "==2021.10.8"
         },
         "cffi": {
             "hashes": [
-                "sha256:06c54a68935738d206570b20da5ef2b6b6d92b38ef3ec45c5422c0ebaf338d4d",
-                "sha256:0c0591bee64e438883b0c92a7bed78f6290d40bf02e54c5bf0978eaf36061771",
-                "sha256:19ca0dbdeda3b2615421d54bef8985f72af6e0c47082a8d26122adac81a95872",
-                "sha256:22b9c3c320171c108e903d61a3723b51e37aaa8c81255b5e7ce102775bd01e2c",
-                "sha256:26bb2549b72708c833f5abe62b756176022a7b9a7f689b571e74c8478ead51dc",
-                "sha256:33791e8a2dc2953f28b8d8d300dde42dd929ac28f974c4b4c6272cb2955cb762",
-                "sha256:3c8d896becff2fa653dc4438b54a5a25a971d1f4110b32bd3068db3722c80202",
-                "sha256:4373612d59c404baeb7cbd788a18b2b2a8331abcc84c3ba40051fcd18b17a4d5",
-                "sha256:487d63e1454627c8e47dd230025780e91869cfba4c753a74fda196a1f6ad6548",
-                "sha256:48916e459c54c4a70e52745639f1db524542140433599e13911b2f329834276a",
-                "sha256:4922cd707b25e623b902c86188aca466d3620892db76c0bdd7b99a3d5e61d35f",
-                "sha256:55af55e32ae468e9946f741a5d51f9896da6b9bf0bbdd326843fec05c730eb20",
-                "sha256:57e555a9feb4a8460415f1aac331a2dc833b1115284f7ded7278b54afc5bd218",
-                "sha256:5d4b68e216fc65e9fe4f524c177b54964af043dde734807586cf5435af84045c",
-                "sha256:64fda793737bc4037521d4899be780534b9aea552eb673b9833b01f945904c2e",
-                "sha256:6d6169cb3c6c2ad50db5b868db6491a790300ade1ed5d1da29289d73bbe40b56",
-                "sha256:7bcac9a2b4fdbed2c16fa5681356d7121ecabf041f18d97ed5b8e0dd38a80224",
-                "sha256:80b06212075346b5546b0417b9f2bf467fea3bfe7352f781ffc05a8ab24ba14a",
-                "sha256:818014c754cd3dba7229c0f5884396264d51ffb87ec86e927ef0be140bfdb0d2",
-                "sha256:8eb687582ed7cd8c4bdbff3df6c0da443eb89c3c72e6e5dcdd9c81729712791a",
-                "sha256:99f27fefe34c37ba9875f224a8f36e31d744d8083e00f520f133cab79ad5e819",
-                "sha256:9f3e33c28cd39d1b655ed1ba7247133b6f7fc16fa16887b120c0c670e35ce346",
-                "sha256:a8661b2ce9694ca01c529bfa204dbb144b275a31685a075ce123f12331be790b",
-                "sha256:a9da7010cec5a12193d1af9872a00888f396aba3dc79186604a09ea3ee7c029e",
-                "sha256:aedb15f0a5a5949ecb129a82b72b19df97bbbca024081ed2ef88bd5c0a610534",
-                "sha256:b315d709717a99f4b27b59b021e6207c64620790ca3e0bde636a6c7f14618abb",
-                "sha256:ba6f2b3f452e150945d58f4badd92310449876c4c954836cfb1803bdd7b422f0",
-                "sha256:c33d18eb6e6bc36f09d793c0dc58b0211fccc6ae5149b808da4a62660678b156",
-                "sha256:c9a875ce9d7fe32887784274dd533c57909b7b1dcadcc128a2ac21331a9765dd",
-                "sha256:c9e005e9bd57bc987764c32a1bee4364c44fdc11a3cc20a40b93b444984f2b87",
-                "sha256:d2ad4d668a5c0645d281dcd17aff2be3212bc109b33814bbb15c4939f44181cc",
-                "sha256:d950695ae4381ecd856bcaf2b1e866720e4ab9a1498cba61c602e56630ca7195",
-                "sha256:e22dcb48709fc51a7b58a927391b23ab37eb3737a98ac4338e2448bef8559b33",
-                "sha256:e8c6a99be100371dbb046880e7a282152aa5d6127ae01783e37662ef73850d8f",
-                "sha256:e9dc245e3ac69c92ee4c167fbdd7428ec1956d4e754223124991ef29eb57a09d",
-                "sha256:eb687a11f0a7a1839719edd80f41e459cc5366857ecbed383ff376c4e3cc6afd",
-                "sha256:eb9e2a346c5238a30a746893f23a9535e700f8192a68c07c0258e7ece6ff3728",
-                "sha256:ed38b924ce794e505647f7c331b22a693bee1538fdf46b0222c4717b42f744e7",
-                "sha256:f0010c6f9d1a4011e429109fda55a225921e3206e7f62a0c22a35344bfd13cca",
-                "sha256:f0c5d1acbfca6ebdd6b1e3eded8d261affb6ddcf2186205518f1428b8569bb99",
-                "sha256:f10afb1004f102c7868ebfe91c28f4a712227fe4cb24974350ace1f90e1febbf",
-                "sha256:f174135f5609428cc6e1b9090f9268f5c8935fddb1b25ccb8255a2d50de6789e",
-                "sha256:f3ebe6e73c319340830a9b2825d32eb6d8475c1dac020b4f0aa774ee3b898d1c",
-                "sha256:f627688813d0a4140153ff532537fbe4afea5a3dffce1f9deb7f91f848a832b5",
-                "sha256:fd4305f86f53dfd8cd3522269ed7fc34856a8ee3709a5e28b2836b2db9d4cd69"
+                "sha256:00c878c90cb53ccfaae6b8bc18ad05d2036553e6d9d1d9dbcf323bbe83854ca3",
+                "sha256:0104fb5ae2391d46a4cb082abdd5c69ea4eab79d8d44eaaf79f1b1fd806ee4c2",
+                "sha256:06c48159c1abed75c2e721b1715c379fa3200c7784271b3c46df01383b593636",
+                "sha256:0808014eb713677ec1292301ea4c81ad277b6cdf2fdd90fd540af98c0b101d20",
+                "sha256:10dffb601ccfb65262a27233ac273d552ddc4d8ae1bf93b21c94b8511bffe728",
+                "sha256:14cd121ea63ecdae71efa69c15c5543a4b5fbcd0bbe2aad864baca0063cecf27",
+                "sha256:17771976e82e9f94976180f76468546834d22a7cc404b17c22df2a2c81db0c66",
+                "sha256:181dee03b1170ff1969489acf1c26533710231c58f95534e3edac87fff06c443",
+                "sha256:23cfe892bd5dd8941608f93348c0737e369e51c100d03718f108bf1add7bd6d0",
+                "sha256:263cc3d821c4ab2213cbe8cd8b355a7f72a8324577dc865ef98487c1aeee2bc7",
+                "sha256:2756c88cbb94231c7a147402476be2c4df2f6078099a6f4a480d239a8817ae39",
+                "sha256:27c219baf94952ae9d50ec19651a687b826792055353d07648a5695413e0c605",
+                "sha256:2a23af14f408d53d5e6cd4e3d9a24ff9e05906ad574822a10563efcef137979a",
+                "sha256:31fb708d9d7c3f49a60f04cf5b119aeefe5644daba1cd2a0fe389b674fd1de37",
+                "sha256:3415c89f9204ee60cd09b235810be700e993e343a408693e80ce7f6a40108029",
+                "sha256:3773c4d81e6e818df2efbc7dd77325ca0dcb688116050fb2b3011218eda36139",
+                "sha256:3b96a311ac60a3f6be21d2572e46ce67f09abcf4d09344c49274eb9e0bf345fc",
+                "sha256:3f7d084648d77af029acb79a0ff49a0ad7e9d09057a9bf46596dac9514dc07df",
+                "sha256:41d45de54cd277a7878919867c0f08b0cf817605e4eb94093e7516505d3c8d14",
+                "sha256:4238e6dab5d6a8ba812de994bbb0a79bddbdf80994e4ce802b6f6f3142fcc880",
+                "sha256:45db3a33139e9c8f7c09234b5784a5e33d31fd6907800b316decad50af323ff2",
+                "sha256:45e8636704eacc432a206ac7345a5d3d2c62d95a507ec70d62f23cd91770482a",
+                "sha256:4958391dbd6249d7ad855b9ca88fae690783a6be9e86df65865058ed81fc860e",
+                "sha256:4a306fa632e8f0928956a41fa8e1d6243c71e7eb59ffbd165fc0b41e316b2474",
+                "sha256:57e9ac9ccc3101fac9d6014fba037473e4358ef4e89f8e181f8951a2c0162024",
+                "sha256:59888172256cac5629e60e72e86598027aca6bf01fa2465bdb676d37636573e8",
+                "sha256:5e069f72d497312b24fcc02073d70cb989045d1c91cbd53979366077959933e0",
+                "sha256:64d4ec9f448dfe041705426000cc13e34e6e5bb13736e9fd62e34a0b0c41566e",
+                "sha256:6dc2737a3674b3e344847c8686cf29e500584ccad76204efea14f451d4cc669a",
+                "sha256:74fdfdbfdc48d3f47148976f49fab3251e550a8720bebc99bf1483f5bfb5db3e",
+                "sha256:75e4024375654472cc27e91cbe9eaa08567f7fbdf822638be2814ce059f58032",
+                "sha256:786902fb9ba7433aae840e0ed609f45c7bcd4e225ebb9c753aa39725bb3e6ad6",
+                "sha256:8b6c2ea03845c9f501ed1313e78de148cd3f6cad741a75d43a29b43da27f2e1e",
+                "sha256:91d77d2a782be4274da750752bb1650a97bfd8f291022b379bb8e01c66b4e96b",
+                "sha256:91ec59c33514b7c7559a6acda53bbfe1b283949c34fe7440bcf917f96ac0723e",
+                "sha256:920f0d66a896c2d99f0adbb391f990a84091179542c205fa53ce5787aff87954",
+                "sha256:a5263e363c27b653a90078143adb3d076c1a748ec9ecc78ea2fb916f9b861962",
+                "sha256:abb9a20a72ac4e0fdb50dae135ba5e77880518e742077ced47eb1499e29a443c",
+                "sha256:c2051981a968d7de9dd2d7b87bcb9c939c74a34626a6e2f8181455dd49ed69e4",
+                "sha256:c21c9e3896c23007803a875460fb786118f0cdd4434359577ea25eb556e34c55",
+                "sha256:c2502a1a03b6312837279c8c1bd3ebedf6c12c4228ddbad40912d671ccc8a962",
+                "sha256:d4d692a89c5cf08a8557fdeb329b82e7bf609aadfaed6c0d79f5a449a3c7c023",
+                "sha256:da5db4e883f1ce37f55c667e5c0de439df76ac4cb55964655906306918e7363c",
+                "sha256:e7022a66d9b55e93e1a845d8c9eba2a1bebd4966cd8bfc25d9cd07d515b33fa6",
+                "sha256:ef1f279350da2c586a69d32fc8733092fd32cc8ac95139a00377841f59a3f8d8",
+                "sha256:f54a64f8b0c8ff0b64d18aa76675262e1700f3995182267998c31ae974fbc382",
+                "sha256:f5c7150ad32ba43a07c4479f40241756145a1f03b43480e058cfd862bf5041c7",
+                "sha256:f6f824dc3bce0edab5f427efcfb1d63ee75b6fcb7282900ccaf925be84efb0fc",
+                "sha256:fd8a250edc26254fe5b33be00402e6d287f562b6a5b2152dec302fa15bb3e997",
+                "sha256:ffaa5c925128e29efbde7301d8ecaf35c8c60ffbcd6a1ffd3a552177c8e5e796"
             ],
-            "version": "==1.14.6"
+            "version": "==1.15.0"
         },
         "charset-normalizer": {
             "hashes": [
-                "sha256:5d209c0a931f215cee683b6445e2d77677e7e75e159f78def0db09d68fafcaa6",
-                "sha256:5ec46d183433dcbd0ab716f2d7f29d8dee50505b3fdb40c6b985c7c4f5a3591f"
+                "sha256:e019de665e2bcf9c2b64e2e5aa025fa991da8720daa3c1138cadd2fd1856aed0",
+                "sha256:f7af805c321bfa1ce6714c51f254e0d5bb5e5834039bc17db7ebe3a4cec9492b"
             ],
             "markers": "python_version >= '3'",
-            "version": "==2.0.6"
+            "version": "==2.0.7"
         },
         "cryptography": {
             "hashes": [
-                "sha256:0a7dcbcd3f1913f664aca35d47c1331fce738d44ec34b7be8b9d332151b0b01e",
-                "sha256:1eb7bb0df6f6f583dd8e054689def236255161ebbcf62b226454ab9ec663746b",
-                "sha256:21ca464b3a4b8d8e86ba0ee5045e103a1fcfac3b39319727bc0fc58c09c6aff7",
-                "sha256:34dae04a0dce5730d8eb7894eab617d8a70d0c97da76b905de9efb7128ad7085",
-                "sha256:3520667fda779eb788ea00080124875be18f2d8f0848ec00733c0ec3bb8219fc",
-                "sha256:3c4129fc3fdc0fa8e40861b5ac0c673315b3c902bbdc05fc176764815b43dd1d",
-                "sha256:3fa3a7ccf96e826affdf1a0a9432be74dc73423125c8f96a909e3835a5ef194a",
-                "sha256:5b0fbfae7ff7febdb74b574055c7466da334a5371f253732d7e2e7525d570498",
-                "sha256:695104a9223a7239d155d7627ad912953b540929ef97ae0c34c7b8bf30857e89",
-                "sha256:8695456444f277af73a4877db9fc979849cd3ee74c198d04fc0776ebc3db52b9",
-                "sha256:94cc5ed4ceaefcbe5bf38c8fba6a21fc1d365bb8fb826ea1688e3370b2e24a1c",
-                "sha256:94fff993ee9bc1b2440d3b7243d488c6a3d9724cc2b09cdb297f6a886d040ef7",
-                "sha256:9965c46c674ba8cc572bc09a03f4c649292ee73e1b683adb1ce81e82e9a6a0fb",
-                "sha256:a00cf305f07b26c351d8d4e1af84ad7501eca8a342dedf24a7acb0e7b7406e14",
-                "sha256:a305600e7a6b7b855cd798e00278161b681ad6e9b7eca94c721d5f588ab212af",
-                "sha256:cd65b60cfe004790c795cc35f272e41a3df4631e2fb6b35aa7ac6ef2859d554e",
-                "sha256:d2a6e5ef66503da51d2110edf6c403dc6b494cc0082f85db12f54e9c5d4c3ec5",
-                "sha256:d9ec0e67a14f9d1d48dd87a2531009a9b251c02ea42851c060b25c782516ff06",
-                "sha256:f44d141b8c4ea5eb4dbc9b3ad992d45580c1d22bf5e24363f2fbf50c2d7ae8a7"
+                "sha256:07bb7fbfb5de0980590ddfc7f13081520def06dc9ed214000ad4372fb4e3c7f6",
+                "sha256:18d90f4711bf63e2fb21e8c8e51ed8189438e6b35a6d996201ebd98a26abbbe6",
+                "sha256:1ed82abf16df40a60942a8c211251ae72858b25b7421ce2497c2eb7a1cee817c",
+                "sha256:22a38e96118a4ce3b97509443feace1d1011d0571fae81fc3ad35f25ba3ea999",
+                "sha256:2d69645f535f4b2c722cfb07a8eab916265545b3475fdb34e0be2f4ee8b0b15e",
+                "sha256:4a2d0e0acc20ede0f06ef7aa58546eee96d2592c00f450c9acb89c5879b61992",
+                "sha256:54b2605e5475944e2213258e0ab8696f4f357a31371e538ef21e8d61c843c28d",
+                "sha256:7075b304cd567694dc692ffc9747f3e9cb393cc4aa4fb7b9f3abd6f5c4e43588",
+                "sha256:7b7ceeff114c31f285528ba8b390d3e9cfa2da17b56f11d366769a807f17cbaa",
+                "sha256:7eba2cebca600a7806b893cb1d541a6e910afa87e97acf2021a22b32da1df52d",
+                "sha256:928185a6d1ccdb816e883f56ebe92e975a262d31cc536429041921f8cb5a62fd",
+                "sha256:9933f28f70d0517686bd7de36166dda42094eac49415459d9bdf5e7df3e0086d",
+                "sha256:a688ebcd08250eab5bb5bca318cc05a8c66de5e4171a65ca51db6bd753ff8953",
+                "sha256:abb5a361d2585bb95012a19ed9b2c8f412c5d723a9836418fab7aaa0243e67d2",
+                "sha256:c10c797ac89c746e488d2ee92bd4abd593615694ee17b2500578b63cad6b93a8",
+                "sha256:ced40344e811d6abba00295ced98c01aecf0c2de39481792d87af4fa58b7b4d6",
+                "sha256:d57e0cdc1b44b6cdf8af1d01807db06886f10177469312fbde8f44ccbb284bc9",
+                "sha256:d99915d6ab265c22873f1b4d6ea5ef462ef797b4140be4c9d8b179915e0985c6",
+                "sha256:eb80e8a1f91e4b7ef8b33041591e6d89b2b8e122d787e87eeb2b08da71bb16ad",
+                "sha256:ebeddd119f526bcf323a89f853afb12e225902a24d29b55fe18dd6fcb2838a76"
             ],
-            "version": "==3.4.8"
+            "version": "==35.0.0"
         },
         "execnet": {
             "hashes": [
@@ -142,11 +156,11 @@
         },
         "idna": {
             "hashes": [
-                "sha256:14475042e284991034cb48e06f6851428fb14c4dc953acd9be9a5e95c7b6dd7a",
-                "sha256:467fbad99067910785144ce333826c71fb0e63a425657295239737f7ecd125f3"
+                "sha256:84d9dd047ffa80596e0f246e2eab0b391788b0503584e8945f2368256d2735ff",
+                "sha256:9d643ff0a55b762d5cdb124b8eaa99c66322e2157b69160bc32796e824360e6d"
             ],
             "markers": "python_version >= '3'",
-            "version": "==3.2"
+            "version": "==3.3"
         },
         "iniconfig": {
             "hashes": [
@@ -207,11 +221,11 @@
                 "crypto"
             ],
             "hashes": [
-                "sha256:934d73fbba91b0483d3857d1aff50e96b2a892384ee2c17417ed3203f173fca1",
-                "sha256:fba44e7898bbca160a2b2b501f492824fc8382485d3a6f11ba5d0c1937ce6130"
+                "sha256:b888b4d56f06f6dcd777210c334e69c737be74755d3e5e9ee3fe67dc18a0ee41",
+                "sha256:e0c4bb8d9f0af0c7f5b1ec4c5036309617d03d56932877f2f7a0beeb5318322f"
             ],
             "index": "pypi",
-            "version": "==2.1.0"
+            "version": "==2.3.0"
         },
         "pyparsing": {
             "hashes": [
@@ -272,21 +286,21 @@
         },
         "urllib3": {
             "hashes": [
-                "sha256:39fb8672126159acb139a7718dd10806104dec1e2f0f6c88aab05d17df10c8d4",
-                "sha256:f57b4c16c62fa2760b7e3d97c35b255512fb6b59a259730f36ba32ce9f8e342f"
+                "sha256:4987c65554f7a2dbf30c18fd48778ef124af6fab771a377103da0585e2336ece",
+                "sha256:c4fdf4019605b6e5423637e01bc9fe4daef873709a7973e195ceba0a62bbc844"
             ],
             "markers": "python_version >= '2.7' and python_version not in '3.0, 3.1, 3.2, 3.3, 3.4' and python_version < '4'",
-            "version": "==1.26.6"
+            "version": "==1.26.7"
         }
     },
     "develop": {
         "flake8": {
             "hashes": [
-                "sha256:07528381786f2a6237b061f6e96610a4167b226cb926e2aa2b6b1d78057c576b",
-                "sha256:bf8fd333346d844f616e8d47905ef3a3384edae6b4e9beb0c5101e25e3110907"
+                "sha256:479b1304f72536a55948cb40a32dce8bb0ffe3501e26eaf292c7e60eb5e0428d",
+                "sha256:806e034dda44114815e23c16ef92f95c91e4c71100ff52813adf7132a6ad870d"
             ],
             "index": "pypi",
-            "version": "==3.9.2"
+            "version": "==4.0.1"
         },
         "mccabe": {
             "hashes": [
@@ -333,19 +347,19 @@
         },
         "pycodestyle": {
             "hashes": [
-                "sha256:514f76d918fcc0b55c6680472f0a37970994e07bbb80725808c17089be302068",
-                "sha256:c389c1d06bf7904078ca03399a4816f974a1d590090fecea0c63ec26ebaf1cef"
+                "sha256:720f8b39dde8b293825e7ff02c475f3077124006db4f440dcbc9a20b76548a20",
+                "sha256:eddd5847ef438ea1c7870ca7eb78a9d47ce0cdb4851a5523949f2601d0cbbe7f"
             ],
-            "markers": "python_version >= '2.7' and python_version not in '3.0, 3.1, 3.2, 3.3'",
-            "version": "==2.7.0"
+            "markers": "python_version >= '2.7' and python_version not in '3.0, 3.1, 3.2, 3.3, 3.4'",
+            "version": "==2.8.0"
         },
         "pyflakes": {
             "hashes": [
-                "sha256:7893783d01b8a89811dd72d7dfd4d84ff098e5eed95cfa8905b22bbffe52efc3",
-                "sha256:f5bc8ecabc05bb9d291eb5203d6810b49040f6ff446a756326104746cc00c1db"
+                "sha256:05a85c2872edf37a4ed30b0cce2f6093e1d0581f8c19d7393122da7e25b2b24c",
+                "sha256:3bb3a3f256f4b7968c9c788781e4ff07dce46bdf12339dcda61053375426ee2e"
             ],
             "markers": "python_version >= '2.7' and python_version not in '3.0, 3.1, 3.2, 3.3'",
-            "version": "==2.3.1"
+            "version": "==2.4.0"
         },
         "toml": {
             "hashes": [

test_runner/README.md

@@ -53,8 +53,8 @@ Useful environment variables:
 should go.
 `TEST_SHARED_FIXTURES`: Try to re-use a single pageserver for all the tests.
 
-Let stdout and stderr go to the terminal instead of capturing them:
-`pytest -s ...`
+Let stdout, stderr and `INFO` log messages go to the terminal instead of capturing them:
+`pytest -s --log-cli-level=INFO ...`
 (Note many tests capture subprocess outputs separately, so this may not
 show much.)
 
@@ -95,11 +95,13 @@ Python destructors, e.g. `__del__()` aren't recommended for cleanup.
 
 ### Code quality
 
+We force code formatting via yapf:
+
+1. Install `yapf` and other tools (`flake8`, `mypy`) with `pipenv install --dev`.
+1. Reformat all your code by running `pipenv run yapf -ri .` in the `test_runner/` directory.
+
 Before submitting a patch, please consider:
 
 * Writing a couple of docstrings to clarify the reasoning behind a new test.
 * Running `flake8` (or a linter of your choice, e.g. `pycodestyle`) and fixing possible defects, if any.
-* Formatting the code with `yapf -r -i .` (TODO: implement an opt-in pre-commit hook for that).
 * (Optional) Typechecking the code with `mypy .`. Currently this mostly affects `fixtures/zenith_fixtures.py`.
-
-The tools can be installed with `pipenv install --dev`.

test_runner/batch_others/test_auth.py

@@ -1,4 +1,3 @@
-
 from contextlib import closing
 from typing import Iterator
 from uuid import uuid4
@@ -6,7 +5,6 @@ import psycopg2
 from fixtures.zenith_fixtures import PortDistributor, Postgres, ZenithCli, ZenithPageserver, PgBin
 import pytest
 
-
 pytest_plugins = ("fixtures.zenith_fixtures")
 
 
@@ -35,7 +33,9 @@ def test_pageserver_auth(pageserver_auth_enabled: ZenithPageserver):
     ps.safe_psql(f"tenant_create {uuid4().hex}", password=management_token)
 
     # fail to create tenant using tenant token
-    with pytest.raises(psycopg2.DatabaseError, match='Attempt to access management api with tenant scope. Permission denied'):
+    with pytest.raises(
+            psycopg2.DatabaseError,
+            match='Attempt to access management api with tenant scope. Permission denied'):
         ps.safe_psql(f"tenant_create {uuid4().hex}", password=tenant_token)
 
 
@@ -60,14 +60,14 @@ def test_compute_auth_to_pageserver(
         wa_factory.start_n_new(3, management_token)
 
     with Postgres(
-        zenith_cli=zenith_cli,
-        repo_dir=repo_dir,
-        pg_bin=pg_bin,
-        tenant_id=ps.initial_tenant,
-        port=port_distributor.get_port(),
+            zenith_cli=zenith_cli,
+            repo_dir=repo_dir,
+            pg_bin=pg_bin,
+            tenant_id=ps.initial_tenant,
+            port=port_distributor.get_port(),
     ).create_start(
-        branch,
-        wal_acceptors=wa_factory.get_connstrs() if with_wal_acceptors else None,
+            branch,
+            wal_acceptors=wa_factory.get_connstrs() if with_wal_acceptors else None,
     ) as pg:
         with closing(pg.connect()) as conn:
             with conn.cursor() as cur:

test_runner/batch_others/test_branch_behind.py

@@ -1,6 +1,6 @@
 import subprocess
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
-
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
@@ -13,7 +13,7 @@ def test_branch_behind(zenith_cli, pageserver: ZenithPageserver, postgres: Postg
     zenith_cli.run(["branch", "test_branch_behind", "empty"])
 
     pgmain = postgres.create_start('test_branch_behind')
-    print("postgres is running on 'test_branch_behind' branch")
+    log.info("postgres is running on 'test_branch_behind' branch")
 
     main_pg_conn = pgmain.connect()
     main_cur = main_pg_conn.cursor()
@@ -27,7 +27,7 @@ def test_branch_behind(zenith_cli, pageserver: ZenithPageserver, postgres: Postg
     ''')
     main_cur.execute('SELECT pg_current_wal_insert_lsn()')
     lsn_a = main_cur.fetchone()[0]
-    print('LSN after 100 rows: ' + lsn_a)
+    log.info(f'LSN after 100 rows: {lsn_a}')
 
     # Insert some more rows. (This generates enough WAL to fill a few segments.)
     main_cur.execute('''
@@ -37,7 +37,7 @@ def test_branch_behind(zenith_cli, pageserver: ZenithPageserver, postgres: Postg
     ''')
     main_cur.execute('SELECT pg_current_wal_insert_lsn()')
     lsn_b = main_cur.fetchone()[0]
-    print('LSN after 200100 rows: ' + lsn_b)
+    log.info(f'LSN after 200100 rows: {lsn_b}')
 
     # Branch at the point where only 100 rows were inserted
     zenith_cli.run(["branch", "test_branch_behind_hundred", "test_branch_behind@" + lsn_a])
@@ -52,7 +52,7 @@ def test_branch_behind(zenith_cli, pageserver: ZenithPageserver, postgres: Postg
 
     main_cur.execute('SELECT pg_current_wal_insert_lsn()')
     lsn_c = main_cur.fetchone()[0]
-    print('LSN after 400100 rows: ' + lsn_c)
+    log.info(f'LSN after 400100 rows: {lsn_c}')
 
     # Branch at the point where only 200100 rows were inserted
     zenith_cli.run(["branch", "test_branch_behind_more", "test_branch_behind@" + lsn_b])
@@ -86,7 +86,10 @@ def test_branch_behind(zenith_cli, pageserver: ZenithPageserver, postgres: Postg
     assert cur.fetchone() == (1, )
 
     # branch at pre-initdb lsn
+    #
+    # FIXME: This works currently, but probably shouldn't be allowed
     try:
         zenith_cli.run(["branch", "test_branch_preinitdb", "test_branch_behind@0/42"])
+        # FIXME: assert false, "branch with invalid LSN should have failed"
     except subprocess.CalledProcessError:
-        print("Branch creation with pre-initdb LSN failed (as expected)")
+        log.info("Branch creation with pre-initdb LSN failed (as expected)")

test_runner/batch_others/test_clog_truncate.py

@@ -4,6 +4,7 @@ import os
 from contextlib import closing
 
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
@@ -17,14 +18,17 @@ def test_clog_truncate(zenith_cli, pageserver: ZenithPageserver, postgres: Postg
 
     # set agressive autovacuum to make sure that truncation will happen
     config = [
-        'autovacuum_max_workers=10', 'autovacuum_vacuum_threshold=0',
-        'autovacuum_vacuum_insert_threshold=0', 'autovacuum_vacuum_cost_delay=0',
-        'autovacuum_vacuum_cost_limit=10000', 'autovacuum_naptime =1s',
+        'autovacuum_max_workers=10',
+        'autovacuum_vacuum_threshold=0',
+        'autovacuum_vacuum_insert_threshold=0',
+        'autovacuum_vacuum_cost_delay=0',
+        'autovacuum_vacuum_cost_limit=10000',
+        'autovacuum_naptime =1s',
         'autovacuum_freeze_max_age=100000'
     ]
 
     pg = postgres.create_start('test_clog_truncate', config_lines=config)
-    print('postgres is running on test_clog_truncate branch')
+    log.info('postgres is running on test_clog_truncate branch')
 
     # Install extension containing function needed for test
     pg.safe_psql('CREATE EXTENSION zenith_test_utils')
@@ -33,22 +37,22 @@ def test_clog_truncate(zenith_cli, pageserver: ZenithPageserver, postgres: Postg
     with closing(pg.connect()) as conn:
         with conn.cursor() as cur:
             cur.execute('select test_consume_xids(1000*1000*10);')
-            print('xids consumed')
+            log.info('xids consumed')
 
             # call a checkpoint to trigger TruncateSubtrans
             cur.execute('CHECKPOINT;')
 
             # ensure WAL flush
             cur.execute('select txid_current()')
-            print(cur.fetchone())
+            log.info(cur.fetchone())
 
     # wait for autovacuum to truncate the pg_xact
     # XXX Is it worth to add a timeout here?
     pg_xact_0000_path = os.path.join(pg.pg_xact_dir_path(), '0000')
-    print("pg_xact_0000_path = " + pg_xact_0000_path)
+    log.info(f"pg_xact_0000_path = {pg_xact_0000_path}")
 
     while os.path.isfile(pg_xact_0000_path):
-        print("file exists. wait for truncation. " "pg_xact_0000_path = " + pg_xact_0000_path)
+        log.info(f"file exists. wait for truncation. " "pg_xact_0000_path = {pg_xact_0000_path}")
         time.sleep(5)
 
     # checkpoint to advance latest lsn
@@ -59,14 +63,14 @@ def test_clog_truncate(zenith_cli, pageserver: ZenithPageserver, postgres: Postg
             lsn_after_truncation = cur.fetchone()[0]
 
     # create new branch after clog truncation and start a compute node on it
-    print('create branch at lsn_after_truncation ' + lsn_after_truncation)
+    log.info(f'create branch at lsn_after_truncation {lsn_after_truncation}')
     zenith_cli.run(
         ["branch", "test_clog_truncate_new", "test_clog_truncate@" + lsn_after_truncation])
 
     pg2 = postgres.create_start('test_clog_truncate_new')
-    print('postgres is running on test_clog_truncate_new branch')
+    log.info('postgres is running on test_clog_truncate_new branch')
 
     # check that new node doesn't contain truncated segment
     pg_xact_0000_path_new = os.path.join(pg2.pg_xact_dir_path(), '0000')
-    print("pg_xact_0000_path_new = " + pg_xact_0000_path_new)
+    log.info(f"pg_xact_0000_path_new = {pg_xact_0000_path_new}")
     assert os.path.isfile(pg_xact_0000_path_new) is False

test_runner/batch_others/test_config.py

@@ -1,6 +1,7 @@
 from contextlib import closing
 
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
@@ -14,7 +15,7 @@ def test_config(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFact
 
     # change config
     pg = postgres.create_start('test_config', config_lines=['log_min_messages=debug1'])
-    print('postgres is running on test_config branch')
+    log.info('postgres is running on test_config branch')
 
     with closing(pg.connect()) as conn:
         with conn.cursor() as cur:

test_runner/batch_others/test_createdropdb.py

@@ -3,6 +3,7 @@ import pathlib
 
 from contextlib import closing
 from fixtures.zenith_fixtures import ZenithPageserver, PostgresFactory, ZenithCli, check_restored_datadir_content
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
@@ -19,7 +20,7 @@ def test_createdb(
     zenith_cli.run(["branch", "test_createdb", "empty"])
 
     pg = postgres.create_start('test_createdb')
-    print("postgres is running on 'test_createdb' branch")
+    log.info("postgres is running on 'test_createdb' branch")
 
     with closing(pg.connect()) as conn:
         with conn.cursor() as cur:
@@ -40,6 +41,7 @@ def test_createdb(
     for db in (pg, pg2):
         db.connect(dbname='foodb').close()
 
+
 #
 # Test DROP DATABASE
 #
@@ -48,12 +50,12 @@ def test_dropdb(
     pageserver: ZenithPageserver,
     postgres: PostgresFactory,
     pg_bin,
-    test_output_dir
+    test_output_dir,
 ):
     zenith_cli.run(["branch", "test_dropdb", "empty"])
 
     pg = postgres.create_start('test_dropdb')
-    print("postgres is running on 'test_dropdb' branch")
+    log.info("postgres is running on 'test_dropdb' branch")
 
     with closing(pg.connect()) as conn:
         with conn.cursor() as cur:
@@ -65,7 +67,6 @@ def test_dropdb(
             cur.execute("SELECT oid FROM pg_database WHERE datname='foodb';")
             dboid = cur.fetchone()[0]
 
-
     with closing(pg.connect()) as conn:
         with conn.cursor() as cur:
             cur.execute('DROP DATABASE foodb')
@@ -75,7 +76,6 @@ def test_dropdb(
             cur.execute('SELECT pg_current_wal_insert_lsn()')
             lsn_after_drop = cur.fetchone()[0]
 
-
     # Create two branches before and after database drop.
     zenith_cli.run(["branch", "test_before_dropdb", "test_dropdb@" + lsn_before_drop])
     pg_before = postgres.create_start('test_before_dropdb')
@@ -88,13 +88,13 @@ def test_dropdb(
 
     # Test that database subdir exists on the branch before drop
     dbpath = pathlib.Path(pg_before.pgdata_dir) / 'base' / str(dboid)
-    print(dbpath)
+    log.info(dbpath)
 
     assert os.path.isdir(dbpath) == True
 
     # Test that database subdir doesn't exist on the branch after drop
     dbpath = pathlib.Path(pg_after.pgdata_dir) / 'base' / str(dboid)
-    print(dbpath)
+    log.info(dbpath)
 
     assert os.path.isdir(dbpath) == False
 

test_runner/batch_others/test_createuser.py

@@ -1,6 +1,7 @@
 from contextlib import closing
 
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
@@ -12,7 +13,7 @@ def test_createuser(zenith_cli, pageserver: ZenithPageserver, postgres: Postgres
     zenith_cli.run(["branch", "test_createuser", "empty"])
 
     pg = postgres.create_start('test_createuser')
-    print("postgres is running on 'test_createuser' branch")
+    log.info("postgres is running on 'test_createuser' branch")
 
     with closing(pg.connect()) as conn:
         with conn.cursor() as cur:

test_runner/batch_others/test_multixact.py

@@ -1,4 +1,5 @@
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver, check_restored_datadir_content
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
@@ -9,13 +10,17 @@ pytest_plugins = ("fixtures.zenith_fixtures")
 # it only checks next_multixact_id field in restored pg_control,
 # since we don't have functions to check multixact internals.
 #
-def test_multixact(pageserver: ZenithPageserver, postgres: PostgresFactory,
-                    pg_bin, zenith_cli, base_dir, test_output_dir):
+def test_multixact(pageserver: ZenithPageserver,
+                   postgres: PostgresFactory,
+                   pg_bin,
+                   zenith_cli,
+                   base_dir,
+                   test_output_dir):
     # Create a branch for us
     zenith_cli.run(["branch", "test_multixact", "empty"])
     pg = postgres.create_start('test_multixact')
 
-    print("postgres is running on 'test_multixact' branch")
+    log.info("postgres is running on 'test_multixact' branch")
     pg_conn = pg.connect()
     cur = pg_conn.cursor()
 
@@ -55,7 +60,7 @@ def test_multixact(pageserver: ZenithPageserver, postgres: PostgresFactory,
     zenith_cli.run(["branch", "test_multixact_new", "test_multixact@" + lsn])
     pg_new = postgres.create_start('test_multixact_new')
 
-    print("postgres is running on 'test_multixact_new' branch")
+    log.info("postgres is running on 'test_multixact_new' branch")
     pg_new_conn = pg_new.connect()
     cur_new = pg_new_conn.cursor()
 

test_runner/batch_others/test_old_request_lsn.py

@@ -1,9 +1,11 @@
 from contextlib import closing
 
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
+
 #
 # Test where Postgres generates a lot of WAL, and it's garbage collected away, but
 # no pages are evicted so that Postgres uses an old LSN in a GetPage request.
@@ -14,11 +16,14 @@ pytest_plugins = ("fixtures.zenith_fixtures")
 # just a hint that the page hasn't been modified since that LSN, and the page
 # server should return the latest page version regardless of the LSN.
 #
-def test_old_request_lsn(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory, pg_bin):
+def test_old_request_lsn(zenith_cli,
+                         pageserver: ZenithPageserver,
+                         postgres: PostgresFactory,
+                         pg_bin):
     # Create a branch for us
     zenith_cli.run(["branch", "test_old_request_lsn", "empty"])
     pg = postgres.create_start('test_old_request_lsn')
-    print('postgres is running on test_old_request_lsn branch')
+    log.info('postgres is running on test_old_request_lsn branch')
 
     pg_conn = pg.connect()
     cur = pg_conn.cursor()
@@ -46,20 +51,20 @@ def test_old_request_lsn(zenith_cli, pageserver: ZenithPageserver, postgres: Pos
         from pg_settings where name = 'shared_buffers'
     ''')
     row = cur.fetchone()
-    print(f'shared_buffers is {row[0]}, table size {row[1]}');
+    log.info(f'shared_buffers is {row[0]}, table size {row[1]}')
     assert int(row[0]) < int(row[1])
 
-    cur.execute('VACUUM foo');
+    cur.execute('VACUUM foo')
 
     # Make a lot of updates on a single row, generating a lot of WAL. Trigger
     # garbage collections so that the page server will remove old page versions.
     for i in range(10):
         pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0")
         for j in range(100):
-            cur.execute('UPDATE foo SET val = val + 1 WHERE id = 1;');
+            cur.execute('UPDATE foo SET val = val + 1 WHERE id = 1;')
 
     # All (or at least most of) the updates should've been on the same page, so
     # that we haven't had to evict any dirty pages for a long time. Now run
     # a query that sends GetPage@LSN requests with the old LSN.
-    cur.execute("SELECT COUNT(*), SUM(val) FROM foo");
+    cur.execute("SELECT COUNT(*), SUM(val) FROM foo")
     assert cur.fetchone() == (100000, 101000)

test_runner/batch_others/test_pageserver_api.py

@@ -63,7 +63,8 @@ def test_tenant_list_psql(pageserver: ZenithPageserver, zenith_cli):
     cur = conn.cursor()
 
     # check same tenant cannot be created twice
-    with pytest.raises(psycopg2.DatabaseError, match=f'tenant {pageserver.initial_tenant} already exists'):
+    with pytest.raises(psycopg2.DatabaseError,
+                       match=f'tenant {pageserver.initial_tenant} already exists'):
         cur.execute(f'tenant_create {pageserver.initial_tenant}')
 
     # create one more tenant
@@ -102,5 +103,6 @@ def test_pageserver_http_api_client(pageserver: ZenithPageserver):
 
 
 def test_pageserver_http_api_client_auth_enabled(pageserver_auth_enabled: ZenithPageserver):
-    client = pageserver_auth_enabled.http_client(auth_token=pageserver_auth_enabled.auth_keys.generate_management_token())
+    client = pageserver_auth_enabled.http_client(
+        auth_token=pageserver_auth_enabled.auth_keys.generate_management_token())
     check_client(client, pageserver_auth_enabled.initial_tenant)

test_runner/batch_others/test_pageserver_restart.py

@@ -5,20 +5,24 @@ import time
 from contextlib import closing
 from multiprocessing import Process, Value
 from fixtures.zenith_fixtures import WalAcceptorFactory, ZenithPageserver, PostgresFactory
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
+
 # Check that dead minority doesn't prevent the commits: execute insert n_inserts
 # times, with fault_probability chance of getting a wal acceptor down or up
 # along the way. 2 of 3 are always alive, so the work keeps going.
-def test_pageserver_restart(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory, wa_factory: WalAcceptorFactory):
+def test_pageserver_restart(zenith_cli,
+                            pageserver: ZenithPageserver,
+                            postgres: PostgresFactory,
+                            wa_factory: WalAcceptorFactory):
 
     # One safekeeper is enough for this test.
     wa_factory.start_n_new(1)
 
     zenith_cli.run(["branch", "test_pageserver_restart", "empty"])
-    pg = postgres.create_start('test_pageserver_restart',
-                               wal_acceptors=wa_factory.get_connstrs())
+    pg = postgres.create_start('test_pageserver_restart', wal_acceptors=wa_factory.get_connstrs())
 
     pg_conn = pg.connect()
     cur = pg_conn.cursor()
@@ -40,14 +44,14 @@ def test_pageserver_restart(zenith_cli, pageserver: ZenithPageserver, postgres:
         from pg_settings where name = 'shared_buffers'
     ''')
     row = cur.fetchone()
-    print("shared_buffers is {}, table size {}", row[0], row[1]);
+    log.info(f"shared_buffers is {row[0]}, table size {row[1]}")
     assert int(row[0]) < int(row[1])
 
     # Stop and restart pageserver. This is a more or less graceful shutdown, although
     # the page server doesn't currently have a shutdown routine so there's no difference
     # between stopping and crashing.
-    pageserver.stop();
-    pageserver.start();
+    pageserver.stop()
+    pageserver.start()
 
     # Stopping the pageserver breaks the connection from the postgres backend to
     # the page server, and causes the next query on the connection to fail. Start a new
@@ -61,6 +65,5 @@ def test_pageserver_restart(zenith_cli, pageserver: ZenithPageserver, postgres:
     assert cur.fetchone() == (100000, )
 
     # Stop the page server by force, and restart it
-    pageserver.stop();
-    pageserver.start();
-
+    pageserver.stop()
+    pageserver.start()

test_runner/batch_others/test_pgbench.py

@@ -1,4 +1,5 @@
 from fixtures.zenith_fixtures import PostgresFactory
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
@@ -8,7 +9,7 @@ def test_pgbench(postgres: PostgresFactory, pg_bin, zenith_cli):
     zenith_cli.run(["branch", "test_pgbench", "empty"])
 
     pg = postgres.create_start('test_pgbench')
-    print("postgres is running on 'test_pgbench' branch")
+    log.info("postgres is running on 'test_pgbench' branch")
 
     connstr = pg.connstr()
 

test_runner/batch_others/test_readonly_node.py

@@ -0,0 +1,89 @@
+import subprocess
+from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
+
+pytest_plugins = ("fixtures.zenith_fixtures")
+
+
+#
+# Create read-only compute nodes, anchored at historical points in time.
+#
+# This is very similar to the 'test_branch_behind' test, but instead of
+# creating branches, creates read-only nodes.
+#
+def test_readonly_node(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory, pg_bin):
+    zenith_cli.run(["branch", "test_readonly_node", "empty"])
+
+    pgmain = postgres.create_start('test_readonly_node')
+    print("postgres is running on 'test_readonly_node' branch")
+
+    main_pg_conn = pgmain.connect()
+    main_cur = main_pg_conn.cursor()
+
+    # Create table, and insert the first 100 rows
+    main_cur.execute('CREATE TABLE foo (t text)')
+    main_cur.execute('''
+        INSERT INTO foo
+            SELECT 'long string to consume some space' || g
+            FROM generate_series(1, 100) g
+    ''')
+    main_cur.execute('SELECT pg_current_wal_insert_lsn()')
+    lsn_a = main_cur.fetchone()[0]
+    print('LSN after 100 rows: ' + lsn_a)
+
+    # Insert some more rows. (This generates enough WAL to fill a few segments.)
+    main_cur.execute('''
+        INSERT INTO foo
+            SELECT 'long string to consume some space' || g
+            FROM generate_series(1, 200000) g
+    ''')
+    main_cur.execute('SELECT pg_current_wal_insert_lsn()')
+    lsn_b = main_cur.fetchone()[0]
+    print('LSN after 200100 rows: ' + lsn_b)
+
+    # Insert many more rows. This generates enough WAL to fill a few segments.
+    main_cur.execute('''
+        INSERT INTO foo
+            SELECT 'long string to consume some space' || g
+            FROM generate_series(1, 200000) g
+    ''')
+
+    main_cur.execute('SELECT pg_current_wal_insert_lsn()')
+    lsn_c = main_cur.fetchone()[0]
+    print('LSN after 400100 rows: ' + lsn_c)
+
+    # Create first read-only node at the point where only 100 rows were inserted
+    pg_hundred = postgres.create_start("test_readonly_node_hundred",
+                                       branch=f'test_readonly_node@{lsn_a}')
+
+    # And another at the point where 200100 rows were inserted
+    pg_more = postgres.create_start("test_readonly_node_more", branch=f'test_readonly_node@{lsn_b}')
+
+    # On the 'hundred' node, we should see only 100 rows
+    hundred_pg_conn = pg_hundred.connect()
+    hundred_cur = hundred_pg_conn.cursor()
+    hundred_cur.execute('SELECT count(*) FROM foo')
+    assert hundred_cur.fetchone() == (100, )
+
+    # On the 'more' node, we should see 100200 rows
+    more_pg_conn = pg_more.connect()
+    more_cur = more_pg_conn.cursor()
+    more_cur.execute('SELECT count(*) FROM foo')
+    assert more_cur.fetchone() == (200100, )
+
+    # All the rows are visible on the main branch
+    main_cur.execute('SELECT count(*) FROM foo')
+    assert main_cur.fetchone() == (400100, )
+
+    # Check creating a node at segment boundary
+    pg = postgres.create_start("test_branch_segment_boundary",
+                               branch="test_readonly_node@0/3000000")
+    cur = pg.connect().cursor()
+    cur.execute('SELECT 1')
+    assert cur.fetchone() == (1, )
+
+    # Create node at pre-initdb lsn
+    try:
+        zenith_cli.run(["pg", "start", "test_branch_preinitdb", "test_readonly_node@0/42"])
+        assert false, "compute node startup with invalid LSN should have failed"
+    except Exception:
+        print("Node creation with pre-initdb LSN failed (as expected)")

test_runner/batch_others/test_restart_compute.py

@@ -2,6 +2,7 @@ import pytest
 
 from contextlib import closing
 from fixtures.zenith_fixtures import ZenithPageserver, PostgresFactory
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
@@ -11,13 +12,13 @@ pytest_plugins = ("fixtures.zenith_fixtures")
 #
 @pytest.mark.parametrize('with_wal_acceptors', [False, True])
 def test_restart_compute(
-        zenith_cli,
-        pageserver: ZenithPageserver,
-        postgres: PostgresFactory,
-        pg_bin,
-        wa_factory,
-        with_wal_acceptors: bool,
-    ):
+    zenith_cli,
+    pageserver: ZenithPageserver,
+    postgres: PostgresFactory,
+    pg_bin,
+    wa_factory,
+    with_wal_acceptors: bool,
+):
     wal_acceptor_connstrs = None
     zenith_cli.run(["branch", "test_restart_compute", "empty"])
 
@@ -25,9 +26,8 @@ def test_restart_compute(
         wa_factory.start_n_new(3)
         wal_acceptor_connstrs = wa_factory.get_connstrs()
 
-    pg = postgres.create_start('test_restart_compute',
-                               wal_acceptors=wal_acceptor_connstrs)
-    print("postgres is running on 'test_restart_compute' branch")
+    pg = postgres.create_start('test_restart_compute', wal_acceptors=wal_acceptor_connstrs)
+    log.info("postgres is running on 'test_restart_compute' branch")
 
     with closing(pg.connect()) as conn:
         with conn.cursor() as cur:
@@ -36,12 +36,10 @@ def test_restart_compute(
             cur.execute('SELECT sum(key) FROM t')
             r = cur.fetchone()
             assert r == (5000050000, )
-            print("res = ", r)
+            log.info(f"res = {r}")
 
     # Remove data directory and restart
-    pg.stop_and_destroy().create_start('test_restart_compute',
-                                       wal_acceptors=wal_acceptor_connstrs)
-
+    pg.stop_and_destroy().create_start('test_restart_compute', wal_acceptors=wal_acceptor_connstrs)
 
     with closing(pg.connect()) as conn:
         with conn.cursor() as cur:
@@ -49,7 +47,7 @@ def test_restart_compute(
             cur.execute('SELECT sum(key) FROM t')
             r = cur.fetchone()
             assert r == (5000050000, )
-            print("res = ", r)
+            log.info(f"res = {r}")
 
             # Insert another row
             cur.execute("INSERT INTO t VALUES (100001, 'payload2')")
@@ -57,11 +55,10 @@ def test_restart_compute(
 
             r = cur.fetchone()
             assert r == (100001, )
-            print("res = ", r)
+            log.info(f"res = {r}")
 
     # Again remove data directory and restart
-    pg.stop_and_destroy().create_start('test_restart_compute',
-                                       wal_acceptors=wal_acceptor_connstrs)
+    pg.stop_and_destroy().create_start('test_restart_compute', wal_acceptors=wal_acceptor_connstrs)
 
     # That select causes lots of FPI's and increases probability of wakeepers
     # lagging behind after query completion
@@ -72,11 +69,10 @@ def test_restart_compute(
 
             r = cur.fetchone()
             assert r == (100001, )
-            print("res = ", r)
+            log.info(f"res = {r}")
 
     # And again remove data directory and restart
-    pg.stop_and_destroy().create_start('test_restart_compute',
-                                       wal_acceptors=wal_acceptor_connstrs)
+    pg.stop_and_destroy().create_start('test_restart_compute', wal_acceptors=wal_acceptor_connstrs)
 
     with closing(pg.connect()) as conn:
         with conn.cursor() as cur:
@@ -85,4 +81,4 @@ def test_restart_compute(
 
             r = cur.fetchone()
             assert r == (100001, )
-            print("res = ", r)
+            log.info(f"res = {r}")

test_runner/batch_others/test_snapfiles_gc.py

@@ -1,13 +1,19 @@
 from contextlib import closing
 import psycopg2.extras
-import time;
+import time
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
+
 def print_gc_result(row):
-    print("GC duration {elapsed} ms".format_map(row));
-    print("  REL    total: {layer_relfiles_total}, needed_by_cutoff {layer_relfiles_needed_by_cutoff}, needed_by_branches: {layer_relfiles_needed_by_branches}, not_updated: {layer_relfiles_not_updated}, needed_as_tombstone {layer_relfiles_needed_as_tombstone}, removed: {layer_relfiles_removed}, dropped: {layer_relfiles_dropped}".format_map(row))
-    print("  NONREL total: {layer_nonrelfiles_total}, needed_by_cutoff {layer_nonrelfiles_needed_by_cutoff}, needed_by_branches: {layer_nonrelfiles_needed_by_branches}, not_updated: {layer_nonrelfiles_not_updated}, needed_as_tombstone {layer_nonrelfiles_needed_as_tombstone}, removed: {layer_nonrelfiles_removed}, dropped: {layer_nonrelfiles_dropped}".format_map(row))
+    log.info("GC duration {elapsed} ms".format_map(row))
+    log.info(
+        "  REL    total: {layer_relfiles_total}, needed_by_cutoff {layer_relfiles_needed_by_cutoff}, needed_by_branches: {layer_relfiles_needed_by_branches}, not_updated: {layer_relfiles_not_updated}, needed_as_tombstone {layer_relfiles_needed_as_tombstone}, removed: {layer_relfiles_removed}, dropped: {layer_relfiles_dropped}"
+        .format_map(row))
+    log.info(
+        "  NONREL total: {layer_nonrelfiles_total}, needed_by_cutoff {layer_nonrelfiles_needed_by_cutoff}, needed_by_branches: {layer_nonrelfiles_needed_by_branches}, not_updated: {layer_nonrelfiles_not_updated}, needed_as_tombstone {layer_nonrelfiles_needed_as_tombstone}, removed: {layer_nonrelfiles_removed}, dropped: {layer_nonrelfiles_dropped}"
+        .format_map(row))
 
 
 #
@@ -23,7 +29,7 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin):
     with closing(pg.connect()) as conn:
         with conn.cursor() as cur:
             with closing(pageserver.connect()) as psconn:
-                with psconn.cursor(cursor_factory = psycopg2.extras.DictCursor) as pscur:
+                with psconn.cursor(cursor_factory=psycopg2.extras.DictCursor) as pscur:
 
                     # Get the timeline ID of our branch. We need it for the 'do_gc' command
                     cur.execute("SHOW zenith.zenith_timeline")
@@ -33,9 +39,9 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin):
                     cur.execute("CREATE TABLE foo(x integer)")
                     cur.execute("INSERT INTO foo VALUES (1)")
 
-                    cur.execute("select relfilenode from pg_class where oid = 'foo'::regclass");
-                    row = cur.fetchone();
-                    print("relfilenode is {}", row[0]);
+                    cur.execute("select relfilenode from pg_class where oid = 'foo'::regclass")
+                    row = cur.fetchone()
+                    log.info(f"relfilenode is {row[0]}")
 
                     # Run GC, to clear out any garbage left behind in the catalogs by
                     # the CREATE TABLE command. We want to have a clean slate with no garbage
@@ -50,22 +56,23 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin):
                     # update to confuse our numbers either.
                     cur.execute("DELETE FROM foo")
 
-                    print("Running GC before test")
+                    log.info("Running GC before test")
                     pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0")
                     row = pscur.fetchone()
-                    print_gc_result(row);
+                    print_gc_result(row)
                     # remember the number of files
-                    layer_relfiles_remain = row['layer_relfiles_total'] - row['layer_relfiles_removed']
+                    layer_relfiles_remain = (row['layer_relfiles_total'] -
+                                             row['layer_relfiles_removed'])
                     assert layer_relfiles_remain > 0
 
                     # Insert a row and run GC. Checkpoint should freeze the layer
                     # so that there is only the most recent image layer left for the rel,
                     # removing the old image and delta layer.
-                    print("Inserting one row and running GC")
+                    log.info("Inserting one row and running GC")
                     cur.execute("INSERT INTO foo VALUES (1)")
                     pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0")
                     row = pscur.fetchone()
-                    print_gc_result(row);
+                    print_gc_result(row)
                     assert row['layer_relfiles_total'] == layer_relfiles_remain + 2
                     assert row['layer_relfiles_removed'] == 2
                     assert row['layer_relfiles_dropped'] == 0
@@ -73,34 +80,34 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin):
                     # Insert two more rows and run GC.
                     # This should create new image and delta layer file with the new contents, and
                     # then remove the old one image and the just-created delta layer.
-                    print("Inserting two more rows and running GC")
+                    log.info("Inserting two more rows and running GC")
                     cur.execute("INSERT INTO foo VALUES (2)")
                     cur.execute("INSERT INTO foo VALUES (3)")
 
                     pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0")
                     row = pscur.fetchone()
-                    print_gc_result(row);
+                    print_gc_result(row)
                     assert row['layer_relfiles_total'] == layer_relfiles_remain + 2
                     assert row['layer_relfiles_removed'] == 2
                     assert row['layer_relfiles_dropped'] == 0
 
                     # Do it again. Should again create two new layer files and remove old ones.
-                    print("Inserting two more rows and running GC")
+                    log.info("Inserting two more rows and running GC")
                     cur.execute("INSERT INTO foo VALUES (2)")
                     cur.execute("INSERT INTO foo VALUES (3)")
 
                     pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0")
                     row = pscur.fetchone()
-                    print_gc_result(row);
+                    print_gc_result(row)
                     assert row['layer_relfiles_total'] == layer_relfiles_remain + 2
                     assert row['layer_relfiles_removed'] == 2
                     assert row['layer_relfiles_dropped'] == 0
 
                     # Run GC again, with no changes in the database. Should not remove anything.
-                    print("Run GC again, with nothing to do")
+                    log.info("Run GC again, with nothing to do")
                     pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0")
                     row = pscur.fetchone()
-                    print_gc_result(row);
+                    print_gc_result(row)
                     assert row['layer_relfiles_total'] == layer_relfiles_remain
                     assert row['layer_relfiles_removed'] == 0
                     assert row['layer_relfiles_dropped'] == 0
@@ -108,12 +115,12 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin):
                     #
                     # Test DROP TABLE checks that relation data and metadata was deleted by GC from object storage
                     #
-                    print("Drop table and run GC again");
+                    log.info("Drop table and run GC again")
                     cur.execute("DROP TABLE foo")
 
                     pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0")
                     row = pscur.fetchone()
-                    print_gc_result(row);
+                    print_gc_result(row)
 
                     # We still cannot remove the latest layers
                     # because they serve as tombstones for earlier layers.

test_runner/batch_others/test_tenants.py

@@ -21,18 +21,30 @@ def test_tenants_normal_work(
     tenant_1 = tenant_factory.create()
     tenant_2 = tenant_factory.create()
 
-    zenith_cli.run(["branch", f"test_tenants_normal_work_with_wal_acceptors{with_wal_acceptors}", "main", f"--tenantid={tenant_1}"])
-    zenith_cli.run(["branch", f"test_tenants_normal_work_with_wal_acceptors{with_wal_acceptors}", "main", f"--tenantid={tenant_2}"])
+    zenith_cli.run([
+        "branch",
+        f"test_tenants_normal_work_with_wal_acceptors{with_wal_acceptors}",
+        "main",
+        f"--tenantid={tenant_1}"
+    ])
+    zenith_cli.run([
+        "branch",
+        f"test_tenants_normal_work_with_wal_acceptors{with_wal_acceptors}",
+        "main",
+        f"--tenantid={tenant_2}"
+    ])
     if with_wal_acceptors:
         wa_factory.start_n_new(3)
 
     pg_tenant1 = postgres.create_start(
         f"test_tenants_normal_work_with_wal_acceptors{with_wal_acceptors}",
+        None,  # branch name, None means same as node name
         tenant_1,
         wal_acceptors=wa_factory.get_connstrs() if with_wal_acceptors else None,
     )
     pg_tenant2 = postgres.create_start(
         f"test_tenants_normal_work_with_wal_acceptors{with_wal_acceptors}",
+        None,  # branch name, None means same as node name
         tenant_2,
         wal_acceptors=wa_factory.get_connstrs() if with_wal_acceptors else None,
     )
@@ -45,4 +57,4 @@ def test_tenants_normal_work(
                 cur.execute("CREATE TABLE t(key int primary key, value text)")
                 cur.execute("INSERT INTO t SELECT generate_series(1,100000), 'payload'")
                 cur.execute("SELECT sum(key) FROM t")
-                assert cur.fetchone() == (5000050000,)
+                assert cur.fetchone() == (5000050000, )

test_runner/batch_others/test_timeline_size.py

@@ -2,11 +2,10 @@ from contextlib import closing
 from uuid import UUID
 import psycopg2.extras
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
+from fixtures.log_helper import log
 
 
-def test_timeline_size(
-    zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory, pg_bin
-):
+def test_timeline_size(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory, pg_bin):
     # Branch at the point where only 100 rows were inserted
     zenith_cli.run(["branch", "test_timeline_size", "empty"])
 
@@ -15,7 +14,7 @@ def test_timeline_size(
     assert res["current_logical_size"] == res["current_logical_size_non_incremental"]
 
     pgmain = postgres.create_start("test_timeline_size")
-    print("postgres is running on 'test_timeline_size' branch")
+    log.info("postgres is running on 'test_timeline_size' branch")
 
     with closing(pgmain.connect()) as conn:
         with conn.cursor() as cur:
@@ -23,13 +22,11 @@ def test_timeline_size(
 
             # Create table, and insert the first 100 rows
             cur.execute("CREATE TABLE foo (t text)")
-            cur.execute(
-                """
+            cur.execute("""
                 INSERT INTO foo
                     SELECT 'long string to consume some space' || g
                     FROM generate_series(1, 10) g
-            """
-            )
+            """)
 
             res = client.branch_detail(UUID(pageserver.initial_tenant), "test_timeline_size")
             assert res["current_logical_size"] == res["current_logical_size_non_incremental"]

test_runner/batch_others/test_twophase.py

@@ -1,7 +1,7 @@
 import os
 
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver, PgBin
-
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
@@ -9,11 +9,14 @@ pytest_plugins = ("fixtures.zenith_fixtures")
 #
 # Test branching, when a transaction is in prepared state
 #
-def test_twophase(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory, pg_bin: PgBin):
+def test_twophase(zenith_cli,
+                  pageserver: ZenithPageserver,
+                  postgres: PostgresFactory,
+                  pg_bin: PgBin):
     zenith_cli.run(["branch", "test_twophase", "empty"])
 
     pg = postgres.create_start('test_twophase', config_lines=['max_prepared_transactions=5'])
-    print("postgres is running on 'test_twophase' branch")
+    log.info("postgres is running on 'test_twophase' branch")
 
     conn = pg.connect()
     cur = conn.cursor()
@@ -45,7 +48,7 @@ def test_twophase(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFa
     cur.execute('CHECKPOINT')
 
     twophase_files = os.listdir(pg.pg_twophase_dir_path())
-    print(twophase_files)
+    log.info(twophase_files)
     assert len(twophase_files) == 4
 
     cur.execute("COMMIT PREPARED 'insert_three'")
@@ -53,7 +56,7 @@ def test_twophase(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFa
     cur.execute('CHECKPOINT')
 
     twophase_files = os.listdir(pg.pg_twophase_dir_path())
-    print(twophase_files)
+    log.info(twophase_files)
     assert len(twophase_files) == 2
 
     # Create a branch with the transaction in prepared state
@@ -67,7 +70,7 @@ def test_twophase(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFa
 
     # Check that we restored only needed twophase files
     twophase_files2 = os.listdir(pg2.pg_twophase_dir_path())
-    print(twophase_files2)
+    log.info(twophase_files2)
     assert twophase_files2.sort() == twophase_files.sort()
 
     conn2 = pg2.connect()
@@ -79,8 +82,8 @@ def test_twophase(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFa
     cur2.execute("ROLLBACK PREPARED 'insert_two'")
 
     cur2.execute('SELECT * FROM foo')
-    assert cur2.fetchall() == [('one',), ('three',)]
+    assert cur2.fetchall() == [('one', ), ('three', )]
 
     # Only one committed insert is visible on the original branch
     cur.execute('SELECT * FROM foo')
-    assert cur.fetchall() == [('three',)]
+    assert cur.fetchall() == [('three', )]

test_runner/batch_others/test_vm_bits.py

@@ -1,17 +1,23 @@
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
+
 #
 # Test that the VM bit is cleared correctly at a HEAP_DELETE and
 # HEAP_UPDATE record.
 #
-def test_vm_bit_clear(pageserver: ZenithPageserver, postgres: PostgresFactory, pg_bin, zenith_cli, base_dir):
+def test_vm_bit_clear(pageserver: ZenithPageserver,
+                      postgres: PostgresFactory,
+                      pg_bin,
+                      zenith_cli,
+                      base_dir):
     # Create a branch for us
     zenith_cli.run(["branch", "test_vm_bit_clear", "empty"])
     pg = postgres.create_start('test_vm_bit_clear')
 
-    print("postgres is running on 'test_vm_bit_clear' branch")
+    log.info("postgres is running on 'test_vm_bit_clear' branch")
     pg_conn = pg.connect()
     cur = pg_conn.cursor()
 
@@ -48,13 +54,12 @@ def test_vm_bit_clear(pageserver: ZenithPageserver, postgres: PostgresFactory, p
     ''')
 
     cur.execute('SELECT * FROM vmtest_delete WHERE id = 1')
-    assert(cur.fetchall() == []);
+    assert (cur.fetchall() == [])
     cur.execute('SELECT * FROM vmtest_update WHERE id = 1')
-    assert(cur.fetchall() == []);
+    assert (cur.fetchall() == [])
 
     cur.close()
 
-
     # Check the same thing on the branch that we created right after the DELETE
     #
     # As of this writing, the code in smgrwrite() creates a full-page image whenever
@@ -63,7 +68,7 @@ def test_vm_bit_clear(pageserver: ZenithPageserver, postgres: PostgresFactory, p
     # server at the right point-in-time avoids that full-page image.
     pg_new = postgres.create_start('test_vm_bit_clear_new')
 
-    print("postgres is running on 'test_vm_bit_clear_new' branch")
+    log.info("postgres is running on 'test_vm_bit_clear_new' branch")
     pg_new_conn = pg_new.connect()
     cur_new = pg_new_conn.cursor()
 
@@ -74,6 +79,6 @@ def test_vm_bit_clear(pageserver: ZenithPageserver, postgres: PostgresFactory, p
     ''')
 
     cur_new.execute('SELECT * FROM vmtest_delete WHERE id = 1')
-    assert(cur_new.fetchall() == []);
+    assert (cur_new.fetchall() == [])
     cur_new.execute('SELECT * FROM vmtest_update WHERE id = 1')
-    assert(cur_new.fetchall() == []);
+    assert (cur_new.fetchall() == [])

test_runner/batch_others/test_wal_acceptor.py

@@ -9,13 +9,17 @@ from contextlib import closing
 from multiprocessing import Process, Value
 from fixtures.zenith_fixtures import WalAcceptorFactory, ZenithPageserver, PostgresFactory, PgBin
 from fixtures.utils import lsn_to_hex, mkdir_if_needed
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
 
 # basic test, write something in setup with wal acceptors, ensure that commits
 # succeed and data is written
-def test_normal_work(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory, wa_factory):
+def test_normal_work(zenith_cli,
+                     pageserver: ZenithPageserver,
+                     postgres: PostgresFactory,
+                     wa_factory):
     zenith_cli.run(["branch", "test_wal_acceptors_normal_work", "empty"])
     wa_factory.start_n_new(3)
     pg = postgres.create_start('test_wal_acceptors_normal_work',
@@ -33,7 +37,10 @@ def test_normal_work(zenith_cli, pageserver: ZenithPageserver, postgres: Postgre
 
 # Run page server and multiple acceptors, and multiple compute nodes running
 # against different timelines.
-def test_many_timelines(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory, wa_factory):
+def test_many_timelines(zenith_cli,
+                        pageserver: ZenithPageserver,
+                        postgres: PostgresFactory,
+                        wa_factory):
     n_timelines = 2
 
     wa_factory.start_n_new(3)
@@ -65,7 +72,10 @@ def test_many_timelines(zenith_cli, pageserver: ZenithPageserver, postgres: Post
 # Check that dead minority doesn't prevent the commits: execute insert n_inserts
 # times, with fault_probability chance of getting a wal acceptor down or up
 # along the way. 2 of 3 are always alive, so the work keeps going.
-def test_restarts(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory, wa_factory: WalAcceptorFactory):
+def test_restarts(zenith_cli,
+                  pageserver: ZenithPageserver,
+                  postgres: PostgresFactory,
+                  wa_factory: WalAcceptorFactory):
     fault_probability = 0.01
     n_inserts = 1000
     n_acceptors = 3
@@ -176,7 +186,11 @@ def stop_value():
 
 
 # do inserts while concurrently getting up/down subsets of acceptors
-def test_race_conditions(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory, wa_factory, stop_value):
+def test_race_conditions(zenith_cli,
+                         pageserver: ZenithPageserver,
+                         postgres: PostgresFactory,
+                         wa_factory,
+                         stop_value):
 
     wa_factory.start_n_new(3)
 
@@ -203,6 +217,7 @@ def test_race_conditions(zenith_cli, pageserver: ZenithPageserver, postgres: Pos
     stop_value.value = 1
     proc.join()
 
+
 class ProposerPostgres:
     """Object for running safekeepers sync with walproposer"""
     def __init__(self, pgdata_dir: str, pg_bin: PgBin, timeline_id: str, tenant_id: str):
@@ -284,10 +299,37 @@ def test_sync_safekeepers(repo_dir: str, pg_bin: PgBin, wa_factory: WalAcceptorF
         )
         lsn_hex = lsn_to_hex(res["inserted_wal"]["end_lsn"])
         lsn_after_append.append(lsn_hex)
-        print(f"safekeeper[{i}] lsn after append: {lsn_hex}")
+        log.info(f"safekeeper[{i}] lsn after append: {lsn_hex}")
 
     # run sync safekeepers
     lsn_after_sync = pg.sync_safekeepers()
-    print(f"lsn after sync = {lsn_after_sync}")
+    log.info(f"lsn after sync = {lsn_after_sync}")
 
     assert all(lsn_after_sync == lsn for lsn in lsn_after_append)
+
+
+def test_timeline_status(zenith_cli, pageserver, postgres, wa_factory: WalAcceptorFactory):
+    wa_factory.start_n_new(1)
+
+    zenith_cli.run(["branch", "test_timeline_status", "empty"])
+    pg = postgres.create_start('test_timeline_status', wal_acceptors=wa_factory.get_connstrs())
+
+    wa = wa_factory.instances[0]
+    wa_http_cli = wa.http_client()
+    wa_http_cli.check_status()
+
+    # learn zenith timeline from compute
+    tenant_id = pg.safe_psql("show zenith.zenith_tenant")[0][0]
+    timeline_id = pg.safe_psql("show zenith.zenith_timeline")[0][0]
+
+    # fetch something sensible from status
+    epoch = wa_http_cli.timeline_status(tenant_id, timeline_id).acceptor_epoch
+
+    pg.safe_psql("create table t(i int)")
+
+    # ensure epoch goes up after reboot
+    pg.stop().start()
+    pg.safe_psql("insert into t values(10)")
+
+    epoch_after_reboot = wa_http_cli.timeline_status(tenant_id, timeline_id).acceptor_epoch
+    assert epoch_after_reboot > epoch

test_runner/batch_others/test_wal_acceptor_async.py

@@ -1,11 +1,14 @@
 import asyncio
 import asyncpg
 import random
+import time
 
 from fixtures.zenith_fixtures import WalAcceptor, WalAcceptorFactory, ZenithPageserver, PostgresFactory, Postgres
+from fixtures.log_helper import getLogger
+from fixtures.utils import lsn_from_hex, lsn_to_hex
 from typing import List
-from fixtures.utils import debug_print
 
+log = getLogger('root.wal_acceptor_async')
 pytest_plugins = ("fixtures.zenith_fixtures")
 
 
@@ -18,13 +21,16 @@ class BankClient(object):
     async def initdb(self):
         await self.conn.execute('DROP TABLE IF EXISTS bank_accs')
         await self.conn.execute('CREATE TABLE bank_accs(uid int primary key, amount int)')
-        await self.conn.execute('''
+        await self.conn.execute(
+            '''
             INSERT INTO bank_accs
             SELECT *, $1 FROM generate_series(0, $2)
-        ''', self.init_amount, self.n_accounts - 1)
+        ''',
+            self.init_amount,
+            self.n_accounts - 1)
         await self.conn.execute('DROP TABLE IF EXISTS bank_log')
         await self.conn.execute('CREATE TABLE bank_log(from_uid int, to_uid int, amount int)')
-        
+
         # TODO: Remove when https://github.com/zenithdb/zenith/issues/644 is fixed
         await self.conn.execute('ALTER TABLE bank_accs SET (autovacuum_enabled = false)')
         await self.conn.execute('ALTER TABLE bank_log SET (autovacuum_enabled = false)')
@@ -33,6 +39,7 @@ class BankClient(object):
         row = await self.conn.fetchrow('SELECT sum(amount) AS sum FROM bank_accs')
         assert row['sum'] == self.n_accounts * self.init_amount
 
+
 async def bank_transfer(conn: asyncpg.Connection, from_uid, to_uid, amount):
     # avoid deadlocks by sorting uids
     if from_uid > to_uid:
@@ -41,16 +48,22 @@ async def bank_transfer(conn: asyncpg.Connection, from_uid, to_uid, amount):
     async with conn.transaction():
         await conn.execute(
             'UPDATE bank_accs SET amount = amount + ($1) WHERE uid = $2',
-            amount, to_uid,
+            amount,
+            to_uid,
         )
         await conn.execute(
             'UPDATE bank_accs SET amount = amount - ($1) WHERE uid = $2',
-            amount, from_uid,
+            amount,
+            from_uid,
         )
-        await conn.execute('INSERT INTO bank_log VALUES ($1, $2, $3)',
-            from_uid, to_uid, amount,
+        await conn.execute(
+            'INSERT INTO bank_log VALUES ($1, $2, $3)',
+            from_uid,
+            to_uid,
+            amount,
         )
 
+
 class WorkerStats(object):
     def __init__(self, n_workers):
         self.counters = [0] * n_workers
@@ -63,18 +76,18 @@ class WorkerStats(object):
         self.counters[worker_id] += 1
 
     def check_progress(self):
-        debug_print("Workers progress: {}".format(self.counters))
+        log.debug("Workers progress: {}".format(self.counters))
 
         # every worker should finish at least one tx
         assert all(cnt > 0 for cnt in self.counters)
 
         progress = sum(self.counters)
-        print('All workers made {} transactions'.format(progress))
+        log.info('All workers made {} transactions'.format(progress))
 
 
 async def run_random_worker(stats: WorkerStats, pg: Postgres, worker_id, n_accounts, max_transfer):
     pg_conn = await pg.connect_async()
-    debug_print('Started worker {}'.format(worker_id))
+    log.debug('Started worker {}'.format(worker_id))
 
     while stats.running:
         from_uid = random.randint(0, n_accounts - 1)
@@ -84,13 +97,45 @@ async def run_random_worker(stats: WorkerStats, pg: Postgres, worker_id, n_accou
         await bank_transfer(pg_conn, from_uid, to_uid, amount)
         stats.inc_progress(worker_id)
 
-        debug_print('Executed transfer({}) {} => {}'.format(amount, from_uid, to_uid))
+        log.debug('Executed transfer({}) {} => {}'.format(amount, from_uid, to_uid))
 
-    debug_print('Finished worker {}'.format(worker_id))
+    log.debug('Finished worker {}'.format(worker_id))
 
     await pg_conn.close()
 
 
+async def wait_for_lsn(safekeeper: WalAcceptor,
+                       tenant_id: str,
+                       timeline_id: str,
+                       wait_lsn: str,
+                       polling_interval=1,
+                       timeout=600):
+    """
+    Poll flush_lsn from safekeeper until it's greater or equal than
+    provided wait_lsn. To do that, timeline_status is fetched from
+    safekeeper every polling_interval seconds.
+    """
+
+    started_at = time.time()
+    client = safekeeper.http_client()
+
+    flush_lsn = client.timeline_status(tenant_id, timeline_id).flush_lsn
+    log.info(
+        f'Safekeeper at port {safekeeper.port.pg} has flush_lsn {flush_lsn}, waiting for lsn {wait_lsn}'
+    )
+
+    while lsn_from_hex(wait_lsn) > lsn_from_hex(flush_lsn):
+        elapsed = time.time() - started_at
+        if elapsed > timeout:
+            raise RuntimeError(
+                f"timed out waiting for safekeeper at port {safekeeper.port.pg} to reach {wait_lsn}, current lsn is {flush_lsn}"
+            )
+
+        await asyncio.sleep(polling_interval)
+        flush_lsn = client.timeline_status(tenant_id, timeline_id).flush_lsn
+        log.debug(f'safekeeper port={safekeeper.port.pg} flush_lsn={flush_lsn} wait_lsn={wait_lsn}')
+
+
 # This test will run several iterations and check progress in each of them.
 # On each iteration 1 acceptor is stopped, and 2 others should allow
 # background workers execute transactions. In the end, state should remain
@@ -103,6 +148,9 @@ async def run_restarts_under_load(pg: Postgres, acceptors: List[WalAcceptor], n_
     iterations = 6
 
     pg_conn = await pg.connect_async()
+    tenant_id = await pg_conn.fetchval("show zenith.zenith_tenant")
+    timeline_id = await pg_conn.fetchval("show zenith.zenith_timeline")
+
     bank = BankClient(pg_conn, n_accounts=n_accounts, init_amount=init_amount)
     # create tables and initial balances
     await bank.initdb()
@@ -113,19 +161,19 @@ async def run_restarts_under_load(pg: Postgres, acceptors: List[WalAcceptor], n_
         worker = run_random_worker(stats, pg, worker_id, bank.n_accounts, max_transfer)
         workers.append(asyncio.create_task(worker))
 
-
     for it in range(iterations):
-        victim = acceptors[it % len(acceptors)]
+        victim_idx = it % len(acceptors)
+        victim = acceptors[victim_idx]
         victim.stop()
 
-        # Wait till previous victim recovers so it is ready for the next
-        # iteration by making any writing xact.
-        conn = await pg.connect_async()
-        await conn.execute(
-            'UPDATE bank_accs SET amount = amount WHERE uid = 1',
-            timeout=120
-        )
-        await conn.close()
+        flush_lsn = await pg_conn.fetchval('SELECT pg_current_wal_flush_lsn()')
+        flush_lsn = lsn_to_hex(flush_lsn)
+        log.info(f'Postgres flush_lsn {flush_lsn}')
+
+        # Wait until alive safekeepers catch up with postgres
+        for idx, safekeeper in enumerate(acceptors):
+            if idx != victim_idx:
+                await wait_for_lsn(safekeeper, tenant_id, timeline_id, flush_lsn)
 
         stats.reset()
         await asyncio.sleep(period_time)
@@ -134,7 +182,7 @@ async def run_restarts_under_load(pg: Postgres, acceptors: List[WalAcceptor], n_
 
         victim.start()
 
-    print('Iterations are finished, exiting coroutines...')
+    log.info('Iterations are finished, exiting coroutines...')
     stats.running = False
     # await all workers
     await asyncio.gather(*workers)
@@ -144,7 +192,9 @@ async def run_restarts_under_load(pg: Postgres, acceptors: List[WalAcceptor], n_
 
 
 # restart acceptors one by one, while executing and validating bank transactions
-def test_restarts_under_load(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory,
+def test_restarts_under_load(zenith_cli,
+                             pageserver: ZenithPageserver,
+                             postgres: PostgresFactory,
                              wa_factory: WalAcceptorFactory):
 
     wa_factory.start_n_new(3)

test_runner/batch_others/test_zenith_cli.py

@@ -23,8 +23,11 @@ def helper_compare_branch_list(page_server_cur, zenith_cli, initial_tenant: str)
 
     res = zenith_cli.run(["branch", f"--tenantid={initial_tenant}"])
     res.check_returncode()
-    branches_cli_with_tenant_arg = sorted(map(lambda b: b.split(':')[-1].strip(), res.stdout.strip().split("\n")))
-    branches_cli_with_tenant_arg = [b for b in branches_cli if b.startswith('test_cli_') or b in ('empty', 'main')]
+    branches_cli_with_tenant_arg = sorted(
+        map(lambda b: b.split(':')[-1].strip(), res.stdout.strip().split("\n")))
+    branches_cli_with_tenant_arg = [
+        b for b in branches_cli if b.startswith('test_cli_') or b in ('empty', 'main')
+    ]
 
     assert branches_api == branches_cli == branches_cli_with_tenant_arg
 
@@ -54,6 +57,7 @@ def test_cli_branch_list(pageserver: ZenithPageserver, zenith_cli):
     assert 'test_cli_branch_list_main' in branches_cli
     assert 'test_cli_branch_list_nested' in branches_cli
 
+
 def helper_compare_tenant_list(page_server_cur, zenith_cli: ZenithCli):
     page_server_cur.execute(f'tenant_list')
     tenants_api = sorted(json.loads(page_server_cur.fetchone()[0]))

test_runner/batch_pg_regress/test_isolation.py

@@ -6,8 +6,14 @@ from fixtures.zenith_fixtures import ZenithPageserver, PostgresFactory
 pytest_plugins = ("fixtures.zenith_fixtures")
 
 
-def test_isolation(pageserver: ZenithPageserver, postgres: PostgresFactory, pg_bin, zenith_cli, test_output_dir, pg_distrib_dir,
-                   base_dir, capsys):
+def test_isolation(pageserver: ZenithPageserver,
+                   postgres: PostgresFactory,
+                   pg_bin,
+                   zenith_cli,
+                   test_output_dir,
+                   pg_distrib_dir,
+                   base_dir,
+                   capsys):
 
     # Create a branch for us
     zenith_cli.run(["branch", "test_isolation", "empty"])

test_runner/batch_pg_regress/test_pg_regress.py

@@ -6,8 +6,14 @@ from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver, check_re
 pytest_plugins = ("fixtures.zenith_fixtures")
 
 
-def test_pg_regress(pageserver: ZenithPageserver, postgres: PostgresFactory, pg_bin, zenith_cli, test_output_dir, pg_distrib_dir,
-                    base_dir, capsys):
+def test_pg_regress(pageserver: ZenithPageserver,
+                    postgres: PostgresFactory,
+                    pg_bin,
+                    zenith_cli,
+                    test_output_dir,
+                    pg_distrib_dir,
+                    base_dir,
+                    capsys):
 
     # Create a branch for us
     zenith_cli.run(["branch", "test_pg_regress", "empty"])

test_runner/batch_pg_regress/test_zenith_regress.py

@@ -2,12 +2,19 @@ import os
 
 from fixtures.utils import mkdir_if_needed
 from fixtures.zenith_fixtures import PageserverPort, PostgresFactory, check_restored_datadir_content
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures")
 
 
-def test_zenith_regress(postgres: PostgresFactory, pg_bin, zenith_cli, test_output_dir, pg_distrib_dir,
-                        base_dir, capsys, pageserver_port: PageserverPort):
+def test_zenith_regress(postgres: PostgresFactory,
+                        pg_bin,
+                        zenith_cli,
+                        test_output_dir,
+                        pg_distrib_dir,
+                        base_dir,
+                        capsys,
+                        pageserver_port: PageserverPort):
 
     # Create a branch for us
     zenith_cli.run(["branch", "test_zenith_regress", "empty"])
@@ -38,7 +45,7 @@ def test_zenith_regress(postgres: PostgresFactory, pg_bin, zenith_cli, test_outp
         '--inputdir={}'.format(src_path),
     ]
 
-    print(pg_regress_command)
+    log.info(pg_regress_command)
     env = {
         'PGPORT': str(pg.port),
         'PGUSER': pg.username,

test_runner/fixtures/benchmark_fixture.py

@@ -1,5 +1,3 @@
-from pprint import pprint
-
 import os
 import re
 import timeit
@@ -26,7 +24,6 @@ from typing import Any, Callable, Dict, Iterator, List, Optional, TypeVar, cast
 from typing_extensions import Literal
 
 from .utils import (get_self_dir, mkdir_if_needed, subprocess_capture)
-
 """
 This file contains fixtures for micro-benchmarks.
 
@@ -57,7 +54,6 @@ in the test initialization, or measure disk usage after the test query.
 
 """
 
-
 # All the results are collected in this list, as a tuple:
 # (test_name: str, metric_name: str, metric_value: float, unit: str)
 #
@@ -67,6 +63,7 @@ in the test initialization, or measure disk usage after the test query.
 global zenbenchmark_results
 zenbenchmark_results = []
 
+
 class ZenithBenchmarkResults:
     """ An object for recording benchmark results. """
     def __init__(self):
@@ -79,6 +76,7 @@ class ZenithBenchmarkResults:
 
         self.results.append((test_name, metric_name, metric_value, unit))
 
+
 # Session scope fixture that initializes the results object
 @pytest.fixture(autouse=True, scope='session')
 def zenbenchmark_global(request) -> Iterator[ZenithBenchmarkResults]:
@@ -90,6 +88,7 @@ def zenbenchmark_global(request) -> Iterator[ZenithBenchmarkResults]:
 
     yield zenbenchmark_results
 
+
 class ZenithBenchmarker:
     """
     An object for recording benchmark results. This is created for each test
@@ -105,7 +104,6 @@ class ZenithBenchmarker:
         """
         self.results.record(self.request.node.name, metric_name, metric_value, unit)
 
-
     @contextmanager
     def record_duration(self, metric_name):
         """
@@ -136,7 +134,8 @@ class ZenithBenchmarker:
         # The metric should be an integer, as it's a number of bytes. But in general
         # all prometheus metrics are floats. So to be pedantic, read it as a float
         # and round to integer.
-        matches = re.search(r'^pageserver_disk_io_bytes{io_operation="write"} (\S+)$', all_metrics,
+        matches = re.search(r'^pageserver_disk_io_bytes{io_operation="write"} (\S+)$',
+                            all_metrics,
                             re.MULTILINE)
         return int(round(float(matches.group(1))))
 
@@ -147,8 +146,7 @@ class ZenithBenchmarker:
         # Fetch all the exposed prometheus metrics from page server
         all_metrics = pageserver.http_client().get_metrics()
         # See comment in get_io_writes()
-        matches = re.search(r'^pageserver_maxrss_kb (\S+)$', all_metrics,
-                            re.MULTILINE)
+        matches = re.search(r'^pageserver_maxrss_kb (\S+)$', all_metrics, re.MULTILINE)
         return int(round(float(matches.group(1))))
 
     def get_timeline_size(self, repo_dir: str, tenantid: str, timelineid: str):
@@ -173,7 +171,11 @@ class ZenithBenchmarker:
         yield
         after = self.get_io_writes(pageserver)
 
-        self.results.record(self.request.node.name, metric_name, round((after - before) / (1024 * 1024)), 'MB')
+        self.results.record(self.request.node.name,
+                            metric_name,
+                            round((after - before) / (1024 * 1024)),
+                            'MB')
+
 
 @pytest.fixture(scope='function')
 def zenbenchmark(zenbenchmark_global, request) -> Iterator[ZenithBenchmarker]:
@@ -187,9 +189,7 @@ def zenbenchmark(zenbenchmark_global, request) -> Iterator[ZenithBenchmarker]:
 
 # Hook to print the results at the end
 @pytest.hookimpl(hookwrapper=True)
-def pytest_terminal_summary(
-    terminalreporter: TerminalReporter, exitstatus: int, config: Config
-):
+def pytest_terminal_summary(terminalreporter: TerminalReporter, exitstatus: int, config: Config):
     yield
 
     global zenbenchmark_results

test_runner/fixtures/log_helper.py

@@ -0,0 +1,45 @@
+import logging
+import logging.config
+"""
+This file configures logging to use in python tests.
+Logs are automatically captured and shown in their
+own section after all tests are executed. 
+
+To see logs for all (even successful) tests, run
+pytest with the following command:
+- `pipenv run pytest -n8 -rA`
+
+Other log config can be set in pytest.ini file.
+You can add `log_cli = true` to it to watch
+logs in real time.
+
+To get more info about logging with pytest, see
+https://docs.pytest.org/en/6.2.x/logging.html
+"""
+
+# this config is only used for default log levels,
+# log format is specified in pytest.ini file
+LOGGING = {
+    "version": 1,
+    "loggers": {
+        "root": {
+            "level": "INFO"
+        },
+        "root.wal_acceptor_async": {
+            "level": "INFO"  # a lot of logs on DEBUG level
+        }
+    }
+}
+
+
+def getLogger(name='root') -> logging.Logger:
+    """Method to get logger for tests.
+    
+    Should be used to get correctly initialized logger. """
+    return logging.getLogger(name)
+
+
+# default logger for tests
+log = getLogger()
+
+logging.config.dictConfig(LOGGING)

test_runner/fixtures/utils.py

@@ -2,6 +2,7 @@ import os
 import subprocess
 
 from typing import Any, List
+from fixtures.log_helper import log
 
 
 def get_self_dir() -> str:
@@ -39,7 +40,7 @@ def subprocess_capture(capture_dir: str, cmd: List[str], **kwargs: Any) -> str:
 
     with open(stdout_filename, 'w') as stdout_f:
         with open(stderr_filename, 'w') as stderr_f:
-            print('(capturing output to "{}.stdout")'.format(base))
+            log.info('(capturing output to "{}.stdout")'.format(base))
             subprocess.run(cmd, **kwargs, stdout=stdout_f, stderr=stderr_f)
 
     return basepath
@@ -58,14 +59,13 @@ def global_counter() -> int:
     _global_counter += 1
     return _global_counter
 
-def debug_print(*args, **kwargs) -> None:
-    """ Print to the console if TEST_DEBUG_PRINT is set in env.
-    
-    All parameters are passed to print().
-    """
-    if os.environ.get('TEST_DEBUG_PRINT') is not None:
-        print(*args, **kwargs)
 
 def lsn_to_hex(num: int) -> str:
     """ Convert lsn from int to standard hex notation. """
     return "{:X}/{:X}".format(num >> 32, num & 0xffffffff)
+
+
+def lsn_from_hex(lsn_hex: str) -> int:
+    """ Convert lsn from hex notation to int. """
+    l, r = lsn_hex.split('/')
+    return (int(l, 16) << 32) + int(r, 16)

test_runner/fixtures/zenith_fixtures.py

@@ -1,5 +1,5 @@
 from dataclasses import dataclass
-from functools import cached_property
+from cached_property import cached_property
 import asyncpg
 import os
 import pathlib
@@ -13,9 +13,8 @@ import signal
 import subprocess
 import time
 import filecmp
-import difflib
 
-from contextlib import closing
+from contextlib import closing, suppress
 from pathlib import Path
 from dataclasses import dataclass
 
@@ -27,6 +26,7 @@ from typing_extensions import Literal
 import requests
 
 from .utils import (get_self_dir, mkdir_if_needed, subprocess_capture)
+from fixtures.log_helper import log
 """
 This file contains pytest fixtures. A fixture is a test resource that can be
 summoned by placing its name in the test's arguments.
@@ -54,14 +54,15 @@ DEFAULT_POSTGRES_DIR = 'tmp_install'
 BASE_PORT = 15000
 WORKER_PORT_NUM = 100
 
+
 def pytest_configure(config):
     """
     Ensure that no unwanted daemons are running before we start testing.
     Check that we do not owerflow available ports range.
     """
     numprocesses = config.getoption('numprocesses')
-    if numprocesses is not None and BASE_PORT + numprocesses * WORKER_PORT_NUM > 32768: # do not use ephemeral ports
-         raise Exception('Too many workers configured. Cannot distrubute ports for services.')
+    if numprocesses is not None and BASE_PORT + numprocesses * WORKER_PORT_NUM > 32768:  # do not use ephemeral ports
+        raise Exception('Too many workers configured. Cannot distrubute ports for services.')
 
     # does not use -c as it is not supported on macOS
     cmd = ['pgrep', 'pageserver|postgres|safekeeper']
@@ -105,7 +106,11 @@ class PgProtocol:
         self.port = port
         self.username = username or "zenith_admin"
 
-    def connstr(self, *, dbname: str = 'postgres', username: Optional[str] = None, password: Optional[str] = None) -> str:
+    def connstr(self,
+                *,
+                dbname: str = 'postgres',
+                username: Optional[str] = None,
+                password: Optional[str] = None) -> str:
         """
         Build a libpq connection string for the Postgres instance.
         """
@@ -117,7 +122,12 @@ class PgProtocol:
         return f'{res} password={password}'
 
     # autocommit=True here by default because that's what we need most of the time
-    def connect(self, *, autocommit=True, dbname: str = 'postgres', username: Optional[str] = None, password: Optional[str] = None) -> PgConnection:
+    def connect(self,
+                *,
+                autocommit=True,
+                dbname: str = 'postgres',
+                username: Optional[str] = None,
+                password: Optional[str] = None) -> PgConnection:
         """
         Connect to the node.
         Returns psycopg2's connection object.
@@ -133,7 +143,11 @@ class PgProtocol:
         conn.autocommit = autocommit
         return conn
 
-    async def connect_async(self, *, dbname: str = 'postgres', username: Optional[str] = None, password: Optional[str] = None) -> asyncpg.Connection:
+    async def connect_async(self,
+                            *,
+                            dbname: str = 'postgres',
+                            username: Optional[str] = None,
+                            password: Optional[str] = None) -> asyncpg.Connection:
         """
         Connect to the node from async python.
         Returns asyncpg's connection object.
@@ -188,22 +202,22 @@ class ZenithCli:
 
         >>> result = zenith_cli.run(...)
         >>> assert result.stderr == ""
-        >>> print(result.stdout)
+        >>> log.info(result.stdout)
         """
 
         assert type(arguments) == list
 
         args = [self.bin_zenith] + arguments
-        print('Running command "{}"'.format(' '.join(args)))
+        log.info('Running command "{}"'.format(' '.join(args)))
 
         # Interceipt CalledProcessError and print more info
         try:
             res = subprocess.run(args,
-                                env=self.env,
-                                check=True,
-                                universal_newlines=True,
-                                stdout=subprocess.PIPE,
-                                stderr=subprocess.PIPE)
+                                 env=self.env,
+                                 check=True,
+                                 universal_newlines=True,
+                                 stdout=subprocess.PIPE,
+                                 stderr=subprocess.PIPE)
         except subprocess.CalledProcessError as exc:
             # this way command output will be in recorded and shown in CI in failure message
             msg = f"""\
@@ -211,7 +225,7 @@ class ZenithCli:
               stdout: {exc.stdout}
               stderr: {exc.stderr}
             """
-            print(msg)
+            log.info(msg)
 
             raise Exception(msg) from exc
 
@@ -241,21 +255,17 @@ class ZenithPageserverHttpClient(requests.Session):
         return res.json()
 
     def branch_create(self, tenant_id: uuid.UUID, name: str, start_point: str) -> Dict:
-        res = self.post(
-            f"http://localhost:{self.port}/v1/branch",
-            json={
-                'tenant_id': tenant_id.hex,
-                'name': name,
-                'start_point': start_point,
-            }
-        )
+        res = self.post(f"http://localhost:{self.port}/v1/branch",
+                        json={
+                            'tenant_id': tenant_id.hex,
+                            'name': name,
+                            'start_point': start_point,
+                        })
         res.raise_for_status()
         return res.json()
 
     def branch_detail(self, tenant_id: uuid.UUID, name: str) -> Dict:
-        res = self.get(
-            f"http://localhost:{self.port}/v1/branch/{tenant_id.hex}/{name}",
-        )
+        res = self.get(f"http://localhost:{self.port}/v1/branch/{tenant_id.hex}/{name}", )
         res.raise_for_status()
         return res.json()
 
@@ -297,7 +307,11 @@ class AuthKeys:
         return token
 
     def generate_tenant_token(self, tenant_id):
-        token = jwt.encode({"scope": "tenant", "tenant_id": tenant_id}, self.priv, algorithm="RS256")
+        token = jwt.encode({
+            "scope": "tenant", "tenant_id": tenant_id
+        },
+                           self.priv,
+                           algorithm="RS256")
 
         if isinstance(token, bytes):
             token = token.decode()
@@ -322,6 +336,7 @@ def worker_base_port(worker_seq_no: int):
     # so workers have disjoint set of ports for services
     return BASE_PORT + worker_seq_no * WORKER_PORT_NUM
 
+
 class PortDistributor:
     def __init__(self, base_port: int, port_number: int) -> None:
         self.iterator = iter(range(base_port, base_port + port_number))
@@ -330,13 +345,15 @@ class PortDistributor:
         try:
             return next(self.iterator)
         except StopIteration:
-            raise RuntimeError('port range configured for test is exhausted, consider enlarging the range')
+            raise RuntimeError(
+                'port range configured for test is exhausted, consider enlarging the range')
 
 
 @zenfixture
 def port_distributor(worker_base_port):
     return PortDistributor(base_port=worker_base_port, port_number=WORKER_PORT_NUM)
 
+
 @dataclass
 class PageserverPort:
     pg: int
@@ -351,14 +368,18 @@ class ZenithPageserver(PgProtocol):
         self.running = False
         self.initial_tenant = None
         self.repo_dir = repo_dir
-        self.service_port = port # do not shadow PgProtocol.port which is just int
+        self.service_port = port  # do not shadow PgProtocol.port which is just int
 
     def init(self, enable_auth: bool = False) -> 'ZenithPageserver':
         """
         Initialize the repository, i.e. run "zenith init".
         Returns self.
         """
-        cmd = ['init', f'--pageserver-pg-port={self.service_port.pg}', f'--pageserver-http-port={self.service_port.http}']
+        cmd = [
+            'init',
+            f'--pageserver-pg-port={self.service_port.pg}',
+            f'--pageserver-http-port={self.service_port.http}'
+        ]
         if enable_auth:
             cmd.append('--enable-auth')
         self.zenith_cli.run(cmd)
@@ -392,7 +413,7 @@ class ZenithPageserver(PgProtocol):
         if immediate:
             cmd.append('immediate')
 
-        print(cmd)
+        log.info(f"Stopping pageserver with {cmd}")
         if self.running:
             self.zenith_cli.run(cmd)
             self.running = False
@@ -418,18 +439,17 @@ class ZenithPageserver(PgProtocol):
         )
 
 
-
-
 @zenfixture
 def pageserver_port(port_distributor: PortDistributor) -> PageserverPort:
     pg = port_distributor.get_port()
     http = port_distributor.get_port()
-    print(f"pageserver_port: pg={pg} http={http}")
+    log.info(f"pageserver_port: pg={pg} http={http}")
     return PageserverPort(pg=pg, http=http)
 
 
 @zenfixture
-def pageserver(zenith_cli: ZenithCli, repo_dir: str, pageserver_port: PageserverPort) -> Iterator[ZenithPageserver]:
+def pageserver(zenith_cli: ZenithCli, repo_dir: str,
+               pageserver_port: PageserverPort) -> Iterator[ZenithPageserver]:
     """
     The 'pageserver' fixture provides a Page Server that's up and running.
 
@@ -441,16 +461,18 @@ def pageserver(zenith_cli: ZenithCli, repo_dir: str, pageserver_port: Pageserver
     By convention, the test branches are named after the tests. For example,
     test called 'test_foo' would create and use branches with the 'test_foo' prefix.
     """
-    ps = ZenithPageserver(zenith_cli=zenith_cli, repo_dir=repo_dir, port=pageserver_port).init().start()
+    ps = ZenithPageserver(zenith_cli=zenith_cli, repo_dir=repo_dir,
+                          port=pageserver_port).init().start()
     # For convenience in tests, create a branch from the freshly-initialized cluster.
     zenith_cli.run(["branch", "empty", "main"])
 
     yield ps
 
     # After the yield comes any cleanup code we need.
-    print('Starting pageserver cleanup')
+    log.info('Starting pageserver cleanup')
     ps.stop(True)
 
+
 class PgBin:
     """ A helper class for executing postgres binaries """
     def __init__(self, log_dir: str, pg_distrib_dir: str):
@@ -486,7 +508,7 @@ class PgBin:
         """
 
         self._fixpath(command)
-        print('Running command "{}"'.format(' '.join(command)))
+        log.info('Running command "{}"'.format(' '.join(command)))
         env = self._build_env(env)
         subprocess.run(command, env=env, cwd=cwd, check=True)
 
@@ -503,7 +525,7 @@ class PgBin:
         """
 
         self._fixpath(command)
-        print('Running command "{}"'.format(' '.join(command)))
+        log.info('Running command "{}"'.format(' '.join(command)))
         env = self._build_env(env)
         return subprocess_capture(self.log_dir, command, env=env, cwd=cwd, check=True, **kwargs)
 
@@ -512,9 +534,11 @@ class PgBin:
 def pg_bin(test_output_dir: str, pg_distrib_dir: str) -> PgBin:
     return PgBin(test_output_dir, pg_distrib_dir)
 
+
 @pytest.fixture
 def pageserver_auth_enabled(zenith_cli: ZenithCli, repo_dir: str, pageserver_port: PageserverPort):
-    with ZenithPageserver(zenith_cli=zenith_cli, repo_dir=repo_dir, port=pageserver_port).init(enable_auth=True).start() as ps:
+    with ZenithPageserver(zenith_cli=zenith_cli, repo_dir=repo_dir,
+                          port=pageserver_port).init(enable_auth=True).start() as ps:
         # For convenience in tests, create a branch from the freshly-initialized cluster.
         zenith_cli.run(["branch", "empty", "main"])
         yield ps
@@ -522,21 +546,27 @@ def pageserver_auth_enabled(zenith_cli: ZenithCli, repo_dir: str, pageserver_por
 
 class Postgres(PgProtocol):
     """ An object representing a running postgres daemon. """
-    def __init__(self, zenith_cli: ZenithCli, repo_dir: str, pg_bin: PgBin, tenant_id: str, port: int):
+    def __init__(self,
+                 zenith_cli: ZenithCli,
+                 repo_dir: str,
+                 pg_bin: PgBin,
+                 tenant_id: str,
+                 port: int):
         super().__init__(host='localhost', port=port)
 
         self.zenith_cli = zenith_cli
         self.running = False
         self.repo_dir = repo_dir
-        self.branch: Optional[str] = None  # dubious, see asserts below
-        self.pgdata_dir: Optional[str] = None # Path to computenode PGDATA
+        self.node_name: Optional[str] = None  # dubious, see asserts below
+        self.pgdata_dir: Optional[str] = None  # Path to computenode PGDATA
         self.tenant_id = tenant_id
         self.pg_bin = pg_bin
-        # path to conf is <repo_dir>/pgdatadirs/tenants/<tenant_id>/<branch_name>/postgresql.conf
+        # path to conf is <repo_dir>/pgdatadirs/tenants/<tenant_id>/<node_name>/postgresql.conf
 
     def create(
         self,
-        branch: str,
+        node_name: str,
+        branch: Optional[str] = None,
         wal_acceptors: Optional[str] = None,
         config_lines: Optional[List[str]] = None,
     ) -> 'Postgres':
@@ -550,9 +580,19 @@ class Postgres(PgProtocol):
         if not config_lines:
             config_lines = []
 
-        self.zenith_cli.run(['pg', 'create', branch, f'--tenantid={self.tenant_id}', f'--port={self.port}'])
-        self.branch = branch
-        path = pathlib.Path('pgdatadirs') / 'tenants' / self.tenant_id / self.branch
+        if branch is None:
+            branch = node_name
+
+        self.zenith_cli.run([
+            'pg',
+            'create',
+            f'--tenantid={self.tenant_id}',
+            f'--port={self.port}',
+            node_name,
+            branch
+        ])
+        self.node_name = node_name
+        path = pathlib.Path('pgdatadirs') / 'tenants' / self.tenant_id / self.node_name
         self.pgdata_dir = os.path.join(self.repo_dir, path)
 
         if wal_acceptors is not None:
@@ -569,20 +609,21 @@ class Postgres(PgProtocol):
         Returns self.
         """
 
-        assert self.branch is not None
+        assert self.node_name is not None
 
-        print(f"Starting postgres on branch {self.branch}")
+        log.info(f"Starting postgres node {self.node_name}")
 
-        run_result = self.zenith_cli.run(['pg', 'start', self.branch, f'--tenantid={self.tenant_id}', f'--port={self.port}'])
+        run_result = self.zenith_cli.run(
+            ['pg', 'start', f'--tenantid={self.tenant_id}', f'--port={self.port}', self.node_name])
         self.running = True
 
-        print(f"stdout: {run_result.stdout}")
+        log.info(f"stdout: {run_result.stdout}")
 
         return self
 
     def pg_data_dir_path(self) -> str:
         """ Path to data directory """
-        path = pathlib.Path('pgdatadirs') / 'tenants' / self.tenant_id / self.branch
+        path = pathlib.Path('pgdatadirs') / 'tenants' / self.tenant_id / self.node_name
         return os.path.join(self.repo_dir, path)
 
     def pg_xact_dir_path(self) -> str:
@@ -639,8 +680,8 @@ class Postgres(PgProtocol):
         """
 
         if self.running:
-            assert self.branch is not None
-            self.zenith_cli.run(['pg', 'stop', self.branch, f'--tenantid={self.tenant_id}'])
+            assert self.node_name is not None
+            self.zenith_cli.run(['pg', 'stop', self.node_name, f'--tenantid={self.tenant_id}'])
             self.running = False
 
         return self
@@ -651,15 +692,17 @@ class Postgres(PgProtocol):
         Returns self.
         """
 
-        assert self.branch is not None
+        assert self.node_name is not None
         assert self.tenant_id is not None
-        self.zenith_cli.run(['pg', 'stop', '--destroy', self.branch, f'--tenantid={self.tenant_id}'])
+        self.zenith_cli.run(
+            ['pg', 'stop', '--destroy', self.node_name, f'--tenantid={self.tenant_id}'])
 
         return self
 
     def create_start(
         self,
-        branch: str,
+        node_name: str,
+        branch: Optional[str] = None,
         wal_acceptors: Optional[str] = None,
         config_lines: Optional[List[str]] = None,
     ) -> 'Postgres':
@@ -670,6 +713,7 @@ class Postgres(PgProtocol):
         """
 
         self.create(
+            node_name=node_name,
             branch=branch,
             wal_acceptors=wal_acceptors,
             config_lines=config_lines,
@@ -683,9 +727,15 @@ class Postgres(PgProtocol):
     def __exit__(self, exc_type, exc, tb):
         self.stop()
 
+
 class PostgresFactory:
     """ An object representing multiple running postgres daemons. """
-    def __init__(self, zenith_cli: ZenithCli, repo_dir: str, pg_bin: PgBin, initial_tenant: str, port_distributor: PortDistributor):
+    def __init__(self,
+                 zenith_cli: ZenithCli,
+                 repo_dir: str,
+                 pg_bin: PgBin,
+                 initial_tenant: str,
+                 port_distributor: PortDistributor):
         self.zenith_cli = zenith_cli
         self.repo_dir = repo_dir
         self.num_instances = 0
@@ -694,13 +744,13 @@ class PostgresFactory:
         self.port_distributor = port_distributor
         self.pg_bin = pg_bin
 
-    def create_start(
-        self,
-        branch: str = "main",
-        tenant_id: Optional[str] = None,
-        wal_acceptors: Optional[str] = None,
-        config_lines: Optional[List[str]] = None
-    ) -> Postgres:
+    def create_start(self,
+                     node_name: str = "main",
+                     branch: Optional[str] = None,
+                     tenant_id: Optional[str] = None,
+                     wal_acceptors: Optional[str] = None,
+                     config_lines: Optional[List[str]] = None) -> Postgres:
+
         pg = Postgres(
             zenith_cli=self.zenith_cli,
             repo_dir=self.repo_dir,
@@ -712,18 +762,18 @@ class PostgresFactory:
         self.instances.append(pg)
 
         return pg.create_start(
+            node_name=node_name,
             branch=branch,
             wal_acceptors=wal_acceptors,
             config_lines=config_lines,
         )
 
-    def create(
-        self,
-        branch: str = "main",
-        tenant_id: Optional[str] = None,
-        wal_acceptors: Optional[str] = None,
-        config_lines: Optional[List[str]] = None
-    ) -> Postgres:
+    def create(self,
+               node_name: str = "main",
+               branch: Optional[str] = None,
+               tenant_id: Optional[str] = None,
+               wal_acceptors: Optional[str] = None,
+               config_lines: Optional[List[str]] = None) -> Postgres:
 
         pg = Postgres(
             zenith_cli=self.zenith_cli,
@@ -737,18 +787,17 @@ class PostgresFactory:
         self.instances.append(pg)
 
         return pg.create(
+            node_name=node_name,
             branch=branch,
             wal_acceptors=wal_acceptors,
             config_lines=config_lines,
         )
 
-    def config(
-        self,
-        branch: str = "main",
-        tenant_id: Optional[str] = None,
-        wal_acceptors: Optional[str] = None,
-        config_lines: Optional[List[str]] = None
-    ) -> Postgres:
+    def config(self,
+               node_name: str = "main",
+               tenant_id: Optional[str] = None,
+               wal_acceptors: Optional[str] = None,
+               config_lines: Optional[List[str]] = None) -> Postgres:
 
         pg = Postgres(
             zenith_cli=self.zenith_cli,
@@ -762,7 +811,7 @@ class PostgresFactory:
         self.instances.append(pg)
 
         return pg.config(
-            branch=branch,
+            node_name=node_name,
             wal_acceptors=wal_acceptors,
             config_lines=config_lines,
         )
@@ -773,13 +822,18 @@ class PostgresFactory:
 
         return self
 
+
 @zenfixture
 def initial_tenant(pageserver: ZenithPageserver):
     return pageserver.initial_tenant
 
 
 @zenfixture
-def postgres(zenith_cli: ZenithCli, initial_tenant: str, repo_dir: str, pg_bin: PgBin, port_distributor: PortDistributor) -> Iterator[PostgresFactory]:
+def postgres(zenith_cli: ZenithCli,
+             initial_tenant: str,
+             repo_dir: str,
+             pg_bin: PgBin,
+             port_distributor: PortDistributor) -> Iterator[PostgresFactory]:
     pgfactory = PostgresFactory(
         zenith_cli=zenith_cli,
         repo_dir=repo_dir,
@@ -791,9 +845,10 @@ def postgres(zenith_cli: ZenithCli, initial_tenant: str, repo_dir: str, pg_bin:
     yield pgfactory
 
     # After the yield comes any cleanup code we need.
-    print('Starting postgres cleanup')
+    log.info('Starting postgres cleanup')
     pgfactory.stop_all()
 
+
 def read_pid(path: Path):
     """ Read content of file into number """
     return int(path.read_text())
@@ -804,20 +859,22 @@ class WalAcceptorPort:
     pg: int
     http: int
 
+
 @dataclass
 class WalAcceptor:
     """ An object representing a running wal acceptor daemon. """
     wa_bin_path: Path
     data_dir: Path
     port: WalAcceptorPort
-    num: int # identifier for logging
+    num: int  # identifier for logging
     pageserver_port: int
     auth_token: Optional[str] = None
 
     def start(self) -> 'WalAcceptor':
         # create data directory if not exists
         self.data_dir.mkdir(parents=True, exist_ok=True)
-        self.pidfile.unlink(missing_ok=True)
+        with suppress(FileNotFoundError):
+            self.pidfile.unlink()
 
         cmd = [str(self.wa_bin_path)]
         cmd.extend(["-D", str(self.data_dir)])
@@ -828,18 +885,25 @@ class WalAcceptor:
         # Tell page server it can receive WAL from this WAL safekeeper
         cmd.extend(["--pageserver", f"localhost:{self.pageserver_port}"])
         cmd.extend(["--recall", "1 second"])
-        print('Running command "{}"'.format(' '.join(cmd)))
+        log.info('Running command "{}"'.format(' '.join(cmd)))
         env = {'PAGESERVER_AUTH_TOKEN': self.auth_token} if self.auth_token else None
         subprocess.run(cmd, check=True, env=env)
 
-        # wait for wal acceptor start by checkking that pid is readable
-        for _ in range(3):
-            pid = self.get_pid()
-            if pid is not None:
-                return self
-            time.sleep(0.5)
-
-        raise RuntimeError("cannot get wal acceptor pid")
+        # wait for wal acceptor start by checking its status
+        started_at = time.time()
+        while True:
+            try:
+                http_cli = self.http_client()
+                http_cli.check_status()
+            except Exception as e:
+                elapsed = time.time() - started_at
+                if elapsed > 3:
+                    raise RuntimeError(
+                        f"timed out waiting {elapsed:.0f}s for wal acceptor start: {e}")
+                time.sleep(0.5)
+            else:
+                break  # success
+        return self
 
     @property
     def pidfile(self) -> Path:
@@ -857,20 +921,21 @@ class WalAcceptor:
         return pid
 
     def stop(self) -> 'WalAcceptor':
-        print('Stopping wal acceptor {}'.format(self.num))
+        log.info('Stopping wal acceptor {}'.format(self.num))
         pid = self.get_pid()
         if pid is None:
-            print("Wal acceptor {} is not running".format(self.num))
+            log.info("Wal acceptor {} is not running".format(self.num))
             return self
 
         try:
             os.kill(pid, signal.SIGTERM)
         except Exception:
             # TODO: cleanup pid file on exit in wal acceptor
-            pass # pidfile might be obsolete
+            pass  # pidfile might be obsolete
         return self
 
-    def append_logical_message(self, tenant_id: str, timeline_id: str, request: Dict[str, Any]) -> Dict[str, Any]:
+    def append_logical_message(self, tenant_id: str, timeline_id: str,
+                               request: Dict[str, Any]) -> Dict[str, Any]:
         """
         Send JSON_CTRL query to append LogicalMessage to WAL and modify 
         safekeeper state. It will construct LogicalMessage from provided
@@ -886,15 +951,23 @@ class WalAcceptor:
             conn.autocommit = True
             with conn.cursor() as cur:
                 request_json = json.dumps(request)
-                print(f"JSON_CTRL request on port {self.port.pg}: {request_json}")
+                log.info(f"JSON_CTRL request on port {self.port.pg}: {request_json}")
                 cur.execute("JSON_CTRL " + request_json)
                 all = cur.fetchall()
-                print(f"JSON_CTRL response: {all[0][0]}")
+                log.info(f"JSON_CTRL response: {all[0][0]}")
                 return json.loads(all[0][0])
 
+    def http_client(self):
+        return WalAcceptorHttpClient(port=self.port.http)
+
+
 class WalAcceptorFactory:
     """ An object representing multiple running wal acceptors. """
-    def __init__(self, zenith_binpath: Path, data_dir: Path, pageserver_port: int, port_distributor: PortDistributor):
+    def __init__(self,
+                 zenith_binpath: Path,
+                 data_dir: Path,
+                 pageserver_port: int,
+                 port_distributor: PortDistributor):
         self.wa_bin_path = zenith_binpath / 'safekeeper'
         self.data_dir = data_dir
         self.instances: List[WalAcceptor] = []
@@ -940,7 +1013,10 @@ class WalAcceptorFactory:
 
 
 @zenfixture
-def wa_factory(zenith_binpath: str, repo_dir: str, pageserver_port: PageserverPort, port_distributor: PortDistributor) -> Iterator[WalAcceptorFactory]:
+def wa_factory(zenith_binpath: str,
+               repo_dir: str,
+               pageserver_port: PageserverPort,
+               port_distributor: PortDistributor) -> Iterator[WalAcceptorFactory]:
     """ Gives WalAcceptorFactory providing wal acceptors. """
     wafactory = WalAcceptorFactory(
         zenith_binpath=Path(zenith_binpath),
@@ -950,16 +1026,38 @@ def wa_factory(zenith_binpath: str, repo_dir: str, pageserver_port: PageserverPo
     )
     yield wafactory
     # After the yield comes any cleanup code we need.
-    print('Starting wal acceptors cleanup')
+    log.info('Starting wal acceptors cleanup')
     wafactory.stop_all()
 
 
+@dataclass
+class SafekeeperTimelineStatus:
+    acceptor_epoch: int
+    flush_lsn: str
+
+
+class WalAcceptorHttpClient(requests.Session):
+    def __init__(self, port: int) -> None:
+        super().__init__()
+        self.port = port
+
+    def check_status(self):
+        self.get(f"http://localhost:{self.port}/v1/status").raise_for_status()
+
+    def timeline_status(self, tenant_id: str, timeline_id: str) -> SafekeeperTimelineStatus:
+        res = self.get(f"http://localhost:{self.port}/v1/timeline/{tenant_id}/{timeline_id}")
+        res.raise_for_status()
+        resj = res.json()
+        return SafekeeperTimelineStatus(acceptor_epoch=resj['acceptor_state']['epoch'],
+                                        flush_lsn=resj['flush_lsn'])
+
+
 @zenfixture
 def base_dir() -> str:
     """ find the base directory (currently this is the git root) """
 
     base_dir = os.path.normpath(os.path.join(get_self_dir(), '../..'))
-    print('\nbase_dir is', base_dir)
+    log.info(f'base_dir is {base_dir}')
     return base_dir
 
 
@@ -988,7 +1086,7 @@ def test_output_dir(request: Any, top_output_dir: str) -> str:
         test_name = 'shared'
 
     test_output_dir = os.path.join(top_output_dir, test_name)
-    print('test_output_dir is', test_output_dir)
+    log.info(f'test_output_dir is {test_output_dir}')
     shutil.rmtree(test_output_dir, ignore_errors=True)
     mkdir_if_needed(test_output_dir)
     return test_output_dir
@@ -1030,7 +1128,7 @@ def pg_distrib_dir(base_dir: str) -> str:
         pg_dir = env_postgres_bin
     else:
         pg_dir = os.path.normpath(os.path.join(base_dir, DEFAULT_POSTGRES_DIR))
-    print('postgres dir is', pg_dir)
+    log.info(f'postgres dir is {pg_dir}')
     if not os.path.exists(os.path.join(pg_dir, 'bin/postgres')):
         raise Exception('postgres not found at "{}"'.format(pg_dir))
     return pg_dir
@@ -1052,6 +1150,7 @@ class TenantFactory:
 def tenant_factory(zenith_cli: ZenithCli):
     return TenantFactory(zenith_cli)
 
+
 #
 # Test helpers
 #
@@ -1062,18 +1161,29 @@ def list_files_to_compare(pgdata_dir: str):
             rel_dir = os.path.relpath(root, pgdata_dir)
             # Skip some dirs and files we don't want to compare
             skip_dirs = ['pg_wal', 'pg_stat', 'pg_stat_tmp', 'pg_subtrans', 'pg_logical']
-            skip_files = ['pg_internal.init', 'pg.log', 'zenith.signal', 'postgresql.conf',
-                        'postmaster.opts', 'postmaster.pid', 'pg_control']
+            skip_files = [
+                'pg_internal.init',
+                'pg.log',
+                'zenith.signal',
+                'postgresql.conf',
+                'postmaster.opts',
+                'postmaster.pid',
+                'pg_control'
+            ]
             if rel_dir not in skip_dirs and filename not in skip_files:
                 rel_file = os.path.join(rel_dir, filename)
                 pgdata_files.append(rel_file)
 
     pgdata_files.sort()
-    print(pgdata_files)
+    log.info(pgdata_files)
     return pgdata_files
 
+
 # pg is the existing and running compute node, that we want to compare with a basebackup
-def check_restored_datadir_content(zenith_cli: ZenithCli, test_output_dir: str, pg: Postgres, pageserver_pg_port: int):
+def check_restored_datadir_content(zenith_cli: ZenithCli,
+                                   test_output_dir: str,
+                                   pg: Postgres,
+                                   pageserver_pg_port: int):
 
     # Get the timeline ID of our branch. We need it for the 'basebackup' command
     with closing(pg.connect()) as conn:
@@ -1085,7 +1195,7 @@ def check_restored_datadir_content(zenith_cli: ZenithCli, test_output_dir: str,
     pg.stop()
 
     # Take a basebackup from pageserver
-    restored_dir_path = os.path.join(test_output_dir, f"{pg.branch}_restored_datadir")
+    restored_dir_path = os.path.join(test_output_dir, f"{pg.node_name}_restored_datadir")
     mkdir_if_needed(restored_dir_path)
 
     psql_path = os.path.join(pg.pg_bin.pg_bin_path, 'psql')
@@ -1115,9 +1225,7 @@ def check_restored_datadir_content(zenith_cli: ZenithCli, test_output_dir: str,
                                                 restored_dir_path,
                                                 pgdata_files,
                                                 shallow=False)
-    print('filecmp result mismatch and error lists:')
-    print(mismatch)
-    print(error)
+    log.info(f'filecmp result mismatch and error lists:\n\t mismatch={mismatch}\n\t error={error}')
 
     for f in mismatch:
 

test_runner/netstat-script.sh

@@ -0,0 +1,8 @@
+#!/bin/bash
+
+while true; do
+  echo -n "==== CURRENT TIME:" >> /tmp/test_output/netstat.stdout
+  date +"%T.%N" >> /tmp/test_output/netstat.stdout
+  sudo netstat -vpnoa | grep tcp | sort >> /tmp/test_output/netstat.stdout
+  sleep 0.5
+done

test_runner/performance/test_bulk_insert.py

@@ -1,9 +1,11 @@
 import os
 from contextlib import closing
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures", "fixtures.benchmark_fixture")
 
+
 #
 # Run bulk INSERT test.
 #
@@ -14,16 +16,21 @@ pytest_plugins = ("fixtures.zenith_fixtures", "fixtures.benchmark_fixture")
 # 3. Disk space used
 # 4. Peak memory usage
 #
-def test_bulk_insert(postgres: PostgresFactory, pageserver: ZenithPageserver, pg_bin, zenith_cli, zenbenchmark, repo_dir: str):
+def test_bulk_insert(postgres: PostgresFactory,
+                     pageserver: ZenithPageserver,
+                     pg_bin,
+                     zenith_cli,
+                     zenbenchmark,
+                     repo_dir: str):
     # Create a branch for us
     zenith_cli.run(["branch", "test_bulk_insert", "empty"])
 
     pg = postgres.create_start('test_bulk_insert')
-    print("postgres is running on 'test_bulk_insert' branch")
+    log.info("postgres is running on 'test_bulk_insert' branch")
 
     # Open a connection directly to the page server that we'll use to force
     # flushing the layers to disk
-    psconn = pageserver.connect();
+    psconn = pageserver.connect()
     pscur = psconn.cursor()
 
     # Get the timeline ID of our branch. We need it for the 'do_gc' command
@@ -47,5 +54,7 @@ def test_bulk_insert(postgres: PostgresFactory, pageserver: ZenithPageserver, pg
             zenbenchmark.record("peak_mem", zenbenchmark.get_peak_mem(pageserver) / 1024, 'MB')
 
             # Report disk space used by the repository
-            timeline_size = zenbenchmark.get_timeline_size(repo_dir, pageserver.initial_tenant, timeline)
-            zenbenchmark.record('size', timeline_size / (1024*1024), 'MB')
+            timeline_size = zenbenchmark.get_timeline_size(repo_dir,
+                                                           pageserver.initial_tenant,
+                                                           timeline)
+            zenbenchmark.record('size', timeline_size / (1024 * 1024), 'MB')

test_runner/performance/test_bulk_tenant_create.py

@@ -37,7 +37,9 @@ def test_bulk_tenant_create(
 
         tenant = tenant_factory.create()
         zenith_cli.run([
-            "branch", f"test_bulk_tenant_create_{tenants_count}_{i}_{use_wal_acceptors}", "main",
+            "branch",
+            f"test_bulk_tenant_create_{tenants_count}_{i}_{use_wal_acceptors}",
+            "main",
             f"--tenantid={tenant}"
         ])
 
@@ -46,6 +48,7 @@ def test_bulk_tenant_create(
 
         pg_tenant = postgres.create_start(
             f"test_bulk_tenant_create_{tenants_count}_{i}_{use_wal_acceptors}",
+            None,  # branch name, None means same as node name
             tenant,
             wal_acceptors=wa_factory.get_connstrs() if use_wal_acceptors == 'with_wa' else None,
         )

test_runner/performance/test_gist_build.py

@@ -1,24 +1,31 @@
 import os
 from contextlib import closing
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures", "fixtures.benchmark_fixture")
 
+
 #
 # Test buffering GisT build. It WAL-logs the whole relation, in 32-page chunks.
 # As of this writing, we're duplicate those giant WAL records for each page,
 # which makes the delta layer about 32x larger than it needs to be.
 #
-def test_gist_buffering_build(postgres: PostgresFactory, pageserver: ZenithPageserver, pg_bin, zenith_cli, zenbenchmark, repo_dir: str):
+def test_gist_buffering_build(postgres: PostgresFactory,
+                              pageserver: ZenithPageserver,
+                              pg_bin,
+                              zenith_cli,
+                              zenbenchmark,
+                              repo_dir: str):
     # Create a branch for us
     zenith_cli.run(["branch", "test_gist_buffering_build", "empty"])
 
     pg = postgres.create_start('test_gist_buffering_build')
-    print("postgres is running on 'test_gist_buffering_build' branch")
+    log.info("postgres is running on 'test_gist_buffering_build' branch")
 
     # Open a connection directly to the page server that we'll use to force
     # flushing the layers to disk
-    psconn = pageserver.connect();
+    psconn = pageserver.connect()
     pscur = psconn.cursor()
 
     # Get the timeline ID of our branch. We need it for the 'do_gc' command
@@ -28,13 +35,17 @@ def test_gist_buffering_build(postgres: PostgresFactory, pageserver: ZenithPages
             timeline = cur.fetchone()[0]
 
             # Create test table.
-            cur.execute("create table gist_point_tbl(id int4, p point)");
-            cur.execute("insert into gist_point_tbl select g, point(g, g) from generate_series(1, 1000000) g;");
+            cur.execute("create table gist_point_tbl(id int4, p point)")
+            cur.execute(
+                "insert into gist_point_tbl select g, point(g, g) from generate_series(1, 1000000) g;"
+            )
 
             # Build the index.
             with zenbenchmark.record_pageserver_writes(pageserver, 'pageserver_writes'):
                 with zenbenchmark.record_duration('build'):
-                    cur.execute("create index gist_pointidx2 on gist_point_tbl using gist(p) with (buffering = on)");
+                    cur.execute(
+                        "create index gist_pointidx2 on gist_point_tbl using gist(p) with (buffering = on)"
+                    )
 
                     # Flush the layers from memory to disk. This is included in the reported
                     # time and I/O
@@ -44,5 +55,7 @@ def test_gist_buffering_build(postgres: PostgresFactory, pageserver: ZenithPages
             zenbenchmark.record("peak_mem", zenbenchmark.get_peak_mem(pageserver) / 1024, 'MB')
 
             # Report disk space used by the repository
-            timeline_size = zenbenchmark.get_timeline_size(repo_dir, pageserver.initial_tenant, timeline)
-            zenbenchmark.record('size', timeline_size / (1024*1024), 'MB')
+            timeline_size = zenbenchmark.get_timeline_size(repo_dir,
+                                                           pageserver.initial_tenant,
+                                                           timeline)
+            zenbenchmark.record('size', timeline_size / (1024 * 1024), 'MB')

test_runner/performance/test_perf_pgbench.py

@@ -1,9 +1,11 @@
 import os
 from contextlib import closing
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures", "fixtures.benchmark_fixture")
 
+
 #
 # Run a very short pgbench test.
 #
@@ -13,16 +15,21 @@ pytest_plugins = ("fixtures.zenith_fixtures", "fixtures.benchmark_fixture")
 # 2. Time to run 5000 pgbench transactions
 # 3. Disk space used
 #
-def test_pgbench(postgres: PostgresFactory, pageserver: ZenithPageserver, pg_bin, zenith_cli, zenbenchmark, repo_dir: str):
+def test_pgbench(postgres: PostgresFactory,
+                 pageserver: ZenithPageserver,
+                 pg_bin,
+                 zenith_cli,
+                 zenbenchmark,
+                 repo_dir: str):
     # Create a branch for us
     zenith_cli.run(["branch", "test_pgbench_perf", "empty"])
 
     pg = postgres.create_start('test_pgbench_perf')
-    print("postgres is running on 'test_pgbench_perf' branch")
+    log.info("postgres is running on 'test_pgbench_perf' branch")
 
     # Open a connection directly to the page server that we'll use to force
     # flushing the layers to disk
-    psconn = pageserver.connect();
+    psconn = pageserver.connect()
     pscur = psconn.cursor()
 
     # Get the timeline ID of our branch. We need it for the 'do_gc' command
@@ -52,4 +59,4 @@ def test_pgbench(postgres: PostgresFactory, pageserver: ZenithPageserver, pg_bin
 
     # Report disk space used by the repository
     timeline_size = zenbenchmark.get_timeline_size(repo_dir, pageserver.initial_tenant, timeline)
-    zenbenchmark.record('size', timeline_size / (1024*1024), 'MB')
+    zenbenchmark.record('size', timeline_size / (1024 * 1024), 'MB')

test_runner/performance/test_write_amplification.py

@@ -13,19 +13,26 @@
 import os
 from contextlib import closing
 from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver
+from fixtures.log_helper import log
 
 pytest_plugins = ("fixtures.zenith_fixtures", "fixtures.benchmark_fixture")
 
-def test_write_amplification(postgres: PostgresFactory, pageserver: ZenithPageserver, pg_bin, zenith_cli, zenbenchmark, repo_dir: str):
+
+def test_write_amplification(postgres: PostgresFactory,
+                             pageserver: ZenithPageserver,
+                             pg_bin,
+                             zenith_cli,
+                             zenbenchmark,
+                             repo_dir: str):
     # Create a branch for us
     zenith_cli.run(["branch", "test_write_amplification", "empty"])
 
     pg = postgres.create_start('test_write_amplification')
-    print("postgres is running on 'test_write_amplification' branch")
+    log.info("postgres is running on 'test_write_amplification' branch")
 
     # Open a connection directly to the page server that we'll use to force
     # flushing the layers to disk
-    psconn = pageserver.connect();
+    psconn = pageserver.connect()
     pscur = psconn.cursor()
 
     with closing(pg.connect()) as conn:
@@ -70,5 +77,7 @@ def test_write_amplification(postgres: PostgresFactory, pageserver: ZenithPagese
                         pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0")
 
             # Report disk space used by the repository
-            timeline_size = zenbenchmark.get_timeline_size(repo_dir, pageserver.initial_tenant, timeline)
-            zenbenchmark.record('size', timeline_size / (1024*1024), 'MB')
+            timeline_size = zenbenchmark.get_timeline_size(repo_dir,
+                                                           pageserver.initial_tenant,
+                                                           timeline)
+            zenbenchmark.record('size', timeline_size / (1024 * 1024), 'MB')

test_runner/pytest.ini

@@ -1,2 +1,4 @@
 [pytest]
 minversion = 6.0
+log_format = %(asctime)s.%(msecs)-3d %(levelname)s [%(filename)s:%(lineno)d] %(message)s
+log_date_format = %Y-%m-%d %H:%M:%S

test_runner/setup.cfg

@@ -10,6 +10,7 @@ max-line-length = 100
 [yapf]
 based_on_style = pep8
 column_limit = 100
+split_all_top_level_comma_separated_values = true
 
 [mypy]
 # some tests don't typecheck when this flag is set

test_runner/test_broken.py

@@ -1,6 +1,8 @@
 import pytest
 import os
 
+from fixtures.log_helper import log
+
 pytest_plugins = ("fixtures.zenith_fixtures")
 """
 Use this test to see what happens when tests fail.
@@ -22,7 +24,7 @@ def test_broken(zenith_cli, pageserver, postgres, pg_bin):
     zenith_cli.run(["branch", "test_broken", "empty"])
 
     postgres.create_start("test_broken")
-    print('postgres is running')
+    log.info('postgres is running')
 
-    print('THIS NEXT COMMAND WILL FAIL:')
+    log.info('THIS NEXT COMMAND WILL FAIL:')
     pg_bin.run('pgbench -i_am_a_broken_test'.split())

walkeeper/Cargo.toml

@@ -11,6 +11,8 @@ regex = "1.4.5"
 bincode = "1.3"
 bytes = "1.0.1"
 byteorder = "1.4.3"
+hyper = "0.14"
+routerify = "2"
 fs2 = "0.4.3"
 lazy_static = "1.4.0"
 serde_json = "1"

walkeeper/src/bin/safekeeper.rs

@@ -14,6 +14,7 @@ use zenith_utils::http::endpoint;
 use zenith_utils::logging;
 
 use walkeeper::defaults::{DEFAULT_HTTP_LISTEN_ADDR, DEFAULT_PG_LISTEN_ADDR};
+use walkeeper::http;
 use walkeeper::s3_offload;
 use walkeeper::wal_service;
 use walkeeper::WalAcceptorConf;
@@ -164,11 +165,12 @@ fn start_wal_acceptor(conf: WalAcceptorConf) -> Result<()> {
 
     let mut threads = Vec::new();
 
+    let conf_cloned = conf.clone();
     let http_endpoint_thread = thread::Builder::new()
         .name("http_endpoint_thread".into())
         .spawn(|| {
-            // No authentication at all: read-only metrics only, early stage.
-            let router = endpoint::make_router();
+            // TODO authentication
+            let router = http::make_router(conf_cloned);
             endpoint::serve_thread_main(router, http_listener).unwrap();
         })
         .unwrap();

walkeeper/src/http/mod.rs

@@ -0,0 +1,2 @@
+pub mod routes;
+pub use routes::make_router;

walkeeper/src/http/routes.rs

@@ -0,0 +1,92 @@
+use hyper::{Body, Request, Response, StatusCode};
+use routerify::ext::RequestExt;
+use routerify::RouterBuilder;
+use serde::Serialize;
+use serde::Serializer;
+use std::fmt::Display;
+use std::sync::Arc;
+use zenith_utils::lsn::Lsn;
+
+use crate::safekeeper::AcceptorState;
+use crate::timeline::CreateControlFile;
+use crate::timeline::GlobalTimelines;
+use crate::WalAcceptorConf;
+use zenith_utils::http::endpoint;
+use zenith_utils::http::error::ApiError;
+use zenith_utils::http::json::json_response;
+use zenith_utils::http::request::parse_request_param;
+use zenith_utils::zid::{ZTenantId, ZTimelineId};
+
+/// Healthcheck handler.
+async fn status_handler(_: Request<Body>) -> Result<Response<Body>, ApiError> {
+    Ok(json_response(StatusCode::OK, "")?)
+}
+
+fn get_conf(request: &Request<Body>) -> &WalAcceptorConf {
+    request
+        .data::<Arc<WalAcceptorConf>>()
+        .expect("unknown state type")
+        .as_ref()
+}
+
+fn display_serialize<S, F>(z: &F, s: S) -> Result<S::Ok, S::Error>
+where
+    S: Serializer,
+    F: Display,
+{
+    s.serialize_str(&format!("{}", z))
+}
+
+/// Info about timeline on safekeeper ready for reporting.
+#[derive(Debug, Serialize)]
+struct TimelineStatus {
+    #[serde(serialize_with = "display_serialize")]
+    tenant_id: ZTenantId,
+    #[serde(serialize_with = "display_serialize")]
+    timeline_id: ZTimelineId,
+    acceptor_state: AcceptorState,
+    #[serde(serialize_with = "display_serialize")]
+    commit_lsn: Lsn,
+    #[serde(serialize_with = "display_serialize")]
+    truncate_lsn: Lsn,
+    #[serde(serialize_with = "display_serialize")]
+    flush_lsn: Lsn,
+}
+
+/// Report info about timeline.
+async fn timeline_status_handler(request: Request<Body>) -> Result<Response<Body>, ApiError> {
+    let tenant_id: ZTenantId = parse_request_param(&request, "tenant_id")?;
+    let timeline_id: ZTimelineId = parse_request_param(&request, "timeline_id")?;
+
+    let tli = GlobalTimelines::get(
+        get_conf(&request),
+        tenant_id,
+        timeline_id,
+        CreateControlFile::False,
+    )
+    .map_err(ApiError::from_err)?;
+    let sk_state = tli.get_info();
+    let (flush_lsn, _) = tli.get_end_of_wal();
+
+    let status = TimelineStatus {
+        tenant_id,
+        timeline_id,
+        acceptor_state: sk_state.acceptor_state,
+        commit_lsn: sk_state.commit_lsn,
+        truncate_lsn: sk_state.truncate_lsn,
+        flush_lsn,
+    };
+    Ok(json_response(StatusCode::OK, status)?)
+}
+
+/// Safekeeper http router.
+pub fn make_router(conf: WalAcceptorConf) -> RouterBuilder<hyper::Body, ApiError> {
+    let router = endpoint::make_router();
+    router
+        .data(Arc::new(conf))
+        .get("/v1/status", status_handler)
+        .get(
+            "/v1/timeline/:tenant_id/:timeline_id",
+            timeline_status_handler,
+        )
+}

walkeeper/src/lib.rs

@@ -2,6 +2,7 @@
 use std::path::PathBuf;
 use std::time::Duration;
 
+pub mod http;
 pub mod json_ctrl;
 pub mod receive_wal;
 pub mod replication;

walkeeper/src/safekeeper.rs

@@ -290,13 +290,13 @@ lazy_static! {
         "Current flush_lsn, grouped by timeline",
         &["ztli"]
     )
-    .expect("Failed to register safekeeper_flush_lsn int gauge vec");
+    .expect("Failed to register safekeeper_flush_lsn gauge vec");
     static ref COMMIT_LSN_GAUGE: GaugeVec = register_gauge_vec!(
         "safekeeper_commit_lsn",
         "Current commit_lsn (not necessarily persisted to disk), grouped by timeline",
         &["ztli"]
     )
-    .expect("Failed to register safekeeper_commit_lsn int gauge vec");
+    .expect("Failed to register safekeeper_commit_lsn gauge vec");
 }
 
 struct SafeKeeperMetrics {
@@ -312,6 +312,13 @@ impl SafeKeeperMetrics {
             commit_lsn: COMMIT_LSN_GAUGE.with_label_values(&[&ztli_str]),
         }
     }
+
+    fn new_noname() -> SafeKeeperMetrics {
+        SafeKeeperMetrics {
+            flush_lsn: FLUSH_LSN_GAUGE.with_label_values(&["n/a"]),
+            commit_lsn: COMMIT_LSN_GAUGE.with_label_values(&["n/a"]),
+        }
+    }
 }
 
 /// SafeKeeper which consumes events (messages from compute) and provides
@@ -322,7 +329,7 @@ pub struct SafeKeeper<ST: Storage> {
     pub flush_lsn: Lsn,
     pub tli: u32,
     // Cached metrics so we don't have to recompute labels on each update.
-    metrics: Option<SafeKeeperMetrics>,
+    metrics: SafeKeeperMetrics,
     /// not-yet-flushed pairs of same named fields in s.*
     pub commit_lsn: Lsn,
     pub truncate_lsn: Lsn,
@@ -341,7 +348,7 @@ where
         SafeKeeper {
             flush_lsn,
             tli,
-            metrics: None,
+            metrics: SafeKeeperMetrics::new_noname(),
             commit_lsn: state.commit_lsn,
             truncate_lsn: state.truncate_lsn,
             storage,
@@ -393,7 +400,7 @@ where
         self.s.server.wal_seg_size = msg.wal_seg_size;
         self.storage.persist(&self.s, true)?;
 
-        self.metrics = Some(SafeKeeperMetrics::new(self.s.server.ztli));
+        self.metrics = SafeKeeperMetrics::new(self.s.server.ztli);
 
         info!(
             "processed greeting from proposer {:?}, sending term {:?}",
@@ -518,11 +525,7 @@ where
         }
         if last_rec_lsn > self.flush_lsn {
             self.flush_lsn = last_rec_lsn;
-            self.metrics
-                .as_ref()
-                .unwrap()
-                .flush_lsn
-                .set(u64::from(self.flush_lsn) as f64);
+            self.metrics.flush_lsn.set(u64::from(self.flush_lsn) as f64);
         }
 
         // Advance commit_lsn taking into account what we have locally. xxx this
@@ -541,8 +544,6 @@ where
                 commit_lsn >= msg.h.epoch_start_lsn && self.s.commit_lsn < msg.h.epoch_start_lsn;
             self.commit_lsn = commit_lsn;
             self.metrics
-                .as_ref()
-                .unwrap()
                 .commit_lsn
                 .set(u64::from(self.commit_lsn) as f64);
         }

walkeeper/src/send_wal.rs

@@ -13,7 +13,7 @@ use std::str::FromStr;
 use std::sync::Arc;
 use zenith_utils::postgres_backend;
 use zenith_utils::postgres_backend::PostgresBackend;
-use zenith_utils::pq_proto::{BeMessage, FeStartupMessage, RowDescriptor};
+use zenith_utils::pq_proto::{BeMessage, FeStartupMessage, RowDescriptor, INT4_OID, TEXT_OID};
 use zenith_utils::zid::{ZTenantId, ZTimelineId};
 
 use crate::timeline::CreateControlFile;
@@ -71,19 +71,16 @@ impl postgres_backend::Handler for SendWalHandler {
         }
         if query_string.starts_with(b"IDENTIFY_SYSTEM") {
             self.handle_identify_system(pgb)?;
-            Ok(())
         } else if query_string.starts_with(b"START_REPLICATION") {
             ReplicationConn::new(pgb).run(self, pgb, &query_string)?;
-            Ok(())
         } else if query_string.starts_with(b"START_WAL_PUSH") {
             ReceiveWalConn::new(pgb)?.run(self)?;
-            Ok(())
         } else if query_string.starts_with(b"JSON_CTRL") {
             handle_json_ctrl(self, pgb, &query_string)?;
-            Ok(())
         } else {
             bail!("Unexpected command {:?}", query_string);
         }
+        Ok(())
     }
 }
 
@@ -113,25 +110,25 @@ impl SendWalHandler {
         pgb.write_message_noflush(&BeMessage::RowDescription(&[
             RowDescriptor {
                 name: b"systemid",
-                typoid: 25,
+                typoid: TEXT_OID,
                 typlen: -1,
                 ..Default::default()
             },
             RowDescriptor {
                 name: b"timeline",
-                typoid: 23,
+                typoid: INT4_OID,
                 typlen: 4,
                 ..Default::default()
             },
             RowDescriptor {
                 name: b"xlogpos",
-                typoid: 25,
+                typoid: TEXT_OID,
                 typlen: -1,
                 ..Default::default()
             },
             RowDescriptor {
                 name: b"dbname",
-                typoid: 25,
+                typoid: TEXT_OID,
                 typlen: -1,
                 ..Default::default()
             },

walkeeper/src/timeline.rs

@@ -289,7 +289,7 @@ lazy_static! {
 }
 
 /// A zero-sized struct used to manage access to the global timelines map.
-struct GlobalTimelines;
+pub struct GlobalTimelines;
 
 impl GlobalTimelines {
     /// Get a timeline with control file loaded from the global TIMELINES map.

zenith/src/main.rs

@@ -32,12 +32,16 @@ struct BranchTreeEl {
 //   * Providing CLI api to the pageserver
 //   * TODO: export/import to/from usual postgres
 fn main() -> Result<()> {
-    let timeline_arg = Arg::with_name("timeline")
-        .short("n")
+    let node_arg = Arg::with_name("node")
         .index(1)
-        .help("Timeline name")
+        .help("Node name")
         .required(true);
 
+    let timeline_arg = Arg::with_name("timeline")
+        .index(2)
+        .help("Branch name or a point-in time specification")
+        .required(false);
+
     let tenantid_arg = Arg::with_name("tenantid")
         .long("tenantid")
         .help("Tenant id. Represented as a hexadecimal string 32 symbols length")
@@ -102,7 +106,10 @@ fn main() -> Result<()> {
                 .subcommand(SubCommand::with_name("list").arg(tenantid_arg.clone()))
                 .subcommand(SubCommand::with_name("create")
                     .about("Create a postgres compute node")
-                    .arg(timeline_arg.clone()).arg(tenantid_arg.clone()).arg(port_arg.clone())
+                    .arg(node_arg.clone())
+                    .arg(timeline_arg.clone())
+                    .arg(tenantid_arg.clone())
+                    .arg(port_arg.clone())
                     .arg(
                         Arg::with_name("config-only")
                             .help("Don't do basebackup, create compute node with only config files")
@@ -111,13 +118,13 @@ fn main() -> Result<()> {
                     ))
                 .subcommand(SubCommand::with_name("start")
                     .about("Start a postgres compute node.\n This command actually creates new node from scratch, but preserves existing config files")
-                    .arg(
-                        timeline_arg.clone()
-                    ).arg(
-                        tenantid_arg.clone()
-                    ).arg(port_arg.clone()))
+                    .arg(node_arg.clone())
+                    .arg(timeline_arg.clone())
+                    .arg(tenantid_arg.clone())
+                    .arg(port_arg.clone()))
                 .subcommand(
                     SubCommand::with_name("stop")
+                        .arg(node_arg.clone())
                         .arg(timeline_arg.clone())
                         .arg(tenantid_arg.clone())
                         .arg(
@@ -430,25 +437,32 @@ fn handle_pg(pg_match: &ArgMatches, env: &local_env::LocalEnv) -> Result<()> {
             let tenantid: ZTenantId = list_match
                 .value_of("tenantid")
                 .map_or(Ok(env.tenantid), |value| value.parse())?;
+
             let branch_infos = get_branch_infos(env, &tenantid).unwrap_or_else(|e| {
                 eprintln!("Failed to load branch info: {}", e);
                 HashMap::new()
             });
 
-            println!("BRANCH\tADDRESS\t\tLSN\t\tSTATUS");
-            for ((_, timeline_name), node) in cplane
+            println!("NODE\tADDRESS\t\tBRANCH\tLSN\t\tSTATUS");
+            for ((_, node_name), node) in cplane
                 .nodes
                 .iter()
                 .filter(|((node_tenantid, _), _)| node_tenantid == &tenantid)
             {
+                // FIXME: This shows the LSN at the end of the timeline. It's not the
+                // right thing to do for read-only nodes that might be anchored at an
+                // older point in time, or following but lagging behind the primary.
+                let lsn_str = branch_infos
+                    .get(&node.timelineid)
+                    .map(|bi| bi.latest_valid_lsn.to_string())
+                    .unwrap_or_else(|| "?".to_string());
+
                 println!(
-                    "{}\t{}\t{}\t{}",
-                    timeline_name,
+                    "{}\t{}\t{}\t{}\t{}",
+                    node_name,
                     node.address,
-                    branch_infos
-                        .get(&node.timelineid)
-                        .map(|bi| bi.latest_valid_lsn.to_string())
-                        .unwrap_or_else(|| "?".to_string()),
+                    node.timelineid, // FIXME: resolve human-friendly branch name
+                    lsn_str,
                     node.status(),
                 );
             }
@@ -457,26 +471,28 @@ fn handle_pg(pg_match: &ArgMatches, env: &local_env::LocalEnv) -> Result<()> {
             let tenantid: ZTenantId = create_match
                 .value_of("tenantid")
                 .map_or(Ok(env.tenantid), |value| value.parse())?;
-            let timeline_name = create_match.value_of("timeline").unwrap_or("main");
+            let node_name = create_match.value_of("node").unwrap_or("main");
+            let timeline_name = create_match.value_of("timeline").unwrap_or(node_name);
 
             let port: Option<u16> = match create_match.value_of("port") {
                 Some(p) => Some(p.parse()?),
                 None => None,
             };
-            cplane.new_node(tenantid, timeline_name, port)?;
+            cplane.new_node(tenantid, node_name, timeline_name, port)?;
         }
         ("start", Some(start_match)) => {
             let tenantid: ZTenantId = start_match
                 .value_of("tenantid")
                 .map_or(Ok(env.tenantid), |value| value.parse())?;
-            let timeline_name = start_match.value_of("timeline").unwrap_or("main");
+            let node_name = start_match.value_of("node").unwrap_or("main");
+            let timeline_name = start_match.value_of("timeline");
 
             let port: Option<u16> = match start_match.value_of("port") {
                 Some(p) => Some(p.parse()?),
                 None => None,
             };
 
-            let node = cplane.nodes.get(&(tenantid, timeline_name.to_owned()));
+            let node = cplane.nodes.get(&(tenantid, node_name.to_owned()));
 
             let auth_token = if matches!(env.auth_type, AuthType::ZenithJWT) {
                 let claims = Claims::new(Some(tenantid), Scope::Tenant);
@@ -485,12 +501,11 @@ fn handle_pg(pg_match: &ArgMatches, env: &local_env::LocalEnv) -> Result<()> {
                 None
             };
 
-            println!(
-                "Starting {} postgres on timeline {}...",
-                if node.is_some() { "existing" } else { "new" },
-                timeline_name
-            );
             if let Some(node) = node {
+                if timeline_name.is_some() {
+                    println!("timeline name ignored because node exists already");
+                }
+                println!("Starting existing postgres {}...", node_name);
                 node.start(&auth_token)?;
             } else {
                 // when used with custom port this results in non obvious behaviour
@@ -498,12 +513,17 @@ fn handle_pg(pg_match: &ArgMatches, env: &local_env::LocalEnv) -> Result<()> {
                 // start --port X
                 // stop
                 // start <-- will also use port X even without explicit port argument
-                let node = cplane.new_node(tenantid, timeline_name, port)?;
+                let timeline_name = timeline_name.unwrap_or(node_name);
+                println!(
+                    "Starting new postgres {} on {}...",
+                    node_name, timeline_name
+                );
+                let node = cplane.new_node(tenantid, node_name, timeline_name, port)?;
                 node.start(&auth_token)?;
             }
         }
         ("stop", Some(stop_match)) => {
-            let timeline_name = stop_match.value_of("timeline").unwrap_or("main");
+            let node_name = stop_match.value_of("node").unwrap_or("main");
             let destroy = stop_match.is_present("destroy");
             let tenantid: ZTenantId = stop_match
                 .value_of("tenantid")
@@ -511,8 +531,8 @@ fn handle_pg(pg_match: &ArgMatches, env: &local_env::LocalEnv) -> Result<()> {
 
             let node = cplane
                 .nodes
-                .get(&(tenantid, timeline_name.to_owned()))
-                .ok_or_else(|| anyhow!("postgres {} is not found", timeline_name))?;
+                .get(&(tenantid, node_name.to_owned()))
+                .ok_or_else(|| anyhow!("postgres {} is not found", node_name))?;
             node.stop(destroy)?;
         }
 

zenith_utils/src/http/mod.rs

@@ -1,3 +1,4 @@
 pub mod endpoint;
 pub mod error;
 pub mod json;
+pub mod request;

zenith_utils/src/http/request.rs

@@ -0,0 +1,33 @@
+use std::str::FromStr;
+
+use super::error::ApiError;
+use hyper::{Body, Request};
+use routerify::ext::RequestExt;
+
+pub fn get_request_param<'a>(
+    request: &'a Request<Body>,
+    param_name: &str,
+) -> Result<&'a str, ApiError> {
+    match request.param(param_name) {
+        Some(arg) => Ok(arg),
+        None => {
+            return Err(ApiError::BadRequest(format!(
+                "no {} specified in path param",
+                param_name
+            )))
+        }
+    }
+}
+
+pub fn parse_request_param<T: FromStr>(
+    request: &Request<Body>,
+    param_name: &str,
+) -> Result<T, ApiError> {
+    match get_request_param(request, param_name)?.parse() {
+        Ok(v) => Ok(v),
+        Err(_) => Err(ApiError::BadRequest(format!(
+            "failed to parse {}",
+            param_name
+        ))),
+    }
+}

zenith_utils/src/pq_proto.rs

@@ -15,8 +15,9 @@ use std::str;
 pub type Oid = u32;
 pub type SystemId = u64;
 
-pub const TEXT_OID: Oid = 25;
 pub const INT8_OID: Oid = 20;
+pub const INT4_OID: Oid = 23;
+pub const TEXT_OID: Oid = 25;
 
 #[derive(Debug)]
 pub enum FeMessage {

zenith_utils/src/sock_split.rs

@@ -107,21 +107,12 @@ impl io::Write for WriteStream {
     }
 }
 
-pub struct TlsBoxed {
-    stream: BufStream,
-    session: rustls::ServerSession,
-}
-
-impl TlsBoxed {
-    fn rustls_stream(&mut self) -> rustls::Stream<rustls::ServerSession, BufStream> {
-        rustls::Stream::new(&mut self.session, &mut self.stream)
-    }
-}
+type TlsStream<T> = rustls::StreamOwned<rustls::ServerSession, T>;
 
 pub enum BidiStream {
     Tcp(BufStream),
     /// This variant is boxed, because [`rustls::ServerSession`] is quite larger than [`BufStream`].
-    Tls(Box<TlsBoxed>),
+    Tls(Box<TlsStream<BufStream>>),
 }
 
 impl BidiStream {
@@ -134,11 +125,11 @@ impl BidiStream {
             Self::Tcp(stream) => stream.get_ref().shutdown(how),
             Self::Tls(tls_boxed) => {
                 if how == Shutdown::Read {
-                    tls_boxed.stream.get_ref().shutdown(how)
+                    tls_boxed.sock.get_ref().shutdown(how)
                 } else {
-                    tls_boxed.session.send_close_notify();
-                    let res = tls_boxed.rustls_stream().flush();
-                    tls_boxed.stream.get_ref().shutdown(how)?;
+                    tls_boxed.sess.send_close_notify();
+                    let res = tls_boxed.flush();
+                    tls_boxed.sock.get_ref().shutdown(how)?;
                     res
                 }
             }
@@ -155,7 +146,7 @@ impl BidiStream {
                 (ReadStream::Tcp(reader), WriteStream::Tcp(stream))
             }
             Self::Tls(tls_boxed) => {
-                let reader = tls_boxed.stream.into_reader();
+                let reader = tls_boxed.sock.into_reader();
                 let buffer_data = reader.buffer().to_owned();
                 let read_buf_cfg = rustls_split::BufCfg::with_data(buffer_data, 8192);
                 let write_buf_cfg = rustls_split::BufCfg::with_capacity(8192);
@@ -164,7 +155,7 @@ impl BidiStream {
                 let socket = Arc::try_unwrap(reader.into_inner().0).unwrap();
 
                 let (read_half, write_half) =
-                    rustls_split::split(socket, tls_boxed.session, read_buf_cfg, write_buf_cfg);
+                    rustls_split::split(socket, tls_boxed.sess, read_buf_cfg, write_buf_cfg);
                 (ReadStream::Tls(read_half), WriteStream::Tls(write_half))
             }
         }
@@ -175,7 +166,7 @@ impl BidiStream {
             Self::Tcp(mut stream) => {
                 session.complete_io(&mut stream)?;
                 assert!(!session.is_handshaking());
-                Ok(Self::Tls(Box::new(TlsBoxed { stream, session })))
+                Ok(Self::Tls(Box::new(TlsStream::new(session, stream))))
             }
             Self::Tls { .. } => Err(io::Error::new(
                 io::ErrorKind::InvalidInput,
@@ -189,7 +180,7 @@ impl io::Read for BidiStream {
     fn read(&mut self, buf: &mut [u8]) -> io::Result<usize> {
         match self {
             Self::Tcp(stream) => stream.read(buf),
-            Self::Tls(tls_boxed) => tls_boxed.rustls_stream().read(buf),
+            Self::Tls(tls_boxed) => tls_boxed.read(buf),
         }
     }
 }
@@ -198,14 +189,14 @@ impl io::Write for BidiStream {
     fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
         match self {
             Self::Tcp(stream) => stream.write(buf),
-            Self::Tls(tls_boxed) => tls_boxed.rustls_stream().write(buf),
+            Self::Tls(tls_boxed) => tls_boxed.write(buf),
         }
     }
 
     fn flush(&mut self) -> io::Result<()> {
         match self {
             Self::Tcp(stream) => stream.flush(),
-            Self::Tls(tls_boxed) => tls_boxed.rustls_stream().flush(),
+            Self::Tls(tls_boxed) => tls_boxed.flush(),
         }
     }
 }