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