log_connections stopped being a boolean

A setting that changed type

Most of the settings in a PostgreSQL configuration file have held the same type since they were introduced. A number stays a number, a boolean stays a boolean, and the tooling that reads them can be written once. That stability is why configuration management for PostgreSQL tends to be thin: a template, a few values, and an assertion or two that the values are what the template said.

In 18, one of the more commonly asserted settings changed type. The switch that controls whether connections are logged used to be a boolean, and it now takes a list of the stages you want logged. The old spellings are still accepted for compatibility, which is generous and is also the reason this change is quiet rather than loud: writing the old value works, and reading it back gets you something that is not the old value.

What each server thinks the setting is

SELECT name, vartype, setting, boot_val FROM pg_settings WHERE name = 'log_connections';

      name       | vartype | setting | boot_val 
-----------------+---------+---------+----------
 log_connections | bool    | off     | off
(1 row)

On 17 it is a boolean whose value and default are both off. On 18:

      name       | vartype | setting | boot_val 
-----------------+---------+---------+----------
 log_connections | string  |         | 
(1 row)

A string, and both the value and the default are empty. Not the word off, not a null the type system would let you test for. An empty list, rendered as nothing at all, because no stages are being logged.

That difference is the whole of the breakage, and it is worth seeing in the form an assertion actually takes.

SELECT current_setting('log_connections') = 'off' AS the_usual_assertion_passes;

 the_usual_assertion_passes 
----------------------------
 t
(1 row)

On 17 that is true. On 18:

 the_usual_assertion_passes 
----------------------------
 f
(1 row)

The check that has been passing for years now fails, on a cluster where connection logging is off exactly as intended. Whether that matters depends entirely on what your tooling does with a failed assertion. A configuration run that reports drift and stops is the good case: somebody looks, works it out in ten minutes, and moves on. A configuration run that corrects drift by writing the value it expected is the case to worry about, because it will write the old boolean into the configuration file on every run, forever, and nothing will ever converge.

There is a second flavour of the same problem in monitoring rather than configuration. A dashboard panel that displays the connection-logging state, or an audit report that lists security-relevant settings and their values, now has a blank where it used to have a word. A reviewer reading that report sees an empty cell and has no way to tell whether the setting is off or the collection is broken.

Writing the new values on the old version

The compatibility runs one way only. A 17 server rejects the new vocabulary outright.

ALTER SYSTEM SET log_connections = 'setup_durations';

ERROR:  parameter "log_connections" requires a Boolean value

That error message is the single most useful thing on this page for anyone managing a mixed fleet, because it is what a rollout of a new configuration template hits the first time it touches a cluster that has not been upgraded yet. It is loud, it names the setting, and it stops the configuration from being written. A template that carries the new vocabulary is not deployable to older majors, and there is no spelling that works on both and means the new thing.

In the other direction the old vocabulary is accepted.

ALTER SYSTEM SET log_connections = 'on';
SELECT pg_reload_conf();
SELECT pg_sleep(1);
SHOW log_connections;

ALTER SYSTEM
 pg_reload_conf 
----------------
 t
(1 row)

 pg_sleep 
----------
 
(1 row)

 log_connections 
-----------------
 off
(1 row)

On 17 that reads back as off, because the setting is written to the configuration file and the running session was started before the reload, which is its own well-known nuisance and not what this page is about. On 18:

ALTER SYSTEM
 pg_reload_conf 
----------------
 t
(1 row)

 pg_sleep 
----------
 
(1 row)

 log_connections 
-----------------
 
(1 row)

Blank again. The value was accepted, the reload happened, and what comes back is neither the word you wrote nor the list it maps to in the session that asked. The setting is one that takes effect at connection start, so the session doing the asking is reporting what was true when it connected, and on 18 what was true when it connected renders as an empty string rather than as off. Anything comparing the readback to what it wrote will disagree on both versions, for different reasons, and only one of those reasons is new.

What the new stages are actually for

The list takes four stage names and a catch-all. Three of them correspond to things the old boolean logged: the moment the connection was received, the moment the user was authenticated, and the moment the session was authorized against a database. Turning the old boolean on gave you all three and no way to ask for fewer.

The fourth is new and is the reason to care about any of this.

