Обсуждение: FDW Foreign Table Access: strange LOG message

Hi all,

I use Postgres 10.3 on a Debian Stretch system with foreign tables, and noticed strange LOG messages when accessing
them.

The data base setup is basically

---8<------------------------------------------------------------------------------------------
CREATE EXTENSION IF NOT EXISTS postgres_fdw WITH SCHEMA public;
CREATE SERVER ext_server FOREIGN DATA WRAPPER postgres_fdw OPTIONS (
     dbname 'ext_db', host 'localhost', updatable 'false');
CREATE FOREIGN TABLE public.ext_table (
     […]
) SERVER ext_server OPTIONS (schema_name 'public', table_name 'some_table', updatable 'false');
---8<------------------------------------------------------------------------------------------

Now I use the following trivial Python2 (psycopg2) code to access the tables:

---8<------------------------------------------------------------------------------------------
import psycopg2
conn = psycopg2.connect(dbname='my_db')
with conn.cursor() as csr:
    csr.execute("SELECT * FROM […] LIMIT 1")
    csr.fetchone()
conn.close()
---8<------------------------------------------------------------------------------------------

When I access a “local” table of my_db in the SELECT statement, there is no LOG message.  However, reading from
ext_tableworks just fine, but the conn.close() statement above triggers the log message 

---8<------------------------------------------------------------------------------------------
[time stamp/pid] user@my_db LOG:  could not receive data from client: Connection reset by peer
---8<------------------------------------------------------------------------------------------

Did I miss something in the setup here?  Or is there any other way to get rid of the message (which fills ~95% of my
logs)?

Thanks in advance,
Albrecht.

On 03/20/2018 11:52 AM, Albrecht Dreß wrote:
> Hi all,
> 
> I use Postgres 10.3 on a Debian Stretch system with foreign tables, and 
> noticed strange LOG messages when accessing them.
> 
> The data base setup is basically
> 
> ---8<------------------------------------------------------------------------------------------ 
> 
> CREATE EXTENSION IF NOT EXISTS postgres_fdw WITH SCHEMA public;
> CREATE SERVER ext_server FOREIGN DATA WRAPPER postgres_fdw OPTIONS (
>      dbname 'ext_db', host 'localhost', updatable 'false');
> CREATE FOREIGN TABLE public.ext_table (
>      […]
> ) SERVER ext_server OPTIONS (schema_name 'public', table_name 
> 'some_table', updatable 'false');
> ---8<------------------------------------------------------------------------------------------ 
> 
> 
> Now I use the following trivial Python2 (psycopg2) code to access the 
> tables:
> 
> ---8<------------------------------------------------------------------------------------------ 
> 
> import psycopg2
> conn = psycopg2.connect(dbname='my_db')
> with conn.cursor() as csr:
>     csr.execute("SELECT * FROM […] LIMIT 1")
>     csr.fetchone()
> conn.close()
> ---8<------------------------------------------------------------------------------------------ 
> 
> 
> When I access a “local” table of my_db in the SELECT statement, there is 
> no LOG message.  However, reading from ext_table works just fine, but 
> the conn.close() statement above triggers the log message
> 
> ---8<------------------------------------------------------------------------------------------ 
> 
> [time stamp/pid] user@my_db LOG:  could not receive data from client: 
> Connection reset by peer
> ---8<------------------------------------------------------------------------------------------ 
> 
> 
> Did I miss something in the setup here?  Or is there any other way to 
> get rid of the message (which fills ~95% of my logs)?

My suspicion is it has to do with this:

https://www.postgresql.org/docs/10/static/postgres-fdw.html#id-1.11.7.43.10
"
F.34.2. Connection Management

postgres_fdw establishes a connection to a foreign server during the 
first query that uses a foreign table associated with the foreign 
server. This connection is kept and re-used for subsequent queries in 
the same session. However, if multiple user identities (user mappings) 
are used to access the foreign server, a connection is established for 
each user mapping.
"

