From c73407715c9a12af017bb5027d3d6d9f460635a6 Mon Sep 17 00:00:00 2001 From: Alexey Masterov Date: Tue, 9 Jul 2024 18:30:38 +0200 Subject: [PATCH] Fix the problem W1203 --- scripts/benchmark_durations.py | 4 +- scripts/flaky_tests.py | 4 +- scripts/force_layer_download.py | 12 +- scripts/sk_cleanup_tenants/script.py | 18 +- test_runner/fixtures/broker.py | 4 +- test_runner/fixtures/compute_reconfigure.py | 2 +- test_runner/fixtures/flaky.py | 4 +- test_runner/fixtures/metrics.py | 4 +- test_runner/fixtures/neon_fixtures.py | 172 +++++++++--------- test_runner/fixtures/pageserver/http.py | 30 +-- .../fixtures/pageserver/many_tenants.py | 4 +- test_runner/fixtures/pageserver/utils.py | 26 +-- test_runner/fixtures/port_distributor.py | 2 +- test_runner/fixtures/remote_storage.py | 6 +- test_runner/fixtures/safekeeper/http.py | 4 +- test_runner/fixtures/safekeeper/utils.py | 2 +- test_runner/fixtures/utils.py | 12 +- test_runner/fixtures/workload.py | 10 +- .../pagebench/test_large_slru_basebackup.py | 6 +- .../pagebench/test_ondemand_download_churn.py | 6 +- ...er_max_throughput_getpage_at_latest_lsn.py | 6 +- .../performance/test_branch_creation.py | 4 +- test_runner/performance/test_gc_feedback.py | 6 +- .../performance/test_logical_replication.py | 2 +- test_runner/performance/test_perf_olap.py | 6 +- test_runner/performance/test_seqscans.py | 2 +- .../performance/test_sharding_autosplit.py | 4 +- .../test_storage_controller_scale.py | 14 +- .../performance/test_wal_backpressure.py | 6 +- test_runner/regress/test_ancestor_branch.py | 18 +- test_runner/regress/test_aux_files.py | 2 +- test_runner/regress/test_backpressure.py | 18 +- test_runner/regress/test_bad_connection.py | 6 +- test_runner/regress/test_branch_and_gc.py | 6 +- test_runner/regress/test_branch_behind.py | 12 +- test_runner/regress/test_branching.py | 14 +- test_runner/regress/test_broken_timeline.py | 6 +- test_runner/regress/test_change_pageserver.py | 2 +- test_runner/regress/test_clog_truncate.py | 8 +- test_runner/regress/test_close_fds.py | 2 +- test_runner/regress/test_compaction.py | 12 +- test_runner/regress/test_compatibility.py | 2 +- test_runner/regress/test_ddl_forwarding.py | 6 +- .../regress/test_disk_usage_eviction.py | 36 ++-- .../regress/test_download_extensions.py | 6 +- .../regress/test_explain_with_lfc_stats.py | 6 +- test_runner/regress/test_fullbackup.py | 2 +- test_runner/regress/test_gc_aggressive.py | 4 +- test_runner/regress/test_hot_standby.py | 12 +- test_runner/regress/test_import.py | 6 +- .../regress/test_ingestion_layer_size.py | 6 +- test_runner/regress/test_large_schema.py | 2 +- test_runner/regress/test_layer_bloating.py | 6 +- .../regress/test_layers_from_future.py | 10 +- test_runner/regress/test_lfc_resize.py | 2 +- .../test_lfc_working_set_approximation.py | 16 +- .../regress/test_logical_replication.py | 10 +- test_runner/regress/test_neon_superuser.py | 4 +- test_runner/regress/test_next_xid.py | 20 +- test_runner/regress/test_old_request_lsn.py | 2 +- test_runner/regress/test_ondemand_download.py | 28 +-- .../regress/test_ondemand_slru_download.py | 2 +- .../regress/test_pageserver_generations.py | 18 +- .../test_pageserver_getpage_throttle.py | 4 +- .../regress/test_pageserver_layer_rolling.py | 10 +- .../test_pageserver_metric_collection.py | 4 +- .../regress/test_pageserver_reconnect.py | 2 +- .../regress/test_pageserver_restart.py | 8 +- ...test_pageserver_restarts_under_workload.py | 2 +- .../regress/test_pageserver_secondary.py | 40 ++-- test_runner/regress/test_pitr_gc.py | 4 +- test_runner/regress/test_read_validation.py | 6 +- test_runner/regress/test_recovery.py | 2 +- test_runner/regress/test_remote_storage.py | 8 +- test_runner/regress/test_replica_start.py | 2 +- test_runner/regress/test_s3_restore.py | 4 +- test_runner/regress/test_sharding.py | 44 ++--- test_runner/regress/test_sni_router.py | 2 +- .../regress/test_storage_controller.py | 30 +-- test_runner/regress/test_tenant_conf.py | 10 +- test_runner/regress/test_tenant_detach.py | 4 +- test_runner/regress/test_tenant_size.py | 14 +- test_runner/regress/test_tenant_tasks.py | 2 +- test_runner/regress/test_tenants.py | 34 ++-- .../test_tenants_with_remote_storage.py | 4 +- test_runner/regress/test_timeline_delete.py | 4 +- test_runner/regress/test_timeline_size.py | 22 +-- test_runner/regress/test_vm_bits.py | 6 +- test_runner/regress/test_wal_acceptor.py | 106 +++++------ .../regress/test_wal_acceptor_async.py | 46 ++--- test_runner/regress/test_wal_receiver.py | 2 +- test_runner/regress/test_wal_restore.py | 6 +- .../test_walredo_not_left_behind_on_detach.py | 4 +- 93 files changed, 567 insertions(+), 563 deletions(-) diff --git a/scripts/benchmark_durations.py b/scripts/benchmark_durations.py index beafdc3d855d..017328efa77a 100755 --- a/scripts/benchmark_durations.py +++ b/scripts/benchmark_durations.py @@ -126,10 +126,10 @@ def main(args: argparse.Namespace): for row in rows: pytest_name = f"{row['parent_suite'].replace('.', '/')}/{row['suite']}.py::{row['name']}" duration = row["percentile_ms"] / 1000 - logging.info(f"\t{pytest_name}: {duration}") + logging.info("\t%s: %s", pytest_name, duration) res[pytest_name] = duration - logging.info(f"saving results to {output.name}") + logging.info("saving results to %s", output.name) json.dump(res, output, indent=2) diff --git a/scripts/flaky_tests.py b/scripts/flaky_tests.py index 9f27b2b2d642..6acc4f5fc821 100755 --- a/scripts/flaky_tests.py +++ b/scripts/flaky_tests.py @@ -93,10 +93,10 @@ def get_pageserver_default_tenant_config_compaction_algorithm() -> Optional[Dict res[row["parent_suite"]][row["suite"]][parametrized_test] = True logging.info( - f"\t{row['parent_suite'].replace('.', '/')}/{row['suite']}.py::{parametrized_test}" + "\t%s/%s.py::%s", row['parent_suite'].replace('.', '/'), row['suite'], parametrized_test ) - logging.info(f"saving results to {output.name}") + logging.info("saving results to %s", output.name) json.dump(res, output, indent=2) diff --git a/scripts/force_layer_download.py b/scripts/force_layer_download.py index 5472d86d8f4f..218b79a14771 100644 --- a/scripts/force_layer_download.py +++ b/scripts/force_layer_download.py @@ -124,7 +124,7 @@ async def do_timeline(client: Client, tenant_id, timeline_id): while True: st = await client.timeline_poll_download_remote_layers_status(tenant_id, timeline_id) - logging.info(f"{tenant_id}:{timeline_id} state is: {st}") + logging.info("%s:%s state is: %s", tenant_id, timeline_id, st) if spawned["task_id"] != st["task_id"]: raise ClientException("download task ids changed while polling") @@ -161,7 +161,7 @@ async def taskq_handler(task_q, result_q): except asyncio.QueueEmpty: logging.debug("taskq_handler observed empty task_q, returning") return - logging.info(f"starting task {id}") + logging.info("starting task %s", id) try: res = await fut except Exception as e: @@ -172,7 +172,7 @@ async def taskq_handler(task_q, result_q): async def print_progress(result_q, tasks): while True: await asyncio.sleep(10) - logging.info(f"{result_q.qsize()} / {len(tasks)} tasks done") + logging.info("%s / %s tasks done", result_q.qsize(), len(tasks)) async def main_impl(args, report_out, client: Client): @@ -205,13 +205,13 @@ async def main_impl(args, report_out, client: Client): logging.info("expanded spec:") for tid, tlid in tenant_and_timline_ids: - logging.info(f"{tid}:{tlid}") + logging.info("%s:%s", tid, tlid) logging.info("remove duplicates after expanding spec") tmp = list(set(tenant_and_timline_ids)) assert len(tmp) <= len(tenant_and_timline_ids) if len(tmp) != len(tenant_and_timline_ids): - logging.info(f"spec had {len(tenant_and_timline_ids) - len(tmp)} duplicates") + logging.info("spec had %s duplicates", len(tenant_and_timline_ids) - len(tmp)) tenant_and_timline_ids = tmp logging.info("create tasks and process them at specified concurrency") @@ -244,7 +244,7 @@ async def main_impl(args, report_out, client: Client): report = defaultdict(list) for id, result in results: - logging.info(f"result for {id}: {result}") + logging.info("result for %s: %s", id, result) if isinstance(result, Completed): if result.status["failed_download_count"] == 0: report["completed_without_errors"].append(id) diff --git a/scripts/sk_cleanup_tenants/script.py b/scripts/sk_cleanup_tenants/script.py index c20a4bb83067..8762e3418d2b 100644 --- a/scripts/sk_cleanup_tenants/script.py +++ b/scripts/sk_cleanup_tenants/script.py @@ -26,7 +26,7 @@ trash_dir: Path = args.trash_dir dry_run: bool = args.dry_run -logging.info(f"dry_run={dry_run}") +logging.info("dry_run=%s", dry_run) sk_id: int = args.safekeeper_id sk_host: str = args.safekeeper_host @@ -94,10 +94,10 @@ def cleanup_tenant(tenant_id): assert tenant_dir.exists(), f"{tenant_dir}" assert tenant_dir.is_dir(), f"{tenant_dir}" - logging.info(f"copying {tenant_dir} to {tenant_dir_in_trash}") + logging.info("copying %s to %s", tenant_dir, tenant_dir_in_trash) shutil.copytree(src=tenant_dir, dst=tenant_dir_in_trash, symlinks=False, dirs_exist_ok=False) - logging.info(f"deleting {tenant_dir}") + logging.info("deleting %s", tenant_dir) call_delete_tenant_api(tenant_id) logging.info("tenant is now deleted, checking that it's gone") @@ -106,27 +106,27 @@ def cleanup_tenant(tenant_id): if os.path.exists("script.pid"): logging.info( - f"script is already running, with pid={Path('script.pid').read_text()}. Terminate it first." + "script is already running, with pid=%s. Terminate it first.", Path('script.pid').read_text() ) exit(1) with open("script.pid", "w", encoding="utf-8") as f: f.write(str(os.getpid())) -logging.info(f"started script.py, pid={os.getpid()}") +logging.info("started script.py, pid=%s", os.getpid()) for line in sys.stdin: tenant_id = line.strip() try: - logging.info(f"start tenant {tenant_id}") + logging.info("start tenant %s", tenant_id) cleanup_tenant(tenant_id) - logging.info(f"done tenant {tenant_id}") + logging.info("done tenant %s", tenant_id) except KeyboardInterrupt: print("KeyboardInterrupt exception is caught") break except: # noqa: E722 - logging.exception(f"failed to clean up tenant {tenant_id}") + logging.exception("failed to clean up tenant %s", tenant_id) -logging.info(f"finished script.py, pid={os.getpid()}") +logging.info("finished script.py, pid=%s", os.getpid()) os.remove("script.pid") diff --git a/test_runner/fixtures/broker.py b/test_runner/fixtures/broker.py index 8aca90a0979a..4c4b612c539a 100644 --- a/test_runner/fixtures/broker.py +++ b/test_runner/fixtures/broker.py @@ -27,11 +27,11 @@ def check_status(self): def try_start(self): if self.handle is not None: - log.debug(f"storage_broker is already running on port {self.port}") + log.debug("storage_broker is already running on port %s", self.port) return listen_addr = self.listen_addr() - log.info(f'starting storage_broker to listen incoming connections at "{listen_addr}"') + log.info('starting storage_broker to listen incoming connections at "%s"', listen_addr) with open(self.logfile, "wb") as logfile: args = [ str(self.neon_binpath / "storage_broker"), diff --git a/test_runner/fixtures/compute_reconfigure.py b/test_runner/fixtures/compute_reconfigure.py index 66fc35b6aa44..a78ae64e6865 100644 --- a/test_runner/fixtures/compute_reconfigure.py +++ b/test_runner/fixtures/compute_reconfigure.py @@ -49,7 +49,7 @@ def compute_reconfigure_listener(make_httpserver): def handler(request: Request): assert request.json is not None body: dict[str, Any] = request.json - log.info(f"notify-attach request: {body}") + log.info("notify-attach request: %s", body) if self.on_notify is not None: self.on_notify(body) diff --git a/test_runner/fixtures/flaky.py b/test_runner/fixtures/flaky.py index d13f3318b059..3eb35bfc000d 100644 --- a/test_runner/fixtures/flaky.py +++ b/test_runner/fixtures/flaky.py @@ -40,7 +40,7 @@ def pytest_collection_modifyitems(config: Config, items: List[pytest.Item]): try: flaky_tests = json.loads(content) except ValueError: - log.error(f"Can't parse {content} as json") + log.error("Can't parse %s as json", content) return for item in items: @@ -54,7 +54,7 @@ def pytest_collection_modifyitems(config: Config, items: List[pytest.Item]): if flaky_tests.get(parent_suite, {}).get(suite, {}).get(name, False): # Rerun 3 times = 1 original run + 2 reruns - log.info(f"Marking {item.nodeid} as flaky. It will be rerun up to 3 times") + log.info("Marking %s as flaky. It will be rerun up to 3 times", item.nodeid) item.add_marker(pytest.mark.flaky(reruns=2)) # pytest-rerunfailures is not compatible with pytest-timeout (timeout is not set for reruns), diff --git a/test_runner/fixtures/metrics.py b/test_runner/fixtures/metrics.py index c019cbbc7790..e413c6be7867 100644 --- a/test_runner/fixtures/metrics.py +++ b/test_runner/fixtures/metrics.py @@ -48,7 +48,7 @@ def get_metric_value( metrics = self.get_metrics() results = metrics.query_all(name, filter=filter) if not results: - log.info(f'could not find metric "{name}"') + log.info('could not find metric "%s"', name) return None assert len(results) == 1, f"metric {name} with given filters is not unique, got: {results}" return results[0].value @@ -81,7 +81,7 @@ def get_metrics_values( if not absence_ok: if len(result) != len(names): - log.info(f"Metrics found: {metrics.metrics}") + log.info("Metrics found: %s", metrics.metrics) raise RuntimeError(f"could not find all metrics {' '.join(names)}") return result diff --git a/test_runner/fixtures/neon_fixtures.py b/test_runner/fixtures/neon_fixtures.py index c002e11c1c08..d3f258ed1acc 100644 --- a/test_runner/fixtures/neon_fixtures.py +++ b/test_runner/fixtures/neon_fixtures.py @@ -116,7 +116,7 @@ def base_dir() -> Iterator[Path]: # find the base directory (currently this is the git root) base_dir = get_self_dir().parent.parent - log.info(f"base_dir is {base_dir}") + log.info("base_dir is %s", base_dir) yield base_dir @@ -133,7 +133,7 @@ def neon_binpath(base_dir: Path, build_type: str) -> Iterator[Path]: binpath = Path(env_neon_bin) else: binpath = base_dir / "target" / build_type - log.info(f"neon_binpath is {binpath}") + log.info("neon_binpath is %s", binpath) if not (binpath / "pageserver").exists(): raise Exception(f"neon binaries not found at '{binpath}'") @@ -148,7 +148,7 @@ def pg_distrib_dir(base_dir: Path) -> Iterator[Path]: else: distrib_dir = base_dir / "pg_install" - log.info(f"pg_distrib_dir is {distrib_dir}") + log.info("pg_distrib_dir is %s", distrib_dir) yield distrib_dir @@ -161,7 +161,7 @@ def top_output_dir(base_dir: Path) -> Iterator[Path]: output_dir = base_dir / DEFAULT_OUTPUT_DIR output_dir.mkdir(exist_ok=True) - log.info(f"top_output_dir is {output_dir}") + log.info("top_output_dir is %s", output_dir) yield output_dir @@ -180,7 +180,7 @@ def versioned_pg_distrib_dir(pg_distrib_dir: Path, pg_version: PgVersion) -> Ite if not postgres_bin_path.exists(): raise Exception(f"postgres not found at '{postgres_bin_path}'") - log.info(f"versioned_pg_distrib_dir is {versioned_dir}") + log.info("versioned_pg_distrib_dir is %s", versioned_dir) yield versioned_dir @@ -376,7 +376,7 @@ def safe_psql_many( with conn.cursor() as cur: for query in queries: if log_query: - log.info(f"Executing query: {query}") + log.info("Executing query: %s", query) cur.execute(query) if cur.description is None: @@ -516,7 +516,7 @@ def __init__( ] = pageserver_default_tenant_config_compaction_algorithm if self.pageserver_default_tenant_config_compaction_algorithm is not None: log.debug( - f"Overriding pageserver default compaction algorithm to {self.pageserver_default_tenant_config_compaction_algorithm}" + "Overriding pageserver default compaction algorithm to %s", self.pageserver_default_tenant_config_compaction_algorithm ) self.pageserver_get_vectored_impl: Optional[str] = None @@ -532,7 +532,7 @@ def __init__( self.pageserver_validate_vectored_get: Optional[bool] = None if (validate := os.getenv("PAGESERVER_VALIDATE_VEC_GET")) is not None: self.pageserver_validate_vectored_get = bool(validate) - log.debug(f'Overriding pageserver validate_vectored_get config to "{validate}"') + log.debug('Overriding pageserver validate_vectored_get config to "%s"', validate) self.pageserver_aux_file_policy = pageserver_aux_file_policy @@ -573,7 +573,7 @@ def init_start( # Prepare the default branch to start the postgres on later. # Pageserver itself does not create tenants and timelines, until started first and asked via HTTP API. log.debug( - f"Services started, creating initial tenant {env.initial_tenant} and its initial timeline" + "Services started, creating initial tenant %s and its initial timeline", env.initial_tenant ) initial_tenant, initial_timeline = env.neon_cli.create_tenant( tenant_id=env.initial_tenant, @@ -585,7 +585,7 @@ def init_start( ) assert env.initial_tenant == initial_tenant assert env.initial_timeline == initial_timeline - log.info(f"Initial timeline {initial_tenant}/{initial_timeline} created successfully") + log.info("Initial timeline %s/%s created successfully", initial_tenant, initial_timeline) return env @@ -674,18 +674,18 @@ def from_repo_dir( if self.test_overlay_dir is None: log.info( - f"Copying pageserver tenants directory {tenants_from_dir} to {tenants_to_dir}" + "Copying pageserver tenants directory %s to %s", tenants_from_dir, tenants_to_dir ) shutil.copytree(tenants_from_dir, tenants_to_dir) else: log.info( - f"Creating overlayfs mount of pageserver tenants directory {tenants_from_dir} to {tenants_to_dir}" + "Creating overlayfs mount of pageserver tenants directory %s to %s", tenants_from_dir, tenants_to_dir ) self.overlay_mount(f"{ps_dir.name}:tenants", tenants_from_dir, tenants_to_dir) for sk_from_dir in (repo_dir / "safekeepers").glob("sk*"): sk_to_dir = self.repo_dir / "safekeepers" / sk_from_dir.name - log.info(f"Copying safekeeper directory {sk_from_dir} to {sk_to_dir}") + log.info("Copying safekeeper directory %s to %s", sk_from_dir, sk_to_dir) sk_to_dir.rmdir() shutil.copytree(sk_from_dir, sk_to_dir, ignore=shutil.ignore_patterns("*.log", "*.pid")) @@ -751,7 +751,7 @@ def overlay_mount(self, ident: str, srcdir: Path, dstdir: Path): f"lowerdir={srcdir},upperdir={upper},workdir={work}", str(dstdir), ] - log.info(f"Mounting overlayfs srcdir={srcdir} dstdir={dstdir}: {cmd}") + log.info("Mounting overlayfs srcdir=%s dstdir=%s: %s", srcdir, dstdir, cmd) subprocess_capture( self.test_output_dir, cmd, check=True, echo_stderr=True, echo_stdout=True ) @@ -816,11 +816,11 @@ def overlay_cleanup_teardown(self): (ident, mountpoint) = self.overlay_mounts_created_by_us.pop() ident_state_dir = self.test_overlay_dir / ident log.info( - f"Unmounting overlayfs mount created during setup for ident {ident} at {mountpoint}" + "Unmounting overlayfs mount created during setup for ident %s at %s", ident, mountpoint ) self._overlay_umount(mountpoint) log.info( - f"Cleaning up overlayfs state dir (owned by root user) for ident {ident} at {ident_state_dir}" + "Cleaning up overlayfs state dir (owned by root user) for ident %s at %s", ident, ident_state_dir ) cmd = ["sudo", "rm", "-rf", str(ident_state_dir)] subprocess_capture( @@ -911,14 +911,14 @@ def cleanup_local_storage(self): continue if SMALL_DB_FILE_NAME_REGEX.fullmatch(test_file.name): continue - log.debug(f"Removing large database {test_file} file") + log.debug("Removing large database %s file", test_file) test_file.unlink() elif test_entry.is_dir(): directories_to_clean.append(test_entry) for directory_to_clean in reversed(directories_to_clean): if not os.listdir(directory_to_clean): - log.debug(f"Removing empty directory {directory_to_clean}") + log.debug("Removing empty directory %s", directory_to_clean) directory_to_clean.rmdir() def cleanup_remote_storage(self): @@ -950,20 +950,20 @@ def __exit__( try: StorageScrubber(self).scan_metadata() except Exception as e: - log.error(f"Error during remote storage scrub: {e}") + log.error("Error during remote storage scrub: %s", e) cleanup_error = e try: self.cleanup_remote_storage() except Exception as e: - log.error(f"Error during remote storage cleanup: {e}") + log.error("Error during remote storage cleanup: %s", e) if cleanup_error is not None: cleanup_error = e try: self.cleanup_local_storage() except Exception as e: - log.error(f"Error during local storage cleanup: {e}") + log.error("Error during local storage cleanup: %s", e) if cleanup_error is not None: cleanup_error = e @@ -981,7 +981,7 @@ def __exit__( try: self.overlay_cleanup_teardown() except Exception as e: - log.error(f"Error cleaning up overlay state: {e}") + log.error("Error cleaning up overlay state: %s", e) if cleanup_error is not None: cleanup_error = e @@ -1173,7 +1173,7 @@ def __init__(self, config: NeonEnvBuilder): self.safekeepers.append(Safekeeper(env=self, id=id, port=port)) cfg["safekeepers"].append(sk_cfg) - log.info(f"Config: {cfg}") + log.info("Config: %s", cfg) self.neon_cli.init( cfg, force=config.config_init_force, @@ -1550,7 +1550,7 @@ def raw_cli( else: stdout = "" - log.warn(f"CLI timeout: stderr={stderr}, stdout={stdout}") + log.warn("CLI timeout: stderr=%s, stdout=%s", stderr, stdout) raise indent = " " @@ -1558,7 +1558,7 @@ def raw_cli( stripped = res.stdout.strip() lines = stripped.splitlines() if len(lines) < 2: - log.debug(f"Run {res.args} success: {stripped}") + log.debug("Run %s success: %s", res.args, stripped) else: log.debug("Run %s success:\n%s" % (res.args, textwrap.indent(stripped, indent))) elif check_return_code: @@ -1828,7 +1828,7 @@ def pageserver_stop(self, id: int, immediate=False) -> "subprocess.CompletedProc if immediate: cmd.extend(["-m", "immediate"]) - log.info(f"Stopping pageserver with {cmd}") + log.info("Stopping pageserver with %s", cmd) return self.raw_cli(cmd) def safekeeper_start( @@ -2060,7 +2060,7 @@ def log_contains( """Check that the log contains a line that matches the given regex""" logfile = self.logfile if not logfile.exists(): - log.warning(f"Skipping log check: {logfile} does not exist") + log.warning("Skipping log check: %s does not exist", logfile) return None contains_re = re.compile(pattern) @@ -2121,7 +2121,7 @@ def retryable_node_operation(op, ps_id, max_attempts, backoff): return except StorageControllerApiException as e: max_attempts -= 1 - log.info(f"Operation failed ({max_attempts} attempts left): {e}") + log.info("Operation failed (%s attempts left): %s", max_attempts, e) if max_attempts == 0: raise e @@ -2236,7 +2236,7 @@ def inspect(self, tenant_shard_id: Union[TenantId, TenantShardId]) -> Optional[t headers=self.headers(TokenScope.ADMIN), ) json = response.json() - log.info(f"Response: {json}") + log.info("Response: %s", json) if json["attachment"]: # Explicit int() to make python type linter happy return (int(json["attachment"][0]), int(json["attachment"][1])) @@ -2251,7 +2251,7 @@ def node_register(self, node: NeonPageserver): "listen_pg_addr": "localhost", "listen_pg_port": node.service_port.pg, } - log.info(f"node_register({body})") + log.info("node_register(%s)", body) self.request( "POST", f"{self.env.storage_controller_api}/control/v1/node", @@ -2260,7 +2260,7 @@ def node_register(self, node: NeonPageserver): ) def node_drain(self, node_id): - log.info(f"node_drain({node_id})") + log.info("node_drain(%s)", node_id) self.request( "PUT", f"{self.env.storage_controller_api}/control/v1/node/{node_id}/drain", @@ -2268,7 +2268,7 @@ def node_drain(self, node_id): ) def cancel_node_drain(self, node_id): - log.info(f"cancel_node_drain({node_id})") + log.info("cancel_node_drain(%s)", node_id) self.request( "DELETE", f"{self.env.storage_controller_api}/control/v1/node/{node_id}/drain", @@ -2276,7 +2276,7 @@ def cancel_node_drain(self, node_id): ) def node_fill(self, node_id): - log.info(f"node_fill({node_id})") + log.info("node_fill(%s)", node_id) self.request( "PUT", f"{self.env.storage_controller_api}/control/v1/node/{node_id}/fill", @@ -2284,7 +2284,7 @@ def node_fill(self, node_id): ) def cancel_node_fill(self, node_id): - log.info(f"cancel_node_fill({node_id})") + log.info("cancel_node_fill(%s)", node_id) self.request( "DELETE", f"{self.env.storage_controller_api}/control/v1/node/{node_id}/fill", @@ -2316,7 +2316,7 @@ def tenant_list(self): return response.json() def node_configure(self, node_id, body: dict[str, Any]): - log.info(f"node_configure({node_id}, {body})") + log.info("node_configure(%s, %s)", node_id, body) body["node_id"] = node_id self.request( "PUT", @@ -2360,7 +2360,7 @@ def tenant_create( headers=self.headers(TokenScope.PAGE_SERVER_API), ) response.raise_for_status() - log.info(f"tenant_create success: {response.json()}") + log.info("tenant_create success: %s", response.json()) def locate(self, tenant_id: TenantId) -> list[dict[str, Any]]: """ @@ -2397,7 +2397,7 @@ def tenant_shard_split( headers=self.headers(TokenScope.ADMIN), ) body = response.json() - log.info(f"tenant_shard_split success: {body}") + log.info("tenant_shard_split success: %s", body) shards: list[TenantShardId] = body["new_shards"] return shards @@ -2408,11 +2408,11 @@ def tenant_shard_migrate(self, tenant_shard_id: TenantShardId, dest_ps_id: int): json={"tenant_shard_id": str(tenant_shard_id), "node_id": dest_ps_id}, headers=self.headers(TokenScope.ADMIN), ) - log.info(f"Migrated tenant {tenant_shard_id} to pageserver {dest_ps_id}") + log.info("Migrated tenant %s to pageserver %s", tenant_shard_id, dest_ps_id) assert self.env.get_tenant_pageserver(tenant_shard_id).id == dest_ps_id def tenant_policy_update(self, tenant_id: TenantId, body: dict[str, Any]): - log.info(f"tenant_policy_update({tenant_id}, {body})") + log.info("tenant_policy_update(%s, %s)", tenant_id, body) self.request( "PUT", f"{self.env.storage_controller_api}/control/v1/tenant/{tenant_id}/policy", @@ -2435,7 +2435,7 @@ def reconcile_all(self): ) r.raise_for_status() n = r.json() - log.info(f"reconcile_all waited for {n} shards") + log.info("reconcile_all waited for %s shards", n) return n def reconcile_until_idle(self, timeout_secs=30): @@ -2474,7 +2474,7 @@ def poll_node_status( """ Poll the node status until it reaches 'desired_scheduling_policy' or 'max_attempts' have been exhausted """ - log.info(f"Polling {node_id} for {desired_scheduling_policy} scheduling policy") + log.info("Polling %s for %s scheduling policy", node_id, desired_scheduling_policy) while max_attempts > 0: try: status = self.node_status(node_id) @@ -2483,7 +2483,7 @@ def poll_node_status( return else: max_attempts -= 1 - log.info(f"Status call returned {policy=} ({max_attempts} attempts left)") + log.info("Status call returned %s (%s attempts left)", f"{policy=}", max_attempts) if max_attempts == 0: raise AssertionError( @@ -2493,7 +2493,7 @@ def poll_node_status( time.sleep(backoff) except StorageControllerApiException as e: max_attempts -= 1 - log.info(f"Status call failed ({max_attempts} retries left): {e}") + log.info("Status call failed (%s retries left): %s", max_attempts, e) if max_attempts == 0: raise e @@ -2506,7 +2506,7 @@ def configure_failpoints(self, config_strings: Tuple[str, str] | List[Tuple[str, else: pairs = config_strings - log.info(f"Requesting config failpoints: {repr(pairs)}") + log.info("Requesting config failpoints: %s", repr(pairs)) res = self.request( "PUT", @@ -2514,7 +2514,7 @@ def configure_failpoints(self, config_strings: Tuple[str, str] | List[Tuple[str, json=[{"name": name, "actions": actions} for name, actions in pairs], headers=self.headers(TokenScope.ADMIN), ) - log.info(f"Got failpoints request response code {res.status_code}") + log.info("Got failpoints request response code %s", res.status_code) res.raise_for_status() @property @@ -2671,12 +2671,12 @@ def quiesce_tenants(self): def complete(): log.info("Checking tenants...") tenants = client.tenant_list() - log.info(f"Tenant list: {tenants}...") + log.info("Tenant list: %s...", tenants) any_unstable = any((t["state"]["slug"] not in stable_states) for t in tenants) if any_unstable: for t in tenants: - log.info(f"Waiting for tenant {t['id']} in state {t['state']['slug']}") - log.info(f"any_unstable={any_unstable}") + log.info("Waiting for tenant %s in state %s", t['id'], t['state']['slug']) + log.info("any_unstable=%s", any_unstable) assert not any_unstable wait_until(20, 0.5, complete) @@ -2720,7 +2720,7 @@ def assert_no_metric_errors(self): Certain metrics should _always_ be zero: they track conditions that indicate a bug. """ if not self.running: - log.info(f"Skipping metrics check on pageserver {self.id}, it is not running") + log.info("Skipping metrics check on pageserver %s, it is not running", self.id) return for metric in [ @@ -2771,13 +2771,13 @@ def read_tenant_location_conf( self, tenant_shard_id: Union[TenantId, TenantShardId] ) -> dict[str, Any]: path = self.tenant_dir(tenant_shard_id) / "config-v1" - log.info(f"Reading location conf from {path}") + log.info("Reading location conf from %s", path) bytes = open(path, "r").read() try: decoded: dict[str, Any] = toml.loads(bytes) return decoded except: - log.error(f"Failed to decode LocationConf, raw content ({len(bytes)} bytes): {bytes}") + log.error("Failed to decode LocationConf, raw content (%s bytes): %s", len(bytes), bytes) raise def tenant_create( @@ -2880,7 +2880,7 @@ def run( """ self._fixpath(command) - log.info(f"Running command '{' '.join(command)}'") + log.info("Running command '%s'", ' '.join(command)) env = self._build_env(env) subprocess.run(command, env=env, cwd=cwd, check=True) @@ -2900,7 +2900,7 @@ def run_capture( """ self._fixpath(command) - log.info(f"Running command '{' '.join(command)}'") + log.info("Running command '%s'", ' '.join(command)) env = self._build_env(env) base_path, _, _ = subprocess_capture( self.log_dir, @@ -2924,7 +2924,7 @@ def get_pg_controldata_checkpoint_lsn(self, pgdata: str) -> Lsn: checkpoint_lsn = re.findall( "Latest checkpoint location:\\s+([0-9A-F]+/[0-9A-F]+)", result.stdout )[0] - log.info(f"last checkpoint at {checkpoint_lsn}") + log.info("last checkpoint at %s", checkpoint_lsn) return Lsn(checkpoint_lsn) def take_fullbackup( @@ -3154,7 +3154,7 @@ async def run(self, query: Optional[str] = None) -> asyncio.subprocess.Process: if query is not None: run_args += ["--command", query] - log.info(f"Run psql: {subprocess.list2cmdline(run_args)}") + log.info("Run psql: %s", subprocess.list2cmdline(run_args)) return await asyncio.create_subprocess_exec( *run_args, stdout=subprocess.PIPE, @@ -3333,7 +3333,7 @@ def http_query(self, query, args, **kwargs): expected_code = kwargs.get("expected_code") timeout = kwargs.get("timeout") - log.info(f"Executing http query: {query}") + log.info("Executing http query: %s", query) connstr = f"postgresql://{user}:{password}@{self.domain}:{self.proxy_port}/postgres" response = requests.post( @@ -3358,7 +3358,7 @@ async def http2_query(self, query, args, **kwargs): password = kwargs["password"] expected_code = kwargs.get("expected_code") - log.info(f"Executing http2 query: {query}") + log.info("Executing http2 query: %s", query) connstr = f"postgresql://{user}:{password}@{self.domain}:{self.proxy_port}/postgres" async with httpx.AsyncClient( @@ -3397,9 +3397,9 @@ def get_session_id(uri_prefix, uri_line): async def find_auth_link(link_auth_uri, proc): for _ in range(100): line = (await proc.stderr.readline()).decode("utf-8").strip() - log.info(f"psql line: {line}") + log.info("psql line: %s", line) if link_auth_uri in line: - log.info(f"SUCCESS, found auth url: {line}") + log.info("SUCCESS, found auth url: %s", line) return line def __enter__(self) -> NeonProxy: @@ -3631,7 +3631,7 @@ def start( if safekeepers is not None: self.active_safekeepers = safekeepers - log.info(f"Starting postgres endpoint {self.endpoint_id}") + log.info("Starting postgres endpoint %s", self.endpoint_id) self.env.neon_cli.endpoint_start( self.endpoint_id, @@ -3807,7 +3807,7 @@ def create_start( allow_multiple=allow_multiple, ) - log.info(f"Postgres startup took {time.time() - started_at} seconds") + log.info("Postgres startup took %s seconds", time.time() - started_at) return self @@ -3824,7 +3824,7 @@ def __exit__( # Checkpoints running endpoint and returns pg_wal size in MB. def get_pg_wal_size(self): - log.info(f'checkpointing at LSN {self.safe_psql("select pg_current_wal_lsn()")[0][0]}') + log.info('checkpointing at LSN %s', self.safe_psql("select pg_current_wal_lsn()")[0][0]) self.safe_psql("checkpoint") assert self.pgdata_dir is not None # please mypy return get_dir_size(os.path.join(self.pgdata_dir, "pg_wal")) / 1024 / 1024 @@ -3987,7 +3987,7 @@ def start( return self def stop(self, immediate: bool = False) -> "Safekeeper": - log.info(f"Stopping safekeeper {self.id}") + log.info("Stopping safekeeper %s", self.id) self.env.neon_cli.safekeeper_stop(self.id, immediate) self.running = False return self @@ -4016,10 +4016,10 @@ def append_logical_message( conn.autocommit = True with conn.cursor() as cur: request_json = json.dumps(request) - log.info(f"JSON_CTRL request on port {self.port.pg}: {request_json}") + log.info("JSON_CTRL request on port %s: %s", self.port.pg, request_json) cur.execute("JSON_CTRL " + request_json) all = cur.fetchall() - log.info(f"JSON_CTRL response: {all[0][0]}") + log.info("JSON_CTRL response: %s", all[0][0]) res = json.loads(all[0][0]) assert isinstance(res, dict) return res @@ -4041,13 +4041,13 @@ def http_client( def get_timeline_start_lsn(self, tenant_id: TenantId, timeline_id: TimelineId) -> Lsn: timeline_status = self.http_client().timeline_status(tenant_id, timeline_id) timeline_start_lsn = timeline_status.timeline_start_lsn - log.info(f"sk {self.id} timeline start LSN: {timeline_start_lsn}") + log.info("sk %s timeline start LSN: %s", self.id, timeline_start_lsn) return timeline_start_lsn def get_flush_lsn(self, tenant_id: TenantId, timeline_id: TimelineId) -> Lsn: timeline_status = self.http_client().timeline_status(tenant_id, timeline_id) flush_lsn = timeline_status.flush_lsn - log.info(f"sk {self.id} flush LSN: {flush_lsn}") + log.info("sk %s flush LSN: %s", self.id, flush_lsn) return flush_lsn def pull_timeline( @@ -4061,7 +4061,7 @@ def pull_timeline( {"tenant_id": str(tenant_id), "timeline_id": str(timeline_id), "http_hosts": src_https} ) src_ids = [sk.id for sk in srcs] - log.info(f"finished pulling timeline from {src_ids} to {self.id}") + log.info("finished pulling timeline from %s to %s", src_ids, self.id) return res @property @@ -4097,14 +4097,14 @@ def checkpoint_up_to( def are_segments_removed(): segments = self.list_segments(tenant_id, timeline_id) log.info( - f"waiting for all segments before {target_segment_file} to be removed from sk {self.id}, current segments: {segments}" + "waiting for all segments before %s to be removed from sk %s, current segments: %s", target_segment_file, self.id, segments ) assert all(target_segment_file <= s for s in segments) def are_lsns_advanced(): stat = cli.timeline_status(tenant_id, timeline_id) log.info( - f"waiting for remote_consistent_lsn and backup_lsn on sk {self.id} to reach {lsn}, currently remote_consistent_lsn={stat.remote_consistent_lsn}, backup_lsn={stat.backup_lsn}" + "waiting for remote_consistent_lsn and backup_lsn on sk %s to reach %s, currently remote_consistent_lsn=%s, backup_lsn=%s", self.id, lsn, stat.remote_consistent_lsn, stat.backup_lsn ) assert stat.remote_consistent_lsn >= lsn and stat.backup_lsn >= lsn.segment_lsn() @@ -4119,7 +4119,7 @@ def wait_until_paused(self, failpoint: str): msg = f"at failpoint {failpoint}" def paused(): - log.info(f"waiting for hitting failpoint {failpoint}") + log.info("waiting for hitting failpoint %s", failpoint) self.assert_log_contains(msg) wait_until(20, 0.5, paused) @@ -4159,9 +4159,9 @@ def scrubber_cli(self, args: list[str], timeout) -> str: timeout=timeout, ) if status_code: - log.warning(f"Scrub command {args} failed") - log.warning(f"Scrub environment: {env}") - log.warning(f"Output at: {output_path}") + log.warning("Scrub command %s failed", args) + log.warning("Scrub environment: %s", env) + log.warning("Output at: %s", output_path) raise RuntimeError(f"Scrubber failed while running {args}") @@ -4185,7 +4185,7 @@ def tenant_snapshot(self, tenant_id: TenantId, output_path: Path): ["tenant-snapshot", "--tenant-id", str(tenant_id), "--output-path", str(output_path)], timeout=30, ) - log.info(f"tenant-snapshot output: {stdout}") + log.info("tenant-snapshot output: %s", stdout) def pageserver_physical_gc( self, min_age_secs: int, tenant_ids: Optional[list[TenantId]] = None @@ -4221,7 +4221,7 @@ def _get_test_dir(request: FixtureRequest, top_output_dir: Path, prefix: str) -> if (suffix := getattr(request.node, "execution_count", None)) is not None: test_dir = test_dir.parent / f"{test_dir.name}-{suffix}" - log.info(f"get_test_output_dir is {test_dir}") + log.info("get_test_output_dir is %s", test_dir) # make mypy happy assert isinstance(test_dir, Path) return test_dir @@ -4283,7 +4283,7 @@ def test_output_dir( # one directory per test test_dir = get_test_output_dir(request, top_output_dir) - log.info(f"test_output_dir is {test_dir}") + log.info("test_output_dir is %s", test_dir) shutil.rmtree(test_dir, ignore_errors=True) test_dir.mkdir() @@ -4374,14 +4374,14 @@ def test_overlay_dir(request: FixtureRequest, top_output_dir: Path) -> Optional[ return None overlay_dir = get_test_overlay_dir(request, top_output_dir) - log.info(f"test_overlay_dir is {overlay_dir}") + log.info("test_overlay_dir is %s", overlay_dir) overlay_dir.mkdir(exist_ok=True) # unmount stale overlayfs mounts which subdirectories of `overlay_dir/*` as the overlayfs `upperdir` and `workdir` for mountpoint in overlayfs.iter_mounts_beneath(get_test_output_dir(request, top_output_dir)): cmd = ["sudo", "umount", str(mountpoint)] log.info( - f"Unmounting stale overlayfs mount probably created during earlier test run: {cmd}" + "Unmounting stale overlayfs mount probably created during earlier test run: %s", cmd ) subprocess.run(cmd, capture_output=True, check=True) # the overlayfs `workdir`` is owned by `root`, shutil.rmtree won't work. @@ -4538,7 +4538,7 @@ def check_restored_datadir_content( (match, mismatch, error) = filecmp.cmpfiles( endpoint.pgdata_dir, restored_dir_path, pgdata_files, shallow=False ) - log.info(f"filecmp result mismatch and error lists:\n\t mismatch={mismatch}\n\t error={error}") + log.info("filecmp result mismatch and error lists:\n\t mismatch=%s\n\t error=%s", mismatch, error) for f in mismatch: f1 = os.path.join(endpoint.pgdata_dir, f) @@ -4563,9 +4563,9 @@ def logical_replication_sync(subscriber: VanillaPostgres, publisher: Endpoint) - 0 ] if res: - log.info(f"subscriber_lsn={res}") + log.info("subscriber_lsn=%s", res) subscriber_lsn = Lsn(res) - log.info(f"Subscriber LSN={subscriber_lsn}, publisher LSN={ publisher_lsn}") + log.info("Subscriber LSN=%s, publisher LSN=%s", subscriber_lsn, publisher_lsn) if subscriber_lsn >= publisher_lsn: return subscriber_lsn time.sleep(0.5) @@ -4612,7 +4612,7 @@ def wait_replica_caughtup(primary: Endpoint, secondary: Endpoint): secondary.safe_psql_scalar("SELECT pg_last_wal_replay_lsn()", log_query=False) ) caught_up = secondary_lsn >= primary_lsn - log.info(f"caughtup={caught_up}, primary_lsn={primary_lsn}, secondary_lsn={secondary_lsn}") + log.info("caughtup=%s, primary_lsn=%s, secondary_lsn=%s", caught_up, primary_lsn, secondary_lsn) if caught_up: return time.sleep(1) @@ -4626,7 +4626,7 @@ def log_replica_lag(primary: Endpoint, secondary: Endpoint): primary.safe_psql_scalar("SELECT pg_current_wal_flush_lsn()", log_query=False) ) lag = primary_lsn - last_replay_lsn - log.info(f"primary_lsn={primary_lsn}, replay_lsn={last_replay_lsn}, lag={lag}") + log.info("primary_lsn=%s, replay_lsn=%s, lag=%s", primary_lsn, last_replay_lsn, lag) def wait_for_last_flush_lsn( @@ -4646,7 +4646,7 @@ def wait_for_last_flush_lsn( results = [] for tenant_shard_id, pageserver in shards: log.info( - f"wait_for_last_flush_lsn: waiting for {last_flush_lsn} on shard {tenant_shard_id} on pageserver {pageserver.id})" + "wait_for_last_flush_lsn: waiting for %s on shard %s on pageserver %s)", last_flush_lsn, tenant_shard_id, pageserver.id ) waited = wait_for_last_record_lsn( pageserver.http_client(auth_token=auth_token), tenant_shard_id, timeline, last_flush_lsn @@ -4691,7 +4691,7 @@ def flush_ep_to_pageserver( shards = tenant_get_shards(env, tenant, pageserver_id) for tenant_shard_id, pageserver in shards: log.info( - f"flush_ep_to_pageserver: waiting for {commit_lsn} on shard {tenant_shard_id} on pageserver {pageserver.id})" + "flush_ep_to_pageserver: waiting for %s on shard %s on pageserver %s)", commit_lsn, tenant_shard_id, pageserver.id ) waited = wait_for_last_record_lsn( pageserver.http_client(), tenant_shard_id, timeline, commit_lsn diff --git a/test_runner/fixtures/pageserver/http.py b/test_runner/fixtures/pageserver/http.py index 03aee9e5c597..a906e7ec596e 100644 --- a/test_runner/fixtures/pageserver/http.py +++ b/test_runner/fixtures/pageserver/http.py @@ -197,13 +197,13 @@ def configure_failpoints(self, config_strings: Tuple[str, str] | List[Tuple[str, else: pairs = config_strings - log.info(f"Requesting config failpoints: {repr(pairs)}") + log.info("Requesting config failpoints: %s", repr(pairs)) res = self.put( f"http://localhost:{self.port}/v1/failpoints", json=[{"name": name, "actions": actions} for name, actions in pairs], ) - log.info(f"Got failpoints request response code {res.status_code}") + log.info("Got failpoints request response code %s", res.status_code) self.verbose_error(res) res_json = res.json() assert res_json is None @@ -525,13 +525,13 @@ def timeline_gc( self.is_testing_enabled_or_skip() log.info( - f"Requesting GC: tenant {tenant_id}, timeline {timeline_id}, gc_horizon {repr(gc_horizon)}" + "Requesting GC: tenant %s, timeline %s, gc_horizon %s", tenant_id, timeline_id, repr(gc_horizon) ) res = self.put( f"http://localhost:{self.port}/v1/tenant/{tenant_id}/timeline/{timeline_id}/do_gc", json={"gc_horizon": gc_horizon}, ) - log.info(f"Got GC request response code: {res.status_code}") + log.info("Got GC request response code: %s", res.status_code) self.verbose_error(res) res_json = res.json() assert res_json is not None @@ -558,12 +558,12 @@ def timeline_compact( if enhanced_gc_bottom_most_compaction: query["enhanced_gc_bottom_most_compaction"] = "true" - log.info(f"Requesting compact: tenant {tenant_id}, timeline {timeline_id}") + log.info("Requesting compact: tenant %s, timeline %s", tenant_id, timeline_id) res = self.put( f"http://localhost:{self.port}/v1/tenant/{tenant_id}/timeline/{timeline_id}/compact", params=query, ) - log.info(f"Got compact request response code: {res.status_code}") + log.info("Got compact request response code: %s", res.status_code) self.verbose_error(res) res_json = res.json() assert res_json is None @@ -572,7 +572,7 @@ def timeline_preserve_initdb_archive( self, tenant_id: Union[TenantId, TenantShardId], timeline_id: TimelineId ): log.info( - f"Requesting initdb archive preservation for tenant {tenant_id} and timeline {timeline_id}" + "Requesting initdb archive preservation for tenant %s and timeline %s", tenant_id, timeline_id ) res = self.post( f"http://localhost:{self.port}/v1/tenant/{tenant_id}/timeline/{timeline_id}/preserve_initdb_archive", @@ -588,7 +588,7 @@ def timeline_get_lsn_by_timestamp( **kwargs, ): log.info( - f"Requesting lsn by timestamp {timestamp}, tenant {tenant_id}, timeline {timeline_id}, {with_lease=}" + "Requesting lsn by timestamp %s, tenant %s, timeline %s, %s", timestamp, tenant_id, timeline_id, f"{with_lease=}" ) with_lease_query = f"{with_lease=}".lower() res = self.get( @@ -606,7 +606,7 @@ def timeline_lsn_lease( "lsn": str(lsn), } - log.info(f"Requesting lsn lease for {lsn=}, {tenant_id=}, {timeline_id=}") + log.info("Requesting lsn lease for %s, %s, %s", f"{lsn=}", f"{tenant_id=}", f"{timeline_id=}") res = self.post( f"http://localhost:{self.port}/v1/tenant/{tenant_id}/timeline/{timeline_id}/lsn_lease", json=data, @@ -618,7 +618,7 @@ def timeline_lsn_lease( def timeline_get_timestamp_of_lsn( self, tenant_id: Union[TenantId, TenantShardId], timeline_id: TimelineId, lsn: Lsn ): - log.info(f"Requesting time range of lsn {lsn}, tenant {tenant_id}, timeline {timeline_id}") + log.info("Requesting time range of lsn %s, tenant %s, timeline %s", lsn, tenant_id, timeline_id) res = self.get( f"http://localhost:{self.port}/v1/tenant/{tenant_id}/timeline/{timeline_id}/get_timestamp_of_lsn?lsn={lsn}", ) @@ -629,7 +629,7 @@ def timeline_get_timestamp_of_lsn( def timeline_layer_map_info( self, tenant_id: Union[TenantId, TenantShardId], timeline_id: TimelineId ): - log.info(f"Requesting layer map info of tenant {tenant_id}, timeline {timeline_id}") + log.info("Requesting layer map info of tenant %s, timeline %s", tenant_id, timeline_id) res = self.get( f"http://localhost:{self.port}/v1/tenant/{tenant_id}/timeline/{timeline_id}/layer", ) @@ -654,12 +654,12 @@ def timeline_checkpoint( if wait_until_uploaded: query["wait_until_uploaded"] = "true" - log.info(f"Requesting checkpoint: tenant {tenant_id}, timeline {timeline_id}") + log.info("Requesting checkpoint: tenant %s, timeline %s", tenant_id, timeline_id) res = self.put( f"http://localhost:{self.port}/v1/tenant/{tenant_id}/timeline/{timeline_id}/checkpoint", params=query, ) - log.info(f"Got checkpoint request response code: {res.status_code}") + log.info("Got checkpoint request response code: %s", res.status_code) self.verbose_error(res) res_json = res.json() assert res_json is None @@ -903,10 +903,10 @@ def perf_info( ): self.is_testing_enabled_or_skip() - log.info(f"Requesting perf info: tenant {tenant_id}, timeline {timeline_id}") + log.info("Requesting perf info: tenant %s, timeline %s", tenant_id, timeline_id) res = self.post( f"http://localhost:{self.port}/v1/tenant/{tenant_id}/timeline/{timeline_id}/perf_info", ) - log.info(f"Got perf info response code: {res.status_code}") + log.info("Got perf info response code: %s", res.status_code) self.verbose_error(res) return res.json() diff --git a/test_runner/fixtures/pageserver/many_tenants.py b/test_runner/fixtures/pageserver/many_tenants.py index c437258c6f87..2f27771b5e14 100644 --- a/test_runner/fixtures/pageserver/many_tenants.py +++ b/test_runner/fixtures/pageserver/many_tenants.py @@ -37,13 +37,13 @@ def single_timeline( log.info("invoking callback to create template tenant") template_tenant, template_timeline, template_config = setup_template(env) log.info( - f"template tenant is template_tenant={template_tenant} template_timeline={template_timeline}" + "template tenant is template_tenant=%s template_timeline=%s", template_tenant, template_timeline ) log.info("detach template tenant form pageserver") env.pageserver.tenant_detach(template_tenant) - log.info(f"duplicating template tenant {ncopies} times in S3") + log.info("duplicating template tenant %s times in S3", ncopies) tenants = fixtures.pageserver.remote_storage.duplicate_tenant(env, template_tenant, ncopies) log.info("attach duplicated tenants to pageserver") diff --git a/test_runner/fixtures/pageserver/utils.py b/test_runner/fixtures/pageserver/utils.py index b75a480a637e..212d4566b9dc 100644 --- a/test_runner/fixtures/pageserver/utils.py +++ b/test_runner/fixtures/pageserver/utils.py @@ -22,7 +22,7 @@ def assert_tenant_state( message: Optional[str] = None, ) -> None: tenant_status = pageserver_http.tenant_status(tenant) - log.info(f"tenant_status: {tenant_status}") + log.info("tenant_status: %s", tenant_status) assert tenant_status["state"]["slug"] == expected_state, message or tenant_status @@ -58,7 +58,7 @@ def wait_for_upload( return lr_lsn = last_record_lsn(pageserver_http, tenant, timeline) log.info( - f"waiting for remote_consistent_lsn to reach {lsn}, now {current_lsn}, last_record_lsn={lr_lsn}, iteration {i + 1}" + "waiting for remote_consistent_lsn to reach %s, now %s, last_record_lsn=%s, iteration %s", lsn, current_lsn, lr_lsn, i + 1 ) time.sleep(1) raise Exception( @@ -88,9 +88,9 @@ def wait_until_tenant_state( try: tenant = pageserver_http.tenant_status(tenant_id=tenant_id) except Exception as e: - log.debug(f"Tenant {tenant_id} state retrieval failure: {e}") + log.debug("Tenant %s state retrieval failure: %s", tenant_id, e) else: - log.debug(f"Tenant {tenant_id} data: {tenant}") + log.debug("Tenant %s data: %s", tenant_id, tenant) if _tenant_in_expected_state(tenant, expected_state): return tenant @@ -116,7 +116,7 @@ def wait_until_all_tenants_state( tenants = pageserver_http.tenant_list() except Exception as e: if http_error_ok: - log.debug(f"Failed to list tenants: {e}") + log.debug("Failed to list tenants: %s", e) else: raise else: @@ -143,7 +143,7 @@ def wait_until_timeline_state( for i in range(iterations): try: timeline = pageserver_http.timeline_detail(tenant_id=tenant_id, timeline_id=timeline_id) - log.debug(f"Timeline {tenant_id}/{timeline_id} data: {timeline}") + log.debug("Timeline %s/%s data: %s", tenant_id, timeline_id, timeline) if isinstance(timeline["state"], str): if timeline["state"] == expected_state: return timeline @@ -152,7 +152,7 @@ def wait_until_timeline_state( return timeline except Exception as e: - log.debug(f"Timeline {tenant_id}/{timeline_id} state retrieval failure: {e}") + log.debug("Timeline %s/%s state retrieval failure: %s", tenant_id, timeline_id, e) if i == iterations - 1: # do not sleep last time, we already know that we failed @@ -204,7 +204,7 @@ def wait_for_last_record_lsn( return current_lsn if i % 10 == 0: log.info( - f"{tenant}/{timeline} waiting for last_record_lsn to reach {lsn}, now {current_lsn}, iteration {i + 1}" + "%s/%s waiting for last_record_lsn to reach %s, now %s, iteration %s", tenant, timeline, lsn, current_lsn, i + 1 ) time.sleep(0.1) raise Exception( @@ -248,9 +248,9 @@ def wait_for_upload_queue_empty( if not found: tl.append((s.labels, int(s.value))) assert len(tl) == len(started), "something broken with join logic" - log.info(f"upload queue for {tenant_id}/{timeline_id}:") + log.info("upload queue for %s/%s:", tenant_id, timeline_id) for labels, queue_count in tl: - log.info(f" {labels}: {queue_count}") + log.info(" %s: %s", labels, queue_count) if all(queue_count == 0 for (_, queue_count) in tl): return time.sleep(wait_period_secs) @@ -270,7 +270,7 @@ def timeline_is_missing(): data = {} try: data = pageserver_http.timeline_detail(tenant_id, timeline_id) - log.info(f"timeline detail {data}") + log.info("timeline detail %s", data) except PageserverApiException as e: log.debug(e) if e.status_code == 404: @@ -313,7 +313,7 @@ def assert_prefix_empty( # https://neon-github-public-dev.s3.amazonaws.com/reports/pr-5322/6207777020/index.html#suites/3556ed71f2d69272a7014df6dcb02317/53b5c368b5a68865 # this seems like a mock_s3 issue log.warning( - f"contradicting ListObjectsV2 response with KeyCount={keys} and Contents={objects}, CommonPrefixes={common_prefixes}, assuming this means KeyCount=0" + "contradicting ListObjectsV2 response with KeyCount=%s and Contents=%s, CommonPrefixes=%s, assuming this means KeyCount=0", keys, objects, common_prefixes ) keys = 0 elif keys != 0 and len(objects) == 0: @@ -321,7 +321,7 @@ def assert_prefix_empty( # https://neon-github-public-dev.s3.amazonaws.com/reports/pr-4938/6000769714/index.html#suites/3556ed71f2d69272a7014df6dcb02317/ca01e4f4d8d9a11f # looking at moto impl, it might be there's a race with common prefix (sub directory) not going away with deletes log.warning( - f"contradicting ListObjectsV2 response with KeyCount={keys} and Contents={objects}, CommonPrefixes={common_prefixes}" + "contradicting ListObjectsV2 response with KeyCount=%s and Contents=%s, CommonPrefixes=%s", keys, objects, common_prefixes ) filtered_count = 0 diff --git a/test_runner/fixtures/port_distributor.py b/test_runner/fixtures/port_distributor.py index fd808d7a5f7d..97adfcbd2788 100644 --- a/test_runner/fixtures/port_distributor.py +++ b/test_runner/fixtures/port_distributor.py @@ -25,7 +25,7 @@ def can_bind(host: str, port: int) -> bool: sock.listen() return True except socket.error: - log.info(f"Port {port} is in use, skipping") + log.info("Port %s is in use, skipping", port) return False finally: sock.close() diff --git a/test_runner/fixtures/remote_storage.py b/test_runner/fixtures/remote_storage.py index 3734efbb2ae4..67d04022e780 100644 --- a/test_runner/fixtures/remote_storage.py +++ b/test_runner/fixtures/remote_storage.py @@ -94,7 +94,7 @@ def timeline_latest_generation(self, tenant_id, timeline_id): index_parts = [f for f in timeline_files if f.startswith("index_part")] def parse_gen(filename): - log.info(f"parsing index_part '{filename}'") + log.info("parsing index_part '%s'", filename) parts = filename.split("-") if len(parts) == 2: return int(parts[1], 16) @@ -260,7 +260,7 @@ def do_cleanup(self): Delete=objects_to_delete, ) - log.info(f"deleted {cnt} objects from remote storage") + log.info("deleted %s objects from remote storage", cnt) def tenants_path(self) -> str: return f"{self.prefix_in_bucket}/tenants" @@ -335,7 +335,7 @@ def to_bucket_name(user: str, test_name: str) -> str: bucket_name = to_bucket_name(user, test_name) log.info( - f"using mock_s3 bucket name {bucket_name} for user={user}, test_name={test_name}" + "using mock_s3 bucket name %s for user=%s, test_name=%s", bucket_name, user, test_name ) return S3Storage( diff --git a/test_runner/fixtures/safekeeper/http.py b/test_runner/fixtures/safekeeper/http.py index 11e6fef28f17..1640c9306cd3 100644 --- a/test_runner/fixtures/safekeeper/http.py +++ b/test_runner/fixtures/safekeeper/http.py @@ -66,13 +66,13 @@ def configure_failpoints(self, config_strings: Union[Tuple[str, str], List[Tuple else: pairs = config_strings - log.info(f"Requesting config failpoints: {repr(pairs)}") + log.info("Requesting config failpoints: %s", repr(pairs)) res = self.put( f"http://localhost:{self.port}/v1/failpoints", json=[{"name": name, "actions": actions} for name, actions in pairs], ) - log.info(f"Got failpoints request response code {res.status_code}") + log.info("Got failpoints request response code %s", res.status_code) res.raise_for_status() res_json = res.json() assert res_json is None diff --git a/test_runner/fixtures/safekeeper/utils.py b/test_runner/fixtures/safekeeper/utils.py index 0e4b5d78834f..04dce6a0b3b4 100644 --- a/test_runner/fixtures/safekeeper/utils.py +++ b/test_runner/fixtures/safekeeper/utils.py @@ -7,5 +7,5 @@ def are_walreceivers_absent( sk_http_cli: SafekeeperHttpClient, tenant_id: TenantId, timeline_id: TimelineId ): status = sk_http_cli.timeline_status(tenant_id, timeline_id) - log.info(f"waiting for walreceivers to be gone, currently {status.walreceivers}") + log.info("waiting for walreceivers to be gone, currently %s", status.walreceivers) return len(status.walreceivers) == 0 diff --git a/test_runner/fixtures/utils.py b/test_runner/fixtures/utils.py index 0989dc1893a7..7f2235b87a35 100644 --- a/test_runner/fixtures/utils.py +++ b/test_runner/fixtures/utils.py @@ -121,7 +121,7 @@ def run(self): try: with open(stdout_filename, "wb") as stdout_f: with open(stderr_filename, "wb") as stderr_f: - log.info(f'Capturing stdout to "{base}.stdout" and stderr to "{base}.stderr"') + log.info('Capturing stdout to "%s.stdout" and stderr to "%s.stderr"', base, base) p = subprocess.Popen( cmd, @@ -337,7 +337,7 @@ def allure_add_grafana_links(host: str, timeline_id: TimelineId, start_ms: int, for name, link in links.items(): allure.dynamic.link(link, name=name) - log.info(f"{name}: {link}") + log.info("%s: %s", name, link) def start_in_background( @@ -345,7 +345,7 @@ def start_in_background( ) -> subprocess.Popen[bytes]: """Starts a process, creates the logfile and redirects stderr and stdout there. Runs the start checks before the process is started, or errors.""" - log.info(f'Running command "{" ".join(command)}"') + log.info('Running command "%s"', " ".join(command)) with open(cwd / log_file_name, "wb") as log_file: spawned_process = subprocess.Popen(command, stdout=log_file, stderr=log_file, cwd=cwd) @@ -481,14 +481,14 @@ def scan_log_for_errors(input: Iterable[str], allowed_errors: List[str]) -> List def assert_no_errors(log_file, service, allowed_errors): if not log_file.exists(): - log.warning(f"Skipping {service} log check: {log_file} does not exist") + log.warning("Skipping %s log check: %s does not exist", service, log_file) return with log_file.open("r") as f: errors = scan_log_for_errors(f, allowed_errors) for _lineno, error in errors: - log.info(f"not allowed {service} error: {error.strip()}") + log.info("not allowed %s error: %s", service, error.strip()) assert not errors, f"First log error on {service}: {errors[0]}\nHint: use scripts/check_allowed_errors.sh to test any new allowed_error you add" @@ -559,7 +559,7 @@ def build_hash_list(p: Path) -> List[Tuple[str, bytes]]: assert len(mismatching) == 0, f"files with hash mismatch: {mismatching}" elapsed = time.time() - started_at - log.info(f"assert_pageserver_backups_equal completed in {elapsed}s") + log.info("assert_pageserver_backups_equal completed in %ss", elapsed) class PropagatingThread(threading.Thread): diff --git a/test_runner/fixtures/workload.py b/test_runner/fixtures/workload.py index dfd9caba3e94..40f6e3d875af 100644 --- a/test_runner/fixtures/workload.py +++ b/test_runner/fixtures/workload.py @@ -77,7 +77,7 @@ def endpoint(self, pageserver_id: Optional[int] = None) -> Endpoint: connstring = self._endpoint.safe_psql( "SELECT setting FROM pg_settings WHERE name='neon.pageserver_connstring'" ) - log.info(f"Workload.endpoint: connstr={connstring}") + log.info("Workload.endpoint: connstr=%s", connstring) return self._endpoint @@ -137,7 +137,7 @@ def churn_rows(self, n, pageserver_id: Optional[int] = None, upload=True, ingest end = start + n_iter - 1 log.info( - f"start,end = {start},{end}, cursor={self.churn_cursor}, expect_rows={self.expect_rows}" + "start,end = %s,%s, cursor=%s, expect_rows=%s", start, end, self.churn_cursor, self.expect_rows ) assert end < self.expect_rows @@ -176,9 +176,9 @@ def churn_rows(self, n, pageserver_id: Optional[int] = None, upload=True, ingest # Wait for written data to be uploaded to S3 (force a checkpoint to trigger upload) ps_http.timeline_checkpoint(tenant_shard_id, self.timeline_id) wait_for_upload(ps_http, tenant_shard_id, self.timeline_id, last_flush_lsn) - log.info(f"Churn: waiting for remote LSN {last_flush_lsn}") + log.info("Churn: waiting for remote LSN %s", last_flush_lsn) else: - log.info(f"Churn: not waiting for upload, disk LSN {last_flush_lsn}") + log.info("Churn: not waiting for upload, disk LSN %s", last_flush_lsn) def validate(self, pageserver_id: Optional[int] = None): endpoint = self.endpoint(pageserver_id) @@ -191,5 +191,5 @@ def validate(self, pageserver_id: Optional[int] = None): ] ) - log.info(f"validate({self.expect_rows}): {result}") + log.info("validate(%s): %s", self.expect_rows, result) assert result == [[("",)], [(self.expect_rows,)]] diff --git a/test_runner/performance/pageserver/pagebench/test_large_slru_basebackup.py b/test_runner/performance/pageserver/pagebench/test_large_slru_basebackup.py index b41ae601975f..6f0021adaa6c 100644 --- a/test_runner/performance/pageserver/pagebench/test_large_slru_basebackup.py +++ b/test_runner/performance/pageserver/pagebench/test_large_slru_basebackup.py @@ -155,14 +155,14 @@ def run_benchmark(env: NeonEnv, pg_bin: PgBin, record, duration_secs: int): # don't specify the targets explicitly, let pagebench auto-discover them ] - log.info(f"command: {' '.join(cmd)}") + log.info("command: %s", ' '.join(cmd)) basepath = pg_bin.run_capture(cmd, with_command_header=False) results_path = Path(basepath + ".stdout") - log.info(f"Benchmark results at: {results_path}") + log.info("Benchmark results at: %s", results_path) with open(results_path, "r") as f: results = json.load(f) - log.info(f"Results:\n{json.dumps(results, sort_keys=True, indent=2)}") + log.info("Results:\n%s", f"{json.dumps(results, sort_keys=True, indent=2)}") total = results["total"] metric = "request_count" diff --git a/test_runner/performance/pageserver/pagebench/test_ondemand_download_churn.py b/test_runner/performance/pageserver/pagebench/test_ondemand_download_churn.py index 644c1f559b80..5560fff519b5 100644 --- a/test_runner/performance/pageserver/pagebench/test_ondemand_download_churn.py +++ b/test_runner/performance/pageserver/pagebench/test_ondemand_download_churn.py @@ -125,14 +125,14 @@ def run_benchmark( # don't specify the targets explicitly, let pagebench auto-discover them ] - log.info(f"command: {' '.join(cmd)}") + log.info("command: %s", ' '.join(cmd)) basepath = pg_bin.run_capture(cmd, with_command_header=False) results_path = Path(basepath + ".stdout") - log.info(f"Benchmark results at: {results_path}") + log.info("Benchmark results at: %s", results_path) with open(results_path, "r") as f: results = json.load(f) - log.info(f"Results:\n{json.dumps(results, sort_keys=True, indent=2)}") + log.info("Results:\n%s", f"{json.dumps(results, sort_keys=True, indent=2)}") metric = "downloads_count" record( diff --git a/test_runner/performance/pageserver/pagebench/test_pageserver_max_throughput_getpage_at_latest_lsn.py b/test_runner/performance/pageserver/pagebench/test_pageserver_max_throughput_getpage_at_latest_lsn.py index 60861cf939b8..76b526c21778 100644 --- a/test_runner/performance/pageserver/pagebench/test_pageserver_max_throughput_getpage_at_latest_lsn.py +++ b/test_runner/performance/pageserver/pagebench/test_pageserver_max_throughput_getpage_at_latest_lsn.py @@ -220,14 +220,14 @@ def run_pagebench_benchmark( f"{duration_secs}s", # don't specify the targets explicitly, let pagebench auto-discover them ] - log.info(f"command: {' '.join(cmd)}") + log.info("command: %s", ' '.join(cmd)) basepath = pg_bin.run_capture(cmd, with_command_header=False) results_path = Path(basepath + ".stdout") - log.info(f"Benchmark results at: {results_path}") + log.info("Benchmark results at: %s", results_path) with open(results_path, "r") as f: results = json.load(f) - log.info(f"Results:\n{json.dumps(results, sort_keys=True, indent=2)}") + log.info("Results:\n%s", f"{json.dumps(results, sort_keys=True, indent=2)}") total = results["total"] diff --git a/test_runner/performance/test_branch_creation.py b/test_runner/performance/test_branch_creation.py index b3866f18135a..50f6d5b377c6 100644 --- a/test_runner/performance/test_branch_creation.py +++ b/test_runner/performance/test_branch_creation.py @@ -54,7 +54,7 @@ def test_branch_creation_heavy_write(neon_compare: NeonCompare, n_branches: int) ) def run_pgbench(branch: str): - log.info(f"Start a pgbench workload on branch {branch}") + log.info("Start a pgbench workload on branch %s", branch) endpoint = env.endpoints.create_start(branch, tenant_id=tenant) connstr = endpoint.connstr() @@ -81,7 +81,7 @@ def run_pgbench(branch: str): env.neon_cli.create_branch(f"b{i + 1}", f"b{p}", tenant_id=tenant) dur = timeit.default_timer() - timer - log.info(f"Creating branch b{i+1} took {dur}s") + log.info("Creating branch b%s took %ss", i+1, dur) branch_creation_durations.append(dur) threads.append(threading.Thread(target=run_pgbench, args=(f"b{i+1}",), daemon=True)) diff --git a/test_runner/performance/test_gc_feedback.py b/test_runner/performance/test_gc_feedback.py index 4c326111c247..c84f6f5ecfa6 100644 --- a/test_runner/performance/test_gc_feedback.py +++ b/test_runner/performance/test_gc_feedback.py @@ -61,7 +61,7 @@ def test_gc_feedback(neon_env_builder: NeonEnvBuilder, zenbenchmark: NeonBenchma # cur.execute("select pg_table_size('t')") # logical_size = cur.fetchone()[0] logical_size = client.timeline_detail(tenant_id, timeline_id)["current_logical_size"] - log.info(f"Logical storage size {logical_size}") + log.info("Logical storage size %s", logical_size) client.timeline_checkpoint(tenant_id, timeline_id) @@ -73,7 +73,7 @@ def test_gc_feedback(neon_env_builder: NeonEnvBuilder, zenbenchmark: NeonBenchma client.timeline_compact(tenant_id, timeline_id) physical_size = client.timeline_detail(tenant_id, timeline_id)["current_physical_size"] - log.info(f"Physical storage size {physical_size}") + log.info("Physical storage size %s", physical_size) max_num_of_deltas_above_image = 0 max_total_num_of_deltas = 0 @@ -146,6 +146,6 @@ def test_gc_feedback(neon_env_builder: NeonEnvBuilder, zenbenchmark: NeonBenchma cur.execute("SELECT * FROM t") # ensure data is not corrupted layer_map_path = env.repo_dir / "layer-map.json" - log.info(f"Writing layer map to {layer_map_path}") + log.info("Writing layer map to %s", layer_map_path) with layer_map_path.open("w") as f: f.write(json.dumps(client.timeline_layer_map_info(tenant_id, timeline_id))) diff --git a/test_runner/performance/test_logical_replication.py b/test_runner/performance/test_logical_replication.py index 7d11facc2949..ce304dca3654 100644 --- a/test_runner/performance/test_logical_replication.py +++ b/test_runner/performance/test_logical_replication.py @@ -37,7 +37,7 @@ def test_logical_replication(neon_simple_env: NeonEnv, pg_bin: PgBin, vanilla_pg # Wait logical replication to sync start = time.time() logical_replication_sync(vanilla_pg, endpoint) - log.info(f"Sync with master took {time.time() - start} seconds") + log.info("Sync with master took %s seconds", time.time() - start) sum_master = endpoint.safe_psql("select sum(abalance) from pgbench_accounts")[0][0] sum_replica = vanilla_pg.safe_psql("select sum(abalance) from pgbench_accounts")[0][0] diff --git a/test_runner/performance/test_perf_olap.py b/test_runner/performance/test_perf_olap.py index aaa2f8fec283..b464bcf460d2 100644 --- a/test_runner/performance/test_perf_olap.py +++ b/test_runner/performance/test_perf_olap.py @@ -153,14 +153,14 @@ def run_psql( label, query = labelled_query.label, labelled_query.query - log.info(f"Running query {label} {times} times") + log.info("Running query %s %s times", label, times) for i in range(times): run = i + 1 - log.info(f"Run {run}/{times}") + log.info("Run %s/%s", run, times) with env.zenbenchmark.record_duration(f"{label}/{run}"): env.pg_bin.run_capture(["psql", connstr, "-c", query], env=environ) if explain: - log.info(f"Explaining query {label}") + log.info("Explaining query %s", label) run += 1 with env.zenbenchmark.record_duration(f"{label}/EXPLAIN"): env.pg_bin.run_capture( diff --git a/test_runner/performance/test_seqscans.py b/test_runner/performance/test_seqscans.py index 67d4f3ae9bde..2987652d7494 100644 --- a/test_runner/performance/test_seqscans.py +++ b/test_runner/performance/test_seqscans.py @@ -54,7 +54,7 @@ def test_seqscans(env: PgCompare, scale: int, rows: int, iters: int, workers: in assert row is not None shared_buffers = row[0] table_size = row[1] - log.info(f"shared_buffers is {shared_buffers}, table size {table_size}") + log.info("shared_buffers is %s, table size %s", shared_buffers, table_size) assert int(shared_buffers) < int(table_size) env.zenbenchmark.record("table_size", table_size, "bytes", MetricReport.TEST_PARAM) diff --git a/test_runner/performance/test_sharding_autosplit.py b/test_runner/performance/test_sharding_autosplit.py index 9cd83f09599a..a0283462de67 100644 --- a/test_runner/performance/test_sharding_autosplit.py +++ b/test_runner/performance/test_sharding_autosplit.py @@ -146,7 +146,7 @@ def check_pgbench_output(out_path: str): # f"pgbench on tenant {endpoint.tenant_id} run at {out_path} has tps < {min_tps}" # ) - log.info(f"Checked {matched_lines} progress lines, lowest TPS was {min_tps}") + log.info("Checked %s progress lines, lowest TPS was %s", matched_lines, min_tps) if matched_lines == 0: raise RuntimeError(f"pgbench output at {out_path} contained no progress lines") @@ -223,7 +223,7 @@ def assert_all_split(): timeline_info = shard_zero_ps.http_client().timeline_detail( shard_zero_id, tenant_state.timeline_id ) - log.info(f"{shard_zero_id} timeline: {timeline_info}") + log.info("%s timeline: %s", shard_zero_id, timeline_info) # Run compaction for all tenants, restart endpoint so that on subsequent reads we will # definitely hit pageserver for reads. This compaction passis expected to drop unwanted diff --git a/test_runner/performance/test_storage_controller_scale.py b/test_runner/performance/test_storage_controller_scale.py index 3a6113706fa9..4bc7fd032af4 100644 --- a/test_runner/performance/test_storage_controller_scale.py +++ b/test_runner/performance/test_storage_controller_scale.py @@ -60,7 +60,7 @@ def get_consistent_node_shard_counts(env: NeonEnv, total_shards) -> defaultdict[ "secondary" ] - log.info(f"{tenant_placement=}") + log.info("%s", f"{tenant_placement=}") matching = { tid: intent[tid] for tid in observed if tid in intent and intent[tid] == observed[tid] @@ -155,7 +155,7 @@ def check_memory(): rss = env.storage_controller.get_metric_value("process_resident_memory_bytes") assert rss is not None - log.info(f"Resident memory: {rss} ({ rss / (shard_count * tenant_count)} per shard)") + log.info("Resident memory: %s (%s per shard)", rss, rss / (shard_count * tenant_count)) assert rss < expect_memory_per_shard * shard_count * tenant_count # We use a fixed seed to make the test somewhat reproducible: we want a randomly @@ -188,7 +188,7 @@ def check_memory(): for f in futs: f.result() log.info( - f"Created {len(tenants)} tenants in {time.time() - t1}, {len(tenants) / (time.time() - t1)}/s" + "Created %s tenants in %s, %s/s", len(tenants), time.time() - t1, len(tenants) / (time.time() - t1) ) run_ops = api_concurrency * 4 @@ -242,7 +242,7 @@ def check_memory(): # Time how long a no-op background reconcile takes: this measures how long it takes to # loop over all the shards looking for work to do. runtime = time.time() - t1 - log.info(f"No-op call to reconcile_all took {runtime}s") + log.info("No-op call to reconcile_all took %ss", runtime) assert runtime < 1 break @@ -262,7 +262,7 @@ def check_memory(): check_memory() shard_counts = get_consistent_node_shard_counts(env, total_shards) - log.info(f"Shard counts before rolling restart: {shard_counts}") + log.info("Shard counts before rolling restart: %s", shard_counts) assert_consistent_balanced_attachments(env, total_shards) @@ -278,7 +278,7 @@ def check_memory(): ) shard_counts = get_consistent_node_shard_counts(env, total_shards) - log.info(f"Shard counts after draining node {ps.id}: {shard_counts}") + log.info("Shard counts after draining node %s: %s", ps.id, shard_counts) # Assert that we've drained the node assert shard_counts[str(ps.id)] == 0 # Assert that those shards actually went somewhere @@ -293,7 +293,7 @@ def check_memory(): env.storage_controller.poll_node_status(ps.id, "Active", max_attempts=24, backoff=5) shard_counts = get_consistent_node_shard_counts(env, total_shards) - log.info(f"Shard counts after filling node {ps.id}: {shard_counts}") + log.info("Shard counts after filling node %s: %s", ps.id, shard_counts) assert_consistent_balanced_attachments(env, total_shards) diff --git a/test_runner/performance/test_wal_backpressure.py b/test_runner/performance/test_wal_backpressure.py index 513ebc74c38f..36757307f915 100644 --- a/test_runner/performance/test_wal_backpressure.py +++ b/test_runner/performance/test_wal_backpressure.py @@ -228,7 +228,7 @@ def record_lsn_write_lag(env: PgCompare, run_cond: Callable[[], bool], pool_inte last_pg_flush_lsn = curr_pg_flush_lsn log.info( - f"received_lsn_lag={res[1]}, pg_flush_lsn={res[2]}, received_lsn={res[3]}, lsn_process_speed={lsn_process_speed:.2f}MB/s, lsn_produce_speed={lsn_produce_speed:.2f}MB/s" + "received_lsn_lag=%s, pg_flush_lsn=%s, received_lsn=%s, lsn_process_speed=%sMB/s, lsn_produce_speed=%sMB/s", res[1], res[2], res[3], f"{lsn_process_speed:.2f}", f"{lsn_produce_speed:.2f}" ) time.sleep(pool_interval) @@ -266,11 +266,11 @@ def record_read_latency( t2 = timeit.default_timer() log.info( - f"Executed read query {read_query}, got {cur.fetchall()}, read time {t2-t1:.2f}s" + "Executed read query %s, got %s, read time %ss", read_query, cur.fetchall(), f"{t2-t1:.2f}" ) read_latencies.append(t2 - t1) except Exception as err: - log.error(f"Got error when executing the read query: {err}") + log.error("Got error when executing the read query: %s", err) time.sleep(read_interval) diff --git a/test_runner/regress/test_ancestor_branch.py b/test_runner/regress/test_ancestor_branch.py index 7e40081aa2a0..b4642aa5e04f 100644 --- a/test_runner/regress/test_ancestor_branch.py +++ b/test_runner/regress/test_ancestor_branch.py @@ -25,11 +25,11 @@ def test_ancestor_branch(neon_env_builder: NeonEnvBuilder): endpoint_branch0 = env.endpoints.create_start("main", tenant_id=tenant) branch0_cur = endpoint_branch0.connect().cursor() branch0_timeline = TimelineId(query_scalar(branch0_cur, "SHOW neon.timeline_id")) - log.info(f"b0 timeline {branch0_timeline}") + log.info("b0 timeline %s", branch0_timeline) # Create table, and insert 100k rows. branch0_lsn = query_scalar(branch0_cur, "SELECT pg_current_wal_insert_lsn()") - log.info(f"b0 at lsn {branch0_lsn}") + log.info("b0 at lsn %s", branch0_lsn) branch0_cur.execute("CREATE TABLE foo (t text) WITH (autovacuum_enabled = off)") branch0_cur.execute( @@ -40,7 +40,7 @@ def test_ancestor_branch(neon_env_builder: NeonEnvBuilder): """ ) lsn_100 = query_scalar(branch0_cur, "SELECT pg_current_wal_insert_lsn()") - log.info(f"LSN after 100k rows: {lsn_100}") + log.info("LSN after 100k rows: %s", lsn_100) # Create branch1. env.neon_cli.create_branch("branch1", "main", tenant_id=tenant, ancestor_start_lsn=lsn_100) @@ -48,10 +48,10 @@ def test_ancestor_branch(neon_env_builder: NeonEnvBuilder): branch1_cur = endpoint_branch1.connect().cursor() branch1_timeline = TimelineId(query_scalar(branch1_cur, "SHOW neon.timeline_id")) - log.info(f"b1 timeline {branch1_timeline}") + log.info("b1 timeline %s", branch1_timeline) branch1_lsn = query_scalar(branch1_cur, "SELECT pg_current_wal_insert_lsn()") - log.info(f"b1 at lsn {branch1_lsn}") + log.info("b1 at lsn %s", branch1_lsn) # Insert 100k rows. branch1_cur.execute( @@ -62,7 +62,7 @@ def test_ancestor_branch(neon_env_builder: NeonEnvBuilder): """ ) lsn_200 = query_scalar(branch1_cur, "SELECT pg_current_wal_insert_lsn()") - log.info(f"LSN after 200k rows: {lsn_200}") + log.info("LSN after 200k rows: %s", lsn_200) # Create branch2. env.neon_cli.create_branch("branch2", "branch1", tenant_id=tenant, ancestor_start_lsn=lsn_200) @@ -70,10 +70,10 @@ def test_ancestor_branch(neon_env_builder: NeonEnvBuilder): branch2_cur = endpoint_branch2.connect().cursor() branch2_timeline = TimelineId(query_scalar(branch2_cur, "SHOW neon.timeline_id")) - log.info(f"b2 timeline {branch2_timeline}") + log.info("b2 timeline %s", branch2_timeline) branch2_lsn = query_scalar(branch2_cur, "SELECT pg_current_wal_insert_lsn()") - log.info(f"b2 at lsn {branch2_lsn}") + log.info("b2 at lsn %s", branch2_lsn) # Insert 100k rows. branch2_cur.execute( @@ -84,7 +84,7 @@ def test_ancestor_branch(neon_env_builder: NeonEnvBuilder): """ ) lsn_300 = query_scalar(branch2_cur, "SELECT pg_current_wal_insert_lsn()") - log.info(f"LSN after 300k rows: {lsn_300}") + log.info("LSN after 300k rows: %s", lsn_300) # Run compaction on branch1. compact = f"compact {tenant} {branch1_timeline}" diff --git a/test_runner/regress/test_aux_files.py b/test_runner/regress/test_aux_files.py index 5328aef15678..d38f7451b92b 100644 --- a/test_runner/regress/test_aux_files.py +++ b/test_runner/regress/test_aux_files.py @@ -40,7 +40,7 @@ def test_aux_v2_config_switch(neon_env_builder: NeonEnvBuilder, vanilla_pg): "CREATE TABLE replication_example(id SERIAL PRIMARY KEY, somedata int, text varchar(120), testcolumn1 int, testcolumn2 int, testcolumn3 int);" ) connstr = endpoint.connstr().replace("'", "''") - log.info(f"ep connstr is {endpoint.connstr()}, subscriber connstr {vanilla_pg.connstr()}") + log.info("ep connstr is %s, subscriber connstr %s", endpoint.connstr(), vanilla_pg.connstr()) vanilla_pg.safe_psql(f"create subscription sub1 connection '{connstr}' publication pub1") # Wait logical replication channel to be established diff --git a/test_runner/regress/test_backpressure.py b/test_runner/regress/test_backpressure.py index 819912dd0517..6329771daf9e 100644 --- a/test_runner/regress/test_backpressure.py +++ b/test_runner/regress/test_backpressure.py @@ -27,17 +27,17 @@ def check_backpressure(endpoint: Endpoint, stop_event: threading.Event, polling_ cur.execute("select pg_size_bytes(current_setting('max_replication_write_lag'))") res = cur.fetchone() max_replication_write_lag_bytes = res[0] - log.info(f"max_replication_write_lag: {max_replication_write_lag_bytes} bytes") + log.info("max_replication_write_lag: %s bytes", max_replication_write_lag_bytes) cur.execute("select pg_size_bytes(current_setting('max_replication_flush_lag'))") res = cur.fetchone() max_replication_flush_lag_bytes = res[0] - log.info(f"max_replication_flush_lag: {max_replication_flush_lag_bytes} bytes") + log.info("max_replication_flush_lag: %s bytes", max_replication_flush_lag_bytes) cur.execute("select pg_size_bytes(current_setting('max_replication_apply_lag'))") res = cur.fetchone() max_replication_apply_lag_bytes = res[0] - log.info(f"max_replication_apply_lag: {max_replication_apply_lag_bytes} bytes") + log.info("max_replication_apply_lag: %s bytes", max_replication_apply_lag_bytes) with pg_cur(endpoint) as cur: while not stop_event.is_set(): @@ -60,9 +60,11 @@ def check_backpressure(endpoint: Endpoint, stop_event: threading.Event, polling_ remote_consistent_lsn_lag = res[2] log.info( - f"received_lsn_lag = {received_lsn_lag} ({res[3]}), " - f"disk_consistent_lsn_lag = {disk_consistent_lsn_lag} ({res[4]}), " - f"remote_consistent_lsn_lag = {remote_consistent_lsn_lag} ({res[5]})" + "received_lsn_lag = %s (%s), " + "disk_consistent_lsn_lag = %s (%s), " + "remote_consistent_lsn_lag = %s (%s)", + received_lsn_lag, res[3], disk_consistent_lsn_lag, res[4], remote_consistent_lsn_lag, + res[5] ) # Since feedback from pageserver is not immediate, we should allow some lag overflow @@ -80,7 +82,7 @@ def check_backpressure(endpoint: Endpoint, stop_event: threading.Event, polling_ time.sleep(polling_interval) except Exception as e: - log.info(f"backpressure check query failed: {e}") + log.info("backpressure check query failed: %s", e) stop_event.set() log.info("check thread stopped") @@ -150,7 +152,7 @@ def test_backpressure_received_lsn_lag(neon_env_builder: NeonEnvBuilder): f"Exception {e} while inserting rows and WAL lag overflowed configured threshold. That means backpressure doesn't work." ) from e - log.info(f"inserted {rows_inserted} rows") + log.info("inserted %s rows", rows_inserted) if check_thread.is_alive(): log.info("stopping check thread") diff --git a/test_runner/regress/test_bad_connection.py b/test_runner/regress/test_bad_connection.py index 82a3a05c2ba7..9c6a64b1ef83 100644 --- a/test_runner/regress/test_bad_connection.py +++ b/test_runner/regress/test_bad_connection.py @@ -29,7 +29,7 @@ def execute_retry_on_timeout(query): cur.execute(query) return except psycopg2.errors.QueryCanceled: - log.info(f"Query '{query}' timed out - retrying") + log.info("Query '%s' timed out - retrying", query) # Create table, and insert some rows. Make it big enough that it doesn't fit in # shared_buffers, otherwise the SELECT after restart will just return answer @@ -53,7 +53,7 @@ def execute_retry_on_timeout(query): ) row = cur.fetchone() assert row is not None - log.info(f"shared_buffers is {row[0]}, table size {row[1]}") + log.info("shared_buffers is %s, table size %s", row[0], row[1]) assert int(row[0]) < int(row[1]) execute_retry_on_timeout("SELECT count(*) FROM foo") @@ -68,4 +68,4 @@ def execute_retry_on_timeout(query): execute_retry_on_timeout("SELECT t FROM foo ORDER BY RANDOM() LIMIT 10") cur.fetchall() times_executed += 1 - log.info(f"Workload executed {times_executed} times") + log.info("Workload executed %s times", times_executed) diff --git a/test_runner/regress/test_branch_and_gc.py b/test_runner/regress/test_branch_and_gc.py index eb503ddbfa0d..cdf91c4ba569 100644 --- a/test_runner/regress/test_branch_and_gc.py +++ b/test_runner/regress/test_branch_and_gc.py @@ -80,11 +80,11 @@ def test_branch_and_gc(neon_simple_env: NeonEnv, build_type: str): ) main_cur.execute("INSERT INTO foo SELECT FROM generate_series(1, 100000)") lsn1 = Lsn(query_scalar(main_cur, "SELECT pg_current_wal_insert_lsn()")) - log.info(f"LSN1: {lsn1}") + log.info("LSN1: %s", lsn1) main_cur.execute("INSERT INTO foo SELECT FROM generate_series(1, 100000)") lsn2 = Lsn(query_scalar(main_cur, "SELECT pg_current_wal_insert_lsn()")) - log.info(f"LSN2: {lsn2}") + log.info("LSN2: %s", lsn2) # Set the GC horizon so that lsn1 is inside the horizon, which means # we can create a new branch starting from lsn1. @@ -181,7 +181,7 @@ def do_gc(): with pytest.raises(TimelineCreate406): new_timeline_id = TimelineId.generate() log.info( - f"Expecting failure for branch behind gc'ing LSN, new_timeline_id={new_timeline_id}" + "Expecting failure for branch behind gc'ing LSN, new_timeline_id=%s", new_timeline_id ) pageserver_http_client.timeline_create(env.pg_version, tenant, new_timeline_id, b0, lsn) diff --git a/test_runner/regress/test_branch_behind.py b/test_runner/regress/test_branch_behind.py index 0a5336f5a246..88e04c3631a2 100644 --- a/test_runner/regress/test_branch_behind.py +++ b/test_runner/regress/test_branch_behind.py @@ -42,7 +42,7 @@ def test_branch_behind(neon_env_builder: NeonEnvBuilder): """ ) lsn_a = Lsn(query_scalar(main_cur, "SELECT pg_current_wal_insert_lsn()")) - log.info(f"LSN after 100 rows: {lsn_a}") + log.info("LSN after 100 rows: %s", lsn_a) # Insert some more rows. (This generates enough WAL to fill a few segments.) main_cur.execute( @@ -53,7 +53,7 @@ def test_branch_behind(neon_env_builder: NeonEnvBuilder): """ ) lsn_b = Lsn(query_scalar(main_cur, "SELECT pg_current_wal_insert_lsn()")) - log.info(f"LSN after 200100 rows: {lsn_b}") + log.info("LSN after 200100 rows: %s", lsn_b) # Branch at the point where only 100 rows were inserted env.neon_cli.create_branch( @@ -70,7 +70,7 @@ def test_branch_behind(neon_env_builder: NeonEnvBuilder): ) lsn_c = Lsn(query_scalar(main_cur, "SELECT pg_current_wal_insert_lsn()")) - log.info(f"LSN after 400100 rows: {lsn_c}") + log.info("LSN after 400100 rows: %s", lsn_c) # Branch at the point where only 200100 rows were inserted env.neon_cli.create_branch( @@ -107,7 +107,7 @@ def test_branch_behind(neon_env_builder: NeonEnvBuilder): # retry the same with the HTTP API, so that we can inspect the status code with pytest.raises(TimelineCreate406): new_timeline_id = TimelineId.generate() - log.info(f"Expecting failure for branch pre-initdb LSN, new_timeline_id={new_timeline_id}") + log.info("Expecting failure for branch pre-initdb LSN, new_timeline_id=%s", new_timeline_id) pageserver_http.timeline_create( env.pg_version, env.initial_tenant, new_timeline_id, env.initial_timeline, Lsn("0/42") ) @@ -121,7 +121,7 @@ def test_branch_behind(neon_env_builder: NeonEnvBuilder): with pytest.raises(TimelineCreate406): new_timeline_id = TimelineId.generate() log.info( - f"Expecting failure for branch pre-ancestor LSN, new_timeline_id={new_timeline_id}" + "Expecting failure for branch pre-ancestor LSN, new_timeline_id=%s", new_timeline_id ) pageserver_http.timeline_create( env.pg_version, @@ -143,7 +143,7 @@ def test_branch_behind(neon_env_builder: NeonEnvBuilder): # retry the same with the HTTP API, so that we can inspect the status code with pytest.raises(TimelineCreate406): new_timeline_id = TimelineId.generate() - log.info(f"Expecting failure for branch behind gc'd LSN, new_timeline_id={new_timeline_id}") + log.info("Expecting failure for branch behind gc'd LSN, new_timeline_id=%s", new_timeline_id) pageserver_http.timeline_create( env.pg_version, env.initial_tenant, new_timeline_id, branch_behind_timeline_id, gced_lsn ) diff --git a/test_runner/regress/test_branching.py b/test_runner/regress/test_branching.py index 03d6946c1581..6f61cbcac379 100644 --- a/test_runner/regress/test_branching.py +++ b/test_runner/regress/test_branching.py @@ -51,7 +51,7 @@ def test_branching_with_pgbench( ) def run_pgbench(connstr: str): - log.info(f"Start a pgbench workload on pg {connstr}") + log.info("Start a pgbench workload on pg %s", connstr) pg_bin.run_capture(["pgbench", "-i", f"-s{scale}", connstr]) pg_bin.run_capture(["pgbench", "-T15", connstr]) @@ -72,7 +72,7 @@ def run_pgbench(connstr: str): # random a delay between [0, 5] delay = random.random() * 5 time.sleep(delay) - log.info(f"Sleep {delay}s") + log.info("Sleep %ss", delay) # If the number of concurrent threads exceeds a threshold, wait for # all the threads to finish before spawning a new one. Because the @@ -133,7 +133,7 @@ def test_branching_unnormalized_start_lsn(neon_simple_env: NeonEnv, pg_bin: PgBi # and is smaller than `curr_lsn`. start_lsn = Lsn((int(curr_lsn) - XLOG_BLCKSZ) // XLOG_BLCKSZ * XLOG_BLCKSZ) - log.info(f"Branching b1 from b0 starting at lsn {start_lsn}...") + log.info("Branching b1 from b0 starting at lsn %s...", start_lsn) env.neon_cli.create_branch("b1", "b0", ancestor_start_lsn=start_lsn) endpoint1 = env.endpoints.create_start("b1") @@ -262,14 +262,14 @@ def test_non_uploaded_root_timeline_is_deleted_after_restart(neon_env_builder: N # Create a timeline whose creation will succeed. The tenant will need at least one # timeline to be loadable. success_timeline = TimelineId.generate() - log.info(f"Creating timeline {success_timeline}") + log.info("Creating timeline %s", success_timeline) ps_http.timeline_create(env.pg_version, env.initial_tenant, success_timeline, timeout=60) # Create a timeline whose upload to remote storage will be blocked ps_http.configure_failpoints(("before-upload-index-pausable", "pause")) def start_creating_timeline(): - log.info(f"Creating (expect failure) timeline {env.initial_timeline}") + log.info("Creating (expect failure) timeline %s", env.initial_timeline) with pytest.raises(RequestException): ps_http.timeline_create( env.pg_version, env.initial_tenant, env.initial_timeline, timeout=60 @@ -354,7 +354,7 @@ def test_duplicate_creation(neon_env_builder: NeonEnvBuilder): env.pageserver.tenant_create(env.initial_tenant) success_timeline = TimelineId.generate() - log.info(f"Creating timeline {success_timeline}") + log.info("Creating timeline %s", success_timeline) ps_http = env.pageserver.http_client() success_result = ps_http.timeline_create( env.pg_version, env.initial_tenant, success_timeline, timeout=60 @@ -363,7 +363,7 @@ def test_duplicate_creation(neon_env_builder: NeonEnvBuilder): ps_http.configure_failpoints(("timeline-creation-after-uninit", "pause")) def start_creating_timeline(): - log.info(f"Creating (expect failure) timeline {env.initial_timeline}") + log.info("Creating (expect failure) timeline %s", env.initial_timeline) with pytest.raises(RequestException): ps_http.timeline_create( env.pg_version, env.initial_tenant, env.initial_timeline, timeout=60 diff --git a/test_runner/regress/test_broken_timeline.py b/test_runner/regress/test_broken_timeline.py index 61afd820caac..b941584b0325 100644 --- a/test_runner/regress/test_broken_timeline.py +++ b/test_runner/regress/test_broken_timeline.py @@ -54,7 +54,7 @@ def test_local_corruption(neon_env_builder: NeonEnvBuilder): # Leave the first timeline alone, but corrupt the others in different ways (tenant0, timeline0, pg0) = tenant_timelines[0] - log.info(f"Timeline {tenant0}/{timeline0} is left intact") + log.info("Timeline %s/%s is left intact", tenant0, timeline0) (tenant1, timeline1, pg1) = tenant_timelines[2] timeline_path = f"{env.pageserver.workdir}/tenants/{tenant1}/timelines/{timeline1}/" @@ -66,7 +66,7 @@ def test_local_corruption(neon_env_builder: NeonEnvBuilder): with open(p, "wb") as f: f.truncate(0) f.truncate(size) - log.info(f"Timeline {tenant1}/{timeline1} got its local layer files spoiled") + log.info("Timeline %s/%s got its local layer files spoiled", tenant1, timeline1) env.pageserver.start() @@ -82,7 +82,7 @@ def test_local_corruption(neon_env_builder: NeonEnvBuilder): with pytest.raises(Exception, match=f"{reconstruct_function_name} for layer ") as err: pg1.start() log.info( - f"As expected, compute startup failed for timeline {tenant1}/{timeline1} with corrupt layers: {err}" + "As expected, compute startup failed for timeline %s/%s with corrupt layers: %s", tenant1, timeline1, err ) diff --git a/test_runner/regress/test_change_pageserver.py b/test_runner/regress/test_change_pageserver.py index 4d2cdb8e320a..37b7fd2fb15e 100644 --- a/test_runner/regress/test_change_pageserver.py +++ b/test_runner/regress/test_change_pageserver.py @@ -54,7 +54,7 @@ def fetchone(): ) row = curs[0].fetchone() assert row is not None - log.info(f"shared_buffers is {row[0]}, table size {row[1]}") + log.info("shared_buffers is %s, table size %s", row[0], row[1]) assert int(row[0]) < int(row[1]) execute("SELECT count(*) FROM foo") diff --git a/test_runner/regress/test_clog_truncate.py b/test_runner/regress/test_clog_truncate.py index 26e6e336b972..efe5c1e5f9b5 100644 --- a/test_runner/regress/test_clog_truncate.py +++ b/test_runner/regress/test_clog_truncate.py @@ -44,10 +44,10 @@ def test_clog_truncate(neon_simple_env: NeonEnv): # wait for autovacuum to truncate the pg_xact # XXX Is it worth to add a timeout here? pg_xact_0000_path = os.path.join(endpoint.pg_xact_dir_path(), "0000") - log.info(f"pg_xact_0000_path = {pg_xact_0000_path}") + log.info("pg_xact_0000_path = %s", pg_xact_0000_path) while os.path.isfile(pg_xact_0000_path): - log.info(f"file exists. wait for truncation: {pg_xact_0000_path=}") + log.info("file exists. wait for truncation: %s", f"{pg_xact_0000_path=}") time.sleep(5) # checkpoint to advance latest lsn @@ -56,7 +56,7 @@ def test_clog_truncate(neon_simple_env: NeonEnv): lsn_after_truncation = query_scalar(cur, "select pg_current_wal_insert_lsn()") # create new branch after clog truncation and start a compute node on it - log.info(f"create branch at lsn_after_truncation {lsn_after_truncation}") + log.info("create branch at lsn_after_truncation %s", lsn_after_truncation) env.neon_cli.create_branch( "test_clog_truncate_new", "test_clog_truncate", ancestor_start_lsn=lsn_after_truncation ) @@ -64,5 +64,5 @@ def test_clog_truncate(neon_simple_env: NeonEnv): # check that new node doesn't contain truncated segment pg_xact_0000_path_new = os.path.join(endpoint2.pg_xact_dir_path(), "0000") - log.info(f"pg_xact_0000_path_new = {pg_xact_0000_path_new}") + log.info("pg_xact_0000_path_new = %s", pg_xact_0000_path_new) assert os.path.isfile(pg_xact_0000_path_new) is False diff --git a/test_runner/regress/test_close_fds.py b/test_runner/regress/test_close_fds.py index ce9ecb3dc4dd..87e4242eff38 100644 --- a/test_runner/regress/test_close_fds.py +++ b/test_runner/regress/test_close_fds.py @@ -47,7 +47,7 @@ def start_workload(): # parse the `lsof` command's output to get only the list of commands commands = [line.split(" ")[0] for line in res.stdout.strip().split("\n")[1:]] if len(commands) > 0: - log.info(f"lsof commands: {commands}") + log.info("lsof commands: %s", commands) assert commands == ["pageserve"] time.sleep(1.0) diff --git a/test_runner/regress/test_compaction.py b/test_runner/regress/test_compaction.py index 49dcb9b86a9d..5bb72f888c71 100644 --- a/test_runner/regress/test_compaction.py +++ b/test_runner/regress/test_compaction.py @@ -55,7 +55,7 @@ def test_pageserver_compaction_smoke(neon_env_builder: NeonEnvBuilder): for i in range(1, churn_rounds + 1): if i % 10 == 0: - log.info(f"Running churn round {i}/{churn_rounds} ...") + log.info("Running churn round %s/%s ...", i, churn_rounds) workload.churn_rows(row_count, env.pageserver.id) ps_http.timeline_compact(tenant_id, timeline_id) @@ -77,7 +77,7 @@ def test_pageserver_compaction_smoke(neon_env_builder: NeonEnvBuilder): metrics = env.pageserver.http_client().get_metrics() for name in layer_access_metric_names: layer_access_metrics = metrics.query_all(name) - log.info(f"Got metrics: {layer_access_metrics}") + log.info("Got metrics: %s", layer_access_metrics) non_vectored_sum = metrics.query_one("pageserver_layers_visited_per_read_global_sum") non_vectored_count = metrics.query_one("pageserver_layers_visited_per_read_global_count") @@ -95,7 +95,7 @@ def test_pageserver_compaction_smoke(neon_env_builder: NeonEnvBuilder): assert vectored_sum.value == 0 vectored_average = 0 - log.info(f"{non_vectored_average=} {vectored_average=}") + log.info("%s %s", f"{non_vectored_average=}", f"{vectored_average=}") # The upper bound for average number of layer visits below (8) # was chosen empirically for this workload. @@ -176,7 +176,7 @@ def test_sharding_compaction( assert layer.layer_file_size > 0 shard_has_image_layers.append(len(image_layer_sizes) > 1) - log.info(f"Shard {shard_id} image layer sizes: {json.dumps(image_layer_sizes, indent=2)}") + log.info("Shard %s image layer sizes: %s", shard_id, f"{json.dumps(image_layer_sizes, indent=2)}") if stripe_size == TINY_STRIPES: # Checking the average size validates that our keyspace partitioning is properly respecting sharding: if @@ -186,7 +186,7 @@ def test_sharding_compaction( # We only do this check with tiny stripes, because large stripes may not give all shards enough # data to have statistically significant image layers avg_size = sum(v for v in image_layer_sizes.values()) / len(image_layer_sizes) - log.info(f"Shard {shard_id} average image layer size: {avg_size}") + log.info("Shard %s average image layer size: %s", shard_id, avg_size) assert avg_size > compaction_target_size / 2 if stripe_size == TINY_STRIPES: @@ -249,7 +249,7 @@ def test_uploads_and_deletions( try: generate_uploads_and_deletions(env, pageserver=env.pageserver) except PageserverApiException as e: - log.info(f"Obtained PageserverApiException: {e}") + log.info("Obtained PageserverApiException: %s", e) # The errors occur flakily and no error is ensured to occur, # however at least one of them occurs. diff --git a/test_runner/regress/test_compatibility.py b/test_runner/regress/test_compatibility.py index 65649e0c0a84..5f0efd95f419 100644 --- a/test_runner/regress/test_compatibility.py +++ b/test_runner/regress/test_compatibility.py @@ -314,7 +314,7 @@ def check_neon_works(env: NeonEnv, test_output_dir: Path, sql_dump_path: Path, r pageserver_http.timeline_preserve_initdb_archive(tenant_id, timeline_id) except PageserverApiException as e: # Allow the error as we might be running the old pageserver binary - log.info(f"Got allowed error: '{e}'") + log.info("Got allowed error: '%s'", e) # Delete all files from local_fs_remote_storage except initdb-preserved.tar.zst, # the file is required for `timeline_create` with `existing_initdb_timeline_id`. diff --git a/test_runner/regress/test_ddl_forwarding.py b/test_runner/regress/test_ddl_forwarding.py index 50da673d87d0..8339a057a429 100644 --- a/test_runner/regress/test_ddl_forwarding.py +++ b/test_runner/regress/test_ddl_forwarding.py @@ -45,7 +45,7 @@ def handle_role(dbs, roles, operation): def ddl_forward_handler( request: Request, dbs: Dict[str, str], roles: Dict[str, str], ddl: "DdlForwardingContext" ) -> Response: - log.info(f"Received request with data {request.get_data(as_text=True)}") + log.info("Received request with data %s", f"{request.get_data(as_text=True)}") if ddl.fail: log.info("FAILING") return Response(status=500, response="Failed just cuz") @@ -80,7 +80,7 @@ def __init__(self, httpserver: HTTPServer, vanilla_pg: VanillaPostgres, host: st "shared_preload_libraries = 'neon'", ] ) - log.info(f"Listening on {ddl_url}") + log.info("Listening on %s", ddl_url) self.server.expect_request(endpoint, method="PATCH").respond_with_handler( lambda request: ddl_forward_handler(request, self.dbs, self.roles, self) ) @@ -123,7 +123,7 @@ def ddl( def test_ddl_forwarding(ddl: DdlForwardingContext): curr_user = ddl.send("SELECT current_user")[0][0] - log.info(f"Current user is {curr_user}") + log.info("Current user is %s", curr_user) ddl.send_and_wait("CREATE DATABASE bork") assert ddl.dbs == {"bork": curr_user} ddl.send_and_wait("CREATE ROLE volk WITH PASSWORD 'nu_zayats'") diff --git a/test_runner/regress/test_disk_usage_eviction.py b/test_runner/regress/test_disk_usage_eviction.py index 7722828c79dd..05ed190f0ed7 100644 --- a/test_runner/regress/test_disk_usage_eviction.py +++ b/test_runner/regress/test_disk_usage_eviction.py @@ -225,7 +225,7 @@ def _eviction_env( Creates two tenants, one somewhat larger than the other. """ - log.info(f"setting up eviction_env for test {request.node.name}") + log.info("setting up eviction_env for test %s", request.node.name) neon_env_builder.num_pageservers = num_pageservers neon_env_builder.enable_pageserver_remote_storage(RemoteStorageKind.LOCAL_FS) @@ -358,7 +358,7 @@ def test_broken_tenants_are_skipped(eviction_env: EvictionEnv): target = broken_size_pre + healthy_size_pre response = env.pageserver_http.disk_usage_eviction_run({"evict_bytes": target}) - log.info(f"{response}") + log.info("%s", response) broken_size_post, _, _ = poor_mans_du( env.neon_env, @@ -399,7 +399,7 @@ def test_pageserver_evicts_until_pressure_is_relieved( response = pageserver_http.disk_usage_eviction_run( {"evict_bytes": target, "eviction_order": order.config()} ) - log.info(f"{response}") + log.info("%s", response) (later_total_on_disk, _, _) = env.timelines_du(env.pageserver) @@ -462,7 +462,7 @@ def test_pageserver_respects_overridden_resident_size( response = ps_http.disk_usage_eviction_run( {"evict_bytes": target, "eviction_order": order.config()} ) - log.info(f"{response}") + log.info("%s", response) time.sleep(1) # give log time to flush assert not env.neon_env.pageserver.log_contains( @@ -508,7 +508,7 @@ def test_pageserver_falls_back_to_global_lru(eviction_env: EvictionEnv, order: E response = ps_http.disk_usage_eviction_run( {"evict_bytes": target, "eviction_order": order.config()} ) - log.info(f"{response}") + log.info("%s", response) (later_total_on_disk, _, _) = env.timelines_du(env.pageserver) actual_change = total_on_disk - later_total_on_disk @@ -556,7 +556,7 @@ def test_partial_evict_tenant(eviction_env: EvictionEnv, order: EvictionOrder): response = ps_http.disk_usage_eviction_run( {"evict_bytes": target, "eviction_order": order.config()} ) - log.info(f"{response}") + log.info("%s", response) (later_total_on_disk, _, _) = env.timelines_du(env.pageserver) actual_change = total_on_disk - later_total_on_disk @@ -581,11 +581,11 @@ def test_partial_evict_tenant(eviction_env: EvictionEnv, order: EvictionOrder): warm_upper = warm_lower + 3 * env.layer_size cold_upper = 2 * env.layer_size - log.info(f"tenants: warm={warm[0]}, cold={cold[0]}") + log.info("tenants: warm=%s, cold=%s", warm[0], cold[0]) log.info( - f"expecting for warm tenant: {human_bytes(warm_lower)} < {human_bytes(warm_size)} < {human_bytes(warm_upper)}" + "expecting for warm tenant: %s < %s < %s", human_bytes(warm_lower), human_bytes(warm_size), human_bytes(warm_upper) ) - log.info(f"expecting for cold tenant: {human_bytes(cold_size)} < {human_bytes(cold_upper)}") + log.info("expecting for cold tenant: %s < %s", human_bytes(cold_size), human_bytes(cold_upper)) assert warm_size > warm_lower, "warmed up tenant should be at about half size (lower)" assert warm_size < warm_upper, "warmed up tenant should be at about half size (upper)" @@ -602,7 +602,7 @@ def test_partial_evict_tenant(eviction_env: EvictionEnv, order: EvictionOrder): expected_ratio = later_total_on_disk / total_on_disk log.info( - f"freed up {100 * expected_ratio}%, expecting the layer counts to decrease in similar ratio" + "freed up %s%%, expecting the layer counts to decrease in similar ratio", 100 * expected_ratio ) for tenant_id, original_count in tenant_layers.items(): @@ -613,7 +613,7 @@ def test_partial_evict_tenant(eviction_env: EvictionEnv, order: EvictionOrder): expectation = 0.06 log.info( - f"tenant {tenant_id} layer count {original_count} -> {count_now}, ratio: {ratio}, expecting {abs_diff} < {expectation}" + "tenant %s layer count %s -> %s, ratio: %s, expecting %s < %s", tenant_id, original_count, count_now, ratio, abs_diff, expectation ) # in this test case both relative_spare and relative_equal produce # the same outcomes; this must be a quantization effect of similar @@ -660,7 +660,7 @@ def test_fast_growing_tenant(neon_env_builder: NeonEnvBuilder, pg_bin: PgBin, or response = env.pageserver.http_client().disk_usage_eviction_run( {"evict_bytes": total_on_disk // 5, "eviction_order": order.config()} ) - log.info(f"{response}") + log.info("%s", response) after_tenant_layers = count_layers_per_tenant(env.pageserver, map(lambda x: x[0], timelines)) @@ -668,14 +668,14 @@ def test_fast_growing_tenant(neon_env_builder: NeonEnvBuilder, pg_bin: PgBin, or for i, ((tenant_id, _timeline_id), _scale) in enumerate(timelines): # we expect the oldest to suffer most originally, after = tenant_layers[tenant_id], after_tenant_layers[tenant_id] - log.info(f"{i + 1}th tenant went from {originally} -> {after}") + log.info("%sth tenant went from %s -> %s", i + 1, originally, after) ratio = after / originally ratios.append(ratio) assert ( len(ratios) == 4 ), "rest of the assertions expect 3 + 1 timelines, ratios, scales, all in order" - log.info(f"{ratios}") + log.info("%s", ratios) if order == EvictionOrder.ABSOLUTE_ORDER: # first tenant loses most @@ -722,10 +722,10 @@ def poor_mans_du( else: smallest_layer = size if verbose: - log.info(f"{tenant_id}/{timeline_id} => {file.name} {size} ({human_bytes(size)})") + log.info("%s/%s => %s %s (%s)", tenant_id, timeline_id, file.name, size, human_bytes(size)) if verbose: - log.info(f"{tenant_id}/{timeline_id}: sum {total} ({human_bytes(total)})") + log.info("%s/%s: sum %s (%s)", tenant_id, timeline_id, total, human_bytes(total)) total_on_disk += total assert smallest_layer is not None or total_on_disk == 0 and largest_layer == 0 @@ -868,7 +868,7 @@ def test_secondary_mode_eviction(eviction_env_ha: EvictionEnv): }, ) readback_conf = ps_secondary.read_tenant_location_conf(tenant_id) - log.info(f"Read back conf: {readback_conf}") + log.info("Read back conf: %s", readback_conf) # Request secondary location to download all layers that the attached location indicated # in its heatmap @@ -878,7 +878,7 @@ def test_secondary_mode_eviction(eviction_env_ha: EvictionEnv): evict_bytes = total_size // 3 response = ps_secondary.http_client().disk_usage_eviction_run({"evict_bytes": evict_bytes}) - log.info(f"{response}") + log.info("%s", response) post_eviction_total_size, _, _ = env.timelines_du(ps_secondary) diff --git a/test_runner/regress/test_download_extensions.py b/test_runner/regress/test_download_extensions.py index 27eb05ac0912..c14c78dc9448 100644 --- a/test_runner/regress/test_download_extensions.py +++ b/test_runner/regress/test_download_extensions.py @@ -25,13 +25,13 @@ def neon_env_builder_local( pg_version: PgVersion, ) -> NeonEnvBuilder: test_local_pginstall = test_output_dir / "pg_install" - log.info(f"copy {pg_distrib_dir} to {test_local_pginstall}") + log.info("copy %s to %s", pg_distrib_dir, test_local_pginstall) shutil.copytree( pg_distrib_dir / pg_version.v_prefixed, test_local_pginstall / pg_version.v_prefixed ) neon_env_builder.pg_distrib_dir = test_local_pginstall - log.info(f"local neon_env_builder.pg_distrib_dir: {neon_env_builder.pg_distrib_dir}") + log.info("local neon_env_builder.pg_distrib_dir: %s", neon_env_builder.pg_distrib_dir) return neon_env_builder @@ -55,7 +55,7 @@ def test_remote_extensions( archive_path = f"{build_tag}/v{pg_version}/extensions/anon.tar.zst" def endpoint_handler_build_tag(request: Request) -> Response: - log.info(f"request: {request}") + log.info("request: %s", request) file_name = "anon.tar.zst" file_path = f"test_runner/regress/data/extension_test/5670669815/v{pg_version}/extensions/anon.tar.zst" diff --git a/test_runner/regress/test_explain_with_lfc_stats.py b/test_runner/regress/test_explain_with_lfc_stats.py index 5231dedcdac2..34cde66faa9d 100644 --- a/test_runner/regress/test_explain_with_lfc_stats.py +++ b/test_runner/regress/test_explain_with_lfc_stats.py @@ -12,7 +12,7 @@ def test_explain_with_lfc_stats(neon_simple_env: NeonEnv): branchname = "test_explain_with_lfc_stats" env.neon_cli.create_branch(branchname, "empty") - log.info(f"Creating endopint with 1MB shared_buffers and 64 MB LFC for branch {branchname}") + log.info("Creating endopint with 1MB shared_buffers and 64 MB LFC for branch %s", branchname) endpoint = env.endpoints.create_start( branchname, config_lines=[ @@ -25,7 +25,7 @@ def test_explain_with_lfc_stats(neon_simple_env: NeonEnv): cur = endpoint.connect().cursor() - log.info(f"preparing some data in {endpoint.connstr()}") + log.info("preparing some data in %s", endpoint.connstr()) ddl = """ CREATE TABLE pgbench_accounts ( @@ -45,7 +45,7 @@ def test_explain_with_lfc_stats(neon_simple_env: NeonEnv): "insert into pgbench_accounts(aid,bid,abalance,filler) select aid, (aid - 1) / 100000 + 1, 0, '' from generate_series(1, 100000) as aid;" ) - log.info(f"warming up caches with sequential scan in {endpoint.connstr()}") + log.info("warming up caches with sequential scan in %s", endpoint.connstr()) cur.execute("SELECT * FROM pgbench_accounts WHERE abalance > 0") log.info("running explain analyze without LFC values to verify they do not show up in the plan") diff --git a/test_runner/regress/test_fullbackup.py b/test_runner/regress/test_fullbackup.py index e6d51a77a6a7..351da3ea35f6 100644 --- a/test_runner/regress/test_fullbackup.py +++ b/test_runner/regress/test_fullbackup.py @@ -38,7 +38,7 @@ def test_fullbackup( cur.execute("CHECKPOINT") lsn = Lsn(query_scalar(cur, "SELECT pg_current_wal_insert_lsn()")) - log.info(f"start_backup_lsn = {lsn}") + log.info("start_backup_lsn = %s", lsn) # Get and unpack fullbackup from pageserver restored_dir_path = env.repo_dir / "restored_datadir" diff --git a/test_runner/regress/test_gc_aggressive.py b/test_runner/regress/test_gc_aggressive.py index 44133f2350e8..1c703e61a9f8 100644 --- a/test_runner/regress/test_gc_aggressive.py +++ b/test_runner/regress/test_gc_aggressive.py @@ -152,8 +152,8 @@ def get_num_remote_ops(file_kind: str, op_kind: str) -> int: # file unnecessarily. pageserver_http.timeline_compact(tenant_id, timeline_id) - log.info(f"{num_index_uploads} index uploads after GC iteration {i}") + log.info("%s index uploads after GC iteration %s", num_index_uploads, i) after = num_index_uploads - log.info(f"{after - before} new index uploads during test") + log.info("%s new index uploads during test", after - before) assert after - before < 5 diff --git a/test_runner/regress/test_hot_standby.py b/test_runner/regress/test_hot_standby.py index 8edc8c554c82..c04e342c1ff4 100644 --- a/test_runner/regress/test_hot_standby.py +++ b/test_runner/regress/test_hot_standby.py @@ -197,7 +197,7 @@ def test_hot_standby_gc(neon_env_builder: NeonEnvBuilder, pause_apply: bool): def run_pgbench(connstr: str, pg_bin: PgBin): - log.info(f"Start a pgbench workload on pg {connstr}") + log.info("Start a pgbench workload on pg %s", connstr) # s10 is about 150MB of data. In debug mode init takes about 15s on SSD. pg_bin.run_capture(["pgbench", "-i", "-s10", connstr]) log.info("pgbench init done") @@ -245,7 +245,7 @@ def test_hot_standby_feedback(neon_env_builder: NeonEnvBuilder, pg_bin: PgBin): ], ) as secondary: log.info( - f"primary connstr is {primary.connstr()}, secondary connstr {secondary.connstr()}" + "primary connstr is %s, secondary connstr %s", primary.connstr(), secondary.connstr() ) t = threading.Thread(target=run_pgbench, args=(primary.connstr(), pg_bin)) t.start() @@ -261,14 +261,14 @@ def xmin_is_not_null(): "select xmin from pg_replication_slots where slot_name = 'wal_proposer_slot'", log_query=False, ) - log.info(f"xmin is {slot_xmin}") + log.info("xmin is %s", slot_xmin) assert int(slot_xmin) > 0 wait_until(10, 1.0, xmin_is_not_null) for _ in range(1, 5): # in debug mode takes about 5-7s balance = secondary.safe_psql_scalar("select sum(abalance) from pgbench_accounts") - log.info(f"balance={balance}") + log.info("balance=%s", balance) log_replica_lag(primary, secondary) t.join() @@ -278,7 +278,7 @@ def xmin_is_null(): "select xmin from pg_replication_slots where slot_name = 'wal_proposer_slot'", log_query=False, ) - log.info(f"xmin is {slot_xmin}") + log.info("xmin is %s", slot_xmin) assert slot_xmin is None wait_until(10, 1.0, xmin_is_null) @@ -329,7 +329,7 @@ async def standby_workload(): # assert(writecounter - readcounter < 1000) assert readcounter <= writecounter if reads % 100 == 0: - log.info(f"read {reads}: counter {readcounter}, last update {writecounter}") + log.info("read %s: counter %s, last update %s", reads, readcounter, writecounter) reads += 1 await conn.execute("SELECT clear_buffer_cache()") diff --git a/test_runner/regress/test_import.py b/test_runner/regress/test_import.py index d97e882a7093..589445417cc1 100644 --- a/test_runner/regress/test_import.py +++ b/test_runner/regress/test_import.py @@ -190,7 +190,7 @@ def test_import_from_pageserver_multisegment( logical_size = env.pageserver.http_client().timeline_detail(env.initial_tenant, timeline)[ "current_logical_size" ] - log.info(f"timeline logical size = {logical_size / (1024 ** 2)}MB") + log.info("timeline logical size = %sMB", logical_size / (1024 ** 2)) assert logical_size > 1024**3 # = 1GB tar_output_file = _import(num_rows, lsn, env, pg_bin, timeline, test_output_dir) @@ -202,7 +202,7 @@ def test_import_from_pageserver_multisegment( for f in tar_f.getnames(): if segfile_re.search(f) is not None: cnt_seg_files += 1 - log.info(f"Found a segment file: {f} in the backup archive file") + log.info("Found a segment file: %s in the backup archive file", f) assert cnt_seg_files > 0 @@ -243,7 +243,7 @@ def _import( Returns: path to the backup archive file""" - log.info(f"start_backup_lsn = {lsn}") + log.info("start_backup_lsn = %s", lsn) # Get a fullbackup from pageserver tar_output_file = test_output_dir / "fullbackup.tar" diff --git a/test_runner/regress/test_ingestion_layer_size.py b/test_runner/regress/test_ingestion_layer_size.py index 44c77b341060..3a2a29a26d93 100644 --- a/test_runner/regress/test_ingestion_layer_size.py +++ b/test_runner/regress/test_ingestion_layer_size.py @@ -57,7 +57,7 @@ def test_ingesting_large_batches_of_images(neon_env_builder: NeonEnvBuilder, bui size = cur.fetchone() assert size is not None assert isinstance(size[0], int) - log.info(f"gin index size: {human_bytes(size[0])}") + log.info("gin index size: %s", human_bytes(size[0])) assert ( size[0] > checkpoint_distance * 3 ), f"gin index is not large enough: {human_bytes(size[0])}" @@ -116,7 +116,7 @@ def histogram_historic_layers( ) -> Histogram: def log_layer(layer: HistoricLayerInfo) -> HistoricLayerInfo: log.info( - f"{layer.layer_file_name} {human_bytes(layer.layer_file_size)} ({layer.layer_file_size} bytes)" + "%s %s (%s bytes)", layer.layer_file_name, human_bytes(layer.layer_file_size), layer.layer_file_size ) return layer @@ -147,5 +147,5 @@ def histogram(sizes: Iterable[int], minimum_sizes: List[Union[int, float]]) -> H def print_layer_size_histogram(h: Histogram): for index, min_size in enumerate(h.buckets): log.info( - f">= {human_bytes(min_size)}: {h.counts[index]} layers total {human_bytes(h.sums[index])}" + ">= %s: %s layers total %s", human_bytes(min_size), h.counts[index], human_bytes(h.sums[index]) ) diff --git a/test_runner/regress/test_large_schema.py b/test_runner/regress/test_large_schema.py index c5d5b5fe647f..86a0be197d8a 100644 --- a/test_runner/regress/test_large_schema.py +++ b/test_runner/regress/test_large_schema.py @@ -79,5 +79,5 @@ def test_large_schema(neon_env_builder: NeonEnvBuilder): ) for filename in os.listdir(timeline_path): if filename.startswith("00000"): - log.info(f"layer {filename} size is {os.path.getsize(timeline_path + filename)}") + log.info("layer %s size is %s", filename, os.path.getsize(timeline_path + filename)) assert os.path.getsize(timeline_path + filename) < 512_000_000 diff --git a/test_runner/regress/test_layer_bloating.py b/test_runner/regress/test_layer_bloating.py index 77dc8a35b5c2..42529f9a2c1f 100644 --- a/test_runner/regress/test_layer_bloating.py +++ b/test_runner/regress/test_layer_bloating.py @@ -36,7 +36,7 @@ def test_layer_bloating(neon_simple_env: NeonEnv, vanilla_pg): vanilla_pg.safe_psql("create table t(pk integer primary key)") connstr = endpoint.connstr().replace("'", "''") - log.info(f"ep connstr is {endpoint.connstr()}, subscriber connstr {vanilla_pg.connstr()}") + log.info("ep connstr is %s, subscriber connstr %s", endpoint.connstr(), vanilla_pg.connstr()) vanilla_pg.safe_psql(f"create subscription sub1 connection '{connstr}' publication pub1") cur.execute( @@ -58,8 +58,8 @@ def test_layer_bloating(neon_simple_env: NeonEnv, vanilla_pg): # Check layer file sizes timeline_path = f"{env.pageserver.workdir}/tenants/{env.initial_tenant}/timelines/{timeline}/" - log.info(f"Check {timeline_path}") + log.info("Check %s", timeline_path) for filename in os.listdir(timeline_path): if filename.startswith("00000"): - log.info(f"layer {filename} size is {os.path.getsize(timeline_path + filename)}") + log.info("layer %s size is %s", filename, os.path.getsize(timeline_path + filename)) assert os.path.getsize(timeline_path + filename) < 512_000_000 diff --git a/test_runner/regress/test_layers_from_future.py b/test_runner/regress/test_layers_from_future.py index 3b2218dd9b09..3329ec026fb4 100644 --- a/test_runner/regress/test_layers_from_future.py +++ b/test_runner/regress/test_layers_from_future.py @@ -147,13 +147,13 @@ def get_future_layers(): assert isinstance(future_layer, ImageLayerName) assert future_layer.lsn == last_record_lsn log.info( - f"got layer from the future: lsn={future_layer.lsn} disk_consistent_lsn={ip.disk_consistent_lsn} last_record_lsn={last_record_lsn}" + "got layer from the future: lsn=%s disk_consistent_lsn=%s last_record_lsn=%s", future_layer.lsn, ip.disk_consistent_lsn, last_record_lsn ) assert isinstance(env.pageserver_remote_storage, LocalFsStorage) future_layer_path = env.pageserver_remote_storage.remote_layer_path( tenant_id, timeline_id, future_layer.to_str() ) - log.info(f"future layer path: {future_layer_path}") + log.info("future layer path: %s", future_layer_path) pre_stat = future_layer_path.stat() time.sleep(1.1) # so that we can use change in pre_stat.st_mtime to detect overwrites @@ -192,7 +192,7 @@ def future_layer_is_gone_from_index_part(): future_layer_path = env.pageserver_remote_storage.remote_layer_path( tenant_id, timeline_id, future_layer.to_str(), generation=generation_before_detach ) - log.info(f"future layer path: {future_layer_path}") + log.info("future layer path: %s", future_layer_path) assert future_layer_path.exists() # wait for re-ingestion of the WAL from safekeepers into the in-memory layer @@ -232,7 +232,7 @@ def future_layer_is_gone_from_index_part(): log.info("integrity-check the remote storage") ip = get_index_part() for layer_file_name, layer_metadata in ip.layer_metadata.items(): - log.info(f"Layer metadata {layer_file_name.to_str()}: {layer_metadata}") + log.info("Layer metadata %s: %s", layer_file_name.to_str(), layer_metadata) layer_path = env.pageserver_remote_storage.remote_layer_path( tenant_id, timeline_id, layer_file_name.to_str(), layer_metadata.generation ) @@ -243,5 +243,5 @@ def future_layer_is_gone_from_index_part(): tenant_id, timeline_id, future_layer.to_str(), generation=generation_after_reattach ) final_stat = future_layer_path.stat() - log.info(f"future layer path: {future_layer_path}") + log.info("future layer path: %s", future_layer_path) assert final_stat.st_mtime != pre_stat.st_mtime diff --git a/test_runner/regress/test_lfc_resize.py b/test_runner/regress/test_lfc_resize.py index 2a3442448a10..d459aad61ffe 100644 --- a/test_runner/regress/test_lfc_resize.py +++ b/test_runner/regress/test_lfc_resize.py @@ -25,7 +25,7 @@ def test_lfc_resize(neon_simple_env: NeonEnv, pg_bin: PgBin): scale = 10 def run_pgbench(connstr: str): - log.info(f"Start a pgbench workload on pg {connstr}") + log.info("Start a pgbench workload on pg %s", connstr) pg_bin.run_capture(["pgbench", "-i", f"-s{scale}", connstr]) pg_bin.run_capture(["pgbench", "-c4", f"-T{n_resize}", "-Mprepared", connstr]) diff --git a/test_runner/regress/test_lfc_working_set_approximation.py b/test_runner/regress/test_lfc_working_set_approximation.py index 6465bdfd217d..97b6e92e134d 100644 --- a/test_runner/regress/test_lfc_working_set_approximation.py +++ b/test_runner/regress/test_lfc_working_set_approximation.py @@ -14,7 +14,7 @@ def test_lfc_working_set_approximation(neon_simple_env: NeonEnv): branchname = "test_approximate_working_set_size" env.neon_cli.create_branch(branchname, "empty") - log.info(f"Creating endopint with 1MB shared_buffers and 64 MB LFC for branch {branchname}") + log.info("Creating endopint with 1MB shared_buffers and 64 MB LFC for branch %s", branchname) endpoint = env.endpoints.create_start( branchname, config_lines=[ @@ -28,7 +28,7 @@ def test_lfc_working_set_approximation(neon_simple_env: NeonEnv): cur = endpoint.connect().cursor() cur.execute("create extension neon") - log.info(f"preparing some data in {endpoint.connstr()}") + log.info("preparing some data in %s", endpoint.connstr()) ddl = """ CREATE TABLE pgbench_accounts ( @@ -55,14 +55,14 @@ def test_lfc_working_set_approximation(neon_simple_env: NeonEnv): cur.execute("vacuum ANALYZE pgbench_accounts") # determine table size - working set should approximate table size after sequential scan pages = query_scalar(cur, "SELECT relpages FROM pg_class WHERE relname = 'pgbench_accounts'") - log.info(f"pgbench_accounts has {pages} pages, resetting working set to zero") + log.info("pgbench_accounts has %s pages, resetting working set to zero", pages) cur.execute("select approximate_working_set_size(true)") cur.execute( 'SELECT count(*) FROM pgbench_accounts WHERE abalance > 0 or jsonb_column_extended @> \'{"tell everyone": [{"Neon": "IsCool"}]}\'::jsonb' ) # verify working set size after sequential scan matches table size and reset working set for next test blocks = query_scalar(cur, "select approximate_working_set_size(true)") - log.info(f"working set size after sequential scan on pgbench_accounts {blocks}") + log.info("working set size after sequential scan on pgbench_accounts %s", blocks) assert pages * 0.8 < blocks < pages * 1.2 # run a few point queries with index lookup cur.execute("SELECT abalance FROM pgbench_accounts WHERE aid = 4242") @@ -71,7 +71,7 @@ def test_lfc_working_set_approximation(neon_simple_env: NeonEnv): cur.execute("SELECT abalance FROM pgbench_accounts WHERE aid = 204242") # verify working set size after some index access of a few select pages only blocks = query_scalar(cur, "select approximate_working_set_size(true)") - log.info(f"working set size after some index access of a few select pages only {blocks}") + log.info("working set size after some index access of a few select pages only %s", blocks) assert blocks < 10 @@ -104,15 +104,15 @@ def test_sliding_working_set_approximation(neon_simple_env: NeonEnv): cur.execute(f"select approximate_working_set_size_seconds({int(after - before_1k + 1)})") estimation_1k = cur.fetchall()[0][0] - log.info(f"Working set size for selecting 1k records {estimation_1k}") + log.info("Working set size for selecting 1k records %s", estimation_1k) cur.execute(f"select approximate_working_set_size_seconds({int(after - before_10k + 1)})") estimation_10k = cur.fetchall()[0][0] - log.info(f"Working set size for selecting 10k records {estimation_10k}") + log.info("Working set size for selecting 10k records %s", estimation_10k) cur.execute("select pg_table_size('t')") size = cur.fetchall()[0][0] // 8192 - log.info(f"Table size {size} blocks") + log.info("Table size %s blocks", size) assert estimation_1k >= 20 and estimation_1k <= 40 assert estimation_10k >= 200 and estimation_10k <= 400 diff --git a/test_runner/regress/test_logical_replication.py b/test_runner/regress/test_logical_replication.py index 41283e4d2ca0..51341f6a046b 100644 --- a/test_runner/regress/test_logical_replication.py +++ b/test_runner/regress/test_logical_replication.py @@ -57,7 +57,7 @@ def test_logical_replication(neon_simple_env: NeonEnv, vanilla_pg): "CREATE TABLE replication_example(id SERIAL PRIMARY KEY, somedata int, text varchar(120), testcolumn1 int, testcolumn2 int, testcolumn3 int);" ) connstr = endpoint.connstr().replace("'", "''") - log.info(f"ep connstr is {endpoint.connstr()}, subscriber connstr {vanilla_pg.connstr()}") + log.info("ep connstr is %s, subscriber connstr %s", endpoint.connstr(), vanilla_pg.connstr()) vanilla_pg.safe_psql(f"create subscription sub1 connection '{connstr}' publication pub1") # Wait logical replication channel to be established @@ -214,7 +214,7 @@ def slot_removed(ep): vanilla_pg.start() vanilla_pg.safe_psql("create table t(pk integer primary key, payload integer)") connstr = endpoint.connstr().replace("'", "''") - log.info(f"ep connstr is {endpoint.connstr()}, subscriber connstr {vanilla_pg.connstr()}") + log.info("ep connstr is %s, subscriber connstr %s", endpoint.connstr(), vanilla_pg.connstr()) vanilla_pg.safe_psql(f"create subscription sub1 connection '{connstr}' publication pub1") wait_until(number_of_iterations=10, interval=2, func=partial(slot_removed, endpoint)) @@ -354,7 +354,7 @@ def test_restart_endpoint(neon_simple_env: NeonEnv, vanilla_pg): vanilla_pg.safe_psql("create table t(pk integer primary key, value text)") vanilla_pg.safe_psql("CREATE TABLE replication_example(id SERIAL PRIMARY KEY, somedata int);") - log.info(f"ep connstr is {endpoint.connstr()}, subscriber connstr {vanilla_pg.connstr()}") + log.info("ep connstr is %s, subscriber connstr %s", endpoint.connstr(), vanilla_pg.connstr()) connstr = endpoint.connstr().replace("'", "''") vanilla_pg.safe_psql(f"create subscription sub1 connection '{connstr}' publication pub1") logical_replication_sync(vanilla_pg, endpoint) @@ -397,7 +397,7 @@ def test_large_records(neon_simple_env: NeonEnv, vanilla_pg): vanilla_pg.start() vanilla_pg.safe_psql("CREATE TABLE reptbl(id int, largeval text);") - log.info(f"ep connstr is {endpoint.connstr()}, subscriber connstr {vanilla_pg.connstr()}") + log.info("ep connstr is %s, subscriber connstr %s", endpoint.connstr(), vanilla_pg.connstr()) connstr = endpoint.connstr().replace("'", "''") vanilla_pg.safe_psql(f"create subscription sub1 connection '{connstr}' publication pub1") @@ -504,7 +504,7 @@ def test_replication_shutdown(neon_simple_env: NeonEnv): pub_conn = f"host=localhost port={pub.pg_port} dbname=neondb user=mr_whiskers password=cat" query = f"CREATE SUBSCRIPTION sub CONNECTION '{pub_conn}' PUBLICATION pub" - log.info(f"Creating subscription: {query}") + log.info("Creating subscription: %s", query) cur.execute(query) with pub.cursor(dbname="neondb", user="mr_whiskers", password="cat") as pcur: diff --git a/test_runner/regress/test_neon_superuser.py b/test_runner/regress/test_neon_superuser.py index fd31df84da2f..ab803947a2c1 100644 --- a/test_runner/regress/test_neon_superuser.py +++ b/test_runner/regress/test_neon_superuser.py @@ -62,7 +62,7 @@ def test_neon_superuser(neon_simple_env: NeonEnv, pg_version: PgVersion): pub_conn = f"host=localhost port={pub.pg_port} dbname=neondb user=mr_whiskers password=cat" query = f"CREATE SUBSCRIPTION sub CONNECTION '{pub_conn}' PUBLICATION pub" - log.info(f"Creating subscription: {query}") + log.info("Creating subscription: %s", query) cur.execute(query) with pub.cursor(dbname="neondb", user="mr_whiskers", password="cat") as pcur: @@ -95,5 +95,5 @@ def check_that_changes_propagated(): cur.execute("RESET ROLE") cur.execute("DROP ROLE not_a_superuser") query = "DROP SUBSCRIPTION sub CASCADE" - log.info(f"Dropping subscription: {query}") + log.info("Dropping subscription: %s", query) cur.execute(query) diff --git a/test_runner/regress/test_next_xid.py b/test_runner/regress/test_next_xid.py index 51e847135efd..ce36de34fee4 100644 --- a/test_runner/regress/test_next_xid.py +++ b/test_runner/regress/test_next_xid.py @@ -131,7 +131,7 @@ def test_import_at_2bil( # Advance nextXid close to 2 billion XIDs while True: xid = int(query_scalar(cur, "SELECT txid_current()")) - log.info(f"xid now {xid}") + log.info("xid now %s", xid) # Consume 10k transactons at a time until we get to 2^31 - 200k if xid < 2 * 1024 * 1024 * 1024 - 100000: cur.execute("select test_consume_xids(50000);") @@ -230,8 +230,8 @@ def advance_multixid_to( rec = cur.fetchone() assert rec is not None (ckpt_oldest_multi_xid, ckpt_next_multi_xid) = rec - log.info(f"oldestMultiXid was {ckpt_oldest_multi_xid}, nextMultiXid was {ckpt_next_multi_xid}") - log.info(f"Resetting to {next_multi_xid}") + log.info("oldestMultiXid was %s, nextMultiXid was %s", ckpt_oldest_multi_xid, ckpt_next_multi_xid) + log.info("Resetting to %s", next_multi_xid) # Use pg_resetwal to reset the next multiXid and multiOffset to given values. vanilla_pg.stop() @@ -253,13 +253,13 @@ def advance_multixid_to( # missing segments, but will clean it up by truncating the SLRUs up to the new value, # closing the gap. segname = "%04X" % MultiXactIdToOffsetSegment(next_multi_xid) - log.info(f"Creating dummy segment pg_multixact/offsets/{segname}") + log.info("Creating dummy segment pg_multixact/offsets/%s", segname) with open(vanilla_pg.pgdatadir / "pg_multixact" / "offsets" / segname, "w") as of: of.write("\0" * SLRU_PAGES_PER_SEGMENT * BLCKSZ) of.flush() segname = "%04X" % MXOffsetToMemberSegment(next_multi_offset) - log.info(f"Creating dummy segment pg_multixact/members/{segname}") + log.info("Creating dummy segment pg_multixact/members/%s", segname) with open(vanilla_pg.pgdatadir / "pg_multixact" / "members" / segname, "w") as of: of.write("\0" * SLRU_PAGES_PER_SEGMENT * BLCKSZ) of.flush() @@ -273,7 +273,7 @@ def advance_multixid_to( datminmxid = int( query_scalar(cur, "select min(datminmxid::text::int8) from pg_database") ) - log.info(f"datminmxid {datminmxid}") + log.info("datminmxid %s", datminmxid) if next_multi_xid - datminmxid < 1_000_000: # not wraparound-aware! break time.sleep(0.5) @@ -405,7 +405,7 @@ def test_multixid_wraparound_import( # not be the latest one, but close enough. row_xmax = int(query_scalar(cur3, "SELECT xmax FROM tt LIMIT 1")) cur3.execute("COMMIT") - log.info(f"observed a row with xmax {row_xmax}") + log.info("observed a row with xmax %s", row_xmax) # High value means not wrapped around yet if row_xmax >= 0xFFFFFF00: @@ -424,7 +424,7 @@ def test_multixid_wraparound_import( next_multixact_id_before_restart = row_xmax log.info( - f"next_multixact_id is now at {next_multixact_id_before_restart} or a little higher" + "next_multixact_id is now at %s or a little higher", next_multixact_id_before_restart ) break @@ -445,7 +445,7 @@ def test_multixid_wraparound_import( next_multixact_id_after_restart = int( query_scalar(cur, "select next_multixact_id from pg_control_checkpoint()") ) - log.info(f"next_multixact_id after restart: {next_multixact_id_after_restart}") + log.info("next_multixact_id after restart: %s", next_multixact_id_after_restart) assert next_multixact_id_after_restart >= next_multixact_id_before_restart # The multi-offset should wrap around as well @@ -453,5 +453,5 @@ def test_multixid_wraparound_import( next_multi_offset_after_restart = int( query_scalar(cur, "select next_multi_offset from pg_control_checkpoint()") ) - log.info(f"next_multi_offset after restart: {next_multi_offset_after_restart}") + log.info("next_multi_offset after restart: %s", next_multi_offset_after_restart) assert next_multi_offset_after_restart < 100000 diff --git a/test_runner/regress/test_old_request_lsn.py b/test_runner/regress/test_old_request_lsn.py index f1dd3fb67d37..ba2d53076dcc 100644 --- a/test_runner/regress/test_old_request_lsn.py +++ b/test_runner/regress/test_old_request_lsn.py @@ -49,7 +49,7 @@ def test_old_request_lsn(neon_env_builder: NeonEnvBuilder): ) row = cur.fetchone() assert row is not None - log.info(f"shared_buffers is {row[0]}, table size {row[1]}") + log.info("shared_buffers is %s, table size %s", row[0], row[1]) assert int(row[0]) < int(row[1]) cur.execute("VACUUM foo") diff --git a/test_runner/regress/test_ondemand_download.py b/test_runner/regress/test_ondemand_download.py index 4a25dfd874b4..e4406ddd0505 100644 --- a/test_runner/regress/test_ondemand_download.py +++ b/test_runner/regress/test_ondemand_download.py @@ -111,7 +111,7 @@ def test_ondemand_download_large_rel(neon_env_builder: NeonEnvBuilder): # remove all the layer files for layer in env.pageserver.tenant_dir().glob("*/timelines/*/*-*_*"): - log.info(f"unlinking layer {layer}") + log.info("unlinking layer %s", layer) layer.unlink() ##### Second start, restore the data and ensure it's the same @@ -134,7 +134,7 @@ def test_ondemand_download_large_rel(neon_env_builder: NeonEnvBuilder): assert query_scalar(cur, "select count(*) from tbl where id = 500000") == 1 after_downloads = get_num_downloaded_layers(client) - log.info(f"layers downloaded before {before_downloads} and after {after_downloads}") + log.info("layers downloaded before %s and after %s", before_downloads, after_downloads) assert after_downloads > before_downloads @@ -245,7 +245,7 @@ def get_resident_physical_size(): # remove all the layer files for layer in env.pageserver.tenant_dir().glob("*/timelines/*/*-*_*"): - log.info(f"unlinking layer {layer}") + log.info("unlinking layer %s", layer) layer.unlink() ##### Second start, restore the data and ensure it's the same @@ -285,7 +285,7 @@ def get_resident_physical_size(): after_downloads = get_num_downloaded_layers(client) num_layers_downloaded.append(after_downloads) - log.info(f"num_layers_downloaded[-1]={num_layers_downloaded[-1]}") + log.info("num_layers_downloaded[-1]=%s", num_layers_downloaded[-1]) # Check that on each query, we need to download at least one more layer file. However in # practice, thanks to compaction and the fact that some requests need to download @@ -294,13 +294,13 @@ def get_resident_physical_size(): # # Do a fuzzy check on that, by checking that after each point-in-time, we have downloaded # more files than we had three iterations ago. - log.info(f"layers downloaded after checkpoint {checkpoint_number}: {after_downloads}") + log.info("layers downloaded after checkpoint %s: %s", checkpoint_number, after_downloads) if len(num_layers_downloaded) > 4: assert after_downloads > num_layers_downloaded[len(num_layers_downloaded) - 4] # Likewise, assert that the resident_physical_size metric grows as layers are downloaded resident_size.append(get_resident_physical_size()) - log.info(f"resident_size[-1]={resident_size[-1]}") + log.info("resident_size[-1]=%s", resident_size[-1]) if len(resident_size) > 4: assert resident_size[-1] > resident_size[len(resident_size) - 4] @@ -387,16 +387,16 @@ def get_resident_physical_size(): wait_for_upload_queue_empty(client, tenant_id, timeline_id) filled_current_physical = get_api_current_physical_size() - log.info(f"filled_current_physical: {filled_current_physical}") + log.info("filled_current_physical: %s", filled_current_physical) filled_size = get_resident_physical_size() - log.info(f"filled_size: {filled_size}") + log.info("filled_size: %s", filled_size) assert filled_current_physical == filled_size, "we don't yet do layer eviction" env.pageserver.stop() # remove all the layer files for layer in env.pageserver.tenant_dir().glob("*/timelines/*/*-*_*"): - log.info(f"unlinking layer {layer.name}") + log.info("unlinking layer %s", layer.name) layer.unlink() ##### Second start, restore the data and ensure it's the same @@ -418,7 +418,7 @@ def get_resident_physical_size(): ), "current_physical_size is sum of loaded layer sizes, independent of whether local or remote" post_unlink_size = get_resident_physical_size() - log.info(f"post_unlink_size: {post_unlink_size}") + log.info("post_unlink_size: %s", post_unlink_size) assert ( post_unlink_size < filled_size ), "we just deleted layers and didn't cause anything to re-download them yet" @@ -431,7 +431,7 @@ def get_resident_physical_size(): errors_ok=True, at_least_one_download=False, ) - log.info(f"info={info}") + log.info("info=%s", info) assert info["state"] == "Completed" assert info["total_layer_count"] > 0 assert info["successful_download_count"] == 0 @@ -456,7 +456,7 @@ def get_resident_physical_size(): max_concurrent_downloads=10, errors_ok=False, ) - log.info(f"info={info}") + log.info("info=%s", info) assert info["state"] == "Completed" assert info["total_layer_count"] > 0 @@ -541,7 +541,7 @@ def downloaded_bytes_and_count(pageserver_http: PageserverHttpClient) -> Tuple[i layer_sizes = 0 for layer in layers.historic_layers: - log.info(f"pre-compact: {layer}") + log.info("pre-compact: %s", layer) layer_sizes += layer.layer_file_size pageserver_http.evict_layer(tenant_id, timeline_id, layer.layer_file_name) @@ -550,7 +550,7 @@ def downloaded_bytes_and_count(pageserver_http: PageserverHttpClient) -> Tuple[i pageserver_http.timeline_compact(tenant_id, timeline_id) layers = pageserver_http.layer_map_info(tenant_id, timeline_id) for layer in layers.historic_layers: - log.info(f"post compact: {layer}") + log.info("post compact: %s", layer) assert len(layers.historic_layers) == 1, "should have compacted to single layer" post_compact = downloaded_bytes_and_count(pageserver_http) diff --git a/test_runner/regress/test_ondemand_slru_download.py b/test_runner/regress/test_ondemand_slru_download.py index d6babe439339..2ef6fdccbe2d 100644 --- a/test_runner/regress/test_ondemand_slru_download.py +++ b/test_runner/regress/test_ondemand_slru_download.py @@ -73,7 +73,7 @@ def test_ondemand_download_pg_xact(neon_env_builder: NeonEnvBuilder, shard_count # Test that this can still on-demand download the old pg_xact segments cur.execute("select xmin, xmax, * from clogtest") tup = cur.fetchall() - log.info(f"tuples = {tup}") + log.info("tuples = %s", tup) @pytest.mark.parametrize("shard_count", [None, 4]) diff --git a/test_runner/regress/test_pageserver_generations.py b/test_runner/regress/test_pageserver_generations.py index 7ce38c5c3c82..4e9ebae0638d 100644 --- a/test_runner/regress/test_pageserver_generations.py +++ b/test_runner/regress/test_pageserver_generations.py @@ -110,7 +110,7 @@ def get_deletion_queue_depth(ps_http) -> int: executed = get_deletion_queue_executed(ps_http) dropped = get_deletion_queue_dropped(ps_http) depth = submitted - executed - dropped - log.info(f"get_deletion_queue_depth: {depth} ({submitted} - {executed} - {dropped})") + log.info("get_deletion_queue_depth: %s (%s - %s - %s)", depth, submitted, executed, dropped) assert depth >= 0 return int(depth) @@ -162,8 +162,8 @@ def parse_generation_suffix(key): if m is None: return None else: - log.info(f"match: {m}") - log.info(f"group: {m.group(1)}") + log.info("match: %s", m) + log.info("group: %s", m.group(1)) return int(m.group(1), 16) assert neon_env_builder.pageserver_remote_storage is not None @@ -196,7 +196,7 @@ def parse_generation_suffix(key): ] ) for key in post_upgrade_keys: - log.info(f"post-upgrade key: {key}") + log.info("post-upgrade key: %s", key) if parse_generation_suffix(key) is not None: suffixed_objects.append(key) else: @@ -363,7 +363,7 @@ def assert_header_written(): if keep_attachment == KeepAttachment.LOSE: before_restart_depth = get_deletion_queue_validated(ps_http) - log.info(f"Restarting pageserver with {before_restart_depth} deletions enqueued") + log.info("Restarting pageserver with %s deletions enqueued", before_restart_depth) main_pageserver.stop(immediate=True) if keep_attachment == KeepAttachment.LOSE: @@ -492,10 +492,10 @@ def evict_all_layers(env: NeonEnv, tenant_id: TenantId, timeline_id: TimelineId) for layer in layer_map.historic_layers: if layer.remote: log.info( - f"Skipping trying to evict remote layer {tenant_id}/{timeline_id} {layer.layer_file_name}" + "Skipping trying to evict remote layer %s/%s %s", tenant_id, timeline_id, layer.layer_file_name ) continue - log.info(f"Evicting layer {tenant_id}/{timeline_id} {layer.layer_file_name}") + log.info("Evicting layer %s/%s %s", tenant_id, timeline_id, layer.layer_file_name) client.evict_layer( tenant_id=tenant_id, timeline_id=timeline_id, layer_name=layer.layer_file_name ) @@ -651,11 +651,11 @@ def test_upgrade_generationless_local_file_paths( files_renamed = 0 for filename in os.listdir(timeline_dir): path = os.path.join(timeline_dir, filename) - log.info(f"Found file {path}") + log.info("Found file %s", path) if path.endswith("-v1-00000001"): new_path = path[:-12] os.rename(path, new_path) - log.info(f"Renamed {path} -> {new_path}") + log.info("Renamed %s -> %s", path, new_path) files_renamed += 1 assert files_renamed > 0 diff --git a/test_runner/regress/test_pageserver_getpage_throttle.py b/test_runner/regress/test_pageserver_getpage_throttle.py index 111285b40c14..48467d37cc2b 100644 --- a/test_runner/regress/test_pageserver_getpage_throttle.py +++ b/test_runner/regress/test_pageserver_getpage_throttle.py @@ -58,11 +58,11 @@ def run_pagebench_at_max_speed_and_get_total_requests_completed(duration_secs: i basepath = pg_bin.run_capture(cmd, with_command_header=False) results_path = Path(basepath + ".stdout") - log.info(f"Benchmark results at: {results_path}") + log.info("Benchmark results at: %s", results_path) with open(results_path, "r") as f: results = json.load(f) - log.info(f"Results:\n{json.dumps(results, sort_keys=True, indent=2)}") + log.info("Results:\n%s", f"{json.dumps(results, sort_keys=True, indent=2)}") return int(results["total"]["request_count"]) log.info("warmup / make sure metrics are present") diff --git a/test_runner/regress/test_pageserver_layer_rolling.py b/test_runner/regress/test_pageserver_layer_rolling.py index 66b6185aaae3..e544fbcd3f0a 100644 --- a/test_runner/regress/test_pageserver_layer_rolling.py +++ b/test_runner/regress/test_pageserver_layer_rolling.py @@ -91,7 +91,7 @@ def query(): def get_dirty_bytes(env): v = env.pageserver.http_client().get_metric_value("pageserver_timeline_ephemeral_bytes") or 0 - log.info(f"dirty_bytes: {v}") + log.info("dirty_bytes: %s", v) return v @@ -155,8 +155,8 @@ def test_pageserver_small_inmemory_layers( total_wal_ingested_after_restart = wait_for_wal_ingest_metric(ps_http_client) - log.info(f"WAL ingested before restart: {total_wal_ingested_before_restart}") - log.info(f"WAL ingested after restart: {total_wal_ingested_after_restart}") + log.info("WAL ingested before restart: %s", total_wal_ingested_before_restart) + log.info("WAL ingested after restart: %s", total_wal_ingested_after_restart) assert total_wal_ingested_after_restart == 0 @@ -271,7 +271,7 @@ def test_total_size_limit(neon_env_builder: NeonEnvBuilder): initdb_lsn = Lsn(http_client.timeline_detail(tenant, timeline)["initdb_lsn"]) total_bytes_ingested += last_flush_lsn - initdb_lsn - log.info(f"Ingested {total_bytes_ingested} bytes since initdb (vs max dirty {max_dirty_data})") + log.info("Ingested %s bytes since initdb (vs max dirty %s)", total_bytes_ingested, max_dirty_data) assert total_bytes_ingested > max_dirty_data # Expected end state: the total physical size of all the tenants is in excess of the max dirty @@ -292,7 +292,7 @@ def get_total_historic_layers(): total_ephemeral_layers += len(layer_map.in_memory_layers) log.info( - f"Total historic layer bytes: {total_historic_bytes} ({total_ephemeral_layers} ephemeral layers)" + "Total historic layer bytes: %s (%s ephemeral layers)", total_historic_bytes, total_ephemeral_layers ) return total_historic_bytes diff --git a/test_runner/regress/test_pageserver_metric_collection.py b/test_runner/regress/test_pageserver_metric_collection.py index cea35a6acb73..742b77539ab5 100644 --- a/test_runner/regress/test_pageserver_metric_collection.py +++ b/test_runner/regress/test_pageserver_metric_collection.py @@ -62,7 +62,7 @@ def metrics_handler(request: Request) -> Response: synthetic_size_calculation_interval="3s" """ - log.info(f"test_metric_collection endpoint is {metric_collection_endpoint}") + log.info("test_metric_collection endpoint is %s", metric_collection_endpoint) # mock http server that returns OK for the metrics httpserver.expect_request("/billing/api/v1/usage_events", method="POST").respond_with_handler( @@ -347,7 +347,7 @@ def __init__(self): def ingest(self, events, is_last): stringified = json.dumps(events, indent=2) - log.info(f"ingesting: {stringified}") + log.info("ingesting: %s", stringified) for event in events: id = TenantId(event["tenant_id"]) if id not in self.tenants: diff --git a/test_runner/regress/test_pageserver_reconnect.py b/test_runner/regress/test_pageserver_reconnect.py index 37ff923632d2..e61639144a5a 100644 --- a/test_runner/regress/test_pageserver_reconnect.py +++ b/test_runner/regress/test_pageserver_reconnect.py @@ -21,7 +21,7 @@ def test_pageserver_reconnect(neon_simple_env: NeonEnv, pg_bin: PgBin): scale = 10 def run_pgbench(connstr: str): - log.info(f"Start a pgbench workload on pg {connstr}") + log.info("Start a pgbench workload on pg %s", connstr) pg_bin.run_capture(["pgbench", "-i", f"-s{scale}", connstr]) pg_bin.run_capture(["pgbench", f"-T{int(n_reconnects*timeout)}", connstr]) diff --git a/test_runner/regress/test_pageserver_restart.py b/test_runner/regress/test_pageserver_restart.py index 4ce53df2140b..ab81950b93e4 100644 --- a/test_runner/regress/test_pageserver_restart.py +++ b/test_runner/regress/test_pageserver_restart.py @@ -50,7 +50,7 @@ def test_pageserver_restart(neon_env_builder: NeonEnvBuilder): ) row = cur.fetchone() assert row is not None - log.info(f"shared_buffers is {row[0]}, table size {row[1]}") + log.info("shared_buffers is %s, table size %s", row[0], row[1]) assert int(row[0]) < int(row[1]) # Stop the pageserver gracefully and restart it. @@ -93,7 +93,7 @@ def assert_complete(): "pageserver_startup_duration_seconds" ): labels = dict(sample.labels) - log.info(f"metric {labels['phase']}={sample.value}") + log.info("metric %s=%s", labels['phase'], sample.value) if labels["phase"] == "complete" and sample.value > 0: return @@ -122,7 +122,7 @@ def assert_complete(): prev_value = None for sample in metrics.query_all("pageserver_startup_duration_seconds"): phase = sample.labels["phase"] - log.info(f"metric {phase}={sample.value}") + log.info("metric %s=%s", phase, sample.value) assert phase in [e[0] for e in expectations], f"Unexpected phase {phase}" values[phase] = sample @@ -198,7 +198,7 @@ def test_pageserver_chaos( ) row = cur.fetchone() assert row is not None - log.info(f"shared_buffers is {row[0]}, table size {row[1]}") + log.info("shared_buffers is %s, table size %s", row[0], row[1]) assert int(row[0]) < int(row[1]) # We run "random" kills using a fixed seed, to improve reproducibility if a test diff --git a/test_runner/regress/test_pageserver_restarts_under_workload.py b/test_runner/regress/test_pageserver_restarts_under_workload.py index 65569f3bac9e..3cefe8150a47 100644 --- a/test_runner/regress/test_pageserver_restarts_under_workload.py +++ b/test_runner/regress/test_pageserver_restarts_under_workload.py @@ -18,7 +18,7 @@ def test_pageserver_restarts_under_worload(neon_simple_env: NeonEnv, pg_bin: PgB scale = 10 def run_pgbench(connstr: str): - log.info(f"Start a pgbench workload on pg {connstr}") + log.info("Start a pgbench workload on pg %s", connstr) pg_bin.run_capture(["pgbench", "-i", f"-s{scale}", connstr]) pg_bin.run_capture(["pgbench", f"-T{n_restarts}", connstr]) diff --git a/test_runner/regress/test_pageserver_secondary.py b/test_runner/regress/test_pageserver_secondary.py index 0416078ebc67..35f543a56489 100644 --- a/test_runner/regress/test_pageserver_secondary.py +++ b/test_runner/regress/test_pageserver_secondary.py @@ -54,7 +54,7 @@ def evict_random_layers( layer_name = parse_layer_file_name(layer.name) if rng.choice([True, False]): - log.info(f"Evicting layer {tenant_id}/{timeline_id} {layer_name.to_str()}") + log.info("Evicting layer %s/%s %s", tenant_id, timeline_id, layer_name.to_str()) client.evict_layer( tenant_id=tenant_id, timeline_id=timeline_id, layer_name=layer_name.to_str() ) @@ -82,7 +82,7 @@ def test_location_conf_churn(neon_env_builder: NeonEnvBuilder, make_httpserver, def ignore_notify(request: Request): # This test does all its own compute configuration (by passing explicit pageserver ID to Workload functions), # so we send controller notifications to /dev/null to prevent it fighting the test for control of the compute. - log.info(f"Ignoring storage controller compute notification: {request.json}") + log.info("Ignoring storage controller compute notification: %s", request.json) return Response(status=200) make_httpserver.expect_request("/notify-attach", method="PUT").respond_with_handler( @@ -157,14 +157,14 @@ def ignore_notify(request: Request): last_state_ps = last_state[pageserver.id] if mode == "_Evictions": if last_state_ps[0].startswith("Attached"): - log.info(f"Action: evictions on pageserver {pageserver.id}") + log.info("Action: evictions on pageserver %s", pageserver.id) evict_random_layers(rng, pageserver, tenant_id, timeline_id) else: log.info( - f"Action: skipping evictions on pageserver {pageserver.id}, is not attached" + "Action: skipping evictions on pageserver %s, is not attached", pageserver.id ) elif mode == "_Restart": - log.info(f"Action: restarting pageserver {pageserver.id}") + log.info("Action: restarting pageserver %s", pageserver.id) pageserver.stop() pageserver.start() if last_state_ps[0].startswith("Attached") and latest_attached == pageserver.id: @@ -197,7 +197,7 @@ def ignore_notify(request: Request): "tenant_conf": {}, } - log.info(f"Action: Configuring pageserver {pageserver.id} to {location_conf}") + log.info("Action: Configuring pageserver %s to %s", pageserver.id, location_conf) # Select a generation number if mode.startswith("Attached"): @@ -307,7 +307,7 @@ def test_live_migration(neon_env_builder: NeonEnvBuilder): pageserver_b.http_client().tenant_secondary_download(tenant_id) migrated_generation = env.storage_controller.attach_hook_issue(tenant_id, pageserver_b.id) - log.info(f"Acquired generation {migrated_generation} for destination pageserver") + log.info("Acquired generation %s for destination pageserver", migrated_generation) assert migrated_generation == initial_generation + 1 # Writes and reads still work in AttachedStale. @@ -340,7 +340,7 @@ def caught_up(): "last_record_lsn" ] log.info( - f"Waiting for LSN to catch up: origin {origin_lsn} vs destination {destination_lsn}" + "Waiting for LSN to catch up: origin %s vs destination %s", origin_lsn, destination_lsn ) assert destination_lsn >= origin_lsn @@ -415,7 +415,7 @@ def validate_heatmap(heatmap): # Download and inspect the heatmap that the pageserver uploaded heatmap_first = env.pageserver_remote_storage.heatmap_content(tenant_id) - log.info(f"Read back heatmap: {heatmap_first}") + log.info("Read back heatmap: %s", heatmap_first) validate_heatmap(heatmap_first) # Do some more I/O to generate more layers @@ -424,7 +424,7 @@ def validate_heatmap(heatmap): # Ensure that another heatmap upload includes the new layers heatmap_second = env.pageserver_remote_storage.heatmap_content(tenant_id) - log.info(f"Read back heatmap: {heatmap_second}") + log.info("Read back heatmap: %s", heatmap_second) assert heatmap_second != heatmap_first validate_heatmap(heatmap_second) @@ -470,7 +470,7 @@ def test_secondary_downloads(neon_env_builder: NeonEnvBuilder): }, ) readback_conf = ps_secondary.read_tenant_location_conf(tenant_id) - log.info(f"Read back conf: {readback_conf}") + log.info("Read back conf: %s", readback_conf) # Explicit upload/download cycle # ============================== @@ -510,7 +510,7 @@ def test_secondary_downloads(neon_env_builder: NeonEnvBuilder): timeline_path = ps_secondary.timeline_dir(tenant_id, timeline_id) for path, _dirs, files in os.walk(timeline_path): for f in files: - log.info(f"Secondary file: {os.path.join(path, f)}") + log.info("Secondary file: %s", os.path.join(path, f)) raise @@ -526,7 +526,7 @@ def test_secondary_downloads(neon_env_builder: NeonEnvBuilder): log.info("Evicting a layer...") layer_to_evict = ps_attached.list_layers(tenant_id, timeline_id)[0] some_other_layer = ps_attached.list_layers(tenant_id, timeline_id)[1] - log.info(f"Victim layer: {layer_to_evict.name}") + log.info("Victim layer: %s", layer_to_evict.name) ps_attached.http_client().evict_layer( tenant_id, timeline_id, layer_name=layer_to_evict.name ) @@ -549,7 +549,7 @@ def test_secondary_downloads(neon_env_builder: NeonEnvBuilder): except: # On assertion failures, log some details to help with debugging heatmap = env.pageserver_remote_storage.heatmap_content(tenant_id) - log.warn(f"heatmap contents: {json.dumps(heatmap,indent=2)}") + log.warn("heatmap contents: %s", f"{json.dumps(heatmap,indent=2)}") raise # Scrub the remote storage @@ -632,7 +632,7 @@ def await_log(pageserver, deadline, expression): try: wait_until(timeout, 1, lambda: pageserver.assert_log_contains(expression)) # type: ignore except: - log.error(f"Timed out waiting for '{expression}'") + log.error("Timed out waiting for '%s'", expression) raise t_start = time.time() @@ -653,7 +653,7 @@ def await_log(pageserver, deadline, expression): else: for timeline_id in timelines: log.info( - f"Waiting for downloads of timeline {timeline_id} on secondary pageserver {ps_secondary.id}" + "Waiting for downloads of timeline %s on secondary pageserver %s", timeline_id, ps_secondary.id ) await_log( ps_secondary, @@ -663,7 +663,7 @@ def await_log(pageserver, deadline, expression): for timeline_id in timelines: log.info( - f"Checking for secondary timeline downloads {timeline_id} on node {ps_secondary.id}" + "Checking for secondary timeline downloads %s on node %s", timeline_id, ps_secondary.id ) # One or more layers should be present for all timelines assert ps_secondary.list_layers(tenant_id, timeline_id) @@ -682,7 +682,7 @@ def await_log(pageserver, deadline, expression): expect_del_timeline = timelines[1] log.info( - f"Waiting for deletion of timeline {expect_del_timeline} on secondary pageserver {ps_secondary.id}" + "Waiting for deletion of timeline %s on secondary pageserver %s", expect_del_timeline, ps_secondary.id ) await_log( ps_secondary, @@ -695,7 +695,7 @@ def await_log(pageserver, deadline, expression): # This one was deleted log.info( - f"Checking for secondary timeline deletion {tenant_id}/{timeline_id} on node {ps_secondary.id}" + "Checking for secondary timeline deletion %s/%s on node %s", tenant_id, timeline_id, ps_secondary.id ) assert not ps_secondary.list_layers(tenant_id, expect_del_timeline) @@ -712,7 +712,7 @@ def await_log(pageserver, deadline, expression): download_rate = (total_heatmap_downloads / tenant_count) / (t_end - t_start) expect_download_rate = 1.0 / upload_period_secs - log.info(f"Download rate: {download_rate * 60}/min vs expected {expect_download_rate * 60}/min") + log.info("Download rate: %s/min vs expected %s/min", download_rate * 60, expect_download_rate * 60) assert download_rate < expect_download_rate * 2 diff --git a/test_runner/regress/test_pitr_gc.py b/test_runner/regress/test_pitr_gc.py index 7e676b55154f..c6884104414a 100644 --- a/test_runner/regress/test_pitr_gc.py +++ b/test_runner/regress/test_pitr_gc.py @@ -37,7 +37,7 @@ def test_pitr_gc(neon_env_builder: NeonEnvBuilder): assert res is not None lsn_a = res[0] xid_a = res[1] - log.info(f"LSN after 100 rows: {lsn_a} xid {xid_a}") + log.info("LSN after 100 rows: %s xid %s", lsn_a, xid_a) main_cur.execute("SELECT pg_current_wal_insert_lsn(), txid_current()") res = main_cur.fetchone() @@ -45,7 +45,7 @@ def test_pitr_gc(neon_env_builder: NeonEnvBuilder): debug_lsn = res[0] debug_xid = res[1] - log.info(f"LSN after 10000 rows: {debug_lsn} xid {debug_xid}") + log.info("LSN after 10000 rows: %s xid %s", debug_lsn, debug_xid) # run GC with env.pageserver.http_client() as pageserver_http: diff --git a/test_runner/regress/test_read_validation.py b/test_runner/regress/test_read_validation.py index 2437c8f806b4..b257c978e024 100644 --- a/test_runner/regress/test_read_validation.py +++ b/test_runner/regress/test_read_validation.py @@ -131,7 +131,7 @@ def test_read_validation(neon_simple_env: NeonEnv): c.execute("select * from page_header(get_raw_page('foo', 'main', 0));") raise AssertionError("query should have failed") except UndefinedTable as e: - log.info(f"Caught an expected failure: {e}") + log.info("Caught an expected failure: %s", e) def test_read_validation_neg(neon_simple_env: NeonEnv): @@ -161,7 +161,7 @@ def test_read_validation_neg(neon_simple_env: NeonEnv): ) raise AssertionError("query should have failed") except UndefinedTable as e: - log.info(f"Caught an expected failure: {e}") + log.info("Caught an expected failure: %s", e) c.execute("create table foo (c int) with (autovacuum_enabled = false)") c.execute("insert into foo values (1)") @@ -173,7 +173,7 @@ def test_read_validation_neg(neon_simple_env: NeonEnv): ) raise AssertionError("query should have failed") except IoError as e: - log.info(f"Caught an expected failure: {e}") + log.info("Caught an expected failure: %s", e) log.info("Pass NULL as an input") expected = (None, None, None) diff --git a/test_runner/regress/test_recovery.py b/test_runner/regress/test_recovery.py index e21f9bb6f625..88cdf655260f 100644 --- a/test_runner/regress/test_recovery.py +++ b/test_runner/regress/test_recovery.py @@ -52,7 +52,7 @@ def test_pageserver_recovery(neon_env_builder: NeonEnvBuilder): while True: cur.execute("update foo set x=x+1") except Exception as err: - log.info(f"Expected server crash {err}") + log.info("Expected server crash %s", err) log.info("Wait before server restart") env.pageserver.stop() diff --git a/test_runner/regress/test_remote_storage.py b/test_runner/regress/test_remote_storage.py index fac7fe9deef6..be089287dbb5 100644 --- a/test_runner/regress/test_remote_storage.py +++ b/test_runner/regress/test_remote_storage.py @@ -120,9 +120,9 @@ def test_remote_storage_backup_and_restore( pageserver_http.timeline_checkpoint(tenant_id, timeline_id) # wait until pageserver successfully uploaded a checkpoint to remote storage - log.info(f"waiting for checkpoint {checkpoint_number} upload") + log.info("waiting for checkpoint %s upload", checkpoint_number) wait_for_upload(client, tenant_id, timeline_id, current_lsn) - log.info(f"upload of checkpoint {checkpoint_number} is done") + log.info("upload of checkpoint %s is done", checkpoint_number) # Check that we had to retry the uploads env.pageserver.assert_log_contains( @@ -443,7 +443,7 @@ def fetch_calls_started(): def ensure_calls_started_grew(): for (file_kind, op_kind), observations in calls_started.items(): - log.info(f"ensure_calls_started_grew: {file_kind} {op_kind}: {observations}") + log.info("ensure_calls_started_grew: %s %s: %s", file_kind, op_kind, observations) assert all( x < y for x, y in zip(observations, observations[1:]) ), f"observations for {file_kind} {op_kind} did not grow monotonically: {observations}" @@ -863,7 +863,7 @@ def layer_deletes_completed(): def until_layer_deletes_completed(): deletes = layer_deletes_completed() - log.info(f"layer_deletes: {deletes}") + log.info("layer_deletes: %s", deletes) # ensure that initdb delta layer AND the previously stuck are now deleted assert deletes >= len(upload_stuck_layers) + 1 diff --git a/test_runner/regress/test_replica_start.py b/test_runner/regress/test_replica_start.py index 17d476a8a690..0d9f0b0322c9 100644 --- a/test_runner/regress/test_replica_start.py +++ b/test_runner/regress/test_replica_start.py @@ -523,7 +523,7 @@ def test_replica_start_with_prepared_xacts_with_subxacts(neon_simple_env: NeonEn # at standby startup. (We had a bug where it didn't at one point during development.) while True: xid = int(query_scalar(primary_cur, "SELECT txid_current()")) - log.info(f"xid now {xid}") + log.info("xid now %s", xid) # Consume 500 transactions at a time until we get close if xid < 65535 - 600: primary_cur.execute("select test_consume_xids(500);") diff --git a/test_runner/regress/test_s3_restore.py b/test_runner/regress/test_s3_restore.py index 9992647e56c7..9102be4c2a46 100644 --- a/test_runner/regress/test_s3_restore.py +++ b/test_runner/regress/test_s3_restore.py @@ -70,7 +70,7 @@ def test_tenant_s3_restore( last_flush_lsns.append(last_flush_lsn) ps_http.timeline_checkpoint(tenant_id, timeline_id) wait_for_upload(ps_http, tenant_id, timeline_id, last_flush_lsn) - log.info(f"{timeline} timeline {timeline_id} {last_flush_lsn=}") + log.info("%s timeline %s %s", timeline, timeline_id, f"{last_flush_lsn=}") parent = timeline # These sleeps are important because they fend off differences in clocks between us and S3 @@ -115,7 +115,7 @@ def test_tenant_s3_restore( env.pageserver.quiesce_tenants() for tline in ps_http.timeline_list(env.initial_tenant): - log.info(f"timeline detail: {tline}") + log.info("timeline detail: %s", tline) for i, timeline in enumerate(["first", "second"]): with env.endpoints.create_start(timeline, tenant_id=tenant_id) as endpoint: diff --git a/test_runner/regress/test_sharding.py b/test_runner/regress/test_sharding.py index d414f986e655..d2bd5f537476 100644 --- a/test_runner/regress/test_sharding.py +++ b/test_runner/regress/test_sharding.py @@ -68,7 +68,7 @@ def get_sizes(): sizes[node_id] = pageserver.http_client().tenant_status(shard["shard_id"])[ "current_physical_size" ] - log.info(f"sizes = {sizes}") + log.info("sizes = %s", sizes) return sizes # The imported initdb for timeline creation should @@ -290,7 +290,7 @@ def test_sharding_split_compaction(neon_env_builder: NeonEnvBuilder, failpoint: if failpoint is None: raise e else: - log.info(f"Compaction failed (failpoint={failpoint}): {e}") + log.info("Compaction failed (failpoint=%s): %s", failpoint, e) if failpoint in ( "compact-shard-ancestors-localonly", @@ -324,7 +324,7 @@ def test_sharding_split_compaction(neon_env_builder: NeonEnvBuilder, failpoint: measured_size += os.stat(abs_path).st_size log.info( - f"shard {shard} reported size {reported_size}, measured size {measured_size} ({len(layer_paths)} layers)" + "shard %s reported size %s, measured size %s (%s layers)", shard, reported_size, measured_size, len(layer_paths) ) if failpoint in ( @@ -409,7 +409,7 @@ def test_sharding_split_smoke( ] ) - log.info(f"Pageserver {pageserver.id} metrics: {metrics}") + log.info("Pageserver %s metrics: %s", pageserver.id, metrics) # Not everything received was committed assert ( @@ -525,7 +525,7 @@ def get_node_shard_counts(env: NeonEnv, tenant_ids): for tid in tenant_ids: for shard in env.storage_controller.tenant_describe(tid)["shards"]: log.info( - f"{shard['tenant_shard_id']}: attached={shard['node_attached']}, secondary={shard['node_secondary']} " + "%s: attached=%s, secondary=%s ", shard['tenant_shard_id'], shard['node_attached'], shard['node_secondary'] ) for node in shard["node_secondary"]: total[int(node)] += 1 @@ -558,7 +558,7 @@ def check_effective_tenant_config(): # More specific check: that we are fully balanced. This is deterministic because # the order in which we consider shards for optimization is deterministic, and the # order of preference of nodes is also deterministic (lower node IDs win). - log.info(f"total: {total}") + log.info("total: %s", total) assert total == { 1: 1, 2: 1, @@ -577,7 +577,7 @@ def check_effective_tenant_config(): 15: 1, 16: 1, } - log.info(f"attached: {attached}") + log.info("attached: %s", attached) assert attached == {1: 1, 2: 1, 3: 1, 5: 1, 6: 1, 7: 1, 9: 1, 11: 1} # Ensure post-split pageserver locations survive a restart (i.e. the child shards @@ -615,7 +615,7 @@ def test_sharding_split_stripe_size( notifications = [] def handler(request: Request): - log.info(f"Notify request: {request}") + log.info("Notify request: %s", request) notifications.append(request.json) return Response(status=200) @@ -651,7 +651,7 @@ def handler(request: Request): {"node_id": int(env.pageservers[0].id), "shard_number": 1}, ], } - log.info(f"Got notification: {notifications[1]}") + log.info("Got notification: %s", notifications[1]) assert notifications[1] == expect_after # Inspect the stripe size on the pageserver @@ -737,7 +737,7 @@ def test_sharding_ingest_layer_sizes( ) for layer in layers.historic_layers: log.info( - f"layer[{pageserver.id}]: {layer.layer_file_name} (size {layer.layer_file_size})" + "layer[%s]: %s (size %s)", pageserver.id, layer.layer_file_name, layer.layer_file_size ) initial_layers_per_shard[shard_id] = set(layers.historic_layers) @@ -787,13 +787,13 @@ def test_sharding_ingest_layer_sizes( lsn_size = 0 log.info( - f"{classification} layer[{pageserver.id}]: {layer.layer_file_name} (size {layer.layer_file_size}, LSN distance {lsn_size})" + "%s layer[%s]: %s (size %s, LSN distance %s)", classification, pageserver.id, layer.layer_file_name, layer.layer_file_size, lsn_size ) # Why an inexact check? # - Because we roll layers on checkpoint_distance * shard_count, we expect to obey the target # layer size on average, but it is still possible to write some tiny layers. - log.info(f"Totals: {small_layer_count} small layers, {ok_layer_count} ok layers") + log.info("Totals: %s small layers, %s ok layers", small_layer_count, ok_layer_count) if small_layer_count <= shard_count: # If each shard has <= 1 small layer pass @@ -862,7 +862,7 @@ def test_sharding_ingest_gaps( # Don't leave the endpoint running, we don't want it writing in the background workload.stop() - log.info(f"Waiting for shards' consistent LSNs to reach {expect_lsn}") + log.info("Waiting for shards' consistent LSNs to reach %s", expect_lsn) shards = tenant_get_shards(env, tenant_id, None) @@ -872,7 +872,7 @@ def assert_all_disk_consistent(): """ for tenant_shard_id, pageserver in shards: timeline_detail = pageserver.http_client().timeline_detail(tenant_shard_id, timeline_id) - log.info(f"{tenant_shard_id} (ps {pageserver.id}) detail: {timeline_detail}") + log.info("%s (ps %s) detail: %s", tenant_shard_id, pageserver.id, timeline_detail) assert Lsn(timeline_detail["disk_consistent_lsn"]) >= expect_lsn # We set a short checkpoint timeout: expect things to get frozen+flushed within that @@ -884,7 +884,7 @@ def assert_all_remote_consistent(): """ for tenant_shard_id, pageserver in shards: timeline_detail = pageserver.http_client().timeline_detail(tenant_shard_id, timeline_id) - log.info(f"{tenant_shard_id} (ps {pageserver.id}) detail: {timeline_detail}") + log.info("%s (ps %s) detail: %s", tenant_shard_id, pageserver.id, timeline_detail) assert Lsn(timeline_detail["remote_consistent_lsn"]) >= expect_lsn # We set a short checkpoint timeout: expect things to get frozen+flushed within that @@ -1182,7 +1182,7 @@ def assert_rolled_back(exclude_ps_id=None) -> None: locations = ps.http_client().tenant_list_locations()["tenant_shards"] for loc in locations: tenant_shard_id = TenantShardId.parse(loc[0]) - log.info(f"Shard {tenant_shard_id} seen on node {ps.id} in mode {loc[1]['mode']}") + log.info("Shard %s seen on node %s in mode %s", tenant_shard_id, ps.id, loc[1]['mode']) assert tenant_shard_id.shard_count == initial_shard_count if loc[1]["mode"] == "Secondary": secondary_count += 1 @@ -1208,7 +1208,7 @@ def assert_split_done(exclude_ps_id=None) -> None: locations = ps.http_client().tenant_list_locations()["tenant_shards"] for loc in locations: tenant_shard_id = TenantShardId.parse(loc[0]) - log.info(f"Shard {tenant_shard_id} seen on node {ps.id} in mode {loc[1]['mode']}") + log.info("Shard %s seen on node %s in mode %s", tenant_shard_id, ps.id, loc[1]['mode']) assert tenant_shard_id.shard_count == split_shard_count if loc[1]["mode"] == "Secondary": secondary_count += 1 @@ -1330,7 +1330,7 @@ def shards_info(): last_record_lsn = shard_info["last_record_lsn"] current_physical_size = shard_info["current_physical_size"] log.info( - f"Shard on pageserver {node_id}: lsn={last_record_lsn}, size={current_physical_size}" + "Shard on pageserver %s: lsn=%s, size=%s", node_id, last_record_lsn, current_physical_size ) return infos @@ -1360,7 +1360,7 @@ def shards_info(): "SHOW max_replication_apply_lag", ] ) - log.info(f"backpressure config: {res}") + log.info("backpressure config: %s", res) last_flush_lsn = None last_timestamp = None @@ -1381,7 +1381,7 @@ def update_write_lsn(): dbname="postgres", )[0] log.info( - f"received_lsn_lag = {res[0]}, received_lsn = {res[1]}, flush_lsn = {res[2]}, throttling_time = {res[3]}" + "received_lsn_lag = %s, received_lsn = %s, flush_lsn = %s, throttling_time = %s", res[0], res[1], res[2], res[3] ) lsn = Lsn(res[2]) @@ -1392,7 +1392,7 @@ def update_write_lsn(): delta_bytes = lsn - last_flush_lsn avg_speed = delta_bytes / delta / 1024 / 1024 log.info( - f"flush_lsn {lsn}, written {delta_bytes/1024}kb for {delta:.3f}s, avg_speed {avg_speed:.3f} MiB/s" + "flush_lsn %s, written %skb for %ss, avg_speed %s MiB/s", lsn, delta_bytes/1024, f"{delta:.3f}", f"{avg_speed:.3f}" ) last_flush_lsn = lsn @@ -1488,7 +1488,7 @@ def test_top_tenants(neon_env_builder: NeonEnvBuilder): ] tenants.append((tenant_id, timeline_id, logical_size)) - log.info(f"Created {tenant_id}/{timeline_id} with size {logical_size}") + log.info("Created %s/%s with size %s", tenant_id, timeline_id, logical_size) # Ask for 1 largest tenant top_1 = env.pageserver.http_client().top_tenants("max_logical_size", 1, 8, 0) diff --git a/test_runner/regress/test_sni_router.py b/test_runner/regress/test_sni_router.py index 4336e6551d05..b398bc864fde 100644 --- a/test_runner/regress/test_sni_router.py +++ b/test_runner/regress/test_sni_router.py @@ -68,7 +68,7 @@ def start(self) -> "PgSniRouter": self._popen = subprocess.Popen(args, stderr=router_log) self._wait_until_ready() - log.info(f"pg_sni_router started, log file: {router_log_path}") + log.info("pg_sni_router started, log file: %s", router_log_path) return self @backoff.on_exception(backoff.expo, OSError, max_time=10) diff --git a/test_runner/regress/test_storage_controller.py b/test_runner/regress/test_storage_controller.py index d37f7aae3dfd..535a711c7767 100644 --- a/test_runner/regress/test_storage_controller.py +++ b/test_runner/regress/test_storage_controller.py @@ -470,7 +470,7 @@ def test_storage_controller_compute_hook( def handler(request: Request): status = handle_params["status"] - log.info(f"Notify request[{status}]: {request}") + log.info("Notify request[%s]: %s", status, request) notifications.append(request.json) return Response(status=status) @@ -497,7 +497,7 @@ def node_evacuated(node_id: int) -> None: wait_until(10, 1, lambda: node_evacuated(env.pageservers[0].id)) # Additional notification from migration - log.info(f"notifications: {notifications}") + log.info("notifications: %s", notifications) expect = { "tenant_id": str(env.initial_tenant), "stripe_size": None, @@ -690,15 +690,15 @@ def test_storage_controller_s3_time_travel_recovery( f"tenants/{tenant_id}-{shard_id_for_list}/timelines/{timeline_id}/", ).get("Contents", []) assert len(objects) > 1 - log.info(f"Found {len(objects)} objects in remote storage") + log.info("Found %s objects in remote storage", len(objects)) should_delete = False for obj in objects: obj_key = obj["Key"] should_delete = not should_delete if not should_delete: - log.info(f"Keeping key on remote storage: {obj_key}") + log.info("Keeping key on remote storage: %s", obj_key) continue - log.info(f"Deleting key from remote storage: {obj_key}") + log.info("Deleting key from remote storage: %s", obj_key) remote_storage_delete_key(env.pageserver_remote_storage, obj_key) pass @@ -1032,7 +1032,7 @@ def create_tenant(tid: TenantId): # ... expecting that each tenant will be placed on a different node def tenants_placed(): node_to_tenants = build_node_to_tenants_map(env) - log.info(f"{node_to_tenants=}") + log.info("%s", f"{node_to_tenants=}") # Check that all the tenants have been attached assert sum((len(ts) for ts in node_to_tenants.values())) == len(tenant_ids) @@ -1056,7 +1056,7 @@ def tenants_placed(): # ... expecting the heartbeats to mark it offline def nodes_offline(): nodes = env.storage_controller.node_list() - log.info(f"{nodes=}") + log.info("%s", f"{nodes=}") for node in nodes: if node["id"] in offline_node_ids: assert node["availability"] == "Offline" @@ -1072,7 +1072,7 @@ def tenant_migrated(): return node_to_tenants = build_node_to_tenants_map(env) - log.info(f"{node_to_tenants=}") + log.info("%s", f"{node_to_tenants=}") observed_tenants = set() for node_id in online_node_ids: @@ -1097,7 +1097,7 @@ def nodes_online(): time.sleep(5) node_to_tenants = build_node_to_tenants_map(env) - log.info(f"Back online: {node_to_tenants=}") + log.info("Back online: %s", f"{node_to_tenants=}") # ... expecting the storage controller to reach a consistent state def storage_controller_consistent(): @@ -1138,7 +1138,7 @@ def test_storage_controller_re_attach(neon_env_builder: NeonEnvBuilder): # Heatbeater will notice it's offline, and consequently attachments move to the other pageserver def failed_over(): locations = survivor_ps.http_client().tenant_list_locations()["tenant_shards"] - log.info(f"locations: {locations}") + log.info("locations: %s", locations) assert len(locations) == 2 assert all(loc[1]["mode"] == "AttachedSingle" for loc in locations) @@ -1289,8 +1289,8 @@ def storcon_cli(args): timeout=10, ) if status_code: - log.warning(f"Command {args} failed") - log.warning(f"Output at: {output_path}") + log.warning("Command %s failed", args) + log.warning("Output at: %s", output_path) raise RuntimeError("CLI failure (check logs for stderr)") @@ -1549,7 +1549,7 @@ def assert_shard_counts_balanced(env: NeonEnv, shard_counts, total_shards): env.storage_controller.poll_node_status(ps.id, "PauseForRestart", max_attempts=6, backoff=5) shard_counts = get_node_shard_counts(env, tenant_ids) - log.info(f"Shard counts after draining node {ps.id}: {shard_counts}") + log.info("Shard counts after draining node %s: %s", ps.id, shard_counts) # Assert that we've drained the node assert shard_counts[ps.id] == 0 # Assert that those shards actually went somewhere @@ -1564,12 +1564,12 @@ def assert_shard_counts_balanced(env: NeonEnv, shard_counts, total_shards): env.storage_controller.poll_node_status(ps.id, "Active", max_attempts=6, backoff=5) shard_counts = get_node_shard_counts(env, tenant_ids) - log.info(f"Shard counts after filling node {ps.id}: {shard_counts}") + log.info("Shard counts after filling node %s: %s", ps.id, shard_counts) assert_shard_counts_balanced(env, shard_counts, total_shards) # Now check that shards are reasonably balanced shard_counts = get_node_shard_counts(env, tenant_ids) - log.info(f"Shard counts after rolling restart: {shard_counts}") + log.info("Shard counts after rolling restart: %s", shard_counts) assert_shard_counts_balanced(env, shard_counts, total_shards) diff --git a/test_runner/regress/test_tenant_conf.py b/test_runner/regress/test_tenant_conf.py index 80fb2b55b8b2..61192b874034 100644 --- a/test_runner/regress/test_tenant_conf.py +++ b/test_runner/regress/test_tenant_conf.py @@ -65,7 +65,7 @@ def set_some_nondefault_global_config(ps_cfg: Dict[str, Any]): # it should match global configuration with closing(env.pageserver.connect()) as psconn: with psconn.cursor(cursor_factory=psycopg2.extras.RealDictCursor) as pscur: - log.info(f"show {env.initial_tenant}") + log.info("show %s", env.initial_tenant) pscur.execute(f"show {env.initial_tenant}") res = pscur.fetchone() assert res is not None @@ -107,7 +107,7 @@ def set_some_nondefault_global_config(ps_cfg: Dict[str, Any]): with psconn.cursor(cursor_factory=psycopg2.extras.RealDictCursor) as pscur: pscur.execute(f"show {tenant}") res = pscur.fetchone() - log.info(f"res: {res}") + log.info("res: %s", res) assert res is not None assert all( i in res.items() @@ -170,7 +170,7 @@ def set_some_nondefault_global_config(ps_cfg: Dict[str, Any]): with psconn.cursor(cursor_factory=psycopg2.extras.RealDictCursor) as pscur: pscur.execute(f"show {tenant}") res = pscur.fetchone() - log.info(f"after config res: {res}") + log.info("after config res: %s", res) assert res is not None assert all( i in res.items() @@ -226,7 +226,7 @@ def set_some_nondefault_global_config(ps_cfg: Dict[str, Any]): with psconn.cursor(cursor_factory=psycopg2.extras.RealDictCursor) as pscur: pscur.execute(f"show {tenant}") res = pscur.fetchone() - log.info(f"after restart res: {res}") + log.info("after restart res: %s", res) assert res is not None assert all( i in res.items() @@ -287,7 +287,7 @@ def set_some_nondefault_global_config(ps_cfg: Dict[str, Any]): with psconn.cursor(cursor_factory=psycopg2.extras.RealDictCursor) as pscur: pscur.execute(f"show {tenant}") res = pscur.fetchone() - log.info(f"after restart res: {res}") + log.info("after restart res: %s", res) assert res is not None assert all( i in res.items() diff --git a/test_runner/regress/test_tenant_detach.py b/test_runner/regress/test_tenant_detach.py index b165588636c7..c88876d135ac 100644 --- a/test_runner/regress/test_tenant_detach.py +++ b/test_runner/regress/test_tenant_detach.py @@ -200,11 +200,11 @@ async def update_table(pg_conn: asyncpg.Connection): await pg_conn.fetchrow(f"UPDATE t SET counter = counter + 1 WHERE id = {id}") updates_finished += 1 if updates_finished % 1000 == 0: - log.info(f"update {updates_finished} / {updates_to_perform}") + log.info("update %s / %s", updates_finished, updates_to_perform) break except asyncpg.PostgresError as e: # Received error from Postgres. Log it, sleep a little, and continue - log.info(f"UPDATE error: {e}") + log.info("UPDATE error: %s", e) await asyncio.sleep(0.1) async def sleep_and_reattach(pageserver_http: PageserverHttpClient, tenant_id: TenantId): diff --git a/test_runner/regress/test_tenant_size.py b/test_runner/regress/test_tenant_size.py index 70e8fe67d595..9afe1898f1db 100644 --- a/test_runner/regress/test_tenant_size.py +++ b/test_runner/regress/test_tenant_size.py @@ -87,7 +87,7 @@ def test_branched_empty_timeline_size(neon_simple_env: NeonEnv, test_output_dir: wait_for_last_flush_lsn(env, endpoint, tenant_id, first_branch_timeline_id) size_after_branching = http_client.tenant_size(tenant_id) - log.info(f"size_after_branching: {size_after_branching}") + log.info("size_after_branching: %s", size_after_branching) assert size_after_branching > initial_size @@ -344,7 +344,7 @@ def get_current_consistent_size( current_lsn = after_lsn size_debug_file.write(size_debug) assert size > 0 - log.info(f"size: {size} at lsn {current_lsn}") + log.info("size: %s at lsn %s", size, current_lsn) return (current_lsn, size) with env.endpoints.create_start( @@ -458,7 +458,7 @@ def get_current_consistent_size( # developing these tests that locally the value is a bit more than what we # get in the ci. for phase, lsn, size in collected_responses: - log.info(f"collected: {phase}, {lsn}, {size}") + log.info("collected: %s, %s, %s", phase, lsn, size) env.pageserver.stop() env.pageserver.start() @@ -756,7 +756,7 @@ def insert_with_action( client = env.pageserver.http_client() with env.endpoints.create_start("main", tenant_id=tenant) as ep: initial_size = client.tenant_size(tenant) - log.info(f"initial size: {initial_size}") + log.info("initial size: %s", initial_size) with ep.cursor() as cur: cur.execute( @@ -766,12 +766,12 @@ def insert_with_action( if action == "lease": res = client.timeline_lsn_lease(tenant, timeline, last_flush_lsn) - log.info(f"result from lsn_lease api: {res}") + log.info("result from lsn_lease api: %s", res) elif action == "branch": ro_branch = env.neon_cli.create_branch( "ro_branch", tenant_id=tenant, ancestor_start_lsn=last_flush_lsn ) - log.info(f"{ro_branch=} created") + log.info("%s created", f"{ro_branch=}") else: raise AssertionError("Invalid action type, only `lease` and `branch`are accepted") @@ -792,7 +792,7 @@ def insert_with_action( flush_ep_to_pageserver(env, ep, tenant, timeline) size_after_action_and_insert = client.tenant_size(tenant) - log.info(f"{size_after_action_and_insert=}") + log.info("%s", f"{size_after_action_and_insert=}") size_debug_file = open(test_output_dir / f"size_debug_{action}.html", "w") size_debug = client.tenant_size_debug(tenant) diff --git a/test_runner/regress/test_tenant_tasks.py b/test_runner/regress/test_tenant_tasks.py index d08ad3cd2e5d..53940ea1009a 100644 --- a/test_runner/regress/test_tenant_tasks.py +++ b/test_runner/regress/test_tenant_tasks.py @@ -71,7 +71,7 @@ def assert_tasks_finish(): tasks_panicked = client.get_metric_value( "pageserver_tenant_task_events_total", {"event": "panic"} ) - log.info(f"started {tasks_started}, ended {tasks_ended}, panicked {tasks_panicked}") + log.info("started %s, ended %s, panicked %s", tasks_started, tasks_ended, tasks_panicked) assert tasks_started == tasks_ended assert tasks_panicked is None or int(tasks_panicked) == 0 diff --git a/test_runner/regress/test_tenants.py b/test_runner/regress/test_tenants.py index 04b3fdd80fa5..201277873267 100644 --- a/test_runner/regress/test_tenants.py +++ b/test_runner/regress/test_tenants.py @@ -160,37 +160,37 @@ def query_all_safekeepers(name, filter): # Test metrics per timeline for tt in ttids: - log.info(f"Checking metrics for {tt}") + log.info("Checking metrics for %s", tt) ps_lsn = Lsn(int(ps_metrics.query_one("pageserver_last_record_lsn", filter=tt).value)) sk_lsns = [ Lsn(int(sk.query_one("safekeeper_commit_lsn", filter=tt).value)) for sk in sk_metrics ] - log.info(f"ps_lsn: {ps_lsn}") - log.info(f"sk_lsns: {sk_lsns}") + log.info("ps_lsn: %s", ps_lsn) + log.info("sk_lsns: %s", sk_lsns) assert ps_lsn <= max(sk_lsns) assert ps_lsn > Lsn(0) # Test common metrics for metrics in all_metrics: - log.info(f"Checking common metrics for {metrics.name}") + log.info("Checking common metrics for %s", metrics.name) log.info( - f"process_cpu_seconds_total: {metrics.query_one('process_cpu_seconds_total').value}" + "process_cpu_seconds_total: %s", metrics.query_one('process_cpu_seconds_total').value ) - log.info(f"process_threads: {int(metrics.query_one('process_threads').value)}") + log.info("process_threads: %s", int(metrics.query_one('process_threads').value)) log.info( - f"process_resident_memory_bytes (MB): {metrics.query_one('process_resident_memory_bytes').value / 1024 / 1024}" + "process_resident_memory_bytes (MB): %s", metrics.query_one('process_resident_memory_bytes').value / 1024 / 1024 ) log.info( - f"process_virtual_memory_bytes (MB): {metrics.query_one('process_virtual_memory_bytes').value / 1024 / 1024}" + "process_virtual_memory_bytes (MB): %s", metrics.query_one('process_virtual_memory_bytes').value / 1024 / 1024 ) - log.info(f"process_open_fds: {int(metrics.query_one('process_open_fds').value)}") - log.info(f"process_max_fds: {int(metrics.query_one('process_max_fds').value)}") + log.info("process_open_fds: %s", int(metrics.query_one('process_open_fds').value)) + log.info("process_max_fds: %s", int(metrics.query_one('process_max_fds').value)) log.info( - f"process_start_time_seconds (UTC): {datetime.fromtimestamp(metrics.query_one('process_start_time_seconds').value)}" + "process_start_time_seconds (UTC): %s", datetime.fromtimestamp(metrics.query_one('process_start_time_seconds').value) ) for io_direction in ["read", "write"]: @@ -205,7 +205,7 @@ def query_all_safekeepers(name, filter): }, ) total_bytes = sum(int(metric.value) for metric in io_metrics) - log.info(f"Pageserver {io_direction} bytes from another AZ: {total_bytes}") + log.info("Pageserver %s bytes from another AZ: %s", io_direction, total_bytes) # We expect some bytes to be read/written, to make sure metrics are working assert total_bytes > 0 @@ -236,7 +236,7 @@ def query_all_safekeepers(name, filter): assert len(ps_samples) > 0, f"expected at least one sample for {metric}" for sample in ps_samples: labels = ",".join([f'{key}="{value}"' for key, value in sample.labels.items()]) - log.info(f"{sample.name}{{{labels}}} {sample.value}") + log.info("%s{%s} %s", sample.name, labels, sample.value) # Test that we gather tenant operations metrics storage_operation_metrics = [ @@ -400,10 +400,10 @@ def create_bg(delay_ms): ) except PageserverApiException as e: if e.status_code == 409: - log.info(f"delay_ms={delay_ms} 409") + log.info("delay_ms=%s 409", delay_ms) pass elif e.status_code == 429: - log.info(f"delay_ms={delay_ms} 429") + log.info("delay_ms=%s 429", delay_ms) pass elif e.status_code == 400: if "is less than existing" in e.message: @@ -470,7 +470,7 @@ def only_int(samples: List[Sample]) -> int: directory_entries_count = only_int(directory_entries_count_metric) - log.info(f"pageserver_directory_entries_count metric value: {directory_entries_count}") + log.info("pageserver_directory_entries_count metric value: %s", directory_entries_count) assert directory_entries_count > COUNT_AT_LEAST_EXPECTED @@ -478,5 +478,5 @@ def only_int(samples: List[Sample]) -> int: counts = timeline_detail["directory_entries_counts"] assert counts - log.info(f"directory counts: {counts}") + log.info("directory counts: %s", counts) assert counts[2] > COUNT_AT_LEAST_EXPECTED diff --git a/test_runner/regress/test_tenants_with_remote_storage.py b/test_runner/regress/test_tenants_with_remote_storage.py index 168876b71129..3d8baadd5136 100644 --- a/test_runner/regress/test_tenants_with_remote_storage.py +++ b/test_runner/regress/test_tenants_with_remote_storage.py @@ -142,10 +142,10 @@ def test_tenants_attached_after_download(neon_env_builder: NeonEnvBuilder): # run checkpoint manually to be sure that data landed in remote storage pageserver_http.timeline_checkpoint(tenant_id, timeline_id) - log.info(f"waiting for checkpoint {checkpoint_number} upload") + log.info("waiting for checkpoint %s upload", checkpoint_number) # wait until pageserver successfully uploaded a checkpoint to remote storage wait_for_upload(client, tenant_id, timeline_id, current_lsn) - log.info(f"upload of checkpoint {checkpoint_number} is done") + log.info("upload of checkpoint %s is done", checkpoint_number) # Check that we had to retry the uploads env.pageserver.assert_log_contains( diff --git a/test_runner/regress/test_timeline_delete.py b/test_runner/regress/test_timeline_delete.py index da37f469b329..7f9ec308f454 100644 --- a/test_runner/regress/test_timeline_delete.py +++ b/test_runner/regress/test_timeline_delete.py @@ -243,7 +243,7 @@ def test_delete_timeline_exercise_crash_safety_failpoints( ) reason = timeline_info["state"]["Broken"]["reason"] - log.info(f"timeline broken: {reason}") + log.info("timeline broken: %s", reason) # failpoint may not be the only error in the stack assert reason.endswith(f"failpoint: {failpoint}"), reason @@ -831,7 +831,7 @@ def test_timeline_delete_resumed_on_attach( ) reason = timeline_info["state"]["Broken"]["reason"] - log.info(f"timeline broken: {reason}") + log.info("timeline broken: %s", reason) # failpoint may not be the only error in the stack assert reason.endswith(f"failpoint: {failpoint}"), reason diff --git a/test_runner/regress/test_timeline_size.py b/test_runner/regress/test_timeline_size.py index f47356839c26..a869a337d22e 100644 --- a/test_runner/regress/test_timeline_size.py +++ b/test_runner/regress/test_timeline_size.py @@ -139,7 +139,7 @@ def wait_for_pageserver_catchup(endpoint_main: Endpoint, polling_interval=1, tim """, dbname="postgres", )[0] - log.info(f"pg_cluster_size = {res[0]}, received_lsn_lag = {res[1]}") + log.info("pg_cluster_size = %s, received_lsn_lag = %s", res[0], res[1]) received_lsn_lag = res[1] time.sleep(polling_interval) @@ -179,7 +179,7 @@ def test_timeline_size_quota_on_startup(neon_env_builder: NeonEnvBuilder): raise AssertionError() except psycopg2.errors.DiskFull as err: - log.info(f"Query expectedly failed with: {err}") + log.info("Query expectedly failed with: %s", err) # Restart endpoint that reached the limit to ensure that it doesn't fail on startup # i.e. the size limit is not enforced during startup. @@ -206,7 +206,7 @@ def test_timeline_size_quota_on_startup(neon_env_builder: NeonEnvBuilder): raise AssertionError() except psycopg2.errors.DiskFull as err: - log.info(f"Query expectedly failed with: {err}") + log.info("Query expectedly failed with: %s", err) def test_timeline_size_quota(neon_env_builder: NeonEnvBuilder): @@ -257,7 +257,7 @@ def test_timeline_size_quota(neon_env_builder: NeonEnvBuilder): raise AssertionError() except psycopg2.errors.DiskFull as err: - log.info(f"Query expectedly failed with: {err}") + log.info("Query expectedly failed with: %s", err) # drop table to free space cur.execute("DROP TABLE foo") @@ -278,7 +278,7 @@ def test_timeline_size_quota(neon_env_builder: NeonEnvBuilder): cur.execute("SELECT * from pg_size_pretty(neon.pg_cluster_size())") pg_cluster_size = cur.fetchone() - log.info(f"pg_cluster_size = {pg_cluster_size}") + log.info("pg_cluster_size = %s", pg_cluster_size) new_res = client.timeline_detail( env.initial_tenant, new_timeline_id, include_non_incremental_logical_size=True @@ -330,7 +330,7 @@ def assert_size_calculation_not_done(): assert_size_calculation_not_done() log.info( - f"delete the timeline using {deletion_method}, this should cancel size computation tasks and wait for them to finish" + "delete the timeline using %s, this should cancel size computation tasks and wait for them to finish", deletion_method ) if deletion_method == "tenant_detach": @@ -730,11 +730,11 @@ def test_ondemand_activation(neon_env_builder: NeonEnvBuilder): def get_tenant_states(): states = {} - log.info(f"Tenant ids: {tenant_ids}") + log.info("Tenant ids: %s", tenant_ids) for tenant_id in tenant_ids: tenant = pageserver_http.tenant_status(tenant_id=tenant_id) states[tenant_id] = tenant["state"]["slug"] - log.info(f"Tenant states: {states}") + log.info("Tenant states: %s", states) return states def at_least_one_active(): @@ -923,7 +923,7 @@ def test_timeline_logical_size_task_priority(neon_env_builder: NeonEnvBuilder): wait_for_last_flush_lsn(env, endpoint, tenant_id, timeline_id) # restart with failpoint inside initial size calculation task - log.info(f"Detaching tenant {tenant_id} and stopping pageserver...") + log.info("Detaching tenant %s and stopping pageserver...", tenant_id) endpoint.stop() env.pageserver.tenant_detach(tenant_id) @@ -934,7 +934,7 @@ def test_timeline_logical_size_task_priority(neon_env_builder: NeonEnvBuilder): } ) - log.info(f"Re-attaching tenant {tenant_id}...") + log.info("Re-attaching tenant %s...", tenant_id) env.pageserver.tenant_attach(tenant_id) # kick off initial size calculation task (the response we get here is the estimated size) @@ -997,7 +997,7 @@ def get_tenant_states() -> dict[str, list[TenantId]]: def one_is_active(): states = get_tenant_states() - log.info(f"{states}") + log.info("%s", states) assert len(states["Active"]) == 1 wait_until(10, 1, one_is_active) diff --git a/test_runner/regress/test_vm_bits.py b/test_runner/regress/test_vm_bits.py index 225b952e7300..cc653ca2599d 100644 --- a/test_runner/regress/test_vm_bits.py +++ b/test_runner/regress/test_vm_bits.py @@ -153,7 +153,7 @@ def test_vm_bit_clear_on_heap_lock_whitebox(neon_env_builder: NeonEnvBuilder): cur.execute("COMMIT") cur.execute("VACUUM (FREEZE, DISABLE_PAGE_SKIPPING true, VERBOSE) vmtest_lock") for notice in pg_conn.notices: - log.info(f"{notice}") + log.info("%s", notice) # This test has been flaky in the past, because background activity like # auto-analyze and compute_ctl's activity monitor queries have prevented the @@ -266,7 +266,7 @@ def test_vm_bit_clear_on_heap_lock_blackbox(neon_env_builder: NeonEnvBuilder): for _ in range(1000): cur.execute("select min(datfrozenxid::text::int) from pg_database") datfrozenxid = int(cur.fetchall()[0][0]) - log.info(f"datfrozenxid {datfrozenxid} locking_xid: {locking_xid}") + log.info("datfrozenxid %s locking_xid: %s", datfrozenxid, locking_xid) if datfrozenxid > locking_xid + 3000000: break time.sleep(0.5) @@ -289,5 +289,5 @@ def test_vm_bit_clear_on_heap_lock_blackbox(neon_env_builder: NeonEnvBuilder): # ERROR: could not access status of transaction 1027 cur.execute("select xmin, xmax, * from vmtest_lock where id = 40000 for update") tup = cur.fetchall() - log.info(f"tuple = {tup}") + log.info("tuple = %s", tup) cur.execute("commit transaction") diff --git a/test_runner/regress/test_wal_acceptor.py b/test_runner/regress/test_wal_acceptor.py index 77a9a29e72ac..e0459ba6a904 100644 --- a/test_runner/regress/test_wal_acceptor.py +++ b/test_runner/regress/test_wal_acceptor.py @@ -61,7 +61,7 @@ def wait_lsn_force_checkpoint( ): pageserver_conn_options = pageserver_conn_options or {} lsn = Lsn(endpoint.safe_psql("SELECT pg_current_wal_flush_lsn()")[0][0]) - log.info(f"pg_current_wal_flush_lsn is {lsn}, waiting for it on pageserver") + log.info("pg_current_wal_flush_lsn is %s, waiting for it on pageserver", lsn) auth_token = None if "password" in pageserver_conn_options: @@ -167,7 +167,7 @@ def collect_metrics(message: str) -> List[TimelineMetrics]: > neon_env_builder.num_safekeepers ), f"timeline_id={timeline_id}, timeline_detail={timeline_detail}, sk_metrics={sk_metrics}" timeline_metrics.append(m) - log.info(f"{message}: {timeline_metrics}") + log.info("%s: %s", message, timeline_metrics) return timeline_metrics # TODO: https://github.com/neondatabase/neon/issues/809 @@ -286,13 +286,13 @@ def test_broker(neon_env_builder: NeonEnvBuilder): # wait until remote_consistent_lsn gets advanced on all safekeepers clients = [sk.http_client() for sk in env.safekeepers] stat_before = [cli.timeline_status(tenant_id, timeline_id) for cli in clients] - log.info(f"statuses before insert: {stat_before}") + log.info("statuses before insert: %s", stat_before) endpoint.safe_psql("INSERT INTO t SELECT generate_series(1,100), 'payload'") # wait for remote_consistent_lsn to reach flush_lsn, forcing it with checkpoint new_rcl = last_flush_lsn_upload(env, endpoint, tenant_id, timeline_id) - log.info(f"new_rcl: {new_rcl}") + log.info("new_rcl: %s", new_rcl) endpoint.stop() # and wait till remote_consistent_lsn propagates to all safekeepers @@ -324,7 +324,7 @@ def test_broker(neon_env_builder: NeonEnvBuilder): sk.stop() sk.start() stat_after_restart = [cli.timeline_status(tenant_id, timeline_id) for cli in clients] - log.info(f"statuses after {stat_after_restart}") + log.info("statuses after %s", stat_after_restart) assert all([s.remote_consistent_lsn >= new_rcl for s in stat_after_restart]) @@ -404,7 +404,7 @@ def test_wal_removal(neon_env_builder: NeonEnvBuilder, auth_enabled: bool): lambda first_segments=first_segments: all(not os.path.exists(p) for p in first_segments), "first segment get removed", wait_f=lambda http_cli=http_cli, tenant_id=tenant_id, timeline_id=timeline_id: log.info( - f"waiting for segments removal, sk info: {http_cli.timeline_status(tenant_id=tenant_id, timeline_id=timeline_id)}" + "waiting for segments removal, sk info: %s", f"{http_cli.timeline_status(tenant_id=tenant_id, timeline_id=timeline_id)}" ), ) @@ -418,7 +418,7 @@ def wait(f, desc, timeout=30, wait_f=None): if f(): break except Exception as e: - log.info(f"got exception while waiting for {desc}: {e}") + log.info("got exception while waiting for %s: %s", desc, e) pass elapsed = time.time() - started_at if elapsed > timeout: @@ -433,14 +433,14 @@ def is_segment_offloaded( ): http_cli = sk.http_client() tli_status = http_cli.timeline_status(tenant_id, timeline_id) - log.info(f"sk status is {tli_status}") + log.info("sk status is %s", tli_status) return tli_status.backup_lsn >= seg_end def is_flush_lsn_caught_up(sk: Safekeeper, tenant_id: TenantId, timeline_id: TimelineId, lsn: Lsn): http_cli = sk.http_client() tli_status = http_cli.timeline_status(tenant_id, timeline_id) - log.info(f"sk status is {tli_status}") + log.info("sk status is %s", tli_status) return tli_status.flush_lsn >= lsn @@ -449,7 +449,7 @@ def is_wal_trimmed(sk: Safekeeper, tenant_id: TenantId, timeline_id: TimelineId, tli_status = http_cli.timeline_status(tenant_id, timeline_id) sk_wal_size = get_dir_size(sk.timeline_dir(tenant_id, timeline_id)) sk_wal_size_mb = sk_wal_size / 1024 / 1024 - log.info(f"Safekeeper id={sk.id} wal_size={sk_wal_size_mb:.2f}MB status={tli_status}") + log.info("Safekeeper id=%s wal_size=%sMB status=%s", sk.id, f"{sk_wal_size_mb:.2f}", tli_status) return sk_wal_size_mb <= target_size_mb @@ -582,7 +582,7 @@ def test_s3_wal_replay(neon_env_builder: NeonEnvBuilder): pageserver_lsn = Lsn(ps_http.timeline_detail(tenant_id, timeline_id)["last_record_lsn"]) lag = last_lsn - pageserver_lsn log.info( - f"Pageserver last_record_lsn={pageserver_lsn}; flush_lsn={last_lsn}; lag before replay is {lag / 1024}kb" + "Pageserver last_record_lsn=%s; flush_lsn=%s; lag before replay is %skb", pageserver_lsn, last_lsn, lag / 1024 ) endpoint.stop() @@ -640,7 +640,7 @@ def test_s3_wal_replay(neon_env_builder: NeonEnvBuilder): tenant_status = ps_http.tenant_status(tenant_id) if tenant_status["state"]["slug"] == "Loading": - log.debug(f"Tenant {tenant_id} is still loading, retrying") + log.debug("Tenant %s is still loading, retrying", tenant_id) else: pageserver_lsn = Lsn( env.pageserver.http_client().timeline_detail(tenant_id, timeline_id)[ @@ -651,14 +651,14 @@ def test_s3_wal_replay(neon_env_builder: NeonEnvBuilder): if time.time() > last_debug_print + 10 or lag <= 0: last_debug_print = time.time() - log.info(f"Pageserver last_record_lsn={pageserver_lsn}; lag is {lag / 1024}kb") + log.info("Pageserver last_record_lsn=%s; lag is %skb", pageserver_lsn, lag / 1024) if lag <= 0: break time.sleep(1) - log.info(f"WAL redo took {elapsed} s") + log.info("WAL redo took %s s", elapsed) # verify data endpoint.create_start("test_s3_wal_replay") @@ -726,7 +726,7 @@ def sync_safekeepers(self) -> Lsn: basepath = self.pg_bin.run_capture(command, env, with_command_header=False) - log.info(f"postgres --sync-safekeepers output: {basepath}") + log.info("postgres --sync-safekeepers output: %s", basepath) stdout_filename = basepath + ".stdout" @@ -799,11 +799,11 @@ def test_sync_safekeepers( ) lsn = Lsn(res["inserted_wal"]["end_lsn"]) lsn_after_append.append(lsn) - log.info(f"safekeeper[{i}] lsn after append: {lsn}") + log.info("safekeeper[%s] lsn after append: %s", i, lsn) # run sync safekeepers lsn_after_sync = pg.sync_safekeepers() - log.info(f"lsn after sync = {lsn_after_sync}") + log.info("lsn after sync = %s", lsn_after_sync) assert all(lsn_after_sync == lsn for lsn in lsn_after_append) @@ -854,7 +854,7 @@ def test_timeline_status(neon_env_builder: NeonEnvBuilder, auth_enabled: bool): # fetch debug_dump endpoint debug_dump_0 = wa_http_cli_debug.debug_dump({"dump_all": "true"}) - log.info(f"debug_dump before reboot {debug_dump_0}") + log.info("debug_dump before reboot %s", debug_dump_0) assert debug_dump_0["timelines_count"] == 1 assert debug_dump_0["timelines"][0]["timeline_id"] == str(timeline_id) @@ -873,7 +873,7 @@ def test_timeline_status(neon_env_builder: NeonEnvBuilder, auth_enabled: bool): # fetch debug_dump after reboot debug_dump_1 = wa_http_cli_debug.debug_dump({"dump_all": "true"}) - log.info(f"debug_dump after reboot {debug_dump_1}") + log.info("debug_dump after reboot %s", debug_dump_1) assert debug_dump_1["timelines_count"] == 1 assert debug_dump_1["timelines"][0]["timeline_id"] == str(timeline_id) @@ -1030,7 +1030,7 @@ def __enter__(self): self.ts_before = time.time() def __exit__(self, *exc): - log.info(f"{self.desc} finished in {time.time() - self.ts_before}s") + log.info("%s finished in %ss", self.desc, time.time() - self.ts_before) # Context manager which logs WAL position change on exit. @@ -1042,12 +1042,12 @@ def __init__(self, ep, desc_before): def __enter__(self): self.ts_before = time.time() self.lsn_before = Lsn(self.ep.safe_psql_scalar("select pg_current_wal_lsn()")) - log.info(f"{self.desc_before}, lsn_before={self.lsn_before}") + log.info("%s, lsn_before=%s", self.desc_before, self.lsn_before) def __exit__(self, *exc): lsn_after = Lsn(self.ep.safe_psql_scalar("select pg_current_wal_lsn()")) log.info( - f"inserted {((lsn_after - self.lsn_before) / 1024 / 1024):.3f} MB of WAL in {(time.time() - self.ts_before):.3f}s" + "inserted %s MB of WAL in %ss", f"{((lsn_after - self.lsn_before) / 1024 / 1024):.3f}", f"{(time.time() - self.ts_before):.3f}" ) @@ -1094,7 +1094,7 @@ def is_flush_lsn_aligned(sk_http_clis, tenant_id, timeline_id): sk_http_cli.timeline_status(tenant_id, timeline_id).flush_lsn for sk_http_cli in sk_http_clis ] - log.info(f"waiting for flush_lsn alignment, flush_lsns={flush_lsns}") + log.info("waiting for flush_lsn alignment, flush_lsns=%s", flush_lsns) return all([flush_lsns[0] == flsn for flsn in flush_lsns]) @@ -1119,7 +1119,7 @@ def cmp_sk_wal(sks: List[Safekeeper], tenant_id: TenantId, timeline_id: Timeline assert ( segs[0] == cmp_segs ), f"lists of segments on sks {sks[0].id} and {sk.id} are not identic: {segs[0]} and {cmp_segs}" - log.info(f"comparing segs {segs[0]}") + log.info("comparing segs %s", segs[0]) sk0 = sks[0] for sk in sks[1:]: @@ -1130,7 +1130,7 @@ def cmp_sk_wal(sks: List[Safekeeper], tenant_id: TenantId, timeline_id: Timeline shallow=False, ) log.info( - f"filecmp result mismatch and not regular files:\n\t mismatch={mismatch}\n\t not_regular={not_regular}" + "filecmp result mismatch and not regular files:\n\t mismatch=%s\n\t not_regular=%s", mismatch, not_regular ) for f in mismatch: @@ -1314,7 +1314,7 @@ def test_peer_recovery(neon_env_builder: NeonEnvBuilder): sk1_tli_status = sk1_http_cli.timeline_status(tenant_id, timeline_id) sk2_tli_status = sk2_http_cli.timeline_status(tenant_id, timeline_id) log.info( - f"flush_lsns after insertion: sk1={sk1_tli_status.flush_lsn}, sk2={sk2_tli_status.flush_lsn}" + "flush_lsns after insertion: sk1=%s, sk2=%s", sk1_tli_status.flush_lsn, sk2_tli_status.flush_lsn ) assert sk2_tli_status.flush_lsn - sk1_tli_status.flush_lsn >= 16 * 1024 * 1024 @@ -1323,7 +1323,7 @@ def test_peer_recovery(neon_env_builder: NeonEnvBuilder): sk1_tli_status = sk1_http_cli.timeline_status(tenant_id, timeline_id) sk2_tli_status = sk2_http_cli.timeline_status(tenant_id, timeline_id) log.info( - f"flush_lsns after waiting: sk1={sk1_tli_status.flush_lsn}, sk2={sk2_tli_status.flush_lsn}" + "flush_lsns after waiting: sk1=%s, sk2=%s", sk1_tli_status.flush_lsn, sk2_tli_status.flush_lsn ) assert sk2_tli_status.flush_lsn - sk1_tli_status.flush_lsn >= 16 * 1024 * 1024 @@ -1366,7 +1366,7 @@ def test_wp_graceful_shutdown(neon_env_builder: NeonEnvBuilder, pg_bin: PgBin): # tests. Persisting it without risking too many cf flushes needs a wp -> sk # protocol change. (though in reality shutdown sync-safekeepers does flush # of cf, so most of the time persisted value wouldn't lag) - log.info(f"sk commit_lsn {commit_lsn}") + log.info("sk commit_lsn %s", commit_lsn) # note that ckpt_lsn is the *beginning* of checkpoint record, so commit_lsn # must be actually higher assert commit_lsn > ckpt_lsn, "safekeeper must have checkpoint record" @@ -1438,7 +1438,7 @@ def start_safekeeper(self, i): "--broker-endpoint", self.broker.client_url(), ] - log.info(f'Running command "{" ".join(cmd)}"') + log.info('Running command "%s"', " ".join(cmd)) safekeeper_client = SafekeeperHttpClient( port=port.http, @@ -1479,7 +1479,7 @@ def kill_safekeeper(self, sk_dir): pid_file = os.path.join(sk_dir, "safekeeper.pid") with open(pid_file, "r") as f: pid = int(f.read()) - log.info(f"Killing safekeeper with pid {pid}") + log.info("Killing safekeeper with pid %s", pid) os.kill(pid, signal.SIGKILL) def __enter__(self): @@ -1541,9 +1541,9 @@ def show_statuses(safekeepers: List[Safekeeper], tenant_id: TenantId, timeline_i http_cli = sk.http_client() try: status = http_cli.timeline_status(tenant_id, timeline_id) - log.info(f"Safekeeper {sk.id} status: {status}") + log.info("Safekeeper %s status: %s", sk.id, status) except Exception as e: - log.info(f"Safekeeper {sk.id} status error: {e}") + log.info("Safekeeper %s status error: %s", sk.id, e) neon_env_builder.num_safekeepers = 4 env = neon_env_builder.init_start() @@ -1751,9 +1751,9 @@ def show_statuses(safekeepers: List[Safekeeper], tenant_id: TenantId, timeline_i http_cli = sk.http_client(auth_token=env.auth_keys.generate_tenant_token(tenant_id)) try: status = http_cli.timeline_status(tenant_id, timeline_id) - log.info(f"Safekeeper {sk.id} status: {status}") + log.info("Safekeeper %s status: %s", sk.id, status) except Exception as e: - log.info(f"Safekeeper {sk.id} status error: {e}") + log.info("Safekeeper %s status error: %s", sk.id, e) neon_env_builder.num_safekeepers = 4 env = neon_env_builder.init_start() @@ -1784,7 +1784,7 @@ def show_statuses(safekeepers: List[Safekeeper], tenant_id: TenantId, timeline_i show_statuses(env.safekeepers, tenant_id, timeline_id) action = "reconfiguing" if live_sk_change else "restarting" - log.info(f"{action} compute with new config to verify that it works") + log.info("%s compute with new config to verify that it works", action) new_sks = [1, 3, 4] if not live_sk_change: endpoint.stop_and_destroy().create("main") @@ -1835,7 +1835,7 @@ def test_pull_timeline_gc(neon_env_builder: NeonEnvBuilder): endpoint.safe_psql("insert into t select generate_series(1, 1000), 'pear'") src_flush_lsn = src_sk.get_flush_lsn(tenant_id, timeline_id) - log.info(f"flush_lsn on src before pull_timeline: {src_flush_lsn}") + log.info("flush_lsn on src before pull_timeline: %s", src_flush_lsn) src_http = src_sk.http_client() # run pull_timeline which will halt before downloading files @@ -1859,7 +1859,7 @@ def test_pull_timeline_gc(neon_env_builder: NeonEnvBuilder): # Checkpoint timeline beyond lsn. src_sk.checkpoint_up_to(tenant_id, timeline_id, lsn, wait_wal_removal=False) first_segment_p = src_sk.timeline_dir(tenant_id, timeline_id) / "000000010000000000000001" - log.info(f"first segment exist={os.path.exists(first_segment_p)}") + log.info("first segment exist=%s", os.path.exists(first_segment_p)) src_http.configure_failpoints(("sk-snapshot-after-list-pausable", "off")) pt_handle.join() @@ -1869,7 +1869,7 @@ def test_pull_timeline_gc(neon_env_builder: NeonEnvBuilder): timeline_start_lsn = src_sk.get_timeline_start_lsn(tenant_id, timeline_id) dst_flush_lsn = dst_sk.get_flush_lsn(tenant_id, timeline_id) - log.info(f"flush_lsn on dst after pull_timeline: {dst_flush_lsn}") + log.info("flush_lsn on dst after pull_timeline: %s", dst_flush_lsn) assert dst_flush_lsn >= src_flush_lsn digests = [ sk.http_client().timeline_digest(tenant_id, timeline_id, timeline_start_lsn, dst_flush_lsn) @@ -1966,11 +1966,11 @@ def collect_stats() -> Dict[str, float]: for sk in sk_metrics: queries_received = sk.query_all("safekeeper_pg_queries_received_total") - log.info(f"{sk.name} queries received: {queries_received}") + log.info("%s queries received: %s", sk.name, queries_received) for sample in queries_received: total[sample.labels["query"]] = total.get(sample.labels["query"], 0) + sample.value - log.info(f"Total queries received: {total}") + log.info("Total queries received: %s", total) # in the perfect world, we should see only one START_REPLICATION query, # here we check for 5 to prevent flakiness @@ -2029,13 +2029,13 @@ def remember_lsn(): # remember LSN right after timeline creation lsn = remember_lsn() - log.info(f"LSN after timeline creation: {lsn}") + log.info("LSN after timeline creation: %s", lsn) endpoint.safe_psql("create table t(key int, value text)") timeline_status = env.safekeepers[0].http_client().timeline_status(tenant_id, timeline_id) timeline_start_lsn = timeline_status.timeline_start_lsn - log.info(f"Timeline start LSN: {timeline_start_lsn}") + log.info("Timeline start LSN: %s", timeline_start_lsn) current_percent = 0.0 for new_percent in target_percents: @@ -2051,20 +2051,20 @@ def remember_lsn(): # remember LSN right after reaching new_percent lsn = remember_lsn() - log.info(f"LSN after inserting {new_rows} rows: {lsn}") + log.info("LSN after inserting %s rows: %s", new_rows, lsn) # TODO: would be also good to test cases where not all segments are uploaded to S3 for lsn in lsns: new_timeline_id = TimelineId.generate() - log.info(f"Copying branch for LSN {lsn}, to timeline {new_timeline_id}") + log.info("Copying branch for LSN %s, to timeline %s", lsn, new_timeline_id) orig_digest = ( env.safekeepers[0] .http_client() .timeline_digest(tenant_id, timeline_id, timeline_start_lsn, lsn) ) - log.info(f"Original digest: {orig_digest}") + log.info("Original digest: %s", orig_digest) for sk in env.safekeepers: sk.http_client().copy_timeline( @@ -2079,7 +2079,7 @@ def remember_lsn(): new_digest = sk.http_client().timeline_digest( tenant_id, new_timeline_id, timeline_start_lsn, lsn ) - log.info(f"Digest after timeline copy on safekeeper {sk.id}: {new_digest}") + log.info("Digest after timeline copy on safekeeper %s: %s", sk.id, new_digest) assert orig_digest == new_digest @@ -2113,9 +2113,9 @@ def test_patch_control_file(neon_env_builder: NeonEnvBuilder): timeline_start_lsn_before = res["old_control_file"]["timeline_start_lsn"] timeline_start_lsn_after = res["new_control_file"]["timeline_start_lsn"] - log.info(f"patch_control_file response: {res}") + log.info("patch_control_file response: %s", res) log.info( - f"updated control file timeline_start_lsn, before {timeline_start_lsn_before}, after {timeline_start_lsn_after}" + "updated control file timeline_start_lsn, before %s, after %s", timeline_start_lsn_before, timeline_start_lsn_after ) assert timeline_start_lsn_after == "0/1" @@ -2130,7 +2130,7 @@ def test_patch_control_file(neon_env_builder: NeonEnvBuilder): .http_client() .debug_dump({"dump_control_file": "true", "timeline_id": str(timeline_id)}) ) - log.info(f"dump_control_file response: {res}") + log.info("dump_control_file response: %s", res) assert res["timelines"][0]["control_file"]["timeline_start_lsn"] == "0/1" @@ -2229,7 +2229,7 @@ def test_s3_eviction( endpoints[-1].safe_psql("INSERT INTO t VALUES (0)") lsn = endpoints[-1].safe_psql("SELECT pg_current_wal_flush_lsn()")[0][0] - log.info(f"{branch_name}: LSN={lsn}") + log.info("%s: LSN=%s", branch_name, lsn) endpoints[-1].stop() @@ -2244,18 +2244,18 @@ def test_s3_eviction( for j in range(n_timelines): detail = ps_client.timeline_detail(env.initial_tenant, timelines[j]) log.debug( - f'{branch_names[j]}: RCL={detail["remote_consistent_lsn"]}, LRL={detail["last_record_lsn"]}' + '%s: RCL=%s, LRL=%s', branch_names[j], detail["remote_consistent_lsn"], detail["last_record_lsn"] ) i = random.randint(0, n_timelines - 1) - log.info(f"Starting endpoint {i}") + log.info("Starting endpoint %s", i) endpoints[i].start() check_values[i] += 1 res = endpoints[i].safe_psql("UPDATE t SET i = i + 1 RETURNING i") assert res[0][0] == check_values[i] lsn = endpoints[i].safe_psql("SELECT pg_current_wal_flush_lsn()")[0][0] - log.info(f"{branch_names[i]}: LSN={lsn}") + log.info("%s: LSN=%s", branch_names[i], lsn) endpoints[i].stop() diff --git a/test_runner/regress/test_wal_acceptor_async.py b/test_runner/regress/test_wal_acceptor_async.py index 3f0a4a2ff8a6..b4c3473be87b 100644 --- a/test_runner/regress/test_wal_acceptor_async.py +++ b/test_runner/regress/test_wal_acceptor_async.py @@ -77,20 +77,20 @@ def inc_progress(self, worker_id): self.counters[worker_id] += 1 def check_progress(self): - log.debug(f"Workers progress: {self.counters}") + log.debug("Workers progress: %s", self.counters) # every worker should finish at least one tx assert all(cnt > 0 for cnt in self.counters) progress = sum(self.counters) - log.info(f"All workers made {progress} transactions") + log.info("All workers made %s transactions", progress) async def run_random_worker( stats: WorkerStats, endpoint: Endpoint, worker_id, n_accounts, max_transfer ): pg_conn = await endpoint.connect_async() - log.debug(f"Started worker {worker_id}") + log.debug("Started worker %s", worker_id) while stats.running: from_uid = random.randint(0, n_accounts - 1) @@ -100,9 +100,9 @@ async def run_random_worker( await bank_transfer(pg_conn, from_uid, to_uid, amount) stats.inc_progress(worker_id) - log.debug(f"Executed transfer({amount}) {from_uid} => {to_uid}") + log.debug("Executed transfer(%s) %s => %s", amount, from_uid, to_uid) - log.debug(f"Finished worker {worker_id}") + log.debug("Finished worker %s", worker_id) await pg_conn.close() @@ -126,7 +126,7 @@ async def wait_for_lsn( 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}" + "Safekeeper at port %s has flush_lsn %s, waiting for lsn %s", safekeeper.port.pg, flush_lsn, wait_lsn ) while wait_lsn > flush_lsn: @@ -138,7 +138,7 @@ async def wait_for_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}") + log.debug("safekeeper port=%s flush_lsn=%s wait_lsn=%s", safekeeper.port.pg, flush_lsn, wait_lsn) # This test will run several iterations and check progress in each of them. @@ -182,13 +182,13 @@ async def run_restarts_under_load( victim.stop() flush_lsn = Lsn(await pg_conn.fetchval("SELECT pg_current_wal_flush_lsn()")) - log.info(f"Postgres flush_lsn {flush_lsn}") + log.info("Postgres flush_lsn %s", flush_lsn) pageserver_lsn = Lsn( env.pageserver.http_client().timeline_detail(tenant_id, timeline_id)["last_record_lsn"] ) sk_ps_lag = flush_lsn - pageserver_lsn - log.info(f"Pageserver last_record_lsn={pageserver_lsn} lag={sk_ps_lag / 1024}kb") + log.info("Pageserver last_record_lsn=%s lag=%skb", pageserver_lsn, sk_ps_lag / 1024) # Wait until alive safekeepers catch up with postgres for idx, safekeeper in enumerate(acceptors): @@ -291,7 +291,7 @@ async def exec_compute_query( res = await conn.fetch(query) await conn.close() after_conn = time.time() - log.info(f"{query} took {after_conn - before_conn}s") + log.info("%s took %ss", query, after_conn - before_conn) return res @@ -359,14 +359,14 @@ async def run(self): pgdir_name=f"bgcompute{self.index}_key{verify_key}", allow_multiple=True, ) - log.info(f"result: {res}") + log.info("result: %s", res) if len(res) != 1: raise Exception("No result returned") if res[0][0] != verify_key: raise Exception("Wrong result returned") self.successful_queries.append(verify_key) except Exception as e: - log.info(f"BackgroundCompute {self.index} query failed: {e}") + log.info("BackgroundCompute %s query failed: %s", self.index, e) # With less sleep, there is a very big chance of not committing # anything or only 1 xact during test run. @@ -402,8 +402,9 @@ async def run_concurrent_computes( current_queries_by_0 = len(computes[0].successful_queries) - initial_queries_by_0 if current_queries_by_0 >= 1: log.info( - f"Found {current_queries_by_0} successful queries " - f"by computes[0], completing the test" + "Found %s successful queries " + "by computes[0], completing the test", + current_queries_by_0 ) break await asyncio.sleep(0.1) @@ -416,11 +417,12 @@ async def run_concurrent_computes( result = await exec_compute_query(env, branch, "SELECT * FROM query_log") # we should have inserted something while single compute was running log.info( - f"Executed {len(result)} queries, {current_queries_by_0} of them " - f"by computes[0] after we started stopping the others" + "Executed %s queries, %s of them " + "by computes[0] after we started stopping the others", + len(result), current_queries_by_0 ) for row in result: - log.info(f"{row[0]} {row[1]} {row[2]}") + log.info("%s %s %s", row[0], row[1], row[2]) # ensure everything reported as committed wasn't lost for compute in computes: @@ -642,14 +644,14 @@ async def xmas_garland(safekeepers: List[Safekeeper], data: RaceConditionTest): if random.random() >= 0.5: victims.append(sk) log.info( - f"Iteration {data.iteration}: stopping {list(map(lambda sk: sk.id, victims))} safekeepers" + "Iteration %s: stopping %s safekeepers", data.iteration, f"{list(map(lambda sk: sk.id, victims))}" ) for v in victims: v.stop() await asyncio.sleep(1) for v in victims: v.start() - log.info(f"Iteration {data.iteration} finished") + log.info("Iteration %s finished", data.iteration) await asyncio.sleep(1) @@ -670,7 +672,7 @@ async def run_race_conditions(env: NeonEnv, endpoint: Endpoint): expected_sum += i i += 1 - log.info(f"Executed {i-1} queries") + log.info("Executed %s queries", i-1) res = await conn.fetchval("SELECT sum(key) FROM t") assert res == expected_sum @@ -727,7 +729,7 @@ def adjust_safekeepers(env: NeonEnv, active_sk: List[bool]): continue adjust_safekeepers(env, active_sk) - log.info(f"Iteration {it}: {active_sk}") + log.info("Iteration %s: %s", it, active_sk) endpoint.start() conn = await endpoint.connect_async() @@ -744,7 +746,7 @@ def adjust_safekeepers(env: NeonEnv, active_sk: List[bool]): endpoint.start() conn = await endpoint.connect_async() - log.info(f"Executed {i-1} queries") + log.info("Executed %s queries", i-1) res = await conn.fetchval("SELECT sum(key) FROM t") assert res == expected_sum diff --git a/test_runner/regress/test_wal_receiver.py b/test_runner/regress/test_wal_receiver.py index 6582b342187f..1f1c26bd16ba 100644 --- a/test_runner/regress/test_wal_receiver.py +++ b/test_runner/regress/test_wal_receiver.py @@ -78,7 +78,7 @@ def customize_pageserver_toml(ps_cfg: Dict[str, Any]): stopped_safekeeper = env.safekeepers[-1] stopped_safekeeper_id = stopped_safekeeper.id - log.info(f"Stopping safekeeper {stopped_safekeeper.id}") + log.info("Stopping safekeeper %s", stopped_safekeeper.id) stopped_safekeeper.stop() # sleep until stopped safekeeper is removed from candidates time.sleep(2) diff --git a/test_runner/regress/test_wal_restore.py b/test_runner/regress/test_wal_restore.py index 01a1d5cf55b4..fc26ee36054b 100644 --- a/test_runner/regress/test_wal_restore.py +++ b/test_runner/regress/test_wal_restore.py @@ -73,7 +73,7 @@ def decompress_zstd( input_file_name: Path, output_dir: Path, ): - log.info(f"decompressing zstd to: {output_dir}") + log.info("decompressing zstd to: %s", output_dir) output_dir.mkdir(mode=0o750, parents=True, exist_ok=True) with tempfile.TemporaryFile(suffix=".tar") as temp: decompressor = zstandard.ZstdDecompressor() @@ -132,7 +132,7 @@ def test_wal_restore_initdb( restored_lsn = Lsn( restored.safe_psql("SELECT pg_current_wal_flush_lsn()", user="cloud_admin")[0][0] ) - log.info(f"original lsn: {original_lsn}, restored lsn: {restored_lsn}") + log.info("original lsn: %s, restored lsn: %s", original_lsn, restored_lsn) assert restored.safe_psql("select count(*) from t", user="cloud_admin") == [(300000,)] @@ -172,7 +172,7 @@ def test_wal_restore_http(neon_env_builder: NeonEnvBuilder, broken_tenant: bool) obj_key = obj["Key"] if "initdb-preserved.tar.zst" in obj_key: continue - log.info(f"Deleting key from remote storage: {obj_key}") + log.info("Deleting key from remote storage: %s", obj_key) remote_storage_delete_key(env.pageserver_remote_storage, obj_key) pass diff --git a/test_runner/regress/test_walredo_not_left_behind_on_detach.py b/test_runner/regress/test_walredo_not_left_behind_on_detach.py index 375cfcb4feb0..2296ae33f2c6 100644 --- a/test_runner/regress/test_walredo_not_left_behind_on_detach.py +++ b/test_runner/regress/test_walredo_not_left_behind_on_detach.py @@ -72,7 +72,7 @@ def test_walredo_not_left_behind_on_detach(neon_env_builder: NeonEnvBuilder): ) row = cur.fetchone() assert row is not None - log.info(f"shared_buffers is {row[0]}, table size {row[1]}") + log.info("shared_buffers is %s, table size %s", row[0], row[1]) assert int(row[0]) < int(row[1]) cur.execute("SELECT count(*) FROM foo") @@ -92,7 +92,7 @@ def test_walredo_not_left_behind_on_detach(neon_env_builder: NeonEnvBuilder): pageserver_http.tenant_detach(tenant_id) except Exception as e: last_error = e - log.error(f"try {i} error detaching tenant: {e}") + log.error("try %s error detaching tenant: %s", i, e) continue else: break