# Checking port 14647 # Found port 14647 Name: primary Data directory: /Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata Backup directory: /Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/backup Archive directory: /Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/archives Connection string: port=14647 host=/var/folders/29/gl405mp12vq9wrgkv_dhh73h0000gn/T/OVocCVzYIF Log file: /Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/log/005_log_duration_destination_primary.log [02:16:02.342](0.039s) # initializing database system by copying initdb template # Running: cp -RPp /Users/admin/pgsql/build/tmp_install/initdb-template /Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata # Running: /Users/admin/pgsql/build/src/test/regress/pg_regress --config-auth /Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata ### Starting node "primary" # Running: pg_ctl -w -D /Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata -l /Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/log/005_log_duration_destination_primary.log -o --cluster-name=primary start waiting for server to start.... done server started # Postmaster PID for node "primary" is 29494 1111 psql::1: ERROR: column "e1e1" does not exist LINE 1: SELECT E1E1 ^ [02:16:03.225](0.883s) ok 1 - File 'current_logfiles' in the data directory looks correct [02:16:03.226](0.000s) ok 2 - found expected log file content for stderr [02:16:03.226](0.000s) ok 3 - Duration statements are written to the duration stderr log file [02:16:03.226](0.000s) ok 4 - Duration statements do NOT get written to the normal stderr log file [02:16:03.226](0.000s) ok 5 - Duration statements do NOT get written to the normal CSV log file [02:16:03.226](0.000s) ok 6 - Duration statements do NOT get written to the normal JSON log file [02:16:03.226](0.000s) ok 7 - Error statements do NOT get written to the duration stderr log file [02:16:03.226](0.000s) ok 8 - Errors statements are written to the normal stderr log file [02:16:03.226](0.000s) ok 9 - Errors statements are written to the normal CSV log file [02:16:03.226](0.000s) ok 10 - Errors statements are written to the normal JSON log file t 2222 psql::1: ERROR: column "e2e2" does not exist LINE 1: SELECT E2E2 ^ [02:16:03.303](0.077s) ok 11 - found expected log file content for stderr [02:16:03.304](0.000s) not ok 12 - Duration CSV log file gets added to list on reload [02:16:03.304](0.000s) # Failed test 'Duration CSV log file gets added to list on reload' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 99. [02:16:03.304](0.000s) ok 13 - Duration stderr log file gets removed from list on reload [02:16:03.304](0.000s) not ok 14 - Duration statements are written to the duration CSV log file [02:16:03.304](0.000s) # Failed test 'Duration statements are written to the duration CSV log file' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 105. [02:16:03.304](0.000s) # undef # doesn't match '(?^:SELECT 2222)' [02:16:03.304](0.000s) not ok 15 - Duration statements do NOT get written to the normal stderr log file [02:16:03.304](0.000s) # Failed test 'Duration statements do NOT get written to the normal stderr log file' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 109. [02:16:03.305](0.000s) # '2024-07-27 02:16:03.153 UTC [29494][postmaster] LOG: starting PostgreSQL 18devel on aarch64-darwin, compiled by clang-15.0.0, 64-bit # 2024-07-27 02:16:03.154 UTC [29494][postmaster] LOG: listening on Unix socket "/var/folders/29/gl405mp12vq9wrgkv_dhh73h0000gn/T/OVocCVzYIF/.s.PGSQL.14647" # 2024-07-27 02:16:03.162 UTC [29503][startup] LOG: database system was shut down at 2024-07-27 02:12:43 UTC # 2024-07-27 02:16:03.169 UTC [29494][postmaster] LOG: database system is ready to accept connections # 2024-07-27 02:16:03.198 UTC [29515][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.198 UTC [29515][client backend] [[unknown]][0/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.198 UTC [29515][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.204 UTC [29515][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.006 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.223 UTC [29517][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.223 UTC [29517][client backend] [[unknown]][1/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.223 UTC [29517][client backend] [[unknown]][1/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.224 UTC [29517][client backend] [005_log_duration_destination.pl][1/2:0] ERROR: column "e1e1" does not exist at character 8 # 2024-07-27 02:16:03.224 UTC [29517][client backend] [005_log_duration_destination.pl][1/2:0] STATEMENT: SELECT E1E1 # 2024-07-27 02:16:03.224 UTC [29517][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.245 UTC [29519][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.245 UTC [29519][client backend] [[unknown]][2/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.245 UTC [29519][client backend] [[unknown]][2/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.247 UTC [29519][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.263 UTC [29521][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.263 UTC [29521][client backend] [[unknown]][3/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.263 UTC [29521][client backend] [[unknown]][3/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.264 UTC [29494][postmaster] LOG: received SIGHUP, reloading configuration files # 2024-07-27 02:16:03.264 UTC [29521][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.265 UTC [29494][postmaster] LOG: parameter "log_duration_destination" changed to "csvlog" # 2024-07-27 02:16:03.278 UTC [29523][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.278 UTC [29523][client backend] [[unknown]][4/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.278 UTC [29523][client backend] [[unknown]][4/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.279 UTC,"admin","postgres",29523,"[local]",66a45863.7353,4,"SELECT",2024-07-27 02:16:03 UTC,4/0,0,LOG,00000,"duration: 0.108 ms statement: SELECT 2222",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # 2024-07-27 02:16:03.279 UTC [29523][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.000 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.300 UTC [29526][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.301 UTC [29526][client backend] [[unknown]][5/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.301 UTC [29526][client backend] [[unknown]][5/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.302 UTC [29526][client backend] [005_log_duration_destination.pl][5/2:0] ERROR: column "e2e2" does not exist at character 8 # 2024-07-27 02:16:03.302 UTC [29526][client backend] [005_log_duration_destination.pl][5/2:0] STATEMENT: SELECT E2E2 # 2024-07-27 02:16:03.302 UTC [29526][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # ' # matches '(?^:SELECT 2222)' [02:16:03.305](0.000s) ok 16 - Error statements do NOT get written to the duration CSV log file t 3333 psql::1: ERROR: column "e3e3" does not exist LINE 1: SELECT E3E3 ^ [02:16:03.378](0.074s) ok 17 - found expected log file content for stderr [02:16:03.379](0.000s) not ok 18 - Duration JSON log file gets added to list on reload [02:16:03.379](0.000s) # Failed test 'Duration JSON log file gets added to list on reload' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 127. [02:16:03.379](0.000s) not ok 19 - Duration statements are written to the duration JSON log file [02:16:03.379](0.000s) # Failed test 'Duration statements are written to the duration JSON log file' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 130. [02:16:03.379](0.000s) # undef # doesn't match '(?^:SELECT 3333)' [02:16:03.379](0.000s) not ok 20 - Duration statements do NOT get written to the normal stderr log file [02:16:03.379](0.000s) # Failed test 'Duration statements do NOT get written to the normal stderr log file' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 134. [02:16:03.379](0.000s) # '2024-07-27 02:16:03.153 UTC [29494][postmaster] LOG: starting PostgreSQL 18devel on aarch64-darwin, compiled by clang-15.0.0, 64-bit # 2024-07-27 02:16:03.154 UTC [29494][postmaster] LOG: listening on Unix socket "/var/folders/29/gl405mp12vq9wrgkv_dhh73h0000gn/T/OVocCVzYIF/.s.PGSQL.14647" # 2024-07-27 02:16:03.162 UTC [29503][startup] LOG: database system was shut down at 2024-07-27 02:12:43 UTC # 2024-07-27 02:16:03.169 UTC [29494][postmaster] LOG: database system is ready to accept connections # 2024-07-27 02:16:03.198 UTC [29515][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.198 UTC [29515][client backend] [[unknown]][0/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.198 UTC [29515][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.204 UTC [29515][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.006 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.223 UTC [29517][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.223 UTC [29517][client backend] [[unknown]][1/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.223 UTC [29517][client backend] [[unknown]][1/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.224 UTC [29517][client backend] [005_log_duration_destination.pl][1/2:0] ERROR: column "e1e1" does not exist at character 8 # 2024-07-27 02:16:03.224 UTC [29517][client backend] [005_log_duration_destination.pl][1/2:0] STATEMENT: SELECT E1E1 # 2024-07-27 02:16:03.224 UTC [29517][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.245 UTC [29519][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.245 UTC [29519][client backend] [[unknown]][2/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.245 UTC [29519][client backend] [[unknown]][2/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.247 UTC [29519][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.263 UTC [29521][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.263 UTC [29521][client backend] [[unknown]][3/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.263 UTC [29521][client backend] [[unknown]][3/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.264 UTC [29494][postmaster] LOG: received SIGHUP, reloading configuration files # 2024-07-27 02:16:03.264 UTC [29521][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.265 UTC [29494][postmaster] LOG: parameter "log_duration_destination" changed to "csvlog" # 2024-07-27 02:16:03.278 UTC [29523][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.278 UTC [29523][client backend] [[unknown]][4/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.278 UTC [29523][client backend] [[unknown]][4/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.279 UTC,"admin","postgres",29523,"[local]",66a45863.7353,4,"SELECT",2024-07-27 02:16:03 UTC,4/0,0,LOG,00000,"duration: 0.108 ms statement: SELECT 2222",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # 2024-07-27 02:16:03.279 UTC [29523][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.000 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.300 UTC [29526][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.301 UTC [29526][client backend] [[unknown]][5/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.301 UTC [29526][client backend] [[unknown]][5/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.302 UTC [29526][client backend] [005_log_duration_destination.pl][5/2:0] ERROR: column "e2e2" does not exist at character 8 # 2024-07-27 02:16:03.302 UTC [29526][client backend] [005_log_duration_destination.pl][5/2:0] STATEMENT: SELECT E2E2 # 2024-07-27 02:16:03.302 UTC [29526][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.321 UTC [29528][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.322 UTC [29528][client backend] [[unknown]][6/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.322 UTC [29528][client backend] [[unknown]][6/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.323 UTC,"admin","postgres",29528,"[local]",66a45863.7358,4,"ALTER SYSTEM",2024-07-27 02:16:03 UTC,6/0,0,LOG,00000,"duration: 0.352 ms statement: ALTER SYSTEM SET log_duration_destination='csvlog, jsonlog'",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # 2024-07-27 02:16:03.323 UTC [29528][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.338 UTC [29530][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.338 UTC [29530][client backend] [[unknown]][7/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.338 UTC [29530][client backend] [[unknown]][7/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.338 UTC,"admin","postgres",29530,"[local]",66a45863.735a,4,"SELECT",2024-07-27 02:16:03 UTC,7/0,0,LOG,00000,"duration: 0.152 ms statement: SELECT pg_reload_conf()",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # 2024-07-27 02:16:03.338 UTC [29494][postmaster] LOG: received SIGHUP, reloading configuration files # 2024-07-27 02:16:03.339 UTC [29494][postmaster] LOG: parameter "log_duration_destination" changed to "csvlog, jsonlog" # 2024-07-27 02:16:03.347 UTC [29530][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.009 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.361 UTC [29532][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.361 UTC [29532][client backend] [[unknown]][8/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.361 UTC [29532][client backend] [[unknown]][8/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.362 UTC,"admin","postgres",29532,"[local]",66a45863.735c,4,"SELECT",2024-07-27 02:16:03 UTC,8/0,0,LOG,00000,"duration: 0.103 ms statement: SELECT 3333",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # {"timestamp":"2024-07-27 02:16:03.362 UTC","user":"admin","dbname":"postgres","pid":29532,"remote_host":"[local]","session_id":"66a45863.735c","line_num":4,"ps":"SELECT","session_start":"2024-07-27 02:16:03 UTC","vxid":"8/0","txid":0,"error_severity":"LOG","message":"duration: 0.103 ms statement: SELECT 3333","application_name":"005_log_duration_destination.pl","backend_type":"client backend","query_id":0} # 2024-07-27 02:16:03.362 UTC [29532][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.000 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.375 UTC [29534][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.376 UTC [29534][client backend] [[unknown]][9/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.376 UTC [29534][client backend] [[unknown]][9/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.377 UTC [29534][client backend] [005_log_duration_destination.pl][9/2:0] ERROR: column "e3e3" does not exist at character 8 # 2024-07-27 02:16:03.377 UTC [29534][client backend] [005_log_duration_destination.pl][9/2:0] STATEMENT: SELECT E3E3 # 2024-07-27 02:16:03.377 UTC [29534][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # ' # matches '(?^:SELECT 3333)' [02:16:03.380](0.000s) ok 21 - Error statements do NOT get written to the duration JSON log file t 4444 psql::1: ERROR: column "e4e4" does not exist LINE 1: SELECT E4E4 ^ [02:16:03.463](0.083s) ok 22 - found expected log file content for stderr [02:16:03.463](0.000s) not ok 23 - Duration stderr log file gets added to list on reload [02:16:03.463](0.000s) # Failed test 'Duration stderr log file gets added to list on reload' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 152. [02:16:03.463](0.000s) not ok 24 - Duration CSV log file gets added to list on reload [02:16:03.464](0.000s) # Failed test 'Duration CSV log file gets added to list on reload' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 155. [02:16:03.464](0.000s) not ok 25 - Duration JSON log file gets added to list on reload [02:16:03.464](0.000s) # Failed test 'Duration JSON log file gets added to list on reload' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 158. [02:16:03.464](0.000s) not ok 26 - Duration statements are written to the duration stderr log file [02:16:03.464](0.000s) # Failed test 'Duration statements are written to the duration stderr log file' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 161. [02:16:03.464](0.000s) # undef # doesn't match '(?^:SELECT 4444)' [02:16:03.464](0.000s) not ok 27 - Duration statements are written to the duration CSV log file [02:16:03.464](0.000s) # Failed test 'Duration statements are written to the duration CSV log file' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 164. [02:16:03.464](0.000s) # undef # doesn't match '(?^:SELECT 4444)' [02:16:03.465](0.000s) not ok 28 - Duration statements are written to the duration JSON log file [02:16:03.465](0.000s) # Failed test 'Duration statements are written to the duration JSON log file' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 167. [02:16:03.465](0.000s) # undef # doesn't match '(?^:SELECT 4444)' [02:16:03.465](0.000s) not ok 29 - Duration statements do NOT get written to the normal stderr log file [02:16:03.465](0.000s) # Failed test 'Duration statements do NOT get written to the normal stderr log file' # at /Users/admin/pgsql/src/bin/pg_ctl/t/005_log_duration_destination.pl line 171. [02:16:03.465](0.000s) # '2024-07-27 02:16:03.153 UTC [29494][postmaster] LOG: starting PostgreSQL 18devel on aarch64-darwin, compiled by clang-15.0.0, 64-bit # 2024-07-27 02:16:03.154 UTC [29494][postmaster] LOG: listening on Unix socket "/var/folders/29/gl405mp12vq9wrgkv_dhh73h0000gn/T/OVocCVzYIF/.s.PGSQL.14647" # 2024-07-27 02:16:03.162 UTC [29503][startup] LOG: database system was shut down at 2024-07-27 02:12:43 UTC # 2024-07-27 02:16:03.169 UTC [29494][postmaster] LOG: database system is ready to accept connections # 2024-07-27 02:16:03.198 UTC [29515][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.198 UTC [29515][client backend] [[unknown]][0/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.198 UTC [29515][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.204 UTC [29515][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.006 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.223 UTC [29517][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.223 UTC [29517][client backend] [[unknown]][1/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.223 UTC [29517][client backend] [[unknown]][1/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.224 UTC [29517][client backend] [005_log_duration_destination.pl][1/2:0] ERROR: column "e1e1" does not exist at character 8 # 2024-07-27 02:16:03.224 UTC [29517][client backend] [005_log_duration_destination.pl][1/2:0] STATEMENT: SELECT E1E1 # 2024-07-27 02:16:03.224 UTC [29517][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.245 UTC [29519][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.245 UTC [29519][client backend] [[unknown]][2/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.245 UTC [29519][client backend] [[unknown]][2/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.247 UTC [29519][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.263 UTC [29521][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.263 UTC [29521][client backend] [[unknown]][3/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.263 UTC [29521][client backend] [[unknown]][3/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.264 UTC [29494][postmaster] LOG: received SIGHUP, reloading configuration files # 2024-07-27 02:16:03.264 UTC [29521][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.265 UTC [29494][postmaster] LOG: parameter "log_duration_destination" changed to "csvlog" # 2024-07-27 02:16:03.278 UTC [29523][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.278 UTC [29523][client backend] [[unknown]][4/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.278 UTC [29523][client backend] [[unknown]][4/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.279 UTC,"admin","postgres",29523,"[local]",66a45863.7353,4,"SELECT",2024-07-27 02:16:03 UTC,4/0,0,LOG,00000,"duration: 0.108 ms statement: SELECT 2222",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # 2024-07-27 02:16:03.279 UTC [29523][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.000 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.300 UTC [29526][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.301 UTC [29526][client backend] [[unknown]][5/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.301 UTC [29526][client backend] [[unknown]][5/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.302 UTC [29526][client backend] [005_log_duration_destination.pl][5/2:0] ERROR: column "e2e2" does not exist at character 8 # 2024-07-27 02:16:03.302 UTC [29526][client backend] [005_log_duration_destination.pl][5/2:0] STATEMENT: SELECT E2E2 # 2024-07-27 02:16:03.302 UTC [29526][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.321 UTC [29528][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.322 UTC [29528][client backend] [[unknown]][6/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.322 UTC [29528][client backend] [[unknown]][6/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.323 UTC,"admin","postgres",29528,"[local]",66a45863.7358,4,"ALTER SYSTEM",2024-07-27 02:16:03 UTC,6/0,0,LOG,00000,"duration: 0.352 ms statement: ALTER SYSTEM SET log_duration_destination='csvlog, jsonlog'",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # 2024-07-27 02:16:03.323 UTC [29528][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.338 UTC [29530][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.338 UTC [29530][client backend] [[unknown]][7/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.338 UTC [29530][client backend] [[unknown]][7/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.338 UTC,"admin","postgres",29530,"[local]",66a45863.735a,4,"SELECT",2024-07-27 02:16:03 UTC,7/0,0,LOG,00000,"duration: 0.152 ms statement: SELECT pg_reload_conf()",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # 2024-07-27 02:16:03.338 UTC [29494][postmaster] LOG: received SIGHUP, reloading configuration files # 2024-07-27 02:16:03.339 UTC [29494][postmaster] LOG: parameter "log_duration_destination" changed to "csvlog, jsonlog" # 2024-07-27 02:16:03.347 UTC [29530][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.009 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.361 UTC [29532][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.361 UTC [29532][client backend] [[unknown]][8/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.361 UTC [29532][client backend] [[unknown]][8/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.362 UTC,"admin","postgres",29532,"[local]",66a45863.735c,4,"SELECT",2024-07-27 02:16:03 UTC,8/0,0,LOG,00000,"duration: 0.103 ms statement: SELECT 3333",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # {"timestamp":"2024-07-27 02:16:03.362 UTC","user":"admin","dbname":"postgres","pid":29532,"remote_host":"[local]","session_id":"66a45863.735c","line_num":4,"ps":"SELECT","session_start":"2024-07-27 02:16:03 UTC","vxid":"8/0","txid":0,"error_severity":"LOG","message":"duration: 0.103 ms statement: SELECT 3333","application_name":"005_log_duration_destination.pl","backend_type":"client backend","query_id":0} # 2024-07-27 02:16:03.362 UTC [29532][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.000 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.375 UTC [29534][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.376 UTC [29534][client backend] [[unknown]][9/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.376 UTC [29534][client backend] [[unknown]][9/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.377 UTC [29534][client backend] [005_log_duration_destination.pl][9/2:0] ERROR: column "e3e3" does not exist at character 8 # 2024-07-27 02:16:03.377 UTC [29534][client backend] [005_log_duration_destination.pl][9/2:0] STATEMENT: SELECT E3E3 # 2024-07-27 02:16:03.377 UTC [29534][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.390 UTC [29538][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.390 UTC [29538][client backend] [[unknown]][10/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.390 UTC [29538][client backend] [[unknown]][10/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.393 UTC,"admin","postgres",29538,"[local]",66a45863.7362,4,"ALTER SYSTEM",2024-07-27 02:16:03 UTC,10/0,0,LOG,00000,"duration: 2.112 ms statement: ALTER SYSTEM SET log_duration_destination='csvlog, stderr, jsonlog'",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # {"timestamp":"2024-07-27 02:16:03.393 UTC","user":"admin","dbname":"postgres","pid":29538,"remote_host":"[local]","session_id":"66a45863.7362","line_num":4,"ps":"ALTER SYSTEM","session_start":"2024-07-27 02:16:03 UTC","vxid":"10/0","txid":0,"error_severity":"LOG","message":"duration: 2.112 ms statement: ALTER SYSTEM SET log_duration_destination='csvlog, stderr, jsonlog'","application_name":"005_log_duration_destination.pl","backend_type":"client backend","query_id":0} # 2024-07-27 02:16:03.393 UTC [29538][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.003 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.412 UTC [29541][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.412 UTC [29541][client backend] [[unknown]][11/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.412 UTC [29541][client backend] [[unknown]][11/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.413 UTC,"admin","postgres",29541,"[local]",66a45863.7365,4,"SELECT",2024-07-27 02:16:03 UTC,11/0,0,LOG,00000,"duration: 0.194 ms statement: SELECT pg_reload_conf()",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # {"timestamp":"2024-07-27 02:16:03.413 UTC","user":"admin","dbname":"postgres","pid":29541,"remote_host":"[local]","session_id":"66a45863.7365","line_num":4,"ps":"SELECT","session_start":"2024-07-27 02:16:03 UTC","vxid":"11/0","txid":0,"error_severity":"LOG","message":"duration: 0.194 ms statement: SELECT pg_reload_conf()","application_name":"005_log_duration_destination.pl","backend_type":"client backend","query_id":0} # 2024-07-27 02:16:03.413 UTC [29494][postmaster] LOG: received SIGHUP, reloading configuration files # 2024-07-27 02:16:03.414 UTC [29541][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.414 UTC [29494][postmaster] LOG: parameter "log_duration_destination" changed to "csvlog, stderr, jsonlog" # 2024-07-27 02:16:03.434 UTC [29547][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.435 UTC [29547][client backend] [[unknown]][12/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.435 UTC [29547][client backend] [[unknown]][12/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.436 UTC,"admin","postgres",29547,"[local]",66a45863.736b,4,"SELECT",2024-07-27 02:16:03 UTC,12/0,0,LOG,00000,"duration: 0.251 ms statement: SELECT 4444",,,,,,,,,"005_log_duration_destination.pl","client backend",,0 # {"timestamp":"2024-07-27 02:16:03.436 UTC","user":"admin","dbname":"postgres","pid":29547,"remote_host":"[local]","session_id":"66a45863.736b","line_num":4,"ps":"SELECT","session_start":"2024-07-27 02:16:03 UTC","vxid":"12/0","txid":0,"error_severity":"LOG","message":"duration: 0.251 ms statement: SELECT 4444","application_name":"005_log_duration_destination.pl","backend_type":"client backend","query_id":0} # 2024-07-27 02:16:03.436 UTC [29547][client backend] [005_log_duration_destination.pl][12/0:0] LOG: duration: 0.251 ms statement: SELECT 4444 # 2024-07-27 02:16:03.436 UTC [29547][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # 2024-07-27 02:16:03.459 UTC [29550][not initialized] [[unknown]][:0] LOG: connection received: host=[local] # 2024-07-27 02:16:03.460 UTC [29550][client backend] [[unknown]][13/1:0] LOG: connection authenticated: user="admin" method=trust (/Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117) # 2024-07-27 02:16:03.460 UTC [29550][client backend] [[unknown]][13/1:0] LOG: connection authorized: user=admin database=postgres application_name=005_log_duration_destination.pl # 2024-07-27 02:16:03.461 UTC [29550][client backend] [005_log_duration_destination.pl][13/2:0] ERROR: column "e4e4" does not exist at character 8 # 2024-07-27 02:16:03.461 UTC [29550][client backend] [005_log_duration_destination.pl][13/2:0] STATEMENT: SELECT E4E4 # 2024-07-27 02:16:03.461 UTC [29550][client backend] [005_log_duration_destination.pl][:0] LOG: disconnection: session time: 0:00:00.001 user=admin database=postgres host=[local] # ' # matches '(?^:SELECT 4444)' [02:16:03.465](0.000s) ok 30 - Error statements do NOT get written to the duration stderr log file [02:16:03.465](0.000s) ok 31 - Error statements do NOT get written to the duration CSV log file [02:16:03.465](0.000s) ok 32 - Error statements do NOT get written to the duration JSON log file t [02:16:05.562](2.097s) ok 33 - Log file has rotated to a new name (type=csvlog) [02:16:05.563](0.000s) ok 34 - Log file has rotated to a new name (type=jsonlog) [02:16:05.563](0.000s) ok 35 - Log file has rotated to a new name (type=stderr) t 5555 psql::1: ERROR: column "e5e5" does not exist LINE 1: SELECT E5E5 ^ [02:16:05.661](0.099s) ok 36 - found expected log file content for stderr [02:16:05.662](0.000s) ok 37 - Duration stderr gets removed from list on reload [02:16:05.662](0.000s) ok 38 - Duration CSV gets removed from list on reload [02:16:05.662](0.000s) ok 39 - Duration JSON gets removed from list on reload [02:16:05.662](0.000s) ok 40 - Duration statements are written to the normal stderr log file [02:16:05.662](0.000s) 1..40 ### Stopping node "primary" using mode immediate # Running: pg_ctl -D /Users/admin/pgsql/build/testrun/pg_ctl/005_log_duration_destination/data/t_005_log_duration_destination_primary_data/pgdata -m immediate stop waiting for server to shut down.... done server stopped # No postmaster PID for node "primary" [02:16:05.777](0.114s) # Looks like you failed 13 tests of 40.