Guessing that conn.close() is not closing the internal FDW connection 
properly. Not sure how to fix, I will ponder some though.

> 
> Thanks in advance,
> Albrecht.


-- 
Adrian Klaver
adrian.klaver@aklaver.com

Adrian Klaver <adrian.klaver@aklaver.com> writes:
> On 03/20/2018 11:52 AM, Albrecht Dreß wrote:
>> I use Postgres 10.3 on a Debian Stretch system with foreign tables, and 
>> noticed strange LOG messages when accessing them.
>> [time stamp/pid] user@my_db LOG:  could not receive data from client: 
>> Connection reset by peer

> My suspicion is it has to do with this:
> postgres_fdw establishes a connection to a foreign server during the 
> first query that uses a foreign table associated with the foreign 
> server. This connection is kept and re-used for subsequent queries in 
> the same session.

Perhaps.  It's not entirely clear if these complaints are about the
original user session or the sub-session opened by postgres_fdw.
(Albrecht, if you're not sure either, enabling log_connections and
log_disconnections might make it clearer.)

I don't see any such log messages when testing postgres_fdw here,
which is odd; why are my results different?

If these are about the FDW connections, maybe the answer is that
postgres_fdw ought to establish a backend-exit callback in which
it can shut down its connections gracefully.  If it's doing that
now, I sure don't see where.

            regards, tom lane

Hi Adrian & Tom:

Thanks a lot for your input!

Am 20.03.18 20:38 schrieb(en) Tom Lane:
>> My suspicion is it has to do with this:
>> postgres_fdw establishes a connection to a foreign server during the first query that uses a foreign table
associatedwith the foreign server. This connection is kept and re-used for subsequent queries in the same session. 
>
> Perhaps.  It's not entirely clear if these complaints are about the original user session or the sub-session opened
bypostgres_fdw. (Albrecht, if you're not sure either, enabling log_connections and log_disconnections might make it
clearer.)

Unfortunately, in my original post, I confused the primary and secondary (accessed via the FDW) data bases in my
examplewhen I anonymised their identifiers…  Sorry for the confusion!  The /real/ structure is 

     client ---[libpq]--> my_db ---[FDW]--> ext_db

and the LOG message is actually related to the “internal” connection, i.e. ext_db (*not* my_db) complains about “could
notreceive data” after accessing the table in ext_db through the FDW from my_db. 

The effect is not limited to Python, but happens with psql, too.  I.e. running (ext_table is the foreign table mapped
intomy_db, and a mapping exists only for user “user”) 

sudo -u user /usr/lib/postgresql/10/bin/psql my_db <<< "select * from ext_table limit 1;"

*also* triggers the LOG message

[time stamp/pid] user@ext_db LOG:  could not receive data from client: Connection reset by peer

> I don't see any such log messages when testing postgres_fdw here, which is odd; why are my results different?

Yes, that's strange!  I have the following deb packages (from the stretch-pgdg repo) installed:

postgresql-10            10.3-1.pgdg90+1 amd64
postgresql-client-10     10.3-1.pgdg90+1 amd64
postgresql-client-common 190.pgdg90+1    all
postgresql-common        190.pgdg90+1    all
libpq5:amd64             10.3-1.pgdg90+1 amd64

> If these are about the FDW connections, maybe the answer is that postgres_fdw ought to establish a backend-exit
callbackin which it can shut down its connections gracefully. 

Hmm, yes, sounds like a sensible explanation.

> If it's doing that now, I sure don't see where.

So, if I understand you correctly, this needs to be addressed in postgres_fdw, and there is nothing I can fix in my
setup(except for suppressing LOG messages) to get rid of the message? 

Thanks again,
Albrecht.

On 03/21/2018 11:15 AM, Albrecht Dreß wrote:
> Hi Adrian & Tom:
> 
> Thanks a lot for your input!
> 
> Am 20.03.18 20:38 schrieb(en) Tom Lane:

