[Bug]: Lock condition when trying to create database from a template

[itroot]

What type of bug is this?

Locking issue

What subsystems and features are affected?

Background worker

What happened?

I tried to create a database from the template, and instead of that I'm getting an error:

ERROR:  source database "postgres" is being accessed by other users
DETAIL:  There is 1 other session using the database.

Command that gets an error is: psql "host=localhost user=postgres password=postgres dbname=postgres port=5432 sslmode=disable" -c 'CREATE DATABASE test_42 WITH template = postgres;'

Notes

Workaround 1

It is possible to make it work via artificial delay in the beginning of the query:

# this works (note SELECT 1;)
ivan@bbox:~$ psql "host=localhost user=postgres password=postgres dbname=postgres port=5432 sslmode=disable" -c 'SELECT 1;' -c 'CREATE DATABASE test_42 WITH template = postgres;' 
 ?column? 
----------
        1
(1 row)

CREATE DATABASE
ivan@bbox:~$ 

Workaround 2

It works if postgres started with -c timescaledb.max_background_workers=0

TimescaleDB version affected

2.5.1

PostgreSQL version used

14

What operating system did you use?

Ubuntu 21.04 x64

What installation method did you use?

Docker

What platform did you run on?

Not applicable

Relevant log output and stack trace

Locks observed


