001_rep_changes.pl succeeds after a long time - Mailing list pgsql-hackers

Hello,

I noticed that the test file 001_repo_changes.pl finished successfully
after having taken 180s to run.  This seems pretty suspicious --
normally that step takes around one second.

The problem is seen in this step:

[19:44:49.572](0.262s) ok 24 - update works with dropped subscriber column
### Stopping node "publisher" using mode fast
# Running: pg_ctl -D
/home/alvherre/Code/pgsql-build/master/src/test/subscription/tmp_check/t_001_rep_changes_publisher_data/pgdata-m fast
stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "publisher"
### Starting node "publisher"
# Running: pg_ctl -w -D
/home/alvherre/Code/pgsql-build/master/src/test/subscription/tmp_check/t_001_rep_changes_publisher_data/pgdata-l
/home/alvherre/Code/pgsql-build/master/src/test/subscription/tmp_check/log/001_rep_changes_publisher.log-o
--cluster-name=publisherstart
 
waiting for server to start.... done
server started
# Postmaster PID for node "publisher" is 3502228
Waiting for replication conn tap_sub's replay_lsn to pass 0/17DEBD8 on publisher
done
[19:47:50.689](181.116s) ok 25 - check replicated inserts after subscription publication change


Note that test 25 succeeded but took 3 minutes.  If I look at the
publisher logs, I see this:

2025-03-11 19:44:49.885 CET [3501892] 001_rep_changes.pl LOG:  statement: DELETE FROM tab_rep
2025-03-11 19:44:50.052 CET [3494694] LOG:  received fast shutdown request
2025-03-11 19:44:50.052 CET [3494694] LOG:  aborting any active transactions
2025-03-11 19:44:50.053 CET [3494694] LOG:  background worker "logical replication launcher" (PID 3494772) exited with
exitcode 1
 
2025-03-11 19:44:50.053 CET [3494755] LOG:  shutting down
2025-03-11 19:44:50.480 CET [3501776] tap_sub LOG:  released logical replication slot "tap_sub"
2025-03-11 19:44:50.484 CET [3494755] LOG:  checkpoint starting: shutdown immediate
2025-03-11 19:44:50.485 CET [3494755] LOG:  checkpoint complete: wrote 9 buffers (7.0%), wrote 3 SLRU buffers; 0 WAL
file(s)added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s,
average=0.000s; distance=579 kB, estimate=579 kB; lsn=0/17DEB60, redo lsn=0/17DEB60
 
2025-03-11 19:44:50.488 CET [3494694] LOG:  database system is shut down
2025-03-11 19:44:50.884 CET [3502228] LOG:  starting PostgreSQL 18devel on x86_64-pc-linux-gnu, compiled by gcc (Debian
12.2.0-14)12.2.0, 64-bit
 
2025-03-11 19:44:50.884 CET [3502228] LOG:  listening on Unix socket
"/run/user/1000/alvherre-tmp/i4fQURzady/.s.PGSQL.26529"
2025-03-11 19:44:50.886 CET [3502349] LOG:  database system was shut down at 2025-03-11 19:44:50 CET
2025-03-11 19:44:50.889 CET [3502228] LOG:  database system is ready to accept connections
2025-03-11 19:44:50.930 CET [3502395] 001_rep_changes.pl LOG:  statement: SELECT pg_is_in_recovery()
2025-03-11 19:44:50.945 CET [3502428] 001_rep_changes.pl LOG:  statement: SELECT pg_current_wal_lsn()
2025-03-11 19:44:50.960 CET [3502440] 001_rep_changes.pl LOG:  statement: SELECT '0/17DEBD8' <= replay_lsn AND state =
'streaming'
             FROM pg_catalog.pg_stat_replication
             WHERE application_name IN ('tap_sub', 'walreceiver')

The last query is repeated a number of times for 3 minutes, and finally we get this

2025-03-11 19:47:50.569 CET [3540762] 001_rep_changes.pl LOG:  statement: SELECT '0/17DEBD8' <= replay_lsn AND state =
'streaming'
             FROM pg_catalog.pg_stat_replication
             WHERE application_name IN ('tap_sub', 'walreceiver')
2025-03-11 19:47:50.596 CET [3540764] tap_sub LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2025-03-11 19:47:50.597 CET [3540764] tap_sub LOG:  received replication command: IDENTIFY_SYSTEM
2025-03-11 19:47:50.597 CET [3540764] tap_sub STATEMENT:  IDENTIFY_SYSTEM


Meanwhile, the subscriber has this:

2025-03-11 19:44:49.777 CET [3501647] LOG:  logical replication worker for subscription "tap_sub" will restart because
ofa parameter change
 
2025-03-11 19:44:49.785 CET [3501757] LOG:  logical replication apply worker for subscription "tap_sub" has started
2025-03-11 19:44:50.481 CET [3501757] LOG:  data stream from publisher has ended
2025-03-11 19:44:50.481 CET [3501757] ERROR:  could not send end-of-streaming message to primary: server closed the
connectionunexpectedly
 
        This probably means the server terminated abnormally
        before or while processing the request.
    no COPY in progress
2025-03-11 19:44:50.484 CET [3495251] LOG:  background worker "logical replication apply worker" (PID 3501757) exited
withexit code 1
 
2025-03-11 19:44:50.490 CET [3502088] LOG:  logical replication apply worker for subscription "tap_sub" has started
2025-03-11 19:44:50.490 CET [3502088] ERROR:  apply worker for subscription "tap_sub" could not connect to the
publisher:connection to server on socket "/run/user/1000/alvherre-tmp/i4fQURzady/.s.PGSQL.26529" failed: No such file
ordirectory
 
        Is the server running locally and accepting connections on that socket?
2025-03-11 19:44:50.493 CET [3495251] LOG:  background worker "logical replication apply worker" (PID 3502088) exited
withexit code 1
 
2025-03-11 19:47:50.593 CET [3540763] LOG:  logical replication apply worker for subscription "tap_sub" has started


Is the problem that the subscriber never tries to establish the
connection again?

I have tried to reproduce it, but I haven't seen it again.

-- 
Álvaro Herrera               48°01'N 7°57'E  —  https://www.EnterpriseDB.com/
"El sudor es la mejor cura para un pensamiento enfermo" (Bardia)