See comments inline below.
> 
> Unfortunately, in my original post, I confused the primary and secondary 
> (accessed via the FDW) data bases in my example when I anonymised their 
> identifiers…  Sorry for the confusion!  The /real/ structure is
> 
>      client ---[libpq]--> my_db ---[FDW]--> ext_db
> 
> and the LOG message is actually related to the “internal” connection, 
> i.e. ext_db (*not* my_db) complains about “could not receive data” after 
> accessing the table in ext_db through the FDW from my_db.
> 
> The effect is not limited to Python, but happens with psql, too.  I.e. 
> running (ext_table is the foreign table mapped into my_db, and a mapping 
> exists only for user “user”)
> 
> sudo -u user /usr/lib/postgresql/10/bin/psql my_db <<< "select * from 
> ext_table limit 1;"
> 
> *also* triggers the LOG message

Does it also happen when you open a psql session and do?:

psql>select * from ext_table limit 1;

> 
> [time stamp/pid] user@ext_db LOG:  could not receive data from client: 
> Connection reset by peer
> 
>> I don't see any such log messages when testing postgres_fdw here, 
>> which is odd; why are my results different?
> 
> Yes, that's strange!  I have the following deb packages (from the 
> stretch-pgdg repo) installed:
> 
> postgresql-10            10.3-1.pgdg90+1 amd64
> postgresql-client-10     10.3-1.pgdg90+1 amd64
> postgresql-client-common 190.pgdg90+1    all
> postgresql-common        190.pgdg90+1    all
> libpq5:amd64             10.3-1.pgdg90+1 amd64

I am not seeing --contrib which is where I would expect postgres_fdw to 
come from.

Is --contrib installed?

If not where is postgres_fdw coming from?

> 
>> If these are about the FDW connections, maybe the answer is that 
>> postgres_fdw ought to establish a backend-exit callback in which it 
>> can shut down its connections gracefully.
> 
> Hmm, yes, sounds like a sensible explanation.
> 
>> If it's doing that now, I sure don't see where.
> 
> So, if I understand you correctly, this needs to be addressed in 
> postgres_fdw, and there is nothing I can fix in my setup (except for 
> suppressing LOG messages) to get rid of the message?
> 
> Thanks again,
> Albrecht.


-- 
Adrian Klaver
adrian.klaver@aklaver.com

Hi Adrian:

Am 21.03.18 19:25 schrieb(en) Adrian Klaver:
> Does it also happen when you open a psql session and do?:
>
> psql>select * from ext_table limit 1;

No messages are printed whilst the session is open.  However, when I quit the session by typing “\q” /after/ entering
thecommand above, the LOG message appears.  It does not appear when I query tables from my_db exclusively, though, i.e.
whenI do not access the Foreign Table. 

>> postgresql-10            10.3-1.pgdg90+1 amd64
>> postgresql-client-10     10.3-1.pgdg90+1 amd64
>> postgresql-client-common 190.pgdg90+1    all
>> postgresql-common        190.pgdg90+1    all
>> libpq5:amd64             10.3-1.pgdg90+1 amd64
>
> I am not seeing --contrib which is where I would expect postgres_fdw to come from.

Apparently, it is packaged with the main server deb file:

albrecht@odysseus:~$ dpkg -S $(find /usr/share/postgresql -name "*fdw*")
postgresql-10: /usr/share/postgresql/10/extension/file_fdw--1.0.sql
postgresql-10: /usr/share/postgresql/10/extension/file_fdw.control
postgresql-10: /usr/share/postgresql/10/extension/postgres_fdw--1.0.sql
postgresql-10: /usr/share/postgresql/10/extension/postgres_fdw.control

…and additionally it contains /usr/lib/postgresql/10/postgres_fdw.so, of course.  I double-checked the package
http://apt.postgresql.org/pub/repos/apt/pool/main/p/postgresql-10/postgresql-10_10.3-1.pgdg90+1_amd64.deb;it is
installedproperly. 

> Is --contrib installed?

No.  But the deb file postgresql-contrib_10+190.pgdg90+1_all.deb contains only the changelog and copyright files.

> If not where is postgres_fdw coming from?

