# Checking port 17007
# Found port 17007
Name: primary
Data directory: /tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/backup
Archive directory: /tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/archives
Connection string: port=17007 host=/tmp/ZeSSPwsFgA
Log file: /tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/log/005_log_duration_destination_primary.log
[02:15:34.376](0.073s) # initializing database system by copying initdb template
# Running: cp -RPp /tmp/cirrus-ci-build/tmp_install/initdb-template /tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata
# Running: /tmp/cirrus-ci-build/src/bin/pg_ctl/../../../src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata
### Starting node "primary"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/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 29085
1111
psql:<stdin>:1: ERROR:  column "e1e1" does not exist
LINE 1: SELECT E1E1
               ^
[02:15:35.245](0.869s) ok 1 - File 'current_logfiles' in the data directory looks correct
[02:15:35.246](0.000s) ok 2 - found expected log file content for stderr
[02:15:35.246](0.000s) ok 3 - Duration statements are written to the duration stderr log file
[02:15:35.246](0.000s) ok 4 - Duration statements do NOT get written to the normal stderr log file
[02:15:35.246](0.000s) ok 5 - Duration statements do NOT get written to the normal CSV log file
[02:15:35.246](0.000s) ok 6 - Duration statements do NOT get written to the normal JSON log file
[02:15:35.247](0.000s) ok 7 - Error statements do NOT get written to the duration stderr log file
[02:15:35.247](0.000s) ok 8 - Errors statements are written to the normal stderr log file
[02:15:35.247](0.000s) ok 9 - Errors statements are written to the normal CSV log file
[02:15:35.247](0.000s) ok 10 - Errors statements are written to the normal JSON log file
t
2222
psql:<stdin>:1: ERROR:  column "e2e2" does not exist
LINE 1: SELECT E2E2
               ^
[02:15:35.510](0.263s) ok 11 - found expected log file content for stderr
[02:15:35.510](0.000s) not ok 12 - Duration CSV log file gets added to list on reload
[02:15:35.511](0.000s) 
[02:15:35.511](0.000s) #   Failed test 'Duration CSV log file gets added to list on reload'
#   at t/005_log_duration_destination.pl line 99.
[02:15:35.511](0.000s) ok 13 - Duration stderr log file gets removed from list on reload
[02:15:35.511](0.000s) not ok 14 - Duration statements are written to the duration CSV log file
[02:15:35.511](0.000s) 
[02:15:35.511](0.000s) #   Failed test 'Duration statements are written to the duration CSV log file'
#   at t/005_log_duration_destination.pl line 105.
[02:15:35.511](0.000s) #                   undef
#     doesn't match '(?^:SELECT 2222)'
[02:15:35.511](0.000s) not ok 15 - Duration statements do NOT get written to the normal stderr log file
[02:15:35.512](0.000s) 
[02:15:35.512](0.000s) #   Failed test 'Duration statements do NOT get written to the normal stderr log file'
#   at t/005_log_duration_destination.pl line 109.
[02:15:35.512](0.000s) #                   '2024-07-27 02:15:35.378 UTC [29144][client backend] [005_log_duration_destination.pl][3/0:0] LOG:  duration: 13.007 ms  statement: SELECT pg_reload_conf()
# 2024-07-27 02:15:35.383 UTC [29144][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.021 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.442 UTC [29153][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.447 UTC [29153][client backend] [[unknown]][4/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.448 UTC [29153][client backend] [[unknown]][4/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.454 UTC,"postgres","postgres",29153,"[local]",66a45847.71e1,4,"SELECT",2024-07-27 02:15:35 UTC,4/0,0,LOG,00000,"duration: 0.601 ms  statement: SELECT 2222",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# 2024-07-27 02:15:35.458 UTC [29153][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.017 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.500 UTC [29160][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.501 UTC [29160][client backend] [[unknown]][5/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.501 UTC [29160][client backend] [[unknown]][5/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.505 UTC [29160][client backend] [005_log_duration_destination.pl][5/2:0] ERROR:  column "e2e2" does not exist at character 8
# 2024-07-27 02:15:35.505 UTC [29160][client backend] [005_log_duration_destination.pl][5/2:0] STATEMENT:  SELECT E2E2
# '
#           matches '(?^:SELECT 2222)'
[02:15:35.512](0.000s) ok 16 - Error statements do NOT get written to the duration CSV log file
t
3333
psql:<stdin>:1: ERROR:  column "e3e3" does not exist
LINE 1: SELECT E3E3
               ^
