diff --git a/.circleci/config.yml b/.circleci/config.yml index 629de37522..bd3564c71c 100644 --- a/.circleci/config.yml +++ b/.circleci/config.yml @@ -245,13 +245,13 @@ jobs: # # The junit.xml file allows CircleCI to display more fine-grained test information # in its "Tests" tab in the results page. - # -s prevents pytest from capturing output, which helps to see - # what's going on if the test hangs # --verbose prints name of each test (helpful when there are # multiple tests in one file) # -rA prints summary in the end # -n4 uses four processes to run tests via pytest-xdist - pipenv run pytest --junitxml=$TEST_OUTPUT/junit.xml --tb=short -s --verbose -rA $TEST_SELECTION $EXTRA_PARAMS + # -s is not used to prevent pytest from capturing output, because tests are running + # in parallel and logs are mixed between different tests + pipenv run pytest --junitxml=$TEST_OUTPUT/junit.xml --tb=short --verbose -rA $TEST_SELECTION $EXTRA_PARAMS - run: # CircleCI artifacts are preserved one file at a time, so skipping # this step isn't a good idea. If you want to extract the diff --git a/test_runner/batch_others/test_branch_behind.py b/test_runner/batch_others/test_branch_behind.py index 9189017050..47c2f0b2f9 100644 --- a/test_runner/batch_others/test_branch_behind.py +++ b/test_runner/batch_others/test_branch_behind.py @@ -1,6 +1,6 @@ import subprocess from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver - +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -13,7 +13,7 @@ def test_branch_behind(zenith_cli, pageserver: ZenithPageserver, postgres: Postg zenith_cli.run(["branch", "test_branch_behind", "empty"]) pgmain = postgres.create_start('test_branch_behind') - print("postgres is running on 'test_branch_behind' branch") + log.info("postgres is running on 'test_branch_behind' branch") main_pg_conn = pgmain.connect() main_cur = main_pg_conn.cursor() @@ -27,7 +27,7 @@ def test_branch_behind(zenith_cli, pageserver: ZenithPageserver, postgres: Postg ''') main_cur.execute('SELECT pg_current_wal_insert_lsn()') lsn_a = main_cur.fetchone()[0] - print('LSN after 100 rows: ' + lsn_a) + log.info(f'LSN after 100 rows: {lsn_a}') # Insert some more rows. (This generates enough WAL to fill a few segments.) main_cur.execute(''' @@ -37,7 +37,7 @@ def test_branch_behind(zenith_cli, pageserver: ZenithPageserver, postgres: Postg ''') main_cur.execute('SELECT pg_current_wal_insert_lsn()') lsn_b = main_cur.fetchone()[0] - print('LSN after 200100 rows: ' + lsn_b) + log.info(f'LSN after 200100 rows: {lsn_b}') # Branch at the point where only 100 rows were inserted zenith_cli.run(["branch", "test_branch_behind_hundred", "test_branch_behind@" + lsn_a]) @@ -52,7 +52,7 @@ def test_branch_behind(zenith_cli, pageserver: ZenithPageserver, postgres: Postg main_cur.execute('SELECT pg_current_wal_insert_lsn()') lsn_c = main_cur.fetchone()[0] - print('LSN after 400100 rows: ' + lsn_c) + log.info(f'LSN after 400100 rows: {lsn_c}') # Branch at the point where only 200100 rows were inserted zenith_cli.run(["branch", "test_branch_behind_more", "test_branch_behind@" + lsn_b]) @@ -89,4 +89,4 @@ def test_branch_behind(zenith_cli, pageserver: ZenithPageserver, postgres: Postg try: zenith_cli.run(["branch", "test_branch_preinitdb", "test_branch_behind@0/42"]) except subprocess.CalledProcessError: - print("Branch creation with pre-initdb LSN failed (as expected)") + log.info("Branch creation with pre-initdb LSN failed (as expected)") diff --git a/test_runner/batch_others/test_clog_truncate.py b/test_runner/batch_others/test_clog_truncate.py index e9233986e4..8ad3c22732 100644 --- a/test_runner/batch_others/test_clog_truncate.py +++ b/test_runner/batch_others/test_clog_truncate.py @@ -4,6 +4,7 @@ import os from contextlib import closing from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -24,7 +25,7 @@ def test_clog_truncate(zenith_cli, pageserver: ZenithPageserver, postgres: Postg ] pg = postgres.create_start('test_clog_truncate', config_lines=config) - print('postgres is running on test_clog_truncate branch') + log.info('postgres is running on test_clog_truncate branch') # Install extension containing function needed for test pg.safe_psql('CREATE EXTENSION zenith_test_utils') @@ -33,22 +34,22 @@ def test_clog_truncate(zenith_cli, pageserver: ZenithPageserver, postgres: Postg with closing(pg.connect()) as conn: with conn.cursor() as cur: cur.execute('select test_consume_xids(1000*1000*10);') - print('xids consumed') + log.info('xids consumed') # call a checkpoint to trigger TruncateSubtrans cur.execute('CHECKPOINT;') # ensure WAL flush cur.execute('select txid_current()') - print(cur.fetchone()) + log.info(cur.fetchone()) # wait for autovacuum to truncate the pg_xact # XXX Is it worth to add a timeout here? pg_xact_0000_path = os.path.join(pg.pg_xact_dir_path(), '0000') - print("pg_xact_0000_path = " + pg_xact_0000_path) + log.info(f"pg_xact_0000_path = {pg_xact_0000_path}") while os.path.isfile(pg_xact_0000_path): - print("file exists. wait for truncation. " "pg_xact_0000_path = " + pg_xact_0000_path) + log.info(f"file exists. wait for truncation. " "pg_xact_0000_path = {pg_xact_0000_path}") time.sleep(5) # checkpoint to advance latest lsn @@ -59,14 +60,14 @@ def test_clog_truncate(zenith_cli, pageserver: ZenithPageserver, postgres: Postg lsn_after_truncation = cur.fetchone()[0] # create new branch after clog truncation and start a compute node on it - print('create branch at lsn_after_truncation ' + lsn_after_truncation) + log.info(f'create branch at lsn_after_truncation {lsn_after_truncation}') zenith_cli.run( ["branch", "test_clog_truncate_new", "test_clog_truncate@" + lsn_after_truncation]) pg2 = postgres.create_start('test_clog_truncate_new') - print('postgres is running on test_clog_truncate_new branch') + log.info('postgres is running on test_clog_truncate_new branch') # check that new node doesn't contain truncated segment pg_xact_0000_path_new = os.path.join(pg2.pg_xact_dir_path(), '0000') - print("pg_xact_0000_path_new = " + pg_xact_0000_path_new) + log.info(f"pg_xact_0000_path_new = {pg_xact_0000_path_new}") assert os.path.isfile(pg_xact_0000_path_new) is False diff --git a/test_runner/batch_others/test_config.py b/test_runner/batch_others/test_config.py index d8cc798839..d7c59c4e77 100644 --- a/test_runner/batch_others/test_config.py +++ b/test_runner/batch_others/test_config.py @@ -1,6 +1,7 @@ from contextlib import closing from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -14,7 +15,7 @@ def test_config(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFact # change config pg = postgres.create_start('test_config', config_lines=['log_min_messages=debug1']) - print('postgres is running on test_config branch') + log.info('postgres is running on test_config branch') with closing(pg.connect()) as conn: with conn.cursor() as cur: diff --git a/test_runner/batch_others/test_createdropdb.py b/test_runner/batch_others/test_createdropdb.py index cbe89a77cb..4194538556 100644 --- a/test_runner/batch_others/test_createdropdb.py +++ b/test_runner/batch_others/test_createdropdb.py @@ -3,6 +3,7 @@ import pathlib from contextlib import closing from fixtures.zenith_fixtures import ZenithPageserver, PostgresFactory, ZenithCli, check_restored_datadir_content +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -19,7 +20,7 @@ def test_createdb( zenith_cli.run(["branch", "test_createdb", "empty"]) pg = postgres.create_start('test_createdb') - print("postgres is running on 'test_createdb' branch") + log.info("postgres is running on 'test_createdb' branch") with closing(pg.connect()) as conn: with conn.cursor() as cur: @@ -53,7 +54,7 @@ def test_dropdb( zenith_cli.run(["branch", "test_dropdb", "empty"]) pg = postgres.create_start('test_dropdb') - print("postgres is running on 'test_dropdb' branch") + log.info("postgres is running on 'test_dropdb' branch") with closing(pg.connect()) as conn: with conn.cursor() as cur: @@ -88,13 +89,13 @@ def test_dropdb( # Test that database subdir exists on the branch before drop dbpath = pathlib.Path(pg_before.pgdata_dir) / 'base' / str(dboid) - print(dbpath) + log.info(dbpath) assert os.path.isdir(dbpath) == True # Test that database subdir doesn't exist on the branch after drop dbpath = pathlib.Path(pg_after.pgdata_dir) / 'base' / str(dboid) - print(dbpath) + log.info(dbpath) assert os.path.isdir(dbpath) == False diff --git a/test_runner/batch_others/test_createuser.py b/test_runner/batch_others/test_createuser.py index f44df91c3c..57cc610f55 100644 --- a/test_runner/batch_others/test_createuser.py +++ b/test_runner/batch_others/test_createuser.py @@ -1,6 +1,7 @@ from contextlib import closing from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -12,7 +13,7 @@ def test_createuser(zenith_cli, pageserver: ZenithPageserver, postgres: Postgres zenith_cli.run(["branch", "test_createuser", "empty"]) pg = postgres.create_start('test_createuser') - print("postgres is running on 'test_createuser' branch") + log.info("postgres is running on 'test_createuser' branch") with closing(pg.connect()) as conn: with conn.cursor() as cur: diff --git a/test_runner/batch_others/test_multixact.py b/test_runner/batch_others/test_multixact.py index aaa9e7f58d..403eee9974 100644 --- a/test_runner/batch_others/test_multixact.py +++ b/test_runner/batch_others/test_multixact.py @@ -1,4 +1,5 @@ from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver, check_restored_datadir_content +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -15,7 +16,7 @@ def test_multixact(pageserver: ZenithPageserver, postgres: PostgresFactory, zenith_cli.run(["branch", "test_multixact", "empty"]) pg = postgres.create_start('test_multixact') - print("postgres is running on 'test_multixact' branch") + log.info("postgres is running on 'test_multixact' branch") pg_conn = pg.connect() cur = pg_conn.cursor() @@ -55,7 +56,7 @@ def test_multixact(pageserver: ZenithPageserver, postgres: PostgresFactory, zenith_cli.run(["branch", "test_multixact_new", "test_multixact@" + lsn]) pg_new = postgres.create_start('test_multixact_new') - print("postgres is running on 'test_multixact_new' branch") + log.info("postgres is running on 'test_multixact_new' branch") pg_new_conn = pg_new.connect() cur_new = pg_new_conn.cursor() diff --git a/test_runner/batch_others/test_old_request_lsn.py b/test_runner/batch_others/test_old_request_lsn.py index bb28bdd83f..49e87210e4 100644 --- a/test_runner/batch_others/test_old_request_lsn.py +++ b/test_runner/batch_others/test_old_request_lsn.py @@ -1,6 +1,7 @@ from contextlib import closing from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -18,7 +19,7 @@ def test_old_request_lsn(zenith_cli, pageserver: ZenithPageserver, postgres: Pos # Create a branch for us zenith_cli.run(["branch", "test_old_request_lsn", "empty"]) pg = postgres.create_start('test_old_request_lsn') - print('postgres is running on test_old_request_lsn branch') + log.info('postgres is running on test_old_request_lsn branch') pg_conn = pg.connect() cur = pg_conn.cursor() @@ -46,7 +47,7 @@ def test_old_request_lsn(zenith_cli, pageserver: ZenithPageserver, postgres: Pos from pg_settings where name = 'shared_buffers' ''') row = cur.fetchone() - print(f'shared_buffers is {row[0]}, table size {row[1]}'); + log.info(f'shared_buffers is {row[0]}, table size {row[1]}'); assert int(row[0]) < int(row[1]) cur.execute('VACUUM foo'); diff --git a/test_runner/batch_others/test_pageserver_restart.py b/test_runner/batch_others/test_pageserver_restart.py index 18b17a4efb..0656b7c6e8 100644 --- a/test_runner/batch_others/test_pageserver_restart.py +++ b/test_runner/batch_others/test_pageserver_restart.py @@ -5,6 +5,7 @@ import time from contextlib import closing from multiprocessing import Process, Value from fixtures.zenith_fixtures import WalAcceptorFactory, ZenithPageserver, PostgresFactory +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -40,7 +41,7 @@ def test_pageserver_restart(zenith_cli, pageserver: ZenithPageserver, postgres: from pg_settings where name = 'shared_buffers' ''') row = cur.fetchone() - print("shared_buffers is {}, table size {}", row[0], row[1]); + log.info(f"shared_buffers is {row[0]}, table size {row[1]}"); assert int(row[0]) < int(row[1]) # Stop and restart pageserver. This is a more or less graceful shutdown, although diff --git a/test_runner/batch_others/test_pgbench.py b/test_runner/batch_others/test_pgbench.py index a5423cf3d7..46633daa34 100644 --- a/test_runner/batch_others/test_pgbench.py +++ b/test_runner/batch_others/test_pgbench.py @@ -1,4 +1,5 @@ from fixtures.zenith_fixtures import PostgresFactory +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -8,7 +9,7 @@ def test_pgbench(postgres: PostgresFactory, pg_bin, zenith_cli): zenith_cli.run(["branch", "test_pgbench", "empty"]) pg = postgres.create_start('test_pgbench') - print("postgres is running on 'test_pgbench' branch") + log.info("postgres is running on 'test_pgbench' branch") connstr = pg.connstr() diff --git a/test_runner/batch_others/test_restart_compute.py b/test_runner/batch_others/test_restart_compute.py index 193b675e23..48a19b490b 100644 --- a/test_runner/batch_others/test_restart_compute.py +++ b/test_runner/batch_others/test_restart_compute.py @@ -2,6 +2,7 @@ import pytest from contextlib import closing from fixtures.zenith_fixtures import ZenithPageserver, PostgresFactory +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -27,7 +28,7 @@ def test_restart_compute( pg = postgres.create_start('test_restart_compute', wal_acceptors=wal_acceptor_connstrs) - print("postgres is running on 'test_restart_compute' branch") + log.info("postgres is running on 'test_restart_compute' branch") with closing(pg.connect()) as conn: with conn.cursor() as cur: @@ -36,7 +37,7 @@ def test_restart_compute( cur.execute('SELECT sum(key) FROM t') r = cur.fetchone() assert r == (5000050000, ) - print("res = ", r) + log.info(f"res = {r}") # Remove data directory and restart pg.stop_and_destroy().create_start('test_restart_compute', @@ -49,7 +50,7 @@ def test_restart_compute( cur.execute('SELECT sum(key) FROM t') r = cur.fetchone() assert r == (5000050000, ) - print("res = ", r) + log.info(f"res = {r}") # Insert another row cur.execute("INSERT INTO t VALUES (100001, 'payload2')") @@ -57,7 +58,7 @@ def test_restart_compute( r = cur.fetchone() assert r == (100001, ) - print("res = ", r) + log.info(f"res = {r}") # Again remove data directory and restart pg.stop_and_destroy().create_start('test_restart_compute', @@ -72,7 +73,7 @@ def test_restart_compute( r = cur.fetchone() assert r == (100001, ) - print("res = ", r) + log.info(f"res = {r}") # And again remove data directory and restart pg.stop_and_destroy().create_start('test_restart_compute', @@ -85,4 +86,4 @@ def test_restart_compute( r = cur.fetchone() assert r == (100001, ) - print("res = ", r) + log.info(f"res = {r}") diff --git a/test_runner/batch_others/test_snapfiles_gc.py b/test_runner/batch_others/test_snapfiles_gc.py index e01bf7f179..9cd01ca42e 100644 --- a/test_runner/batch_others/test_snapfiles_gc.py +++ b/test_runner/batch_others/test_snapfiles_gc.py @@ -1,13 +1,14 @@ from contextlib import closing import psycopg2.extras -import time; +import time +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") def print_gc_result(row): - print("GC duration {elapsed} ms".format_map(row)); - print(" REL total: {layer_relfiles_total}, needed_by_cutoff {layer_relfiles_needed_by_cutoff}, needed_by_branches: {layer_relfiles_needed_by_branches}, not_updated: {layer_relfiles_not_updated}, needed_as_tombstone {layer_relfiles_needed_as_tombstone}, removed: {layer_relfiles_removed}, dropped: {layer_relfiles_dropped}".format_map(row)) - print(" NONREL total: {layer_nonrelfiles_total}, needed_by_cutoff {layer_nonrelfiles_needed_by_cutoff}, needed_by_branches: {layer_nonrelfiles_needed_by_branches}, not_updated: {layer_nonrelfiles_not_updated}, needed_as_tombstone {layer_nonrelfiles_needed_as_tombstone}, removed: {layer_nonrelfiles_removed}, dropped: {layer_nonrelfiles_dropped}".format_map(row)) + log.info("GC duration {elapsed} ms".format_map(row)); + log.info(" REL total: {layer_relfiles_total}, needed_by_cutoff {layer_relfiles_needed_by_cutoff}, needed_by_branches: {layer_relfiles_needed_by_branches}, not_updated: {layer_relfiles_not_updated}, needed_as_tombstone {layer_relfiles_needed_as_tombstone}, removed: {layer_relfiles_removed}, dropped: {layer_relfiles_dropped}".format_map(row)) + log.info(" NONREL total: {layer_nonrelfiles_total}, needed_by_cutoff {layer_nonrelfiles_needed_by_cutoff}, needed_by_branches: {layer_nonrelfiles_needed_by_branches}, not_updated: {layer_nonrelfiles_not_updated}, needed_as_tombstone {layer_nonrelfiles_needed_as_tombstone}, removed: {layer_nonrelfiles_removed}, dropped: {layer_nonrelfiles_dropped}".format_map(row)) # @@ -35,7 +36,7 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin): cur.execute("select relfilenode from pg_class where oid = 'foo'::regclass"); row = cur.fetchone(); - print("relfilenode is {}", row[0]); + log.info(f"relfilenode is {row[0]}"); # Run GC, to clear out any garbage left behind in the catalogs by # the CREATE TABLE command. We want to have a clean slate with no garbage @@ -50,7 +51,7 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin): # update to confuse our numbers either. cur.execute("DELETE FROM foo") - print("Running GC before test") + log.info("Running GC before test") pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0") row = pscur.fetchone() print_gc_result(row); @@ -61,7 +62,7 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin): # Insert a row and run GC. Checkpoint should freeze the layer # so that there is only the most recent image layer left for the rel, # removing the old image and delta layer. - print("Inserting one row and running GC") + log.info("Inserting one row and running GC") cur.execute("INSERT INTO foo VALUES (1)") pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0") row = pscur.fetchone() @@ -73,7 +74,7 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin): # Insert two more rows and run GC. # This should create new image and delta layer file with the new contents, and # then remove the old one image and the just-created delta layer. - print("Inserting two more rows and running GC") + log.info("Inserting two more rows and running GC") cur.execute("INSERT INTO foo VALUES (2)") cur.execute("INSERT INTO foo VALUES (3)") @@ -85,7 +86,7 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin): assert row['layer_relfiles_dropped'] == 0 # Do it again. Should again create two new layer files and remove old ones. - print("Inserting two more rows and running GC") + log.info("Inserting two more rows and running GC") cur.execute("INSERT INTO foo VALUES (2)") cur.execute("INSERT INTO foo VALUES (3)") @@ -97,7 +98,7 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin): assert row['layer_relfiles_dropped'] == 0 # Run GC again, with no changes in the database. Should not remove anything. - print("Run GC again, with nothing to do") + log.info("Run GC again, with nothing to do") pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0") row = pscur.fetchone() print_gc_result(row); @@ -108,7 +109,7 @@ def test_layerfiles_gc(zenith_cli, pageserver, postgres, pg_bin): # # Test DROP TABLE checks that relation data and metadata was deleted by GC from object storage # - print("Drop table and run GC again"); + log.info("Drop table and run GC again"); cur.execute("DROP TABLE foo") pscur.execute(f"do_gc {pageserver.initial_tenant} {timeline} 0") diff --git a/test_runner/batch_others/test_timeline_size.py b/test_runner/batch_others/test_timeline_size.py index 45b0c98d40..acc2394306 100644 --- a/test_runner/batch_others/test_timeline_size.py +++ b/test_runner/batch_others/test_timeline_size.py @@ -2,7 +2,7 @@ from contextlib import closing from uuid import UUID import psycopg2.extras from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver - +from fixtures.log_helper import log def test_timeline_size( zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFactory, pg_bin @@ -15,7 +15,7 @@ def test_timeline_size( assert res["current_logical_size"] == res["current_logical_size_non_incremental"] pgmain = postgres.create_start("test_timeline_size") - print("postgres is running on 'test_timeline_size' branch") + log.info("postgres is running on 'test_timeline_size' branch") with closing(pgmain.connect()) as conn: with conn.cursor() as cur: diff --git a/test_runner/batch_others/test_twophase.py b/test_runner/batch_others/test_twophase.py index d818f04da4..a6315fed15 100644 --- a/test_runner/batch_others/test_twophase.py +++ b/test_runner/batch_others/test_twophase.py @@ -1,7 +1,7 @@ import os from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver, PgBin - +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -13,7 +13,7 @@ def test_twophase(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFa zenith_cli.run(["branch", "test_twophase", "empty"]) pg = postgres.create_start('test_twophase', config_lines=['max_prepared_transactions=5']) - print("postgres is running on 'test_twophase' branch") + log.info("postgres is running on 'test_twophase' branch") conn = pg.connect() cur = conn.cursor() @@ -45,7 +45,7 @@ def test_twophase(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFa cur.execute('CHECKPOINT') twophase_files = os.listdir(pg.pg_twophase_dir_path()) - print(twophase_files) + log.info(twophase_files) assert len(twophase_files) == 4 cur.execute("COMMIT PREPARED 'insert_three'") @@ -53,7 +53,7 @@ def test_twophase(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFa cur.execute('CHECKPOINT') twophase_files = os.listdir(pg.pg_twophase_dir_path()) - print(twophase_files) + log.info(twophase_files) assert len(twophase_files) == 2 # Create a branch with the transaction in prepared state @@ -67,7 +67,7 @@ def test_twophase(zenith_cli, pageserver: ZenithPageserver, postgres: PostgresFa # Check that we restored only needed twophase files twophase_files2 = os.listdir(pg2.pg_twophase_dir_path()) - print(twophase_files2) + log.info(twophase_files2) assert twophase_files2.sort() == twophase_files.sort() conn2 = pg2.connect() diff --git a/test_runner/batch_others/test_vm_bits.py b/test_runner/batch_others/test_vm_bits.py index 92509fcbbb..86c56ddb9c 100644 --- a/test_runner/batch_others/test_vm_bits.py +++ b/test_runner/batch_others/test_vm_bits.py @@ -1,4 +1,5 @@ from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -11,7 +12,7 @@ def test_vm_bit_clear(pageserver: ZenithPageserver, postgres: PostgresFactory, p zenith_cli.run(["branch", "test_vm_bit_clear", "empty"]) pg = postgres.create_start('test_vm_bit_clear') - print("postgres is running on 'test_vm_bit_clear' branch") + log.info("postgres is running on 'test_vm_bit_clear' branch") pg_conn = pg.connect() cur = pg_conn.cursor() @@ -63,7 +64,7 @@ def test_vm_bit_clear(pageserver: ZenithPageserver, postgres: PostgresFactory, p # server at the right point-in-time avoids that full-page image. pg_new = postgres.create_start('test_vm_bit_clear_new') - print("postgres is running on 'test_vm_bit_clear_new' branch") + log.info("postgres is running on 'test_vm_bit_clear_new' branch") pg_new_conn = pg_new.connect() cur_new = pg_new_conn.cursor() diff --git a/test_runner/batch_others/test_wal_acceptor.py b/test_runner/batch_others/test_wal_acceptor.py index b5577f28d0..6f5e877714 100644 --- a/test_runner/batch_others/test_wal_acceptor.py +++ b/test_runner/batch_others/test_wal_acceptor.py @@ -9,6 +9,7 @@ from contextlib import closing from multiprocessing import Process, Value from fixtures.zenith_fixtures import WalAcceptorFactory, ZenithPageserver, PostgresFactory, PgBin from fixtures.utils import lsn_to_hex, mkdir_if_needed +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -284,10 +285,10 @@ def test_sync_safekeepers(repo_dir: str, pg_bin: PgBin, wa_factory: WalAcceptorF ) lsn_hex = lsn_to_hex(res["inserted_wal"]["end_lsn"]) lsn_after_append.append(lsn_hex) - print(f"safekeeper[{i}] lsn after append: {lsn_hex}") + log.info(f"safekeeper[{i}] lsn after append: {lsn_hex}") # run sync safekeepers lsn_after_sync = pg.sync_safekeepers() - print(f"lsn after sync = {lsn_after_sync}") + log.info(f"lsn after sync = {lsn_after_sync}") assert all(lsn_after_sync == lsn for lsn in lsn_after_append) diff --git a/test_runner/batch_others/test_wal_acceptor_async.py b/test_runner/batch_others/test_wal_acceptor_async.py index b1647a8544..b2faa9b985 100644 --- a/test_runner/batch_others/test_wal_acceptor_async.py +++ b/test_runner/batch_others/test_wal_acceptor_async.py @@ -3,9 +3,10 @@ import asyncpg import random from fixtures.zenith_fixtures import WalAcceptor, WalAcceptorFactory, ZenithPageserver, PostgresFactory, Postgres +from fixtures.log_helper import getLogger from typing import List -from fixtures.utils import debug_print +log = getLogger('root.wal_acceptor_async') pytest_plugins = ("fixtures.zenith_fixtures") @@ -63,18 +64,18 @@ class WorkerStats(object): self.counters[worker_id] += 1 def check_progress(self): - debug_print("Workers progress: {}".format(self.counters)) + log.debug("Workers progress: {}".format(self.counters)) # every worker should finish at least one tx assert all(cnt > 0 for cnt in self.counters) progress = sum(self.counters) - print('All workers made {} transactions'.format(progress)) + log.info('All workers made {} transactions'.format(progress)) async def run_random_worker(stats: WorkerStats, pg: Postgres, worker_id, n_accounts, max_transfer): pg_conn = await pg.connect_async() - debug_print('Started worker {}'.format(worker_id)) + log.debug('Started worker {}'.format(worker_id)) while stats.running: from_uid = random.randint(0, n_accounts - 1) @@ -84,9 +85,9 @@ async def run_random_worker(stats: WorkerStats, pg: Postgres, worker_id, n_accou await bank_transfer(pg_conn, from_uid, to_uid, amount) stats.inc_progress(worker_id) - debug_print('Executed transfer({}) {} => {}'.format(amount, from_uid, to_uid)) + log.debug('Executed transfer({}) {} => {}'.format(amount, from_uid, to_uid)) - debug_print('Finished worker {}'.format(worker_id)) + log.debug('Finished worker {}'.format(worker_id)) await pg_conn.close() @@ -134,7 +135,7 @@ async def run_restarts_under_load(pg: Postgres, acceptors: List[WalAcceptor], n_ victim.start() - print('Iterations are finished, exiting coroutines...') + log.info('Iterations are finished, exiting coroutines...') stats.running = False # await all workers await asyncio.gather(*workers) diff --git a/test_runner/batch_pg_regress/test_zenith_regress.py b/test_runner/batch_pg_regress/test_zenith_regress.py index 09f5f83933..ab43f511ef 100644 --- a/test_runner/batch_pg_regress/test_zenith_regress.py +++ b/test_runner/batch_pg_regress/test_zenith_regress.py @@ -2,6 +2,7 @@ import os from fixtures.utils import mkdir_if_needed from fixtures.zenith_fixtures import PageserverPort, PostgresFactory, check_restored_datadir_content +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures") @@ -38,7 +39,7 @@ def test_zenith_regress(postgres: PostgresFactory, pg_bin, zenith_cli, test_outp '--inputdir={}'.format(src_path), ] - print(pg_regress_command) + log.info(pg_regress_command) env = { 'PGPORT': str(pg.port), 'PGUSER': pg.username, diff --git a/test_runner/fixtures/benchmark_fixture.py b/test_runner/fixtures/benchmark_fixture.py index 328ebcc1f8..c70ee36256 100644 --- a/test_runner/fixtures/benchmark_fixture.py +++ b/test_runner/fixtures/benchmark_fixture.py @@ -1,5 +1,3 @@ -from pprint import pprint - import os import re import timeit diff --git a/test_runner/fixtures/log_helper.py b/test_runner/fixtures/log_helper.py new file mode 100644 index 0000000000..f253576e7b --- /dev/null +++ b/test_runner/fixtures/log_helper.py @@ -0,0 +1,44 @@ +import logging +import logging.config + +""" +This file configures logging to use in python tests. +Logs are automatically captured and shown in their +own section after all tests are executed. + +To see logs for all (even successful) tests, run +pytest with the following command: +- `pipenv run pytest -n8 -rA` + +Other log config can be set in pytest.ini file. +You can add `log_cli = true` to it to watch +logs in real time. + +To get more info about logging with pytest, see +https://docs.pytest.org/en/6.2.x/logging.html +""" + +# this config is only used for default log levels, +# log format is specified in pytest.ini file +LOGGING = { + "version": 1, + "loggers": { + "root": { + "level": "INFO" + }, + "root.wal_acceptor_async": { + "level": "INFO" # a lot of logs on DEBUG level + } + } +} + +def getLogger(name='root') -> logging.Logger: + """Method to get logger for tests. + + Should be used to get correctly initialized logger. """ + return logging.getLogger(name) + +# default logger for tests +log = getLogger() + +logging.config.dictConfig(LOGGING) diff --git a/test_runner/fixtures/utils.py b/test_runner/fixtures/utils.py index 92bd25ed24..dd90a36dbb 100644 --- a/test_runner/fixtures/utils.py +++ b/test_runner/fixtures/utils.py @@ -2,7 +2,7 @@ import os import subprocess from typing import Any, List - +from fixtures.log_helper import log def get_self_dir() -> str: """ Get the path to the directory where this script lives. """ @@ -39,7 +39,7 @@ def subprocess_capture(capture_dir: str, cmd: List[str], **kwargs: Any) -> str: with open(stdout_filename, 'w') as stdout_f: with open(stderr_filename, 'w') as stderr_f: - print('(capturing output to "{}.stdout")'.format(base)) + log.info('(capturing output to "{}.stdout")'.format(base)) subprocess.run(cmd, **kwargs, stdout=stdout_f, stderr=stderr_f) return basepath @@ -58,14 +58,6 @@ def global_counter() -> int: _global_counter += 1 return _global_counter -def debug_print(*args, **kwargs) -> None: - """ Print to the console if TEST_DEBUG_PRINT is set in env. - - All parameters are passed to print(). - """ - if os.environ.get('TEST_DEBUG_PRINT') is not None: - print(*args, **kwargs) - def lsn_to_hex(num: int) -> str: """ Convert lsn from int to standard hex notation. """ return "{:X}/{:X}".format(num >> 32, num & 0xffffffff) diff --git a/test_runner/fixtures/zenith_fixtures.py b/test_runner/fixtures/zenith_fixtures.py index bf861f8b00..efdd966f02 100644 --- a/test_runner/fixtures/zenith_fixtures.py +++ b/test_runner/fixtures/zenith_fixtures.py @@ -27,6 +27,8 @@ from typing_extensions import Literal import requests from .utils import (get_self_dir, mkdir_if_needed, subprocess_capture) +from fixtures.log_helper import log + """ This file contains pytest fixtures. A fixture is a test resource that can be summoned by placing its name in the test's arguments. @@ -188,13 +190,13 @@ class ZenithCli: >>> result = zenith_cli.run(...) >>> assert result.stderr == "" - >>> print(result.stdout) + >>> log.info(result.stdout) """ assert type(arguments) == list args = [self.bin_zenith] + arguments - print('Running command "{}"'.format(' '.join(args))) + log.info('Running command "{}"'.format(' '.join(args))) # Interceipt CalledProcessError and print more info try: @@ -211,7 +213,7 @@ class ZenithCli: stdout: {exc.stdout} stderr: {exc.stderr} """ - print(msg) + log.info(msg) raise Exception(msg) from exc @@ -392,7 +394,7 @@ class ZenithPageserver(PgProtocol): if immediate: cmd.append('immediate') - print(cmd) + log.info(f"Stopping pageserver with {cmd}") if self.running: self.zenith_cli.run(cmd) self.running = False @@ -424,7 +426,7 @@ class ZenithPageserver(PgProtocol): def pageserver_port(port_distributor: PortDistributor) -> PageserverPort: pg = port_distributor.get_port() http = port_distributor.get_port() - print(f"pageserver_port: pg={pg} http={http}") + log.info(f"pageserver_port: pg={pg} http={http}") return PageserverPort(pg=pg, http=http) @@ -448,7 +450,7 @@ def pageserver(zenith_cli: ZenithCli, repo_dir: str, pageserver_port: Pageserver yield ps # After the yield comes any cleanup code we need. - print('Starting pageserver cleanup') + log.info('Starting pageserver cleanup') ps.stop(True) class PgBin: @@ -486,7 +488,7 @@ class PgBin: """ self._fixpath(command) - print('Running command "{}"'.format(' '.join(command))) + log.info('Running command "{}"'.format(' '.join(command))) env = self._build_env(env) subprocess.run(command, env=env, cwd=cwd, check=True) @@ -503,7 +505,7 @@ class PgBin: """ self._fixpath(command) - print('Running command "{}"'.format(' '.join(command))) + log.info('Running command "{}"'.format(' '.join(command))) env = self._build_env(env) return subprocess_capture(self.log_dir, command, env=env, cwd=cwd, check=True, **kwargs) @@ -571,12 +573,12 @@ class Postgres(PgProtocol): assert self.branch is not None - print(f"Starting postgres on branch {self.branch}") + log.info(f"Starting postgres on branch {self.branch}") run_result = self.zenith_cli.run(['pg', 'start', self.branch, f'--tenantid={self.tenant_id}', f'--port={self.port}']) self.running = True - print(f"stdout: {run_result.stdout}") + log.info(f"stdout: {run_result.stdout}") return self @@ -791,7 +793,7 @@ def postgres(zenith_cli: ZenithCli, initial_tenant: str, repo_dir: str, pg_bin: yield pgfactory # After the yield comes any cleanup code we need. - print('Starting postgres cleanup') + log.info('Starting postgres cleanup') pgfactory.stop_all() def read_pid(path: Path): @@ -828,7 +830,7 @@ class WalAcceptor: # Tell page server it can receive WAL from this WAL safekeeper cmd.extend(["--pageserver", f"localhost:{self.pageserver_port}"]) cmd.extend(["--recall", "1 second"]) - print('Running command "{}"'.format(' '.join(cmd))) + log.info('Running command "{}"'.format(' '.join(cmd))) env = {'PAGESERVER_AUTH_TOKEN': self.auth_token} if self.auth_token else None subprocess.run(cmd, check=True, env=env) @@ -857,10 +859,10 @@ class WalAcceptor: return pid def stop(self) -> 'WalAcceptor': - print('Stopping wal acceptor {}'.format(self.num)) + log.info('Stopping wal acceptor {}'.format(self.num)) pid = self.get_pid() if pid is None: - print("Wal acceptor {} is not running".format(self.num)) + log.info("Wal acceptor {} is not running".format(self.num)) return self try: @@ -886,10 +888,10 @@ class WalAcceptor: conn.autocommit = True with conn.cursor() as cur: request_json = json.dumps(request) - print(f"JSON_CTRL request on port {self.port.pg}: {request_json}") + log.info(f"JSON_CTRL request on port {self.port.pg}: {request_json}") cur.execute("JSON_CTRL " + request_json) all = cur.fetchall() - print(f"JSON_CTRL response: {all[0][0]}") + log.info(f"JSON_CTRL response: {all[0][0]}") return json.loads(all[0][0]) class WalAcceptorFactory: @@ -950,7 +952,7 @@ def wa_factory(zenith_binpath: str, repo_dir: str, pageserver_port: PageserverPo ) yield wafactory # After the yield comes any cleanup code we need. - print('Starting wal acceptors cleanup') + log.info('Starting wal acceptors cleanup') wafactory.stop_all() @@ -959,7 +961,7 @@ def base_dir() -> str: """ find the base directory (currently this is the git root) """ base_dir = os.path.normpath(os.path.join(get_self_dir(), '../..')) - print('\nbase_dir is', base_dir) + log.info(f'base_dir is {base_dir}') return base_dir @@ -988,7 +990,7 @@ def test_output_dir(request: Any, top_output_dir: str) -> str: test_name = 'shared' test_output_dir = os.path.join(top_output_dir, test_name) - print('test_output_dir is', test_output_dir) + log.info(f'test_output_dir is {test_output_dir}') shutil.rmtree(test_output_dir, ignore_errors=True) mkdir_if_needed(test_output_dir) return test_output_dir @@ -1030,7 +1032,7 @@ def pg_distrib_dir(base_dir: str) -> str: pg_dir = env_postgres_bin else: pg_dir = os.path.normpath(os.path.join(base_dir, DEFAULT_POSTGRES_DIR)) - print('postgres dir is', pg_dir) + log.info(f'postgres dir is {pg_dir}') if not os.path.exists(os.path.join(pg_dir, 'bin/postgres')): raise Exception('postgres not found at "{}"'.format(pg_dir)) return pg_dir @@ -1069,7 +1071,7 @@ def list_files_to_compare(pgdata_dir: str): pgdata_files.append(rel_file) pgdata_files.sort() - print(pgdata_files) + log.info(pgdata_files) return pgdata_files # pg is the existing and running compute node, that we want to compare with a basebackup @@ -1115,9 +1117,7 @@ def check_restored_datadir_content(zenith_cli: ZenithCli, test_output_dir: str, restored_dir_path, pgdata_files, shallow=False) - print('filecmp result mismatch and error lists:') - print(mismatch) - print(error) + log.info(f'filecmp result mismatch and error lists:\n\t mismatch={mismatch}\n\t error={error}') for f in mismatch: diff --git a/test_runner/performance/test_bulk_insert.py b/test_runner/performance/test_bulk_insert.py index 95f1ea5e4a..1effa56ee9 100644 --- a/test_runner/performance/test_bulk_insert.py +++ b/test_runner/performance/test_bulk_insert.py @@ -1,6 +1,7 @@ import os from contextlib import closing from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures", "fixtures.benchmark_fixture") @@ -19,7 +20,7 @@ def test_bulk_insert(postgres: PostgresFactory, pageserver: ZenithPageserver, pg zenith_cli.run(["branch", "test_bulk_insert", "empty"]) pg = postgres.create_start('test_bulk_insert') - print("postgres is running on 'test_bulk_insert' branch") + log.info("postgres is running on 'test_bulk_insert' branch") # Open a connection directly to the page server that we'll use to force # flushing the layers to disk diff --git a/test_runner/performance/test_gist_build.py b/test_runner/performance/test_gist_build.py index 040adb1242..b9ef0a3d4b 100644 --- a/test_runner/performance/test_gist_build.py +++ b/test_runner/performance/test_gist_build.py @@ -1,6 +1,7 @@ import os from contextlib import closing from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures", "fixtures.benchmark_fixture") @@ -14,7 +15,7 @@ def test_gist_buffering_build(postgres: PostgresFactory, pageserver: ZenithPages zenith_cli.run(["branch", "test_gist_buffering_build", "empty"]) pg = postgres.create_start('test_gist_buffering_build') - print("postgres is running on 'test_gist_buffering_build' branch") + log.info("postgres is running on 'test_gist_buffering_build' branch") # Open a connection directly to the page server that we'll use to force # flushing the layers to disk diff --git a/test_runner/performance/test_perf_pgbench.py b/test_runner/performance/test_perf_pgbench.py index 18db78f12a..22e8f2aee3 100644 --- a/test_runner/performance/test_perf_pgbench.py +++ b/test_runner/performance/test_perf_pgbench.py @@ -1,6 +1,7 @@ import os from contextlib import closing from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures", "fixtures.benchmark_fixture") @@ -18,7 +19,7 @@ def test_pgbench(postgres: PostgresFactory, pageserver: ZenithPageserver, pg_bin zenith_cli.run(["branch", "test_pgbench_perf", "empty"]) pg = postgres.create_start('test_pgbench_perf') - print("postgres is running on 'test_pgbench_perf' branch") + log.info("postgres is running on 'test_pgbench_perf' branch") # Open a connection directly to the page server that we'll use to force # flushing the layers to disk diff --git a/test_runner/performance/test_write_amplification.py b/test_runner/performance/test_write_amplification.py index 09310c702b..8410499bd2 100644 --- a/test_runner/performance/test_write_amplification.py +++ b/test_runner/performance/test_write_amplification.py @@ -13,6 +13,7 @@ import os from contextlib import closing from fixtures.zenith_fixtures import PostgresFactory, ZenithPageserver +from fixtures.log_helper import log pytest_plugins = ("fixtures.zenith_fixtures", "fixtures.benchmark_fixture") @@ -21,7 +22,7 @@ def test_write_amplification(postgres: PostgresFactory, pageserver: ZenithPagese zenith_cli.run(["branch", "test_write_amplification", "empty"]) pg = postgres.create_start('test_write_amplification') - print("postgres is running on 'test_write_amplification' branch") + log.info("postgres is running on 'test_write_amplification' branch") # Open a connection directly to the page server that we'll use to force # flushing the layers to disk diff --git a/test_runner/pytest.ini b/test_runner/pytest.ini index 78b5304f78..e6c7013559 100644 --- a/test_runner/pytest.ini +++ b/test_runner/pytest.ini @@ -1,2 +1,4 @@ [pytest] minversion = 6.0 +log_format = %(asctime)s.%(msecs)-3d %(levelname)s [%(filename)s:%(lineno)d] %(message)s +log_date_format = %Y-%m-%d %H:%M:%S diff --git a/test_runner/test_broken.py b/test_runner/test_broken.py index da715d7387..66bfe1192c 100644 --- a/test_runner/test_broken.py +++ b/test_runner/test_broken.py @@ -1,6 +1,8 @@ import pytest import os +from fixtures.log_helper import log + pytest_plugins = ("fixtures.zenith_fixtures") """ Use this test to see what happens when tests fail. @@ -22,7 +24,7 @@ def test_broken(zenith_cli, pageserver, postgres, pg_bin): zenith_cli.run(["branch", "test_broken", "empty"]) postgres.create_start("test_broken") - print('postgres is running') + log.info('postgres is running') - print('THIS NEXT COMMAND WILL FAIL:') + log.info('THIS NEXT COMMAND WILL FAIL:') pg_bin.run('pgbench -i_am_a_broken_test'.split())