ALTER SYSTEM SET log_connections = 'all';
SELECT pg_reload_conf();
SELECT pg_sleep(1);
CREATE EXTENSION dblink;
SELECT dblink_connect('newcomer', 'dbname=' || current_database());
SELECT dblink_disconnect('newcomer');
SELECT pg_sleep(1);
SELECT regexp_replace(line, '^.* UTC \[[0-9]+\] LOG:  ', '') AS logged
FROM (
  SELECT line, n
  FROM regexp_split_to_table(pg_read_file('log/postgresql.log'), E'\n') WITH ORDINALITY AS t(line, n)
  WHERE line LIKE '%connection %'
  ORDER BY n DESC
  LIMIT 4
) AS recent
ORDER BY n;

ALTER SYSTEM
 pg_reload_conf 
----------------
 t
(1 row)

 pg_sleep 
----------
 
(1 row)

CREATE EXTENSION
 dblink_connect 
----------------
 OK
(1 row)

 dblink_disconnect 
-------------------
 OK
(1 row)

 pg_sleep 
----------
 
(1 row)

                                                 logged                                                 
--------------------------------------------------------------------------------------------------------
 connection received: host=[local]
 connection authenticated: user="postgres" method=trust (/var/lib/postgresql/18/docker/pg_hba.conf:117)
 connection authorized: user=postgres database=dbx_18_log_connections_aspects
 connection ready: setup total=3.473 ms, fork=0.546 ms, authentication=0.171 ms
(4 rows)

Four lines for one connection, the last of which did not exist before. It reports how long establishing the connection took in total, and splits that total into the time spent creating the backend process and the time spent authenticating the user.

That measurement has been inferred from the client side for as long as PostgreSQL has existed, and inferring it is unsatisfying in a specific way: the client sees the round trip, which includes the network, the pooler if there is one, and the server, and it cannot attribute a slow connection to any of them. The server now reports its own share. On the local socket above the whole thing took a few milliseconds and the split is uninteresting. On a cluster where authentication involves a directory server over a network, the authentication component is frequently the entire story, and it is the component that fails first when the directory is having a bad day.

Two practical notes. The authentication line names the configuration file and the line number of the rule that matched, which is the fastest way to answer why a connection was accepted by one rule rather than another. And the durations line appears only when its stage is requested, so a log parser has to treat its absence as unknown rather than as zero.

What to do before the upgrade

• Find every assertion that compares this setting to a boolean. In a configuration repository they are easy to grep for. In a monitoring stack they hide in panel expressions and in the query that builds the settings audit.
• Decide whether you want the durations. They are the one new capability here, they cost a clock reading per connection, and on a workload that opens connections constantly rather than pooling them that is not free. On a pooled workload it is negligible and the measurement is worth having.
• If you log connections at all, consider asking for fewer stages than the old boolean gave you. Three lines per connection is a meaningful share of the log volume on a busy cluster, and this release is the first time you have had the option of keeping the one you read and dropping the two you do not.
• Check what your log shipper does with the new line before you enable it. A parser built around the three known shapes will usually pass an unrecognised one through, and occasionally will not.

Reading the durations line

The new line is the only reason to care about any of this, and it repays a little precision about what its three numbers mean.

The total is what it says: the interval from the server accepting the connection to the session being ready for queries. The two components are the time spent creating the backend process and the time spent authenticating the user, and the total is larger than their sum because it includes everything else, chiefly the work of attaching to the database and setting up the session.

Each component fails in a characteristic way. A slow process creation is a machine problem: memory pressure, a loaded scheduler, or a large shared memory mapping that every new process has to attach to. It gets worse for everyone at once and it does not depend on who is connecting. A slow authentication is almost always external: a directory server, a certificate check, or a password hashing scheme deliberately chosen to be expensive. It depends on the user and the method, and on a cluster with several authentication rules it can be slow for one application and instant for another.

Distinguishing those from the client side has never been possible, because the client sees one number that also contains the network and the pooler. This line is the server’s own accounting, and subtracting it from what the client measured leaves the part that is not the database, which is the number that settles an argument.

The workload that benefits most is the one that should not be connecting so often in the first place. An application opening a connection per request pays this cost thousands of times a minute, and the durations line turns a vague case for connection pooling into an arithmetic one: multiply the total by the connection rate and you have the share of the cluster’s time spent on establishment rather than on queries. That figure is usually larger than anyone expects and it is the most persuasive thing this release gives an operator arguing for a pooler.

What it costs

The stages themselves cost what connection logging has always cost, which is a log line per connection per stage, and on a cluster that opens thousands of connections a minute that is the dominant term in the log volume rather than a rounding error.

The setting can be changed with a reload and takes effect for connections established afterwards, so there is no restart and no window. Existing sessions keep whatever was in force when they connected, which is the behaviour the readback above demonstrates and is worth remembering when a change appears not to have taken.