[02:15:35.804](0.292s) ok 17 - found expected log file content for stderr
[02:15:35.804](0.000s) not ok 18 - Duration JSON log file gets added to list on reload
[02:15:35.805](0.000s) 
[02:15:35.805](0.000s) #   Failed test 'Duration JSON log file gets added to list on reload'
#   at t/005_log_duration_destination.pl line 127.
[02:15:35.805](0.000s) not ok 19 - Duration statements are written to the duration JSON log file
[02:15:35.805](0.000s) 
[02:15:35.805](0.000s) #   Failed test 'Duration statements are written to the duration JSON log file'
#   at t/005_log_duration_destination.pl line 130.
[02:15:35.805](0.000s) #                   undef
#     doesn't match '(?^:SELECT 3333)'
[02:15:35.805](0.000s) not ok 20 - Duration statements do NOT get written to the normal stderr log file
[02:15:35.805](0.000s) 
[02:15:35.805](0.000s) #   Failed test 'Duration statements do NOT get written to the normal stderr log file'
#   at t/005_log_duration_destination.pl line 134.
[02:15:35.805](0.000s) #                   '2024-07-27 02:15:35.378 UTC [29144][client backend] [005_log_duration_destination.pl][3/0:0] LOG:  duration: 13.007 ms  statement: SELECT pg_reload_conf()
# 2024-07-27 02:15:35.383 UTC [29144][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.021 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.442 UTC [29153][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.447 UTC [29153][client backend] [[unknown]][4/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.448 UTC [29153][client backend] [[unknown]][4/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.454 UTC,"postgres","postgres",29153,"[local]",66a45847.71e1,4,"SELECT",2024-07-27 02:15:35 UTC,4/0,0,LOG,00000,"duration: 0.601 ms  statement: SELECT 2222",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# 2024-07-27 02:15:35.458 UTC [29153][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.017 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.500 UTC [29160][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.501 UTC [29160][client backend] [[unknown]][5/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.501 UTC [29160][client backend] [[unknown]][5/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.505 UTC [29160][client backend] [005_log_duration_destination.pl][5/2:0] ERROR:  column "e2e2" does not exist at character 8
# 2024-07-27 02:15:35.505 UTC [29160][client backend] [005_log_duration_destination.pl][5/2:0] STATEMENT:  SELECT E2E2
# 2024-07-27 02:15:35.514 UTC [29160][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.014 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.566 UTC [29168][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.568 UTC [29168][client backend] [[unknown]][6/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.571 UTC [29168][client backend] [[unknown]][6/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.577 UTC,"postgres","postgres",29168,"[local]",66a45847.71f0,4,"ALTER SYSTEM",2024-07-27 02:15:35 UTC,6/0,0,LOG,00000,"duration: 0.630 ms  statement: ALTER SYSTEM SET log_duration_destination='csvlog, jsonlog'",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# 2024-07-27 02:15:35.591 UTC [29168][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.026 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.621 UTC [29175][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.623 UTC [29175][client backend] [[unknown]][7/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.623 UTC [29175][client backend] [[unknown]][7/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.626 UTC [29085][postmaster] LOG:  received SIGHUP, reloading configuration files
# 2024-07-27 02:15:35.627 UTC [29085][postmaster] LOG:  parameter "log_duration_destination" changed to "csvlog, jsonlog"
# 2024-07-27 02:15:35.633 UTC,"postgres","postgres",29175,"[local]",66a45847.71f7,4,"SELECT",2024-07-27 02:15:35 UTC,7/0,0,LOG,00000,"duration: 7.633 ms  statement: SELECT pg_reload_conf()",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# 2024-07-27 02:15:35.651 UTC [29175][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.029 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.695 UTC [29185][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.696 UTC [29185][client backend] [[unknown]][8/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.696 UTC [29185][client backend] [[unknown]][8/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.699 UTC,"postgres","postgres",29185,"[local]",66a45847.7201,4,"SELECT",2024-07-27 02:15:35 UTC,8/0,0,LOG,00000,"duration: 0.521 ms  statement: SELECT 3333",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# {"timestamp":"2024-07-27 02:15:35.699 UTC","user":"postgres","dbname":"postgres","pid":29185,"remote_host":"[local]","session_id":"66a45847.7201","line_num":4,"ps":"SELECT","session_start":"2024-07-27 02:15:35 UTC","vxid":"8/0","txid":0,"error_severity":"LOG","message":"duration: 0.521 ms  statement: SELECT 3333","application_name":"005_log_duration_destination.pl","backend_type":"client backend","query_id":0}
# 2024-07-27 02:15:35.704 UTC [29185][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.009 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.787 UTC [29191][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.788 UTC [29191][client backend] [[unknown]][9/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.788 UTC [29191][client backend] [[unknown]][9/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.799 UTC [29191][client backend] [005_log_duration_destination.pl][9/2:0] ERROR:  column "e3e3" does not exist at character 8
# 2024-07-27 02:15:35.799 UTC [29191][client backend] [005_log_duration_destination.pl][9/2:0] STATEMENT:  SELECT E3E3
# 2024-07-27 02:15:35.803 UTC [29191][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.021 user=postgres database=postgres host=[local]
# '
#           matches '(?^:SELECT 3333)'
[02:15:35.805](0.000s) ok 21 - Error statements do NOT get written to the duration JSON log file
t
4444
psql:<stdin>:1: ERROR:  column "e4e4" does not exist
LINE 1: SELECT E4E4
               ^