ivan@bbox:~$ psql -x "host=localhost user=postgres password=postgres dbname=template1 port=5432 sslmode=disable" -c "SELECT * FROM pg_locks l JOIN pg_stat_activity a ON a.pid = l.pid;" | cat
-[ RECORD 1 ]------+-------------------------------------------------------------------
locktype           | relation
database           | 1
relation           | 12435
page               | 
tuple              | 
virtualxid         | 
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 7/30
pid                | 214
mode               | AccessShareLock
granted            | t
fastpath           | t
waitstart          | 
datid              | 1
datname            | template1
pid                | 214
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | psql
client_addr        | 172.17.0.1
client_hostname    | 
client_port        | 42990
backend_start      | 2022-02-02 12:54:22.819702+00
xact_start         | 2022-02-02 12:54:22.823572+00
query_start        | 2022-02-02 12:54:22.823572+00
state_change       | 2022-02-02 12:54:22.823573+00
wait_event_type    | 
wait_event         | 
state              | active
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | SELECT * FROM pg_locks l JOIN pg_stat_activity a ON a.pid = l.pid;
backend_type       | client backend
-[ RECORD 2 ]------+-------------------------------------------------------------------
locktype           | relation
database           | 1
relation           | 12290
page               | 
tuple              | 
virtualxid         | 
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 7/30
pid                | 214
mode               | AccessShareLock
granted            | t
fastpath           | t
waitstart          | 
datid              | 1
datname            | template1
pid                | 214
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | psql
client_addr        | 172.17.0.1
client_hostname    | 
client_port        | 42990
backend_start      | 2022-02-02 12:54:22.819702+00
xact_start         | 2022-02-02 12:54:22.823572+00
query_start        | 2022-02-02 12:54:22.823572+00
state_change       | 2022-02-02 12:54:22.823573+00
wait_event_type    | 
wait_event         | 
state              | active
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | SELECT * FROM pg_locks l JOIN pg_stat_activity a ON a.pid = l.pid;
backend_type       | client backend
-[ RECORD 3 ]------+-------------------------------------------------------------------
locktype           | virtualxid
database           | 
relation           | 
page               | 
tuple              | 
virtualxid         | 7/30
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 7/30
pid                | 214
mode               | ExclusiveLock
granted            | t
fastpath           | t
waitstart          | 
datid              | 1
datname            | template1
pid                | 214
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | psql
client_addr        | 172.17.0.1
client_hostname    | 
client_port        | 42990
backend_start      | 2022-02-02 12:54:22.819702+00
xact_start         | 2022-02-02 12:54:22.823572+00
query_start        | 2022-02-02 12:54:22.823572+00
state_change       | 2022-02-02 12:54:22.823573+00
wait_event_type    | 
wait_event         | 
state              | active
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | SELECT * FROM pg_locks l JOIN pg_stat_activity a ON a.pid = l.pid;
backend_type       | client backend
-[ RECORD 4 ]------+-------------------------------------------------------------------
locktype           | virtualxid
database           | 
relation           | 
page               | 
tuple              | 
virtualxid         | 4/18
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 4/18
pid                | 213
mode               | ExclusiveLock
granted            | t
fastpath           | t
waitstart          | 
datid              | 13756
datname            | postgres
pid                | 213
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | TimescaleDB Background Worker Scheduler
client_addr        | 
client_hostname    | 
client_port        | 
backend_start      | 2022-02-02 12:54:21.56695+00
xact_start         | 2022-02-02 12:54:21.567581+00
query_start        | 
state_change       | 
wait_event_type    | Lock
wait_event         | virtualxid
state              | 
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | 
backend_type       | TimescaleDB Background Worker Scheduler
-[ RECORD 5 ]------+-------------------------------------------------------------------
locktype           | relation
database           | 0
relation           | 1260
page               | 
tuple              | 
virtualxid         | 
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 7/30
pid                | 214
mode               | AccessShareLock
granted            | t
fastpath           | f
waitstart          | 
datid              | 1
datname            | template1
pid                | 214
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | psql
client_addr        | 172.17.0.1
client_hostname    | 
client_port        | 42990
backend_start      | 2022-02-02 12:54:22.819702+00
xact_start         | 2022-02-02 12:54:22.823572+00
query_start        | 2022-02-02 12:54:22.823572+00
state_change       | 2022-02-02 12:54:22.823573+00
wait_event_type    | 
wait_event         | 
state              | active
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | SELECT * FROM pg_locks l JOIN pg_stat_activity a ON a.pid = l.pid;
backend_type       | client backend
-[ RECORD 6 ]------+-------------------------------------------------------------------
locktype           | relation
database           | 0
relation           | 2672
page               | 
tuple              | 
virtualxid         | 
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 7/30
pid                | 214
mode               | AccessShareLock
granted            | t
fastpath           | f
waitstart          | 
datid              | 1
datname            | template1
pid                | 214
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | psql
client_addr        | 172.17.0.1
client_hostname    | 
client_port        | 42990
backend_start      | 2022-02-02 12:54:22.819702+00
xact_start         | 2022-02-02 12:54:22.823572+00
query_start        | 2022-02-02 12:54:22.823572+00
state_change       | 2022-02-02 12:54:22.823573+00
wait_event_type    | 
wait_event         | 
state              | active
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | SELECT * FROM pg_locks l JOIN pg_stat_activity a ON a.pid = l.pid;
backend_type       | client backend
-[ RECORD 7 ]------+-------------------------------------------------------------------
locktype           | relation
database           | 0
relation           | 2677
page               | 
tuple              | 
virtualxid         | 
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 7/30
pid                | 214
mode               | AccessShareLock
granted            | t
fastpath           | f
waitstart          | 
datid              | 1
datname            | template1
pid                | 214
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | psql
client_addr        | 172.17.0.1
client_hostname    | 
client_port        | 42990
backend_start      | 2022-02-02 12:54:22.819702+00
xact_start         | 2022-02-02 12:54:22.823572+00
query_start        | 2022-02-02 12:54:22.823572+00
state_change       | 2022-02-02 12:54:22.823573+00
wait_event_type    | 
wait_event         | 
state              | active
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | SELECT * FROM pg_locks l JOIN pg_stat_activity a ON a.pid = l.pid;
backend_type       | client backend
-[ RECORD 8 ]------+-------------------------------------------------------------------
locktype           | virtualxid
database           | 
relation           | 
page               | 
tuple              | 
virtualxid         | 6/83
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 6/83
pid                | 212
mode               | ExclusiveLock
granted            | t
fastpath           | f
waitstart          | 
datid              | 13756
datname            | postgres
pid                | 212
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | psql
client_addr        | 172.17.0.1
client_hostname    | 
client_port        | 42988
backend_start      | 2022-02-02 12:54:21.560066+00
xact_start         | 2022-02-02 12:54:21.564239+00
query_start        | 2022-02-02 12:54:21.564239+00
state_change       | 2022-02-02 12:54:21.56424+00
wait_event_type    | 
wait_event         | 
state              | active
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | CREATE DATABASE test_43 WITH template = postgres;
backend_type       | client backend
-[ RECORD 9 ]------+-------------------------------------------------------------------
locktype           | relation
database           | 0
relation           | 1262
page               | 
tuple              | 
virtualxid         | 
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 7/30
pid                | 214
mode               | AccessShareLock
granted            | t
fastpath           | f
waitstart          | 
datid              | 1
datname            | template1
pid                | 214
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | psql
client_addr        | 172.17.0.1
client_hostname    | 
client_port        | 42990
backend_start      | 2022-02-02 12:54:22.819702+00
xact_start         | 2022-02-02 12:54:22.823572+00
query_start        | 2022-02-02 12:54:22.823572+00
state_change       | 2022-02-02 12:54:22.823573+00
wait_event_type    | 
wait_event         | 
state              | active
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | SELECT * FROM pg_locks l JOIN pg_stat_activity a ON a.pid = l.pid;
backend_type       | client backend
-[ RECORD 10 ]-----+-------------------------------------------------------------------
locktype           | object
database           | 0
relation           | 
page               | 
tuple              | 
virtualxid         | 
transactionid      | 
classid            | 1262
objid              | 13756
objsubid           | 0
virtualtransaction | 6/83
pid                | 212
mode               | ShareLock
granted            | t
fastpath           | f
waitstart          | 
datid              | 13756
datname            | postgres
pid                | 212
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | psql
client_addr        | 172.17.0.1
client_hostname    | 
client_port        | 42988
backend_start      | 2022-02-02 12:54:21.560066+00
xact_start         | 2022-02-02 12:54:21.564239+00
query_start        | 2022-02-02 12:54:21.564239+00
state_change       | 2022-02-02 12:54:21.56424+00
wait_event_type    | 
wait_event         | 
state              | active
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | CREATE DATABASE test_43 WITH template = postgres;
backend_type       | client backend
-[ RECORD 11 ]-----+-------------------------------------------------------------------
locktype           | relation
database           | 0
relation           | 2676
page               | 
tuple              | 
virtualxid         | 
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 7/30
pid                | 214
mode               | AccessShareLock
granted            | t
fastpath           | f
waitstart          | 
datid              | 1
datname            | template1
pid                | 214
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | psql
client_addr        | 172.17.0.1
client_hostname    | 
client_port        | 42990
backend_start      | 2022-02-02 12:54:22.819702+00
xact_start         | 2022-02-02 12:54:22.823572+00
query_start        | 2022-02-02 12:54:22.823572+00
state_change       | 2022-02-02 12:54:22.823573+00
wait_event_type    | 
wait_event         | 
state              | active
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | SELECT * FROM pg_locks l JOIN pg_stat_activity a ON a.pid = l.pid;
backend_type       | client backend
-[ RECORD 12 ]-----+-------------------------------------------------------------------
locktype           | relation
database           | 0
relation           | 2671
page               | 
tuple              | 
virtualxid         | 
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 7/30
pid                | 214
mode               | AccessShareLock
granted            | t
fastpath           | f
waitstart          | 
datid              | 1
datname            | template1
pid                | 214
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | psql
client_addr        | 172.17.0.1
client_hostname    | 
client_port        | 42990
backend_start      | 2022-02-02 12:54:22.819702+00
xact_start         | 2022-02-02 12:54:22.823572+00
query_start        | 2022-02-02 12:54:22.823572+00
state_change       | 2022-02-02 12:54:22.823573+00
wait_event_type    | 
wait_event         | 
state              | active
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | SELECT * FROM pg_locks l JOIN pg_stat_activity a ON a.pid = l.pid;
backend_type       | client backend
-[ RECORD 13 ]-----+-------------------------------------------------------------------
locktype           | virtualxid
database           | 
relation           | 
page               | 
tuple              | 
virtualxid         | 6/83
transactionid      | 
classid            | 
objid              | 
objsubid           | 
virtualtransaction | 4/18
pid                | 213
mode               | ShareLock
granted            | f
fastpath           | f
waitstart          | 2022-02-02 12:54:21.568856+00
datid              | 13756
datname            | postgres
pid                | 213
leader_pid         | 
usesysid           | 10
usename            | postgres
application_name   | TimescaleDB Background Worker Scheduler
client_addr        | 
client_hostname    | 
client_port        | 
backend_start      | 2022-02-02 12:54:21.56695+00
xact_start         | 2022-02-02 12:54:21.567581+00
query_start        | 
state_change       | 
wait_event_type    | Lock
wait_event         | virtualxid
state              | 
backend_xid        | 
backend_xmin       | 750
query_id           | 
query              | 
backend_type       | TimescaleDB Background Worker Scheduler

