pg8000 を使って RDS Proxy 経由で Aurora PostgreSQL にクエリを発行するとタイムアウトする

事象サマリ

• pg8000 を使って Python スクリプトから RDS Proxy 経由で Aurora PostgreSQL にクエリを発行しようとするとタイムアウトする
• pg8000 から直接 Aurora PostfreSQL へ接続するとクエリの発行に成功する
• psycopg2 を使うと RDS Proxy 経由でもクエリの発行に成功する　

事象詳細

• Python スクリプトで出力したログ

$ bash pg8000_rds-proxy_test.sh 
2021-04-29 04:13:18.841675: Start pg8000_rds-proxy_test.py.
2021-04-29 04:13:18.841843: Connecting to database.
2021-04-29 04:13:18.856189: Connected to database.
2021-04-29 04:13:18.856311: Querying to database.
（ここで止まる）

• Python デバッガでステップ実行

$ export PG_HOST_PROXY=apg117-2-proxy-passwd.proxy-******.ap-northeast-1.rds.amazonaws.com
$ export PG_PORT=5432
$ export PG_DATABASE=postgres
$ export PG_USER=awsuser
$ export PG_PASSWORD=******
$ python -m pdb  pg8000_rds-proxy_test.py 
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(3)<module>()
-> import os
(Pdb) b 21
Breakpoint 1 at /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py:21
(Pdb) c
2021-04-29 04:40:03.560735: Start pg8000_rds-proxy_test.py.
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(21)<module>()
-> print(datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f') + ': Connecting to database.')
(Pdb) n
2021-04-29 04:40:07.474857: Connecting to database.
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(22)<module>()
-> conn = pg8000.connect(
(Pdb) n
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(23)<module>()
-> host=pg_host,
(Pdb) n
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(24)<module>()
-> port=int(pg_port),
(Pdb) n
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(25)<module>()
-> database=pg_database,
(Pdb) n
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(26)<module>()
-> user=pg_user,
(Pdb) n
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(27)<module>()
-> password=pg_password
(Pdb) n
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(29)<module>()
-> print(datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f') + ': Connected to database.')
(Pdb) n
2021-04-29 04:40:14.571838: Connected to database.
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(30)<module>()
-> conn.autocommit = True
(Pdb) n
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(31)<module>()
-> cur = conn.cursor()
(Pdb) n
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(32)<module>()
-> sql = "SELECT version();"
(Pdb) n
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(33)<module>()
-> print(datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f') + ': Querying to database.')
(Pdb) n
2021-04-29 04:40:21.079605: Querying to database.
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(34)<module>()
-> cur.execute(sql)
(Pdb) n
ここでハング

• 関数の中に入ってデバッグ

$ python -m pdb  pg8000_rds-proxy_test.py
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(3)<module>()
-> import os
(Pdb) b 33
Breakpoint 1 at /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py:33
(Pdb) c
2021-04-29 11:28:16.026085: Start pg8000_rds-proxy_test.py.
2021-04-29 11:28:16.026303: Connecting to database.
2021-04-29 11:28:16.048258: Connected to database.
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(33)<module>()
-> print(datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f') + ': Querying to database.')
(Pdb) s
2021-04-29 11:28:29.759028: Querying to database.
> /home/ec2-user/pg8000_rds-proxy_test/pg8000_rds-proxy_test.py(34)<module>()
-> cur.execute(sql)
(Pdb) s
--Call--
> /usr/lib/python2.7/site-packages/pg8000/core.py(867)execute()
-> def execute(self, operation, args=None, stream=None):

（中略）

> /usr/lib/python2.7/site-packages/pg8000/core.py(1888)execute()
-> self.handle_messages(cursor)
(Pdb) 
--Call--
> /usr/lib/python2.7/site-packages/pg8000/core.py(2019)handle_messages()
-> def handle_messages(self, cursor):
(Pdb) 
> /usr/lib/python2.7/site-packages/pg8000/core.py(2020)handle_messages()
-> code = self.error = None
(Pdb) 
> /usr/lib/python2.7/site-packages/pg8000/core.py(2022)handle_messages()
-> while code != READY_FOR_QUERY:
(Pdb) 
> /usr/lib/python2.7/site-packages/pg8000/core.py(2023)handle_messages()
-> code, data_len = ci_unpack(self._read(5))
(Pdb) 
--Call--
> /usr/lib64/python2.7/socket.py(340)read()
-> def read(self, size=-1):
(Pdb) 
> /usr/lib64/python2.7/socket.py(344)read()
-> rbufsize = max(self._rbufsize, self.default_bufsize)
(Pdb) 
> /usr/lib64/python2.7/socket.py(348)read()
-> buf = self._rbuf
(Pdb) 
> /usr/lib64/python2.7/socket.py(349)read()
-> buf.seek(0, 2)  # seek end
(Pdb) 
> /usr/lib64/python2.7/socket.py(350)read()
-> if size < 0:
(Pdb) 
> /usr/lib64/python2.7/socket.py(366)read()
-> buf_len = buf.tell()
(Pdb) 
> /usr/lib64/python2.7/socket.py(367)read()
-> if buf_len >= size:
(Pdb) 
> /usr/lib64/python2.7/socket.py(375)read()
-> self._rbuf = StringIO()  # reset _rbuf.  we consume it via buf.
(Pdb) 
> /usr/lib64/python2.7/socket.py(376)read()
-> while True:
(Pdb) 
> /usr/lib64/python2.7/socket.py(377)read()
-> left = size - buf_len
(Pdb) 
> /usr/lib64/python2.7/socket.py(383)read()
-> try:
(Pdb) 
> /usr/lib64/python2.7/socket.py(384)read()
-> data = self._sock.recv(left)
(Pdb) 

• strace でシステムコールトレースを取得

$ strace -s 100 -e sendto -f bash pg8000_rds-proxy_test.sh 
strace: Process 20706 attached
strace: Process 20707 attached
[pid 20707] +++ exited with 0 +++
[pid 20706] --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=20707, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
2021-04-29 04:29:07.096255: Start pg8000_rds-proxy_test.py.
2021-04-29 04:29:07.096740: Connecting to database.
[pid 20706] sendto(4, "F\3\1\0\0\1\0\0\0\0\0\0\25apg117-2-proxy-passwd\22proxy-******\16ap-northeast-1\3rds\tamazonaws\3com\0\0\1\0\1", 91, MSG_NOSIGNAL, NULL, 0) = 91
[pid 20706] sendto(4, {{len=20, type=0x16 /* NLMSG_??? */, flags=NLM_F_REQUEST|0x300, seq=1619670547, pid=0}, "\x00\x00\x00\x00"}, 20, 0, {sa_family=AF_NETLINK, nl_pid=0, nl_groups=00000000}, 12) = 20
[pid 20706] sendto(3, "\0\0\0(\0\3\0\0user\0awsuser\0database\0postgres\0\0", 40, 0, NULL, 0) = 40
[pid 20706] sendto(3, "p\0\0\0(md54ddb9c2b0235466c55bef5825d267e6d\0H\0\0\0\4", 46, 0, NULL, 0) = 46
2021-04-29 04:29:07.151429: Connected to database.
2021-04-29 04:29:07.151610: Querying to database.
[pid 20706] sendto(3, "P\0\0\0001pg8000_statement_20706_1\0SELECT version();\0\0\0H\0\0\0\4D\0\0\0\36Spg8000_statement_20706_1\0H\0\0\0\4S\0\0\0\4", 96, 0, NULL, 0) = 96
（ここで止まる）

• RDS Proxy ログ
  • CloudWatch Logs-Log groups-/aws/rds/proxy/apg117-2-proxy-passwd-apg117-2-proxy-passwd

2021-04-29T04:57:30.466Z [INFO] [proxyEndpoint=default] [clientConnection=4013470675] A new client connected from 172.16.1.36:56286.
2021-04-29T04:57:30.469Z [INFO] [dbConnection=646383231] A TCP connection was established from the proxy at 172.16.11.177:37517 to the database at 172.16.21.46:5432.

• PostgreSQL ログ

2021-04-29 05:41:26 UTC:ip-172-16-11-177.ap-northeast-1.compute.internal(46177):[unknown]@[unknown]:[26396]:LOG:  00000: connection received: host=ip-172-16-11-177.ap-northeast-1.compute.internal port=46177
2021-04-29 05:41:26 UTC:ip-172-16-11-177.ap-northeast-1.compute.internal(46177):[unknown]@[unknown]:[26396]:LOCATION:  BackendInitialize, postmaster.c:4696
2021-04-29 05:41:26 UTC:ip-172-16-11-177.ap-northeast-1.compute.internal(46177):awsuser@postgres:[26396]:LOG:  00000: connection authorized: user=awsuser database=postgres
2021-04-29 05:41:26 UTC:ip-172-16-11-177.ap-northeast-1.compute.internal(46177):awsuser@postgres:[26396]:LOCATION:  PerformAuthentication, postinit.c:283
2021-04-29 05:41:26 UTC:ip-172-16-11-177.ap-northeast-1.compute.internal(46177):awsuser@postgres:[26396]:LOG:  00000: statement: SELECT current_setting('transaction_read_only') AS transaction_read_only;
2021-04-29 05:41:26 UTC:ip-172-16-11-177.ap-northeast-1.compute.internal(46177):awsuser@postgres:[26396]:LOCATION:  exec_simple_query, postgres.c:997
2021-04-29 05:41:26 UTC:ip-172-16-11-177.ap-northeast-1.compute.internal(46177):awsuser@postgres:[26396]:LOG:  00000: EXECUTOR STATISTICS
2021-04-29 05:41:26 UTC:ip-172-16-11-177.ap-northeast-1.compute.internal(46177):awsuser@postgres:[26396]:DETAIL:  ! system usage stats:
	!	0.000000 s user, 0.000014 s system, 0.000013 s elapsed
	!	[0.000000 s user, 0.004675 s system total]
	!	24472 kB max resident size
	!	0/0 [0/8] filesystem blocks in/out
	!	0/2 [0/1518] page faults/reclaims, 0 [0] swaps
	!	0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
	!	0/0 [4/0] voluntary/involuntary context switches
2021-04-29 05:41:26 UTC:ip-172-16-11-177.ap-northeast-1.compute.internal(46177):awsuser@postgres:[26396]:LOCATION:  ShowUsage, postgres.c:5081
2021-04-29 05:41:26 UTC:ip-172-16-11-177.ap-northeast-1.compute.internal(46177):awsuser@postgres:[26396]:STATEMENT:  SELECT current_setting('transaction_read_only') AS transaction_read_only;

テストコード

• pg8000_rds-proxy_test.sh

#!/usr/bin/env bash

export PG_HOST_PROXY=apg117-2-proxy-passwd.proxy-******.ap-northeast-1.rds.amazonaws.com
export PG_PORT=5432
export PG_DATABASE=postgres
export PG_USER=awsuser
export PG_PASSWORD=Password123

python ./pg8000_rds-proxy_test.py

• pg8000_rds-proxy_test.py

#!/usr/bin/env python3

import os
import traceback
import datetime
import pg8000

pg_host = os.environ.get('PG_HOST_PROXY')
pg_port = os.environ.get('PG_PORT')
pg_database = os.environ.get('PG_DATABASE')
pg_user = os.environ.get('PG_USER')
pg_password = os.environ.get('PG_PASSWORD')
script_name = os.path.basename(__file__)

conn = None
cur = None

print(datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f') + ': Start ' + script_name + '.')

try:
    print(datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f') + ': Connecting to database.')
    conn = pg8000.connect(
        host=pg_host,
        port=int(pg_port),
        database=pg_database,
        user=pg_user,
        password=pg_password
    )
    print(datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f') + ': Connected to database.')
    conn.autocommit = True
    cur = conn.cursor()
    sql = "SELECT version();"
    print(datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f') + ': Querying to database.') 
    cur.execute(sql)
    print(datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f') + ': Queryed to database.')

    print(datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f') + ': Print resut set.')
    rows = cur.fetchall()
    for row in rows:
        print(row)

except pg8000.exceptions.DatabaseError as exc:
    print(type(exc))
    print(traceback.format_exc())
    
except Exception as exc:
    print(type(exc))
    print(traceback.format_exc())

finally:
    if cur is not None:
        cur.close()
        cur = None
    if conn is not None:
        conn.close()
        conn = None

print(datetime.datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f') + ': ' + script_name + ' is finised.')

環境

• Aurora PostgreSQL v11.7
• Python 3.6.9
• pg8000-1.19.3

関連

• yoheia/aws/rds/pg8000_rds-proxy_test at master · yoheia/yoheia · GitHub

参考

• Pythonデバッグ方法 入門編 - Qiita
• pg8000/legacy.py at master · tlocke/pg8000 · GitHub
• pg8000/core.py at master · tlocke/pg8000 · GitHub