See above…

Cheers,
Albrecht.

On 03/22/2018 11:08 AM, Albrecht Dreß wrote:
> Hi Adrian:
> 
> Am 21.03.18 19:25 schrieb(en) Adrian Klaver:
>> Does it also happen when you open a psql session and do?:
>>
>> psql>select * from ext_table limit 1;
> 
> No messages are printed whilst the session is open.  However, when I 
> quit the session by typing “\q” /after/ entering the command above, the 
> LOG message appears.  It does not appear when I query tables from my_db 
> exclusively, though, i.e. when I do not access the Foreign Table.

Seems to back up Tom Lanes's observation:

https://www.postgresql.org/message-id/30297.1521574736%40sss.pgh.pa.us
"If these are about the FDW connections, maybe the answer is that
postgres_fdw ought to establish a backend-exit callback in which
it can shut down its connections gracefully.  If it's doing that
now, I sure don't see where."

Looks like it might be time to file a bug report:

https://www.postgresql.org/account/submitbug/


>> I am not seeing --contrib which is where I would expect postgres_fdw 
>> to come from.
> 
> Apparently, it is packaged with the main server deb file:
> 
> albrecht@odysseus:~$ dpkg -S $(find /usr/share/postgresql -name "*fdw*")
> postgresql-10: /usr/share/postgresql/10/extension/file_fdw--1.0.sql
> postgresql-10: /usr/share/postgresql/10/extension/file_fdw.control
> postgresql-10: /usr/share/postgresql/10/extension/postgres_fdw--1.0.sql
> postgresql-10: /usr/share/postgresql/10/extension/postgres_fdw.control
> 
> …and additionally it contains /usr/lib/postgresql/10/postgres_fdw.so, of 
> course.  I double-checked the package 
> http://apt.postgresql.org/pub/repos/apt/pool/main/p/postgresql-10/postgresql-10_10.3-1.pgdg90+1_amd64.deb; 
> it is installed properly.

My mistake, I was looking at an install that had Postgres 9.6. In that 
case the files for 9.6 where in --contrib, presumably because 10 is now 
the default.

> 
>> Is --contrib installed?
> 
> No.  But the deb file postgresql-contrib_10+190.pgdg90+1_all.deb 
> contains only the changelog and copyright files.
> 
>> If not where is postgres_fdw coming from?
> 
> See above…
> 
> Cheers,
> Albrecht.


-- 
Adrian Klaver
adrian.klaver@aklaver.com

Albrecht =?iso-8859-1?b?RHJl3w==?= <albrecht.dress@arcor.de> writes:
> No messages are printed whilst the session is open.  However, when I quit the session by typing “\q” /after/ entering
thecommand above, the LOG message appears.  It does not appear when I query tables from my_db exclusively, though, i.e.
whenI do not access the Foreign Table. 

It finally occurred to me what is a likely explanation for why you're
seeing these messages but I don't when I test postgres_fdw locally:
probably, you are encrypting connections to the foreign server with SSL.
I can reproduce "could not receive data from client: Connection reset by
peer" if I kill -9 a psql client when it's using SSL, but not otherwise.

Anyway, it's clearly not very nice that postgres_fdw makes no attempt
to do a graceful shutdown of its remote connection.  I don't know that
this rises to the level of a bug, exactly, but if somebody wanted to
send in a patch it'd probably get accepted.

            regards, tom lane

On Thu, Mar 22, 2018 at 06:55:12PM -0400, Tom Lane wrote:
> Anyway, it's clearly not very nice that postgres_fdw makes no attempt
> to do a graceful shutdown of its remote connection.  I don't know that
> this rises to the level of a bug, exactly, but if somebody wanted to
> send in a patch it'd probably get accepted.

I won't qualify that as a bug, this is mainly noise.  Still I agree that
it would be cleaner to make more efforts in finishing the connections
when the session goes down.  You would roughly just need to register an
on_shmem_exit callback which loops through all the connections to finish
them.  Now would we want to slow down the session shutdown just for
that?  I am less sure particularly if there is lag between the remote
and the local servers.
--
Michael