ivan@bbox:~$ 

How can we reproduce the bug?

# cleaning up (optional step)
sudo service docker restart

# starting TiemscaleDB
docker run -p 5432:5432 -e POSTGRES_PASSWORD=postgres --name timescaledb --rm -d timescale/timescaledb:2.5.1-pg14

# waiting for it to become ready...
docker exec -it timescaledb bash -c 'c=0; while ! pg_isready; do ((c++)) && ((c==1000)) && exit 1; echo "Waiting for postgres ${c}00 ms..."; sleep 0.1; done;'

# trying to create database from the template
psql "host=localhost user=postgres password=postgres dbname=postgres port=5432 sslmode=disable" -c 'CREATE DATABASE test_42 WITH template = postgres;'

[nikkhils]

@itroot we are connecting to postgres database and then issuing this command CREATE DATABASE test_42 WITH template = postgres;

Note that the template DB to use is postgres itself. Kinda non-standard way of connecting to the same database and using it as a template as well. The documentation at https://www.postgresql.org/docs/current/manage-ag-templatedbs.html mentions:

The principal limitation is that no other sessions can be connected to the source database while it is being copied.

[itroot]

@nikkhils You will get the same with template1

ivan@bbox:~$ psql "host=localhost user=postgres password=postgres dbname=postgres port=5432 sslmode=disable" -c 'CREATE DATABASE test_42 WITH template = template1;'
ERROR:  source database "template1" is being accessed by other users
DETAIL:  There is 1 other session using the database.
ivan@bbox:~$ 

