[pgpool-general: 7446] Re: Supported python async drivers
Tatsuo Ishii
ishii at sraoss.co.jp
Thu Mar 18 14:22:48 JST 2021
> Thanks for your help. Unfortunately, while I can install gdb and compile
> and install the latest version of pgpool2, I only ever played around with
> C/C++ when I was a student and never did any debugging. And that was 20
> years ago :-(. I wouldn't even know where to start. I did confirm that
> exactly the same behaviour appears with the 4.2.2, at least using the
> bitnami docker image (https://hub.docker.com/r/bitnami/pgpool/).
>
> With gdb (attached to the default 4.1.4 deb version available with Ubuntu
> 20.04) I get as far as:
>
> ...
> (No debugging symbols found in /lib/x86_64-linux-gnu/libffi.so.7)
> Reading symbols from /lib/x86_64-linux-gnu/libnss_files.so.2...
> Reading symbols from
> /usr/lib/debug//lib/x86_64-linux-gnu/libnss_files-2.31.so...
> 0x00007397a9a1e0da in __GI___select (nfds=7, readfds=0x7fffa0c1f3d0,
> writefds=0x0, exceptfds=0x0, timeout=0x7fffa0c1f4c0)
> at ../sysdeps/unix/sysv/linux/select.c:41
> 41 ../sysdeps/unix/sysv/linux/select.c: No such file or directory.
> (gdb)
>
> But then I really have no idea where to even start. Is there anything
> particular I could be executing? Might this be a debian issue (the bitnami
> images are debian based and so are all the machines I'm testing on).
I was expecting you to execute "bt" command of gdb, which prints
backtrace of the program.
Anyway, I think I found possible cause of the problem. While looking at:
https://github.com/MagicStack/asyncpg/issues/573
I noticed otsuka's message on 17 May 2020:
------------------------------------------------------------------------------------------------
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: LOG: new connection received
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: DETAIL: connecting host=192.168.34.1 port=51064
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: LOG: md5 authentication successful with frontend
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: LOG: Parse message from frontend.
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: DETAIL: statement: "__asyncpg_stmt_1__", query: "SELECT 1 WHERE 2 > $1"
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: LOG: DB node id: 0 backend pid: 22328 statement: SELECT version()
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: LOG: pool_reuse_block: blockid: 0
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: CONTEXT: while searching system catalog, When relcache is missed
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: LOG: DB node id: 0 backend pid: 22328 statement: Parse: SELECT 1 WHERE 2 > $1
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: LOG: Describe message from frontend.
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: DETAIL: statement: "__asyncpg_stmt_1__"
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: LOG: DB node id: 0 backend pid: 22328 statement: D message
May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: LOG: Flush message from frontend.
(Hangs here)
------------------------------------------------------------------------------------------------
> May 17 14:26:16 pgpool[22264]: 2020-05-17 14:26:16: pid 22286: LOG: Flush message from frontend.
This is interesting since my python program produced "Sync" message,
rather than "Flush" message.
>>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: Sync message from frontend.
So I decided to try to reproduce the problem by using "pgproto" which
can send arbitrary message packets to Pgpool-II (or PostgreSQL), and I
confirmed that the problem only occurs when "Flush" message is used,
but does not occur when "Sync" message is used.
Also I guess certain version of asycpg uses "Flush" message (in the
case of github issues), while other version of asyncpg uses "Sync"
message (in my case).
Can you please check your asyncpg uses "Flush" or "Sync" message?
(that is possible by enabling log_client_message). If it uses "Flush",
attached patch should fix the problem.
> On Thu, 18 Mar 2021 at 08:34, Tatsuo Ishii <ishii at sraoss.co.jp>
wrote:
>
>> > Ok, so I was able to get it to work... I thought - why don't I activate
>> > logging to see what is happening? And of course it then promptly started
>> to
>> > work :-).
>> >
>> > If I set `log_client_messages = on` and `client_min_messages = log`
>> (where
>> > it has to be *at least* log - notice level doesn't work, all the debugX
>> > do). then the asyncpg works fine.
>> >
>> > Interesting! Any ideas what might be going on?
>>
>> No idea but I suspect the problem might be triggered by timing: with
>> logging, pgpool is somewhat slow down and may not trigger the problem.
>> It would be helpful if you attach gdb to hang pgpool process and
>> examine the process.
>>
>> > Thanks again
>> >
>> > On Wed, 17 Mar 2021 at 23:09, Anton Melser <anton at transcrob.es> wrote:
>> >
>> >> So I was able to reproduce with just plain pgpool2 on my laptop. I have
>> a
>> >> WSL2 Ubuntu with postgresql 13 installed from the official Postgresql
>> PPA,
>> >> and pgpool2 4.1.4 installed from the same.
>> >>
>> >> The postgresql 13 is on port 5433, the pgpool2 on 5434.
>> >>
>> >> I kept all default configurations, except for the host0 datadir. If I
>> use
>> >> psql, I can perform the same query with no problem:
>> >>
>> >> (broadcaster) anton at dwin:~/dev/tc/transcrobes$ PGPASSWORD=transpass
>> psql
>> >> -U postgres -h 127.0.0.1 -p 5433 -c 'select username from auth_user
>> where
>> >> id = 10' transcrobes
>> >> Pager usage is off.
>> >> username
>> >> ----------
>> >> user5
>> >> (1 row)
>> >>
>> >> (broadcaster) anton at dwin:~/dev/tc/transcrobes$ PGPASSWORD=transpass
>> psql
>> >> -U postgres -h 127.0.0.1 -p 5434 -c 'select username from auth_user
>> where
>> >> id = 10' transcrobes
>> >> Pager usage is off.
>> >> username
>> >> ----------
>> >> user5
>> >> (1 row)
>> >>
>> >> But with the following python+asyncpg, it only works when pointing
>> >> directly at the postgresql
>> >> ````
>> >> import sys
>> >> import asyncio
>> >> import asyncpg
>> >>
>> >> async def run(host, port):
>> >> conn = await asyncpg.connect(user='postgres', password='transpass',
>> >> database='transcrobes', host=host,
>> >> port=port)
>> >> values = await conn.fetch(
>> >> 'SELECT username FROM auth_user WHERE id = $1',
>> >> 10,
>> >> )
>> >> await conn.close()
>> >> print(values)
>> >>
>> >> loop = asyncio.get_event_loop()
>> >> print(sys.argv)
>> >> loop.run_until_complete(run(sys.argv[1], sys.argv[2]))
>> >> ````
>> >>
>> >> (broadcaster) anton at dwin:~/dev/tc/transcrobes$ python
>> tmp/asyncpgtest2.py
>> >> 127.0.0.1 5433
>> >> ['tmp/asyncpgtest2.py', '127.0.0.1', '5433']
>> >> [<Record username='user5'>]
>> >> (broadcaster) anton at dwin:~/dev/tc/transcrobes$ python
>> tmp/asyncpgtest2.py
>> >> 127.0.0.1 5434
>> >> ['tmp/asyncpgtest2.py', '127.0.0.1', '5434']
>> >> !!! Here hangs and doesn't return !!!
>> >>
>> >> It looks like your attached script was removed by the list software,
>> could
>> >> you send the text in the body so I can try out on my end? Others also
>> >> mentioned fetching/select queries in the ticket I referred to above.
>> >>
>> >> Thanks!
>> >>
>> >> On Wed, 17 Mar 2021 at 22:27, Anton Melser <anton at transcrob.es> wrote:
>> >>
>> >>> Thanks very much for investigating that!. I experienced something very
>> >>> similar to https://github.com/MagicStack/asyncpg/issues/573, which was
>> >>> also experienced by a few others. I will try and set up a basic
>> >>> reproduction use case. I will note that it does appear that *all* of
>> us are
>> >>> using the Bitnami postgresql-ha images/helm chart... So it may
>> actually be
>> >>> a special config they use, or possibly related to having it in a docker
>> >>> image... I'll investigate further and report back.
>> >>>
>> >>> Thanks again for your quick reply on this!
>> >>>
>> >>> On Wed, 17 Mar 2021 at 21:20, Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
>> >>>
>> >>>> >> Hi,
>> >>>> >>
>> >>>> >> I am using pgpool2 for failover (and maybe later load balancing,
>> it's
>> >>>> a
>> >>>> >> long story...) and am starting to migrate some of my code to use
>> >>>> async.
>> >>>> >> Many async projects that support postgres I have seen do so via
>> >>>> asyncpg.
>> >>>> >> asyncpg doesn't seem to work at all with pgpool2 (at least with my
>> >>>> current
>> >>>> >> pgpool config, which works perfectly synchronously with psycopg2).
>> >>>> Basic
>> >>>> >> initial testing suggests aiopg does support pgpool2, at least for
>> >>>> what I
>> >>>> >> tested it with. This is probably because it is based on
>> >>>> psycopg2-binary.
>> >>>> >>
>> >>>> >> Unfortunately almost all of the projects I have been looking at
>> using
>> >>>> that
>> >>>> >> require async postgres only support asyncpg (Broadcaster,
>> >>>> TortoiseORM,...),
>> >>>> >> not aiopg.
>> >>>> >>
>> >>>> >> Is there an officially supported async driver for python? Is one
>> >>>> planned?
>> >>>> >
>> >>>> > I am not familiar with "async" nor "asyncpg". To understand what
>> they
>> >>>> > are doing, it would be helpful to config Pgpool-II with
>> >>>> > log_client_messages = on and share the pgpool log.
>> >>>>
>> >>>> I have tried with asyncpg myself. (see attached python
>> >>>> program. Forgive me if there's something wrong. This is my first
>> >>>> python script:-) With log_client_messages = on, and log_connections =
>> >>>> on it seems Pgpool-II works fine.
>> >>>>
>> >>>> 2021-03-17 22:15:33: child pid 28311: LOG: new connection received
>> >>>> 2021-03-17 22:15:33: child pid 28311: DETAIL: connecting
>> host=127.0.0.1
>> >>>> port=33452
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: Parse message from
>> >>>> frontend.
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: DETAIL: statement:
>> >>>> "__asyncpg_stmt_1__", query: "SELECT 1;"
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: DB node id: 0 backend
>> >>>> pid: 28670 statement: SELECT version()
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: DB node id: 2 backend
>> >>>> pid: 28669 statement: Parse: SELECT 1;
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: Describe message from
>> >>>> frontend.
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: DETAIL: statement:
>> >>>> "__asyncpg_stmt_1__"
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: DB node id: 2 backend
>> >>>> pid: 28669 statement: D message
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: Sync message from
>> >>>> frontend.
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: Bind message from
>> >>>> frontend.
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: DETAIL: portal: "",
>> >>>> statement: "__asyncpg_stmt_1__"
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: DB node id: 2 backend
>> >>>> pid: 28669 statement: Bind: SELECT 1;
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: Execute message from
>> >>>> frontend.
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: DETAIL: portal: ""
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: DB node id: 2 backend
>> >>>> pid: 28669 statement: Execute: SELECT 1;
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: Sync message from
>> >>>> frontend.
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: Terminate message from
>> >>>> frontend.
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: DB node id: 0 backend
>> >>>> pid: 28670 statement: DISCARD ALL
>> >>>> 2021-03-17 22:15:33: [unknown] pid 28311: LOG: DB node id: 2 backend
>> >>>> pid: 28669 statement: DISCARD ALL
>> >>>>
>> >>>> Best regards,
>> >>>> --
>> >>>> Tatsuo Ishii
>> >>>> SRA OSS, Inc. Japan
>> >>>> English: http://www.sraoss.co.jp/index_en.php
>> >>>> Japanese:http://www.sraoss.co.jp
>> >>>>
>> >>>
>>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: flush.diff
Type: text/x-patch
Size: 1204 bytes
Desc: not available
URL: <http://www.pgpool.net/pipermail/pgpool-general/attachments/20210318/ade2c91e/attachment-0001.bin>
More information about the pgpool-general
mailing list