Re: logical replication: could not create file "state.tmp": File exists

On 12/2/19 7:12 PM, Andres Freund wrote:
> Hi,
>
> On 2019-11-30 15:09:39 +0300, Grigory Smolkin wrote:
>> One of my colleagues encountered an out of space condition, which broke his
>> logical replication setup.
>> It`s manifested with the following errors:
>>
>> ERROR:  could not receive data from WAL stream: ERROR:  could not create
>> file "pg_replslot/some_sub/state.tmp": File exists
> Hm. What was the log output leading to this state? Some cases of this
> would end up in a PANIC, which'd remove the .tmp file during
> recovery. But there's some where we won't - it seems the right fix for
> this would be to unlink the tmp file in that case?
>
>
>> I`ve digged a bit into this problem, and it`s turned out that in
>> SaveSlotToPath() temp file for replication slot is opened with 'O_CREAT |
>> O_EXCL' flags, which makes this routine as not very reentrant.
>>
>> Since an exclusive lock is taken before temp file creation, I think it
>> should be safe to replace O_EXCL with O_TRUNC.
> I'm very doubtful about this. I think it's a good safety measure to
> ensure that there's no previous state file that we're somehow
> overwriting.
>
>
>> Script to reproduce and patch are attached.
> Well:
>
>> # Imitate out_of_space/write_operation_error
>> touch ${PGDATA_PUB}/pg_replslot/mysub/state.tmp
> Doesn't really replicate how we got into this state...


I`ve managed to reproduce the issue using the attached script:

2019-12-02 20:32:12.547 MSK [4180] ERROR:  could not write to file 
"pg_logical/snapshots/0-160E9A28.snap.4180.tmp": No space left on device
2019-12-02 20:32:12.548 MSK [4178] ERROR:  could not receive data from 
WAL stream: ERROR:  could not write to file 
"pg_logical/snapshots/0-160E9A28.snap.4180.tmp": No space left on device
2019-12-02 20:32:12.557 MSK [4645] LOG:  logical replication apply 
worker for subscription "mysub" has started
2019-12-02 20:32:12.562 MSK [4091] LOG:  background worker "logical 
replication worker" (PID 4178) exited with exit code 1
2019-12-02 20:32:12.569 MSK [4648] LOG:  starting logical decoding for 
slot "mysub"
2019-12-02 20:32:12.569 MSK [4648] DETAIL:  Streaming transactions 
committing after 0/160E9A28, reading WAL from 0/1566A2D8.
2019-12-02 20:32:12.569 MSK [4648] LOG:  logical decoding found 
consistent point at 0/1566A2D8
2019-12-02 20:32:12.569 MSK [4648] DETAIL:  Logical decoding will begin 
using saved snapshot.
2019-12-02 20:32:12.672 MSK [4648] ERROR:  could not write to file 
"pg_replslot/mysub/state.tmp": No space left on device
2019-12-02 20:32:12.672 MSK [4645] ERROR:  could not receive data from 
WAL stream: ERROR:  could not write to file 
"pg_replslot/mysub/state.tmp": No space left on device
2019-12-02 20:32:12.672 MSK [4091] LOG:  background worker "logical 
replication worker" (PID 4645) exited with exit code 1
2019-12-02 20:32:17.684 MSK [4653] LOG:  logical replication apply 
worker for subscription "mysub" has started
2019-12-02 20:32:17.693 MSK [4654] LOG:  starting logical decoding for 
slot "mysub"
2019-12-02 20:32:17.693 MSK [4654] DETAIL:  Streaming transactions 
committing after 0/160E9A28, reading WAL from 0/1566A2D8.
2019-12-02 20:32:17.693 MSK [4654] LOG:  logical decoding found 
consistent point at 0/1566A2D8
2019-12-02 20:32:17.693 MSK [4654] DETAIL:  Logical decoding will begin 
using saved snapshot.
2019-12-02 20:32:17.847 MSK [4654] ERROR:  could not write to file 
"pg_logical/snapshots/0-160E9A28.snap.4654.tmp": No space left on device
2019-12-02 20:32:17.847 MSK [4653] ERROR:  could not receive data from 
WAL stream: ERROR:  could not write to file 
"pg_logical/snapshots/0-160E9A28.snap.4654.tmp": No space left on device
2019-12-02 20:32:17.848 MSK [4091] LOG:  background worker "logical 
replication worker" (PID 4653) exited with exit code 1
2019-12-02 20:32:22.859 MSK [4658] LOG:  logical replication apply 
worker for subscription "mysub" has started
2019-12-02 20:32:22.868 MSK [4659] LOG:  starting logical decoding for 
slot "mysub"
2019-12-02 20:32:22.868 MSK [4659] DETAIL:  Streaming transactions 
committing after 0/160E9A28, reading WAL from 0/1566A2D8.
2019-12-02 20:32:22.868 MSK [4659] LOG:  logical decoding found 
consistent point at 0/1566A2D8
2019-12-02 20:32:22.868 MSK [4659] DETAIL:  Logical decoding will begin 
using saved snapshot.
2019-12-02 20:32:22.868 MSK [4659] ERROR:  could not create file 
"pg_replslot/mysub/state.tmp": File exists
2019-12-02 20:32:22.869 MSK [4658] ERROR:  could not receive data from 
WAL stream: ERROR:  could not create file "pg_replslot/mysub/state.tmp": 
File exists