Also, -c timescaledb.max_background_workers=0 make it work (please see workarounds section). So it's not the postgres issue, it's related to timescaledb workers.

[wynnw]

I've seen this same thing in our test system once we added timescaledb into the postgresql.conf configuration (postgres 14). It's included in the shared_preload_libraries but not enabled on the database yet. We drop/restore databases in the test harness to get a clean environment, and sometimes get the same crash, and nothing seems to prevent it but the timescaledb.max_background_workers=0 setting.

[devanubis]

Just to chime in that this is still occurring in 2023 (latest docker images), and for our test environment the only mode of configuration available is setting environment variables, however the timescaledb-ha docker image doesn't support those environment variables 😿 (timescale/timescaledb-docker-ha#366)

[jnidzwetzki]

Hello @devanubis,

Thanks for reaching out. I was also able to reproduce this behavior with the most recent timescale/timescaledb:2.10.0-pg14 container image.

$ docker run -p 5432:5432 -e POSTGRES_PASSWORD=postgres --name timescaledb --rm -d timescale/timescaledb:2.10.0-pg14
$ docker exec -it timescaledb psql -U postgres

postgres=# CREATE DATABASE test_42 WITH template = template1;
ERROR:  source database "template1" is being accessed by other users
DETAIL:  There is 1 other session using the database.

postgres=# \c template1
You are now connected to database "template1" as user "postgres".
template1=# \dx
                                      List of installed extensions
    Name     | Version |   Schema   |                            Description                            
-------------+---------+------------+-------------------------------------------------------------------
 plpgsql     | 1.0     | pg_catalog | PL/pgSQL procedural language
 timescaledb | 2.10.0  | public     | Enables scalable inserts and complex queries for time-series data
(2 rows)

[rafales]

Running into similar issue. I'm creating a fresh database when running tests from the tempalte1 template. Often I get the error about the database being in use by someone else. I checked and it's the timescale db background worker.

[alechartung]

Anybody find a workaround? I'm running into this on DigitalOcean's managed PostgreSQL, where I don't even have superuser to try and kill it.

Edit: The workaround I went with was doing SELECT timescaledb_pre_restore(); in the template database, then SELECT timescaledb_post_restore(); in the newly created database.