[02:15:36.093](0.288s) ok 22 - found expected log file content for stderr
[02:15:36.093](0.000s) not ok 23 - Duration stderr log file gets added to list on reload
[02:15:36.094](0.000s) 
[02:15:36.094](0.000s) #   Failed test 'Duration stderr log file gets added to list on reload'
#   at t/005_log_duration_destination.pl line 152.
[02:15:36.094](0.000s) not ok 24 - Duration CSV log file gets added to list on reload
[02:15:36.094](0.000s) 
[02:15:36.094](0.000s) #   Failed test 'Duration CSV log file gets added to list on reload'
#   at t/005_log_duration_destination.pl line 155.
[02:15:36.094](0.000s) not ok 25 - Duration JSON log file gets added to list on reload
[02:15:36.094](0.000s) 
[02:15:36.094](0.000s) #   Failed test 'Duration JSON log file gets added to list on reload'
#   at t/005_log_duration_destination.pl line 158.
[02:15:36.094](0.000s) not ok 26 - Duration statements are written to the duration stderr log file
[02:15:36.095](0.000s) 
[02:15:36.095](0.000s) #   Failed test 'Duration statements are written to the duration stderr log file'
#   at t/005_log_duration_destination.pl line 161.
[02:15:36.095](0.000s) #                   undef
#     doesn't match '(?^:SELECT 4444)'
[02:15:36.095](0.000s) not ok 27 - Duration statements are written to the duration CSV log file
[02:15:36.095](0.000s) 
[02:15:36.095](0.000s) #   Failed test 'Duration statements are written to the duration CSV log file'
#   at t/005_log_duration_destination.pl line 164.
[02:15:36.095](0.000s) #                   undef
#     doesn't match '(?^:SELECT 4444)'
[02:15:36.095](0.000s) not ok 28 - Duration statements are written to the duration JSON log file
[02:15:36.095](0.000s) 
[02:15:36.095](0.000s) #   Failed test 'Duration statements are written to the duration JSON log file'
#   at t/005_log_duration_destination.pl line 167.
[02:15:36.095](0.000s) #                   undef
#     doesn't match '(?^:SELECT 4444)'
[02:15:36.096](0.000s) not ok 29 - Duration statements do NOT get written to the normal stderr log file
[02:15:36.096](0.000s) 
[02:15:36.096](0.000s) #   Failed test 'Duration statements do NOT get written to the normal stderr log file'
#   at t/005_log_duration_destination.pl line 171.
[02:15:36.096](0.000s) #                   '2024-07-27 02:15:35.378 UTC [29144][client backend] [005_log_duration_destination.pl][3/0:0] LOG:  duration: 13.007 ms  statement: SELECT pg_reload_conf()
# 2024-07-27 02:15:35.383 UTC [29144][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.021 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.442 UTC [29153][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.447 UTC [29153][client backend] [[unknown]][4/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.448 UTC [29153][client backend] [[unknown]][4/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.454 UTC,"postgres","postgres",29153,"[local]",66a45847.71e1,4,"SELECT",2024-07-27 02:15:35 UTC,4/0,0,LOG,00000,"duration: 0.601 ms  statement: SELECT 2222",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# 2024-07-27 02:15:35.458 UTC [29153][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.017 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.500 UTC [29160][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.501 UTC [29160][client backend] [[unknown]][5/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.501 UTC [29160][client backend] [[unknown]][5/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.505 UTC [29160][client backend] [005_log_duration_destination.pl][5/2:0] ERROR:  column "e2e2" does not exist at character 8
# 2024-07-27 02:15:35.505 UTC [29160][client backend] [005_log_duration_destination.pl][5/2:0] STATEMENT:  SELECT E2E2
# 2024-07-27 02:15:35.514 UTC [29160][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.014 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.566 UTC [29168][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.568 UTC [29168][client backend] [[unknown]][6/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.571 UTC [29168][client backend] [[unknown]][6/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.577 UTC,"postgres","postgres",29168,"[local]",66a45847.71f0,4,"ALTER SYSTEM",2024-07-27 02:15:35 UTC,6/0,0,LOG,00000,"duration: 0.630 ms  statement: ALTER SYSTEM SET log_duration_destination='csvlog, jsonlog'",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# 2024-07-27 02:15:35.591 UTC [29168][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.026 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.621 UTC [29175][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.623 UTC [29175][client backend] [[unknown]][7/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.623 UTC [29175][client backend] [[unknown]][7/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.626 UTC [29085][postmaster] LOG:  received SIGHUP, reloading configuration files
# 2024-07-27 02:15:35.627 UTC [29085][postmaster] LOG:  parameter "log_duration_destination" changed to "csvlog, jsonlog"
# 2024-07-27 02:15:35.633 UTC,"postgres","postgres",29175,"[local]",66a45847.71f7,4,"SELECT",2024-07-27 02:15:35 UTC,7/0,0,LOG,00000,"duration: 7.633 ms  statement: SELECT pg_reload_conf()",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# 2024-07-27 02:15:35.651 UTC [29175][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.029 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.695 UTC [29185][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.696 UTC [29185][client backend] [[unknown]][8/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.696 UTC [29185][client backend] [[unknown]][8/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.699 UTC,"postgres","postgres",29185,"[local]",66a45847.7201,4,"SELECT",2024-07-27 02:15:35 UTC,8/0,0,LOG,00000,"duration: 0.521 ms  statement: SELECT 3333",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# {"timestamp":"2024-07-27 02:15:35.699 UTC","user":"postgres","dbname":"postgres","pid":29185,"remote_host":"[local]","session_id":"66a45847.7201","line_num":4,"ps":"SELECT","session_start":"2024-07-27 02:15:35 UTC","vxid":"8/0","txid":0,"error_severity":"LOG","message":"duration: 0.521 ms  statement: SELECT 3333","application_name":"005_log_duration_destination.pl","backend_type":"client backend","query_id":0}
# 2024-07-27 02:15:35.704 UTC [29185][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.009 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.787 UTC [29191][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.788 UTC [29191][client backend] [[unknown]][9/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.788 UTC [29191][client backend] [[unknown]][9/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.799 UTC [29191][client backend] [005_log_duration_destination.pl][9/2:0] ERROR:  column "e3e3" does not exist at character 8
# 2024-07-27 02:15:35.799 UTC [29191][client backend] [005_log_duration_destination.pl][9/2:0] STATEMENT:  SELECT E3E3
# 2024-07-27 02:15:35.803 UTC [29191][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.021 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.849 UTC [29201][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.854 UTC [29201][client backend] [[unknown]][10/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.854 UTC [29201][client backend] [[unknown]][10/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.860 UTC,"postgres","postgres",29201,"[local]",66a45847.7211,4,"ALTER SYSTEM",2024-07-27 02:15:35 UTC,10/0,0,LOG,00000,"duration: 0.649 ms  statement: ALTER SYSTEM SET log_duration_destination='csvlog, stderr, jsonlog'",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# {"timestamp":"2024-07-27 02:15:35.860 UTC","user":"postgres","dbname":"postgres","pid":29201,"remote_host":"[local]","session_id":"66a45847.7211","line_num":4,"ps":"ALTER SYSTEM","session_start":"2024-07-27 02:15:35 UTC","vxid":"10/0","txid":0,"error_severity":"LOG","message":"duration: 0.649 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:15:35.875 UTC [29201][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.026 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.934 UTC [29212][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:35.936 UTC [29212][client backend] [[unknown]][11/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:35.936 UTC [29212][client backend] [[unknown]][11/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:35.949 UTC,"postgres","postgres",29212,"[local]",66a45847.721c,4,"SELECT",2024-07-27 02:15:35 UTC,11/0,0,LOG,00000,"duration: 0.933 ms  statement: SELECT pg_reload_conf()",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# {"timestamp":"2024-07-27 02:15:35.949 UTC","user":"postgres","dbname":"postgres","pid":29212,"remote_host":"[local]","session_id":"66a45847.721c","line_num":4,"ps":"SELECT","session_start":"2024-07-27 02:15:35 UTC","vxid":"11/0","txid":0,"error_severity":"LOG","message":"duration: 0.933 ms  statement: SELECT pg_reload_conf()","application_name":"005_log_duration_destination.pl","backend_type":"client backend","query_id":0}
# 2024-07-27 02:15:35.950 UTC [29085][postmaster] LOG:  received SIGHUP, reloading configuration files
# 2024-07-27 02:15:35.950 UTC [29212][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.022 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:35.951 UTC [29085][postmaster] LOG:  parameter "log_duration_destination" changed to "csvlog, stderr, jsonlog"
# 2024-07-27 02:15:36.003 UTC [29224][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:36.005 UTC [29224][client backend] [[unknown]][12/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:36.008 UTC [29224][client backend] [[unknown]][12/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:36.018 UTC,"postgres","postgres",29224,"[local]",66a45848.7228,4,"SELECT",2024-07-27 02:15:36 UTC,12/0,0,LOG,00000,"duration: 0.701 ms  statement: SELECT 4444",,,,,,,,,"005_log_duration_destination.pl","client backend",,0
# {"timestamp":"2024-07-27 02:15:36.018 UTC","user":"postgres","dbname":"postgres","pid":29224,"remote_host":"[local]","session_id":"66a45848.7228","line_num":4,"ps":"SELECT","session_start":"2024-07-27 02:15:36 UTC","vxid":"12/0","txid":0,"error_severity":"LOG","message":"duration: 0.701 ms  statement: SELECT 4444","application_name":"005_log_duration_destination.pl","backend_type":"client backend","query_id":0}
# 2024-07-27 02:15:36.018 UTC [29224][client backend] [005_log_duration_destination.pl][12/0:0] LOG:  duration: 0.701 ms  statement: SELECT 4444
# 2024-07-27 02:15:36.025 UTC [29224][client backend] [005_log_duration_destination.pl][:0] LOG:  disconnection: session time: 0:00:00.023 user=postgres database=postgres host=[local]
# 2024-07-27 02:15:36.084 UTC [29236][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
# 2024-07-27 02:15:36.086 UTC [29236][client backend] [[unknown]][13/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/t_005_log_duration_destination_primary_data/pgdata/pg_hba.conf:117)
# 2024-07-27 02:15:36.086 UTC [29236][client backend] [[unknown]][13/1:0] LOG:  connection authorized: user=postgres database=postgres application_name=005_log_duration_destination.pl
# 2024-07-27 02:15:36.089 UTC [29236][client backend] [005_log_duration_destination.pl][13/2:0] ERROR:  column "e4e4" does not exist at character 8
# 2024-07-27 02:15:36.089 UTC [29236][client backend] [005_log_duration_destination.pl][13/2:0] STATEMENT:  SELECT E4E4
# '
#           matches '(?^:SELECT 4444)'
[02:15:36.096](0.000s) ok 30 - Error statements do NOT get written to the duration stderr log file
[02:15:36.096](0.000s) ok 31 - Error statements do NOT get written to the duration CSV log file
[02:15:36.096](0.000s) ok 32 - Error statements do NOT get written to the duration JSON log file
t
[02:15:38.176](2.080s) ok 33 - Log file has rotated to a new name (type=csvlog)
[02:15:38.176](0.000s) ok 34 - Log file has rotated to a new name (type=jsonlog)
[02:15:38.177](0.000s) ok 35 - Log file has rotated to a new name (type=stderr)
t
5555
psql:<stdin>:1: ERROR:  column "e5e5" does not exist
LINE 1: SELECT E5E5
               ^
[02:15:38.543](0.366s) ok 36 - found expected log file content for stderr
[02:15:38.543](0.000s) ok 37 - Duration stderr gets removed from list on reload
[02:15:38.544](0.000s) ok 38 - Duration CSV gets removed from list on reload
[02:15:38.544](0.000s) ok 39 - Duration JSON gets removed from list on reload
[02:15:38.544](0.000s) ok 40 - Duration statements are written to the normal stderr log file
[02:15:38.544](0.000s) 1..40
### Stopping node "primary" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/src/bin/pg_ctl/tmp_check/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:15:38.659](0.115s) # Looks like you failed 13 tests of 40.