[pgpool-general: 7450] Re: Supported python async drivers
Tatsuo Ishii
ishii at sraoss.co.jp
Thu Mar 18 16:46:38 JST 2021
> Just checked git, it has been committed to master so I'll be looking
> forward to 4.2.3!
>
> Thanks a million!
You are welcome!
> On Thu, 18 Mar 2021 at 15:27, Anton Melser <anton at transcrob.es> wrote:
>
>> Thanks very much, that indeed looks like it has fixed the problem, though
>> I confess that I had extra errors that I don't understand
>> ...
>> 2021-03-18 14:54:47: pid 32308: LOG: find_primary_node:
>> make_persistent_db_connection_noerror failed on node 0
>> 2021-03-18 14:54:47: pid 32308: LOCATION: pgpool_main.c:3172
>> 2021-03-18 14:54:48: pid 32308: ERROR: authentication failed
>> ...
>> I don't really understand what or how the modification changes things, and
>> adding logging *didn't* make things work with the 4.2.2 I compiled without
>> the change.
>>
>> In any case, without your modification it hangs, with your modification it
>> doesn't.
>>
>> Can you confirm that this is a change you are happy to make in the
>> official repo?
>>
>> Thanks for all your help!
>>
>> On Thu, 18 Mar 2021 at 13:22, Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
>>
>>> > 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
>>> >> >>>>
>>> >> >>>
>>> >>
>>>
>>
More information about the pgpool-general
mailing list