Thread: Logical Replication: SELECT pg_catalog.set_config Statement

Hello everybody,

not sure where to post this, general seems most appropriate.

We have tried logical replication in a test-setup, and it appears to 
work fine.
However, the following statement keeps running:

SELECT pg_catalog.set_config('search_path', '', false);

It is issued by the user 'subscriber' we have created for the subscription. Originally it only had the 'Replication'
role,but we have subsequently made it Superuser.
 
However, the behaviour is the same.

                               List of roles
  Role name  |                   Attributes                   | Member of
------------+------------------------------------------------+-----------
  postgres   | Superuser, Create role, Create DB, Replication | {}
  subscriber | Superuser, Replication                         | {}

Strangely, when I log in as subscriber and query the searchpath, the result is 'public'
I can then execute the above statement, and it sets the search_path to ''

At the next restart, the statement pops up again, and hangs ....
Here is the log:
2021-05-17 16:08:03.595 CEST -usztestlogrepsub@10.139.0.41  <mailto:usztestlogrepsub@10.139.0.41>: LOG:  statement:
SELECTpg_catalog.set_config('search_path', '', false);
 
2021-05-17 16:08:03.596 CEST -usztestlogrepsub@10.139.0.41  <mailto:usztestlogrepsub@10.139.0.41>: LOG:  received
replicationcommand: IDENTIFY_SYSTEM
 
2021-05-17 16:08:03.596 CEST -usztestlogrepsub@10.139.0.41  <mailto:usztestlogrepsub@10.139.0.41>: LOG:  received
replicationcommand: START_REPLICATION SLOT "usztestlogrepsub" LOGICAL E51/EC041228 (proto_version '1',
publication_names'"usztestlogreppub"')
 
2021-05-17 16:08:03.597 CEST -usztestlogrepsub@10.139.0.41  <mailto:usztestlogrepsub@10.139.0.41>: LOG:  starting
logicaldecoding for slot "usztestlogrepsub"
 
2021-05-17 16:08:03.597 CEST -usztestlogrepsub@10.139.0.41  <mailto:usztestlogrepsub@10.139.0.41>: DETAIL:  Streaming
transactionscommitting after E51/EC06B668, reading WAL from E51/EC06B668.
 
2021-05-17 16:08:03.597 CEST -usztestlogrepsub@10.139.0.41  <mailto:usztestlogrepsub@10.139.0.41>: LOG:  logical
decodingfound consistent point at E51/EC06B668
 
2021-05-17 16:08:03.597 CEST -usztestlogrepsub@10.139.0.41  <mailto:usztestlogrepsub@10.139.0.41>: DETAIL:  There are
norunning transactions.
 

Can anybody explain why this happens, and how to avoid it?

regards
Hannes


-- 


    

=?UTF-8?Q?Hannes_K=c3=bchtreiber?= <h.kuehtreiber@synedra.com> writes:
> We have tried logical replication in a test-setup, and it appears to
> work fine.
> However, the following statement keeps running:

> SELECT pg_catalog.set_config('search_path', '', false);

What makes you think it "keeps running"?  It looks to me like the
replication client does that and then goes about its business:

> 2021-05-17 16:08:03.595 CEST -usztestlogrepsub@10.139.0.41  <mailto:usztestlogrepsub@10.139.0.41>: LOG:  statement:
SELECTpg_catalog.set_config('search_path', '', false); 
> 2021-05-17 16:08:03.596 CEST -usztestlogrepsub@10.139.0.41  <mailto:usztestlogrepsub@10.139.0.41>: LOG:  received
replicationcommand: IDENTIFY_SYSTEM 

Admittedly, since you seem to have omitted the PID from your
log_line_prefix, it's hard to be 100% sure that these log entries
are from the same process.  But I bet they are.  The standard
walreceiver definitely does things this way.

In short, I think there's nothing to see here.

            regards, tom lane

Hello Tom, thanks for your answer!

We found out because we are monitoring long running queries, and saw it had been running for a month before the restart yesterday.
I just queried pg_stat_activity and it seems to be running since then.

taimusz=# SELECT pid, query_start, usename, left(query,70)
FROM pg_stat_activity
WHERE query != '<IDLE>' AND query NOT ILIKE '%pg_stat_activity%'
ORDER BY query_start;
   pid   |          query_start          |  usename   |                                  left
---------+-------------------------------+------------+------------------------------------------------------------------------
 2321161 | 2021-05-17 16:15:13.906679+02 | subscriber | SELECT pg_catalog.set_config('search_path', '', false);

SELECT pg_catalog.set_config('search_path', '', false);

What makes you think it "keeps running"?  It looks to me like the
replication client does that and then goes about its business:

Admittedly, since you seem to have omitted the PID from your
log_line_prefix, it's hard to be 100% sure that these log entries
are from the same process.  But I bet they are.  The standard
walreceiver definitely does things this way.

Sorry for omitting the PIDs. But you are probably right, it is a test environment where not much is happening

In short, I think there's nothing to see here.
			regards, tom lane

I wish this is the case. There seem to be no bloated tables, but before trying this on a production system I want to be sure

regards

Hannes

--

=?UTF-8?Q?Hannes_K=c3=bchtreiber?= <h.kuehtreiber@synedra.com> writes:
> Hello Tom, thanks for your answer!
> We found out because we are monitoring long running queries, and saw it 
> had been running for a month before the restart yesterday.
> I just queried pg_stat_activity and it seems to be running since then.

Oh, that's because pg_stat_activity continues to show the last plain-SQL
query executed by the session.

I think we recently changed things so that replication commands
would be shown in pg_stat_activity too, but evidently you're running
a version older than that.

            regards, tom lane