>
> Greetings,
>
> Andres Freund

-- 
Grigory Smolkin
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company

#!/bin/bash

set -exu
set -o errexit

PREFIX=/home/gsmol/task/13_devel
PGDATA_PUB=/tmp/200MB/data_pub # created as: mkdir -p /tmp/200MB/ && sudo mount -t tmpfs -o size=200m tmpfs /tmp/200MB
PUB_WAL_DIR=/tmp/wal
PGDATA_SUB=${PREFIX}/data_sub
PORT_PUB=15431
PORT_SUB=15430

${PREFIX}/bin/pg_ctl stop -m immediate -D ${PGDATA_PUB} || echo "all is well"
${PREFIX}/bin/pg_ctl stop -m immediate -D ${PGDATA_SUB} || echo "all is well"
rm -rf ${PGDATA_PUB} ${PGDATA_SUB} ${PUB_WAL_DIR}

${PREFIX}/bin/initdb -k -D ${PGDATA_PUB} -X ${PUB_WAL_DIR}
echo "port = ${PORT_PUB}" >> ${PGDATA_PUB}/postgresql.auto.conf
echo "wal_level = logical" >> ${PGDATA_PUB}/postgresql.auto.conf
echo "autovacuum = off" >> ${PGDATA_PUB}/postgresql.auto.conf

${PREFIX}/bin/initdb -k -D ${PGDATA_SUB}
echo "port = ${PORT_SUB}" >> ${PGDATA_SUB}/postgresql.auto.conf

# start publisher cluster
${PREFIX}/bin/pg_ctl start -D ${PGDATA_PUB}

# start subscriber cluster
${PREFIX}/bin/pg_ctl start -D ${PGDATA_SUB}

# generate some data
${PREFIX}/bin/pgbench -i -s 9 -p ${PORT_PUB} postgres

# PUBLICATION
${PREFIX}/bin/psql -p ${PORT_PUB} -d postgres -c "CREATE PUBLICATION mypub FOR table pgbench_accounts"

# SUBSCRIPTION
${PREFIX}/bin/psql -p ${PORT_SUB} -d postgres -c "CREATE TABLE pgbench_accounts(aid int not null PRIMARY KEY, bid int,abalance int,filler char(84))"
${PREFIX}/bin/psql -p ${PORT_SUB} -d postgres -c "CREATE SUBSCRIPTION mysub CONNECTION 'host=localhost port=${PORT_PUB} dbname=postgres' PUBLICATION mypub"

# emulate out of space
mkdir ${PGDATA_PUB}/somedir
cp -av ${PUB_WAL_DIR} ${PGDATA_PUB}/somedir || echo "we should get empty state.tmp \
at the next launch of synchronization worker from replica"