Michael Paquier <michael@paquier.xyz> writes:
> On Thu, Mar 22, 2018 at 06:55:12PM -0400, Tom Lane wrote:
>> Anyway, it's clearly not very nice that postgres_fdw makes no attempt
>> to do a graceful shutdown of its remote connection.  I don't know that
>> this rises to the level of a bug, exactly, but if somebody wanted to
>> send in a patch it'd probably get accepted.

> I won't qualify that as a bug, this is mainly noise.  Still I agree that
> it would be cleaner to make more efforts in finishing the connections
> when the session goes down.  You would roughly just need to register an
> on_shmem_exit callback which loops through all the connections to finish
> them.

That was my basic thought.  Not sure whether on_proc_exit is better than
on_shmem_exit, but one or the other.

> Now would we want to slow down the session shutdown just for
> that?  I am less sure particularly if there is lag between the remote
> and the local servers.

Yeah, I think the sticky part might be what to do if the shutdown attempt
blocks.  I vaguely recall that PQfinish just fires off an 'X' protocol
message and doesn't wait for an answer, so maybe there's not huge risk
there, but you don't really want to risk any delay.  (The worst-case
scenario is that you've gotten SIGTERM from init because a system
shutdown is beginning, and you don't have much time before it brings
the hammer down with SIGKILL, preventing a clean database shutdown
and thereby risking data corruption if anything is wrong with the
filesystem sync semantics.  I am not sure if it's more or less dangerous
for this purpose if the "remote" session is another backend in the same
cluster, and therefore also subject to the same shutdown signal.)

            regards, tom lane

Hi Tom:

Am 22.03.18 23:55 schrieb(en) Tom Lane:
> It finally occurred to me what is a likely explanation for why you're seeing these messages but I don't when I test
postgres_fdwlocally: probably, you are encrypting connections to the foreign server with SSL. 

I can confirm that the confusing LOG messages go away when I disable SSL in the server definition, i.e. either by
explicitlystating 

CREATE SERVER ext_server FOREIGN DATA WRAPPER postgres_fdw OPTIONS (
    dbname 'ext_db', host 'localhost', sslmode 'disable', updatable 'false');

or by just saying

CREATE SERVER ext_server FOREIGN DATA WRAPPER postgres_fdw OPTIONS (
    dbname 'ext_db', updatable 'false');

Linking different data bases on the same machine using the FDW may be a special use case, though…

> Anyway, it's clearly not very nice that postgres_fdw makes no attempt to do a graceful shutdown of its remote
connection. I don't know that this rises to the level of a bug, exactly, but if somebody wanted to send in a patch it'd
probablyget accepted. 

Knowing the background and the workarounds above, I agree with you that it's basically noise.  It would be nice if
therewas a note about it in the documentation, though – other users might stumble over it, too. 

A different, confusing point (which is closer to a “bug” IMHO) is that connections to localhost are actually encrypted
bydefault.  This is basically useless and just a waste of cpu cycles – if a malicious user may somehow tap (tcpdump)
lo,there is a different problem which can not be mitigated by encryption… 

Thank you so much for your help and insights!

Cheers,
Albrecht.

Albrecht =?iso-8859-1?b?RHJl3w==?= <albrecht.dress@arcor.de> writes:
> A different, confusing point (which is closer to a “bug” IMHO) is that connections to localhost are actually
encryptedby default.  This is basically useless and just a waste of cpu cycles – if a malicious user may somehow tap
(tcpdump)lo, there is a different problem which can not be mitigated by encryption… 

I agree that it's not very useful to do that, but it'd be tough for us to
make it not happen by default --- that requires knowing an awful lot about
the local network topology.  Not sure that we'd want to assume that
"localhost" is safe, and we'd certainly not know what to do for
connections that use the host's name.

Note that in most scenarios, "local" connections travel over a Unix socket
not TCP, and in that case we don't encrypt.

            regards, tom lane